Node.js에서 옵저버빌리티 추적과 로그 엮기

소개

현대의 분산 시스템에서는 애플리케이션의 동작을 이해하고 문제를 신속하게 진단하는 것이 무엇보다 중요합니다. 애플리케이션이 확장되고 복잡해짐에 따라 기존 로깅 도구나 독립형 추적 도구만으로는 부족합니다. 추적에서 제공하는 실행 경로, 구성 요소 상호 작용 및 타이밍 정보를 기반으로 애플리케이션 로그가 운영 컨텍스트와 본질적으로 연결되는 총체적인 보기가 필요합니다. 바로 여기서 로깅 프레임워크와 추적 시스템을 연결하는 것이 매우 중요해집니다.

Node.js 생태계에서 Pino는 고성능 로거로 두각을 나타내고 있으며, OpenTelemetry는 추적을 포함한 원격 측정 데이터를 수집하는 업계 표준으로 부상했습니다. Pino와 OpenTelemetry 간의 격차를 해소하면 추적 컨텍스트로 로그를 풍부하게 만들 수 있어 디버깅, 성능 분석 및 전반적인 시스템 이해에 훨씬 더 강력해집니다. 이 글에서는 이 중요한 연결을 설정하는 과정을 안내하여 궁극적으로 애플리케이션의 옵저버빌리티를 향상시킬 것입니다.

옵저버빌리티의 기둥

구현 세부 사항에 들어가기 전에 다룰 핵심 개념을 간략하게 정의해 보겠습니다.

• 옵저버빌리티: 외부 출력 데이터를 조사하여 시스템의 내부 상태를 추론하는 능력입니다. 시스템에 대한 임의의 질문을 하고 제공된 데이터(로그, 메트릭, 추적)에서 답변을 얻는 것에 관한 것입니다.
• 로그: 애플리케이션 내에서 발생하는 이벤트의 개별 타임스탬프 기록입니다. 무엇이, 언제, 때로는 왜 발생했는지에 대한 자세한 텍스트 정보를 제공합니다. Pino는 Node.js에서 구조화된 고성능 로깅을 위한 훌륭한 선택입니다.
• 추적: 분산 시스템을 통한 요청 또는 트랜잭션의 엔드투엔드 여정을 나타냅니다. 추적은 하나 이상의 **스팬(span)**으로 구성되며, 각 스팬은 작업의 논리적 단위를 나타냅니다(예: 함수 호출, 데이터베이스 쿼리, API 요청). 추적은 서비스 경계를 넘어서 컨텍스트, 인과 관계 및 지연 시간 정보를 제공합니다. OpenTelemetry는 추적을 생성하고 수집하기 위한 공급업체에 구애받지 않는 표준을 제공합니다.
• 추적 컨텍스트: 추적 및 현재 스팬을 식별하는 정보입니다. 이 컨텍스트는 프로세스 및 서비스 경계를 넘어 전파되어 개별 스팬이 함께 연결되어 완전한 추적을 형성할 수 있습니다. 주요 구성 요소에는 traceId 및 spanId가 포함됩니다.

목표는 Pino 로그에 이 추적 컨텍스트를 주입하여 문제 영역 로그 항목에서 실행 경로 전체를 보여주는 관련 추적으로 직접 이동하는 것을 쉽게 만드는 것입니다.

Pino 로그를 OpenTelemetry 추적과 연결

Pino를 OpenTelemetry와 통합하는 기본 원칙은 간단합니다. 로그가 기록되는 곳마다 현재 OpenTelemetry traceId 및 spanId를 로그 기록에 포함하려고 합니다. 이렇게 하면 직접적인 상관 관계가 설정됩니다.

1단계: OpenTelemetry 설정

먼저 애플리케이션에 OpenTelemetry가 계측되었는지 확인합니다. 여기에는 필요한 SDK 및 자동 계측 패키지 설치가 포함됩니다.

npm install @opentelemetry/sdk-node @opentelemetry/api @opentelemetry/auto-instrumentations-node
npm install @opentelemetry/exporter-collector --save-dev # 또는 OTLP gRPC와 같은 다른 익스포터

그런 다음 애플리케이션의 진입점(예: src/instrumentation.js 또는 src/tracing.js)에서 OpenTelemetry를 초기화합니다.

// src/tracing.js
import { NodeSDK } from '@opentelemetry/sdk-node';
import { ConsoleSpanExporter } from '@opentelemetry/sdk-trace-base';
import { Resource } from '@opentelemetry/resources';
import { SemanticResourceAttributes } from '@opentelemetry/semantic-conventions';
import { PeriodicExportingSpanProcessor } from '@opentelemetry/sdk-trace-base';
import { HttpInstrumentation } from '@opentelemetry/instrumentation-http';
import { ExpressInstrumentation } from '@opentelemetry/instrumentation-express';
import { OTLPTraceExporter } from '@opentelemetry/exporter-trace-otlp-grpc'; // 예제 OTLP 익스포터

const sdk = new NodeSDK({
  resource: new Resource({
    [SemanticResourceAttributes.SERVICE_NAME]: 'my-nodejs-app',
    [SemanticResourceAttributes.SERVICE_VERSION]: '1.0.0',
  }),
  spanProcessor: new PeriodicExportingSpanProcessor(new OTLPTraceExporter()), // 또는 개발용 ConsoleSpanExporter()
  instrumentations: [
    new HttpInstrumentation(),
    new ExpressInstrumentation(),
    // PostgreSQL용 @opentelemetry/instrumentation-pg와 같은 기타 관련 계측 추가
  ],
});

sdk.start();

console.log('OpenTelemetry tracing initialized.');

// 종료 시 추적이 플러시되도록 보장
process.on('SIGTERM', () => {
  sdk.shutdown()
    .then(() => console.log('Tracing terminated'))
    .catch((error) => console.log('Error terminating tracing', error))
    .finally(() => process.exit(0));
});

이 계측이 활성화된 상태로 애플리케이션을 실행해야 합니다.

node -r ./src/tracing.js src/index.js

2단계: Pino에 추적 컨텍스트 통합

Pino는 로그 기록에 컨텍스트 속성을 추가할 수 있는 '바인딩' 또는 '자식 로거'라는 강력한 기능을 제공합니다. @opentelemetry/api의 trace.getSpanContext() 메서드를 활용하여 현재 추적 및 스팬 ID를 검색할 수 있습니다.

먼저 Pino를 설치합니다.

npm install pino

이제 Pino 로거 인스턴스를 만듭니다. 핵심은 추적 컨텍스트가 사용 가능한 각 요청 또는 작업에 대해 자식 로거를 생성하여 컨텍스트 속성을 로그 기록에 주입하는 pino-caller 또는 사용자 지정 함수를 사용하는 것입니다.

Express.js를 사용한 예는 다음과 같습니다.

// src/index.js (OpenTelemetry 계측 후)
import express from 'express';
import pino from 'pino';
import { trace } from '@opentelemetry/api';

const app = express();
const port = 3000;

// 기본 Pino 로거 생성
const logger = pino({
  level: process.env.LOG_LEVEL || 'info',
  formatters: {
    // 이 포맷터는 상관 ID가 최상위 레벨에 있도록 보장합니다.
    log: (obj) => {
      if (obj.traceId && obj.spanId) {
        return { traceId: obj.traceId, spanId: obj.spanId, ...obj };
      }
      return obj;
    },
  },
});

// OpenTelemetry 추적 컨텍스트를 로거에 주입하는 미들웨어
app.use((req, res, next) => {
  const currentSpan = trace.getSpan(trace.activeContext());
  if (currentSpan) {
    const spanContext = currentSpan.spanContext();
    if (spanContext.traceId && spanContext.spanId) {
      // 추적 및 스팬 ID를 사용하여 자식 로거 생성
      req.log = logger.child({
        traceId: spanContext.traceId,
        spanId: spanContext.spanId,
      });
      req.log.debug('Request started'); // 예제 로그
    } else {
      req.log = logger; // 추적 컨텍스트 없음, 기본 로거 사용
    }
  } else {
    req.log = logger; // 활성 스팬 없음, 기본 로거 사용
  }
  next();
});

app.get('/', (req, res) => {
  req.log.info('Handling root request');
  // 다른 스팬을 생성할 수 있는 일부 작업 시뮬레이션
  const myService = {
    doSomething: (log) => {
      log.debug('Doing something important in service');
      // 여기서 별도의 모듈/함수였다면 새 스팬을 생성할 수 있습니다.
      // const newSpan = tracer.startSpan('myService.doSomething');
      // newSpan.end();
    }
  };
  myService.doSomething(req.log);
  res.send('Hello from Node.js with correlated logs!');
});

app.get('/error', (req, res) => {
    req.log.error('An error occurred during request processing!');
    res.status(500).send('Something went wrong!');
});

app.listen(port, () => {
  logger.info(`App listening at http://localhost:${port}`);
});

이 예에서:

1. 기본 pino 로거를 생성합니다.
2. 들어오는 요청을 가로채는 미들웨어를 생성합니다.
3. 미들웨어 내에서 trace.getSpan(trace.activeContext())를 사용하여 현재 활성 OpenTelemetry 스팬을 가져옵니다.
4. 스팬이 있으면 traceId 및 spanId를 추출합니다.
5. logger.child({ traceId, spanId })를 사용하여 child 로거를 생성합니다. 이 자식 로거는 기록하는 모든 로그에 이러한 속성을 자동으로 포함합니다.
6. 그런 다음 req.log에 이 자식 로거를 할당하여 요청 처리 체인 전체에서 접근할 수 있도록 합니다.

이제 /에 요청하면 콘솔(또는 로그 대상)에 다음과 유사한 로그가 표시됩니다(가독성을 위해 서식이 지정됨).

{
  "traceId": "a1b2c3d4e5f6a7b8c9d0e1f2a3b4c5d6",
  "spanId": "f7e8d9c0b1a2e3f4",
  "level": 30,
  "time": 1678886400000,
  "pid": 12345,
  "hostname": "my-host",
  "msg": "Request started"
}
{
  "traceId": "a1b2c3d4e5f6a7b8c9d0e1f2a3b4c5d6",
  "spanId": "f7e8d9c0b1a2e3f4",
  "level": 30,
  "time": 1678886400000,
  "pid": 12345,
  "hostname": "my-host",
  "msg": "Handling root request"
}
{
  "traceId": "a1b2c3d4e5f6a7b8c9d0e1f2a3b4c5d6",
  "spanId": "f7e8d9c0b1a2e3f4",
  "level": 20,
  "time": 1678886400000,
  "pid": 12345,
  "hostname": "my-host",
  "msg": "Doing something important in service"
}

동일한 요청과 관련된 모든 로그에 traceId 및 spanId가 일관되게 포함되어 있음을 확인합니다. 강력한 옵저버빌리티를 가능하게 하는 것은 이 강력한 상관 관계입니다.

애플리케이션 및 이점

이 설정을 사용하면 다음과 같은 몇 가지 이점을 얻을 수 있습니다.

• 더 빠른 근본 원인 분석: 오류 로그가 나타나면 해당 traceId를 사용하여 전체 추적을 즉시 검색하여 관련된 모든 작업, 서비스 및 타이밍을 볼 수 있습니다. 이렇게 하면 관련 없는 로그를 살펴보는 데 걸리는 시간이 크게 줄어듭니다.
• 컨텍스트가 풍부한 로그: 모든 로그 항목에는 해당 작업에 대한 컨텍스트가 포함됩니다. 이는 여러 서비스에 걸쳐 있는 경우에도 마찬가지입니다.
• 향상된 디버깅: 로그 관리 시스템에서 traceId별로 로그를 필터링하여 특정 사용자 상호 작용 또는 프로세스와 관련된 로그만 보고 이벤트의 순차적인 스토리를 제공할 수 있습니다.
• 성능 병목 현상 식별: 로그와 추적 타이밍을 상관시켜 코드의 어느 부분이 시간이 너무 오래 걸리는지 또는 외부 호출이 너무 오래 걸리는지 정확히 찾아낸 다음 필요한 경우 자세한 로그로 드릴다운할 수 있습니다.
• 통합된 옵저버빌리티 경험: 로그 관리 시스템(Elastic Stack, Splunk, Sumo Logic, Datadog 등) 및 APM 도구(Jaeger, Zipkin, Datadog APM, New Relic 등)는 이러한 상관 ID를 활용하여 로그를 추적과 함께 표시하여 애플리케이션의 상태 및 성능에 대한 진정한 통합 보기를 제공할 수 있습니다.

결론

Pino 로그와 OpenTelemetry 추적을 통합하는 것은 Node.js 애플리케이션에서 포괄적인 옵저버빌리티를 달성하기 위한 기본 단계입니다. 추적 및 스팬 ID를 로그 기록에 직접 포함하면 분산된 원격 측정 신호를 시스템 동작의 강력하고 상호 연결된 스토리로 변환할 수 있습니다. 이 상관 관계는 디버깅을 간소화하고, 근본 원인 분석을 가속화하며, 애플리케이션의 운영 상태에 대한 훨씬 더 명확한 그림을 제공합니다. 이 관행을 채택하면 옵저버빌리티 전략이 파편화된 통찰력에서 분산 시스템에 대한 진정으로 일관된 이해로 나아갈 수 있습니다.