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

[runephilosof-abtion]

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_ids), 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

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.

[linear-code]

RUBY-200

[sl0thentr0py]

Ideally our middleware would be first in the middleware stack but I think there's a reason the original author of the sentry-rails gem put it in this place. I'll investigate a bit and get back to you.

[runephilosof-abtion]

From the PR

Sentry::Rails::CaptureExceptions is deliberately positioned right after ActionDispatch::ShowExceptions (to skip transaction creation for static asset requests).