getsentry / getsentry/sentry-ruby

Rails::Rack::Logger's "Started ..." log line (and anything else logged before Sentry::Rails::CaptureExceptions) gets an unrelated trace_id/span_id

Open
#3,015 3 comments 0 reactions 1 assignee Claimed by @solnic View on GitHub
Improvement Ruby sentry-rails
Dominant language
Ruby
Stars
987
Forks
541
Avg merge
17h 40m
Merged PRs (30d)
19

Description

### Summary
Log entries emitted by middleware that runs *before* `Sentry::Rails::CaptureExceptions` in the Rack stack (most notably Rails' own `Rails::Rack::Logger`, which logs `"Started GET \"/path\" for ..."`) get a `trace_id`/`span_id` that doesn't match the rest of the request's logs/spans. This makes `trace_id` unreliable as a way to group "everything that happened during this one request" in Sentry Logs/Structured Logging.

### Environment

- `sentry-ruby` / `sentry-rails` 6.4.0
- Rails 7.2
- `config.enable_logs = true`, `config.enabled_patches << :logger`, Rails structured logging subscribers enabled

### Steps to reproduce

1. Enable `config.enable_logs = true` and the `:logger` patch (or Rails structured logging subscribers).
2. Make a request to any controller action.
3. Compare the `trace_id`/`span_id` attributes on the log entry for `"Started POST \"/foo\" for ..."` (from `Rails::Rack::Logger`) vs. the log entry for the controller action itself (e.g. from `Sentry::Rails::LogSubscribers::ActionControllerSubscriber`, or any `Rails.logger.info` call inside the action).

### Actual behavior
The `"Started ..."` line has a *different* `trace_id`/`span_id` than every other log line from the same request.

### Expected behavior
All log lines from a single request share the same `trace_id` (and appropriate `span_id`s), so `trace_id` can reliably group them.

### Root cause (as far as I can tell)

`Sentry::Rails::CaptureExceptions` is inserted here:

https://github.com/getsentry/sentry-ruby/blob/master/sentry-rails/lib/sentry/rails/railtie.rb#L12

```ruby
app.config.middleware.insert_after ActionDispatch::ShowExceptions, Sentry::Rails::CaptureExceptions
```

In a default Rails app, `Rails::Rack::Logger` (which emits `"Started ..."`) sits *before* `ActionDispatch::ShowExceptions` in the middleware stack, i.e. it runs before `CaptureExceptions` even starts `Sentry.with_scope`/the transaction:

https://github.com/getsentry/sentry-ruby/blob/master/sentry-ruby/lib/sentry/rack/capture_exceptions.rb#L16-L18

At that point, `Scope#get_trace_context` has no active span:

https://github.com/getsentry/sentry-ruby/blob/master/sentry-ruby/lib/sentry/scope.rb#L341-L350

so it falls back to `scope.propagation_context`. That propagation context isn't generated from the current request at all - it's whatever was set the *first* time this pooled thread's hub was cloned, via the default (env-less) `generate_propagation_context` call made when the `Scope` was constructed:

https://github.com/getsentry/sentry-ruby/blob/master/sentry-ruby/lib/sentry/scope.rb#L406-L407

Because `Hub#pop_scope` restores the base per-thread layer after each request finishes, this stale trace_id is effectively **fixed per pooled thread** (from whenever that thread's hub was first cloned) rather than something that changes per-request - so it's not quite "leftover from the previous request" so much as "a value from whenever this thread's hub was born," but the practical effect is the same: it's unrelated to the current request's trace.

Once `CaptureExceptions` runs and starts the real transaction a few lines later (via `continue_trace` → `scope.generate_propagation_context(env)`), every subsequent log correctly shares that transaction's `trace_id`/`span_id` - only things logged *before* `CaptureExceptions` runs are affected.

There's actually a second, compounding issue: even once `continue_trace` runs, if the request isn't continuing an *incoming* distributed trace (the common case - no `sentry-trace` header), `continue_trace` returns `nil`, and `Hub#start_transaction`'s fallback (`Transaction.new(**options)`) generates its own **independent** `trace_id` via `Utils.uuid`, completely ignoring the trace_id that was just established on `scope.propagation_context`. So the transaction (and everything logged after it starts) ends up with yet another trace_id, unrelated to whatever a piece of middleware placed before `CaptureExceptions` would have seen even if it ran with perfectly fresh/correct context.

### Suggested fix
`CaptureExceptions` currently bundles two separate concerns:

1. Establishing trace/scope context for the request (ideally as early as possible).
2. Exception capturing + skipping transaction creation for static asset requests served by `Rack::Sendfile`/`ActionDispatch::Static` (this is why it's deliberately positioned relative to `ActionDispatch::ShowExceptions`, per the existing comment in `railtie.rb`).

Because these are coupled into one middleware, it can't be moved earlier without also moving the exception-interception logic earlier, which is presumably not desired.

Splitting out a small, separate middleware that only establishes trace/scope context (inserted much earlier - e.g. as the very first middleware), while leaving today's `CaptureExceptions` exactly where it is for exception handling, would let early-lifecycle log lines share the correct trace context without touching the existing exception-capture/asset-skip behavior. `CaptureExceptions` (and `Hub#continue_trace`/`Hub#start_transaction`) would then need to detect that context was already established for this request and reuse it rather than clobbering/diverging from it.

I've prototyped exactly this (new `Sentry::Rails::CaptureContext` middleware + a small opt-in env flag so the rest of the pipeline reuses the established context instead of regenerating it) and it resolves the issue in my testing. Opening a PR with that patch shortly - happy to adjust the approach if there's history here I'm not aware of.

Contributor guide

Open the contributing guide

Assessment

This issue has not been assessed yet.

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.