DebuggingGENERALSCALE-SPECIFICILLUSTRATIVE

Logs Are Evidence, Not Thinking

A log line is an observation that was cheap to make in advance. It supports or kills a hypothesis; it does not generate one. "Add more logging" is only a plan when you can say which hypothesis the new line would distinguish.

The moveWorked exampleNext questions

The situation, the reflex, and why it stalls

Every lesson starts where being stuck starts: someone has a problem, and the first move that comes to mind feels like progress.

The question

You have thousands of log lines and no idea what caused the failure. What is logging for, and how do you use it without drowning in it?

The situation

Payment failed. You open the log aggregator and search for "error". There are hundreds of hits from the last hour: retries, a warning about a deprecated option, a stack trace from an unrelated cron job. Someone suggests adding more logging; someone else suggests the logs are useless.

The reflex

Read the logs from the top, or add log lines everywhere in the suspect code and re-run. Both feel like gathering data, and data is what a good debugger wants.

Why it stalls

Reading unfiltered logs produces a list of true facts with no way to rank them. The deprecated-option warning is real and is not the cause; without a hypothesis, nothing says so.

What the reflex produces — and fails to produce
  • Reading unfiltered logs produces a list of true facts with no way to rank them. The deprecated-option warning is real and is not the cause; without a hypothesis, nothing says so.
  • Logging everywhere produces noise that hides the line that matters, and the re-run takes time; when the new lines all print, they confirm that the code ran, which was not in doubt.
  • The log becomes a substitute for thinking about where the failure could be. "Let's see what the logs say" postpones the hypothesis to after the reading, and the reading has no end.
  • The evidence that would settle it is missing — the provider's response body, the request id, the order state at the time — because nobody decided in advance what a future debugger would need to know (Debuggability by Design).
ProblemUnderstandRequirementsConstraintsUnknownsDecompositionSmallest StepModelExperimentObserveDebugLearnIterate

The move

Precisely enough to apply it to a problem you have never seen — not a slogan.

  • Treat each log line as a recorded observation at a point in the system, and use it the way you use any observation: to test a hypothesis you already hold. Search the log for the thing your hypothesis predicts, not for "error".
  • Read along one request, not along time. A request id or correlation id threads the lines that belong to one checkout through every layer; without it, the log is a pile of interleaved stories.
  • When the log cannot answer the hypothesis, add exactly the line that would — at the boundary where the hypothesis says the data goes wrong, carrying the values the hypothesis is about — and nothing else. A log line added with a prediction is instrumentation; one added without is noise with a timestamp.
  • Decide in advance what a future debugger will need: at every boundary, what came in, what went out, and an id that links them. That decision is design, and it is cheaper than any amount of debugging without it.

"We need more logging", climbed

The suggestion is often right and almost never specific. The ladder asks why until the requirement is a line at a boundary carrying named values — and it also names the case where the original suggestion was right as stated, because a system with no boundary logging at all does need more, everywhere the data crosses a line.

From "more logging" to one line

We need more logging.

  1. Why? Because when payment fails we cannot tell what happened.
  2. Why can we not tell? Because the log shows the outbound call to the provider but not what the provider answered.
  3. Why does that matter? Because the hypothesis is that the provider succeeded and our order update failed afterwards, and without the response we cannot distinguish that from a decline.
  4. Why is that the hypothesis worth deciding? Because it is the case where a customer is charged and told they were not — the one we must never leave unexplained.
real requirement At the provider boundary, record the request id, the provider's status, the charge id and the outcome of our subsequent order update, so that "charged but unpaid" is a query.
simpler One structured log line after the provider call and one after the order update, both carrying the request id — not logging in every function of the handler.

the claim was right when The system has no boundary logging at all. Then "more logging" is exactly right: a line at every boundary, inbound and outbound, with an id, before any specific hypothesis — because without it no hypothesis can be tested.

Reading by time against reading by request

The same log read two ways. The first is what the aggregator shows by default and the second is what the request id makes possible. The difference is whether the lines form a story.

The same failure in the log
Search for "error", read by time
Hundreds of lines from every request in the last hour, interleaved: retries from the image service, a cron job's stack trace, a deprecation warning, and somewhere among them the four lines of the failing checkout, not adjacent to each other.
Filter by request id, read in order
Four lines: pay request received with cart id; cart loaded; TypeError at the line reading cart items; 500 sent. No outbound provider call. The story of one request, in order, across the layers it touched.

A hypothesis about one request can only be tested against that request's lines. Time order mixes every request's story together; the id separates them, and the absence of an expected line — the provider call — is visible only when you know all the lines you are looking at belong to the same request.

What a useful line carries

Two lines, both from the provider boundary. The first records that code ran; the second records an observation a future debugger can query. Note what the second one does not carry: the card number, which is evidence of nothing and a liability in every log store it reaches.

A line that says nothing, and one that is evidence
1# says that code ran
2INFO calling provider...
3INFO done
4
5# says what crossed the boundary, and can be queried
6INFO provider.charge request_id=r-8c1f order_id=o-4412 amount=4999 currency=EUR
7INFO provider.charge.result request_id=r-8c1f status=200 charge_id=ch_9a3 outcome=succeeded
8ERROR order.mark_paid request_id=r-8c1f order_id=o-4412 error="deadlock detected"

With the second form, "charged but unpaid" is a query: provider outcome succeeded and no matching mark_paid success for the same request id. With the first form it is a feeling.

How to do it

Most important first.

  • Form the hypothesis first (Debugging Is Problem Solving), then write down what line you expect to find in the log if it is true, and what you expect if it is false.
  • Find the request id from the failing request — the network tab, or the response headers — and filter the log to that id before reading anything.
  • Read the filtered lines in order across layers: what arrived, what was sent onward, what came back, what was written. The first line that disagrees with your model of the request is where the bug is or is near.
  • If the line you need does not exist, add it at the boundary, with the request id and the values in question, and re-run the reproduction once. Keep it if it is the kind of line every request should have; remove it if it was a probe.
  • Structure the lines: fields, not sentences, so that "all pay requests with provider status ≠ 200 in the last hour" is a query and not a regular expression (Structured Logging: Fields a Program Can Read).

Worked on a concrete problem

The move has to produce something. This is what it produced.

  • Hypothesis: the backend calls the provider and mis-handles a declined response. Prediction: a filtered log for the failing request id shows an outbound call and a non-success response. Observation: filtered to the id, there are four lines — request received, cart loaded, TypeError in the handler, 500 sent. No outbound call. The hypothesis is dead and the failure is placed before the provider call, in seconds, from lines that were already there.
  • Hypothesis for a second bug: the provider succeeds but our database write afterwards fails, so the customer is charged and told it failed. Prediction: the log shows the provider returning success and a later error on the order update. Observation: the log has the outbound call but never records the provider's response body. The line does not exist. Add one line — at the provider boundary, with request id, provider status and charge id — re-run the reproduction, and the prediction can now be checked (What If Payment Fails?).
  • The "more logging" proposal, made precise. Falsifiable form: "if we log X at boundary Y, hypothesis H becomes decidable". For the second bug, X is the provider response, Y is the provider call, H is the failed write after a successful charge — and that line is worth adding permanently, because every charge should record what the provider said. "Log everything in the handler" has no X, Y or H and is not a plan.

How you know it worked

What now exists that did not before, and what question you can now ask.

  • You search the log for a predicted line, and either find it or find its absence; both are results.
  • You can read one request's story across every layer in order.
  • Every log line you add is attached to a hypothesis and a boundary, and you can say whether it stays.
  • The system records, at each boundary, what came in and what went out, so the next bug starts with evidence rather than with adding it.

The questions you can now ask

The field this whole domain exists for. After this lesson, these are the questions to put to an unfamiliar problem.

Next questions
  • ?What line would I expect to find if my hypothesis is true — and what if it is false?
  • ?What is the request id, and can I read this one request's story across every layer?
  • ?At which boundary does the data go wrong, and does a line exist there that shows what crossed it?
  • ?If I add a line, which hypothesis does it distinguish, and should it stay after the bug is fixed?
  • ?Is this log line a claim by code that might be wrong, or an observation of state I can verify elsewhere?

What can go wrong

How the move itself fails
  • Logging so much that the storage cost and the noise both grow, and the line that matters is one in a million (The Log Bill and What It Is Buying).
  • Logging the wrong thing: "entering handler" and "leaving handler" record that code ran, not what it did with what data. The useful line carries values at a boundary.
  • Logging secrets — card numbers, tokens — because "we might need them", which turns the evidence store into a liability (Secrets in Logs).
  • Trusting the log over the system. A line says "order marked paid"; the row says unpaid. The row is the truth and the line is a claim made by code that may be the bug.
What the move costs
  • Hypothesis-first reading can miss a cause you did not think to hypothesise. Occasionally an unfiltered scan turns up the unexpected line — the deprecated option was, this once, the cause. The move is a default, not a ban on browsing.
  • Boundary logging with ids costs design effort up front and a little per request forever, on systems where most requests are never debugged.
  • Adding a probe line requires a re-run, which for an unreproducible bug means waiting for the next occurrence with the line in place.
Misreads
  • "Logs are the bad version of a debugger." They are the observation you can make after the fact, in production, across services, without stopping anything. A debugger sees more at one point; a log sees one thing at many points and many times.
  • "Good logging means logging a lot." It means logging what crosses boundaries, with an id, in a queryable shape. Volume without those is cost.
  • "If it's in the log it happened." A log line is written by code, and the code can be wrong about what it did. Verify claims about state against the state.

Where this applies

Problem-solving advice is stated as universal far more often than it is. These labels say what each method is specific to — and where CONTESTED appears, the note gives the strongest form of the opposing view.

  • GENERALReading evidence against a hypothesis is the same for logs, traces, metrics and database rows; logs are the most common form and the easiest to produce badly.
  • SCALE-SPECIFICAt small scale, unstructured lines and grep are fine and structured logging is overhead; once several services handle one request, the correlation id and a queryable shape stop being nice-to-haves and become the only way to read one request's story.
  • ILLUSTRATIVEThe four filtered lines, the missing provider response and the deprecated-option warning are invented to show logs being used as evidence; no real logging setup is described.

Where the depth lives

This domain asks the question and hands the answer off by name.

Further
  • The manifesto's layers page at /manifesto/layers is worth a look here: the log line at a boundary is the record of one layer handing to the next, and deciding what it carries is deciding what you will be able to know later.