Runbook pages.

Builds & investigations Design note

Dynamic per-user Rails debug logs, scoped to the request

One user could reproduce a production bug. A request-scoped Rails override captured their debug logs, expired on its own, and left other traffic alone.

12 min read · updated

railsloggingsemantic_loggerredisplatform

Share

Component-level debug logging still records every user who calls that component. I wanted logs from one user's next few requests, with a tag I could search for in the aggregator.

Changing Rails.logger.level = :debug would enable debug across the app. The per-component override from the previous post narrows that to a service, but it still includes accounts I'm not investigating. That post also covers why production usually defaults to info or warn.

This override needed to apply to the current request and clear when it finished, including when it raised an exception. I also wanted it to expire on its own and work alongside the component-level setting.

The request boundary

Concrete requirements:

Per-user, not per-class. Last post's dial handled per-class. The new one works on the orthogonal axis.

Request-scoped. When user 12345's next request comes in, that request's lines emit at debug. When their request completes, the dial unwinds. The next request on the same worker thread starts clean.

A wall-clock TTL on top of that. If I turn on debug for a user at midnight chasing a bug, I shouldn't wake up to nine hours of debug spew across whatever traffic they generated overnight. A finite TTL on the dial entry handles cleanup so I don't have to remember.

Filterable in the aggregator. I want a query like user_debug=12345 (or whatever syntax your stack uses) to surface exactly the lines from that user's debug session, none of the other users, none of the other request types.

Cooperative with last post's per-component dial. If MailerService is already dialed up via the class-level pattern, my per-user override should still be able to push it further for the one user. The two layers should compose, not collide.

Approaches I considered

Rails.logger.level = :debug for the fleet. It's the same sledgehammer I covered last post.

The per-component dial from last post. Closer. Dial PaymentsService to debug, get debug for that one class. But you also get debug for every user's calls into PaymentsService, which is the wrong shape when the bug is one user.

ActiveSupport::TaggedLogging. The default Rails answer for "scope a logger to a request." But it adds tags only, it doesn't change which lines emit1. Wrapping a request in Rails.logger.tagged("user-12345") do ... end gives me a tag on every line that already would have emitted at the current global level. The debug lines I actually wanted still don't fire, because the level is still wherever the app's default sits.

Prefab's filter approach. Same as the previous post: solves it, SaaS dependency, plus the appender-filter shape composes oddly with the class-level dial. Both layers see every line independently and have to agree.

A custom logger subclass with a thread-variable level. Wrap Rails.logger in a subclass that consults a thread variable for the current minimum level. It's doable in maybe twenty lines of code. But it duplicates work that semantic_logger already does and adds a custom logger that future readers have to mentally model. I had a working semantic_logger pipeline. I didn't want to fork it for one feature.

SemanticLogger.silence in an around_action. Once the per-component dial from last post was clean, this turned out to be the right answer. silence(level) is a block-scoped function on a thread-local minimum level2. It lowers the threshold for the duration of the block. The block is ensure-scoped, so nothing leaks if it raises. There's no per-line overhead either. And it cooperates cleanly with the per-component dial as long as you built the dial right. (See post 1's trap section.)

What ruled all of these in or out: the dial had to be per-user and request-scoped, had to filter cleanly in the aggregator, and had to coexist with the existing per-component pattern. silence plus tagged met all four.

Follow one user through a reused worker.

Pick a user. Send all three through one thread.

Adainfo · request completed
Samdebug · controller, service, response
Joinfo · request completed
ensureThread reset to info after every request.

Sam · debug · 30m

Fictional synchronous requests. Jobs and other threads need their own propagation.

The control path

A small module:

module RequestScope
  def self.apply(user_id, &)
    return yield if user_id.blank?

    override = Cache.level_for(user_id)
    return yield if override.nil?

    SemanticLogger.silence(override) do
      SemanticLogger.tagged(user_debug: user_id, &)
    end
  end
end

Wired at the application controller as an around_action:

class ApplicationController < ActionController::Base
  prepend ComponentLogger          # from the previous post
  around_action :apply_user_debug_logging

  def apply_user_debug_logging(&)
    RequestScope.apply(current_user&.id, &)
  end
end

Three lines of glue plus the module. All of the surface area lives here.

Inside apply:

Cache.level_for(user_id) checks an in-process map for an override. If nothing's set, the block runs unwrapped and the cost is one map lookup. No-op for ~99% of requests.

If an override exists, we wrap the block in two ensure-scoped layers.

SemanticLogger.silence(override) sets a thread-local minimum level for the duration of the block. While the block is running, any logger whose own @level is unset falls back to a check against this thread-local, and lines at the silenced level (or higher) emit. Lines below the silenced level still get short-circuited.

SemanticLogger.tagged(user_debug: user_id, &) attaches a named tag to every log entry inside. Both silence and tagged are ensure-scoped inside semantic_logger, so the thread-local state restores even if the block raises. There's no risk of a per-user dial leaking onto the next request that lands on the same worker thread.

In the aggregator, this shows up as a structured tag on every line emitted during that user's request. Whatever query language your aggregator speaks, you can pin a query to just that user's session and exclude everything else: other users' requests, health checks, unrelated background traffic.

The store and the cache

Cache.level_for(user_id) reads from a process-local concurrent map. The map gets refreshed when the per-user store changes, which keeps the per-request lookup at memory speed.

The store under the cache is a single Redis hash, keyed user_debug_logging, with each field keyed by user_id and the value encoding the override. I went with a hash rather than separate keys per user (user_debug:12345, user_debug:67890, and so on) for two reasons. The first is enumeration: pulling every active override is one HGETALL instead of a SCAN across the keyspace, which matters when an operator wants to list everyone currently flagged or clear them in a hurry. The second is locality: every override sits under the same key, so dumping the full state, counting active overrides, or wiping the whole thing is a one-line operation. The separate-key shape scatters the overrides across the keyspace and forces a SCAN every time.

Redis 7.4 changed the hash tradeoff by adding HEXPIRE and HPEXPIRE, which can expire individual fields.3 This design ran on an older Redis version, so expiry stayed in the value. Each entry encoded level:expires_at. Reads treated an expired timestamp as missing and lazily deleted the field. A broadcast refresh also swept expired fields while it already had the hash in memory. Newer deployments can keep the enumeration benefit and let Redis enforce the field lifetime.

The cross-pod invalidation question, how does pod B find out that pod A wrote a new override, gets handled by a broadcast layer on top of the same store. That's a separate post about the broadcast pattern itself. For this post, "the cache is fresh within a second of any write" is enough.

The cooperation with the per-component dial

SemanticLogger.silence only takes effect when the per-class logger's @level is unset. The per-component dial from the previous post has a deliberate @level = nil branch: when the config store says "default level for this class," it clears @level rather than leaving it pinned at whatever the last write was. That cleared state is what lets the thread-local silence kick in for that class.

Without that branch in post 1, the per-user override would silently fail for any class that had ever called logger after boot. The class would have @level pinned to whatever the app's default is (info, warn, depending on your config), the silence would be ignored, and the debug lines wouldn't emit for that class even with the user-level dial set. The investigation would seem fine. The override would be in the store. The around_action would be firing. The tag would be on the lines that did emit. But the lines you cared about wouldn't be there.

The two features cooperate because the per-component dial deliberately leaves room for the per-user one to take over. Building post 1 without thinking about post 2 would have made post 2 silently broken. The fix in post 1 takes one line and one comment, but it carries the weight of this whole pattern.

What improved

A working dial for "log everything for this one user, for the next 30 minutes." Write the override into the config store from a Rails console, an internal admin endpoint, or whatever surface you want to expose: user_id: 12345, level: :debug, expires_at: 30.minutes.from_now. The next request from that user hits the around_action, picks up the override, and emits debug logs for the whole request lifecycle. The aggregator receives every line tagged with a user_debug field set to that user's id. Filter on the tag, see only that user's session.

After 30 minutes the entry expires. The next read returns nil. The around_action becomes a no-op for that user. There's no cleanup to do, no follow-up to remember.

User-level overrides apply to components that still inherit the default. An explicit class-level pin takes precedence. I need to reset that pin before expecting silence(:debug) to produce finer logs for one user.

The limits

Per-user debug access needs a narrower control plane than an ordinary log-level switch. I would require an authenticated operator, record who created the rule and why, cap the duration, and make early revocation easy. The log tag should use a stable internal id rather than an email address. Existing secret and sensitive-field redaction still has to run before any event leaves the process.

Async jobs need a small wiring step. Thread-locals don't auto-propagate across the ActiveJob boundary, so a job enqueued during user 12345's request runs on a different thread (often on a different process) where silence is unset. Good news: this comes up often enough that the patterns are well-worn. Three standard fixes:

  1. Pass the user id explicitly as a job arg. The job has user_id in its arguments and calls RequestScope.apply(user_id, &) around its work. An Active Job around_perform callback can wrap subclass implementations of perform.
  2. Use ActiveSupport::CurrentAttributes with backend support. CurrentAttributes scopes ambient state inside one execution context. It does not make every Active Job adapter carry that state automatically. Sidekiq supports an explicit Sidekiq::CurrentAttributes.persist("Current") setup, while other adapters need their own documented hook.4
  3. Backend-specific integration. Sidekiq exposes client and server middleware for capturing and restoring context. Other adapters expose different extension points, so check the adapter's contract before applying that pattern. Sidekiq's tagged-logging context is one example.

I went with (1) because the jobs in our app already pass user_id for unrelated reasons. (2) is probably cleaner if you're starting fresh, since the auto-propagation removes a class of "I forgot to thread the override into this job" bugs.

Non-controller paths need their own wiring. The hook lives in a controller around_action, so anywhere the request boundary isn't a controller (cron triggers, message-broker callbacks, internal pollers, signal handlers), the around_action doesn't run. The fix has the same shape: call RequestScope.apply at the entry point of whatever the path is. Each entry point has to be wired explicitly. The pattern doesn't propagate by itself.

Class-level dials still win when both are set. If a class has been pinned to a non-default level via the per-component dial, and I want this user at a finer level than that pin, the per-user override loses for that class. The class's @level is pinned, so silence doesn't apply. In practice this comes up rarely because class-level dials are usually transient and short-lived, but it is the shape worth knowing about. The two layers compose for "user-level debug while class is at the app default" but not for "user-level debug while class has its own non-default pin."

The aggregator still has to support tag filtering for this to be useful at all. If you're on a logging stack that doesn't index custom tags, the user_debug filter does nothing for you. Most modern aggregators index custom tags by default. Some hosted budget-tier loggers don't. It's worth checking before you wire this up.

The part worth keeping

If you've built per-user logging in Rails before, especially in a multi-tenant or per-customer setup, I'd love to compare notes. The async-job propagation problem in particular has a few ways to solve it (concern on ApplicationJob, explicit pass-through in perform args, ActiveSupport::CurrentAttributes) and I'm curious which one held up for you. Email's on the contact page. The closer to "I tried this and here's the constraint that bit me," the better.

The pattern from this post sits on top of the per-component dial from the previous one. The two together cover most of the "turn on debug logging for X" cases that come up in production: X is a class, X is a user, and (with both at once) X is a class for one user.

Footnotes

  1. Rails API, ActiveSupport::TaggedLogging. Wraps a block to attach a tag to every log entry inside. The level itself is not changed. ↩

  2. Reid Morrison, Semantic Logger docs. SemanticLogger.silence reduces the minimum level for the duration of a block on the calling thread. Ensure-scoped, so the thread-local state restores even if the block raises. Per the docs, the suppression only applies to loggers that are using the global default level. If a logger has an explicit @level pinned, silence is ignored for that logger. This is the property the per-component pattern from the previous post leaves intact on purpose. ↩

  3. Redis command reference, HEXPIRE. Redis added per-field hash expiry in 7.4. Older servers still need separate keys or application-managed timestamps. ↩

  4. Rails API, ActiveSupport::CurrentAttributes, and Sidekiq documentation, CurrentAttributes. Sidekiq's propagation is opt-in middleware, not a universal Active Job behavior. ↩

Share

Comments