Logging

Back when a service ran on one server, finding a cause was simple. Something broke, you connected to that server and read what had been printed. You added a line that printed a value wherever you were suspicious, then ran it again.

That approach fell apart as servers multiplied. With the same program running on ten machines, the first unknown is which machine handled the failing request. Connecting to each in turn and digging through files eats half an hour, and with disposable units like containers the instance that failed is often already gone, taking its files with it. A customer reporting that "saving didn't work earlier" was frequently a dead end, because "earlier" couldn't be pinned to a time.

So producing the record and keeping it got separated. Programs only emit what happened in an agreed shape, and a different system collects those lines in one place and makes them searchable. Logging settled as the name for the front half — deciding what to emit and emitting it.

One line describes one event. It carries when it happened, how serious it is, what occurred, and the values involved: "14:02:11 / ERROR / document save failed / user 8821 / document 4402 / cause timeout". Naming each value instead of writing prose only is called structured logging, and it's what makes it possible to pull every line for user 8821, or count failures by cause, with a search.

Severity usually comes in five levels.

1. DEBUG — detailed values meant for development. Normally switched off in production.
2. INFO — things that happened normally, like a successful login or a batch job starting.
3. WARN — not a failure yet, but odd. A retry that succeeded, or a response slower than usual.
4. ERROR — one request failed. Most lines a person needs to read sit here.
5. FATAL — the program itself can no longer continue.

The levels exist to keep the everyday volume down. Production keeps INFO and above, and when something is wrong the level is dropped to DEBUG for that area just long enough to look.

Lines also need something to group them. One request may emit ten lines, and with a hundred people using the product at once those become a thousand interleaved lines. So each incoming request gets a unique identifier and every line it produces carries that identifier. Searching for it later collects the story of that one request.

What not to record gets decided in advance too. Passwords, card numbers, and government ID numbers are personally identifiable information (PII), and putting them in a log extends the exposure for as long as those lines are retained. Values like that get masked or replaced before the line goes out.

The heaviest use is the last step of narrowing down an outage. Find the time failures spiked on a chart, work out which part is slow, then read the lines from that moment in that part to see what caused it. The evidence attached to a write-up of an incident is usually these lines.

Support questions run the same way. Given "sharing didn't work yesterday afternoon," you search that account's lines in that window to see whether a failure actually occurred and what caused it. The less reproducible a problem is, the more this record becomes the only evidence there is.

Deployments get watched through logs as well. After a new version goes out, you check whether ERROR lines are running above normal, and roll back if they are. Some teams wire alerting to fire when a particular message appears more than a set number of times.

The cost gets planned up front. Every line takes storage, and indexing it for search costs more. At hundreds of millions of lines a day, only the last two weeks stay immediately searchable and the rest moves to cheaper storage to be pulled when needed. Records kept for audit, where a law or a contract sets the retention period, are handled separately.

"Do you have the request ID? With that I can pull just that one."

A way of saying the single request can be separated out of the interleaved lines.

"There's nothing in the logs for this, so I can't confirm it."

No line is written at that point in the code, so there's no evidence either way.

"Let's drop it to DEBUG, watch for thirty minutes, and put it back."

Turn the detailed lines on briefly and turn them off before the volume becomes a problem.

At Pagedeck, document saves started failing intermittently. A few a day, never reproducible, and the support queue had one sentence: "sometimes it won't save." Theo gathered the lines for the failed save requests and found they all came from a single document, with the same value in the cause field. Every one had happened the moment more than six people were editing at once.

Until then there had only been a count of failed saves. That number said failures were up and nothing more, so the reason meant going into the servers every time. After this, Theo changed the failure line to record the number of concurrent editors alongside it. Most improvement in logging comes from adding values to a line like that rather than from adopting a new tool.

Assuming more is better is the easy mistake. Writing everything down in case it's needed later sounds reasonable. But volume raises two things at once: the cost of keeping and searching it, and the odds that the line you want is buried. Turn a place that emits ten lines a day into one that emits a thousand and the first page of search results fills with them while the single ERROR line goes unseen. The test isn't volume, it's whether a line changes what you would do. A line that leaves your next action unchanged doesn't need to exist.

Treating a pile of logs as observability achieved is the other one. It's the most detailed record available, so the inference is natural. But logs only help once you know where to look. That something is going wrong at all is what numeric signals tell you, and which part of a multi-piece system is stuck is what a joined-up request path tells you. A team with only logs finds out from the customer, and even then starts by hunting for which minute to search.