← posts/b.log()

blog92@web:~$ cat posts/backend-antipatterns-15-unobservable-system.md

BACKEND10 min read

관측 불가능한 시스템 — 로그만 있는 분산 시스템

로그만 있는 분산 시스템에서 장애 원인을 못 찾는 이유. 로그·메트릭·트레이스의 역할 분담, Correlation ID, 카디널리티 폭발, 알림 피로.

장애는 끝났는데 원인을 아무도 모른다

결제 실패율이 14분간 3%까지 올랐다가 저절로 돌아왔다. 배포는 없었다. 포스트모템 회의의 대화는 이렇게 흘러간다.

"주문 서비스 로그에 타임아웃이 찍혔어요." "재고 쪽은요?" "그 시간대 로그가 4만 줄인데 어느 게 그 요청인지 모르겠어요." "실패한 요청 ID 하나만 주세요." "요청 ID를 안 남깁니다."

대시보드에는 그래프가 열 개쯤 있다. CPU, 메모리, 초당 요청 수, 평균 응답시간. 전부 정상 범위다. 로그도 서비스마다 있고, 형식은 서비스마다 다르다.

ts
// 서비스 A
console.log(`order created: ${orderId}`)
// 서비스 B
logger.info("stock reserved", { sku, qty })
// 서비스 C
console.error("[PAYMENT] fail - " + err.message)

데이터가 없는 게 아니다. 데이터는 많은데 질문에 답할 수 없는 상태다. 관측 가능성이 없다는 건 이 상태를 말한다.

로그 파일 하나로 충분했던 시절의 습관

모놀리식에서는 이 습관이 합리적이었다. 프로세스가 하나이므로 로그 파일도 하나다. 예외가 나면 스택 트레이스에 호출 경로 전체가 들어 있고, grep으로 시간대를 좁히면 그 요청이 남긴 줄들이 시간순으로 붙어 있다. 상관관계 ID가 필요 없었던 이유는 프로세스와 파일이 이미 상관관계를 보장했기 때문이다. 디버깅은 사실상 로그를 읽는 일이었고, 로깅 라이브러리를 잘 쓰는 것이 관측의 전부였다.

그 맥락이 무너진 지점은 세 군데다. 프로세스가 여러 개가 되면서 파일도 여러 개가 됐다. 오토스케일링으로 파일 수가 가변이 됐다. 호출이 네트워크를 건너면서 스택 트레이스가 경계에서 끊겼다. 그런데 해법은 그대로 남았다.

로그만 남기는 관행은 맥락이 사라진 뒤에도 남아 있는 해법의 교과서적 사례다(1편). 도구가 나빠서가 아니라, 그 도구가 보장하던 전제가 사라졌기 때문에 안티패턴이 된다.

세 기둥은 대체재가 아니라 역할 분담이다

로그·메트릭·트레이스를 "관측 도구 세 종류"로 묶으면 "우리는 로그 쓰니까 됐다"가 된다. 셋은 답하는 질문이 다르다.

답하는 질문형태못 하는 것
로그무슨 일이 있었나개별 사건의 상세집계·추세. 양이 많아지면 비싸다
메트릭얼마나 나쁜가집계된 시계열개별 요청을 못 본다
트레이스어디서 느려졌나요청 하나의 경로전체 추세, 개별 사건의 상세

셋 중 하나만으로는 답이 안 나오는 질문을 각각 들면 이렇다.

"에러율이 지금 오르고 있나?" — 초당 수천 줄을 실시간 집계하는 비용은 같은 값을 카운터로 올리는 비용보다 몇 자릿수 크다. 메트릭의 자리다.

"이 요청이 왜 3초 걸렸나?" — 메트릭은 이미 집계된 값이라 개별 요청으로 되돌아갈 수 없다. 트레이스의 자리다.

"왜 하필 이 주문만 결제가 거절됐나?" — 트레이스는 어느 구간이 느렸는지만 보여주고 거절 사유 코드와 카드사 응답 본문은 담지 않는다. 로그의 자리다.

Correlation ID 없는 로그가 무가치한 이유는 산수다

서비스 10개가 각각 초당 100줄의 로그를 낸다고 하자. 1분이면 10 × 100 × 60 = 60,000줄이다. 실패한 요청 하나가 남긴 흔적은 서비스를 여러 개 지났어도 15줄 남짓, 비율로는 15 ÷ 60,000 = 0.025%다.

문제는 비율이 아니라 선별 수단이 없다는 것이다. 같은 밀리초에 다른 요청 수십 개의 로그가 섞여 있어 타임스탬프로는 좁힐 수 없다. 사용자 ID로 좁혀도 그 사용자의 다른 요청이 함께 나온다. 서비스 경계를 넘으면 연결고리가 아예 끊긴다.

상관관계 ID는 관측 가능성의 고급 기능이 아니라 최소 요건이다. 이게 없으면 로그의 양을 늘려도 검색 가능성은 오르지 않는다.

평균 대시보드가 숨기는 것

평균 응답시간 200ms인 시스템에서 p99가 5초인 것은 모순이 아니다. 상위 1%가 5초여도 평균에 미치는 기여는 5,000 × 0.01 = 50ms뿐이고, 나머지 99%가 150ms면 전체 평균은 200ms다. 평균은 최악을 희석하도록 설계된 통계량이다.

그 5초를 겪는 사람이 전체의 1%인 것도 아니다. 화면 하나가 API를 20번 호출하면 최소 하나가 p99 구간에 걸릴 확률은 1 − 0.99²⁰ = 18.2%다. 요청의 1%가 느린 시스템에서 사용자의 18%가 느린 화면을 본다. 7편의 꼬리 지연 계산이 그대로 적용된다.

여기에 흔한 실수가 하나 더 붙는다. 백분위수는 평균 낼 수 없다. 인스턴스 10대의 p99를 모아 평균 내는 대시보드가 드물지 않은데, 그 값은 어떤 분포의 백분위수도 아니다. 9대의 p99가 50ms이고 1대가 고장 나 2,000ms라면 평균은 (9 × 50 + 2,000) ÷ 10 = 245ms로 보고된다. 그래프는 살짝 올라간 것처럼 보이지만, 실제로는 트래픽의 10%가 고장 난 인스턴스로 가고 있고 그 10%는 전역 p90 근처까지 망가져 있다. 백분위수를 집계하려면 각 인스턴스가 값이 아니라 히스토그램 버킷을 내보내고, 집계 시점에 버킷을 합산해 다시 계산해야 한다.

카디널리티 폭발: 레이블 하나가 시계열 100만 개를 만든다

메트릭이 싼 이유는 집계돼 있기 때문이고, 그 전제를 깨는 게 고카디널리티 레이블이다. 시계열의 수는 레이블 값 조합의 곱으로 늘어난다.

레이블 3개에 각각 값이 100가지면 100 × 100 × 100 = 1,000,000 시계열이다. 여기에 user_id를 넣으면 사용자 수만큼, 요청 URL을 경로 파라미터까지 포함해 넣으면 주문 수만큼 곱해진다. 증가가 아니라 폭발이다.

시계열 하나마다 인덱스와 최근 샘플 버퍼로 수 KB를 잡으면 100만 계열은 GB 단위 메모리다. 집계 쿼리가 스캔할 계열 수가 곧 비용이므로 쿼리 성능도 같이 무너진다. 구분 기준은 단순하다.

높은 카디널리티는 로그와 트레이스의 영역이고, 메트릭의 영역이 아니다. 메트릭 레이블에는 값의 가짓수가 유한하고 예측 가능한 것만 넣는다(HTTP 메서드, 상태 코드 클래스, 라우트 패턴).

/orders/:id는 라우트 패턴이라 레이블로 써도 되고 /orders/9f3a는 안 된다. 특정 주문을 추적하고 싶다면 그건 트레이스나 로그로 가야 할 질문이다.

알림 피로와 거짓말하는 헬스체크

알림이 주당 100건 오는데 사람이 할 수 있는 행동이 있는 건 5건이라면 신호 대 잡음비는 5%다. 이 상태가 몇 주 지속되면 팀은 알림을 무시하도록 학습된다. 95%를 무시하는 게 합리적이기 때문이고, 나머지 5%가 그 안에 묻힌다. 알림의 자격 조건은 하나다. 사람이 지금 할 수 있는 행동이 있는가. 없으면 알림이 아니라 대시보드 항목이다.

헬스체크는 더 직접적으로 장애를 만든다. liveness와 readiness가 답하는 질문이 다르다.

답하는 질문실패 시 동작넣어도 되는 것
liveness이 프로세스를 재시작해야 하나컨테이너 재시작프로세스 자체의 생존
readiness지금 트래픽을 보내도 되나로드밸런서에서 제외의존성 상태, 워밍업 여부

liveness 엔드포인트에 DB 연결 확인을 넣는 것이 흔한 실수다. DB가 3초 흔들리면 모든 인스턴스가 동시에 liveness에 실패하고, 오케스트레이터는 정상으로 돌던 인스턴스 20대를 전부 재시작시킨다. DB가 곧 회복돼도 이번에는 20대가 동시에 콜드 스타트하며 커넥션을 한꺼번에 재수립한다. 12편의 Thundering Herd다. DB 장애 3초가 애플리케이션 장애 수 분으로 증폭되고, 그 증폭을 만든 건 헬스체크다. 같은 확인을 readiness에 두면 트래픽만 잠시 빠졌다 돌아온다.

탈출 경로와 그 대가

구조화 로그부터 바꾼다. 문자열 연결을 JSON 필드로 바꾸는 것만으로 검색 가능성이 달라진다. 그 위에 상관관계 ID를 실어야 하는데, 흔한 Before는 requestId를 인자로 끌고 다니는 것이다.

ts
// services/order.ts — Before: 시그니처마다 requestId가 붙는다
export async function createOrder(cmd: CreateOrderCommand, requestId: string) {
  logger.info({ requestId }, "order.create.start")
  await stockClient.reserve(cmd.items, requestId)     // 호출마다 전달
  await paymentClient.charge(cmd.payment, requestId)
}

이 방식은 두 군데서 샌다. 하나라도 전달을 빠뜨리면 그 줄만 추적 불가가 되고, ORM이나 HTTP 클라이언트가 내부에서 찍는 로그에는 애초에 넣을 수 없다. AsyncLocalStorage는 비동기 호출 체인을 따라 컨텍스트를 자동 전파하는 런타임 기능이다.

ts
// lib/request-context.ts
import { AsyncLocalStorage } from "node:async_hooks"
import { randomUUID } from "node:crypto"
 
type RequestContext = { correlationId: string; userId?: string }
const als = new AsyncLocalStorage<RequestContext>()
 
export const currentContext = () => als.getStore()
 
// 들어온 헤더를 이어받고, 없으면 여기가 추적의 시작점이 된다
export function requestContext() {
  return (req: Request, res: Response, next: NextFunction) => {
    const correlationId = req.header("x-correlation-id") ?? randomUUID()
    res.setHeader("x-correlation-id", correlationId)
    als.run({ correlationId, userId: req.user?.id }, next)
  }
}
ts
// lib/logger.ts — 로거가 컨텍스트를 스스로 읽는다
import pino from "pino"
 
export const logger = pino({
  mixin: () => {
    const ctx = currentContext()
    return ctx ? { correlationId: ctx.correlationId, userId: ctx.userId } : {}
  },
})
 
// services/order.ts — After: 시그니처에서 requestId가 사라졌는데 모든 줄에 실린다
export async function createOrder(cmd: CreateOrderCommand) {
  logger.info({ itemCount: cmd.items.length }, "order.create.start")
  await stockClient.reserve(cmd.items)   // 클라이언트가 내부에서 헤더를 붙인다
  await paymentClient.charge(cmd.payment)
}

핵심은 mixin이다. 호출부가 아무것도 하지 않아도 모든 로그 줄에 correlationId가 붙는다. HTTP 클라이언트에도 같은 컨텍스트를 읽어 헤더를 붙이는 인터셉터를 달아두면 서비스 경계를 넘어서도 ID가 이어진다.

OpenTelemetry는 최소 범위로 도입한다. 전면 계측을 목표로 잡으면 도입 자체가 분기 프로젝트가 된다. 먼저 할 것은 추적 컨텍스트 전파(traceparent 헤더)와 서비스 경계의 스팬 생성뿐이다. 이것만으로 "어느 서비스에서 시간이 갔는가"에 답할 수 있다.

샘플링은 선택이 아니다. 초당 1,000 요청, 요청당 스팬 10개, 스팬당 1KB면 하루에 1,000 × 10 × 86,400 = 8억 6,400만 스팬, 864GB다. 전량 수집은 감당되지 않는다. 실용적 기준은 오류와 느린 요청 100%, 정상 요청은 확률 샘플링(예: 1%)이다. 정상 트래픽 저장량이 1/100로 줄면서 진단 표본은 남는다.

알림은 증상 기반으로 바꾼다. "CPU 80% 초과"는 원인 기반이라 사용자가 멀쩡하면 행동할 게 없다. "결제 성공률이 5분간 99% 미만"은 증상 기반이고 SLO에 직접 연결된다. 원인 지표는 알림이 아니라 알림을 받은 뒤 보는 대시보드에 둔다.

대가는 분명하다. 관측 데이터 저장 비용은 트래픽에 비례하므로 트래픽이 10배면 관측 비용도 10배다. 스팬 시작·종료·속성 설정이 비즈니스 로직 사이에 끼면 도메인 코드가 읽기 어려워지고, 이를 피하려 자동 계측을 쓰면 마법이 늘어 디버깅이 어려워진다. OpenTelemetry 전면 도입은 그 자체로 몇 스프린트짜리 프로젝트다.

판단 기준 — 로그만으로 충분한 경우

서비스가 하나이고 트래픽이 적을 때. 인스턴스 2대짜리 단일 서비스라면 구조화 로그와 기본 메트릭(요청 수, 에러율, 응답시간 히스토그램)으로 대부분 답할 수 있다. "어느 서비스에서 느려졌나"라는 질문 자체가 성립하지 않는다.

분산 추적의 손익분기는 대략 서비스 3개다. 2개면 양쪽 로그의 타임스탬프 대조로 버틴다. 3개면 대조할 쌍이 3개, 4개면 6개로 늘어 사람이 따라가지 못한다. 반대로 상관관계 ID는 서비스가 2개가 되는 순간부터 필요하다. 도입 비용이 미들웨어 하나라 손익분기가 거의 0이다.

개인 프로젝트와 내부 도구. 사용자가 본인뿐이면 관측 도구 운영 비용이 장애 비용을 넘는다. 관측 투자는 장애 비용에 비례해야 한다.

요약

항목내용
증상장애는 났는데 원인을 모르고, 로그를 뒤져도 요청 하나를 못 따라간다
초기 매력모놀리식에서는 프로세스와 파일이 상관관계를 보장했다. 그 습관이 남았다
수치서비스 10개 × 100줄/초 × 60초 = 60,000줄. 요청 하나의 흔적 15줄 = 0.025%
평균의 함정평균 200ms와 p99 5초는 공존한다. API 20회 호출 화면은 1 − 0.99²⁰ = 18.2%
카디널리티레이블 3개 × 각 100값 = 1,000,000 시계열. 고카디널리티는 로그·트레이스의 몫
헬스체크liveness에 DB 확인을 넣으면 DB 3초 장애가 전 인스턴스 재시작이 된다
탈출구조화 로그 + AsyncLocalStorage 상관관계 ID, 최소 OTel, 샘플링, SLO 기반 알림
대가저장 비용은 트래픽 비례, 계측은 도메인 코드를 오염시키며, 도입이 곧 프로젝트다

다음 편 — 16편. 왜 같은 실수가 반복되는가 — 안티패턴의 생산 메커니즘

4막까지 열네 개의 안티패턴을 시대 순으로 지나왔다. 마지막 편은 개별 패턴이 아니라 그것들을 만들어낸 공통 기전을 다룬다. 왜 각 시대의 해법은 예외 없이 다음 시대의 문제가 되는가. Conway's Law, Golden Hammer, 조직의 인센티브가 코드 구조로 번역되는 경로를 정리하면서 시리즈를 닫는다.

COMMENTS (…)

댓글을 불러오는 중이에요.

NEW COMMENT0 / 1000
⌘↵ 전송

blog92@web:~$ cd ..