From d108a583b006bde91ff219c8565ced796a0a9274 Mon Sep 17 00:00:00 2001 From: Tom de Bruijn Date: Thu, 30 May 2024 22:18:28 +0200 Subject: [PATCH] Improve Rails/Rack request instrumentation Rework the Rails instrumentation to use the Rack::Events module to start and complete the transaction at the very start and end of the request. A new middleware is added at the very top of the middleware stack to start and complete the transaction. This allows us to instrument more of the request's duration, as we're now at the very start and end of the request handling. We will now report the time the request has spend handling any other middleware. This will be visible with a new `process_request.rack` event. To make sure we always close the transaction, listen for the `on_finish` event, but also register a last resort "after_reply" callback. This callback is supported by web servers like Puma and Unicorn. If it's called when a transaction is active, it will close it, preventing transactions to span multiple requests. If no transaction is active, it will do nothing. Moving forward, I'd like to update our Rack, Sinatra, Padrino, Grape, etc. instrumentations to use this EventHandler middleware too, which will be a bit more work, because some require users to manually add middleware. When they all use the same EventHandler, we have one place to start and complete transactions, and issues like https://github.com/appsignal/appsignal-ruby/issues/289 cannot happen again in the future. Previously, our only Rails instrumentation was positioned after the DebugExceptions middleware, just in time to catch any errors before the Rails error middleware showed a nice error/debug page. This wouldn't show the complete picture in request duration. The original Rails instrumentation middleware will remain to report errors and Rails specific metadata. This cannot be part of the EventHandler, without overloading it with responsibilities, and for Rails error reporting we need to be right after the DebugExceptions middleware before errors are no longer bubbled up in the stack. Instead of the transaction ID being the request ID, set a new `request_id` tag to not break existing behavior. Part of https://github.com/appsignal/appsignal-ruby/issues/329 --- ...-request-middleware-in-request-duration.md | 6 + lib/appsignal.rb | 1 + lib/appsignal/integrations/railtie.rb | 5 + lib/appsignal/rack/event_handler.rb | 83 ++++++++ lib/appsignal/rack/rails_instrumentation.rb | 41 ++-- spec/lib/appsignal/rack/event_handler_spec.rb | 191 ++++++++++++++++++ .../rack/rails_instrumentation_spec.rb | 64 +++--- 7 files changed, 344 insertions(+), 47 deletions(-) create mode 100644 .changesets/report-rails-request-middleware-in-request-duration.md create mode 100644 lib/appsignal/rack/event_handler.rb create mode 100644 spec/lib/appsignal/rack/event_handler_spec.rb diff --git a/.changesets/report-rails-request-middleware-in-request-duration.md b/.changesets/report-rails-request-middleware-in-request-duration.md new file mode 100644 index 000000000..5109c181b --- /dev/null +++ b/.changesets/report-rails-request-middleware-in-request-duration.md @@ -0,0 +1,6 @@ +--- +bump: minor +type: change +--- + +Report the time spent in Rails middleware as part of the request duration. The AppSignal Rack middleware is now higher in the middleware stack and reports more time of the request to give insights in how long other middleware took. This is reported under the new `process_request.rack` event in the event timeline. diff --git a/lib/appsignal.rb b/lib/appsignal.rb index 0b2edf3e4..0394c9734 100644 --- a/lib/appsignal.rb +++ b/lib/appsignal.rb @@ -325,5 +325,6 @@ def const_missing(name) require "appsignal/transaction" require "appsignal/version" require "appsignal/rack/generic_instrumentation" +require "appsignal/rack/event_handler" require "appsignal/transmitter" require "appsignal/heartbeat" diff --git a/lib/appsignal/integrations/railtie.rb b/lib/appsignal/integrations/railtie.rb index 856046cfb..e1ea2255e 100644 --- a/lib/appsignal/integrations/railtie.rb +++ b/lib/appsignal/integrations/railtie.rb @@ -29,6 +29,11 @@ def self.initialize_appsignal(app) # Start logger Appsignal.start_logger + app.middleware.insert( + 0, + ::Rack::Events, + [Appsignal::Rack::EventHandler.new] + ) app.middleware.insert_after( ActionDispatch::DebugExceptions, Appsignal::Rack::RailsInstrumentation diff --git a/lib/appsignal/rack/event_handler.rb b/lib/appsignal/rack/event_handler.rb new file mode 100644 index 000000000..53c4afe6c --- /dev/null +++ b/lib/appsignal/rack/event_handler.rb @@ -0,0 +1,83 @@ +# frozen_string_literal: true + +module Appsignal + module Rack + APPSIGNAL_TRANSACTION = "appsignal.transaction" + RACK_AFTER_REPLY = "rack.after_reply" + + class EventHandler + include ::Rack::Events::Abstract + + def self.safe_execution(name) + yield + rescue => e + Appsignal.internal_logger.error( + "Error occurred in #{name}: #{e.class}: #{e}: #{e.backtrace}" + ) + end + + def on_start(request, _response) + self.class.safe_execution("Appsignal::Rack::EventHandler#on_start") do + transaction = Appsignal::Transaction.create( + SecureRandom.uuid, + Appsignal::Transaction::HTTP_REQUEST, + request + ) + request.env[APPSIGNAL_TRANSACTION] = transaction + + request.env[RACK_AFTER_REPLY] ||= [] + request.env[RACK_AFTER_REPLY] << proc do + Appsignal::Rack::EventHandler.safe_execution("Appsignal::Rack::EventHandler's after_reply") do + transaction.finish_event("process_request.rack", "", "") + transaction.set_http_or_background_queue_start + + # Make sure the current transaction is always closed when the request + # is finished. This is a fallback for in case the `on_finish` + # callback is not called. This is supported by servers like Puma and + # Unicorn. + # + # The EventHandler.on_finish callback should be called first, this is + # just a fallback if that doesn't get called. + Appsignal::Transaction.complete_current! + end + end + transaction.start_event + end + end + + def on_error(request, _response, error) + self.class.safe_execution("Appsignal::Rack::EventHandler#on_error") do + transaction = request.env[APPSIGNAL_TRANSACTION] + return unless transaction + + transaction.set_error(error) + end + end + + def on_finish(request, _response) + self.class.safe_execution("Appsignal::Rack::EventHandler#on_finish") do + transaction = request.env[APPSIGNAL_TRANSACTION] + return unless transaction + + transaction.finish_event("process_request.rack", "", "") + transaction.set_action_if_nil("#{request.request_method} #{request.path}") + transaction.set_http_or_background_queue_start + + # Make sure the current transaction is always closed when the request + # is finished + Appsignal::Transaction.complete_current! + end + end + + private + + def format_namespace(namespace) + if namespace == Appsignal::Transaction::HTTP_REQUEST + :web + else + namespace + end + end + end + end +end diff --git a/lib/appsignal/rack/rails_instrumentation.rb b/lib/appsignal/rack/rails_instrumentation.rb index 8de088cd1..bfa073063 100644 --- a/lib/appsignal/rack/rails_instrumentation.rb +++ b/lib/appsignal/rack/rails_instrumentation.rb @@ -22,13 +22,16 @@ def call(env) def call_with_appsignal_monitoring(env) request = ActionDispatch::Request.new(env) - transaction = Appsignal::Transaction.create( - request_id(env), - Appsignal::Transaction::HTTP_REQUEST, - request, - :params_method => :filtered_parameters + transaction = env.fetch( + Appsignal::Rack::APPSIGNAL_TRANSACTION, + Appsignal::Transaction::NilTransaction.new ) + begin + transaction.params = fetch_params(request) + request_id = fetch_request_id(env) + transaction.set_tags(:request_id => request_id) if request_id + @app.call(env) rescue Exception => error # rubocop:disable Lint/RescueException transaction.set_error(error) @@ -38,19 +41,29 @@ def call_with_appsignal_monitoring(env) if controller transaction.set_action_if_nil("#{controller.class}##{controller.action_name}") end - transaction.set_http_or_background_queue_start transaction.set_metadata("path", request.path) - begin - transaction.set_metadata("method", request.request_method) - rescue => error - Appsignal.internal_logger.error("Unable to report HTTP request method: '#{error}'") - end - Appsignal::Transaction.complete_current! + request_method = fetch_request_method(request) + transaction.set_metadata("method", request_method) if request_method end end - def request_id(env) - env["action_dispatch.request_id"] || SecureRandom.uuid + def fetch_request_id(env) + env["action_dispatch.request_id"] + end + + def fetch_params(request) + request.filtered_parameters + rescue => error + # Getting params from the request has been know to fail. + Appsignal.internal_logger.debug "Exception while getting params: #{error}" + nil + end + + def fetch_request_method(request) + request.request_method + rescue => error + Appsignal.internal_logger.error("Unable to report HTTP request method: '#{error}'") + nil end end end diff --git a/spec/lib/appsignal/rack/event_handler_spec.rb b/spec/lib/appsignal/rack/event_handler_spec.rb new file mode 100644 index 000000000..e314fc109 --- /dev/null +++ b/spec/lib/appsignal/rack/event_handler_spec.rb @@ -0,0 +1,191 @@ +describe Appsignal::Rack::EventHandler do + let(:queue_start_time) { fixed_time * 1_000 } + let(:env) do + { + "HTTP_X_REQUEST_START" => "t=#{queue_start_time.to_i}", # in milliseconds + "REQUEST_METHOD" => "GET", + "PATH_INFO" => "/path" + } + end + let(:request) { Rack::Request.new(env) } + let(:response) { nil } + let(:log_stream) { StringIO.new } + let(:log) { log_contents(log_stream) } + before do + start_agent + Appsignal.internal_logger = test_logger(log_stream) + end + around { |example| keep_transactions { example.run } } + + def on_start + described_class.new.on_start(request, response) + end + + describe "#on_start" do + it "creates a new transaction" do + expect { on_start }.to change { created_transactions.length }.by(1) + + transaction = last_transaction + expect(transaction.to_h).to include( + "id" => kind_of(String), + "namespace" => Appsignal::Transaction::HTTP_REQUEST + ) + + expect(Appsignal::Transaction.current).to eq(last_transaction) + end + + it "registers transaction on the request environment" do + on_start + + expect(request.env[Appsignal::Rack::APPSIGNAL_TRANSACTION]) + .to eq(last_transaction) + end + + it "registers an rack.after_reply callback that completes the transaction" do + request.env[Appsignal::Rack::RACK_AFTER_REPLY] = [] + expect do + on_start + end.to change { request.env[Appsignal::Rack::RACK_AFTER_REPLY].length }.by(1) + + expect(Appsignal::Transaction.current).to eq(last_transaction) + + callback = request.env[Appsignal::Rack::RACK_AFTER_REPLY].first + callback.call + + expect(Appsignal::Transaction.current).to be_kind_of(Appsignal::Transaction::NilTransaction) + + expect(last_transaction.ext.queue_start).to eq(queue_start_time) + end + + it "logs errors from rack.after_reply callbacks" do + on_start + + expect(request.env[Appsignal::Rack::APPSIGNAL_TRANSACTION]) + .to receive(:finish_event) + .and_raise(ExampleStandardError, "oh no") + callback = request.env[Appsignal::Rack::RACK_AFTER_REPLY].first + callback.call + + expect(log).to contains_log( + :error, + "Error occurred in Appsignal::Rack::EventHandler's after_reply: ExampleStandardError: oh no" + ) + end + + it "logs an error in case of an error" do + expect(Appsignal::Transaction) + .to receive(:create).and_raise(ExampleStandardError, "oh no") + + on_start + + expect(log).to contains_log( + :error, + "Error occurred in Appsignal::Rack::EventHandler#on_start: ExampleStandardError: oh no" + ) + end + end + + describe "#on_error" do + def on_error(error) + described_class.new.on_error(request, response, error) + end + + it "reports the error" do + on_start + on_error(ExampleStandardError.new("the error")) + + expect(last_transaction.to_h).to include( + "error" => { + "name" => "ExampleStandardError", + "message" => "the error", + "backtrace" => kind_of(String) + } + ) + end + + it "logs an error in case of an internal error" do + on_start + + expect(request.env[Appsignal::Rack::APPSIGNAL_TRANSACTION]) + .to receive(:set_error).and_raise(ExampleStandardError, "oh no") + + on_error(ExampleStandardError.new("the error")) + + expect(log).to contains_log( + :error, + "Error occurred in Appsignal::Rack::EventHandler#on_error: ExampleStandardError: oh no" + ) + end + end + + describe "#on_finish" do + let(:response) { Rack::Events::BufferedResponse.new(200, {}, ["body"]) } + + def on_finish + described_class.new.on_finish(request, response) + end + + it "doesn't do anything without a transaction" do + on_start + + request.env[Appsignal::Rack::APPSIGNAL_TRANSACTION] = nil + + on_finish + + expect(last_transaction.to_h).to include( + "action" => nil, + "sample_data" => {}, + "events" => [] + ) + end + + it "completes the transaction" do + on_start + on_finish + + expect(last_transaction.to_h).to include( + "action" => "GET /path" + ) + expect(last_transaction.ext.queue_start).to eq(queue_start_time) + end + + it "doesn't set the action name if already set" do + on_start + last_transaction.set_action("My action") + on_finish + + expect(last_transaction.to_h).to include( + "action" => "My action" + ) + end + + it "finishes the process_request.rack event" do + on_start + on_finish + + expect(last_transaction.to_h).to include( + "events" => [ + hash_including( + "name" => "process_request.rack", + "title" => "", + "body" => "", + "body_format" => Appsignal::EventFormatter::DEFAULT + ) + ] + ) + end + + it "logs an error in case of an error" do + expect(Appsignal::Transaction) + .to receive(:complete_current!).and_raise(ExampleStandardError, "oh no") + + on_start + on_finish + + expect(log).to contains_log( + :error, + "Error occurred in Appsignal::Rack::EventHandler#on_finish: ExampleStandardError: oh no" + ) + end + end +end diff --git a/spec/lib/appsignal/rack/rails_instrumentation_spec.rb b/spec/lib/appsignal/rack/rails_instrumentation_spec.rb index 481854b11..2d8a4a3ee 100644 --- a/spec/lib/appsignal/rack/rails_instrumentation_spec.rb +++ b/spec/lib/appsignal/rack/rails_instrumentation_spec.rb @@ -9,6 +9,14 @@ class MockController Appsignal.internal_logger = test_logger(log) end + let(:transaction) do + Appsignal::Transaction.new( + "transaction_id", + Appsignal::Transaction::HTTP_REQUEST, + Rack::Request.new(env) + ) + end + let(:app) { double(:call => true) } let(:params) do { "controller" => "blog_posts", @@ -19,12 +27,11 @@ class MockController } end let(:env_extra) { {} } - let(:app) { double(:call => true) } let(:env) do http_request_env_with_data({ :params => params, :with_queue_start => true, - "action_dispatch.request_id" => "1", + "action_dispatch.request_id" => "request_id123", "action_dispatch.parameter_filter" => [:my_custom_param, :password], "action_controller.instance" => double( :class => MockController, @@ -34,6 +41,9 @@ class MockController end let(:middleware) { Appsignal::Rack::RailsInstrumentation.new(app, {}) } around { |example| keep_transactions { example.run } } + before do + env[Appsignal::Rack::APPSIGNAL_TRANSACTION] = transaction + end describe "#call" do before do @@ -43,7 +53,7 @@ class MockController context "when appsignal is active" do before { allow(Appsignal).to receive(:active?).and_return(true) } - it "should call with monitoring" do + it "calls with monitoring" do expect(middleware).to receive(:call_with_appsignal_monitoring).with(env) end end @@ -51,11 +61,11 @@ class MockController context "when appsignal is not active" do before { allow(Appsignal).to receive(:active?).and_return(false) } - it "should not call with monitoring" do + it "does not call with monitoring" do expect(middleware).to_not receive(:call_with_appsignal_monitoring) end - it "should call the app" do + it "calls the app" do expect(app).to receive(:call).with(env) end end @@ -66,36 +76,34 @@ class MockController describe "#call_with_appsignal_monitoring" do def run middleware.call(env) + last_transaction.complete # Manually close transaction to set sample data end it "calls the wrapped app" do - run + expect { run }.to_not(change { created_transactions.length }) expect(app).to have_received(:call).with(env) end - it "creates one transaction with metadata" do + it "sets request metadata on the transaction" do run - expect(created_transactions.length).to eq(1) - transaction_hash = last_transaction.to_h - expect(transaction_hash).to include( + expect(last_transaction.to_h).to include( "namespace" => Appsignal::Transaction::HTTP_REQUEST, "action" => "MockController#index", "metadata" => hash_including( "method" => "GET", "path" => "/blog" + ), + "sample_data" => hash_including( + "tags" => { "request_id" => "request_id123" } ) ) - expect(last_transaction.ext.queue_start).to eq( - fixed_time * 1_000.0 - ) end - it "filter parameters in Rails" do + it "reports Rails filter parameters" do run - transaction_hash = last_transaction.to_h - expect(transaction_hash).to include( + expect(last_transaction.to_h).to include( "sample_data" => hash_including( "params" => params.merge( "my_custom_param" => "[FILTERED]", @@ -113,8 +121,8 @@ def run transaction_hash = last_transaction.to_h expect(transaction_hash["metadata"]).to_not have_key("method") - expect(log_contents(log)).to contains_log(:error, - "Unable to report HTTP request method: '") + expect(log_contents(log)) + .to contains_log(:error, "Unable to report HTTP request method: '") end end @@ -139,23 +147,13 @@ def run end end - describe "#request_id" do - subject { middleware.request_id(env) } - - context "with request id present" do - let(:env) { { "action_dispatch.request_id" => "id" } } - - it "returns the present id" do - is_expected.to eq "id" - end - end + describe "#fetch_request_id" do + subject { middleware.fetch_request_id(env) } - context "with request id not present" do - let(:env) { {} } + let(:env) { { "action_dispatch.request_id" => "id" } } - it "sets a new id" do - expect(subject.length).to eq 36 - end + it "returns the action dispatch id" do + is_expected.to eq "id" end end end