PhilipAng
← All writing

August 20262 min read

What five years of on-call taught me about writing logs

The log line you need at three in the morning is never the one you wrote at three in the afternoon. Some rules I now follow without arguing.

  • Career
  • Engineering

I have been paged enough times to have opinions about logging, and almost all of them are about the gap between writing a log line and reading one.

When you write it, you have the whole system in your head. When you read it, you have been asleep for four hours and you are looking at one line out of two million.

Log the decision, not the arrival

The most common log line in any codebase is some variant of "got here".

logger.info("processing payment");

This tells you the code reached a line, which you already assumed. What you actually want is the branch it took and why:

logger.info("payment routed", {
  paymentId,
  processor: "stripe",
  reason: "currency_unsupported_by_primary",
  amountMinor: 4999,
  currency: "GBP",
});

Now the line answers a question instead of announcing an event. At three in the morning you are always asking "why did it do that", never "did it get there".

Structure everything, format nothing

logger.info(`User ${user.email} failed login from ${ip} (attempt ${n})`);

You cannot query this. Finding every failed login for one address means a regex against a string you have to reverse-engineer from the source. Put the fields in fields, and let the log tool do the joining.

The formatted string is optimised for the one case where you are reading logs with your eyes, which is the rarest case.

Every error gets an identifier the user can read

When something fails, generate an id, log it, and show it to the user. A support ticket that says "error 7f3a9c" turns a forty-minute archaeology session into one query.

It costs almost nothing and it is the single highest-leverage logging change I have made.

Log what you decided not to do

Silent skips are the hardest bugs to find, because there is nothing to search for.

if (!user.emailVerified) {
  logger.info("notification skipped", { userId: user.id, reason: "email_unverified" });
  return;
}

"Why didn't the email send" is answerable in one query instead of by reading the function and guessing which early return fired.

Levels are a promise about who wakes up

The only definition that survives contact with on-call:

  • error — a human needs to act, now. If nobody would act, it is not an error.
  • warn — a human should look at this within a day.
  • info — the audit trail of decisions the system made.
  • debug — off in production.

The failure mode is error inflation. Once a third of your errors are things nobody acts on, people stop reading errors, and the one that mattered scrolls past. An error log that nobody trusts is worse than no error log, because it costs the same to produce and buys nothing.

Never log the secret

Obvious, routinely violated. Connection strings in startup logs. Tokens in request dumps. A whole request body containing a password.

The rule I use is mechanical rather than judgement-based: secrets never enter a log call, and objects that might contain one get an explicit allowlist of fields rather than being spread. Judgement fails at three in the morning. Mechanical rules do not.