Builds & investigations Design note

Tuning Rails log levels per class, without a redeploy

One Rails class needed debug logs in production. A temporary per-class override changed at runtime and expired automatically, without enabling debug across the app.

Share

I wanted to turn on debug logging for one mailer without changing the log level for the rest of the Rails app.

Rails.logger.level = :debug changes the shared logger. It includes controllers, jobs, and other components I wasn't investigating. That extra output costs money to ingest and makes the useful lines harder to find.1

My goal was to change one component's level at runtime, without a redeploy. I needed the override to expire on its own, too.

Setting the level was straightforward. Making it work with inherited loggers, thread-local overrides, and Ruby's method lookup took more care.

A quick primer on log levels, since defaults vary

Ruby's standard log levels go debug, info, warn, error, fatal, in increasing order of severity. The logger holds a level threshold. Lines emitted below the threshold are short-circuited and never reach the appender. So a logger at info will emit info, warn, error, fatal lines and silently drop debug ones.

Rails defaults to info in production2. Moving to debug adds lower-level output such as ActiveRecord query logs. How much output it adds depends on the application and traffic; the ingestion cost depends on the logging backend's pricing. I wanted to keep the extra output within the component I was investigating.

The dial in this post changes one class to debug while leaving other classes at the default. A busy component can still produce a lot of logs, so the narrower scope does not replace watching the volume.

The operating constraint

A few requirements ruled options in or out.

Per-class control was the first need. Setting the level on the controller layer alone won't cut it. Most of the interesting work happens downstream of the controller, in jobs, mailers, service objects, view components, and whatever else your app has accumulated into base classes. Anywhere I have a class with a meaningful boundary, I want to be able to dial its logger independently.

It also had to change at runtime, with no redeploy involved. An investigation dial only earns its name if it's available the moment you need it, not after a CI cycle.

And it had to expire on its own. If I crank a service to debug at midnight chasing a bug, I shouldn't wake up to a nine-hour debug spew because I forgot to turn it off. A finite TTL handles the cleanup so I don't have to remember.

Approaches I considered

Cranking Rails.logger.level globally. This is the default reflex, and it works fine for development. In a production fleet of forty pods serving live traffic, it's the sledgehammer-for-surgery problem from above. Even with five-minute investigations, the aggregator cost is real, and you're polluting every other engineer's logs while you're at it. I ruled this one out fast.

Lograge. Lograge reformats Rails request logs into one-line entries and is excellent for what it does. But it's a request-line cleanup, not a level controller. The level still lives on Rails.logger. Doesn't solve this problem.

Tagged logging. ActiveSupport::TaggedLogging3 lets you wrap a block in tagged("user-123") do ... end and every log entry inside picks up the tag. But again, it's tags, not levels. Wrapping MailerService.deliver in a tagged block doesn't change which lines emit, it changes how they're labeled. It solves the filtering problem after the fact, not the volume problem.

Prefab's filter approach. Prefab.cloud provides a Semantic Logger filter wired as SemanticLogger.add_appender(filter: Prefab.log_filter)4. The filter decides whether to emit each line using dynamic configuration. Prefab also supports offline evaluation from a datafile.5 My preference was to keep control of configuration changes in infrastructure I already operated. Offline evaluation and receiving a new override during an outage are separate questions.

Plain SemanticLogger[ClassName]. Semantic Logger6 gives every class its own logger via SemanticLogger[MailerService]. That part is excellent. Each class's lines come out with the class name in the named-class slot, indexable in the aggregator with no extra work. The level on each per-class logger is a class instance variable, though, which means it's static unless something mutates it. There's no "tune at runtime" baked in. So this gives me the per-class shape but I still need to build the dial.

What ruled all of these in or out: the dial had to live in my own config store, expire on its own, and not require a redeploy or an external service.

Turn up one component.

Move Mailer to debug. The other faders should not move.

info
info
info
info
Emitted lines 8 / 12
debugMailer · details
infoMailer · started
errorMailer · failed
debugOrders · details
infoOrders · started
errorOrders · failed
debugAuth · details
infoAuth · started
errorAuth · failed
debugInventory · details
infoInventory · started
errorInventory · failed

All inherit info.

Fictional lines. Overrides expire after 30 minutes.

The control path

A small concern, prepend'd into every base class that owns a meaningful boundary in the app. ApplicationController, ApplicationJob, ApplicationMailer, ApplicationRecord, ApplicationService, ApplicationCable::Channel, ApplicationComponent (if you use ViewComponent), and any other base class your codebase has grown for things like message delivery or event broadcast. Each subclass inherits the behavior automatically.

The concern overrides one thing: the class-level logger method.

module ComponentLogger
  extend ActiveSupport::Concern

  prepended do
    helper_method :logger if respond_to?(:helper_method)
    include SemanticLogger::Loggable
  end

  delegate :logger, to: :class

  class_methods do
    def logger
      @semantic_logger ||= SemanticLogger[name]
      current_level = logger_level

      if current_level == SemanticLogger.default_level
        @semantic_logger.level = nil
      elsif @semantic_logger.level != current_level
        @semantic_logger.level = current_level
      end

      @semantic_logger
    end

    def logger_level
      if @_cached_level && @_cached_level[:expires_at] > Time.current
        return @_cached_level[:level]
      end

      level = config_store.get(logger_key)&.to_sym || SemanticLogger.default_level
      @_cached_level = { level:, expires_at: Time.current + log_level_cache_ttl }
      level
    end

    def logger_level=(level)
      level = level.to_sym
      config_store.setex(logger_key, log_level_expiry, level)
      @_cached_level = { level:, expires_at: Time.current + log_level_cache_ttl }
      @semantic_logger.level = level if @semantic_logger && @semantic_logger.level != level
    end

    def logger_key = "log_levels:#{name}"
    def log_level_cache_ttl = 2.minutes
    def log_level_expiry = 30.minutes.to_i
  end
end

Walking through it: every call to MailerService.logger checks the in-process cache. If it's been more than two minutes since the last refresh, the cache reads the config store. If the store has an explicit level for this class, the logger pins that level. If not, it clears the level. (More on why "clear" not "leave alone" in a moment.)

Setting the dial, via MailerService.logger_level = :debug, writes to the config store with a thirty-minute TTL. Once the entry expires, a process falls back when it next refreshes its local cache. A value cached just before expiry can remain in use for almost another two minutes. A strict thirty-minute cutoff would need the override's expiry deadline in the local cache too.

Use a key-value store with TTL support: setex, get, and process-local caching are the operations shown here. Pod B learns about pod A's change when its cache expires and it successfully reads the store again. An invalidation channel can shorten that delay, but the snippet does not implement one.

The include that did nothing

The prepend in the snippet above is doing real work. I tried include LoggerConcern first, the way you reach for any concern by default. It silently did nothing on the Rails base classes I cared about. The dial was set, the cache was warm, the class-level method ran when I called it directly in a console, and yet every controller.logger inside the app kept resolving to the inherited Rails.logger, ignoring the per-class dial entirely.

Method-lookup order is what trips this up. Rails base classes wire logger via class_attribute :logger, which defines both a class-level reader and an instance-level reader directly on the base class itself (AbstractController::Base, ActiveJob::Base, ActionMailer::Base, all of them). With include, the concern's instance method (the delegate :logger, to: :class) ends up shadowed in real call paths by the inherited base-class logger. With prepend, the concern's instance methods sit above the including class itself in the ancestor chain, which means the delegate always fires first and lands on the class-level method I actually wrote.

Just one keyword changed. It's worth flagging because the failure was silent: the dial appeared to work, the tests could pass if they were calling the class-level method directly, but the instance-level call paths that emit actual log lines were never going through the dial. The bug didn't fail loud.

Which level wins

Before the trap section dives into the mechanism, a picture of the two states the dial can be in. The branch that pins @level versus the branch that clears it back to nil is the load-bearing piece, and the consequence for whatever thread-local override is layered on top is the whole story.

Logger stateEffective level
Non-default component overrideThe pinned component level wins.
No component override, or it has expiredClear the pin with level = nil; thread-local scope can apply.
No component override and no request scopeInherit the application default.

The trap that took the longest to see

Look at the level-pinning block again.

if current_level == SemanticLogger.default_level
  @semantic_logger.level = nil
elsif @semantic_logger.level != current_level
  @semantic_logger.level = current_level
end

Pay attention to the @semantic_logger.level = nil branch. That's where the weight lives. Without it, here's what breaks.

@semantic_logger is a class-level instance, one per class, shared across all the process's threads. When the config store has a class-level dial set, @semantic_logger.level = current_level is correct. When no dial is set, the obvious thing is to do nothing and leave the level wherever it was. That is wrong.

Why: SemanticLogger.silence(level)7 is the gem's thread-local, block-scoped helper for lowering the minimum log level inside a block. It's the standard way to say "drop this thread's level for the duration of this block, then restore it." Per the docs, silence only takes effect when the per-class logger's @level is unset, meaning the logger falls back to SemanticLogger.default_level_index, which respects the thread-local. If the per-class logger has any explicit @level pinned, silence is ignored for that logger.

That property is load-bearing for a sibling feature I'm covering in the next post: per-user per-request log overrides built on silence. If the per-class dial here pins @level whenever it runs, the sibling feature is silently dead, because every class would be ignoring the thread-local override.

So if the method body sets @semantic_logger.level once, to anything, and never clears it, the thread-local override is permanently dead for that class. The first call to MailerService.logger after boot pins @level to whatever the app's global default is (info, warn, whatever). Every subsequent thread-local override fails silently for that class.

Fixing it takes the explicit nil branch. Whenever the config store says "default level for this class," clear @level back to nil and let the logger fall back. The class-level dial only pins @level when a non-default override is actually set. When it isn't, the thread-local is free to take over.

This is a one-line change with a five-line comment, and the comment is the longer of the two on purpose. Anyone removing the nil branch later would assume it was a no-op.

The useful result

A working dial. Call MailerService.logger_level = :debug from a Rails console, an internal admin endpoint, a feature-flag platform, or however you choose to expose the setter to operators. The setter updates that process immediately; other processes pick it up on their next cache refresh. Logs from that class carry MailerService, and unrelated component levels stay unchanged. The added volume depends on how often the selected class runs and how much it logs.

The store entry expires after thirty minutes. Processes return to the default through the same cache-refresh path, without a manual reset.

The pattern scales to anything with a base class. I have the concern prepend'd in eight or so places, ApplicationController and ApplicationJob and the rest, and every subclass under each base inherits the dynamic logger automatically. Adding a new component is one line.

It also keeps the aggregator clean. Every emitted log carries the class name as a structured field (Semantic Logger's named-class slot), so filtering by class Just Works in whatever query syntax your stack uses. The field is already there. You don't have to add any tagging code on the app side.

The boundary

With a healthy store and calls through this logger accessor, a cached level can lag a change by the remaining two-minute cache window. Store failures and a caller holding onto the logger without going through the accessor need their own handling. Pub/sub or a watch can reduce the normal delay; neither gives the whole fleet a fixed delivery deadline.89

It doesn't change how individual lines emit, only whether they emit. If you want to filter individual lines by content, suppress every health_check, log every line for one user, that is the appender-filter approach Prefab uses. Both shapes are valid. This one is cheaper at the high-volume end because below-level lines short-circuit before reaching the appender. The filter approach is more flexible because the Proc has full context of every log line.

It doesn't help with libraries that own their own loggers. Sidekiq.logger, gem-internal logging, anything that resolves a logger by some other path goes through whatever level it was configured with. The pattern is "every component I own."

The pattern most surprised me by working everywhere. The interface is the same anywhere a base class exists: prepend ComponentLogger and you're done. The dial is now available for that class.

What I'd revisit today

I shipped this with a TTL cache. At read time, every pod checks its own in-memory map. Every pod independently decides when to refresh. Writes wait out the cache window before showing up everywhere. That worked, and the production fleet has been running on it for over a year. But the more system design I've done since then, the more I'd push back on the TTL-cache shape if I were proposing it in a design review today.

The structural issue is read-side polling. Every pod has its own refresh schedule. During an active investigation, when I'm flipping the dial back and forth checking a hypothesis, that lag is frustrating. I would want to see which revision each pod has applied, especially before concluding that an absent debug line means the code path did not run.

Three ways to change that trade-off:

  1. Pub/sub invalidation. Commit the new value, then publish a notification so connected pods can drop their caches. Redis Pub/Sub is at-most-once: a disconnected subscriber misses the message.8 Keep a periodic refresh and reload after reconnect. The gap between the store write and notification also needs a recovery path; two separate operations are not an atomic broadcast.
  2. Watch-based config. A Kubernetes ConfigMap watch can notify clients about changes without waiting for each local TTL. A disconnected client must resume from its resource version or relist if that history has expired.9 I wrote about this pattern. It changes how updates arrive, not whether a slow or disconnected pod can lag.
  3. Versioned snapshots. Associate each immutable snapshot with a revision. Checking that revision can detect an old cache, but the revision and data need a consistent publication and read protocol. Separate reads can race with a writer, and another update can commit after a successful check. Stronger freshness needs an explicit store consistency contract; a version key alone does not provide one.10

The next post extends this dial into per-user, per-request overrides. For a new implementation, I would consider notifications alongside the TTL cache, and keep the refresh path for missed messages. I would measure propagation and make stale revisions visible before promising an operator that the whole fleet has changed.

What survived the implementation

If you've built something similar, or hit a failure mode I didn't, especially around the cooperation with thread-local overrides, I'd love to compare notes. Email's on the contact page. The closer to "I tried this and here's what bit us," the more useful.

Up next: the per-user flavor of this pattern. How to dial debug logging for one specific user through their next handful of requests, without redeploying, without affecting any other users, and without stomping on the per-component dial described here.

Footnotes

  1. Prefab Cloud, Changing Log Levels At Runtime in Rails. The "sledgehammer for surgery" framing for Rails.logger.level = :debug lives in this post. ↩

  2. Rails Guides, Debugging Rails Applications · Log Levels. Production defaults to :info. Levels go :debug, :info, :warn, :error, :fatal, :unknown, in increasing severity, and debug-level emissions in production "can have a massive impact on performance" because of how often Rails internals log at debug. ↩

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

  4. Prefab Cloud, Dynamic Ruby Log Levels With Semantic Logger & Prefab. Covers the appender-filter shape as of prefab-cloud-ruby 1.6.0. ↩

  5. Prefab documentation, Offline Mode. Backend SDKs can evaluate a previously exported configuration datafile without connecting to Prefab's servers. ↩

  6. Reid Morrison, Semantic Logger docs. Per-class logger via SemanticLogger[YourClass], the building block this pattern wraps. ↩

  7. Reid Morrison, Semantic Logger. SemanticLogger.silence reduces the minimum level for the duration of a block on the calling thread. Per the docs, suppression only applies to loggers using the global default level. If a logger has an explicitly configured @level, silence is ignored for that logger. This is the property the nil branch above leaves intact on purpose. ↩

  8. Redis documentation, Pub/Sub delivery semantics. Delivery is at-most-once; messages missed during a disconnection are not replayed. ↩ ↩2

  9. Kubernetes, Efficient detection of changes, and etcd, API guarantees. Watch clients need reconnection and history-expiry handling. A watch does not promise bounded delivery latency. ↩ ↩2

  10. etcd, API guarantees. The documentation distinguishes atomic and linearizable key-value operations from watch delivery and potentially stale serializable reads. ↩

Share

Comments