diff --git a/lib/logtail-rack/http_events.rb b/lib/logtail-rack/http_events.rb index 6cce46e..43af29d 100755 --- a/lib/logtail-rack/http_events.rb +++ b/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) diff --git a/spec/logtail-rack/http_events_spec.rb b/spec/logtail-rack/http_events_spec.rb index 9de15db..f6ad75e 100755 --- a/spec/logtail-rack/http_events_spec.rb +++ b/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