Never fail a request because logging it failed - #31
Merged
Merged
Conversation
Each of these makes the request raise (a 500) or loses the batch today: - collapse_into_single_event without HTTPContext (KeyError :http) - capture_request_body with a missing or non-rewindable Rack 3 input - capture_response_body with a body that isn't an Array - an error while building or formatting an event in HTTPEvents, HTTPContext, UserContext or ErrorEvent (ErrorEvent then raises the logging error instead of the app's exception) Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
- Middleware#log_safely logs the event its block builds and sends any StandardError from building or writing it to the debug logger. HTTPEvents (both modes) and ErrorEvent log through it, so ErrorEvent re-raises the app's exception, not the logging error. - HTTPContext and UserContext build their context in a method that rescues like SessionContext#get_session_id, and the request goes on without that context. SessionContext reports what it rescues too. - The collapsed event fetches the HTTP context with a nil default. - capture_request_body skips a missing or non-rewindable input instead of consuming the body the app still needs. - capture_response_body logs Array bodies joined, and nothing else. The app's own exceptions are untouched: nothing wraps @app.call. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
logtail reports the line that called the logger as the runtime context of a log line. Since log_safely calls the logger itself, with public_send, every request, response and error event says it was logged by middleware.rb in Kernel#public_send instead of by the middleware's call, as on 0.2.8. These tests pass on 0.2.8. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
…to it log_safely called the logger itself, so logtail reported middleware.rb and Kernel#public_send as the runtime context of every request, response and error event. The middlewares call the logger themselves again, as on 0.2.8, and only rescue an error raised while building or writing the event with a rescue modifier on the block. logging_failed passes it to the debug logger, as log_safely did. The runtime context of the events is the same as on 0.2.8 again: the file, the line of the logger call and the label. The tests now check the exact label, so a block around the logger call would fail them too. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
ErrorEvent logs the error in a rescue clause, which Ruby 3.3 and older label "rescue in call", as for 0.2.8. The test now accepts that label too. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Several cases make the gem's own logging code turn a working request into a 500, or drop the whole log batch. From the red-team of 0.2.8 (
verify2.rband the Puma runs):collapse_into_single_event(also switched on bylogrageify!) withoutHTTPContextin front ofHTTPEvents:CurrentContext.fetch(:http)raisesKeyError: key not found: :httpon every request.capture_request_bodyon Rack 3: a missingrack.inputraises onread, and a non-rewindable one raises onrewindafter the body was already read, e.g.undefined method 'rewind' for an instance of Rack::Lint::Wrapper::InputWrapper.capture_response_bodywith a body that isn't an Array logs the body object itself. MessagePack can't encode it, so the batch is lost.request.hostraisingArgumentErrorfor invalid UTF-8 inX-Forwarded-Host, or a formatter raising (the JSON formatter does with json 3 and ActiveSupport 8.0 or older). InErrorEventsuch an error replaces the app's exception.What changes:
HTTPEvents(both modes) andErrorEventstill call the logger themselves, and rescue anyStandardErrorfrom building or writing the event with a rescue modifier on the block,end rescue logging_failed($!). The privateMiddleware#logging_failedsends it toConfig.instance.debuginstead of raising.ErrorEventstill re-raises the app's exception.HTTPContextandUserContextbuild their context in a method that rescues the same way and returns nil, so the request goes on without that context. That is the patternSessionContext#get_session_idalready used; it now also reports what it rescues to the debug logger.CurrentContext.fetch(:http, nil), so withoutHTTPContextit's logged asCompleted 200 OK in ….capture_request_bodyskips an input that is missing or doesn't respond torewind, so the gem never consumes a body the app still needs.capture_response_bodylogs Array bodies joined into one String, and no body otherwise (other bodies may stream and can be iterated only once).@app.call, so the app's own exceptions propagate exactly as before.Behaviour and compatibility:
Logtail::Config.instance.debug_logger = ::Logger.new(STDOUT)).UserContext.custom_user_hashno longer fails the request; the request goes on without user context.capture_response_body,http_response_sent.bodyis now a String instead of an Array of Strings, and nil for non-Array bodies.StandardError, soInterrupt, rack-timeout'sRequestTimeoutExceptionand other non-standard exceptions still propagate.SessionContextkeeps its existingrescue Exception.Follow-up after the E2E run of the release candidate (three more commits: the tests, red on CI; the fix; and the label the tests accept for the error event on Ruby 3.3 and older,
rescue in callas on 0.2.8): the first version called the logger inside alog_safelyhelper, withpublic_send. logtail reports the line that calls the logger as the runtime context of a log line, so every request, response and error event saidmiddleware.rb:32andKernel#public_sendinstead of the middleware'scall(http_events.rb:184and:223,error_event.rb:14on 0.2.8). The logger is called at the call site again and the rescue is a modifier on the block, which keeps the blocks' indentation so the other open rack PRs still merge cleanly. The new tests pass on 0.2.8, and the runtime context of all three events is the same as on 0.2.8 again: file, line and label.Targets the logtail-rack 0.2.9 patch release. No dependencies. The query-string filter (#29) and exception-response (#27) PRs change
HTTPEventstoo; this one only touches its logging blocks and helpers, not the@app.calllines. A local trial merge of all five open rack PRs had no conflicts and passed the suite on Rack 1.2 to 3.2.The first commit only adds the tests and is expected to fail on CI; the fix follows in the next commit.
🤖 Generated with Claude Code