결코 연결되지 않는 세 개의 로그

14:02에 주문이 실패합니다. 고객 지원 티켓에는 결제 오류를 보고한 고객, 그 후 재시도, 그리고 또 다른 오류를 겪었다는 내용이 인용되어 있습니다. 세 개의 로그 라인이 동일한 타임스탬프 범위를 가지고 있지만, 그중 어느 것도 무엇이 일어났는지 일치하지 않습니다.

결제 서비스(payment service)는 14:02:11에 payment.authorized를 기록했습니다. 주문 서비스(order service)는 14:02:11에 order.failed를 기록했습니다. 이들을 조정(reconcile)해야 했던 워커(worker)는 14:02:12에 worker.idle을 기록했습니다. 세 개의 서비스, 세 개의 로그 스트림(log streams), 세 개의 서로 다른 이야기. 그 로그 라인들 사이 어딘가에서 상태 변경(state change)이 유실되었지만, 로그의 그 무엇도 이들을 연결해주지 않기 때문에 아무도 어디서 발생했는지 말할 수 없습니다.

이것은 모든 로그 라인이 국소적으로는 참이지만 전역적으로는 무용지물인 시스템의 전형적인 증상입니다. 해결책은 상관관계 ID(correlation ID)입니다. 즉, 모든 요청과 함께 이동하고, 모든 서비스 경계를 넘나들며, 접하는 모든 로그 라인에 찍히는 하나의 불투명한 문자열(opaque string)입니다. 동기식(synchronous) 코드에서 이것은 헤더(header)나 미들웨어(middleware)로 해결되는 이미 풀린 문제입니다. 비동기(async) Python에서 흥미로운 점은, 당신이 가장 먼저 떠올리는 메커니즘이 조용히 잘못되어 있으며, 실제로 작동하는 것은 대부분의 사람들이 한 번도 임포트(import)해 본 적 없는 표준 라이브러리(standard library)의 구석에 숨겨져 있다는 것입니다.

왜 스레드 로컬 상태(Thread-Local State)가 비동기 코드에서 깨지는가

본능적인 선택은 threading.local()입니다. 하나의 스레드, 하나의 요청, 하나의 컨텍스트(context) — 이것이 스레드 로컬 저장소(thread-local storage)를 대중화시킨 정신적 모델(mental model)이며, 바로 이 모델이 비동기 코드가 위반하는 모델입니다.

asyncio 이벤트 루프(event loop)는 하나의 스레드에서 수천 개의 태스크(tasks)를 실행합니다. 애플리케이션이 요청 A를 처리하는 것에서 요청 B를 처리하는 것으로 전환될 때 스레드는 바뀌지 않으며, 태스크가 바뀝니다. threading.local()은 스레드 식별자(thread identity)를 기준으로 저장소를 키(key)로 삼기 때문에, 동일한 스레드에 있는 모든 태스크는 동일한 슬롯(slot)을 읽고 씁니다. 요청 A가 request_id = "a1"을 설정하고 I/O를 기다리는(await) 동안, 요청 B가 request_id = "b2"를 설정합니다. A가 재개되어 다음 로그 라인을 기록할 때, 필터는 request_id를 읽고 해당 라인에 "b2"를 찍게 됩니다.

import threading

local = threading.local()
...

결과는 ID가 누락되는 것이 아닙니다. 그보다 더 나쁩니다. 바로 잘못된 ID가 찍히는 것입니다. 로그 라인에 이웃한 요청의 ID가 찍히게 되며, 당신이 재구성하려는 타임라인은 적극적으로 오해를 불러일으키게 됩니다. 이것은 "국소적으로는 참이지만, 전역적으로는 무용지물인 (locally true, globally useless)" 실패의 가장 순수한 형태이며, 이것이 바로 비동기 (async) 코드에 대한 표준 권장 사항이 런타임이 당신의 발밑에서 교체할 수 있는 장소에 컨텍스트 (context)를 저장하는 것을 중단하라는 이유입니다.

Contextvars: 태스크와 함께 이동하는 상태

contextvars는 바로 이 문제를 해결하기 위해 존재합니다. 컨텍스트 변수 (context variable)는 실행 컨텍스트 (execution context)당 하나의 값을 보유하며, asyncio 태스크 (task)는 자신만의 컨텍스트를 지닙니다. 루프 (loop)가 하나의 태스크를 중단하고 다른 태스크를 재개할 때, 각 태스크는 공유 슬롯이나 간섭 없이 모든 컨텍스트 변수의 자신만의 복사본을 보게 됩니다.

import contextvars

request_id: contextvars.ContextVar[str] = contextvars.ContextVar("request_id", default="")
...

두 가지 속성이 이를 안전하게 만듭니다. 첫째, 태스크 내부에서의 할당은 해당 태스크와 그 태스크가 await 하는 대상에게만 보이며, 형제 태스크 (sibling tasks)들은 이를 절대 관찰할 수 없습니다. 둘째, 태스크가 종료되면 해당 컨텍스트는 폐기되므로 다음 요청으로 유출되지 않습니다. 값은 스레드 (thread)가 아니라 논리적인 작업 단위 (logical unit of work)를 따라 이동하며, 이것이 바로 상관관계 ID (correlation ID)가 필요로 하는 의미론 (semantics)입니다.

언급할 만한 비용이 있습니다. contextvars는 공짜가 아닙니다. 컨텍스트 변수를 설정하고 읽는 것은 현재 컨텍스트에서의 딕셔너리 조회 (dictionary lookups)를 수반하며, 모든 await는 컨텍스트 장부 기록 (context bookkeeping)을 트리거할 수 있습니다. 로깅 핫 패스 (logging hot path)에서는 이미 수행 중인 I/O에 비해 비용이 무시할 만한 수준이지만, 만약 타이트한 수치 루프 (tight numerical loop) 내부에서 컨텍스트 변수를 사용할 계획이라면 먼저 측정해 보십시오.

30줄로 구현하는 상관관계 ID 미들웨어

미들웨어는 세 가지 작업을 수행합니다. 상위 단계에서 ID가 존재하면 이를 수락하고, 존재하지 않으면 새로운 ID를 생성하며, 호출자가 자신의 로그에 붙일 수 있도록 응답에 해당 ID를 담아 반환하는 것입니다. contextvars를 사용하면 구현이 매우 짧아 한 번에 읽을 수 있을 정도입니다.

동일한 형태가 aiohttp 미들웨어, FastAPI 의존성(dependencies), 그리고 순수 asyncio 서버 핸들러에도 적용됩니다. 중요한 점은 프레임워크 훅(hook)이 아니라, ID가 request_id_var에 존재한다는 것입니다. 따라서 이 요청 내에서 await를 수행하는 모든 하위 함수는 수많은 호출 지점(call sites)을 거치며 매개변수를 전달할 필요 없이 ID를 읽을 수 있습니다.

이는 보기보다 훨씬 중요합니다. 대안인 — 로그를 남기는 모든 함수에 ID를 명시적인 인자로 전달하는 방식 — 방식은 모든 함수 시그니처(signature)를 단순한 배관 작업(plumbing)을 위한 운반체로 만들어 버립니다. 데이터 클래스(dataclass)에 필드를 추가하거나, 헬퍼 함수에 매개변수를 추가하거나, 서드파티 콜백(callback)에 인자를 추가하는 모든 행위가 파괴적 변경(breaking changes)이 됩니다. 컨텍스트 변수(context variable)는 데이터 흐름을 암시적(implicit)으로 유지하며, 호출 지점은 정직하게 유지됩니다. 즉, 컨텍스트가 이미 존재하기 때문에 함수는 필요한 것만 로그로 남기면 됩니다.

컨텍스트 복사 함정: 스레드와 실행기 (Threads and Executors)

대부분의 구현이 빠지는 함정은 바로 이곳입니다: asyncio.create_task()는 현재 컨텍스트를 복사하지만, 스레드 풀 실행기(thread pool executor)로 전달된 작업은 이를 상속받지 않습니다.

loop.run_in_executor(None, blocking_call)를 호출하는 태스크는 blocking_call을 워커 스레드(worker thread)로 넘깁니다. 해당 스레드는 기본 컨텍스트(default context)로 실행되며, 이 컨텍스트에서 request_id는 여전히 비어 있는 기본값입니다. 상관관계 ID(correlation ID)는 정작 가장 필요한 경계 지점 — 실제 몇 초가 걸리며 실제 실패를 로그로 남기는 느리고 차단적인(blocking) 호출 — 에서 소리 없이 사라져 버립니다.

import asyncio
import contextvars

...

해결책은 컨텍스트를 명시적으로 전파(propagate)하는 것입니다. Python 3.11에는 호출자의 컨텍스트를 디스패치(dispatching)하기 전에 복사하는 asyncio.to_thread()가 추가되었습니다. 이는 ID가 경계를 넘어 생존할 수 있게 해주는 한 줄짜리 대체 코드입니다:

async def handle(rid: str) -> None:
    request_id.set(rid)
    await asyncio.to_thread(blocking_call)  # 컨텍스트가 자동으로 복사됩니다

반드시 run_in_executor를 유지해야 하는 코드의 경우, 컨텍스트를 수동으로 복사하고 그 안에서 호출 가능한 객체(callable)를 실행해야 합니다:

cx = contextvars.copy_context()
await loop.run_in_executor(None, lambda: cx.run(blocking_call))

한 가지 규칙을 정해 모든 곳에 적용하세요: asyncio.to_thread를 우선적으로 사용하고, 남아 있는 모든 run_in_executor 호출에 대해 명시적인 ctx.run이 있는지 감사(audit)해야 합니다. 첫 번째 스레드 풀(thread pool)에서 사라져 버리는 상관관계 ID (Correlation ID)는 아예 없는 것보다 더 나쁩니다. 왜냐하면 로그는 완벽해 보이지만, 실제로 중요한 타임라인의 섹션이 소리 없이 누락되기 때문입니다.

모든 라인이 ID를 포함하도록 하는 로깅 필터 (Logging Filter)

미들웨어(middleware)가 변수를 설정하지만, 로그는 여전히 이를 읽어야 합니다. Python의 logging.Filter는 레코드가 출력되기 전에 모든 레코드에 대해 실행되므로, 스탬프를 찍기에 가장 자연스러운 장소입니다:

import logging

class RequestIDFilter(logging.Filter):
...

애플리케이션 코드, 라이브러리 로거(logger), 경고 경로(warning paths)에 이르기까지 모든 라인이 이제 ID를 포함하게 됩니다. 필터는 레코드를 누가 생성했는지 상관하지 않기 때문입니다. 루트 핸들러(root handler)에 부착된 하나의 필터가 당신이 작성한 코드와 작성하지 않은 코드를 모두 아우릅니다.

이것이 바로 세 개의 로그를 다시 연결해 주는 속성입니다. 결제 라인, 주문 라인, 워커(worker) 라인이 모두 동일한 X-Request-ID 값을 가지게 되며, 고객 지원 티켓은 하나의 검색 대상이 됩니다. 집계된 스트림을 해당 문자열 하나로 필터링하면 실패한 주문의 전체 타임라인이 연속적으로 나타납니다. 상관관계 ID (Correlation ID)가 로그를 진실되게 만드는 것은 아닙니다. 로그를 진실에 따라 정렬할 수 있게 만들어 줄 뿐입니다.

타임라인이 복구되었는지 검증하기

교차 통신(cross-talk) 회귀 테스트가 실제로 수행되기 전까지는 구현이 완료된 것이 아닙니다. 두 가지 테스트가 중요한 실패 모드(failure modes)를 다룹니다: 동시 작업(concurrent tasks)은 ID를 공유해서는 안 되며, 실행기(executor) 작업은 ID를 상속받아야 합니다.

import asyncio
import contextvars

...

비동기 테스트를 실행하는 CI 작업에서 이를 실행하세요. 만약 둘 중 하나라도 실패한다면, 해결책은 위에서 언급한 두 가지 패턴 중 하나여야 합니다. 새로운 설정 플래그(configuration flag)나 전역 변수(global variable)가 아닙니다.

Contextvars만으로는 충분하지 않을 때

컨텍스트 변수(context variable)는 하나의 프로세스 내에서 ID를 전달합니다. 요청이 네트워크 경계(network boundary)를 넘는 순간, ID는 와이어 프로토콜(wire protocol)에 실려야 합니다. 예를 들어 HTTP의 X-Request-ID 헤더, OpenTelemetry를 위한 traceparent 헤더, 또는 큐(queue)의 message_id 필드와 같은 방식입니다. 미들웨어(middleware)는 이미 헤더를 앞으로 전파하고 있습니다. 따라서 상류(upstream)로부터 동일한 헤더를 읽어 아웃바운드 호출(outbound calls)에 부착해야 하며, 그래야만 세 개의 서비스가 연결된 체인이 각각의 로컬 고유 ID 세 개를 생성하는 대신, 검색 가능한 하나의 ID를 생성하게 됩니다.

이미 OpenTelemetry를 실행 중인 시스템의 경우, 상관관계 ID(correlation ID)를 새로 만드는 대신 트레이스 컨텍스트(trace context)를 기반으로 사용하는 것이 실용적인 선택입니다. 즉, traceparent를 읽고, 트레이스 ID(trace ID)를 컨텍스트 변수에 저장한 뒤, 필터(filter)가 이를 기록하도록 하는 것입니다. 패턴은 변하지 않으며, 문자열의 출처만 바뀔 뿐입니다.

그리고 한 가지 솔직한 한계가 있습니다: contextvars가 충돌(crash)한 프로세스의 로그를 마법처럼 나타나게 해주지는 않습니다. 이는 이미 작성된 로그 라인들 사이의 간극을 메워줄 뿐입니다. 프로세스가 플러시(flush) 도중에 종료되어 아예 작성되지 못한 로그 라인을 부활시킬 수는 없습니다. 이를 위해서는 여전히 내구성이 있고 버퍼링된 전송(durable, buffered shipping) 방식이 필요합니다. 하지만 모든 서비스가 무언가를 기록했지만 아무도 점들을 연결할 수 없었던 일반적인 장애 상황에서, 상관관계 ID는 타임라인(timeline)과 타임스탬프 더미(pile of timestamps)를 가르는 결정적인 차이를 만듭니다.

원문은 Dispatch에 처음 게시되었습니다.