필사 모드: Designing Structured Logging — Logs That Actually Help During an Incident

• Introduction — When You Cannot Grep Your Logs Mid-Incident
• Logs for Humans and Logs for Machines Are Different Things
• The Fields Every Log Line Must Carry
• The Single Criterion That Actually Separates Log Levels
• Propagating the Correlation ID Past Service Boundaries
• Cardinality and Cost — What You Must Not Put In
• Logs, Metrics, and Traces — What to Look At and When
• Closing — Logs Are Not for Reading, They Are for Filtering

Introduction — When You Cannot Grep Your Logs Mid-Incident

An alert wakes you at dawn and you open the logs. The request passes through three services, and each service has a different log format. One is local time, another is UTC. There is no common key to identify the request, so you pair up lines with similar timestamps by eye. Eventually you find a line reading "user 8812 checkout failed after 4102ms", but counting how many such users there are means writing a fresh regular expression.

The cause of this situation is not a shortage of logs. On the contrary, hundreds of millions of lines pile up every day. The problem is that those logs were designed on the assumption that a human would read them one line at a time. What incident response needs is not reading but filtering and aggregation.

This post is about the design that changes that assumption.

Logs for Humans and Logs for Machines Are Different Things

Logs in a local development environment are read by humans. They have colour, they are sentences, and scrolling through them in order tells a story. Production logs are read by machines. They get filtered, aggregated, and joined. Trying to satisfy both requirements with one format is what ruins most logs.

The answer is to emit the same log differently. Production gets one line of JSON, local gets a pretty-printed rendering. And there is one decisive rule.

// Bad: the values are melted into the message string
logger.info(`user ${userId} checkout failed after ${ms}ms: ${err.message}`)
// -> counting the same event needs a regex, and the regex breaks when err.message changes

// Good: the message is a constant, every varying value is a field
logger.error(
  {
    event: 'checkout.failed',
    user_id: userId,
    order_id: orderId,
    duration_ms: ms,
    payment_provider: 'tosspay',
    err: { type: err.name, code: err.code, message: err.message },
  },
  'checkout failed'
)

Keep the message string constant. That is what lets you count the same event under a single key. The moment a varying value moves inside the message, that log becomes a sentence and drops out of anything aggregatable.

Following this one rule alone lets you answer the following questions immediately. When did this failure start, is it concentrated on a particular payment provider, does it only happen to one tenant. With logs left as sentences, every one of those questions requires fresh parsing.

The event field deserves separate emphasis. Put a dot-separated domain event name there as a stable identifier and it becomes a counter directly in the log backend. The message text is for humans and event is for machines.

The Fields Every Log Line Must Carry

You do not need many fields. The fields whose absence blocks an investigation are a fixed set.

Timestamps deserve a separate note. Always use RFC 3339 format including the offset, and preferably UTC. Local time without an offset produces situations like this.

# The payment service logs KST with no offset, the checkout service logs UTC
grep 'payment accepted' payment.log | tail -1
# 2026-07-26T13:02:11.004 payment accepted order_id=A-99183

grep 'checkout completed' checkout.log | tail -1
# 2026-07-26T04:02:11.118Z checkout completed order_id=A-99183

# Same event, but they look nine hours apart. There is no way to sort both logs on one screen.

With pino, for example, you set this up in the base configuration.

import pino from 'pino'

export const logger = pino({
  level: process.env.LOG_LEVEL ?? 'info',
  timestamp: pino.stdTimeFunctions.isoTime, // ISO 8601 including the offset
  formatters: {
    level: (label) => ({ level: label }), // emit "info" instead of 30
  },
  base: {
    'service.name': process.env.OTEL_SERVICE_NAME,
    'service.version': process.env.SERVICE_VERSION,
    'deployment.environment': process.env.APP_ENV,
  },
})

Values placed in base are attached to every line automatically. Do not repeat resource-level fields at individual call sites. The moment you repeat them, somewhere will forget one.

The Single Criterion That Actually Separates Log Levels

Level definitions appear in every document, but actual usage differs from team to team. Fix on one criterion for the judgement and the arguments end.

The criterion is this. ERROR means our system failed to do its job. If the user made a mistake, if the failure was expected, or if a retry recovered it, it is not an ERROR.

• ERROR: a defect on our side prevented the request from being handled. Accumulation should lead to a page. Examples: retries exhausted after a dependency timeout, deserialization failure, connection pool exhaustion.
• WARN: it was handled but in a degraded way. No action is needed now, but the trend must be watched. Examples: success after retry, fallback response served, cache miss rate spiking, a certificate about to expire.
• INFO: an event that changed state. Keep only the facts you will need to reconstruct things later. Examples: order created, deployment finished, configuration reloaded.
• DEBUG: narrative for developers. The production default is off, and it must be possible to turn on dynamically for a specific request or a specific tenant.

The point people get wrong most often here is 4xx responses. A malformed request body, an expired token, a lack of permission — these are the results of our system working correctly. The moment you stamp them as ERROR, most of your ERROR logs fill up with normal traffic and real defects get buried inside. Log client errors as INFO or WARN, and watch for spikes in their ratio with metrics.

// Error handler: split the level by where the responsibility lies
app.use((err, req, res, next) => {
  const status = err.status ?? 500
  const fields = {
    event: 'http.request.failed',
    http_status: status,
    route: req.route?.path,
    err: { type: err.name, code: err.code, message: err.message },
  }

  if (status >= 500) {
    req.log.error(fields, 'request failed') // our responsibility
  } else if (status === 429) {
    req.log.warn(fields, 'request throttled') // degradation
  } else {
    req.log.info(fields, 'request rejected') // client responsibility
  }

  res.status(status).json({ error: err.publicMessage ?? 'request failed' })
})

Check whether the level policy has taken hold with one indicator. Is every ERROR log something worth someone looking at. If not, that log is not an ERROR.

Propagating the Correlation ID Past Service Boundaries

A request ID that is only valid inside one service is half a solution. The point where it starts paying off is when it crosses a service boundary.

The standard is W3C Trace Context, and the header is traceparent. The format is fixed at four parts.

curl -sD - -o /dev/null https://checkout.internal/v1/orders \
  -H 'traceparent: 00-4bf92f3577b34da6a3ce929d0e0e4736-00f067aa0ba902b7-01' \
  -H 'tracestate: acme=t61rcWkgMzE'

# 00                                 version
# 4bf92f3577b34da6a3ce929d0e0e4736   trace ID (16 bytes, identical across the whole request)
# 00f067aa0ba902b7                   parent span ID (8 bytes, differs at each call hop)
# 01                                 flags (a trailing bit of 1 means sampled)

Watch that last flag carefully. 01 means this trace will be stored. 00 means it will be dropped. Log this value alongside everything else and you can immediately explain the situation where "I clicked the trace link and there was nothing there".

In the application, the key is to make the logger attach the trace context automatically. If call sites have to pass it every time, it will definitely get missed.

import { context, trace } from '@opentelemetry/api'
import { AsyncLocalStorage } from 'node:async_hooks'

const requestStore = new AsyncLocalStorage()

// Plant the context exactly once at the request entry point
export function requestContext(req, res, next) {
  const requestId = req.headers['x-request-id'] ?? crypto.randomUUID()
  res.setHeader('x-request-id', requestId)
  requestStore.run({ requestId, tenantId: req.auth?.tenantId }, () => next())
}

// A thin wrapper every log call passes through
export function ctx(fields = {}) {
  const store = requestStore.getStore() ?? {}
  const span = trace.getSpan(context.active())
  const sc = span?.spanContext()
  return {
    ...fields,
    request_id: store.requestId,
    tenant_id: store.tenantId,
    trace_id: sc?.traceId,
    span_id: sc?.spanId,
    trace_sampled: sc ? Boolean(sc.traceFlags & 1) : undefined,
  }
}

logger.error(ctx({ event: 'checkout.failed', order_id: orderId }), 'checkout failed')

There are three places where propagation actually breaks. First, code paths using a hand-rolled HTTP client — if auto-instrumentation cannot wrap it, the header is never attached. Second, message queues — unless you inject into the headers yourself, the producer and consumer traces are severed. Third, batch jobs and cron — unless you start a new trace at the entry point, trace_id is simply empty in the logs.

Cardinality and Cost — What You Must Not Put In

Logs are not free. Start with the arithmetic.

# 1.2KB per line on average, 4,000 lines per second
python3 -c "print(f'{1.2*1024*4000*86400/1e9:.1f} GB/day')"
# 424.7 GB/day

# Assuming 30 day retention at a unit price of 2.5 currency units per GB including indexing
python3 -c "print(f'{424.7*30*2.5:,.0f} per month')"
# 31,853 per month

What you should reduce here is not the number of lines but the size per line and the set of indexed fields. The following do not belong in logs.

• Personal data: full email addresses, phone numbers, home addresses, dates of birth, national ID numbers. Substitute a hash or an internal ID where you need one.
• Secrets: Authorization headers, cookies, API keys, card numbers, refresh tokens. Once these land in a log they are replicated simultaneously into backups, indexes, and cold storage.
• Large payloads: full request and response bodies, repeated stack trace dumps, serialized object dumps. Keep only the size and a hash of the body, and if you truly need it, park it in separate storage with a short TTL.
• Meaningless unique values: put unbounded UUIDs into a field the log backend indexes and the index grows larger than the data. Distinguish fields you index from fields you merely store.

Redaction should happen inside the application as a matter of principle. Stripping it in the collection pipeline happens after the value has already left the process, which multiplies the leak paths.

export const logger = pino({
  redact: {
    paths: [
      'req.headers.authorization',
      'req.headers.cookie',
      'req.headers["x-api-key"]',
      'req.body.password',
      'req.body.card_number',
      '*.email',
      '*.phone',
      'user.ssn',
    ],
    censor: '[REDACTED]',
  },
})

Sampling is the last resort for reducing volume, but the method matters. Implement the common advice of "keep only 10% of INFO logs" as a per-line random draw and you get the worst possible outcome. One request leaves fragments of logs behind and no request has a complete story.

Decide sampling per request, not per line. Hash the trace_id to make the call and all the logs of one request are kept together or dropped together.

const KEEP_RATIO = 0.05

// Deterministic decision from the trace_id — one request keeps all its logs or none
function keepLowSeverity(traceId) {
  if (!traceId) return true
  const bucket = parseInt(traceId.slice(-4), 16) / 0xffff
  return bucket < KEEP_RATIO
}

export function emit(level, fields, msg) {
  const enriched = ctx(fields)
  const alwaysKeep = level === 'error' || level === 'warn' || enriched.trace_sampled
  if (!alwaysKeep && !keepLowSeverity(enriched.trace_id)) return
  logger[level](enriched, msg)
}

Never sample ERROR and WARN. And keep the logs of a request whose trace was sampled. That is what stops you staring at an empty screen after jumping from a trace to the logs.

Logs, Metrics, and Traces — What to Look At and When

The three signals are not substitutes for each other, they are an investigation order. A team that has all three switched on and still investigates slowly usually has no order.

• Metrics come first. They answer when something started going wrong and how big the blast radius is. They are cheap, always on, and low cardinality, which makes them the only signal that can justify an alert.
• Traces come next. They answer, for one slow request, which service and which segment consumed the time. Enter with the scope narrowed by the time range and route the metrics pointed at.
• Logs come last. They answer exactly what happened inside that span, which values arrived and which branch they took. Filter by trace_id on the way in and the number of lines to read drops to a few dozen.

For this order to work you need links between the signals. The bridge from metrics to traces is exemplars. Attach a trace_id to histogram observations and you can click a spike on the graph and open exactly that trace.

# With exemplars attached, you jump straight from a point on this graph to the trace
histogram_quantile(
  0.99,
  sum by (le, route) (rate(http_request_duration_seconds_bucket{job="checkout-api"}[5m]))
)

The bridge from traces to logs is the trace_id field we built earlier. The bridge from logs to metrics is the event field. With all three bridges in place, investigation time drops from tens of minutes to a few minutes. Miss even one and eye-based pairing starts again at that point.

Closing — Logs Are Not for Reading, They Are for Filtering

There is one sentence to remember. The purpose of a production log is not to be read but to be filtered.

Every rule follows from that purpose. Keep the message constant and pull the values out into fields. Put trace_id, service.name, and a timestamp with an offset on every line. Use ERROR only when it is our responsibility. Wipe sensitive values before they leave the process. Sample per request.

If you fix exactly one thing today, start by pulling the variables out of your message strings. That single change turns questions that only a regular expression could answer into questions you can aggregate immediately.

Further reading.

• W3C Trace Context specification
• OpenTelemetry: Logs data model
• OpenTelemetry Semantic Conventions
• Google SRE Workbook: Alerting on SLOs