diff --git a/lib/logtail-rack/error_event.rb b/lib/logtail-rack/error_event.rb index 19d0f00..34eddf4 100755 --- a/lib/logtail-rack/error_event.rb +++ b/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 diff --git a/lib/logtail-rack/http_context.rb b/lib/logtail-rack/http_context.rb index 7f1336d..4701b6e 100755 --- a/lib/logtail-rack/http_context.rb +++ b/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 diff --git a/lib/logtail-rack/http_events.rb b/lib/logtail-rack/http_events.rb index 6cce46e..185ee2b 100755 --- a/lib/logtail-rack/http_events.rb +++ b/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 diff --git a/lib/logtail-rack/middleware.rb b/lib/logtail-rack/middleware.rb index e8f9f94..5d66e3a 100755 --- a/lib/logtail-rack/middleware.rb +++ b/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 diff --git a/lib/logtail-rack/session_context.rb b/lib/logtail-rack/session_context.rb index 4618d78..5eeb6e4 100755 --- a/lib/logtail-rack/session_context.rb +++ b/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 diff --git a/lib/logtail-rack/user_context.rb b/lib/logtail-rack/user_context.rb index 7e26c57..9e90666 100755 --- a/lib/logtail-rack/user_context.rb +++ b/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) diff --git a/lib/logtail-rack/util/request.rb b/lib/logtail-rack/util/request.rb index d412e83..d71c13a 100755 --- a/lib/logtail-rack/util/request.rb +++ b/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 diff --git a/spec/logtail-rack/error_event_spec.rb b/spec/logtail-rack/error_event_spec.rb new file mode 100644 index 0000000..70cbb92 --- /dev/null +++ b/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 diff --git a/spec/logtail-rack/http_context_spec.rb b/spec/logtail-rack/http_context_spec.rb new file mode 100644 index 0000000..7c2806a --- /dev/null +++ b/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 diff --git a/spec/logtail-rack/http_events_spec.rb b/spec/logtail-rack/http_events_spec.rb index 9de15db..c268fd2 100755 --- a/spec/logtail-rack/http_events_spec.rb +++ b/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: #") + 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: #").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 diff --git a/spec/logtail-rack/user_context_spec.rb b/spec/logtail-rack/user_context_spec.rb new file mode 100644 index 0000000..ee40d8d --- /dev/null +++ b/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