Every developer has lived through this scene: the adrenaline spike when a production incident is announced. That mix of dread about what you are going to find and frenzy to collect any piece of information that will let you understand and then fix the problem.
It happened to me again a few days ago. I can still picture myself rushing to the logs, and I still remember the frustration of finding nothing but basic information and an unhelpful error message: “Unable to load cache”.
Frustration quickly gave way to anger: we had lowered the log level a few months earlier, tired of being drowned day after day in debug logs telling us that everything was fine, that our probes were connecting without trouble, and that the databases were returning their data just fine.
Drowning in logs when everything is fine, or doomed to miss them during an incident. This logging dilemma looked to me like a curse there was no escaping.
Of course, we had also put in place a hot toggle for the log level, reassured by the promise that the powerful filters of our logging tool would give us, once the level was switched to debug, all the information needed to resolve an incident.
But raising the log level after the fact is sometimes a bad bet, especially when the error is tied to a temporal context (load spike, database backup, and so on), because it then becomes difficult or even impossible to reproduce the error in order to collect the information in the logs. And that is without mentioning the small operational frictions which, while not blocking, slow down reproduction, understanding, and therefore the fix:
- how do you identify the right pod on which to raise the log level?
- How do you handle the security of the toggle endpoints?
- How do you make their semantics clear:
- does /log/increase raise the log level or the log verbosity?
- Does /log/increase move the level toward error or toward debug?
In hindsight, the verdict is clear: the dynamic toggle is an improvement, but not the solution for our use case.
All the more so because the powerful filters do not solve the problem, at best they soften it: with more debug logs, I have the information about the incident, but it stays buried in all the noise of unrelated debug information. Looking for one very specific needle in a haystack does not fundamentally change the nature or the difficulty of the task.
The real problem is that you have to decide before the incident which logs deserve to be kept, when you only find out afterwards which ones were actually useful.
Hence the idea of a “dynamic” per-operation level, implemented by dllog (that is the DL, Dynamic Level, in dllog): error logs retroactively change the log level to reveal the debug logs that preceded them. When everything is fine you only see the logs at the current level (Info, for example), but in case of an error the Debug-level logs before and after the error are displayed as well.
In principle, you just plug into the existing logger (slog or zap for now):
logger := slog.New(dllog.NewJSON(os.Stderr))
slog.SetDefault(logger)
mux := http.NewServeMux()
mux.HandleFunc("/order", func(w http.ResponseWriter, r *http.Request) {
ctx := r.Context()
// Buffered: invisible if the request succeeds.
slog.DebugContext(ctx, "loading cart", "user", 42)
slog.DebugContext(ctx, "applying discount", "code", "SUMMER")
// An Error record first replays everything buffered above.
slog.ErrorContext(ctx, "payment declined", "provider", "stripe")
w.WriteHeader(http.StatusInternalServerError)
})
// The middleware opens one scope per request, triggering the replay on 5xx and on panic.
http.ListenAndServe(":8080", dllog.Middleware()(mux))
For the implementation, you have to watch out for performance and for the various concurrency issues:
- Circular buffers
- sync.Pool
- Lock-free operations
- Deferred formatting
- …
The result is something usable:
slog at Info:
dllog at Info:
slog at Debug:
The difference is striking: less noise when everything is fine, but the useful context when things break. The payoff: potentially fewer logs to store, and above all less time wasted understanding the incident.
So this curse was not inevitable after all. That is what I love about my job: there are always paths to explore outside of habits and near-certainties, and those paths are sometimes surprisingly effective.
Top comments (3)
The cost model here is the part I keep turning over: buffered debug logs are paid for in memory on every request, and replayed only when something fails. One scope per request with a replay on 5xx and on panic is a clean design — my question is where the circular buffer truncates. If a request emits megabytes before the error, do you drop from the front (losing the earliest context, which is usually the cause) or from the back (losing the state right before the failure, which is usually the symptom)?
And the prior question the post raises well: which debug statements deserve the buffer at all. In my experience the ones that pay off are exactly the ones that look redundant when you write them — the resolved config, the branch that got taken, the argument that was parsed differently than expected. Did dllog end up needing per-statement opt-in, or does everything at Debug level get buffered by default?
The ring is fixed-count (256 slots by default, not byte-bounded), and when it's full the oldest entry is evicted to make room. So you keep the symptom and lose the earliest cause. Three reasons I landed there:
The replay is not silent about it. The scope counts evictions and the flush reports how many were dropped, so a replay that truncated says so. You never get a buffer that looks complete but isn't, which to me is the actual failure mode worth engineering against. "I lost the cause" is recoverable if you know you lost it; "this looks like the whole story" is not.
Dropping from the back would mean deciding, at write time, that the buffer is full and this new record isn't worth keeping. That's the same premature decision that levels already force, reintroduced one layer down. Drop-oldest at least keeps the decision monotonic: the buffer is always the most recent N of the operation.
And empirically the entries nearest the failure are the ones that localize it, while the earliest ones are frequently setup you can reconstruct from elsewhere (the request line, the config, the route). That's a weaker argument than the first two and I'd change my mind on evidence.
The real answer to your scenario, though, is that a request emitting megabytes before the error is a scope that's too coarse. The unit is per-operation, not per-request necessarily, so you can open a scope around the inner step that actually fails. That's the pressure valve rather than a smarter eviction policy.
On the second question: everything at or above the buffer floor gets buffered, the floor defaults to Debug, and there's no per-statement opt-in. I considered it and deliberately didn't build it, because your own observation is the argument against it. The statements that pay off are the ones that look redundant when you write them, which means the author is exactly the wrong person to be asked, at write time, "is this worth keeping?" Per-statement opt-in asks that question in the place where it's least answerable. Buffering everything below the emit level and deciding at the end of the operation moves the decision to the moment where you actually know whether the operation failed.
The cost of that is the one you named: you pay memory on every request for logs most of which are discarded. The bound is what makes it tolerable, fixed slot count per scope, pooled rings, so it's a ceiling you can compute rather than something that grows with traffic.
Some comments may only be visible to logged-in visitors. Sign in to view all comments.