Devin.KR
통합 검색 Ctrl K

관측 가능성 - 구조화 로그·지표·추적 ID

개발자KR 조회 19

이 장에서 배우는 것

서버가 개발자의 컴퓨터에서 벗어나 운영 환경에 배포되고 나면, 내부에서 어떤 일이 일어나고 있는지 파악하기가 매우 어려워진다. 트래픽이 적을 때는 콘솔에 출력되는 텍스트 몇 줄만으로도 원인을 찾을 수 있지만, 초당 수백 건의 요청이 들어오는 상황에서는 여러 요청의 로그가 뒤섞여 흐름을 추적할 수 없게 된다.

이러한 문제를 해결하고 시스템의 내부 상태를 외부에서 파악할 수 있게 만드는 속성을 관측 가능성(observability)이라고 부른다. 앞 장에서 성능이 저하되는 구간을 찾기 위해 프로파일링 기법을 활용했다면, 이번에는 서버가 평소에 자신의 상태를 잘 기록하고 보고하도록 만드는 방법을 알아본다.

  • 로그를 일반 텍스트가 아닌 JSON 구조화 데이터로 남기는 방법
  • 표준 모듈의 AsyncLocalStorage를 이용해 요청마다 고유한 추적 ID를 부여하고 유지하는 방법
  • 로드밸런서가 서버의 생존 여부를 판단할 수 있는 상태 확인(health check) 엔드포인트 구현
  • 서버의 메모리 사용량, 요청 처리 횟수 등 핵심 지표를 수집하고 노출하는 방법

문제 상황

로그 수집 서버를 운영 환경에 배포한 후, 간헐적으로 특정 클라이언트의 로그 업로드 요청이 실패한다는 보고를 받았다. 원인을 찾기 위해 서버 로그를 열어보았으나, 다음과 같이 무질서한 텍스트 뭉치만 남아 있었다.

요청 수신: /api/logs
요청 수신: /api/logs
본문 길이: 1024
데이터베이스 연결 중...
본문 길이: 512
오류 발생: 데이터 형식이 올바르지 않습니다.
요청 완료: 202
요청 수신: /api/logs

어떤 본문 길이가 오류를 발생시켰는지, 데이터베이스 연결은 어떤 요청에서 이루어졌는지 위 텍스트만으로는 도저히 연결할 수 없다. 비동기로 동작하는 Node.js 특성상 여러 요청의 처리 과정이 시분할로 교차하면서 로그가 뒤죽박죽 섞였기 때문이다. 또한, 현재 서버가 초당 몇 개의 요청을 처리하고 있는지, 메모리 누수는 없는지 파악하려면 외부 모니터링 도구와 연동할 수 있는 정량적인 수치가 필요하지만 지금의 서버는 아무런 지표도 제공하지 않는다.

구조화 로그와 JSON

가장 먼저 해결해야 할 문제는 로그의 형태를 바꾸는 것이다. 사람의 눈으로 읽기 편한 문장 형태의 텍스트 로그는 프로그램이 분석하거나 검색하기 매우 까다롭다. 대신 로그를 기계가 읽기 쉬운 형태인 JSON으로 남기면, 수집기와 검색 엔진이 이 데이터를 쉽게 파싱하여 필터링할 수 있다.

구조화 로그(structured log)는 시간, 로그 수준, 메시지, 그리고 각종 부가 정보를 명확한 키와 값의 쌍으로 관리한다. Node.js에서는 외부 라이브러리를 쓰지 않더라도, 자바스크립트 객체를 만든 뒤 JSON.stringify를 호출하여 표준 출력(stdout)으로 내보내는 방식으로 단순하고 강력한 구조화 로거를 만들 수 있다.

텍스트 로그와 구조화 로그의 형태 차이 비교

추적 ID와 AsyncLocalStorage

구조화 로그를 도입해도 여러 요청이 섞이는 문제는 남는다. 이를 해결하려면 각 HTTP 요청이 시작될 때 고유한 식별자(추적 ID)를 발급하고, 해당 요청과 연관된 모든 작업에서 로그를 남길 때 이 식별자를 포함해야 한다.

하지만 Node.js에서 이 식별자를 모든 함수의 인자로 일일이 넘기는 것은 매우 번거롭다. node:async_hooks 모듈에서 제공하는 AsyncLocalStorage를 사용하면 비동기 흐름을 따라가는 문맥(context) 저장소를 만들 수 있다.

HTTP 요청의 추적 ID가 비동기 함수들을 거쳐 로거까지 전달되는 흐름

이 클래스의 run 메서드에 저장할 상태와 콜백 함수를 전달하면, 콜백 안에서 파생된 모든 비동기 작업(타이머, 파일 입출력, 프로미스 등)은 동일한 상태를 공유하게 된다. 어느 깊이의 함수에서든 getStore()를 호출하여 처음에 넣어둔 추적 ID를 꺼내볼 수 있다.

상태 확인과 지표 수집 엔드포인트

운영 환경에서는 로드밸런서나 컨테이너 오케스트레이션 도구가 서버 프로세스의 상태를 주기적으로 감시한다. 프로세스가 살아있더라도 내부 무한 루프에 빠지거나 데이터베이스 연결이 끊겨 정상적인 응답이 불가능한 상태일 수 있으므로, HTTP 요청에 대해 서버가 "나는 정상 작동 중이다"라고 응답하는 전용 주소가 필요하다. 이를 상태 확인 엔드포인트라고 부르며 주로 /healthz라는 경로를 사용한다.

더 나아가 시스템의 정량적인 상태를 숫자로 보여주는 지표(metrics) 엔드포인트도 필요하다. 누적 요청 횟수, 오류 발생 횟수, 프로세스 가동 시간, 메모리 사용량 등을 JSON 형태로 반환하는 /metrics 경로를 만들면, 외부 수집기가 이 주소를 주기적으로 호출하여 그래프를 그리고 경고 알람을 설정할 수 있다.

주요 관측 가능성 용어 정리
용어 목적 구현 예시
구조화 로그 검색과 분석이 쉬운 기계 친화적 기록 JSON 객체 표준 출력
추적 ID 비동기 흐름 내의 연관 작업 식별 AsyncLocalStorage와 UUID
상태 확인 로드밸런서에게 정상 트래픽 처리 가능 여부 보고 /healthz 200 OK 응답
지표 시스템의 시계열 정량 수치 모니터링 /metrics JSON 통계 응답

완성 코드

이제 위에서 설명한 세 가지 개념을 하나의 로그 수집 서버에 통합해 본다. 코드는 두 개의 파일로 나눈다.

logger.mjs

import { AsyncLocalStorage } from 'node:async_hooks';

// 비동기 문맥을 저장할 전역 저장소를 생성한다.
export const asyncLocalStorage = new AsyncLocalStorage();

export function logInfo(message, extra = {}) {
  // 현재 실행 중인 비동기 문맥에서 저장소를 가져온다.
  const store = asyncLocalStorage.getStore();
  const traceId = store ? store.traceId : 'no-trace';
  
  const logEntry = {
    level: 'INFO',
    timestamp: new Date().toISOString(),
    traceId,
    message,
    ...extra
  };
  
  // JSON 문자열로 변환하고 줄바꿈 문자를 붙여 출력한다.
  process.stdout.write(JSON.stringify(logEntry) + '\n');
}

export function logError(message, error, extra = {}) {
  const store = asyncLocalStorage.getStore();
  const traceId = store ? store.traceId : 'no-trace';
  
  const logEntry = {
    level: 'ERROR',
    timestamp: new Date().toISOString(),
    traceId,
    message,
    errorMessage: error.message,
    stack: error.stack,
    ...extra
  };
  
  process.stderr.write(JSON.stringify(logEntry) + '\n');
}

server.mjs

import { createServer } from 'node:http';
import { randomUUID } from 'node:crypto';
import { performance } from 'node:perf_hooks';
import { asyncLocalStorage, logInfo, logError } from './logger.mjs';

// 서버의 상태 지표를 담을 전역 객체
const metrics = {
  requestCount: 0,
  errorCount: 0
};

const server = createServer((req, res) => {
  // 클라이언트가 보낸 추적 ID가 없다면 새로 생성한다.
  const traceId = req.headers['x-trace-id'] || randomUUID();
  const store = { traceId };

  // 이 요청의 수명 주기 동안 store를 비동기 문맥으로 유지한다.
  asyncLocalStorage.run(store, () => {
    metrics.requestCount++;
    const startTime = performance.now();

    // 응답이 끝날 때 걸린 시간을 로그로 남긴다.
    res.on('finish', () => {
      const duration = performance.now() - startTime;
      logInfo('Request completed', { 
        method: req.method, 
        url: req.url, 
        status: res.statusCode, 
        durationMs: Math.round(duration) 
      });
    });

    try {
      if (req.url === '/healthz') {
        res.writeHead(200, { 'Content-Type': 'application/json' });
        res.end(JSON.stringify({ status: 'ok' }));
        return;
      }

      if (req.url === '/metrics') {
        const mem = process.memoryUsage();
        res.writeHead(200, { 'Content-Type': 'application/json' });
        res.end(JSON.stringify({
          uptime: Math.round(process.uptime()),
          requests: metrics.requestCount,
          errors: metrics.errorCount,
          rssBytes: mem.rss
        }));
        return;
      }

      if (req.url === '/api/logs' && req.method === 'POST') {
        let body = '';
        req.on('data', chunk => { body += chunk; });
        req.on('end', () => {
          logInfo('Log payload received', { byteLength: body.length });
          res.writeHead(202, { 'Content-Type': 'application/json' });
          res.end(JSON.stringify({ message: 'accepted' }));
        });
        return;
      }

      metrics.errorCount++;
      res.writeHead(404, { 'Content-Type': 'application/json' });
      res.end(JSON.stringify({ error: 'Not found' }));
    } catch (err) {
      metrics.errorCount++;
      logError('Internal server error', err);
      if (!res.headersSent) {
        res.writeHead(500, { 'Content-Type': 'application/json' });
        res.end(JSON.stringify({ error: 'Internal Server Error' }));
      }
    }
  });
});

server.listen(3000, () => {
  logInfo('Server started', { port: 3000 });
});

줄별 해설

logger.mjs에서 생성한 new AsyncLocalStorage() 인스턴스는 어플리케이션 전체에서 하나만 존재해야 한다. logInfo 함수 내부를 보면 함수의 인자로 추적 ID를 전혀 받지 않지만, asyncLocalStorage.getStore()를 호출하여 현재 문맥에 바인딩된 상태 객체를 가져온다. 만약 run 메서드 바깥에서 이 함수가 호출된다면 store는 undefined가 되므로 방어 코드를 작성해 두었다.

server.mjs에서는 HTTP 요청이 들어올 때마다 node:crypto 모듈의 randomUUID()로 고유 문자열을 만든다. 이후 asyncLocalStorage.run() 안에서 라우팅 로직을 실행한다. 가장 중요한 부분은 res.on('finish', ...) 이벤트 리스너다. 이 리스너 역시 run() 블록 안에서 등록되었으므로 비동기적으로 응답이 끝나는 시점에 호출되어도 정확히 자신의 추적 ID를 기억하고 로그를 남긴다. 또한 performance.now()를 이용해 요청을 처리하는 데 걸린 밀리초(ms) 단위의 시간 지표를 함께 남겨 병목 구간을 찾기 쉽게 만들었다.

상태 확인 주소인 /healthz는 의존성이 정상인지 판단한 뒤 200 코드를 반환한다. 지표 주소인 /metrics는 글로벌 process 객체에서 프로세스가 떠 있었던 시간과 힙 메모리 외부에 할당된 물리 메모리 크기(RSS)를 가져와 내부 통계치와 함께 응답한다.

실행 결과

서버를 실행하고 다른 터미널에서 curl 명령을 사용해 서버에 요청을 보낸다.

$ node server.mjs
{"level":"INFO","timestamp":"2023-10-27T10:00:00.000Z","traceId":"no-trace","message":"Server started","port":3000}

위 시작 로그는 HTTP 요청 밖에서 발생했으므로 traceId가 no-trace로 기록된다. 이제 /api/logs에 데이터를 보낸다.

$ curl -X POST -d "sample log data" http://localhost:3000/api/logs
{"message":"accepted"}

서버의 터미널에는 동일한 traceId를 가진 두 줄의 로그가 JSON 형태로 출력된다.

{"level":"INFO","timestamp":"2023-10-27T10:00:15.123Z","traceId":"a1b2c3d4-5678-90ab-cdef-112233445566","message":"Log payload received","byteLength":15}
{"level":"INFO","timestamp":"2023-10-27T10:00:15.125Z","traceId":"a1b2c3d4-5678-90ab-cdef-112233445566","message":"Request completed","method":"POST","url":"/api/logs","status":202,"durationMs":2}

마지막으로 지표 수집 엔드포인트를 호출한다.

$ curl http://localhost:3000/metrics
{"uptime":120,"requests":2,"errors":0,"rssBytes":35643392}

실무에서 자주 틀리는 것

콜백 밖에서 저장소 접근하기

가장 흔한 실수는 비동기 작업이 시작되기 전이나, AsyncLocalStorage.run() 블록과 전혀 무관한 곳에서 getStore()를 호출하여 undefined 오류를 겪는 일이다.

// 틀린 코드
const store = asyncLocalStorage.getStore();
asyncLocalStorage.run(store, () => { /* ... */ });

// 고친 코드
asyncLocalStorage.run({ traceId: '123' }, () => {
  const store = asyncLocalStorage.getStore(); // 정상 작동
});

메모리 누수를 유발하는 지표 배열

각 요청의 처리 시간이나 상세 데이터를 지표로 제공하겠다며 전역 배열에 끝없이 push하는 코드는 심각한 메모리 누수를 일으킨다.

// 틀린 코드: 요청이 들어올 때마다 무한히 커진다.
const metrics = { requestTimes: [] };
metrics.requestTimes.push(duration);

// 고친 코드: 누적합이나 평균 등 단일 숫자로 집계한다.
const metrics = { totalDuration: 0, count: 0 };
metrics.totalDuration += duration;
metrics.count++;

로깅 시 민감한 객체 전체 덤프

구조화 로그를 쓴다며 요청 객체나 오류 객체를 그대로 JSON.stringify에 넘기면, 순환 참조 오류가 발생하거나 환경 변수 등의 비밀값이 로그에 노출될 수 있다. 반드시 필요한 속성만 골라내어 복사한 뒤 남겨야 한다.

// 틀린 코드
logInfo('요청 정보', { request: req });

// 고친 코드
logInfo('요청 정보', { method: req.method, url: req.url });

한눈에 보기

관측 가능성 주요 기법과 특징
개념 활용 도구/모듈 해결하는 문제 주의점
구조화 로그 JSON.stringify, process.stdout 텍스트 로그 분석의 어려움 극복 객체 순환 참조, 민감 정보 노출
비동기 문맥 추적 node:async_hooks (AsyncLocalStorage) 동시 요청 로그 뒤섞임 방지 run() 스코프 내에서만 유효함
상태/지표 노출 /healthz, /metrics 엔드포인트 시스템 무응답, 자원 사용량 파악 불가 지표 집계 변수의 메모리 증가 억제

연습 문제

  1. 현재 예제의 /metrics 엔드포인트는 모든 요청에 대해 성공과 실패 여부와 무관하게 requestCount를 1씩 증가시킵니다. 상태 코드가 400 이상인 경우에는 errorCount만 증가하고 requestCount는 증가하지 않도록 코드를 수정해 보세요.
  2. logError 함수 내부를 보면 에러 객체의 stack 속성을 JSON에 포함하고 있습니다. 개발 환경에서는 유용하지만 운영 환경에서는 스택 트레이스 길이가 길어 스토리지 비용을 증가시킵니다. process.env.NODE_ENV가 production일 때는 stack을 남기지 않게 조건문을 추가해 보세요.
  3. AsyncLocalStorage를 여러 개 생성하여 하나는 사용자 인증 정보(세션 ID)를, 하나는 시스템 추적 ID를 저장하려고 합니다. 이것이 가능한지, 그리고 성능상 어떤 불이익이 있을지 생각해 보세요.

정답과 해설

  1. metrics.requestCount++ 위치를 응답이 끝나는 res.on('finish', ...) 리스너 내부로 옮기고, if (res.statusCode < 400) 조건을 추가하여 분기하면 됩니다. 에러 카운트 역시 이 블록 안에서 statusCode >= 400일 때 증가시키는 방식이 더 정확합니다.
  2. const includeStack = process.env.NODE_ENV !== 'production'; 변수를 선언한 뒤, 구조분해 할당 부분에서 ...(includeStack && { stack: error.stack }) 형태로 작성하면 운영 환경에서는 속성 자체가 제외됩니다.
  3. 여러 개의 인스턴스를 생성하여 동시에 사용하는 것은 가능합니다. 하지만 컨텍스트 전환이 일어날 때마다 V8 엔진이 추적해야 할 비동기 훅의 갯수가 늘어나므로 약간의 성능 오버헤드가 발생합니다. 가급적 하나의 AsyncLocalStorage에 객체를 담고, 그 안에서 { traceId, sessionId } 형태로 여러 값을 관리하는 것이 자원을 더 효율적으로 사용하는 방법입니다.

댓글 0

아직 댓글이 없습니다. 첫 댓글을 남겨 보세요.

댓글을 남기려면 로그인이 필요합니다.