omeryanbas.com

Ömer Yanbaş

General Manager, Ticofab Yazılım

OperationsPractice

Three fields that make logs worth reading

Most logs cannot answer the one question an incident asks. A correlation id, the subject being worked on and an outcome with a reason fix that.

Something goes wrong in production and you open the logs. There are four hundred thousand lines from the last hour, most of them saying Processing item or Error: failed to send, and none of them says which item or why it failed. The information needed to answer the customer is technically in there, spread across three services, with nothing to tie it together. The logs were written, they were just not written to be read.

What one line has to answer

A log line is a record made by a program for a person who will arrive later with a question. The question is almost always some version of the same three: which request was this, which record was it working on, and what happened to it. A line that answers all three is worth keeping. A line that answers none is noise that costs disk and attention.

That gives three fields that belong on essentially every line.

A correlation id, created once when work enters the system and carried everywhere. One request produces lines in the web process, in a queue worker and in an outbound call, and without a shared id those are three unrelated piles.

The subject, as a type and an id. "subject_type": "message", "subject_id": "84213" is what turns a complaint about one order into a search. Starting from a timestamp instead means reading everything that happened in that minute.

The outcome, with a reason. Not a sentence, a short code from a fixed set: "outcome": "rejected", "reason": "quota_exceeded". A code can be counted, grouped and charted. A sentence can only be read.

Here is the same event written both ways:

{"level":"error","msg":"Failed to send message to recipient, giving up"}

{"time":"2026-04-23T09:12:44.118Z","level":"error","service":"sender",
 "request_id":"01HXQ8R4M2","subject_type":"message","subject_id":"84213",
 "event":"dispatch","outcome":"rejected","reason":"invalid_recipient",
 "attempt":3,"duration_ms":412}

The first line tells you something bad happened somewhere. The second tells you which message, on which request, after how many attempts, and why, and it lets you count how many other messages failed for the same reason today.

Why free text ages badly

The sentence in a log message is written once and then edited forever. Somebody rewords it during a refactor, somebody else adds a variable to the middle of it, a third person changes Failed to send to Send failed. Every dashboard, alert and saved search built on that sentence breaks silently, and nobody finds out until the alert that should have fired does not.

A field name is an interface. reason keeps its meaning when the surrounding code is rewritten, and a new value in it is an addition rather than a break. Field names also survive the thing sentences never survive: aggregation. group by reason over a day of logs is the fastest product research available to a backend engineer, and it is simply impossible over prose.

Log levels are the same kind of contract, and they are worth defining once in a sentence each:

  • error: a person has to do something, and this line is allowed to page someone.
  • warn: the system handled it, but a human should care if it repeats.
  • info: a state change somebody may need to reconstruct later, one per unit of work.
  • debug: detail for a developer, off in production unless enabled for a single request.

The failure mode here is inflation. When routine rejections are logged as errors, the error level stops meaning anything, the alert gets muted, and a real error arrives into a channel nobody reads. A message rejected for an invalid recipient is ordinary business, not an incident, and it belongs at info or warn with a reason code.

Grepping a real incident in under a minute

The test of a logging setup is how fast it takes you from a complaint to a cause. With the three fields present, it is two commands. Start from the only thing the customer knows, the record number:

# 1. find the request that touched this record
rg '"subject_id":"84213"' /var/log/app/*.jsonl | jq -r .request_id | head -1
# 01HXQ8R4M2

# 2. replay everything that request did, in every service
rg '"request_id":"01HXQ8R4M2"' /var/log/app/*.jsonl \
  | jq -c '{t:.time, svc:.service, ev:.event, out:.outcome, r:.reason}'
{"t":"09:12:41.004","svc":"api",    "ev":"accept",   "out":"ok",      "r":null}
{"t":"09:12:41.120","svc":"api",    "ev":"enqueue",  "out":"ok",      "r":null}
{"t":"09:12:42.660","svc":"worker", "ev":"dispatch", "out":"retry",   "r":"provider_timeout"}
{"t":"09:12:43.900","svc":"worker", "ev":"dispatch", "out":"retry",   "r":"provider_timeout"}
{"t":"09:12:44.118","svc":"sender", "ev":"dispatch", "out":"rejected","r":"invalid_recipient"}

Five lines and the whole story is there, including the fact that two timeouts happened before the real reason appeared. The third command is the one that turns an anecdote into a decision:

rg '"outcome":"rejected"' /var/log/app/*.jsonl | jq -r .reason | sort | uniq -c | sort -rn
#  1842 invalid_recipient
#   311 quota_exceeded
#    27 content_blocked

Now you know whether you are looking at one unhappy customer or at eighteen hundred records with a data quality problem. The same shape of question comes up in the delivery report that arrives before the record, where knowing which id arrived first is the entire diagnosis.

What never belongs in a log

Logs get shipped to other systems, copied into tickets, pasted into chat and kept for months. Treat everything written there as public within the company and durable.

  • No credentials, tokens, keys, cookies or authorisation headers, including in a serialised error object, which is where they usually leak.
  • No full request or response bodies. Log the size, the content type and a hash if you need to compare two payloads.
  • No personal data beyond what the line needs. An account id answers almost every operational question that a phone number or an email address would answer.
  • No message content. If you must be able to prove what was sent, store it in the database with an access control and log the record id.

Redaction belongs in the logger itself, not in the call sites, because a call site added next month will not remember the rule. A short allow list of fields, with everything else dropped, is safer than a deny list of secrets you have thought of so far.

How to check it worked

The rule is only real if something enforces it. Two checks catch almost everything: a test that fails when a logged event is missing a required field, and a scan over yesterday's output looking for lines that cannot be traced.

# every event that appeared at least once without the three fields
cat /var/log/app/*.jsonl \
  | jq -r 'select(.request_id == null or .subject_id == null or .outcome == null) | .event' \
  | sort | uniq -c | sort -rn
#   914 cache_refresh
#     3 webhook_receive

An empty result means every event in production can be traced from an id. A long list is a to do list, ordered by how often the gap will hurt. In the output above, cache_refresh has no subject because it genuinely has none, so the honest fix is to exempt it explicitly rather than to invent an id for it.

What to watch out for

  • Volume is a cost and a hazard. Logs that grow faster than you expect fill a disk and take the service down with them, which is the failure I wrote about in log rotation and the silent cost of a full disk.
  • An id that changes on retry is not a correlation id. If a job runs three times, all three runs should carry the same id as the original request, which is also what makes them traceable as idempotent jobs.
  • Reason codes need a home. Keep the set in one file as a union type, so adding one is a code review and not a typo.
  • Clock skew between machines makes an ordered replay lie. Log in one format with a timezone offset, and if two services disagree by seconds, fix the clocks before you trust the sequence.

The practical bar is low and almost nobody clears it: a person who has never seen the code should be able to take one identifier from a support message and reconstruct what the system did. That needs three fields, a fixed vocabulary of reasons, and the discipline to leave everything else out. The payoff arrives on a bad day, when the difference between a five minute answer and a two hour search is whether somebody wrote down the id.

Questions and answers

What is a correlation id in logging?
It is a single identifier created when a request enters the system and attached to every log line produced while handling it, including in other services and background jobs. It lets you retrieve the whole story of one request with one filter. Generate it at the edge, accept an incoming one if a caller already sent it, and return it in the response so support can quote it.
Should logs be JSON or plain text?
Structured lines, usually one JSON object per line, for anything a machine will ever filter or count. Plain text is fine for a local development console. The important part is that the values live in named fields rather than inside a sentence, because fields survive rewording and sentences do not.
What should never be written to a log?
Credentials of any kind, session tokens, API keys, full request and response bodies, card data, and personal data you do not need for the specific question the line answers. Log an id or a hash instead of the value. Logs are copied to other systems and kept for months, so anything that lands there should be assumed to spread.
How many log lines should one request produce?
At info level, one line per meaningful state change, which is usually between one and five for a normal request. Anything finer belongs at debug and stays off in production unless you enable it for a single request. A service that writes twenty info lines per request makes its own logs unreadable and its disk bill larger.