diff --git a/CHANGELOG.md b/CHANGELOG.md index 6e569e9..7171f64 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -1,3 +1,6 @@ +### master +* Add support for tagged measurements (#123) + ### Version 1.4.2 * Bump librato-rack dependency to fix warns with ruby 2.4 diff --git a/README.md b/README.md index 210ce40..1e76b57 100644 --- a/README.md +++ b/README.md @@ -68,17 +68,41 @@ To see all config options or for information on combining config files and envir If you are using the Librato Heroku addon, your user and token environment variables will already be set in your Heroku environment. If you are running without the addon you will need to provide them yourself. -In either case you will need to specify a custom source for your app to track properly. If `librato-rails` does not detect an explicit source it will not start. You can set the source in your environment: +If Heroku idles your application, measurements will not be sent until it receives another request and is restarted. If you see intermittent gaps in your measurements during periods of low traffic, this is the most likely cause. - heroku config:add LIBRATO_SOURCE=myappname +If you are using Librato as a Heroku addon, [a paid plan](https://elements.heroku.com/addons/librato#pricing) is required for reporting custom metrics with librato-rails. You can view more about available addon levels [here](https://elements.heroku.com/addons/librato#pricing). -If you are using a config file, add your source entry to that instead. +## Default Tags -Full information on configuration options is available on the [configuration wiki page](https://github.com/librato/librato-rails/wiki/Configuration). +Librato Metrics supports tagged measurements that are associated with a metric, one or more tag pairs, and a point in time. For more information on tagged measurements, visit our [API documentation](https://www.librato.com/docs/api/#measurements). -If Heroku idles your application, measurements will not be sent until it receives another request and is restarted. If you see intermittent gaps in your measurements during periods of low traffic, this is the most likely cause. +##### Detected Tags -If you are using Librato as a Heroku addon, [a paid plan](https://elements.heroku.com/addons/librato#pricing) is required for reporting custom metrics with librato-rails. You can view more about available addon levels [here](https://elements.heroku.com/addons/librato#pricing). +By default, `service`, `environment` and `host` are detected and applied as default tags for submitted measurements. Optionally, you can override the detected values in your configuration file: + +```yaml +production: + user: + token: + tags: + service: 'myapp' + environment: 'production' + host: 'myapp-prod-1' +``` + +##### Custom Tags + +In addition to the default tags, you can also provide custom tags: + +```yaml +production: + user: + token: + tags: + region: 'us-east-1' +``` + +Full information on configuration options is available on the [configuration wiki page](https://github.com/librato/librato-rails/wiki/Configuration). ## Automatic Measurements @@ -93,9 +117,8 @@ The metrics automatically recorded by `librato-rails` are organized into named m ###### Request Metrics * *rails_controller*: Metrics which provide a high level overview of request performance including `rails.request.total`, `rails.request.time`, `rails.request.time.db`, `rails.request.time.view`, and `rails.request.slow` -* *rails_method*: `rails.request.method.*` metrics (GET, POST, etc) -* *rails_status*: `rails.request.status.*` metrics broken out by individual status codes and class (200, 2xx, etc) -* *rails_action*: `rails.action.*` metrics specific to individual controller actions via the [instrument_action](#instrument_action-experimental) helper +* *rails_method*: `rails.request.method` metric with `method` tag name and HTTP method tag value, e.g. `method=POST` +* *rails_status*: `rails.request.status` metric with `status` tag name and HTTP status code tag value, e.g. `status=200` ###### System-Specific Metrics @@ -110,8 +133,8 @@ The metrics automatically recorded by `librato-rails` are organized into named m Rack measurements are taken from the very beginning of your [rack middleware stack](http://guides.rubyonrails.org/rails_on_rack.html). They include all time spent in your ruby process (not just in Rails proper). They will also show requests that are handled entirely in middleware and don't appear in the `rails` suites above. * *rack*: The `rack.request.total`, `rack.request.time`, `rack.request.slow`, and `rack.request.queue.time` metrics -* *rack_method*: `rack.request.method.*` metrics (GET, POST, etc) -* *rack_status*: `rack.request.status.*` metrics metrics broken out by individual status codes and class (200, 2xx, etc) +* *rack_method*: `rack.request.method` metric with `method` tag name and HTTP method tag value, e.g. `method=POST` +* *rack_status*: `rack.request.status` metric with `status` tag name and HTTP status code tag value, e.g. `status=200` ###### Queue Time @@ -156,13 +179,20 @@ Use for tracking a running total of something _across_ requests, examples: ```ruby # increment the 'sales_completed' metric by one -Librato.increment 'sales_completed' +Librato.increment 'sales.completed' +# => {:service=>"myapp", :environment=>"production", :host=>"myapp-prod-1"} # increment by five -Librato.increment 'items_purchased', by: 5 +Librato.increment 'items.purchased', by: 5 +# => {:service=>"myapp", :environment=>"production", :host=>"myapp-prod-1"} -# increment with a custom source -Librato.increment 'user.purchases', source: user.id +# increment with custom per-measurement tags +Librato.increment 'user.purchases', tags: { user_id: user.id, currency: 'USD' } +# => {:user_id=>43, :currency=>"USD"} + +# increment with custom per-measurement tags and inherited default tags +Librato.increment 'user.purchases', tags: { user_id: user.id, currency: 'USD' }, inherit_tags: true +# => {:service=>"myapp", :environment=>"production", :host=>"myapp-prod-1", :user_id=>43, :currency=>"USD"} ``` Other things you might track this way: user signups, requests of a certain type or to a certain route, total jobs queued or processed, emails sent or received @@ -175,7 +205,7 @@ Especially with custom sources you may want the opposite behavior - reporting a ```ruby # report a value for 'user.uploaded_file' only during non-zero intervals -Librato.increment 'user.uploaded_file', source: user.id, sporadic: true +Librato.increment 'user.uploaded_file', tags: { user: user.id, bucket: bucket.name }, sporadic: true ``` #### measure @@ -185,8 +215,8 @@ Use when you want to track an average value _per_-request. Examples: ```ruby Librato.measure 'user.social_graph.nodes', 212 -# report from a custom source -Librato.measure 'jobs.queued', 3, source: 'worker.12' +# report from custom per-measurement tags +Librato.measure 'jobs.queued', 3, tags: { priority: 'high', worker: 'worker.12' } ``` #### timing @@ -196,8 +226,8 @@ Like `Librato.measure` this is per-request, but specialized for timing informati ```ruby Librato.timing 'twitter.lookup.time', 21.2 -# report from a custom source -Librato.measure 'api.response.time', time, source: node_name +# report from custom per-measurement tags +Librato.measure 'api.response.time', time, tags: { node: node_name, db: 'rr1' } ``` The block form auto-submits the time it took for its contents to execute as the measurement value: @@ -250,54 +280,6 @@ end Symbols can be used interchangably with strings for metric names. -## Controller Helpers - -`librato-rails` also has special helpers which are available inside your controllers: - -#### instrument_action -_experimental_, this interface may change: - -Use when you want to profile execution time or request volume for a specific controller action: - -```ruby -class CommentController < ApplicationController - instrument_action :create # can accept a list - - def create - # ... - end -end -``` - -Optionally, you can instrument all controller actions: - -```ruby -class ArticlesController < ApplicationController - instrument_action :all - - def create - # ... - end - - def show - # ... - end -end -``` - -Once you instrument an action, `librato-rails` will start reporting a set of metrics specific to that action including: - -* rails.action.request.total (# of requests) -* rails.action.request.slow (requests >= 200ms to produce) -* rails.action.request.exceptions -* rails.action.request.time (total time spent in action) -* rails.action.request.time.db (db interaction time) -* rails.action.request.time.view (view rendering time) - -Each instrumented action will appear as a source for the `rails.action.*` metrics, for example `mycontroller.action.html`. - -IMPORTANT NOTE: Metrics from `instrument_action` take into account all time spent in the ActionController stack for that action, including before/after filters and any global processing. They are _not_ equivalent to using a `Librato.timing` block inside the method body. - ## Use with ActiveSupport::Notifications `librato-rails` and [ActiveSupport::Notifications](http://api.rubyonrails.org/classes/ActiveSupport/Notifications.html) work great together. In fact, many of the Rails metrics provided are produced by subscribing to the [instrumentation events](http://edgeguides.rubyonrails.org/active_support_instrumentation.html) built into Rails. @@ -324,7 +306,7 @@ ActiveSupport::Notifications.subscribe 'my.event' do |*args| Librato.timing 'my.event.time', event.duration # use payload data to do user-specific tracking - Librato.increment 'user.did.event', source: user.id, sporadic: true + Librato.increment 'user.did.event', tags: { user: user.id }, sporadic: true # do conditional tracking if user.feature_on?(:sample_group) @@ -357,14 +339,11 @@ Never fear, [we have some guidelines](https://github.com/librato/librato-rails/w ## Cross-Process Aggregation -`librato-rails` submits measurements back to the Librato platform on a _per-process_ basis. By default these measurements are then combined into a single measurement per source (default is your hostname) before persisting the data. +`librato-rails` submits measurements back to the Librato platform on a _per-process_ basis. By default these measurements are then combined into a single measurement per default tags (detects `service`, `environment` and `host`) before persisting the data. For example if you have 4 hosts with 8 unicorn instances each (i.e. 32 processes total), on the Librato site you'll find 4 data streams (1 per host) instead of 32. Current pricing applies after aggregation, so in this case you will be charged for 4 streams instead of 32. -If you want to report per-process instead, you can set `source_pids` to `true` in -your config, which will append the process id to the source name used by each thread. - ## Troubleshooting Note that it may take 2-3 minutes for the first results to show up in your Librato account after you have started your servers with `librato-rails` enabled and the first request has been received. diff --git a/lib/librato/rails/configuration.rb b/lib/librato/rails/configuration.rb index 9ec9fd7..f326e19 100644 --- a/lib/librato/rails/configuration.rb +++ b/lib/librato/rails/configuration.rb @@ -1,3 +1,4 @@ +require "socket" require "yaml" module Librato @@ -8,9 +9,9 @@ module Rails # https://github.com/librato/librato-rack/blob/master/lib/librato/rack/configuration.rb # class Configuration < Rack::Configuration - CONFIG_SETTABLE = %w{user token flush_interval log_level prefix source source_pids proxy suites} + CONFIG_SETTABLE = %w{flush_interval log_level prefix proxy suites tags token user} - DEFAULT_SUITES = [:rails_action, :rails_cache, :rails_controller, :rails_mail, :rails_method, :rails_render, :rails_sql, :rails_status, :rails_job] + DEFAULT_SUITES = [:rails_cache, :rails_controller, :rails_mail, :rails_method, :rails_render, :rails_sql, :rails_status, :rails_job] attr_accessor :config_by, :config_file @@ -32,6 +33,8 @@ def load_configuration super end + self.tags = detect_tags + # respect autorun and log_level env vars regardless of config method self.autorun = detect_autorun self.log_level = :info if log_level.blank? @@ -46,7 +49,11 @@ def configure_with_config_file env_specific = YAML.load(ERB.new(File.read(config_file)).result)[::Rails.env] if env_specific settable = CONFIG_SETTABLE & env_specific.keys - settable.each { |key| self.send("#{key}=", env_specific[key]) } + settable.each do |key| + value = env_specific[key] + value.symbolize_keys! if key == "tags" + self.send("#{key}=", value) + end end end @@ -54,6 +61,18 @@ def default_suites super + DEFAULT_SUITES end + def default_tags + { + service: ::Rails.application.class.to_s.split("::").first.underscore, + environment: ::Rails.env, + host: Socket.gethostname.downcase + } + end + + def detect_tags + has_tags? ? default_tags.merge(self.tags) : default_tags + end + end end end diff --git a/lib/librato/rails/railtie.rb b/lib/librato/rails/railtie.rb index 19aace1..36b2d8a 100644 --- a/lib/librato/rails/railtie.rb +++ b/lib/librato/rails/railtie.rb @@ -40,7 +40,6 @@ class Railtie < ::Rails::Railtie end tracker = config.librato_rails.tracker - require_relative 'subscribers/action' if tracker.suite_enabled?(:rails_action) require_relative 'subscribers/cache' if tracker.suite_enabled?(:rails_cache) require_relative 'subscribers/controller' if tracker.suite_enabled?(:rails_controller) require_relative 'subscribers/mail' if tracker.suite_enabled?(:rails_mail) @@ -50,7 +49,7 @@ class Railtie < ::Rails::Railtie require_relative 'subscribers/status' if tracker.suite_enabled?(:rails_status) Librato::Rails::VersionSpecifier.supported(min: '4.2') do - require_relative 'subscribers/job'if tracker.suite_enabled?(:rails_job) + require_relative 'subscribers/job' if tracker.suite_enabled?(:rails_job) end end diff --git a/lib/librato/rails/subscribers/action.rb b/lib/librato/rails/subscribers/action.rb deleted file mode 100644 index 380e9a8..0000000 --- a/lib/librato/rails/subscribers/action.rb +++ /dev/null @@ -1,39 +0,0 @@ -module Librato - module Rails - module Subscribers - - # Controller Actions - - ActiveSupport::Notifications.subscribe 'process_action.action_controller' do |*args| - - event = ActiveSupport::Notifications::Event.new(*args) - controller = event.payload[:controller] - action = event.payload[:action] - - format = event.payload[:format] || "all" - format = "all" if format == "*/*" - exception = event.payload[:exception] - - if @watches && (@watches.index(controller) || @watches.index("#{controller}##{action}")) - source = "#{controller}.#{action}.#{format}" - collector.group 'rails.action.request' do |r| - - r.increment 'total', source: source - r.increment 'slow', source: source if event.duration > 200.0 - r.timing 'time', event.duration, source: source, percentile: 95 - - if exception - r.increment 'exceptions', source: source - else - r.timing 'time.db', event.payload[:db_runtime] || 0, source: source, percentile: 95 - r.timing 'time.view', event.payload[:view_runtime] || 0, source: source, percentile: 95 - end - - end - end - - end # end subscribe - - end - end -end diff --git a/lib/librato/rails/subscribers/cache.rb b/lib/librato/rails/subscribers/cache.rb index adc250e..79223c3 100644 --- a/lib/librato/rails/subscribers/cache.rb +++ b/lib/librato/rails/subscribers/cache.rb @@ -7,16 +7,18 @@ module Subscribers %w{read generate fetch_hit write delete}.each do |metric| ActiveSupport::Notifications.subscribe "cache_#{metric}.active_support" do |*args| + event = ActiveSupport::Notifications::Event.new(*args) collector.group "rails.cache" do |c| c.increment metric c.timing "#{metric}.time", event.duration - end - end + end # end group + + end # end subscribe end end end -end \ No newline at end of file +end diff --git a/lib/librato/rails/subscribers/controller.rb b/lib/librato/rails/subscribers/controller.rb index aad62de..e85c92c 100644 --- a/lib/librato/rails/subscribers/controller.rb +++ b/lib/librato/rails/subscribers/controller.rb @@ -2,26 +2,29 @@ module Librato module Rails module Subscribers - # Controllers + # ActionController - ActiveSupport::Notifications.subscribe 'process_action.action_controller' do |*args| + ActiveSupport::Notifications.subscribe "process_action.action_controller" do |*args| event = ActiveSupport::Notifications::Event.new(*args) exception = event.payload[:exception] + format = event.payload[:format].to_s || "all" + format = "all" if format == "*/*" + tags = { + controller: event.payload[:controller], + action: event.payload[:action], + format: format, + } collector.group "rails.request" do |r| + r.increment "total", tags: tags, inherit_tags: true + r.timing "time", event.duration, tags: tags, inherit_tags: true, percentile: 95 + r.timing "time.db", event.payload[:db_runtime] || 0, tags: tags, inherit_tags: true, percentile: 95 + r.timing "time.view", event.payload[:view_runtime] || 0, tags: tags, inherit_tags: true, percentile: 95 - r.increment 'total' - r.timing 'time', event.duration, percentile: 95 - - if exception - r.increment 'exceptions' - else - r.timing 'time.db', event.payload[:db_runtime] || 0, percentile: 95 - r.timing 'time.view', event.payload[:view_runtime] || 0, percentile: 95 + if event.duration > 200.0 + r.increment "slow", tags: tags, inherit_tags: true end - - r.increment 'slow' if event.duration > 200.0 end # end group end # end subscribe diff --git a/lib/librato/rails/subscribers/job.rb b/lib/librato/rails/subscribers/job.rb index c299ccc..1ec9705 100644 --- a/lib/librato/rails/subscribers/job.rb +++ b/lib/librato/rails/subscribers/job.rb @@ -1,17 +1,26 @@ module Librato module Rails module Subscribers - hooks = %w{enqueue_at enqueue perform_start perform} - hooks.each do |hook| - ActiveSupport::Notifications.subscribe "#{hook}.active_job" do |*args| + # ActionJob + + %w{enqueue_at enqueue perform_start perform}.each do |metric| + + ActiveSupport::Notifications.subscribe "#{metric}.active_job" do |*args| + event = ActiveSupport::Notifications::Event.new(*args) + tags = { + adapter: event.payload[:adapter].to_s.demodulize.underscore, + job: event.payload[:job].class.to_s.demodulize.underscore + } + + collector.group "rails.job" do |c| + c.increment metric, tags: tags, inherit_tags: true + c.timing "#{metric}.time", event.duration, tags: tags, inherit_tags: true + end # end group + + end # end subscribe - collector.group 'rails.job' do |c| - c.increment hook - c.timing "#{hook}.time", event.duration, source: event.payload[:job].class - end - end end end end diff --git a/lib/librato/rails/subscribers/mail.rb b/lib/librato/rails/subscribers/mail.rb index 072b6a2..ea11dc9 100644 --- a/lib/librato/rails/subscribers/mail.rb +++ b/lib/librato/rails/subscribers/mail.rb @@ -4,15 +4,18 @@ module Subscribers # ActionMailer - ActiveSupport::Notifications.subscribe 'deliver.action_mailer' do |*args| - # payload[:mailer] => 'UserMailer' - collector.increment "rails.mail.sent" - end + ActiveSupport::Notifications.subscribe "deliver.action_mailer" do |*args| + event = ActiveSupport::Notifications::Event.new(*args) + tags = { mailer: event.payload[:mailer] } + collector.increment "rails.mail.sent", tags: tags, inherit_tags: true + end # end subscribe - ActiveSupport::Notifications.subscribe 'receive.action_mailer' do |*args| - collector.increment "rails.mail.received" - end + ActiveSupport::Notifications.subscribe "receive.action_mailer" do |*args| + event = ActiveSupport::Notifications::Event.new(*args) + tags = { mailer: event.payload[:mailer] } + collector.increment "rails.mail.received", tags: tags, inherit_tags: true + end # end subscribe end end -end \ No newline at end of file +end diff --git a/lib/librato/rails/subscribers/method.rb b/lib/librato/rails/subscribers/method.rb index 667d8f9..d0c76dd 100644 --- a/lib/librato/rails/subscribers/method.rb +++ b/lib/librato/rails/subscribers/method.rb @@ -2,19 +2,17 @@ module Librato module Rails module Subscribers - # Controller Method + # ActionController Method - ActiveSupport::Notifications.subscribe 'process_action.action_controller' do |*args| + ActiveSupport::Notifications.subscribe "process_action.action_controller" do |*args| event = ActiveSupport::Notifications::Event.new(*args) - http_method = event.payload[:method] + tags = { method: event.payload[:method].to_s.downcase } - if http_method - verb = http_method.to_s.downcase - - collector.group "rails.request.method" do |m| - m.increment verb - m.timing "#{verb}.time", event.duration + if tags[:method] + collector.group "rails.request" do |m| + m.increment "method", tags: tags, inherit_tags: true + m.timing "method.time", event.duration, tags: tags, inherit_tags: true end # end group end diff --git a/lib/librato/rails/subscribers/render.rb b/lib/librato/rails/subscribers/render.rb index 0d2be67..c88d6da 100644 --- a/lib/librato/rails/subscribers/render.rb +++ b/lib/librato/rails/subscribers/render.rb @@ -7,22 +7,26 @@ module Subscribers %w{partial template}.each do |metric| ActiveSupport::Notifications.subscribe "render_#{metric}.action_view" do |*args| + event = ActiveSupport::Notifications::Event.new(*args) path = event.payload[:identifier].split('/views/', 2) + metric = metric.to_sym if path[1] - source = path[1].gsub('/', ':') - # trim leading underscore for partial sources - source.gsub!(':_', ':') if metric == 'partial' - collector.group "rails.view" do |c| - c.increment "render_#{metric}", source: source, sporadic: true - c.timing "render_#{metric}.time", event.duration, source: source, sporadic: true - end + identifier = path[1].gsub('/', ':') + # trim leading underscore for partials + identifier.gsub!(':_', ':') if metric == :partial + tags = { metric => identifier } + collector.group "rails.view.render" do |c| + c.increment metric, tags: tags, inherit_tags: true, sporadic: true + c.timing "#{metric}.time", event.duration, tags: tags, inherit_tags: true, sporadic: true + end # end group end - end + + end # end subscribe end end end -end \ No newline at end of file +end diff --git a/lib/librato/rails/subscribers/sql.rb b/lib/librato/rails/subscribers/sql.rb index bca534b..4ab33d3 100644 --- a/lib/librato/rails/subscribers/sql.rb +++ b/lib/librato/rails/subscribers/sql.rb @@ -4,21 +4,21 @@ module Subscribers # SQL - ActiveSupport::Notifications.subscribe 'sql.active_record' do |*args| + ActiveSupport::Notifications.subscribe "sql.active_record" do |*args| + payload = args.last + sql = payload[:sql].strip collector.group "rails.sql" do |s| - # puts (payload[:name] || 'nil') + ":" + payload[:sql] + "\n\n" - s.increment 'queries' + s.increment "queries" + s.increment "selects" if sql.starts_with?("SELECT") + s.increment "inserts" if sql.starts_with?("INSERT") + s.increment "updates" if sql.starts_with?("UPDATE") + s.increment "deletes" if sql.starts_with?("DELETE") + end # end group - sql = payload[:sql].strip - s.increment 'selects' if sql.starts_with?('SELECT') - s.increment 'inserts' if sql.starts_with?('INSERT') - s.increment 'updates' if sql.starts_with?('UPDATE') - s.increment 'deletes' if sql.starts_with?('DELETE') - end - end + end # end subscribe end end -end \ No newline at end of file +end diff --git a/lib/librato/rails/subscribers/status.rb b/lib/librato/rails/subscribers/status.rb index 80010f8..2010b9c 100644 --- a/lib/librato/rails/subscribers/status.rb +++ b/lib/librato/rails/subscribers/status.rb @@ -2,19 +2,17 @@ module Librato module Rails module Subscribers - # Controller Status + # ActionController Status - ActiveSupport::Notifications.subscribe 'process_action.action_controller' do |*args| + ActiveSupport::Notifications.subscribe "process_action.action_controller" do |*args| event = ActiveSupport::Notifications::Event.new(*args) - status = event.payload[:status] + tags = { status: event.payload[:status] } - unless status.blank? - collector.group "rails.request.status" do |s| - s.increment status - s.increment "#{status.to_s[0]}xx" - s.timing "#{status}.time", event.duration - s.timing "#{status.to_s[0]}xx.time", event.duration + unless tags[:status].blank? + collector.group "rails.request" do |s| + s.increment "status", tags: tags, inherit_tags: true + s.timing "status.time", event.duration, tags: tags, inherit_tags: true end # end group end diff --git a/lib/librato/rails/tracker.rb b/lib/librato/rails/tracker.rb index 5aeabac..bafde2b 100644 --- a/lib/librato/rails/tracker.rb +++ b/lib/librato/rails/tracker.rb @@ -10,4 +10,4 @@ def version_string end end -end \ No newline at end of file +end diff --git a/librato-rails.gemspec b/librato-rails.gemspec index b621419..f2128bd 100644 --- a/librato-rails.gemspec +++ b/librato-rails.gemspec @@ -25,7 +25,7 @@ Gem::Specification.new do |s| s.add_dependency "railties", ">= 3.0" s.add_dependency "activesupport", ">= 3.0" - s.add_dependency "librato-rack", "~> 1.1.0" + s.add_dependency "librato-rack", "~> 2.0.0" s.add_development_dependency "sqlite3", ">= 1.3" s.add_development_dependency "capybara", "~> 2.0.3" diff --git a/test/dummy/app/controllers/instrument_action_controller.rb b/test/dummy/app/controllers/instrument_action_controller.rb index aaf8ead..f494544 100644 --- a/test/dummy/app/controllers/instrument_action_controller.rb +++ b/test/dummy/app/controllers/instrument_action_controller.rb @@ -14,6 +14,10 @@ def not render nothing: true end + def invalid_format + head :ok + end + private def before diff --git a/test/dummy/app/mailers/user_mailer.rb b/test/dummy/app/mailers/user_mailer.rb index 6824026..1d8fe3d 100644 --- a/test/dummy/app/mailers/user_mailer.rb +++ b/test/dummy/app/mailers/user_mailer.rb @@ -1,8 +1,12 @@ class UserMailer < ActionMailer::Base default from: "from@librato-rails.com" - + def welcome_email(user) @user = user mail(:to => user.email, :subject => "Why Howdy!") end + + def receive(email) + email + end end diff --git a/test/dummy/config/routes.rb b/test/dummy/config/routes.rb index 27dbfb2..337e08e 100644 --- a/test/dummy/config/routes.rb +++ b/test/dummy/config/routes.rb @@ -19,6 +19,7 @@ get 'instrument/inst' => 'instrument_action#inst', :as => :instrument_action get 'instrument/not' => 'instrument_action#not', :as => :not_instrumented + get '/invalid_format' => 'instrument_action#invalid_format' get 'base/action_1' => 'base#action_1', :as => :base_action_1 get 'base/action_2' => 'base#action_2', :as => :base_action_2 diff --git a/test/fixtures/config/empty.yml b/test/fixtures/config/empty.yml index bef2d7d..49fa102 100644 --- a/test/fixtures/config/empty.yml +++ b/test/fixtures/config/empty.yml @@ -1,4 +1,4 @@ test: user: 'test@bar.com' token: 'test key' - log_level: '' \ No newline at end of file + log_level: '' diff --git a/test/fixtures/config/librato.yml b/test/fixtures/config/librato.yml index 31ba8b2..f4dd238 100644 --- a/test/fixtures/config/librato.yml +++ b/test/fixtures/config/librato.yml @@ -3,11 +3,12 @@ test: token: <%= 'test api key' %> prefix: 'rails-test' flush_interval: 30 - source: 'custom-1' - source_pids: false + tags: + region: "us-east-1" + az: "b" proxy: 'http://localhost:8080' suites: all - + production: user: 'live@bar.com' token: 'live api key' diff --git a/test/fixtures/config/simple.yml b/test/fixtures/config/simple.yml index dedd6fa..9758add 100644 --- a/test/fixtures/config/simple.yml +++ b/test/fixtures/config/simple.yml @@ -1,5 +1,3 @@ test: user: 'test@bar.com' token: <%= 'test api key' %> - - diff --git a/test/integration/cache_test.rb b/test/integration/cache_test.rb index ea54ddd..a295eb0 100644 --- a/test/integration/cache_test.rb +++ b/test/integration/cache_test.rb @@ -5,35 +5,35 @@ class CacheTest < ActiveSupport::IntegrationCase test 'cache read' do visit cache_read_path - assert_equal 1, counters["rails.cache.read"] + assert_equal 1, counters["rails.cache.read"][:value] assert_equal 1, aggregate["rails.cache.read.time"][:count] end test 'cache write' do visit cache_write_path - assert_equal 1, counters["rails.cache.write"] + assert_equal 1, counters["rails.cache.write"][:value] assert_equal 1, aggregate["rails.cache.write.time"][:count] end test 'cache fetch_hit' do visit cache_fetch_hit_path - assert_equal 1, counters["rails.cache.fetch_hit"] + assert_equal 1, counters["rails.cache.fetch_hit"][:value] assert_equal 1, aggregate["rails.cache.fetch_hit.time"][:count] end test 'cache generate' do visit cache_generate_path - assert_equal 1, counters["rails.cache.generate"] + assert_equal 1, counters["rails.cache.generate"][:value] assert_equal 1, aggregate["rails.cache.generate.time"][:count] end test 'cache delete' do visit cache_delete_path - assert_equal 1, counters["rails.cache.delete"] + assert_equal 1, counters["rails.cache.delete"][:value] assert_equal 1, aggregate["rails.cache.delete.time"][:count] end diff --git a/test/integration/custom_test.rb b/test/integration/custom_test.rb index 596d632..506e143 100644 --- a/test/integration/custom_test.rb +++ b/test/integration/custom_test.rb @@ -5,8 +5,8 @@ class CustomTest < ActiveSupport::IntegrationCase test 'controller access' do visit custom_path - assert_equal 1, counters['custom.visits'] - assert_equal 3, counters['custom.events'] + assert_equal 1, counters['custom.visits'][:value] + assert_equal 3, counters['custom.events'][:value] assert_equal 12, aggregate['custom.timing'][:sum] assert_equal 2, aggregate['custom.timing'][:count] @@ -15,7 +15,7 @@ class CustomTest < ActiveSupport::IntegrationCase test 'model class access' do visit custom_path - assert_equal 3, counters['custom.model.lookups'] + assert_equal 3, counters['custom.model.lookups'][:value] assert_equal 19.0, aggregate['custom.model.search'][:sum] assert_equal 2, aggregate['custom.model.search'][:count] end @@ -23,7 +23,7 @@ class CustomTest < ActiveSupport::IntegrationCase test 'model instance access' do visit custom_path - assert_equal 1, counters['custom.model.touch'] + assert_equal 1, counters['custom.model.touch'][:value] end end diff --git a/test/integration/instrument_action_test.rb b/test/integration/instrument_action_test.rb index 9ed4450..5b68d36 100644 --- a/test/integration/instrument_action_test.rb +++ b/test/integration/instrument_action_test.rb @@ -2,51 +2,99 @@ class InstrumentActionTest < ActiveSupport::IntegrationCase - test 'instrument controller action' do - visit instrument_action_path - - # puts aggregate.instance_variable_get(:@cache).queued.inspect - # puts counters.instance_variable_get(:@cache).inspect + test "instrument controller action" do + tags = { + controller: "InstrumentActionController", + action: "inst", + format: "html" + }.merge(default_tags) - source = 'InstrumentActionController.inst.html' + visit instrument_action_path - base = 'rails.action.request' + base = "rails.request" timings = %w{time time.db time.view} timings.each do |t| - assert_equal 1, aggregate.fetch("#{base}.#{t}", source: source)[:count] + assert_equal 1, aggregate.fetch("#{base}.#{t}", tags: tags)[:count] end - assert_equal 1, counters.fetch("#{base}.total", source: source) + assert_equal 1, counters.fetch("#{base}.total", tags: tags)[:value] end - test 'instrument all controller actions' do + test "instrument all controller actions" do visit base_action_1_path visit base_action_2_path - metric = 'rails.action.request.time' - - assert_equal 1, aggregate.fetch(metric, source: 'BaseController.action_1.html')[:count] - assert_equal 1, aggregate.fetch(metric, source: 'BaseController.action_2.html')[:count] + metric = "rails.request.time" + + assert_equal 1, aggregate.fetch(metric, + tags: { + controller: "BaseController", + action: "action_1", + format: "html" + }.merge(default_tags))[:count] + assert_equal 1, aggregate.fetch(metric, + tags: { + controller: "BaseController", + action: "action_2", + format: "html" + }.merge(default_tags))[:count] end - test 'instrument all controller actions for inherited controllers' do + test "instrument all controller actions for inherited controllers" do visit intermediate_action_1_path visit derived_action_1_path visit derived_action_2_path - metric = 'rails.action.request.time' - - assert_equal 1, aggregate.fetch(metric, source: 'IntermediateController.action_1.html')[:count] - assert_equal 1, aggregate.fetch(metric, source: 'DerivedController.action_1.html')[:count] - assert_equal 1, aggregate.fetch(metric, source: 'DerivedController.action_2.html')[:count] + metric = "rails.request.time" + + assert_equal 1, aggregate.fetch(metric, + tags: { + controller: "IntermediateController", + action: "action_1", + format: "html" + }.merge(default_tags))[:count] + assert_equal 1, aggregate.fetch(metric, + tags: { + controller: "DerivedController", + action: "action_1", + format: "html" + }.merge(default_tags))[:count] + assert_equal 1, aggregate.fetch(metric, + tags: { + controller: "DerivedController", + action: "action_2", + format: "html" + }.merge(default_tags))[:count] end - test 'instrument all controller actions for all controllers' do + test "instrument all controller actions for all controllers" do visit not_instrumented_path - metric = 'rails.action.request.time' + metric = "rails.request.time" + + assert_equal 1, aggregate.fetch(metric, + tags: { + controller: "InstrumentActionController", + action: "not", + format: "html" + }.merge(default_tags))[:count] + end + + test "instrument invalid format" do + Capybara.current_session.driver.header "Accept", "*/*" + + visit "/invalid_format" + + metric = "rails.request.time" + + assert_equal 1, aggregate.fetch(metric, + tags: { + controller: "InstrumentActionController", + action: "invalid_format", + format: "all" + }.merge(default_tags))[:count] - assert_equal 1, aggregate.fetch(metric, source: 'InstrumentActionController.not.html')[:count] + Capybara.current_session.driver.header "Accept", nil end end diff --git a/test/integration/job_test.rb b/test/integration/job_test.rb index fc5c145..3057970 100644 --- a/test/integration/job_test.rb +++ b/test/integration/job_test.rb @@ -3,16 +3,26 @@ class JobTest < ActiveSupport::IntegrationCase Librato::Rails::VersionSpecifier.supported(min: '4.2') do test 'jobs performed' do + tags = { + adapter: "inline_adapter", + job: "dummy_job" + }.merge(default_tags) + DummyJob.perform_now - assert_equal 1, counters['rails.job.perform'] - assert_equal 1, aggregate.fetch('rails.job.perform.time', source: 'DummyJob')[:count] + assert_equal 1, counters.fetch("rails.job.perform", tags: tags)[:value] + assert_equal 1, aggregate.fetch("rails.job.perform.time", tags: tags)[:count] end test 'jobs enqueued' do + tags = { + adapter: "inline_adapter", + job: "dummy_job" + }.merge(default_tags) + DummyJob.perform_later - assert_equal 1, counters['rails.job.enqueue'] + assert_equal 1, counters.fetch("rails.job.enqueue", tags: tags)[:value] end end end diff --git a/test/integration/mail_test.rb b/test/integration/mail_test.rb index 3e78d64..5df1851 100644 --- a/test/integration/mail_test.rb +++ b/test/integration/mail_test.rb @@ -4,8 +4,16 @@ class MailTest < ActiveSupport::IntegrationCase test 'mail sent' do user = User.create!(:email => 'foo@foo.com', :password => 'wow') + tags = { mailer: "UserMailer" }.merge(default_tags) UserMailer.welcome_email(user).deliver - assert_equal 1, counters["rails.mail.sent"] + assert_equal 1, counters.fetch("rails.mail.sent", tags: tags)[:value] + end + + test "mail received" do + user = User.create!(email: "foo@foo.com", password: "foobar") + tags = { mailer: "UserMailer" }.merge(default_tags) + UserMailer.receive(user.email) + assert_equal 1, counters.fetch("rails.mail.received", tags: tags)[:value] end end diff --git a/test/integration/render_test.rb b/test/integration/render_test.rb index 17ce51e..c8ab130 100644 --- a/test/integration/render_test.rb +++ b/test/integration/render_test.rb @@ -5,23 +5,23 @@ class RenderTest < ActiveSupport::IntegrationCase test 'render partial' do visit render_partial_path - assert_equal 1, counters.fetch("rails.view.render_partial", - source: 'render:first.html.erb') - assert_equal 1, counters.fetch("rails.view.render_partial", - source: 'render:second.html.erb') - assert_equal 1, aggregate.fetch("rails.view.render_partial.time", - source: 'render:first.html.erb')[:count] - assert_equal 1, aggregate.fetch("rails.view.render_partial.time", - source: 'render:second.html.erb')[:count] + assert_equal 1, counters.fetch("rails.view.render.partial", + tags: { partial: "render:first.html.erb" }.merge(default_tags))[:value] + assert_equal 1, counters.fetch("rails.view.render.partial", + tags: { partial: "render:second.html.erb" }.merge(default_tags))[:value] + assert_equal 1, aggregate.fetch("rails.view.render.partial.time", + tags: { partial: "render:first.html.erb" }.merge(default_tags))[:count] + assert_equal 1, aggregate.fetch("rails.view.render.partial.time", + tags: { partial: "render:second.html.erb" }.merge(default_tags))[:count] end test 'render template' do visit render_template_path - assert_equal 1, counters.fetch("rails.view.render_template", - source: 'render:template.html.erb') - assert_equal 1, aggregate.fetch("rails.view.render_template.time", - source: 'render:template.html.erb')[:count] + assert_equal 1, counters.fetch("rails.view.render.template", + tags: { template: "render:template.html.erb" }.merge(default_tags))[:value] + assert_equal 1, aggregate.fetch("rails.view.render.template.time", + tags: { template: "render:template.html.erb" }.merge(default_tags))[:count] end end diff --git a/test/integration/request_test.rb b/test/integration/request_test.rb index a2164ca..9c810e3 100644 --- a/test/integration/request_test.rb +++ b/test/integration/request_test.rb @@ -5,52 +5,67 @@ class RequestTest < ActiveSupport::IntegrationCase # Each request test 'increment total and status' do + tags_1 = { + controller: "HomeController", + action: "index", + format: "html" + }.merge(default_tags) + visit root_path - assert_equal 1, counters["rails.request.total"] - assert_equal 1, counters["rails.request.status.200"] - assert_equal 1, counters["rails.request.status.2xx"] - assert_equal 1, counters["rails.request.method.get"] + assert_equal 1, counters.fetch("rails.request.total", tags: tags_1)[:value] + assert_equal 1, counters.fetch("rails.request.status", tags: { status: 200 }.merge(default_tags))[:value] + assert_equal 1, counters.fetch("rails.request.method", tags: { method: "get" }.merge(default_tags))[:value] + + visit root_path + + assert_equal 2, counters.fetch("rails.request.total", tags: tags_1)[:value] + + tags_2 = { + controller: "StatusController", + action: "index", + format: "html" + }.merge(default_tags) visit '/status/204' - assert_equal 2, counters["rails.request.total"] - assert_equal 1, counters["rails.request.status.200"] - assert_equal 1, counters["rails.request.status.204"] - assert_equal 2, counters["rails.request.status.2xx"] + assert_equal 1, counters.fetch("rails.request.total", tags: tags_2)[:value] + assert_equal 1, counters.fetch("rails.request.status", tags: { status: 204 }.merge(default_tags))[:value] end test 'request times' do + tags = { + controller: "HomeController", + action: "index", + format: "html" + }.merge(default_tags) + visit root_path # common for all paths - assert_equal 1, aggregate["rails.request.time"][:count], + assert_equal 1, aggregate.fetch("rails.request.time", tags: tags)[:count], 'should record total time' - assert_equal 1, aggregate["rails.request.time.db"][:count], + assert_equal 1, aggregate.fetch("rails.request.time.db", tags: tags)[:count], 'should record db time' - assert_equal 1, aggregate["rails.request.time.view"][:count], + assert_equal 1, aggregate.fetch("rails.request.time.view", tags: tags)[:count], 'should record view time' # status specific - assert_equal 1, aggregate["rails.request.status.200.time"][:count] - assert_equal 1, aggregate["rails.request.status.2xx.time"][:count] + assert_equal 1, aggregate.fetch("rails.request.status.time", tags: { status: 200 }.merge(default_tags))[:count] # http method specific - assert_equal 1, aggregate["rails.request.method.get.time"][:count] - end - - test 'track exceptions' do - begin - visit exception_path #rescue nil - rescue RuntimeError => e - raise unless e.message == 'test exception!' - end - assert_equal 1, counters["rails.request.exceptions"] + assert_equal 1, aggregate.fetch("rails.request.method.time", tags: { method: "get" }.merge(default_tags))[:count] end test 'track slow requests' do + tags = { + controller: "HomeController", + action: "slow", + format: "html" + }.merge(default_tags) + visit slow_path - assert_equal 1, counters["rails.request.slow"] + assert_equal 1, counters.fetch("rails.request.slow", tags: tags)[:value] end -end \ No newline at end of file +end diff --git a/test/integration/sql_test.rb b/test/integration/sql_test.rb index 68807b6..21eb3ef 100644 --- a/test/integration/sql_test.rb +++ b/test/integration/sql_test.rb @@ -15,33 +15,43 @@ class SQLTest < ActiveSupport::IntegrationCase assert_increasing_queries do user = User.create!(email: 'foo@foo.com', password: 'wow') - assert_equal 1, counters["rails.sql.inserts"] + assert_equal 1, counters["rails.sql.inserts"][:value] end assert_increasing_queries do - prev = counters["rails.sql.selects"].to_i + prev = + if counters["rails.sql.selects"] + counters["rails.sql.selects"][:value].to_i + else + 0 + end foo = User.find_by_email('foo@foo.com') - assert_equal prev+1, counters["rails.sql.selects"] + assert_equal prev+1, counters["rails.sql.selects"][:value] end assert_increasing_queries do foo.password = 'new password' foo.save - assert_equal 1, counters["rails.sql.updates"] + assert_equal 1, counters["rails.sql.updates"][:value] end assert_increasing_queries do foo.destroy - assert_equal 1, counters["rails.sql.deletes"] + assert_equal 1, counters["rails.sql.deletes"][:value] end end private def assert_increasing_queries - previous = counters["rails.sql.queries"].to_i + previous = + if counters["rails.sql.queries"] + counters["rails.sql.queries"][:value].to_i + else + 0 + end yield - assert counters["rails.sql.queries"].to_i > previous + assert counters["rails.sql.queries"][:value].to_i > previous end end diff --git a/test/support/integration_case.rb b/test/support/integration_case.rb index e525ca8..8ce78d3 100644 --- a/test/support/integration_case.rb +++ b/test/support/integration_case.rb @@ -20,4 +20,8 @@ def collector def counters collector.counters end -end \ No newline at end of file + + def default_tags + collector.tags + end +end diff --git a/test/unit/configuration_test.rb b/test/unit/configuration_test.rb index 09afb1a..a7a86d5 100644 --- a/test/unit/configuration_test.rb +++ b/test/unit/configuration_test.rb @@ -7,24 +7,24 @@ class ConfigTest < MiniTest::Unit::TestCase def teardown ENV.delete('LIBRATO_USER') ENV.delete('LIBRATO_TOKEN') - ENV.delete('LIBRATO_SOURCE') + ENV.delete("LIBRATO_TAGS") # legacy ENV.delete('LIBRATO_METRICS_USER') ENV.delete('LIBRATO_METRICS_TOKEN') - ENV.delete('LIBRATO_METRICS_SOURCE') + ENV.delete("LIBRATO_METRICS_TAGS") end def test_environmental_variable_config ENV['LIBRATO_USER'] = 'foo@bar.com' ENV['LIBRATO_TOKEN'] = 'api_key' - ENV['LIBRATO_SOURCE'] = 'source' + ENV["LIBRATO_TAGS"] = "foo=bar" ENV['LIBRATO_SUITES'] = 'all' config = Configuration.new assert_equal 'foo@bar.com', config.user assert_equal 'api_key', config.token - assert_equal 'source', config.source + assert_equal "bar", config.tags[:foo] assert_equal 'all', config.suites - assert config.explicit_source?, 'source is explicit' + assert config.has_tags?, "tags are explicit" end def test_config_file_config @@ -33,28 +33,33 @@ def test_config_file_config assert_equal 'test api key', config.token assert_equal 'rails-test', config.prefix assert_equal 30, config.flush_interval - assert_equal 'custom-1', config.source - assert_equal false, config.source_pids + assert_equal "us-east-1", config.tags[:region] + assert_equal "b", config.tags[:az] assert_equal 'http://localhost:8080', config.proxy assert_equal 'all', config.suites - assert config.explicit_source?, 'source is explicit' + assert config.has_tags?, "tags are not explicit" end - def test_implicit_source + def test_detect_tags config = fixture_config('simple') assert_equal 'test@bar.com', config.user assert_equal 'test api key', config.token - assert !config.explicit_source?, 'source is not explicit' + config = fixture_config + assert config.tags[:host] # default tag + assert_equal "dummy", config.tags[:service] # default tag + assert_equal "test", config.tags[:environment] # default tag + assert_equal "us-east-1", config.tags[:region] # custom tag end def test_environmental_and_config_file_config ENV['LIBRATO_METRICS_USER'] = 'foo@bar.com' ENV['LIBRATO_METRICS_TOKEN'] = 'api_key' - ENV['LIBRATO_METRICS_SOURCE'] = 'source' config = fixture_config assert_equal 'test@bar.com', config.user # from config file assert_equal 'test api key', config.token # from config file assert_equal 'rails-test', config.prefix # from config file + assert_equal "us-east-1", config.tags[:region] # from config file + assert_equal "b", config.tags[:az] # from config file assert_equal 30, config.flush_interval # from config file end