Serguey Asael Shinder: Log the decision, not the step you happened to be on
Most logging I inherit records progress:
INFO Starting import
INFO Loaded 1 204 records
INFO Validating
INFO Import finishedEvery line is true and none of them helps when the import produced the wrong answer. They record that the code ran, which I can already tell from the fact that we have output.
The line that would have helped
What I always want, and rarely find, is the decision: the place where the program chose between two paths, and the value it chose on.
INFO import: 1 204 records; 37 skipped (missing vat), 2 merged (duplicate email)
INFO import: pricing from cache (age 4m12s, threshold 5m)Both lines describe a branch. The first says how many records took the rejection path and why. The second says which of two sources was used and the number that decided it — so when the price is stale I can see that the cache was 12 seconds inside the window, without reading the code to find out what the window is.
The rule, stated as a test
Before writing a log line, ask: could I reconstruct this from the code and the output?
- "Starting import" — yes, trivially. Delete it.
- "Loaded 1 204 records" — yes, it is in the result. Keep it only if the result is not visible where the log is read.
- "37 skipped (missing vat)" — no. The rejection path leaves no trace anywhere else. This is the line.
- "pricing from cache (age 4m12s, threshold 5m)" — no. Which branch ran is invisible afterwards, and the threshold makes the age meaningful.
Anything that survives the test is a fact about this run that exists nowhere else. That is the entire criterion.
Three shapes that come up constantly
A rejection is a decision. Every filter, every continue, every if (!valid) return is a path that throws information away silently. Count them and report the counts once, with reasons, at the end. A per-item log line at DEBUG is not a substitute, because DEBUG is off in the run you care about.
A fallback is a decision. Cache, retry, secondary region, default configuration — all of them produce a correct answer along an unexpected path. If a fallback is never logged at INFO, the system can run in its degraded mode for months and look healthy.
A threshold comparison is a decision, and log both numbers. over limit is half a line. queue depth 10 421, limit 8 192 is the whole one, and it tells the reader whether this was marginal or a landslide.
What this costs
Fewer lines, not more. The four-line progress log above becomes two lines that carry more information, and the noise that goes away is the noise that trains people to stop reading logs. Every incident I have worked ends the same way: somebody scrolls past two hundred lines that say things ran, looking for the one line that says which way it went.
Write that line.