관측 도구를 켜는 순서와 SDK 충돌

1편에서 요청 하나를 묶는 ID를 만들고 모든 로그에 붙였다. 덕분에 남은 로그는 읽을 수 있게 됐는데, 애초에 로그로 안 남는 실패는 그대로였다. 배치가 try/catch로 삼킨 에러가 그렇다. 찍히지 않으니 묶을 것도 없다.

그래서 남는 곳을 늘리기로 했다. 요청이 어디서 시간을 쓰는지 재는 분산추적, 에러를 모아 보여주는 Sentry, 상태를 주기적으로 재두는 메트릭이다.

붙이는 데 조건을 하나 달았다. 환경변수 하나로 켜고 끌 수 있을 것, 안 켜면 코드가 있어도 아무 일도 안 할 것이다. 관측 도구는 전부 밖에 있는 서버로 데이터를 보내는 물건이라, 그 서버가 없는 로컬과 CI에서 계속 보내려 들면 부팅이 느려지거나 연결 실패 로그가 쌓인다. 안 켜면 아무 일도 안 하게 해두면 그게 0이 된다.

스위치를 다는 건 if 한 줄이었다. 실제로 걸린 건 무엇을 언제 초기화하느냐였고, 거기서 두 번 막혔다.

분산추적을 켜는 import 순서

먼저 붙인 건 OpenTelemetry 분산추적이다. 요청 하나가 지나간 구간을 하나씩 재서 이어 붙인 것을 트레이스라 하고, 그 구간 하나를 span이라 한다. HTTP 요청 하나가 컨트롤러를 거쳐 쿼리를 세 번 날렸으면 span 네댓 개가 붙은 트레이스가 남는다. 여기서 걸린 건 코드가 아니라 import 순서였다.

자동 계측은 우리 코드를 안 고치고 라이브러리 쪽에 손을 대 span을 남기게 하는 방식이다. 그래서 http·express·mysql2 같은 모듈이 require되기 전에 그 손질을 끝내야 한다. 모듈이 이미 메모리에 올라온 뒤엔 늦다. OpenTelemetry 문서가 그 순서를 요구사항으로 적고, 늦었을 때 무슨 일이 나는지도 같이 적는다.

Before any other module in your application is loaded, you must initialize the SDK.

If you fail to initialize the SDK or initialize it too late, no-op implementations will be provided to any library that acquires a tracer or meter from the API.

— Instrumentation, OpenTelemetry JavaScript Documentation

늦으면 에러가 나는 게 아니라 아무것도 안 하는 구현이 대신 들어간다는 게 무섭다. 계측이 모듈 로딩을 가로채, 그 모듈에서 가져다 쓰는 함수를 바꿔치기하는 방식이라 그렇다(이걸 몽키패칭이라 부른다). 바꿔칠 대상을 누가 이미 가져다 쓴 뒤면 할 수 있는 게 없다.

그래서 추적 초기화 파일을 main.ts의 맨 첫 줄에서 import한다. NestJS·TypeORM보다 앞서야 한다. 문서가 꼽는 흔한 실수도 정확히 이것이다. 계측을 켜기 전에 그 대상 패키지를 먼저 require하는 것.

const endpoint = process.env.OTEL_EXPORTER_OTLP_ENDPOINT
if (endpoint) {
  // 수집기 엔드포인트 없으면 통째로 no-op
  const sdk = new NodeSDK({
    traceExporter: new OTLPTraceExporter(),
    instrumentations: [getNodeAutoInstrumentations()],
  })
  try {
    sdk.start() // 계측 설정 오류가 부팅 자체를 막지 않게 격리
  } catch (err) {
    console.error("[otel] SDK 시작 실패 — 트레이싱 없이 부팅 계속", err)
  }
}

추적을 켜는 SDK가 시작에 실패해도 try/catch로 삼키고 앱은 정상 부팅한다. 추적이 없다고 서비스가 못 뜰 이유가 없다.

대신 로그와 추적은 서로를 가리키게 묶었다. 로그에는 지금 도는 트레이스의 ID를 [trace:<id>]로 붙인다. 반대로 span에는 1편에서 만든 requestId를 속성으로 단다. 한 요청을 로그에서 추적으로, 추적에서 로그로 오갈 수 있다.

종료 신호(SIGTERM)를 받으면 버퍼에 남은 span을 마저 내보내야 한다. 그 핸들러는 HTTP 앱에만 달았다.

배치 프로세스에는 안 달았다. 배치는 NestJS가 종료할 때 DB 연결을 정리하게 해뒀다. 거기에 process.exit를 부르는 핸들러를 하나 더 얹으면, Nest가 정리를 끝내기 전에 프로세스가 죽는다. 그래서 이 파일을 배치에서는 import하지 않는 것이 규칙이 됐다.

Sentry를 켜니 추적 SDK가 둘이 됐다

다음은 에러를 모아 보여주는 Sentry인데, 여기서 진짜 함정이 나왔다. Sentry는 v8부터 OpenTelemetry를 자기 기반으로 쓴다. Sentry 문서에 따르면 init이 기본적으로 OpenTelemetry를 자동 설정하기 때문에, 부르는 순간 추적용 SDK를 자기도 하나 띄운다. 그런데 우리는 이미 tracing.ts에서 같은 SDK를 돌리고 있다.

OpenTelemetry는 지금 어느 span 안에서 도는 중인지를 전역 한 곳에 기록해둔다. SDK 두 개가 거기에 각자 등록하려 들면서 부딪친다.

해법은 Sentry의 OTel을 끄고 순수 에러 캡처만 맡기는 것이다. 분산추적은 앞서 만든 tracing.ts 쪽이 계속 담당한다.

if (dsn) {
  // SENTRY_DSN 없으면 no-op
  Sentry.init({
    dsn,
    environment: process.env.SENTRY_ENVIRONMENT ?? "unknown",
    skipOpenTelemetrySetup: true, // Sentry의 OTel 비활성 → tracing.ts와 충돌 회피
    tracesSampleRate: 0, // 트레이싱은 OTLP가, Sentry는 에러만
  })
}

보고 대상은 5xx만이다. 4xx와 늘 나는 401은 사용자 입력 문제지 서버 결함이 아니라 제외한다. 외부 API가 죽어 응답을 못 준 것을 사용자 입력 오류로 돌려주면 안 되는 것과 같은 구분이다. 잡으려던 건 에러를 삼키고 성공한 척 끝나는 배치였다.

그런 배치는 두 경로로 나뉜다. 에러를 catch로 잡고 다시 안 던지는 잡은 reportError를 직접 부른다. 그대로 던져지는 잡은 아무도 안 받은 프라미스 거부를 Sentry가 가로채 자동으로 잡는다. 전파되는 예외에까지 수동 호출을 넣으면 이중 보고가 되니, “삼키는 곳에서만 직접 부른다”로 정했다.

마지막 하나는 버퍼에 남은 것을 내보내는 문제다. 배치는 일이 끝나면 process.exit로 프로세스를 끝내는데, Sentry 전송은 비동기라 그냥 나가면 보고가 버퍼에 담긴 채 사라진다. 그래서 부팅 실패 같은 종료 경로에서 flushErrors()로 전송 완료를 기다린 뒤 exit한다.

나중에 붙인 메트릭

여기까지 만들고 하나를 더 붙였다. 지표를 주기적으로 재서 쌓아두는 Prometheus다.

앞의 것들은 전부 사건이 났을 때 한 줄씩 남기는 것이다. 그래서 “지금 얼마나 느린가”, “에러율이 지난주보다 오르고 있나” 같은 건 못 본다. 사건이 안 나도 계속 재둬야 답할 수 있는 질문이라 그렇다.

Node 프로세스 자체의 상태를 먼저 잰다. CPU와 메모리, 그리고 이벤트 루프가 밀린 시간과 가비지 컬렉션에 쓴 시간이다. 그 위에 요청 수와 에러율과 소요시간을 얹는다.

이 값들을 /metrics 주소로 내놓으면 Prometheus가 주기적으로 긁어간다. 아무나 못 긁게 토큰을 확인하는 가드를 앞에 뒀다. 나머지는 앞선 것들과 같아서, 안 켜면 비용이 없고 긁어가는 쪽이 없으면 아무 일도 안 일어난다.

처음 계획에는 이게 없었다. 앞의 것들이 틀렸다기보다, 다 만들고 나서야 남은 질문이 보였다. 로그를 줄이고 추적을 잇고 에러를 모으고 났더니 “그래서 지금 정상인가”에는 아직 답이 없었다.

켜고 끄는 방식

여기 붙인 것 전부 환경변수 하나로 켜고 끈다. OTEL_EXPORTER_OTLP_ENDPOINT가 없으면 추적은 SDK를 시작조차 안 하고, SENTRY_DSN이 없으면 에러 수집이 통째로 멎고, LOG_HTTP를 안 주면 로그는 기본값인 summary로 돈다. 로컬과 CI에서는 하나도 안 켜지니 부담이 0이다.

운영에서도 전부 켜져 있지는 않다. 추적은 데이터를 받아줄 수집기를 안 세워 보낼 주소가 없고, 메트릭은 /metrics가 열려 있는데 이 글을 쓰는 시점에 그 주소를 주기적으로 긁어가는 쪽이 없다. 태스크 정의에도 배포 워크플로우에도 Prometheus든 CloudWatch 에이전트든 붙여둔 게 없어서, 값은 프로세스 안에 쌓이기만 하다가 다음 배포 때 컨테이너와 함께 사라진다.

켜야만 도는 것으로 만든 이유가 이 어긋남이다. 수집기를 세우는 건 인프라 작업이라 코드가 준비되는 시점과 맞물릴 수가 없고, 코드가 수집기를 전제하면 그때까지 앱이 아예 못 뜨거나 보낼 곳도 없는데 계속 보내려 드는 코드를 안고 돌아야 한다. 지금은 env 한 줄이 비어 있을 뿐이고, 세우는 날 그 줄만 채우면 켜진다.

세울 시점은 조건으로 정해뒀다. 여태 무음 실패는 전부 Sentry에 올라온 에러 하나로 어디를 볼지 좁힐 수 있었으니, 에러는 떴는데 어느 구간에서 시간을 썼는지 몰라 손을 못 대는 경우가 한 번이라도 나오면 그날 세운다.

실제로 잡아낸 실패

켜둔 것이 무엇을 잡았는지는 그 뒤에 나왔다.

워커가 부팅에 실패해 재시작을 반복하는데 배포 잡은 초록불로 끝난 적이 있다. 그 사실이 남아 있던 데는 CloudWatch뿐이었고, 로그를 열고 나서야 워커가 왜 죽는지 짚을 수 있었다. 배포 파이프라인은 그때 아무것도 안 알려줬다.

연차 원장과 잔액이 안 맞는 것을 매일 대조하는 배치는 어긋남이 나오면 reportError로 Sentry에 올린다. 이 경로가 없었으면 잔액이 틀렸다는 걸 문의가 들어와야 알았다.

둘 다 사람이 안 물어보면 아무 증상이 없는 종류다. 1편이 처음에 지목한 무음 실패가 그것이고, 잡아낸 것도 정확히 그쪽이었다. 지금 운영에서 켜져 있는 건 에러 수집이고, 추적과 메트릭은 env 한 줄이 비어 있다.