Logging That Helps: Structured Logs, Levels and Correlation IDs

Logs are the oldest and most familiar kind of telemetry. Every developer has written console.log("here"). That habit works on your laptop. It stops working the day your code runs on five servers and a user says "my payment failed at about 3 p.m.". Which server? Which line? What came before it? A pile of free-form text lines cannot answer that.

This is lesson 1 of nine. In lesson 0 we met the three pillars and said logs are best at "what exactly happened in this one case". Here we learn to write logs that really are good at that. We use pino, a fast JSON logger for Node.js, and we run everything for real. The next lesson, Metrics and Prometheus, covers the numbers side.

You should know basic Node.js. If you have not read Errors, Logging and Graceful Shutdown in the Node.js series, it covers the error-handling side that goes together with this lesson. For the security reason to keep secrets out of logs, see Security Lesson 8.

Words used in this lesson

• A log line is one record of one event, written at one moment.
• Structured logging means each log line is machine-readable data (usually JSON) with named fields, not a sentence.
• A field is one named piece of data in a log line, like orderId or durationMs.
• A log level is a label for how serious or detailed a line is: trace, debug, info, warn, error, fatal.
• A logger is the object you call to write logs.
• A child logger is a logger that remembers extra fields and adds them to every line it writes.
• A correlation id (also called a request id) is a unique id given to a request when it enters your system. It is put on every log line for that request, in every service.
• Redaction means hiding a secret value in a log line, for example replacing a password with [REDACTED].
• PII (personally identifiable information) is data about a person, such as an email, a phone number or an address.
• Sampling means writing only some of the log lines, on purpose, to save space.
• Log injection is when an attacker puts fake log lines inside a value you log.
• A transport is the place a logger sends its lines, such as a file, the terminal, or a network service.
• stdout is the standard output of a process. In containers it is the normal place for logs to go.

The problem with printf-style logs

Let us start with the habit most of us have. Here is a line from a shop service:

user 42 paid 19.99 USD for order 7001 in 83ms

It looks fine to a human. Now someone asks: "Show me all payments over 10 USD that took longer than 80 ms." To do that with free text you must write a regular expression that finds the number after "paid", and another after "in". If a developer later changes the sentence to "order 7001 paid by user 42", every search breaks. Text lines are written for humans, so machines have to guess.

Now the same event as a structured line, written by pino:

{"level":30,"time":"2026-10-12T03:42:46.149Z","service":"shop","userId":42,"orderId":7001,"amount":19.99,"currency":"USD","durationMs":83,"msg":"payment accepted"}

This is one JSON object on one line. Every value has a name. A log tool can filter amount > 10 and durationMs > 80 with no guessing. To show how simple that is, I ran the program and filtered its output with six lines of Node code (a stand-in for what a real log tool does):

big payment: 7001 19.99

The structure is the point. Even without any fancy tool, grep and jq become powerful. And the message ("payment accepted") stays a short, fixed sentence. The changing facts are in the fields. This is the most important habit of this lesson: keep the message constant, put the variable data in fields. A constant message can be grouped and counted ("how many 'payment accepted' lines today?"). A message like "user 42 paid 19.99" is different on every line and cannot be grouped.

Your first pino logger

Install it and write the smallest useful logger:

import pino from "pino";const log = pino({ base: { service: "shop" }, timestamp: pino.stdTimeFunctions.isoTime });log.info({ userId: 42, orderId: 7001, amount: 19.99, currency: "USD", durationMs: 83 }, "payment accepted");log.warn({ orderId: 7002 }, "card declined");log.debug("not shown, default level is info");log.error(new Error("db down"), "query failed");

The call pattern is log.level(fieldsObject, "message"). The fields come first, then the message. This surprises people who are used to console.log("message", data). Real output:

{"level":30,"time":"2026-10-12T03:42:46.149Z","service":"shop","userId":42,"orderId":7001,"amount":19.99,"currency":"USD","durationMs":83,"msg":"payment accepted"}{"level":40,"time":"2026-10-12T03:42:46.149Z","service":"shop","orderId":7002,"msg":"card declined"}{"level":50,"time":"2026-10-12T03:42:46.149Z","service":"shop","err":{"type":"Error","message":"db down","stack":"Error: db down\n    at file:///tmp/lab-obs-a/l1/a.mjs:9:11\n    at ModuleJob.run (node:internal/modules/esm/module_job:343:25) ..."},"msg":"query failed"}

What did pino do for us?

• It wrote one line of JSON per call. The level is a number (30 for info, 40 for warn, 50 for error).
• The base option added service: "shop" to every line. (By default pino also adds pid and hostname. I turned that off in some examples with base: undefined to keep the lines short. In a real deployment those two are often useful.)
• The debug line was not printed. The default minimum level is info.
• The error object became a nested err object with type, message and stack.

Why the numbers for levels?

Pino stores the level as a number so that tools can compare them. The usual set is: trace 10, debug 20, info 30, warn 40, error 50, fatal 60. Setting the logger level to warn means "write warn and above, drop the rest". Pino's docs say that raising the minimum level reduces load, because debug and trace logs are usually needed only in development.

Seeing it as a human: pino-pretty

JSON is for machines. During development you can pipe the output into pino-pretty, which makes it readable. The same kind of line looks like this:

INFO: request received    service: "gateway"    requestId: "49bba672"    method: "GET"

Run it as node app.js | npx pino-pretty. Use it in development only. In production keep the raw JSON, because your log system needs to parse it.

Log levels: what each one means

A level says how important a line is. If everything is info, then levels give you nothing. Here is a simple rule set that works for most teams:

Two rules help a lot.

1. An error should mean something needs attention. If your logs contain 5,000 "errors" a day that are really normal (a user typed a wrong password), people stop reading errors. A wrong password is an info or warn. A database that is down is an error.
2. Do not log an error twice. A common mistake: a function catches an error, logs it, and throws it again. The caller catches it and logs it again. Now one failure makes three lines. Log an error once, where you handle it (and decide what happens next). Elsewhere just let it travel up.

Level costs almost nothing when it is off

A fear is that lots of debug calls slow your program. I measured pino with the level set to warn and called log.info 200,000 times:

pino info call when level=warn     7 ms for 200000

That is about 35 nanoseconds per skipped call (7 ms divided by 200,000). So a disabled log call is very cheap. The expensive part is building the arguments. If you write log.debug({ big: JSON.stringify(hugeObject) }, "dump"), the JSON.stringify runs even when debug is off. Guard that with if (log.isLevelEnabled("debug")), or pass the object itself and let the logger handle it.

What does a log line cost when it is on?

Another real measurement. I wrote 200,000 lines to a file three ways. Each pino line had 5 fields plus level, time and message (a line of about 150 bytes):

fs.writeSync string template       284 ms for 200000pino sync file, 6 fields          1192 ms for 200000pino async buffered, 6 fields     1360 ms for 200000

So in this small VM, pino took about 6 microseconds per line, and a bare string write took about 1.4 microseconds. Pino is slower than a raw write because it builds JSON, but 6 microseconds is a small price for structure. At 1,000 log lines per second that is 6 ms of CPU per second, or 0.6 percent of one core. The async buffered mode was not faster in this simple loop (it was 1360 ms against 1192 ms). I would not trust a single microbenchmark to pick between them. Pino's docs describe async destinations and worker-thread transports as ways to move log writing away from the main thread, and the right choice depends on your load, so measure it in your own service.

What to log, and what not to log

What to log

Think of logs as a diary of important events, not a trace of every line of code. Good things to log:

• Lifecycle: "server started" (with port and version), "shutting down".
• One line per request, at the end: method, route, status, duration, request id. This one line often gives you most of what you need.
• Business events: "order created", "payment failed". These are the facts users care about.
• Errors, with the error object (so you get message and stack) and the context fields (which order, which user id).
• Decisions and fallbacks: "cache miss, using database", "retry 2 of 3".
• Slow or unusual things: "query took 2300 ms".

What not to log

• Secrets: passwords, API keys, session tokens, authorization headers, private keys, full credit card numbers.
• Personal data you do not need: email, phone, address, ID numbers. If you need to tie lines to a person, log an internal user id, not their name.
• Huge bodies: the whole request or response body, whole files.
• Noise in hot loops: a log line inside a loop that runs a million times per request.
• Anything you already measure as a metric. You do not need a log line per request to count requests. You do need the log line for a failed request, with its details.

This is also a security matter. Leaked logs are a real kind of data leak, because logs are often readable by many people and stored for a long time. Security Lesson 8 covers logging and alerting as a security topic.

Redaction: block secrets in one place

You will make mistakes. Somebody will log a whole req object that contains an authorization header. So set up redaction in the logger itself, as a safety net. Pino's redact option takes a list of paths to the fields to hide. Its docs show that paths can use dots, brackets for names with hyphens, and wildcards like stuff.thats[*].secret. You can also set a custom text to show instead.

const safe = pino({  base: undefined, timestamp: false,  redact: { paths: ["password", "req.headers.authorization", "user.*.token"], censor: "[REDACTED]" },});safe.info({ password: "hunter2", req: { headers: { authorization: "Bearer abc", host: "x" } } }, "login attempt");const unsafe = pino({ base: undefined, timestamp: false });unsafe.info({ password: "hunter2" }, "login attempt (no redact)");

Real output:

{"level":30,"password":"[REDACTED]","req":{"headers":{"authorization":"[REDACTED]","host":"x"}},"msg":"login attempt"}{"level":30,"password":"hunter2","msg":"login attempt (no redact)"}

The first logger hid both the password and the authorization header and kept the harmless host. The second one wrote the password in clear text. (If you do not set censor, pino's docs show the default text as [Redacted].)

Log injection: user text can fake log lines

There is a quiet security trap with plain text logs. If you log a value a user controlled, they can add a line break and write a fake line. I tried it. The "username" was bob, then a newline, then a made-up line that looks like an admin logging in:

const name = "bob\n2026-10-12T03:50:00Z INFO admin logged in from 10.0.0.1";console.log("login failed for user " + name);pino({ base: undefined, timestamp: false }).info({ user: name }, "login failed");

Real output:

login failed for user bob2026-10-12T03:50:00Z INFO admin logged in from 10.0.0.1----{"level":30,"user":"bob\n2026-10-12T03:50:00Z INFO admin logged in from 10.0.0.1","msg":"login failed"}

With console.log the attacker's text became a believable second line. With JSON logging the line break was escaped to \n inside a string value, so there is still only one line. Structured logging is not only more searchable. It is safer.

Errors: use the err key

This one is a real trap. I logged the same SyntaxError three ways:

try { JSON.parse("{bad"); } catch (e) {  log.error({ e }, "plain key e");     // wrong key  log.error({ err: e }, "key err");  log.error(e, "error as first arg");}

{"level":50,"e":{},"msg":"plain key e"}{"level":50,"err":{"type":"SyntaxError","message":"Expected property name or '}' in JSON at position 1 (line 1 column 2)","stack":"SyntaxError: ..."},"msg":"key err"}{"level":50,"err":{"type":"SyntaxError","message":"Expected property name or '}' in JSON at position 1 ...

The first line lost the error: "e":{}. A JavaScript Error object has its message and stack as properties that JSON does not copy, so JSON.stringify(error) gives {}. Pino has a special serializer for the key named err, and also when you pass the error as the first argument. So always use err or pass the error first. An empty {} in your error log, found at 2 a.m., is a terrible surprise.

Also notice that the stack trace is inside one JSON string, so a multi-line stack does not break the log into many lines. With plain console.error(new Error("boom")), the stack prints as five separate lines, and a log tool that works line by line will treat them as five events.

Child loggers: add context once

A child logger is a logger that has extra fields built in. You create it once per request, and every line you write with it carries those fields:

const reqLog = log.child({ requestId: "r-123" });reqLog.info("step one");reqLog.info({ step: 2 }, "step two");

{"level":30,"time":"2026-10-12T03:42:46.152Z","service":"shop","requestId":"r-123","msg":"step one"}{"level":30,"time":"2026-10-12T03:42:46.152Z","service":"shop","requestId":"r-123","step":2,"msg":"step two"}

You can pass reqLog down through your functions. That works, but it is tiresome, because every function needs a logger argument. There is a nicer way in Node that we use next.

Correlation ids: follow one request across services

Here is the problem. Your gateway service receives a request and calls an inventory service. A user reports a failed order. In the gateway log you see an error. In the inventory log you see 40,000 lines from the same minute. Which ones belong to this request?

The fix is a correlation id:

1. When a request enters your system, check for an x-request-id header. If it exists, reuse it. If not, make a new random id.
2. Put the id on every log line for that request.
3. When you call another service, pass the id in the x-request-id header.
4. Optionally return it to the client in a response header. The user can then quote it to support.

To put the id on every line without passing a logger around, Node has AsyncLocalStorage. It stores a value that follows the chain of async calls started inside als.run(...). Pino has a mixin option, a function that runs on every log call and adds fields. Together they give each line the id automatically. Here is the core of the program I ran (two real HTTP servers in one script):

import { AsyncLocalStorage } from "node:async_hooks";import { randomUUID } from "node:crypto";import pino from "pino";const als = new AsyncLocalStorage();const mk = (service) => pino({  base: { service }, timestamp: false,  mixin: () => ({ requestId: als.getStore()?.requestId }),});// in each server's request handler:const requestId = req.headers["x-request-id"] || randomUUID().slice(0, 8);als.run({ requestId }, async () => { /* handle the request; every log line gets requestId */ });// when calling another service:http.get(url, { headers: { "x-request-id": als.getStore().requestId } }, ...);

I called the gateway twice: once with no id (it made one), and once with my own id from-client-1, and on the second call I made the inventory service fail. Real output, all 11 lines:

{"level":30,"service":"gateway","requestId":"d65ba049","method":"GET","url":"/item?sku=A1","msg":"request received"}{"level":30,"service":"inventory","requestId":"d65ba049","method":"GET","url":"/stock?sku=A1","msg":"request received"}{"level":30,"service":"inventory","requestId":"d65ba049","sku":"A1","stock":7,"msg":"stock checked"}{"level":30,"service":"inventory","requestId":"d65ba049","status":200,"durationMs":21,"msg":"request done"}{"level":30,"service":"gateway","requestId":"d65ba049","status":200,"durationMs":28,"msg":"request done"}{"level":30,"service":"gateway","requestId":"from-client-1","method":"GET","url":"/item?sku=bad","msg":"request received"}{"level":30,"service":"inventory","requestId":"from-client-1","method":"GET","url":"/stock?sku=bad","msg":"request received"}{"level":40,"service":"inventory","requestId":"from-client-1","sku":"bad","msg":"sku lookup failed"}{"level":30,"service":"inventory","requestId":"from-client-1","status":500,"durationMs":21,"msg":"request done"}{"level":50,"service":"gateway","requestId":"from-client-1","err":"upstream 500","msg":"handler failed"}{"level":30,"service":"gateway","requestId":"from-client-1","status":500,"durationMs":24,"msg":"request done"}

Now to find the whole story of the failed request, you run one search on requestId = "from-client-1". I tested with grep: it returned exactly 6 lines out of 11, from both services, in order. You can read it as a story: the gateway got the request, the inventory service got it, the SKU lookup failed with a warning, inventory answered 500, the gateway logged an error and answered 500 as well. Without the id those six lines would be mixed into thousands of other lines.

A few extra details that matter:

• The inventory service reused the id it received. If it had made its own, the chain would break. Always reuse an incoming id.
• Never trust an incoming id blindly. A client can send any string, including a very long one or one with newlines. Check its length and allowed characters, or replace it if it looks wrong. With JSON logs the newline is escaped, but a 1 MB id would still bloat every line.
• A request id and a trace id (from lesson 3) are close cousins. A trace id is created by your tracing library and is carried in a standard traceparent header. If you use tracing, put the trace id on every log line and you do not need a separate request id. You can then jump from a trace to its logs and back. We do exactly that in lesson 3.

Sampling: keep the rare, sample the common

If you log one line per request at 1,000 requests per second, that is 86 million lines a day. Most of them say "everything is fine". Sampling reduces that. In lesson 0 I showed the numbers. Here is the code:

let errs = 0, kept = 0;for (let i = 0; i < 10000; i++) {  const isErr = rnd() < 0.01;  if (isErr) { errs++; log.error({ i, status: 500 }, "request failed"); }  else if (rnd() < 1 / 20) { kept++; log.info({ i, status: 200 }, "request ok"); }}

Real result:

{ errs: 81, keptSuccess: 474, lines: 555, bytes: 30232 }

Out of 10,000 simulated requests, we wrote 555 lines, all 81 errors and a 1-in-20 sample of the successes. The sample is random, so the number of kept lines changes a little between runs.

Some practical advice on sampling:

• Never sample errors. Keep all of them.
• Sample by a stable key if you can, such as the request id, so that when one line of a request is kept, all lines of that request are kept. Random per-line sampling gives you half-stories.
• Count with metrics, not logs. Sampled logs cannot give you true totals. A counter metric gives you exact totals and costs almost nothing.
• Use levels for the rest. Many teams run info in production and turn on debug for one service for a short time when they investigate.
• Keep the sampling rate in the line (a field like sampleRate: 20) so that anyone counting can multiply back.

Another way to save is retention. Keep the last 7 to 14 days of full logs and keep only errors for longer. That is a storage policy, not a code change.

Config you should set up once

A short list of choices that pay off:

1. One logger module in your service that exports the configured logger. Everyone imports it, nobody calls pino() again.
2. Level from the environment: pino({ level: process.env.LOG_LEVEL ?? "info" }). You can change it without a code change.
3. A fixed base: service, version (or git commit) and env. When you read a line, you know where it came from.
4. ISO timestamps with pino.stdTimeFunctions.isoTime, so that time is readable and sortable. Keep servers on UTC.
5. Redaction paths for the headers and fields you know are sensitive.
6. Log to stdout in containers.
7. A naming style for fields. Pick one (camelCase is common in Node) and use it everywhere. Put the unit in the name (durationMs, sizeBytes). A field called duration might be seconds, milliseconds or text.
8. Types stay the same. If userId is a number in one line and a string in another, many log stores will reject or hide one of them.

Try it

Do these in a scratch folder with npm i pino.

1. Write a script that logs console.log style: console.log("order " + id + " failed: " + reason). Then rewrite it with pino. List two things you can now do that you could not before.
2. Log an error with log.error({ e: new Error("x") }, "oops"). What do you see? Fix it.
3. Make a logger that hides the fields password and card.number. Test it with an object that has both.
4. Create a tiny HTTP server with two routes. Add a request id: reuse x-request-id if present, otherwise create one. Use AsyncLocalStorage and mixin so that every log line shows the id. Test it with curl -H "x-request-id: abc".
5. A teammate wants to log the full request body on every request "just in case". Name three problems.
6. You run 500 requests per second and log one line per request, about 200 bytes each. How much log data is that per day? How much is left if you only keep errors (1 percent) and 1 in 20 of the rest?

Answers

1. With a structured line you can filter by field values (for example, all failed orders where reason = "card declined"), count by reason, and send the data to any log tool without a custom parser. Also the message stays constant, so grouping works.
2. You see "e":{}. The error's message and stack are lost, because Error properties are not copied by JSON.stringify. Use the key err (log.error({ err }, "oops")) or pass the error first (log.error(err, "oops")).
3. pino({ redact: { paths: ["password", "card.number"], censor: "[REDACTED]" } }). Then check the output. Remember that other paths (like card.cvv) are not hidden unless listed.
4. You should see the same requestId on every line for one request, and the same id as the one you sent in the header. If you call a second service, pass the header on.
5. (a) It can leak secrets and personal data. (b) It is large, so it costs storage and slows the request path. (c) It makes searching harder because the important lines are buried. Also it may break privacy rules. If you need bodies for debugging, log them only for failed requests, truncated and redacted.
6. 500 lines per second times 86,400 seconds is 43.2 million lines. At 200 bytes that is about 8.6 GB per day. With the policy: 1 percent errors is 0.43 million lines, and 1 in 20 of the rest (99 percent of 43.2 million is 42.8 million) is about 2.14 million lines. Total about 2.57 million lines, around 0.51 GB per day, roughly one seventeenth of the full volume.

Interview questions

Key takeaways

• Write logs as JSON objects with named fields. Keep the message fixed and put the variable facts in fields.
• Use levels with discipline. An error should mean someone may need to act. Log each failure once.
• Log errors under the err key. { e } produced {} in my test.
• Put a correlation id on every line, reuse an incoming id, pass it on every call and through queues. One search then shows the full story across services.
• Never log secrets or unneeded personal data. Use redaction as a safety net, and prefer to log only the fields you need.
• Structured logs are safer: JSON escapes line breaks and stops fake log lines.
• Logging is cheap but not free: about 6 microseconds per line in my test, near zero when the level is off. Build expensive arguments only when the level is on.
• Sample the boring lines, keep all errors, and take totals from metrics.

What's next

Next: Metrics and Prometheus, Lesson 2. Logs tell you what happened to one request. Metrics tell you what is happening to all of them. You will expose a counter, a gauge and a histogram from a Node service with prom-client, let a real Prometheus server scrape it, and ask it for percentiles. Practise now: add a request id and a one-line-per-request log to a small service of your own, then follow one id from start to end.