diff --git a/README.md b/README.md index 1883c58c..ccf6d367 100644 --- a/README.md +++ b/README.md @@ -402,9 +402,19 @@ Airbrake.configure do |c| end ``` -Note: this feature is not available for the free plan. However, you still can -send code hunks. Once you upgrade to a paid plan, old code hunks that you've -sent while being on the free plan would appear in the dashboard. +#### route_stats_flush_period + +By default, it's set to `15`. When `Airbrake.inc_request` is invoked, then +Airbrake Ruby waits 15 seconds trying to collect route stats. After this delay +it sends all route stats in a batch using only one web request. Setting this +value allows speeding up or slowing down this process. Zero value means no +delay. + +```ruby +Airbrake.configure do |c| + c.route_stats_flush_period = 0 +end +``` ### Asynchronous Airbrake options diff --git a/lib/airbrake-ruby.rb b/lib/airbrake-ruby.rb index 5b3f8520..fa226a01 100644 --- a/lib/airbrake-ruby.rb +++ b/lib/airbrake-ruby.rb @@ -4,6 +4,7 @@ require 'thread' require 'set' require 'socket' +require 'time' require 'airbrake-ruby/version' require 'airbrake-ruby/config' @@ -33,6 +34,7 @@ require 'airbrake-ruby/notifier' require 'airbrake-ruby/code_hunk' require 'airbrake-ruby/file_cache' +require 'airbrake-ruby/route_sender' # This module defines the Airbrake API. The user is meant to interact with # Airbrake via its public class methods. Before using the library, you must to @@ -115,6 +117,9 @@ def configured? # @macro see_public_api_method def merge_context(_context); end + + # @macro see_public_api_method + def inc_request(method, route, status_code, dur, time); end end # A Hash that holds all notifiers. The keys of the Hash are notifier @@ -343,5 +348,27 @@ def create_deploy(deploy_params) def merge_context(context) @notifiers[:default].merge_context(context) end + + # Increments request count of a certain +route+ that was invoked with + # +method+, and returned +status_code+ at +time+ and took +dur+ + # milliseconds. + # + # After a certain amount of time (n seconds) the aggregated route + # information will be sent to Airbrake. + # + # @example + # Airbrake.inc_request('POST', '/thing/:id/create', 200, 123, Time.now) + # + # @param [String] method The HTTP method that was invoked + # @param [String] route The route that was invoked + # @param [Integer] status_code The respose code that the route returned + # @param [Float] dur How much time the processing of the request took in + # milliseconds + # @param [Time] time When the request happened + # @return [void] + # @since v2.13.0 + def inc_request(method, route, status_code, dur, time) + @notifiers[:default].inc_request(method, route, status_code, dur, time) + end end end diff --git a/lib/airbrake-ruby/config.rb b/lib/airbrake-ruby/config.rb index 2d211b50..7912f413 100644 --- a/lib/airbrake-ruby/config.rb +++ b/lib/airbrake-ruby/config.rb @@ -83,6 +83,12 @@ class Config # @since v2.5.0 attr_accessor :code_hunks + # @return [Integer] how many seconds to wait before sending collected route + # stats + # @api public + # @since v2.13.0 + attr_accessor :route_stats_flush_period + # @param [Hash{Symbol=>Object}] user_config the hash to be used to build the # config def initialize(user_config = {}) @@ -113,6 +119,7 @@ def initialize(user_config = {}) ) self.versions = {} + self.route_stats_flush_period = 15 merge(user_config) end diff --git a/lib/airbrake-ruby/notifier.rb b/lib/airbrake-ruby/notifier.rb index 3ab5cde1..dfcd23a1 100644 --- a/lib/airbrake-ruby/notifier.rb +++ b/lib/airbrake-ruby/notifier.rb @@ -36,6 +36,8 @@ def initialize(user_config) @async_sender = AsyncSender.new(@config) @sync_sender = SyncSender.new(@config) + + @route_sender = RouteSender.new(@config) end # @macro see_public_api_method @@ -95,6 +97,11 @@ def merge_context(context) @context.merge!(context) end + # @macro see_public_api_method + def inc_request(*args) + @route_sender.inc_request(*args) + end + private def convert_to_exception(ex) diff --git a/lib/airbrake-ruby/response.rb b/lib/airbrake-ruby/response.rb index 3ff9d287..eafc6c3b 100644 --- a/lib/airbrake-ruby/response.rb +++ b/lib/airbrake-ruby/response.rb @@ -16,16 +16,19 @@ module Response # @param [Net::HTTPResponse] response # @param [Logger] logger # @return [Hash{String=>String}] parsed response - # rubocop:disable Metrics/MethodLength + # rubocop:disable Metrics/MethodLength, Metrics/AbcSize def self.parse(response, logger) code = response.code.to_i body = response.body begin case code + when 200 + logger.debug("#{LOG_LABEL} #{name} (#{code}): #{body}") + { response.msg => response.body } when 201 parsed_body = JSON.parse(body) - logger.debug("#{LOG_LABEL} #{parsed_body}") + logger.debug("#{LOG_LABEL} #{name} (#{code}): #{parsed_body}") parsed_body when 400, 401, 403, 420 parsed_body = JSON.parse(body) @@ -47,7 +50,7 @@ def self.parse(response, logger) { 'error' => ex.inspect } end end - # rubocop:enable Metrics/MethodLength + # rubocop:enable Metrics/MethodLength, Metrics/AbcSize def self.truncated_body(body) if body.nil? diff --git a/lib/airbrake-ruby/route_sender.rb b/lib/airbrake-ruby/route_sender.rb new file mode 100644 index 00000000..b1919696 --- /dev/null +++ b/lib/airbrake-ruby/route_sender.rb @@ -0,0 +1,106 @@ +module Airbrake + # RouteSender aggregates information about requests and periodically sends + # collected data to Airbrake. + # @since v2.13.0 + class RouteSender + # The key that represents a route. + RouteKey = Struct.new(:method, :route, :statusCode, :time) + + # RouteStat holds data that describes a route's performance. + RouteStat = Struct.new(:count, :sum, :sumsq, :min, :max) do + # @param [Integer] count The number of requests + # @param [Float] sum The sum of request duration in milliseconds + # @param [Float] sumsq The squared sum of request duration in milliseconds + # @param [Float] min The minimal request duration + # @param [Float] max The maximum request duration + def initialize(count: 0, sum: 0.0, sumsq: 0.0, min: 0.0, max: 0.0) + super(count, sum, sumsq, min, max) + end + end + + # @param [Airbrake::Config] config + def initialize(config) + @config = config + @flush_period = config.route_stats_flush_period + @sender = SyncSender.new(config, :put) + @routes = {} + @thread = nil + @mutex = Mutex.new + end + + # @macro see_public_api_method + def inc_request(method, route, status_code, dur, tm) + route = create_route_key(method, route, status_code, tm) + + promise = Airbrake::Promise.new + + @mutex.synchronize do + @routes[route] ||= RouteStat.new + increment_stats(@routes[route], dur) + + if @flush_period > 0 + schedule_flush(promise) + else + send(@routes, promise) + end + end + + promise + end + + private + + def create_route_key(method, route, status_code, tm) + # rubocop:disable Style/DateTime + time = DateTime.new( + tm.year, tm.month, tm.day, tm.hour, tm.min, 0, tm.zone || 0 + ) + # rubocop:enable Style/DateTime + RouteKey.new(method, route, status_code, time.rfc3339) + end + + def increment_stats(stat, dur) + stat.count += 1 + + ms = dur.to_f + stat.sum += ms + stat.sumsq += ms * ms + + stat.min = ms if ms < stat.min || stat.min == 0 + stat.max = ms if ms > stat.max + end + + def schedule_flush(promise) + @thread ||= Thread.new do + sleep(@flush_period) + + routes = nil + @mutex.synchronize do + routes = @routes + @routes = {} + @thread = nil + end + + send(routes, promise) + end + + # Setting a name is needed to test the timer. + # Ruby <=2.2 doesn't support Thread#name, so we have this check. + @thread.name = 'route-stat-thread' if @thread.respond_to?(:name) + end + + def send(routes, promise) + if routes.none? + raise "#{self.class.name}##{__method__}: routes cannot be empty. Race?" + end + + @config.logger.debug("#{LOG_LABEL} RouteStats#send: #{routes}") + + @sender.send( + { routes: routes.map { |k, v| k.to_h.merge(v.to_h) } }, + promise, + URI.join(@config.host, "api/v4/projects/#{@config.project_id}/routes-stats") + ) + end + end +end diff --git a/lib/airbrake-ruby/sync_sender.rb b/lib/airbrake-ruby/sync_sender.rb index edf183d0..d8d04239 100644 --- a/lib/airbrake-ruby/sync_sender.rb +++ b/lib/airbrake-ruby/sync_sender.rb @@ -1,5 +1,6 @@ module Airbrake - # Responsible for sending notices to Airbrake synchronously. Supports proxies. + # Responsible for sending data to Airbrake synchronously via PUT or POST + # methods. Supports proxies. # # @see AsyncSender # @api private @@ -9,21 +10,22 @@ class SyncSender CONTENT_TYPE = 'application/json'.freeze # @param [Airbrake::Config] config - def initialize(config) + def initialize(config, method = :post) @config = config + @method = method @rate_limit_reset = Time.now end - # Sends a POST request to the given +endpoint+ with the +notice+ payload. + # Sends a POST or PUT request to the given +endpoint+ with the +data+ payload. # - # @param [Airbrake::Notice] notice - # @param [Airbrake::Notice] endpoint + # @param [#to_json] data + # @param [URI::HTTPS] endpoint # @return [Hash{String=>String}] the parsed HTTP response - def send(notice, promise, endpoint = @config.endpoint) + def send(data, promise, endpoint = @config.endpoint) return promise if rate_limited_ip?(promise) response = nil - req = build_post_request(endpoint, notice) + req = build_request(endpoint, data) return promise if missing_body?(req, promise) @@ -58,16 +60,27 @@ def build_https(uri) end end - def build_post_request(uri, notice) - Net::HTTP::Post.new(uri.request_uri).tap do |req| - req.body = notice.to_json + def build_request(uri, data) + req = + if @method == :put + Net::HTTP::Put.new(uri.request_uri) + else + Net::HTTP::Post.new(uri.request_uri) + end - req['Authorization'] = "Bearer #{@config.project_key}" - req['Content-Type'] = CONTENT_TYPE - req['User-Agent'] = - "#{Airbrake::Notice::NOTIFIER[:name]}/#{Airbrake::AIRBRAKE_RUBY_VERSION}" \ - " Ruby/#{RUBY_VERSION}" - end + build_request_body(req, data) + end + + def build_request_body(req, data) + req.body = data.to_json + + req['Authorization'] = "Bearer #{@config.project_key}" + req['Content-Type'] = CONTENT_TYPE + req['User-Agent'] = + "#{Airbrake::Notice::NOTIFIER[:name]}/#{Airbrake::AIRBRAKE_RUBY_VERSION}" \ + " Ruby/#{RUBY_VERSION}" + + req end def proxy_params @@ -87,7 +100,7 @@ def missing_body?(req, promise) missing = req.body.nil? if missing - reason = "#{LOG_LABEL} notice was not sent because of missing body" + reason = "#{LOG_LABEL} data was not sent because of missing body" @config.logger.error(reason) promise.reject(reason) end diff --git a/spec/airbrake_spec.rb b/spec/airbrake_spec.rb index f57d2f66..7b227b91 100644 --- a/spec/airbrake_spec.rb +++ b/spec/airbrake_spec.rb @@ -110,4 +110,14 @@ described_class.merge_context(foo: 'bar') end end + + describe ".inc_request" do + it "forwards 'inc_request' to the notifier" do + t = Time.now + expect(default_notifier).to receive(:inc_request).with( + 'GET', '/foo', 200, 1000, t + ) + described_class.inc_request('GET', '/foo', 200, 1000, t) + end + end end diff --git a/spec/async_sender_spec.rb b/spec/async_sender_spec.rb index 1492d7c2..3098d98c 100644 --- a/spec/async_sender_spec.rb +++ b/spec/async_sender_spec.rb @@ -21,7 +21,7 @@ sender.close log = stdout.string.split("\n") - notices_sent = log.grep(/\*\*Airbrake: \{\}/).size + notices_sent = log.grep(/\*\*Airbrake: Airbrake::Response \(201\): \{\}/).size notices_dropped = log.grep(/\*\*Airbrake:.*not.*delivered/).size expect(notices_sent).to be >= queue_size expect(notices_sent + notices_dropped).to eq(notices_count) @@ -60,7 +60,7 @@ it "prints the correct number of log messages" do log = @stderr.string.split("\n") - notices_sent = log.grep(/\*\*Airbrake: \{\}/).size + notices_sent = log.grep(/\*\*Airbrake: Airbrake::Response \(201\): \{\}/).size notices_dropped = log.grep(/\*\*Airbrake:.*not.*delivered/).size expect(notices_sent).to be >= @sender.instance_variable_get(:@unsent).max expect(notices_sent + notices_dropped).to eq(300) diff --git a/spec/config_spec.rb b/spec/config_spec.rb index 16640df7..d056c99b 100644 --- a/spec/config_spec.rb +++ b/spec/config_spec.rb @@ -78,6 +78,10 @@ it "doesn't set default whitelist" do expect(config.whitelist_keys).to be_empty end + + it "sets the default route_stats_flush_period" do + expect(config.route_stats_flush_period).to eq(15) + end end end diff --git a/spec/notifier_spec.rb b/spec/notifier_spec.rb index 6751e2d9..f5c16278 100644 --- a/spec/notifier_spec.rb +++ b/spec/notifier_spec.rb @@ -449,5 +449,15 @@ subject.merge_context(apples: 'oranges') end end + + describe "#inc_request" do + it "forwards 'inc_request' to RouteSender" do + t = Time.now + expect_any_instance_of(Airbrake::RouteSender).to receive(:inc_request).with( + 'GET', '/foo', 200, 1000, t + ) + subject.inc_request('GET', '/foo', 200, 1000, t) + end + end end # rubocop:enable Layout/DotPosition diff --git a/spec/response_spec.rb b/spec/response_spec.rb index 29fc50cb..743ac587 100644 --- a/spec/response_spec.rb +++ b/spec/response_spec.rb @@ -5,10 +5,12 @@ let(:out) { StringIO.new } let(:logger) { Logger.new(out) } - context "when response code is 201" do - it "logs response body" do - described_class.parse(OpenStruct.new(code: 201, body: '{}'), logger) - expect(out.string).to match(/Airbrake: {}/) + [200, 201].each do |code| + context "when response code is #{code}" do + it "logs response body" do + described_class.parse(OpenStruct.new(code: code, body: '{}'), logger) + expect(out.string).to match(/Airbrake: Airbrake::Response \(#{code}\): {}/) + end end end diff --git a/spec/route_sender_spec.rb b/spec/route_sender_spec.rb new file mode 100644 index 00000000..f586896c --- /dev/null +++ b/spec/route_sender_spec.rb @@ -0,0 +1,86 @@ +require 'spec_helper' + +RSpec.describe Airbrake::RouteSender do + let(:endpoint) { 'https://api.airbrake.io/api/v4/projects/1/routes-stats' } + + let(:config) do + Airbrake::Config.new( + project_id: 1, + project_key: 'banana', + route_stats_flush_period: 0.1 + ) + end + + subject { described_class.new(config) } + + describe "#inc_request" do + before do + stub_request(:put, endpoint).to_return(status: 200, body: '') + end + + # Let the request finish. + after { sleep 0.2 } + + it "rounds time to the floor minute" do + subject.inc_request('GET', '/foo', 200, 24, Time.new(2018, 1, 1, 0, 0, 20, 0)) + sleep 0.2 + expect( + a_request(:put, endpoint).with(body: /"time":"2018-01-01T00:00:00\+00:00"/) + ).to have_been_made + end + + it "increments routes with the same key" do + subject.inc_request('GET', '/foo', 200, 24, Time.new(2018, 1, 1, 0, 0, 20, 0)) + subject.inc_request('GET', '/foo', 200, 24, Time.new(2018, 1, 1, 0, 0, 50, 0)) + sleep 0.2 + expect( + a_request(:put, endpoint).with(body: /"count":2/) + ).to have_been_made + end + + it "groups routes by time" do + subject.inc_request('GET', '/foo', 200, 24, Time.new(2018, 1, 1, 0, 0, 20, 0)) + subject.inc_request('GET', '/foo', 200, 10, Time.new(2018, 1, 1, 0, 1, 20, 0)) + sleep 0.2 + expect( + a_request(:put, endpoint).with( + body: %r|\A + {"routes":\[ + {"method":"GET","route":"/foo","statusCode":200, + "time":"2018-01-01T00:00:00\+00:00","count":1,"sum":24.0, + "sumsq":576.0,"min":24.0,"max":24.0}, + {"method":"GET","route":"/foo","statusCode":200, + "time":"2018-01-01T00:01:00\+00:00","count":1,"sum":10.0, + "sumsq":100.0,"min":10.0,"max":10.0}\]} + \z|x + ) + ).to have_been_made + end + + it "groups routes by route key" do + subject.inc_request('GET', '/foo', 200, 24, Time.new(2018, 1, 1, 0, 0, 20, 0)) + subject.inc_request('POST', '/foo', 200, 10, Time.new(2018, 1, 1, 0, 0, 20, 0)) + sleep 0.2 + expect( + a_request(:put, endpoint).with( + body: %r|\A + {"routes":\[ + {"method":"GET","route":"/foo","statusCode":200, + "time":"2018-01-01T00:00:00\+00:00","count":1,"sum":24.0, + "sumsq":576.0,"min":24.0,"max":24.0}, + {"method":"POST","route":"/foo","statusCode":200, + "time":"2018-01-01T00:00:00\+00:00","count":1,"sum":10.0, + "sumsq":100.0,"min":10.0,"max":10.0}\]} + \z|x + ) + ).to have_been_made + end + + it "returns a promise" do + promise = subject.inc_request('GET', '/foo', 200, 24, Time.new) + sleep 0.2 + expect(promise).to be_an(Airbrake::Promise) + expect(promise.value).to eq('' => nil) + end + end +end diff --git a/spec/sync_sender_spec.rb b/spec/sync_sender_spec.rb index 6d3e01ba..d95e0980 100644 --- a/spec/sync_sender_spec.rb +++ b/spec/sync_sender_spec.rb @@ -30,7 +30,7 @@ before { stub_request(:post, endpoint).to_return(body: '{}') } it "sets the Content-Type header to JSON" do - sender.send(notice, promise) + sender.send({}, promise) expect( a_request(:post, endpoint).with( headers: { 'Content-Type' => 'application/json' } @@ -39,18 +39,18 @@ end it "sets the User-Agent header to the notifier slug" do - sender.send(notice, promise) + sender.send({}, promise) expect( a_request(:post, endpoint).with( headers: { - 'User-Agent' => %r{airbrake-ruby/\d+\.\d+\.\d+ Ruby/\d+\.\d+\.\d+} + 'User-Agent' => %r{airbrake-ruby/\d+\.\d+\.\d+\.lab Ruby/\d+\.\d+\.\d+} } ) ).to have_been_made.once end it "sets the Authorization header to the project key" do - sender.send(notice, promise) + sender.send({}, promise) expect( a_request(:post, endpoint).with( headers: { 'Authorization' => 'Bearer banana' } @@ -62,13 +62,13 @@ https = double("foo") allow(sender).to receive(:build_https).and_return(https) allow(https).to receive(:request).and_raise(StandardError.new('foo')) - expect(sender.send(notice, promise)).to be_an(Airbrake::Promise) + expect(sender.send({}, promise)).to be_an(Airbrake::Promise) expect(promise.value).to eq('error' => '**Airbrake: HTTP error: foo') expect(stdout.string).to match(/ERROR -- : .+ HTTP error: foo/) end context "when request body is nil" do - it "doesn't send a notice" do + it "doesn't send data" do expect_any_instance_of(Airbrake::Truncator). to receive(:reduce_max_size).and_return(0) @@ -84,8 +84,8 @@ expect(sender.send(notice, promise)).to be_an(Airbrake::Promise) expect(promise.value). - to match('error' => '**Airbrake: notice was not sent because of missing body') - expect(stdout.string).to match(/ERROR -- : .+ notice was not sent/) + to match('error' => '**Airbrake: data was not sent because of missing body') + expect(stdout.string).to match(/ERROR -- : .+ data was not sent/) end end @@ -102,11 +102,11 @@ it "returns error" do p1 = Airbrake::Promise.new - sender.send(notice, p1) + sender.send({}, p1) expect(p1.value).to match('error' => '**Airbrake: IP is rate limited') p2 = Airbrake::Promise.new - sender.send(notice, p2) + sender.send({}, p2) expect(p2.value).to match('error' => '**Airbrake: IP is rate limited') # Wait for X-RateLimit-Delay and then make a new request to make sure p2 @@ -114,11 +114,29 @@ sleep 1 p3 = Airbrake::Promise.new - sender.send(notice, p3) + sender.send({}, p3) expect(p3.value).to match('error' => '**Airbrake: IP is rate limited') expect(a_request(:post, endpoint)).to have_been_made.twice end end + + context "when the provided method is :put" do + before { stub_request(:put, endpoint).to_return(status: 200, body: '') } + + it "PUTs the request" do + sender = described_class.new(config, :put) + sender.send({}, promise) + expect(a_request(:put, endpoint)).to have_been_made + end + end + + context "when the provided method is :post" do + it "POSTs the request" do + sender = described_class.new(config, :post) + sender.send({}, promise) + expect(a_request(:post, endpoint)).to have_been_made + end + end end end