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
- Lingua principale
- Ruby
- Stelle
- 987
- Fork
- 541
- Merge medio
- 17h 40m
- PR unite (30g)
- 19
Descrizione
### 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.
Guida per i contributori
Apri la guida per i contributori
Valutazione
Questa issue non è ancora stata valutata.