Log the real status of exception responses and honour log_rescued_responses

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!

lib/logtail-rails/error_event.rb

@@ -18,26 +18,46 @@ 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
         end
 
         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)

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'

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

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
 

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