Skip to content

Never fail a request because logging it failed - #31

Merged
PetrHeinz merged 5 commits into
mainfrom
claude/never-fail-requests
Oct 2, 2026
Merged

PetrHeinz merged 5 commits into
mainfrom
claude/never-fail-requests

Conversation

@PetrHeinz

@PetrHeinz PetrHeinz commented Oct 1, 2026 •

Copy link
Copy Markdown
Member

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.rb and the Puma runs):

  • collapse_into_single_event (also switched on by logrageify!) without HTTPContext in front of HTTPEvents: CurrentContext.fetch(:http) raises KeyError: key not found: :http on every request.
  • capture_request_body on Rack 3: a missing rack.input raises on read, and a non-rewindable one raises on rewind after the body was already read, e.g. undefined method 'rewind' for an instance of Rack::Lint::Wrapper::InputWrapper.
  • capture_response_body with a body that isn't an Array logs the body object itself. MessagePack can't encode it, so the batch is lost.
  • Any other error while building or writing an event fails the request too, for example Rack's own request.host raising ArgumentError for invalid UTF-8 in X-Forwarded-Host, or a formatter raising (the JSON formatter does with json 3 and ActiveSupport 8.0 or older). In ErrorEvent such an error replaces the app's exception.

What changes:

  • HTTPEvents (both modes) and ErrorEvent still call the logger themselves, and rescue any StandardError from building or writing the event with a rescue modifier on the block, end rescue logging_failed($!). The private Middleware#logging_failed sends it to Config.instance.debug instead of raising. ErrorEvent still re-raises the app's exception.
  • HTTPContext and UserContext build their context in a method that rescues the same way and returns nil, so the request goes on without that context. That is the pattern SessionContext#get_session_id already used; it now also reports what it rescues to the debug logger.
  • The collapsed event uses CurrentContext.fetch(:http, nil), so without HTTPContext it's logged as Completed 200 OK in ….
  • capture_request_body skips an input that is missing or doesn't respond to rewind, so the gem never consumes a body the app still needs.
  • capture_response_body logs Array bodies joined into one String, and no body otherwise (other bodies may stream and can be iterated only once).
  • Nothing wraps @app.call, so the app's own exceptions propagate exactly as before.

Behaviour and compatibility:

  • A request that used to fail because of logging now succeeds. The lost event shows up only with a debug logger set (Logtail::Config.instance.debug_logger = ::Logger.new(STDOUT)).
  • A raising UserContext.custom_user_hash no longer fails the request; the request goes on without user context.
  • With capture_response_body, http_response_sent.body is now a String instead of an Array of Strings, and nil for non-Array bodies.
  • The new rescues only catch StandardError, so Interrupt, rack-timeout's RequestTimeoutException and other non-standard exceptions still propagate. SessionContext keeps its existing rescue 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 call as on 0.2.8): the first version called the logger inside a log_safely helper, with public_send. logtail reports the line that calls the logger as the runtime context of a log line, so every request, response and error event said middleware.rb:32 and Kernel#public_send instead of the middleware's call (http_events.rb:184 and :223, error_event.rb:14 on 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 HTTPEvents too; this one only touches its logging blocks and helpers, not the @app.call lines. 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

PetrHeinz and others added 5 commits October 1, 2026 18:48
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>
@PetrHeinz
PetrHeinz marked this pull request as ready for review October 2, 2026 09:20
@PetrHeinz
PetrHeinz merged commit ac43d6d into main Oct 2, 2026
26 checks passed
@PetrHeinz
PetrHeinz deleted the claude/never-fail-requests branch October 2, 2026 11:34
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant