"Failed to detach context"가 쏟아지는 이유 - 제너레이터, contextvars, 그리고 지연된 정리

트레이싱을 붙인 뒤 애플리케이션 로그에 컨텍스트 detach 실패 경고가 쌓이기 시작합니다. 스택 트레이스는 계측 코드 안쪽을 가리키고, 애플리케이션 코드에는 잘못이 없어 보입니다. 트레이스 화면을 열어 보면 스팬은 대체로 정상적으로 보입니다.

그래서 "무해한 경고"로 분류하고 로그 레벨을 낮추게 됩니다. 실제로는 컨텍스트 스택이 어긋났다는 신호이고, 어긋난 스택은 엉뚱한 부모에 붙은 스팬으로 나타납니다. 눈에 잘 안 띌 뿐입니다.

이 글에서는 컨텍스트가 어떤 규칙으로 붙고 떨어지는지, 제너레이터와 비동기 태스크가 그 규칙을 어디서 깨는지, 그리고 어떻게 고쳐야 하는지 정리합니다.

1. Context는 불변이고 attach/detach는 스택이다

먼저 스펙의 정의를 봅니다.

Context is a propagation mechanism which carries execution-scoped values across API boundaries and between logically associated execution units.

A Context MUST be immutable, and its write operations MUST result in the creation of a new Context containing the original values and the specified values updated.

컨텍스트는 바꾸는 것이 아니라 새로 만드는 것입니다. 현재 스팬을 바꾼다는 말은 "현재 스팬이 다른 값인 새 컨텍스트를 만들어 붙인다"는 뜻입니다.

붙이고 떼는 연산에는 규칙이 있습니다.

Attach Context ... MUST return a value that can be used as a Token to restore the previous Context.

every call to this operation should result in a corresponding call to Detach Context.

attach는 토큰을 돌려주고, 그 토큰으로만 원래 상태로 되돌릴 수 있습니다. 짝이 맞아야 하고, 순서도 맞아야 합니다. 스펙은 detach의 목적을 이렇게 설명합니다.

Detach is intended to help making sure the correct Context is associated with the caller's current execution unit. Users can rely on it to identify a wrong call order, i.e. trying to detach a Context that is not the current instance.

detach 실패는 버그가 아니라 진단 장치입니다. "지금 붙어 있는 것이 네가 붙인 그것이 아니다"라고 알려 주는 것이고, 그 말은 그 사이에 컨텍스트가 다른 무언가로 바뀌었다는 뜻입니다.

2. Python에서는 contextvars가 그 역할을 한다

스펙은 구현을 언어에 맡깁니다. Python은 contextvars를 씁니다. ContextVar.set()이 토큰을 주고 reset(token)이 되돌립니다.

var = ContextVar('var', default='default value')

token = var.set('new value')
try:
    assert var.get() == 'new value'
finally:
    var.reset(token)

assert var.get() == 'default value'

토큰에는 제약이 둘 있습니다.

The same token cannot be used twice.

그리고 토큰은 자기가 만들어진 Context에 묶여 있습니다. 다른 Context에서 reset()을 호출하면 실패합니다. OTel의 detach가 실패하는 실제 지점이 여기입니다. 토큰 자체는 멀쩡합니다. 되돌리려는 곳이 토큰이 만들어진 곳과 다를 뿐입니다.

토큰이 무엇을 들고 있는지 보면 이해가 쉽습니다. Token.var는 대상 변수를, Token.old_value는 set() 이전 값을 가리키고, 이전에 값이 없었다면 Token.MISSING입니다. 토큰은 "이 변수를 이 값으로 되돌려라"라는 지시서인데, 그 지시가 유효한 것은 같은 Context 안에서입니다.

그렇다면 Context는 언제 달라질까요?

3. 비동기 태스크는 Context를 복사한다

문서가 명시합니다.

Each asyncio Task runs in its own copied Context

태스크를 만들면 현재 Context가 복사됩니다. 태스크 안에서 set()한 값은 바깥으로 새어 나가지 않습니다. 격리를 위한 설계이고 대부분의 상황에서 옳습니다.

문제는 토큰이 이 경계를 넘을 때입니다. 바깥에서 attach해서 받은 토큰을 태스크 안에서 detach하면, 토큰이 만들어진 Context와 현재 Context가 다르므로 실패합니다. 반대 방향도 마찬가지입니다.

# 위험한 형태 - attach와 detach가 서로 다른 실행 단위에 있다
token = context.attach(ctx)
asyncio.create_task(work())        # 여기서 Context가 복사된다
...
context.detach(token)              # 어느 Context에서 도는지 보장되지 않는다

일부러 이렇게 쓰는 사람은 없습니다. 그런데 제너레이터를 감싸면 의도하지 않게 이 모양이 됩니다.

4. 제너레이터는 본문 실행 시점이 호출 시점과 다르다

제너레이터 함수를 호출하면 본문이 실행되지 않습니다. 제너레이터 객체가 반환되고, 본문은 소비자가 값을 꺼낼 때마다 조금씩 실행됩니다.

스팬 데코레이터를 제너레이터에 붙이면 이렇게 됩니다.

@traced                      # 내부에서 attach → yield → detach
def stream_rows(query):
    with db.cursor() as cur:
        cur.execute(query)
        for row in cur:
            yield row

• attach는 첫 next() 때 실행됩니다. 그 시점의 Context는 첫 소비자의 Context입니다.
• detach는 제너레이터가 소진되거나 닫힐 때 실행됩니다. 그 시점의 Context는 마지막 소비자의 Context입니다.

둘이 같다는 보장이 없습니다. 제너레이터를 만든 곳과 소비하는 곳이 다르면(흔합니다), 소비가 여러 태스크에 걸쳐 일어나면(비동기에서 흔합니다), 두 Context는 달라집니다. 그러면 detach가 실패합니다.

핵심은 제너레이터가 실행 단위를 쪼갠다는 것입니다. 함수는 한 실행 단위 안에서 시작하고 끝나지만, 제너레이터는 여러 실행 단위에 걸쳐 조금씩 돕니다. attach/detach의 짝 맞추기는 "한 실행 단위" 전제 위에 서 있습니다.

5. 소비를 끝내지 않으면 정리 시점이 소비자 손을 떠난다

더 잡기 어려운 경우가 남아 있습니다. 소비자가 제너레이터를 다 읽지 않고 중간에 빠져나가는 경우입니다.

for row in stream_rows("SELECT ..."):
    if row.id == target:
        break            # 제너레이터가 소진되지 않은 채 참조가 끊긴다

이때 제너레이터의 finally 블록(즉 with 블록의 종료 처리)은 객체가 정리될 때 close()가 호출되면서 실행됩니다. CPython에서 다른 참조가 없는 동기 제너레이터라면 루프를 빠져나가 참조 카운트가 0이 되는 순간 정리되므로, 같은 실행 단위에서 곧바로 detach되어 문제가 없습니다. 문제는 그렇지 않은 경우입니다.

• 다른 곳이 참조를 들고 있으면 그 참조가 풀릴 때 정리됩니다. 스트리밍 응답처럼 프레임워크가 제너레이터를 붙잡고 있다가 다른 태스크에서 놓는 경우입니다.
• 참조 순환에 걸려 있으면 순환 GC가 돌 때 정리됩니다. PyPy처럼 참조 카운트를 쓰지 않는 구현도 GC 시점입니다.
• 비동기 제너레이터는 참조 카운트로 즉시 닫히지 않습니다. asyncio는 수거되는 비동기 제너레이터의 aclose()를 create_task로 예약하므로, 정리가 새로 복사된 Context에서 돕니다.

이 경우들에서는 그 시점이 언제인지, 어느 실행 단위인지 애플리케이션이 통제하지 못합니다.

결과가 이렇습니다.

• detach가 아무 관계 없는 Context에서 호출됩니다. 거의 항상 실패합니다.
• 실패 시점이 원인 코드와 멀어서 스택 트레이스가 도움이 되지 않습니다.
• 부하가 높을 때만, 혹은 특정 조기 종료 경로에서만 터져 재현이 어렵습니다.

"평소엔 괜찮은데 가끔 로그가 쏟아진다"의 정체가 이것입니다. 예외로 루프를 빠져나가는 경로가 늘어나면 빈도가 함께 올라갑니다.

6. 그래서 실제로 무엇이 망가지는가

detach가 실패하면 예외는 SDK가 잡아 로그만 남기므로 애플리케이션은 계속 돕니다. 그래서 무해해 보입니다. 망가지는 것은 두 가지입니다.

컨텍스트가 되돌아가지 않습니다. detach가 실패했다는 말은 "현재 스팬"이 원래대로 복구되지 않았다는 뜻입니다. 그 뒤에 만들어지는 스팬은 이미 끝난 스팬을 부모로 삼습니다. 트레이스 트리에 끝난 부모 밑에 시작하는 자식이 생기고, 시간축이 어긋난 것처럼 보입니다.

어긋남이 전파됩니다. 잘못된 부모를 물려받은 스팬이 다시 자식을 만들면서 한 트레이스 전체가 틀어집니다. 어떤 요청은 정상, 어떤 요청은 트리가 이상한 상태가 되고, 이 차이를 설명할 규칙이 없어 보입니다.

로그를 끄는 것은 대응이 아닙니다. 경고 자체가 유일한 단서입니다.

7. 고치는 방법

우선순위대로 넷입니다.

(A) 제너레이터를 스팬으로 감싸지 않는다. 가장 확실합니다. 스팬은 소비가 끝나는 것을 보장할 수 있는 위치, 즉 소비하는 쪽에서 엽니다.

# 제너레이터는 그대로 두고
def stream_rows(query):
    with db.cursor() as cur:
        cur.execute(query)
        yield from cur

# 소비하는 쪽에서 스팬을 연다 - 시작과 끝이 한 실행 단위에 있다
with tracer.start_as_current_span("stream_rows") as span:
    count = 0
    for row in stream_rows(query):
        count += 1
        if row.id == target:
            break
    span.set_attribute("rows.consumed", count)

부수 효과로 계측이 더 정확해집니다. "몇 개를 실제로 소비했는가"는 소비자만 아는 정보입니다.

(B) 감싸야 한다면 소비 완료를 보장한다. 소비자가 반드시 다 읽거나 명시적으로 닫도록 강제합니다. contextlib.closing이 그 역할을 합니다.

from contextlib import closing

with closing(stream_rows(query)) as rows:
    for row in rows:
        ...
        if done:
            break          # 블록을 나갈 때 close()가 즉시 호출된다

close()가 GC가 아니라 블록 종료 시점에 불리므로, detach가 attach와 같은 실행 단위에서 일어납니다. 다만 이 규칙을 모든 호출자가 지켜야 하므로, 라이브러리 경계에서는 강제하기 어렵습니다.

(C) 데코레이터가 제너레이터를 거부한다. 조용히 틀린 트레이스를 만드는 것보다 낫습니다.

import inspect

def traced(func):
    if inspect.isgeneratorfunction(func) or inspect.isasyncgenfunction(func):
        raise TypeError(
            f"{func.__qualname__}: 제너레이터는 감싸지 않는다. 소비하는 쪽에서 스팬을 열 것"
        )
    ...

계측 데코레이터를 만들 때 함께 넣어야 할 가드입니다. 자세한 설계는 OpenTelemetry 데코레이터를 직접 만들 때 무너지는 것들 (opens new window)에 정리했습니다.

(D) 컨텍스트 없이 스팬만 만든다. 부모-자식 관계를 유지하면서 현재 컨텍스트를 바꾸지 않는 방법이 있습니다. 스팬을 만들되 attach하지 않는 것입니다.

def stream_rows(query):
    span = tracer.start_span("stream_rows")     # attach 하지 않는다
    try:
        with db.cursor() as cur:
            cur.execute(query)
            for row in cur:
                yield row
    except Exception as exc:
        span.set_status(Status(StatusCode.ERROR, str(exc)))
        span.record_exception(exc)
        raise
    finally:
        span.end()

attach가 없으니 detach도 없고, 4~5절의 문제가 사라집니다. 대가는 제너레이터 본문 안에서 만들어지는 스팬이 이 스팬의 자식이 되지 않는다는 점입니다. 본문이 다른 계측된 함수를 부르지 않는 단순한 루프라면 이 방식이 잘 맞습니다.

8. 직접 확인하는 방법

먼저 detach 실패가 실제로 나는지, 어디서 나는지 봅니다. SDK가 이 실패를 로그로만 남기므로 경고를 잡아 스택을 남기게 하면 원인 코드가 드러납니다.

import logging, traceback

class DetachTracer(logging.Filter):
    def filter(self, record):
        if "detach" in record.getMessage().lower():
            traceback.print_stack()      # 실제 호출 경로를 찍는다
        return True

logging.getLogger("opentelemetry.context").addFilter(DetachTracer())   # 로거 필터는 자식 로거 이벤트에 적용되지 않는다

덜 소비된 제너레이터는 ResourceWarning을 내지 않고, finally가 있어도 순환 GC가 정상 수거하므로(PEP 442) gc.DEBUG_UNCOLLECTABLE에도 잡히지 않습니다. GC 시점에 도는 것인지 구분하려면 순환 GC가 도는 구간을 로그에 표시합니다.

import gc, logging

log = logging.getLogger("gc")
gc.callbacks.append(lambda phase, info: log.warning("gc %s gen=%s", phase, info["generation"]))

detach 경고가 gc start와 gc stop 사이에 찍히면 순환 GC 경로입니다. 찍힌 스택이 사용자 코드 없이 이벤트 루프(asyncio/events.py의 _run)에서 곧바로 제너레이터로 들어가면 비동기 제너레이터의 aclose() 태스크입니다. 둘 다 5절입니다. 정상적인 호출 경로에서 시작하면 4절입니다.

트레이스 쪽 증상은 부모-자식 시간 관계로 확인합니다.

# 자식이 부모보다 늦게 끝나거나, 부모가 이미 끝난 뒤 시작한 스팬을 찾는다
by_id = {s.context.span_id: s for s in spans}
for s in spans:
    p = by_id.get(s.parent.span_id) if s.parent else None
    if p and s.start_time > p.end_time:
        print(f"부모가 끝난 뒤 시작: {s.name} (부모 {p.name})")

이 조건에 걸리는 스팬이 있으면 컨텍스트 스택이 어긋난 것입니다. 로그 경고와 이 검사가 함께 나오면 원인이 확정됩니다.

9. 트러블슈팅

증상	원인	조치
detach 실패 경고가 간헐적으로 쏟아짐	제너레이터가 중간에 버려져 GC·다른 태스크에서 정리	closing()으로 감싸거나 스팬을 밖으로
스택 트레이스가 계측 코드만 가리킴	정리 시점이 원인 코드와 분리됨	경고 시점에 호출 스택 출력
부하가 높을 때만 발생	GC 타이밍에 의존	조기 종료 경로 점검
부모가 끝난 뒤 시작한 자식 스팬	컨텍스트가 복구되지 않음	위와 동일, 로그를 끄지 말 것
비동기 코드에서만 발생	태스크가 Context를 복사	attach/detach를 한 태스크 안에 가둠
트레이스가 요청마다 다르게 깨짐	어긋난 컨텍스트가 뒤로 전파	근본 원인 제거 후 재확인
스팬은 정상인데 경고만 남음	아직 후속 스팬이 안 생겼을 뿐	무해하지 않음, 동일하게 처리

10. 마무리

• attach가 준 토큰은 그 토큰이 만들어진 Context 안에서만 유효합니다. detach 실패는 "그 사이에 실행 단위가 바뀌었다"는 신호입니다.
• 비동기 태스크는 Context를 복사합니다. attach와 detach가 태스크 경계를 넘으면 짝이 맞지 않습니다.
• 제너레이터는 본문이 여러 실행 단위에 걸쳐 돕니다. attach는 첫 소비 때, detach는 마지막 소비 때 일어나므로 두 Context가 다를 수 있습니다.
• 소비자가 다 읽지 않은 제너레이터가 다른 곳에 참조되거나 순환에 걸리거나 비동기 제너레이터이면 정리가 GC나 별도 태스크로 밀립니다. 그때의 detach는 거의 항상 실패하고, 실패 지점이 원인에서 멀어 진단이 어렵습니다.
• 경고를 끄는 것은 대응이 아닙니다. 복구되지 않은 컨텍스트는 끝난 스팬을 부모로 삼는 자식을 만들고, 그 어긋남이 뒤로 전파됩니다.
• 가장 확실한 해법은 스팬을 소비하는 쪽에서 여는 것입니다. 시작과 끝이 한 실행 단위 안에 있으면 이 부류의 문제가 통째로 사라집니다.

참고

• OpenTelemetry - Context 스펙 (Attach/Detach) (opens new window)
• Python - contextvars (ContextVar, Token, reset) (opens new window)
• PEP 567 - Context Variables (opens new window)
• OpenTelemetry Python - opentelemetry.context API 레퍼런스 (opens new window)
• Python - contextlib.closing (opens new window)
• PEP 442 - Safe object finalization (opens new window)
• PEP 525 - Asynchronous Generators (finalization) (opens new window)