Logging — Request Logging

Request logging: vì sao mỗi log line phải có request id, và structured log cứu debug thế nào khi có sự cố production

Request logging không phải là in console.log('got a request') cho vui. Nó là dấu vết duy nhất còn lại khi một request đã đi qua service, đi qua vài downstream, gặp lỗi, và bị đóng socket. Nếu log không có gì để nối lại các dòng thuộc cùng một request — không có requestId, không có traceId — thì log của một service RPS trung bình biến thành một mớ text xen kẽ giữa hàng chục request đồng thời, và câu hỏi "request X đã đi tới đâu, fail ở service nào" trở thành không trả lời được. Structured log (mỗi dòng là một JSON object với field cố định) + một correlation id truyền qua toàn bộ pipeline chính là cái làm log có thể query được, thay vì grep mù. Hai framework Express và Fastify tiếp cận khác nhau: Fastify tích hợp pino sẵn và tự sinh req.id, Express phải tự dán qua pino-http hoặc middleware tay. Nhưng cả hai đều vỡ theo cùng một kiểu khi correlation id bị đứt giữa các service.

Cơ chế hoạt động

Ba miếng ghép: (1) một structured logger — thường là pino trong ecosystem Node vì nó ghi NDJSON và có async destination, (2) một cơ chế sinh/nhận requestId, (3) một cách propagate id đó qua async work và qua HTTP call sang service khác.

pino là JSON logger tối giản: mỗi lời gọi logger.info({...}, 'message') xuất một dòng NDJSON ra một WritableStream (mặc định là stdout). Log level là số (trace=10, debug=20, info=30, warn=40, error=50, fatal=60, theo pino docs), và có child logger — logger.child({ reqId }) tạo một logger mới bind sẵn các field, mọi log line từ child đều có reqId mà không phải truyền tay.

Với Fastify, chỉ cần logger: true là có pino và request logging tự động — Fastify sinh request.id (mặc định là monotonic counter, đổi được qua option genReqId) và log một cặp dòng "incoming request" / "request completed" cho mỗi request. Trong handler, request.log là child logger đã bind reqId:

import Fastify from 'fastify'
import crypto from 'node:crypto'

const app = Fastify({
  logger: {
    level: process.env.LOG_LEVEL ?? 'info',
    redact: ['req.headers.authorization', 'req.headers.cookie', '*.password'],
  },
  // Ưu tiên id từ upstream nếu có, không thì sinh mới
  genReqId: (req) =>
    req.headers['x-request-id'] ??
    req.headers['traceparent']?.split('-')[1] ??
    crypto.randomUUID(),
  requestIdHeader: 'x-request-id',
  requestIdLogLabel: 'reqId',
})

app.get('/orders/:id', async (req, reply) => {
  req.log.info({ orderId: req.params.id }, 'looking up order')
  const order = await app.db.orders.findById(req.params.id)
  reply.header('x-request-id', req.id)
  return order
})

Với Express, không có logger tích hợp — dùng pino-http, một Express-compatible middleware do cùng maintainer của pino ship. pino-http gắn req.log và req.id, tự log khi res.on('finish') với responseTime, statusCode, req, res đã được serialize gọn qua pino.stdSerializers:

import express from 'express'
import pinoHttp from 'pino-http'
import crypto from 'node:crypto'

const app = express()
app.use(pinoHttp({
  level: process.env.LOG_LEVEL ?? 'info',
  genReqId: (req, res) => {
    const id = req.headers['x-request-id'] ?? crypto.randomUUID()
    res.setHeader('x-request-id', id)
    return id
  },
  customLogLevel: (req, res, err) => {
    if (err || res.statusCode >= 500) return 'error'
    if (res.statusCode >= 400) return 'warn'
    return 'info'
  },
  redact: ['req.headers.authorization', 'req.headers.cookie'],
}))

app.get('/orders/:id', async (req, res) => {
  req.log.info({ orderId: req.params.id }, 'looking up order')
  const order = await db.orders.findById(req.params.id)
  res.json(order)
})

Miếng thứ ba — propagate id qua async work và qua HTTP call downstream — là chỗ hầu hết implementation vỡ. Node core có AsyncLocalStorage (module node:async_hooks) giữ context xuyên qua callback/promise mà không phải truyền tham số:

import { AsyncLocalStorage } from 'node:async_hooks'
export const ctx = new AsyncLocalStorage()

app.addHook('onRequest', (req, _reply, done) => {
  ctx.run({ reqId: req.id }, done)
})

// Ở tầng HTTP client — tự động gắn header khi gọi downstream
export async function fetchDownstream(url, init = {}) {
  const store = ctx.getStore()
  const headers = new Headers(init.headers)
  if (store?.reqId) headers.set('x-request-id', store.reqId)
  return fetch(url, { ...init, headers })
}

Cách "chuẩn" hơn là dùng W3C Trace Context (header traceparent, format 00-<trace-id>-<span-id>-<flags>, theo W3C Trace Context spec). OpenTelemetry SDK cho Node tự inject traceparent vào outgoing HTTP call và extract vào incoming request; log có thể bindings thêm trace_id/span_id để mọi dòng log tự động join được với trace. Đây là mặc định nếu service đã có OpenTelemetry — không phải viết tay.

Vấn đề gặp trong production

Failure mode 1: không có correlation id — không thể truy vết request qua service. Kịch bản: user báo checkout order #42871 fail. Log của service orders có dòng ERROR upstream timeout, log của service payments có dòng ERROR db connection lost cách đó 300ms. Có phải hai lỗi này cùng thuộc một request của user không? Không biết. Không có id chung để nối lại. Grep theo orderId cũng chỉ tìm được ở service orders — service payments không biết orderId là gì, nó chỉ nhận paymentIntentId. Nếu ngay từ đầu mọi service log kèm cùng một x-request-id (hoặc traceparent), query log aggregator theo reqId=abc123 ra đúng chuỗi dòng của một request qua mọi hop.

// SAI: log không có id gì để nối các dòng
app.post('/checkout', async (req, res) => {
  console.log('checkout started')
  const r = await fetch('http://payments/charge', { /* không gắn header id */ })
  if (!r.ok) console.log('payment failed', r.status)
  res.json({ ok: r.ok })
})

// ĐÚNG: sinh/nhận id ở edge, gắn vào log, propagate xuống downstream
app.post('/checkout', async (req, res) => {
  req.log.info({ userId: req.user.id }, 'checkout started')
  const r = await fetch('http://payments/charge', {
    headers: { 'x-request-id': req.id, 'content-type': 'application/json' },
    body: JSON.stringify({ /* ... */ }),
  })
  if (!r.ok) req.log.warn({ status: r.status }, 'payment failed')
  res.json({ ok: r.ok, requestId: req.id })
})

Failure mode 2: unstructured log — không query được. console.log('user ' + userId + ' bought ' + qty) trông đọc được nhưng không parse ngược lại thành field. Log aggregator (Elastic, Loki, Datadog) index theo field JSON; nếu log là plain string, chỉ còn full-text search. "Đếm số request lỗi 500 theo route trong 1h qua" biến thành parse regex trên free text, và grep không phân biệt được error trong error message với error trong stack trace. Structured log giải quyết bằng cách mỗi log line là một JSON có schema:

// SAI: string concat, không có level, không có id, mất field
console.log(`user ${userId} bought ${qty} of ${sku} in ${ms}ms`)

// ĐÚNG: object + message, có level, có reqId (qua child logger)
req.log.info({ userId, qty, sku, durationMs: ms }, 'purchase completed')
// -> {"level":30,"time":...,"reqId":"...","userId":"u1","qty":2,"sku":"...","durationMs":47,"msg":"purchase completed"}

Failure mode 3: log PII/secret ra file — leak dữ liệu. Log request body/headers thô sẽ ghi cả Authorization: Bearer ..., Cookie: session=..., password, số thẻ. Log thường được ship đi khắp nơi (Kafka, S3, log aggregator, backup); một khi PII lọt vào chain đó, khó thu hồi. pino có option redact (theo pino docs), nhận array path để thay bằng [Redacted] trước khi ghi:

// SAI: log toàn bộ req sẽ chứa Authorization/Cookie header
logger.info({ req }, 'incoming')

// ĐÚNG: redact path nhạy cảm ở tầng logger, không dựa vào code call site
const logger = pino({
  redact: {
    paths: ['req.headers.authorization', 'req.headers.cookie', '*.password', '*.creditCard'],
    censor: '[Redacted]',
  },
})

Failure mode 4: sync log chặn event loop. Ghi log đồng bộ (fs.writeSync, hay console.log khi stdout là file/pipe blocking) chặn thread cho tới khi kernel nhận xong. Ở RPS cao, mỗi request đóng góp vài log line, tổng độ trễ log ăn thẳng vào p99. pino mặc định ghi async qua sonic-boom, nhưng nếu dựng pino.destination({ sync: true }) (hoặc dùng transport sai cách), toàn bộ log biến thành blocking. Với high-throughput service, để pino ở chế độ async mặc định, hoặc dùng pino.transport() chạy trên worker thread riêng.

Failure mode 5: correlation id trust boundary. Nhận x-request-id từ client public internet mà không validate: attacker có thể inject id trùng để làm nhiễu log, hoặc chèn ký tự lạ (newline) để log injection. Rule: ở edge (API gateway hoặc service ngoài cùng), sinh id mới; chỉ trust header id từ upstream nội bộ đã xác thực (service mesh, LB) — hoặc validate format (UUID/ULID) trước khi dùng.

Cách debug và monitor

Triệu chứng cần đọc log tốt: user báo "request fail lúc 14:23", user chỉ có thể nhớ thời điểm và một phần URL; hoặc dashboard alert 5xx rate spike nhưng không biết request nào là root cause. Cách tiếp cận:

• Query theo reqId trong log aggregator. Trả x-request-id ra response header và hiển thị nó ở error page cho user, để user copy-paste id vào bug report. Ở Elastic/Loki/Datadog, query reqId:"abc-123" trả về toàn bộ log line của request đó — qua mọi service, đã sort theo timestamp.
• Join log với trace. Nếu đã bật OpenTelemetry, log line có trace_id/span_id, ngược lại trace có attributes.http.request.id. Bấm từ dòng log sang trace UI (Grafana Tempo, Jaeger, Honeycomb, Datadog APM) thấy chính xác downstream call nào chậm.
• Metric từ log. Đếm log level error/warn theo route và emit thành metric (Loki LogQL query theo level, hoặc convert log → metric qua promtail/vector). Alert khi error rate vượt baseline.
• Log volume monitoring. Log volume là chi phí thật (ingest, storage, egress). Theo dõi bytes/sec log mỗi service; một spike volume thường có nghĩa hoặc là stack trace loop (một error đang loop nhanh), hoặc là ai đó bật debug log ở production quên tắt. Đặt sample cho log info khi RPS quá cao (level: 'warn' ở prod, hoặc chỉ log 1/N request thành công).
• Health của logging pipeline. Nếu log destination (Fluent Bit, Vector, Filebeat) đứng, log vẫn ghi ra stdout nhưng không được ship — service vẫn chạy nhưng "mù". Monitor pipeline lag riêng, không phải chỉ log volume ở đích.

Rule phòng ngừa cứng: (1) mọi service bắt buộc có requestId/traceId trong mọi log line — enforce qua template logger, không phải dựa vào từng call site nhớ; (2) không dùng console.log trong code production — lint rule cấm (no-console của ESLint); (3) redact tập trung ở logger config, không phải ở call site; (4) trả x-request-id ra response để user báo bug có id; (5) LOG_LEVEL phải configurable qua env — thay đổi mà không phải redeploy.

Tradeoff

Structured log dễ query, dễ join với trace, dễ redact — nhưng tăng volume so với plain text. Một dòng "user 1 bought 2" (~18 bytes) biến thành một JSON object với level, time, reqId, userId, qty, msg (~100+ bytes). Ở service RPS cao, chênh lệch này nhân lên thành GB/ngày và ăn ngân sách log ingest thật (Datadog/Splunk tính tiền theo GB). Bù lại: query time giảm mạnh vì aggregator index được field, không phải full-text scan; và cost của một sự cố production dài hơn vì grep mù thường lớn hơn cost log volume nhiều lần.

Correlation id truyền qua header có cost: mỗi service phải nhớ đọc + gắn lại khi gọi downstream — quên một chỗ là đứt chuỗi. Automation qua OpenTelemetry instrumentation hoặc middleware chung giải quyết, nhưng thêm dependency và một tầng abstraction. Tự làm bằng AsyncLocalStorage nhẹ hơn nhưng phải wrap tất cả outgoing HTTP client.

Async log giảm latency trên hot path nhưng có risk mất log cuối cùng khi process crash — buffer chưa flush. pino có pino.final() (theo pino docs) để flush trong uncaughtException/SIGTERM handler. Sync log an toàn hơn nhưng chặn event loop; chỉ dùng ở CLI/script ngắn, không dùng ở server RPS cao.

Rule of thumb: mặc định structured JSON log + async destination + một correlation id (ưu tiên W3C traceparent nếu có OpenTelemetry, không thì x-request-id) sinh ở edge và propagate xuyên suốt; info level ở prod với sample nếu cần, debug chỉ bật tạm qua env; redact ở logger config; trả id ra response header. Đừng tối ưu volume trước khi có sự cố đầu tiên buộc phải grep — bài học từ postmortem là "wish we had reqId" nhiều hơn "wish we logged less".

Câu hỏi phỏng vấn

Vì sao cần request id trong log, và cụ thể propagate nó qua các service như thế nào?

Vì một service RPS trung bình có nhiều request đồng thời, log line từ các request khác nhau xen kẽ nhau trong file/stream. Không có một field chung để nối các dòng thuộc cùng một request, thì "request X đã đi qua đâu, fail ở step nào" không trả lời được — chỉ còn grep mù. Cụ thể: ở edge service (service ngoài cùng nhận request từ client), sinh một requestId (UUID/ULID) hoặc lấy từ header x-request-id nếu upstream đã có; bind vào child logger (logger.child({ reqId }) với pino, hoặc request.log sẵn có với Fastify) để mọi log line trong scope request đều mang id. Khi gọi downstream service, gắn id vào request header (x-request-id, hoặc chuẩn hơn là W3C traceparent); downstream đọc header đó, dùng lại làm reqId của nó — chuỗi id không đứt qua network hop. Xuyên qua async work trong cùng process, dùng AsyncLocalStorage (Node core) để giữ context, không phải truyền reqId qua từng argument. Điểm ăn điểm là gọi tên hai hậu quả production: (a) không có correlation id thì incident postmortem chỉ join được manually theo timestamp — cực kỳ chậm và dễ sai khi có concurrent request; (b) nhận id từ public internet không validate là log injection vector — id phải sinh mới ở edge, chỉ trust từ upstream nội bộ; và một hậu quả về monitoring — log volume tăng vì mỗi line có thêm field, nhưng đây là chi phí phải trả để log query được thay vì phải grep mù. Bonus: trả x-request-id ra response header để user báo bug kèm id, khỏi phải hỏi "khoảng lúc mấy giờ".

Hands-on

Dựng một chain hai service Fastify để tái hiện scenario "log không có correlation id" rồi sửa, rồi query theo id.

Chuẩn bị:

mkdir req-logging && cd req-logging
npm init -y
npm pkg set type=module
npm i fastify pino pino-pretty

Tạo service-a.mjs (edge, gọi service-b):

import Fastify from 'fastify'
import crypto from 'node:crypto'

const app = Fastify({
  logger: {
    level: 'info',
    redact: ['req.headers.authorization', 'req.headers.cookie'],
  },
  genReqId: (req) =>
    req.headers['x-request-id'] ?? crypto.randomUUID(),
  requestIdHeader: 'x-request-id',
  requestIdLogLabel: 'reqId',
})

app.get('/checkout/:orderId', async (req, reply) => {
  req.log.info({ orderId: req.params.orderId }, 'checkout starting')

  // Gắn requestId vào call downstream — đây là điểm dễ quên
  const url = 'http://localhost:3102/charge/' + req.params.orderId
  const r = await fetch(url, {
    headers: { 'x-request-id': req.id },
  })
  const body = await r.json()

  if (!r.ok) req.log.warn({ status: r.status, body }, 'charge failed')
  reply.header('x-request-id', req.id)
  return { ok: r.ok, orderId: req.params.orderId, requestId: req.id, downstream: body }
})

await app.listen({ port: 3101, host: '0.0.0.0' })

Tạo service-b.mjs (downstream, fail ngẫu nhiên):

import Fastify from 'fastify'
import crypto from 'node:crypto'

const app = Fastify({
  logger: { level: 'info' },
  genReqId: (req) =>
    req.headers['x-request-id'] ?? crypto.randomUUID(),
  requestIdHeader: 'x-request-id',
  requestIdLogLabel: 'reqId',
})

app.get('/charge/:orderId', async (req, reply) => {
  req.log.info({ orderId: req.params.orderId }, 'charge received')
  // Simulate downstream latency + ~30% failure
  await new Promise(r => setTimeout(r, 20 + Math.random() * 80))
  if (Math.random() < 0.3) {
    req.log.error({ orderId: req.params.orderId }, 'db connection lost')
    return reply.code(500).send({ error: 'db_down' })
  }
  return { charged: true, orderId: req.params.orderId }
})

await app.listen({ port: 3102, host: '0.0.0.0' })

Chạy song song, ghi log ra file để grep sau:

node service-a.mjs 2>&1 | tee -a /tmp/a.log &
node service-b.mjs 2>&1 | tee -a /tmp/b.log &

# Bắn 50 request, mỗi request là một orderId khác
for i in $(seq 1 50); do
  curl -s "http://localhost:3101/checkout/order-$i" > /dev/null &
done
wait

Chọn một request đã fail (theo response {"ok":false,...}) — ví dụ requestId=abc-def-.... Query log của cả hai service theo id đó:

grep '"reqId":"abc-def-..."' /tmp/a.log /tmp/b.log | jq -s 'sort_by(.time)'

Sẽ ra chuỗi log line từ service-a → service-b → error → response, theo đúng thứ tự thời gian, cho đúng một request. Đây là điều không thể làm được nếu không truyền x-request-id sang downstream.

Sau đó, tái hiện failure mode 1 bằng cách xóa dòng headers: { 'x-request-id': req.id } trong service-a. Chạy lại và thử query: service-b sinh id mới cho mỗi request, không match id của service-a — chain bị đứt. Grep theo reqId chỉ ra dòng của service-a; grep theo orderId may ra được nhưng chỉ khi cả hai service tình cờ log cùng field đó.

Cuối cùng, thử log volume: bench và đo size log sinh ra:

# Bench với autocannon để xem log volume và độ trễ
npx autocannon -c 20 -d 10 http://localhost:3101/checkout/bench
wc -c /tmp/a.log /tmp/b.log   # size log sinh ra trong 10s

Bật LOG_LEVEL=warn (sửa level: process.env.LOG_LEVEL ?? 'info' trong config) và chạy lại — volume log giảm mạnh vì info bị bỏ qua, chỉ còn warn/error. Đây là cần chỉnh khi service RPS cao và ngân sách log ingest bị vượt: giảm level ở hot path, giữ error log nguyên vẹn.