Pino structured log + OpenTelemetry correlation

“Service A lambat, cek log!” — buka Kibana, search timestamp, tapi gak ketemu request mana yang slow. Tanpa trace_id, log distributed = mimpi buruk. Pino + OTel context bikin setiap log entry punya trace_id sama dengan span Jaeger / Tempo. Klik trace, dapat semua log terkait.

Kode

// src/logger.ts
import pino, { type Logger } from "pino";
import { trace, context } from "@opentelemetry/api";

interface LogContext {
  trace_id?: string;
  span_id?: string;
  trace_flags?: number;
}

function getOtelContext(): LogContext {
  const span = trace.getSpan(context.active());
  if (!span) return {};

  const ctx = span.spanContext();
  return {
    trace_id: ctx.traceId,
    span_id: ctx.spanId,
    trace_flags: ctx.traceFlags,
  };
}

const isProd = process.env.NODE_ENV === "production";

export const logger: Logger = pino({
  level: process.env.LOG_LEVEL ?? "info",
  base: {
    service: "api-tokopedia",
    env: process.env.NODE_ENV ?? "development",
    version: process.env.APP_VERSION ?? "dev",
  },
  // Mixin function dipanggil per log call — inject trace context dinamis
  mixin: () => getOtelContext(),
  formatters: {
    level: (label) => ({ level: label }),
  },
  // Redact field sensitif sebelum log
  redact: {
    paths: ["password", "token", "*.headers.authorization", "*.body.password"],
    censor: "[REDACTED]",
  },
  // Production: JSON ke stdout. Dev: pretty-print
  transport: isProd
    ? undefined
    : {
        target: "pino-pretty",
        options: { colorize: true, translateTime: "HH:MM:ss" },
      },
});

// src/tracing.ts
import { NodeSDK } from "@opentelemetry/sdk-node";
import { OTLPTraceExporter } from "@opentelemetry/exporter-trace-otlp-http";
import { Resource } from "@opentelemetry/resources";
import { SemanticResourceAttributes } from "@opentelemetry/semantic-conventions";
import { getNodeAutoInstrumentations } from "@opentelemetry/auto-instrumentations-node";

const sdk = new NodeSDK({
  resource: new Resource({
    [SemanticResourceAttributes.SERVICE_NAME]: "api-tokopedia",
    [SemanticResourceAttributes.SERVICE_VERSION]: process.env.APP_VERSION ?? "dev",
  }),
  traceExporter: new OTLPTraceExporter({
    url: process.env.OTEL_ENDPOINT ?? "http://localhost:4318/v1/traces",
  }),
  instrumentations: [
    getNodeAutoInstrumentations({
      "@opentelemetry/instrumentation-fs": { enabled: false },
    }),
  ],
});

sdk.start();

// Shutdown gracefully
process.on("SIGTERM", () => {
  sdk.shutdown().finally(() => process.exit(0));
});

export default sdk;

// src/middleware/log.ts
import type { FastifyInstance } from "fastify";
import { trace } from "@opentelemetry/api";

import { logger } from "../logger";

export function attachLogger(app: FastifyInstance) {
  app.addHook("onRequest", async (req, reply) => {
    const start = process.hrtime.bigint();
    (req as any).log_start = start;

    logger.info({
      msg: "request_started",
      method: req.method,
      url: req.url,
      ip: req.ip,
    });
  });

  app.addHook("onResponse", async (req, reply) => {
    const start = (req as any).log_start as bigint;
    const duration_ms = Number((process.hrtime.bigint() - start) / 1_000_000n);

    const span = trace.getActiveSpan();
    if (span) {
      span.setAttribute("http.status_code", reply.statusCode);
      span.setAttribute("http.duration_ms", duration_ms);
    }

    logger.info({
      msg: "request_completed",
      method: req.method,
      url: req.url,
      status: reply.statusCode,
      duration_ms,
    });
  });

  app.setErrorHandler((err, _req, reply) => {
    logger.error({
      msg: "request_error",
      err: { message: err.message, stack: err.stack, code: (err as any).code },
    });

    const span = trace.getActiveSpan();
    if (span) {
      span.recordException(err);
      span.setStatus({ code: 2, message: err.message }); // ERROR
    }

    reply.code(500).send({ error: "Internal error" });
  });
}

Pemakaian

// src/server.ts — bootstrap dengan tracing dulu
import "./tracing"; // HARUS first import — auto-instrument require()
import Fastify from "fastify";
import { logger } from "./logger";
import { attachLogger } from "./middleware/log";

const app = Fastify({ logger: false });
attachLogger(app);

app.get("/api/produk/:id", async (req, reply) => {
  const { id } = req.params as { id: string };

  logger.debug({ msg: "fetch_produk_start", produk_id: id });

  const produk = await fetchFromDB(id);

  logger.info({ msg: "fetch_produk_success", produk_id: id, harga: produk.harga });

  return produk;
});

await app.listen({ port: 3000 });
logger.info("Server listening on :3000");

// Output log production (JSON line, satu per row)
{
  "level": "info",
  "time": 1717200000000,
  "service": "api-tokopedia",
  "env": "production",
  "trace_id": "5f3b8a2c1d9e4f6a7b8c9d0e1f2a3b4c",
  "span_id": "1a2b3c4d5e6f7a8b",
  "trace_flags": 1,
  "msg": "request_completed",
  "method": "GET",
  "url": "/api/produk/123",
  "status": 200,
  "duration_ms": 47
}

# Query di Loki — filter request slow
{service="api-tokopedia"} | json | duration_ms > 1000
# Lalu klik trace_id → langsung jump ke trace di Tempo

Kapan dipakai

• Microservice di production yang punya distributed trace.
• API gateway yang fan-out ke banyak service downstream.
• Service yang harus comply audit log (financial, healthcare).
• Setup observability stack: Grafana + Loki + Tempo.

Catatan

• mixin per call — Pino call mixin function setiap log. Untuk overhead minimum, snippet ini cuma get span context (cheap).
• import tracing first — auto-instrumentation patch core modules. Kalau import setelah module yang di-patch sudah loaded, instrumentation gak jalan.
• redact path — log password / token = breach. Pino redact lebih cepat dari regex post-process karena terjadi sebelum serialize.
• level di production: info default, debug hanya saat investigation. Setiap log entry punya cost — tinggi-traffic service bisa generate GB log per jam.
• pino-pretty hanya dev — di production, JSON line ke stdout, biarkan log shipper (Promtail / Fluent Bit) yang parse.

Pino sangat fast karena async write. Jangan log di hot path tanpa sampling — bahkan no-op logger.debug() punya cost serialization untuk argument-nya.