diff --git a/lib/logtail-rails.rb b/lib/logtail-rails.rb index 6d431bf..3d078d8 100755 --- a/lib/logtail-rails.rb +++ b/lib/logtail-rails.rb @@ -39,6 +39,12 @@ def self.enabled? def self.integrate! return false if !enabled? + # Log the status Rails responds with when the app raises, the way ShowExceptions + # determines it: from config.action_dispatch.rescue_responses, 500 by default. + Logtail::Integrations::Rack::HTTPEvents.status_for_exception = lambda do |exception| + ::ActionDispatch::ExceptionWrapper.new(nil, exception).status_code + end + ActionController.integrate! ActionDispatch.integrate! ActionView.integrate! diff --git a/lib/logtail-rails/error_event.rb b/lib/logtail-rails/error_event.rb index 21e53fb..3755ee2 100755 --- a/lib/logtail-rails/error_event.rb +++ b/lib/logtail-rails/error_event.rb @@ -18,19 +18,15 @@ class ErrorEvent < Logtail::Integrations::Rack::Middleware # We determine this when the app loads to avoid the overhead on a per request basis. EXCEPTION_WRAPPER_TAKES_CLEANER = defined?(::ActionDispatch::ExceptionWrapper) && !::ActionDispatch::ExceptionWrapper.instance_methods.include?(:env) + # config.action_dispatch.log_rescued_responses (Rails 7.0+), as ActionDispatch::DebugExceptions + # reads it. This gem silences its logging and logs the exception here instead. + LOG_RESCUED_RESPONSES_KEY = "action_dispatch.log_rescued_responses".freeze def call(env) begin status, headers, body = @app.call(env) rescue Exception => exception - Config.instance.logger.fatal do - backtrace = extract_backtrace(env, exception) - Events::Error.new( - name: exception.class.name, - error_message: exception.message, - backtrace: backtrace - ) - end + log_exception(env, exception) raise exception end @@ -38,6 +34,30 @@ def call(env) private + # Never raises, so that the exception of the app is the one that propagates. + def log_exception(env, exception) + return if !log_exception?(env, exception) + + Config.instance.logger.fatal do + backtrace = extract_backtrace(env, exception) + Events::Error.new( + name: exception.class.name, + error_message: exception.message, + backtrace: backtrace + ) + end + rescue StandardError => e + Config.instance.debug { "#{self.class.name} could not log #{exception.class}: #{e.inspect}" } + end + + # Like DebugExceptions, skip rescued responses such as ActiveRecord::RecordNotFound when + # log_rescued_responses is false. Older Rails versions don't set it and log every exception. + def log_exception?(env, exception) + return true if !env.key?(LOG_RESCUED_RESPONSES_KEY) || env[LOG_RESCUED_RESPONSES_KEY] + + !::ActionDispatch::ExceptionWrapper.rescue_responses.key?(exception.class.name) + end + # Rails provides a backtrace cleaner, so we use it here. def extract_backtrace(env, exception) if defined?(::ActionDispatch::ExceptionWrapper) diff --git a/logtail-rails.gemspec b/logtail-rails.gemspec index f3faf7f..a4f5239 100644 --- a/logtail-rails.gemspec +++ b/logtail-rails.gemspec @@ -27,8 +27,8 @@ Gem::Specification.new do |spec| spec.executables = spec.files.grep(%r{^exe/}) { |f| File.basename(f) } spec.require_paths = ["lib"] - spec.add_runtime_dependency "logtail", "~> 0.1", ">= 0.1.14" - spec.add_runtime_dependency "logtail-rack", "~> 0.1" + spec.add_runtime_dependency "logtail", "~> 0.1", ">= 0.1.21" + spec.add_runtime_dependency "logtail-rack", "~> 0.2", ">= 0.2.9" spec.add_runtime_dependency 'activerecord', '>= 5.0.0' spec.add_runtime_dependency 'railties', '>= 5.0.0' diff --git a/spec/logtail-rails/action_dispatch/debug_exceptions_spec.rb b/spec/logtail-rails/action_dispatch/debug_exceptions_spec.rb index f0e12d8..0bda6ce 100755 --- a/spec/logtail-rails/action_dispatch/debug_exceptions_spec.rb +++ b/spec/logtail-rails/action_dispatch/debug_exceptions_spec.rb @@ -38,10 +38,11 @@ def method_for_action(action_name) suppress(RuntimeError) { dispatch_rails_request("/exception") } lines = clean_lines(io.string.split("\n")) - expect(lines.length).to eq(3) + expect(lines.length).to eq(4) expect(lines[2]).to include('RuntimeError (boom)') expect(lines[2]).to include('fatal') expect(lines[2]).to include("\"error\":{\"name\":\"RuntimeError\",\"message\":\"boom\",\"backtrace_json\":\"[") + expect(lines[3]).to include("Completed 500 Internal Server Error in") end # Remove blank lines since Rails does this to space out requests in the logs diff --git a/spec/logtail-rails/error_event_spec.rb b/spec/logtail-rails/error_event_spec.rb index 08fa0b2..af9cfe1 100755 --- a/spec/logtail-rails/error_event_spec.rb +++ b/spec/logtail-rails/error_event_spec.rb @@ -47,11 +47,146 @@ def method_for_action(action_name) lines = clean_lines(io.string.split("\n")) - expect(lines.length).to eq(3) + expect(lines.length).to eq(4) expect(lines[0]).to include("Started GET \\\"/rack_error\\\"") expect(lines[1]).to include("Processing by RackErrorController#index as HTML") expect(lines[2]).to include("RuntimeError (Boom!)") + expect(lines[3]).to include("Completed 500 Internal Server Error in") + end + + it "should re-raise the exception of the app when the logger fails" do + error = RuntimeError.new("Boom!") + allow(logger).to receive(:add).and_raise(IOError, "closed stream") + + expect { described_class.new(->(_env) { raise error }).call(Rack::MockRequest.env_for("/")) }.to raise_error(RuntimeError) { |raised| expect(raised).to be(error) } + end + + it "should re-raise the exception of the app when building the error event fails" do + error = RuntimeError.new("Boom!") + allow(Logtail::Events::Error).to receive(:new).and_raise(ArgumentError, "bad event") + + expect { described_class.new(->(_env) { raise error }).call(Rack::MockRequest.env_for("/")) }.to raise_error(RuntimeError) { |raised| expect(raised).to be(error) } + expect(io.string).to eq("") + end + end + + describe "exception responses" do + around(:each) do |example| + class ExceptionResponseController < ActionController::Base + layout nil + + def runtime_error + raise "Boom!" + end + + def record_not_found + raise ActiveRecord::RecordNotFound, "Couldn't find User" + end + + def record_not_found_in_template + render inline: "<% raise ActiveRecord::RecordNotFound, 'Couldn\\'t find User' %>" + end + + def method_for_action(action_name) + action_name + end + end + + ::RailsApp.routes.draw do + get '/runtime_error' => 'exception_response#runtime_error' + get '/record_not_found' => 'exception_response#record_not_found' + get '/record_not_found_in_template' => 'exception_response#record_not_found_in_template' + end + + example.run + + Object.send(:remove_const, :ExceptionResponseController) + end + + it "should log a fatal error and a response with status 500" do + response = dispatch_rendering_exceptions("/runtime_error") + + expect(response.status).to eq(500) + expect(error_rows.map { |row| [row["level"], row["message"]] }).to eq([["fatal", "RuntimeError (Boom!)"]]) + expect(response_statuses).to eq([500]) + expect(response_rows.first["message"]).to match(/\ACompleted 500 Internal Server Error in \d+\.\dms\z/) + end + + it "should log the response with the status from config.action_dispatch.rescue_responses" do + response = dispatch_rendering_exceptions("/record_not_found") + + expect(response.status).to eq(404) + expect(response_statuses).to eq([404]) + expect(response_rows.first["message"]).to match(/\ACompleted 404 Not Found in \d+\.\dms\z/) + expect(error_rows.map { |row| [row["level"], row["message"]] }).to eq([["fatal", "ActiveRecord::RecordNotFound (Couldn't find User)"]]) + end + + it "should log the response with the status of the exception a template error wraps" do + response = dispatch_rendering_exceptions("/record_not_found_in_template") + + expect(response.status).to eq(404) + expect(response_statuses).to eq([404]) + end + + it "should not log rescued responses when config.action_dispatch.log_rescued_responses is false" do + skip("config.action_dispatch.log_rescued_responses is new in Rails 7.0") unless ::Rails.application.env_config.key?("action_dispatch.log_rescued_responses") + + dispatch_rendering_exceptions("/record_not_found", "action_dispatch.log_rescued_responses" => false) + dispatch_rendering_exceptions("/runtime_error", "action_dispatch.log_rescued_responses" => false) + + expect(error_rows.map { |row| row["message"] }).to eq(["RuntimeError (Boom!)"]) + expect(response_statuses).to eq([404, 500]) + end + + it "should log the error at fatal even when config.action_dispatch.debug_exception_log_level is :error" do + skip("config.action_dispatch.debug_exception_log_level is new in Rails 7.1") unless ::Rails.application.env_config.key?("action_dispatch.debug_exception_log_level") + + dispatch_rendering_exceptions("/runtime_error", "action_dispatch.debug_exception_log_level" => ::Logger::ERROR) + + expect(error_rows.map { |row| [row["level"], row["message"]] }).to eq([["fatal", "RuntimeError (Boom!)"]]) + end + + # Renders exceptions as error pages like a production app, instead of raising them + def dispatch_rendering_exceptions(path, env_config = {}) + show_exceptions = ::Rails.gem_version >= Gem::Version.new("7.1") ? :all : true + + with_env_config(env_config.merge("action_dispatch.show_exceptions" => show_exceptions)) do + dispatch_rails_request(path) + end + end + + # Rails copies its config.action_dispatch settings from env_config into every request env + def with_env_config(settings) + env_config = ::Rails.application.env_config + previous = settings.keys.map { |key| [key, env_config.key?(key), env_config[key]] } + env_config.merge!(settings) + + yield + ensure + previous.each do |key, existed, value| + if existed + env_config[key] = value + else + env_config.delete(key) + end + end + end + + def log_rows + io.string.split("\n").map { |line| JSON.parse(line) } + end + + def error_rows + log_rows.select { |row| row.key?("error") } + end + + def response_rows + log_rows.select { |row| row.dig("event", "http_response_sent") } + end + + def response_statuses + response_rows.map { |row| row["event"]["http_response_sent"]["status"] } end end diff --git a/spec/support/rails.rb b/spec/support/rails.rb index 47cef1c..732257a 100755 --- a/spec/support/rails.rb +++ b/spec/support/rails.rb @@ -15,6 +15,8 @@ class RailsApp < Rails::Application # This ensures our tests fail, otherwise exceptions get swallowed by ActionDispatch::DebugExceptions config.action_dispatch.show_exceptions = false + # What ActiveRecord's railtie adds, which these specs don't load + config.action_dispatch.rescue_responses.merge!("ActiveRecord::RecordNotFound" => :not_found) config.active_support.deprecation = :stderr config.eager_load = false config.hosts = nil