Structured logging: actually seeing what happens in production

The most uncomfortable production conversation starts like this: "a user says the payment did not go through". You open the logs and find this:

Error: Request failed
    at processTicksAndRejections (node:internal/process/task_queues:95:5)

Which user? Which request? When? What were they asking for? Nothing. There are logs, but they are useless.

The problem is not that you failed to write logs. The problem is that you wrote them to be read by a human, when what you actually need to do later is search them.

A line of text versus a structured record

A typical log looks like this:

console.log(`User ${userId} created order ${orderId}`)

Easy to read. But tomorrow, when you need "everything this user did today", you will go hunting through text with grep — and the search breaks the moment you change the wording in one place.

Structured logging takes a different approach: every record is an object.

logger.info({ userId, orderId, amount }, 'order created')

The output is JSON:

{"level":"info","time":1789000000,"userId":"u_123","orderId":"o_456","amount":42000,"msg":"order created"}

The difference is that you now search by field, not by text. "Every record where userId is u_123" is a one-line query that does not depend on phrasing.

In Node.js I use pino: it is fast and writes JSON by default.

import pino from 'pino'

export const logger = pino({
  level: process.env.LOG_LEVEL ?? 'info',
})

The biggest win: correlating a request

Structured logging is good on its own, but the real payoff comes from correlation.

A single HTTP request produces dozens of log records: entry, authentication, three database queries, an external API call, the response. If they are not tied together, you end up manually fishing them out from among a hundred other requests.

The fix is to give every request one identifier and attach it to every record:

app.use((req, res, next) => {
  req.id = req.headers['x-request-id'] ?? crypto.randomUUID()
  req.log = logger.child({ requestId: req.id })
  res.setHeader('x-request-id', req.id)
  next()
})

Three lines of code. The result is large: search by one identifier and the whole story of that request comes out in order.

I also return the identifier in a response header. The reason is practical: when a user complains you can ask them for that string and land directly on the right request. An address instead of a search.

With multiple services, the identifier travels between them too — via the same x-request-id header. Then the logs stay correlated across the entire chain.

Using levels properly

The most common mistake with levels is logging everything as info. Then the level carries no meaning at all.

I draw the line like this:

• error — a human needs to intervene. Work did not get done, a user was affected. This level is wired to alerts.
• warn — something unexpected, but the system handled it. For instance, an external API failed on the first attempt and answered on the second.
• info — a business event. Order created, user registered, report generated.
• debug — technical detail. Off in production, switched on while investigating.

The key test for error: if nobody does anything when this record appears, it is not an error. That simple rule keeps the error level free of noise — and only then can alerts be trusted.

Name your fields consistently

This is boring, but over the long run it is the rule that saves the most time.

If you write userId in one place, user_id in another and uid in a third, you get three ways to search and three ways to get it wrong. Keep one list in the project and stick to it.

My usual set: requestId, userId, organizationId, durationMs, statusCode, route. Everything else gets added per task.

One specific tip — always record duration as durationMs, as a number. Write it as text ("1.2s") and you will never be able to ask for "all requests slower than 500 ms".

What you must never log

Think about this part at the beginning rather than the end, because logs usually live a long time and many people see them.

Never write: passwords, tokens, session keys, card data, the full Authorization header, personal document numbers.

The most common leak path is logging a whole object:

logger.info({ user }, 'user signed in')  // the whole object, password hash included

The correct shape is to pick the fields explicitly:

logger.info({ userId: user.id, role: user.role }, 'user signed in')

In systems handling personal data this rule has to be especially strict. A school system holds student and parent data, and logs are usually the least protected place in the whole stack.

As an extra guard, pino can redact fields automatically:

pino({
  redact: ['req.headers.authorization', 'password', '*.token'],
})

Where to store logs

At the start, nowhere — and that is fine. The log goes to stdout, systemd or Docker collects it, and you read it with journalctl or docker logs.

There is one condition: do not write files yourself and do not hand-roll rotation. That is a solved problem, and getting it wrong fills the disk and stops the server.

When do you need a dedicated collector (Loki, Elastic and friends)? Two signs: you now have several servers or containers, and you need to search several days of history. Until both are true, journalctl | grep works beautifully.

Where to start

If your project is full of console.log today, do not try to replace it all in one day. The order is:

1. Add pino and export a single logger.
2. Create a requestId in request middleware and return it in a response header.
3. Wherever errors are handled, clean up the error level — get the noise out.
4. Write down your field-name list.
5. Configure redaction for sensitive fields.

Five steps, a few hours of work. Next time "a user is complaining" arrives, you will open the logs and see the entire story from one identifier — and you will feel the difference on day one.