Never fail a request because logging it failed

lib/logtail-rack/error_event.rb

@@ -17,7 +17,7 @@ def call(env)
                 error_message: exception.message,
                 backtrace: exception.backtrace
               )
-            end
+            end rescue logging_failed($!)
 
             raise exception
           end

lib/logtail-rack/http_context.rb

@@ -1,3 +1,4 @@
+require "logtail/config"
 require "logtail/contexts/http"
 require "logtail/current_context"
 require "logtail-rack/middleware"
@@ -10,19 +11,30 @@ module Rack
       # A Rack middleware that is reponsible for adding the HTTP context {Logtail::Contexts::HTTP}.
       class HTTPContext < Middleware
         def call(env)
-          request = Util::Request.new(env)
-          context = Contexts::HTTP.new(
-            host: Util::Encoding.force_utf8_encoding(request.host),
-            method: Util::Encoding.force_utf8_encoding(request.request_method),
-            path: request.path,
-            remote_addr: Util::Encoding.force_utf8_encoding(request.ip),
-            request_id: request.request_id
-          )
-
-          CurrentContext.with(context.to_hash) do
+          context = get_http_context(env)
+          if context
+            CurrentContext.with(context) do
+              @app.call(env)
+            end
+          else
             @app.call(env)
           end
         end
+
+        private
+          def get_http_context(env)
+            request = Util::Request.new(env)
+            Contexts::HTTP.new(
+              host: Util::Encoding.force_utf8_encoding(request.host),
+              method: Util::Encoding.force_utf8_encoding(request.request_method),
+              path: request.path,
+              remote_addr: Util::Encoding.force_utf8_encoding(request.ip),
+              request_id: request.request_id
+            ).to_hash
+          rescue StandardError => e
+            Logtail::Config.instance.debug { "Could not build the HTTP context: #{e.inspect}\n\n#{e.backtrace}" }
+            nil
+          end
       end
     end
   end

lib/logtail-rack/http_events.rb

@@ -150,7 +150,7 @@ def call(env)
             request_end = Process.clock_gettime(Process::CLOCK_MONOTONIC)
 
             Config.instance.logger.info do
-              http_context = CurrentContext.fetch(:http)
+              http_context = CurrentContext.fetch(:http, nil)
               content_length = response_content_length(headers)
               duration_ms = ((request_end - request_start) * 1000.0).round(1)
 
@@ -177,7 +177,7 @@ def call(env)
                   }
                 }
               }
-            end
+            end rescue logging_failed($!)
 
             [status, headers, body]
           else
@@ -214,14 +214,15 @@ def call(env)
                   }
                 }
               }
-            end
+            end rescue logging_failed($!)
 
             request_start = Process.clock_gettime(Process::CLOCK_MONOTONIC)
             status, headers, body = @app.call(env)
             request_end = Process.clock_gettime(Process::CLOCK_MONOTONIC)
 
             Config.instance.logger.info do
-              event_body = capture_response_body? ? body : nil
+              # Only an Array body can be read twice, other bodies may stream to the server once
+              event_body = capture_response_body? && body.is_a?(Array) ? body.join : nil
               content_length = response_content_length(headers)
               duration_ms = ((request_end - request_start) * 1000.0).round(1)
 
@@ -248,7 +249,7 @@ def call(env)
                   }
                 }
               }
-            end
+            end rescue logging_failed($!)
 
             [status, headers, body]
           end

lib/logtail-rack/middleware.rb

@@ -1,3 +1,5 @@
+require "logtail/config"
+
 module Logtail
   module Integrations
     module Rack
@@ -22,6 +24,18 @@ def enabled?
         def initialize(app)
           @app = app
         end
+
+        private
+          # Logging must never fail the request, so an error raised while building or writing an event
+          # only goes to the debug logger. The middlewares call the logger themselves, so that the
+          # runtime context of the line points to them, and rescue the error with this method:
+          #
+          #   Config.instance.logger.info do
+          #     ...
+          #   end rescue logging_failed($!)
+          def logging_failed(error)
+            Config.instance.debug { "#{self.class.name} could not log an event: #{error.inspect}\n\n#{error.backtrace}" }
+          end
       end
     end
   end

lib/logtail-rack/session_context.rb

@@ -39,6 +39,7 @@ def get_session_id(env)
               nil
             end
           rescue Exception => e
+            Logtail::Config.instance.debug { "Could not obtain the session id: #{e.inspect}\n\n#{e.backtrace}" }
             nil
           end
       end

lib/logtail-rack/user_context.rb

@@ -93,6 +93,9 @@ def get_user_hash(env)
               Logtail::Config.instance.debug { "Could not locate any user data" }
               nil
             end
+          rescue StandardError => e
+            Logtail::Config.instance.debug { "Could not obtain the user context: #{e.inspect}\n\n#{e.backtrace}" }
+            nil
           end
 
           def get_user_object_hash(user)

lib/logtail-rack/util/request.rb

@@ -13,6 +13,10 @@ class Request < ::Rack::Request
       REQUEST_ID_KEY_NAME2 = 'HTTP_X_REQUEST_ID'.freeze
 
       def body_content
+        # Rack 3 allows a missing or non-rewindable input, and reading one that can't be rewound takes the body
+        # from the app
+        return nil unless body.respond_to?(:rewind)
+
         content = body.read
         body.rewind
         content

spec/logtail-rack/error_event_spec.rb

@@ -0,0 +1,29 @@
+require "spec_helper"
+require "stringio"
+
+RSpec.describe Logtail::Integrations::Rack::ErrorEvent do
+  it "re-raise the app's exception when logging it raises" do
+    app = ->(env) { raise "app failure" }
+    logger = Logtail::Logger.new(StringIO.new)
+    # Like the JSON formatter does with json 3 and ActiveSupport 8.0 or older
+    logger.formatter = ->(*) { raise ArgumentError, "unknown keyword: :quirks_mode" }
+    allow(Logtail::Config.instance).to receive(:logger).and_return(logger)
+
+    expect { described_class.new(app).call(Rack::MockRequest.env_for("https://example.com/test-page")) }.to raise_error(RuntimeError, "app failure")
+  end
+
+  it "log the error with this middleware's call as its runtime context" do
+    app = ->(env) { raise "app failure" }
+    io = StringIO.new
+    logger = Logtail::Logger.new(io)
+    logger.formatter = Logtail::Logger::JSONFormatter.new
+    allow(Logtail::Config.instance).to receive(:logger).and_return(logger)
+
+    expect { described_class.new(app).call(Rack::MockRequest.env_for("https://example.com/test-page")) }.to raise_error(RuntimeError, "app failure")
+
+    runtime = JSON.parse(io.string)["context"]["runtime"]
+    expect(runtime["file"]).to end_with("lib/logtail-rack/error_event.rb")
+    # Ruby 3.3 and older label code in a rescue clause "rescue in call"
+    expect(runtime["frame_label"]).to match(/\A(rescue in )?(Logtail::Integrations::Rack::ErrorEvent#)?call\z/)
+  end
+end

spec/logtail-rack/http_context_spec.rb

@@ -0,0 +1,18 @@
+require "spec_helper"
+
+RSpec.describe Logtail::Integrations::Rack::HTTPContext do
+  it "pass the request on without the HTTP context when reading the request raises" do
+    http_contexts = []
+    app = lambda { |env|
+      http_contexts << Logtail::CurrentContext.fetch(:http, nil)
+      [200, { "content-type" => "text/plain" }, ["hello"]]
+    }
+    # Rack::Request#host raises ArgumentError for invalid UTF-8 in a UTF-8 string
+    request = Rack::MockRequest.env_for("https://example.com/test-page", "HTTP_X_FORWARDED_HOST" => "\xFF")
+
+    response = described_class.new(app).call(request)
+
+    expect(response).to eq([200, { "content-type" => "text/plain" }, ["hello"]])
+    expect(http_contexts).to eq([nil])
+  end
+end

spec/logtail-rack/http_events_spec.rb

@@ -17,6 +17,122 @@
     expect(logs.map { |log| log['message'] }).to match(['Started GET "/test-page"', /Completed 200 OK in \d+\.\d+ms/])
   end
 
+  it "log the request and the response with this middleware's call as their runtime context" do
+    logs = capture_logs { middleware.call mock_request }
+
+    runtimes = logs.map { |log| log["context"]["runtime"] }
+    expect(runtimes.map { |runtime| runtime["file"] }).to all(end_with("lib/logtail-rack/http_events.rb"))
+    expect(runtimes.map { |runtime| runtime["frame_label"] }).to all(match(/\A(Logtail::Integrations::Rack::HTTPEvents#)?call\z/))
+  end
+
+  it "log the single event with this middleware's call as its runtime context" do
+    stack = Logtail::Integrations::Rack::HTTPContext.new(middleware)
+    logs = capture_logs { with_collapse_into_single_event { stack.call mock_request } }
+
+    runtime = logs.first["context"]["runtime"]
+    expect(runtime["file"]).to end_with("lib/logtail-rack/http_events.rb")
+    expect(runtime["frame_label"]).to match(/\A(Logtail::Integrations::Rack::HTTPEvents#)?call\z/)
+  end
+
+  it "return the app's response when collapsing into a single event without HTTPContext" do
+    app = ->(env) { [200, { "content-type" => "text/plain" }, ["hello"]] }
+
+    response = nil
+    logs = capture_logs { with_collapse_into_single_event { response = described_class.new(app).call(mock_request) } }
+
+    expect(response).to eq([200, { "content-type" => "text/plain" }, ["hello"]])
+    expect(logs.map { |log| log['message'] }).to match([/\ACompleted 200 OK in \d+\.\d+ms\z/])
+  end
+
+  it "capture the request body and leave it for the app" do
+    app = ->(env) { [200, { "content-type" => "text/plain" }, [env["rack.input"].read]] }
+    request = Rack::MockRequest.env_for('https://example.com/form', method: "POST", input: "name=value")
+
+    response = nil
+    logs = capture_logs { with_capture_request_body { response = described_class.new(app).call(request) } }
+
+    expect(response[2]).to eq(["name=value"])
+    expect(logs.first["event"]["http_request_received"]["body"]).to eq("name=value")
+  end
+
+  it "leave the request body for the app when the input can't be rewound" do
+    app = ->(env) { [200, { "content-type" => "text/plain" }, [env["rack.input"].read]] }
+    # Rack 3 doesn't require rack.input to be rewindable
+    input = StringIO.new("name=value")
+    input.singleton_class.send(:undef_method, :rewind)
+    request = Rack::MockRequest.env_for('https://example.com/form', method: "POST", input: input)
+
+    response = nil
+    logs = capture_logs { with_capture_request_body { response = described_class.new(app).call(request) } }
+
+    expect(response).to eq([200, { "content-type" => "text/plain" }, ["name=value"]])
+    expect(logs.first["event"]["http_request_received"]["body"]).to be_nil
+  end
+
+  it "return the app's response when capturing the request body without a request input" do
+    app = ->(env) { [200, { "content-type" => "text/plain" }, ["hello"]] }
+    # Rack 3.1 and later may leave rack.input out
+    request = Rack::MockRequest.env_for('https://example.com/test-page')
+    request.delete("rack.input")
+
+    response = nil
+    logs = capture_logs { with_capture_request_body { response = described_class.new(app).call(request) } }
+
+    expect(response).to eq([200, { "content-type" => "text/plain" }, ["hello"]])
+    expect(logs.first["event"]["http_request_received"]["body"]).to be_nil
+  end
+
+  it "log a captured Array response body as one String" do
+    app = ->(env) { [200, { "content-type" => "text/plain" }, ["hello", " world"]] }
+
+    logs = capture_logs { with_capture_response_body { described_class.new(app).call(mock_request) } }
+
+    expect(logs.last["event"]["http_response_sent"]["body"]).to eq("hello world")
+  end
+
+  it "skip capturing a response body that isn't an Array and return it untouched" do
+    # Can be iterated only once, by the server
+    body = Object.new
+    def body.each
+      yield "hello"
+    end
+    app = ->(env) { [200, { "content-type" => "text/plain" }, body] }
+
+    response = nil
+    logs = capture_logs { with_capture_response_body { response = described_class.new(app).call(mock_request) } }
+
+    expect(response[2]).to be(body)
+    expect(logs.last["event"]["http_response_sent"]["body"]).to be_nil
+  end
+
+  it "return the app's response and log the response when logging the request raises" do
+    app = ->(env) { [200, { "content-type" => "text/plain" }, ["hello"]] }
+    # Rack::Request#host raises ArgumentError for invalid UTF-8 in a UTF-8 string
+    request = Rack::MockRequest.env_for('https://example.com/test-page', 'HTTP_X_FORWARDED_HOST' => "\xFF")
+
+    response = nil
+    logs = nil
+    debug_logs = capture_debug_logs { logs = capture_logs { response = described_class.new(app).call(request) } }
+
+    expect(response).to eq([200, { "content-type" => "text/plain" }, ["hello"]])
+    expect(logs.map { |log| log['message'] }).to match([/\ACompleted 200 OK in \d+\.\d+ms\z/])
+    expect(debug_logs).to include("Logtail::Integrations::Rack::HTTPEvents could not log an event: #<ArgumentError: invalid byte sequence in UTF-8>")
+  end
+
+  it "return the app's response when the logger raises" do
+    app = ->(env) { [200, { "content-type" => "text/plain" }, ["hello"]] }
+    logger = Logtail::Logger.new(StringIO.new)
+    # Like the JSON formatter does with json 3 and ActiveSupport 8.0 or older
+    logger.formatter = ->(*) { raise ArgumentError, "unknown keyword: :quirks_mode" }
+    allow(Logtail::Config.instance).to receive(:logger).and_return(logger)
+
+    response = nil
+    debug_logs = capture_debug_logs { response = described_class.new(app).call(mock_request) }
+
+    expect(response).to eq([200, { "content-type" => "text/plain" }, ["hello"]])
+    expect(debug_logs.scan("Logtail::Integrations::Rack::HTTPEvents could not log an event: #<ArgumentError: unknown keyword: :quirks_mode>").length).to eq(2)
+  end
+
   it "log HTTP request headers, filtering the Authorization header by default" do
     logs = capture_logs { middleware.call mock_request }
 
@@ -148,6 +264,33 @@ def capture_logs(&blk)
     Logtail::Config.instance.logger = old_logger
   end
 
+  def capture_debug_logs(&blk)
+    string_io = StringIO.new
+    Logtail::Config.instance.debug_logger = ::Logger.new(string_io)
+
+    blk.call
+
+    string_io.string
+  ensure
+    Logtail::Config.instance.debug_logger = nil
+  end
+
+  def with_capture_request_body(&blk)
+    Logtail::Integrations::Rack::HTTPEvents.capture_request_body = true
+
+    blk.call
+  ensure
+    Logtail::Integrations::Rack::HTTPEvents.capture_request_body = false
+  end
+
+  def with_capture_response_body(&blk)
+    Logtail::Integrations::Rack::HTTPEvents.capture_response_body = true
+
+    blk.call
+  ensure
+    Logtail::Integrations::Rack::HTTPEvents.capture_response_body = false
+  end
+
   def with_http_header_filters(headers, &blk)
     Logtail::Integrations::Rack::HTTPEvents.http_header_filters = headers
 

spec/logtail-rack/user_context_spec.rb

@@ -0,0 +1,25 @@
+require "spec_helper"
+
+RSpec.describe Logtail::Integrations::Rack::UserContext do
+  it "pass the request on without the user context when reading the user raises" do
+    user = Object.new
+    def user.id
+      1
+    end
+    # Like an ActiveRecord user loaded without its email column
+    def user.email
+      raise NoMethodError, "missing attribute 'email' for User"
+    end
+    user_contexts = []
+    app = lambda { |env|
+      user_contexts << Logtail::CurrentContext.fetch(:user, nil)
+      [200, { "content-type" => "text/plain" }, ["hello"]]
+    }
+    request = Rack::MockRequest.env_for("https://example.com/test-page", "warden" => double(user: user))
+
+    response = described_class.new(app).call(request)
+
+    expect(response).to eq([200, { "content-type" => "text/plain" }, ["hello"]])
+    expect(user_contexts).to eq([nil])
+  end
+end