Log a response row with status 500 when the app raises

lib/logtail-rack/http_events.rb

@@ -15,6 +15,7 @@ module Rack
       # response events. The {Events::HTTPRequest} and {Events::HTTPResponse} events
       # respectively.
       class HTTPEvents < Middleware
+        DEFAULT_STATUS_FOR_EXCEPTION = ->(_exception) { 500 }
         DEFAULT_HTTP_HEADER_FILTERS = ["Authorization", "Proxy-Authorization", "Cookie", "Set-Cookie"].freeze
 
         class << self
@@ -105,6 +106,29 @@ def silence_request
             @silence_request
           end
 
+          # When the app raises instead of returning a response, the response event is still
+          # logged, and the exception is re-raised unchanged. This setting resolves the HTTP
+          # status of that event: a callable that receives the exception and returns an Integer
+          # status. The default, {DEFAULT_STATUS_FOR_EXCEPTION}, returns 500, and so does a
+          # callable that raises itself.
+          #
+          # @example
+          #   Logtail::Integrations::Rack::HTTPEvents.status_for_exception = lambda do |exception|
+          #     exception.is_a?(MyApp::NotFound) ? 404 : 500
+          #   end
+          def status_for_exception=(callable)
+            if !callable.respond_to?(:call)
+              raise ArgumentError.new("The value passed to #status_for_exception must respond to #call")
+            end
+
+            @status_for_exception = callable
+          end
+
+          # Accessor method for {#status_for_exception=}
+          def status_for_exception
+            @status_for_exception
+          end
+
           # Filter sensitive HTTP headers (such as "Authorization: Bearer secret_token")
           #
           # Filtered HTTP header values will be sent to Better Stack as "[FILTERED]"
@@ -128,6 +152,7 @@ def normalize_header_name(name)
           end
         end
 
+        self.status_for_exception = DEFAULT_STATUS_FOR_EXCEPTION
         self.http_header_filters = DEFAULT_HTTP_HEADER_FILTERS
 
         CONTENT_LENGTH_KEY = 'content-length'.freeze
@@ -146,7 +171,7 @@ def call(env)
 
           elsif collapse_into_single_event?
             request_start = Process.clock_gettime(Process::CLOCK_MONOTONIC)
-            status, headers, body = @app.call(env)
+            status, headers, body = call_app(env, request, request_start)
             request_end = Process.clock_gettime(Process::CLOCK_MONOTONIC)
 
             Config.instance.logger.info do
@@ -217,7 +242,7 @@ def call(env)
             end
 
             request_start = Process.clock_gettime(Process::CLOCK_MONOTONIC)
-            status, headers, body = @app.call(env)
+            status, headers, body = call_app(env, request, request_start)
             request_end = Process.clock_gettime(Process::CLOCK_MONOTONIC)
 
             Config.instance.logger.info do
@@ -275,6 +300,55 @@ def silenced?(env, request)
             end
           end
 
+          # Calls the app. When it raises instead of returning a response, logs the response
+          # event with the status from {.status_for_exception} and re-raises the exception.
+          def call_app(env, request, request_start)
+            @app.call(env)
+          rescue Exception => exception
+            log_exception_response(request, exception, request_start)
+            raise exception
+          end
+
+          # Never raises, so that the exception of the app is the one that propagates.
+          def log_exception_response(request, exception, request_start)
+            request_end = Process.clock_gettime(Process::CLOCK_MONOTONIC)
+
+            Config.instance.logger.info do
+              duration_ms = ((request_end - request_start) * 1000.0).round(1)
+
+              http_response = HTTPResponse.new(
+                http_context: collapse_into_single_event? ? CurrentContext.fetch(:http, nil) : nil,
+                request_id: request.request_id,
+                status: status_for_exception(exception),
+                duration_ms: duration_ms,
+              )
+
+              {
+                message: http_response.message,
+                event: {
+                  http_response_sent: {
+                    body: http_response.body,
+                    content_length: http_response.content_length,
+                    headers_json: http_response.headers_json,
+                    request_id: http_response.request_id,
+                    service_name: http_response.service_name,
+                    status: http_response.status,
+                    duration_ms: http_response.duration_ms,
+                  }
+                }
+              }
+            end
+          rescue Exception => e
+            Config.instance.debug { "Failed to log the response of a request that raised #{exception.class}: #{e.class}: #{e.message}" }
+          end
+
+          def status_for_exception(exception)
+            self.class.status_for_exception.call(exception)
+          rescue Exception => e
+            Config.instance.debug { "status_for_exception raised #{e.class}: #{e.message}, logging status 500" }
+            500
+          end
+
           def filter_http_headers(headers)
             headers.map do |name, value|
               normalized_name = self.class.normalize_header_name(name)

spec/logtail-rack/http_events_spec.rb

@@ -133,6 +133,109 @@
     expect(logs.first["event"]["http_response_sent"]["duration_ms"]).to eq(39.2)
   end
 
+  it "log a response with status 500 when the app raises, and re-raise the exception unchanged" do
+    error = RuntimeError.new("boom")
+    app = ->(env) { raise error }
+    allow(Process).to receive(:clock_gettime).and_call_original
+    allow(Process).to receive(:clock_gettime).with(Process::CLOCK_MONOTONIC).and_return(100.0, 100.0392345)
+
+    logs = capture_logs do
+      expect { described_class.new(app).call mock_request }.to raise_error(RuntimeError) { |raised| expect(raised).to be(error) }
+    end
+
+    expect(logs.map { |log| log["message"] }).to eq(['Started GET "/test-page"', "Completed 500 Internal Server Error in 39.2ms"])
+    http_response_sent = logs.last["event"]["http_response_sent"]
+    expect(http_response_sent["status"]).to eq(500)
+    expect(http_response_sent["duration_ms"]).to eq(39.2)
+    expect(http_response_sent["headers_json"]).to be_nil
+    expect(http_response_sent["body"]).to be_nil
+  end
+
+  it "log a response with status 500 when the app raises an exception that is not a StandardError" do
+    app = ->(env) { raise NotImplementedError, "not implemented" }
+
+    logs = capture_logs do
+      expect { described_class.new(app).call mock_request }.to raise_error(NotImplementedError, "not implemented")
+    end
+
+    expect(logs.last["event"]["http_response_sent"]["status"]).to eq(500)
+  end
+
+  it "log the status returned by status_for_exception when the app raises" do
+    error = ArgumentError.new("no such record")
+    app = ->(env) { raise error }
+    resolved = []
+    status_for_exception = lambda do |exception|
+      resolved << exception
+      404
+    end
+
+    logs = capture_logs do
+      with_status_for_exception(status_for_exception) do
+        expect { described_class.new(app).call mock_request }.to raise_error(ArgumentError) { |raised| expect(raised).to be(error) }
+      end
+    end
+
+    expect(resolved.length).to eq(1)
+    expect(resolved.first).to be(error)
+    expect(logs.last["message"]).to match(/\ACompleted 404 Not Found in \d+\.\dms\z/)
+    expect(logs.last["event"]["http_response_sent"]["status"]).to eq(404)
+  end
+
+  it "log the status 500 when status_for_exception raises itself" do
+    error = RuntimeError.new("boom")
+    app = ->(env) { raise error }
+
+    logs = capture_logs do
+      with_status_for_exception(->(_exception) { raise "status_for_exception failed" }) do
+        expect { described_class.new(app).call mock_request }.to raise_error(RuntimeError) { |raised| expect(raised).to be(error) }
+      end
+    end
+
+    expect(logs.last["event"]["http_response_sent"]["status"]).to eq(500)
+  end
+
+  it "log the single collapsed event with status 500 when the app raises" do
+    app = ->(env) { raise "boom" }
+    stack = Logtail::Integrations::Rack::HTTPContext.new(described_class.new(app))
+    allow(Process).to receive(:clock_gettime).and_call_original
+    allow(Process).to receive(:clock_gettime).with(Process::CLOCK_MONOTONIC).and_return(100.0, 100.0392345)
+
+    logs = capture_logs do
+      with_collapse_into_single_event do
+        expect { stack.call mock_request }.to raise_error(RuntimeError, "boom")
+      end
+    end
+
+    expect(logs.length).to eq(1)
+    expect(logs.first["message"]).to eq("GET /test-page completed with 500 Internal Server Error in 39.2ms")
+    expect(logs.first["event"]["http_response_sent"]["status"]).to eq(500)
+  end
+
+  it "re-raise the exception of the app when logging its response fails" do
+    error = RuntimeError.new("boom")
+    app = ->(env) { raise error }
+    old_logger = Logtail::Config.instance.logger
+    failing_logger = Logtail::Logger.new(StringIO.new)
+    allow(failing_logger).to receive(:info).and_raise(IOError, "closed stream")
+    Logtail::Config.instance.logger = failing_logger
+
+    with_collapse_into_single_event do
+      expect { described_class.new(app).call mock_request }.to raise_error(RuntimeError) { |raised| expect(raised).to be(error) }
+    end
+  ensure
+    Logtail::Config.instance.logger = old_logger
+  end
+
+  it "resolve the status of an exception to 500 by default" do
+    expect(described_class.status_for_exception).to be(described_class::DEFAULT_STATUS_FOR_EXCEPTION)
+    expect(described_class.status_for_exception.call(RuntimeError.new("boom"))).to eq(500)
+  end
+
+  it "require status_for_exception to be callable" do
+    expect { described_class.status_for_exception = 404 }.to raise_error(ArgumentError)
+  end
+
   def capture_logs(&blk)
     old_logger = Logtail::Config.instance.logger
 
@@ -163,4 +266,12 @@ def with_collapse_into_single_event(&blk)
   ensure
     Logtail::Integrations::Rack::HTTPEvents.collapse_into_single_event = false
   end
+
+  def with_status_for_exception(status_for_exception, &blk)
+    Logtail::Integrations::Rack::HTTPEvents.status_for_exception = status_for_exception
+
+    blk.call
+  ensure
+    Logtail::Integrations::Rack::HTTPEvents.status_for_exception = Logtail::Integrations::Rack::HTTPEvents::DEFAULT_STATUS_FOR_EXCEPTION
+  end
 end