From bc78d1ebad0c7459cf554ce818460bbc4cf6c49f Mon Sep 17 00:00:00 2001 From: Kyrylo Silin Date: Wed, 5 Sep 2018 20:41:13 +0800 Subject: [PATCH] Implement RouteSender and Airbrake.inc_request RouteSender aggregates information about requests and periodically sends collected data to Airbrake. The 'route_stats_flush_period' option allows: * refactoring unit tests without messing with Airbrake Ruby's internals * libraries that depend on airbrake-ruby can generate route stats faster. Without this option there's no way to configure the delay, so every time the user invokes this method, they have to wait 15 seconds for route stats. With this option we can set it 0 and the request will be invoked immediately This feature is currently in beta and not available for everyone. --- README.md | 16 ++++- lib/airbrake-ruby.rb | 27 ++++++++ lib/airbrake-ruby/config.rb | 7 ++ lib/airbrake-ruby/notifier.rb | 7 ++ lib/airbrake-ruby/response.rb | 9 ++- lib/airbrake-ruby/route_sender.rb | 106 ++++++++++++++++++++++++++++++ lib/airbrake-ruby/sync_sender.rb | 47 ++++++++----- spec/airbrake_spec.rb | 10 +++ spec/async_sender_spec.rb | 4 +- spec/config_spec.rb | 4 ++ spec/notifier_spec.rb | 10 +++ spec/response_spec.rb | 10 +-- spec/route_sender_spec.rb | 86 ++++++++++++++++++++++++ spec/sync_sender_spec.rb | 38 ++++++++--- 14 files changed, 342 insertions(+), 39 deletions(-) create mode 100644 lib/airbrake-ruby/route_sender.rb create mode 100644 spec/route_sender_spec.rb 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..004bc85c 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,7 +39,7 @@ 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: { @@ -50,7 +50,7 @@ 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