Node.js 옵저버빌리티: 복잡함 없는 로그, 메트릭, 트레이스

// 여러분이 작성하는 것
console.log("User login failed", email, error.message);
 
// 로그 파일에 나오는 것
// User login failed john@example.com ECONNREFUSED
 
// 이제 이것을 시도해 보세요:
// 1. 지난 1시간 동안의 모든 로그인 실패를 검색
// 2. 사용자별 실패 횟수 집계
// 3. ECONNREFUSED 오류만 필터링
// 4. 이것을 트리거한 요청과 상관관계 파악
// 행운을 빕니다. 구조화되지 않은 문자열입니다. 텍스트를 grep하고 있는 겁니다.

// 구조화된 로깅이 어떤 모습인지
{
  "level": 50,
  "time": 1709312587000,
  "msg": "User login failed",
  "email": "john@example.com",
  "error": "ECONNREFUSED",
  "requestId": "req-abc-123",
  "route": "POST /api/auth/login",
  "responseTime": 1247,
  "pid": 12345
}

// src/lib/logger.ts
import pino from "pino";
 
const isProduction = process.env.NODE_ENV === "production";
 
export const logger = pino({
  level: process.env.LOG_LEVEL || (isProduction ? "info" : "debug"),
  // 프로덕션에서는 stdout에 JSON만. PM2/컨테이너 런타임이 나머지를 처리.
  // 개발 환경에서는 사람이 읽을 수 있는 출력을 위해 pino-pretty 사용.
  ...(isProduction
    ? {}
    : {
        transport: {
          target: "pino-pretty",
          options: {
            colorize: true,
            translateTime: "HH:MM:ss",
            ignore: "pid,hostname",
          },
        },
      }),
  // 모든 로그 라인의 표준 필드
  base: {
    service: process.env.SERVICE_NAME || "api",
    version: process.env.APP_VERSION || "unknown",
  },
  // Error 객체를 올바르게 직렬화
  serializers: {
    err: pino.stdSerializers.err,
    error: pino.stdSerializers.err,
    req: pino.stdSerializers.req,
    res: pino.stdSerializers.res,
  },
  // 민감한 필드 수정
  redact: {
    paths: ["req.headers.authorization", "req.headers.cookie", "password", "creditCard", "ssn"],
    censor: "[REDACTED]",
  },
});

// FATAL (60) - 프로세스가 곧 크래시할 것. 누군가를 깨워라.
logger.fatal({ err }, "Unrecoverable database connection failure");
 
// ERROR (50) - 발생하지 않아야 할 것이 실패함. 곧 조사하라.
logger.error({ err, userId, orderId }, "Payment processing failed");
 
// WARN (40) - 예상치 못했지만 처리됨. 주시하라.
logger.warn({ retryCount: 3, service: "email" }, "Retry limit approaching");
 
// INFO (30) - 기록할 가치가 있는 정상 운영. "무슨 일이 일어났나" 로그.
logger.info({ userId, action: "login" }, "User authenticated");
 
// DEBUG (20) - 디버깅을 위한 상세 정보. 절대 프로덕션에서 사용하지 않음.
logger.debug({ query, params }, "Database query executing");
 
// TRACE (10) - 극도로 상세. 정말 절박할 때만.
logger.trace({ headers: req.headers }, "Incoming request headers");

// 이 자식 로거의 모든 로그에는 userId와 sessionId가 포함됩니다
const userLogger = logger.child({ userId: "usr_4821", sessionId: "ses_xyz" });
 
userLogger.info("User viewed dashboard");
// 출력에 userId와 sessionId가 자동 포함
 
userLogger.info({ page: "/settings" }, "User navigated");
// 출력에 userId, sessionId, 그리고 page가 포함

// src/middleware/request-logger.ts
import { randomUUID } from "node:crypto";
import { logger } from "../lib/logger";
import type { Request, Response, NextFunction } from "express";
 
export function requestLogger(req: Request, res: Response, next: NextFunction) {
  const requestId = req.headers["x-request-id"]?.toString() || randomUUID();
  const startTime = performance.now();
 
  // 요청에 자식 로거 연결
  req.log = logger.child({
    requestId,
    method: req.method,
    path: req.url,
  });
 
  // 응답이 완료되면 로깅
  res.on("finish", () => {
    const duration = Math.round(performance.now() - startTime);
 
    req.log.info(
      {
        statusCode: res.statusCode,
        duration,
        contentLength: res.getHeader("content-length"),
      },
      "Request completed",
    );
  });
 
  // 응답 헤더에 요청 ID 설정 (디버깅에 유용)
  res.setHeader("x-request-id", requestId);
 
  next();
}

// 코드 어딘가의 서비스
export async function getOrder(orderId: string, req: Request) {
  req.log.info({ orderId }, "Fetching order");
 
  const order = await db.orders.findById(orderId);
 
  if (!order) {
    req.log.warn({ orderId }, "Order not found");
    return null;
  }
 
  req.log.info({ orderId, status: order.status }, "Order retrieved");
  return order;
}

import pinoHttp from "pino-http";
import { logger } from "./lib/logger";
 
app.use(
  pinoHttp({
    logger,
    // 노이즈가 많은 경로 커스터마이즈
    autoLogging: {
      ignore: (req) => req.url === "/health" || req.url === "/ready",
    },
    // 쿼리 문자열이나 헤더 같은 추가 컨텍스트
    customProps: (req) => ({
      userAgent: req.headers["user-agent"],
    }),
    // 상태 코드에 따른 커스텀 로그 레벨
    customLogLevel: (req, res, error) => {
      if (res.statusCode >= 500 || error) return "error";
      if (res.statusCode >= 400) return "warn";
      return "info";
    },
  }),
);

npm install -D pino-pretty
node server.js | pino-pretty

// src/lib/metrics.ts
import { Registry, Counter, Histogram, Gauge, collectDefaultMetrics } from "prom-client";
 
export const register = new Registry();
 
// 기본 Node.js 메트릭 (이벤트 루프 지연, 메모리 사용량, GC 등)
collectDefaultMetrics({ register });
 
// HTTP 요청 카운터
export const httpRequestsTotal = new Counter({
  name: "http_requests_total",
  help: "Total number of HTTP requests",
  labelNames: ["method", "route", "status_code"] as const,
  registers: [register],
});
 
// HTTP 요청 기간 히스토그램
export const httpRequestDuration = new Histogram({
  name: "http_request_duration_seconds",
  help: "HTTP request duration in seconds",
  labelNames: ["method", "route", "status_code"] as const,
  buckets: [0.001, 0.005, 0.01, 0.025, 0.05, 0.1, 0.25, 0.5, 1, 2.5, 5, 10],
  registers: [register],
});
 
// 활성 연결 게이지
export const activeConnections = new Gauge({
  name: "active_connections",
  help: "Number of active connections",
  registers: [register],
});
 
// 데이터베이스 쿼리 기간
export const dbQueryDuration = new Histogram({
  name: "db_query_duration_seconds",
  help: "Database query duration in seconds",
  labelNames: ["operation", "table"] as const,
  buckets: [0.001, 0.005, 0.01, 0.05, 0.1, 0.5, 1, 5],
  registers: [register],
});
 
// 외부 API 호출 기간
export const externalApiDuration = new Histogram({
  name: "external_api_duration_seconds",
  help: "External API call duration in seconds",
  labelNames: ["service", "endpoint", "status"] as const,
  buckets: [0.01, 0.05, 0.1, 0.25, 0.5, 1, 2.5, 5, 10],
  registers: [register],
});
 
// 캐시 히트/미스 카운터
export const cacheOperations = new Counter({
  name: "cache_operations_total",
  help: "Cache operations",
  labelNames: ["operation", "result"] as const,
  registers: [register],
});

// src/routes/metrics.ts
import { register } from "../lib/metrics";
import type { Request, Response } from "express";
 
export async function metricsHandler(req: Request, res: Response) {
  try {
    res.set("Content-Type", register.contentType);
    res.end(await register.metrics());
  } catch (err) {
    res.status(500).end(err);
  }
}
 
// app.ts에서
app.get("/metrics", metricsHandler);

// src/middleware/metrics.ts
import { httpRequestsTotal, httpRequestDuration, activeConnections } from "../lib/metrics";
import type { Request, Response, NextFunction } from "express";
 
export function metricsMiddleware(req: Request, res: Response, next: NextFunction) {
  // 헬스체크와 메트릭 엔드포인트는 건너뜀
  if (req.path === "/health" || req.path === "/metrics" || req.path === "/ready") {
    return next();
  }
 
  activeConnections.inc();
  const end = httpRequestDuration.startTimer();
 
  res.on("finish", () => {
    activeConnections.dec();
 
    // 와일드카드를 고유 ID 대신 경로 패턴으로 정규화
    const route = normalizeRoute(req.route?.path || req.path);
 
    const labels = {
      method: req.method,
      route,
      status_code: res.statusCode.toString(),
    };
 
    httpRequestsTotal.inc(labels);
    end(labels);
  });
 
  next();
}
 
function normalizeRoute(path: string): string {
  // /users/123/orders/456 → /users/:id/orders/:id
  return path
    .replace(/\/[0-9a-f]{8}-[0-9a-f]{4}-[0-9a-f]{4}-[0-9a-f]{4}-[0-9a-f]{12}/g, "/:id")
    .replace(/\/\d+/g, "/:id");
}

httpRequestsTotal.inc({ method: "GET", route: "/api/users", status_code: "200" });

activeConnections.inc(); // 요청 시작
activeConnections.dec(); // 요청 완료

const timer = httpRequestDuration.startTimer();
// ... 작업 수행 ...
timer({ method: "GET", route: "/api/users", status_code: "200" });

// 비즈니스 메트릭 예시
export const ordersCreated = new Counter({
  name: "orders_created_total",
  help: "Total orders created",
  labelNames: ["payment_method", "currency"] as const,
  registers: [register],
});
 
export const orderValue = new Histogram({
  name: "order_value_dollars",
  help: "Order value in dollars",
  buckets: [10, 25, 50, 100, 250, 500, 1000, 5000],
  registers: [register],
});
 
export const activeUsers = new Gauge({
  name: "active_users",
  help: "Currently active users",
  registers: [register],
});
 
// 코드에서 사용
ordersCreated.inc({ payment_method: "credit_card", currency: "USD" });
orderValue.observe(149.99);

groups:
  - name: api-alerts
    rules:
      # 5분간 오류율이 5% 이상
      - alert: HighErrorRate
        expr: rate(http_requests_total{status_code=~"5.."}[5m]) / rate(http_requests_total[5m]) > 0.05
        for: 2m
        labels:
          severity: critical
        annotations:
          summary: "높은 오류율 감지"
          description: "5분간 오류율 {{ $value | humanizePercentage }}"
 
      # p99 지연 시간이 2초 이상
      - alert: HighLatency
        expr: histogram_quantile(0.99, rate(http_request_duration_seconds_bucket[5m])) > 2
        for: 5m
        labels:
          severity: warning
        annotations:
          summary: "높은 지연 시간 감지"
          description: "p99 지연 시간 {{ $value | humanizeDuration }}"
 
      # Node.js 이벤트 루프 지연이 100ms 이상
      - alert: EventLoopLag
        expr: nodejs_eventloop_lag_seconds > 0.1
        for: 2m
        labels:
          severity: warning
        annotations:
          summary: "높은 이벤트 루프 지연"

// src/lib/tracing.ts
import { NodeSDK } from "@opentelemetry/sdk-node";
import { getNodeAutoInstrumentations } from "@opentelemetry/auto-instrumentations-node";
import { OTLPTraceExporter } from "@opentelemetry/exporter-trace-otlp-http";
import { Resource } from "@opentelemetry/resources";
import { ATTR_SERVICE_NAME, ATTR_SERVICE_VERSION } from "@opentelemetry/semantic-conventions";
 
const sdk = new NodeSDK({
  resource: new Resource({
    [ATTR_SERVICE_NAME]: process.env.SERVICE_NAME || "api",
    [ATTR_SERVICE_VERSION]: process.env.APP_VERSION || "unknown",
    environment: process.env.NODE_ENV || "development",
  }),
  traceExporter: new OTLPTraceExporter({
    url: process.env.OTEL_EXPORTER_OTLP_ENDPOINT || "http://localhost:4318/v1/traces",
  }),
  instrumentations: [
    getNodeAutoInstrumentations({
      // 가장 유용한 자동 계측 설정
      "@opentelemetry/instrumentation-http": {
        ignoreIncomingPaths: ["/health", "/ready", "/metrics"],
      },
      "@opentelemetry/instrumentation-express": {
        enabled: true,
      },
      "@opentelemetry/instrumentation-pg": {
        enhancedDatabaseReporting: true,
      },
      "@opentelemetry/instrumentation-ioredis": {
        enabled: true,
      },
      // fs 계측은 노이즈가 많음 — 비활성화
      "@opentelemetry/instrumentation-fs": {
        enabled: false,
      },
    }),
  ],
});
 
sdk.start();
 
// 정상 종료 처리
process.on("SIGTERM", () => {
  sdk.shutdown().then(() => process.exit(0));
});

node --require ./src/lib/tracing.js ./src/server.js
# 또는 tsx/ts-node 사용 시
node --require ./src/lib/tracing.ts ./src/server.ts

{
  "scripts": {
    "start": "node --require ./dist/lib/tracing.js ./dist/server.js"
  }
}

import { trace, SpanStatusCode } from "@opentelemetry/api";
 
const tracer = trace.getTracer("order-service");
 
async function processOrder(orderId: string, items: OrderItem[]) {
  return tracer.startActiveSpan("processOrder", async (span) => {
    try {
      span.setAttribute("order.id", orderId);
      span.setAttribute("order.item_count", items.length);
 
      // 재고 확인
      await tracer.startActiveSpan("checkInventory", async (inventorySpan) => {
        const available = await inventoryService.checkAll(items);
        inventorySpan.setAttribute("inventory.all_available", available);
        inventorySpan.end();
      });
 
      // 결제 처리
      await tracer.startActiveSpan("processPayment", async (paymentSpan) => {
        const result = await paymentService.charge(orderId);
        paymentSpan.setAttribute("payment.method", result.method);
        paymentSpan.setAttribute("payment.amount", result.amount);
        paymentSpan.end();
      });
 
      // 주문 확정
      await tracer.startActiveSpan("confirmOrder", async (confirmSpan) => {
        await db.orders.update(orderId, { status: "confirmed" });
        confirmSpan.end();
      });
 
      span.setStatus({ code: SpanStatusCode.OK });
    } catch (error) {
      span.setStatus({
        code: SpanStatusCode.ERROR,
        message: error instanceof Error ? error.message : "Unknown error",
      });
      span.recordException(error as Error);
      throw error;
    } finally {
      span.end();
    }
  });
}

# docker-compose.yml
services:
  jaeger:
    image: jaegertracing/all-in-one:latest
    ports:
      - "16686:16686" # UI
      - "4318:4318" # OTLP HTTP
    environment:
      - COLLECTOR_OTLP_ENABLED=true

import { trace } from "@opentelemetry/api";
 
function getTraceContext() {
  const span = trace.getActiveSpan();
  if (!span) return {};
 
  const context = span.spanContext();
  return {
    traceId: context.traceId,
    spanId: context.spanId,
  };
}
 
// 로거에 통합
const loggerWithTrace = logger.child(getTraceContext());
loggerWithTrace.error({ err }, "Payment failed");
// 출력: {"traceId":"abc123...","spanId":"def456...","msg":"Payment failed",...}

// Exemplar를 메트릭에 추가
const span = trace.getActiveSpan();
if (span) {
  httpRequestDuration.observe(
    {
      method: "GET",
      route: "/api/orders",
      status_code: "200",
    },
    duration,
    { traceID: span.spanContext().traceId }, // Exemplar
  );
}

// 나쁨 — 모든 요청의 전체 본문을 로깅
app.use((req, res, next) => {
  logger.info({ body: req.body, headers: req.headers }, "Incoming request");
  next();
});

// 나쁨 — 사용자 ID를 레이블로 사용
httpRequestsTotal.inc({
  method: "GET",
  route: "/api/users",
  user_id: userId, // 사용자가 100만 명이면 100만 개의 시계열
});

// 나쁨 — 오류를 잡고 조용히 넘김
try {
  await processPayment(order);
} catch (error) {
  // 결제 실패를 "처리"
  return { success: false };
}

// 좋음
try {
  await processPayment(order);
} catch (error) {
  logger.error({ err: error, orderId: order.id }, "Payment processing failed");
  paymentFailures.inc({ reason: categorizeError(error) });
  span?.recordException(error as Error);
  return { success: false, error: "Payment failed" };
}

import { TraceIdRatioBasedSampler } from "@opentelemetry/sdk-trace-base";
 
const sdk = new NodeSDK({
  // 트레이스의 10%만 저장
  sampler: new TraceIdRatioBasedSampler(0.1),
  // ...
});