Skip to content

feat(ai): trace_context 구현 — 문서에만 있던 함수를 실제로 만든다 - #263

Merged
i3months merged 1 commit into
devfrom
feat/ai-trace-context
Sep 28, 2026
Merged

i3months merged 1 commit into
devfrom
feat/ai-trace-context

Conversation

@i3months

Copy link
Copy Markdown
Member

#262 에서 Core 추적을 고치고 "AI 서버 로그에는 아직 traceId 가 없다" 를 남은 과제로 적었다.
그런데 이유가 따로 있었다.

ai/CLAUDE.md 가 없는 함수를 패턴으로 제시하고 있었다

# messaging/consumers/resume_consumer.py (패턴)
async def consume(message: AbstractIncomingMessage) -> None:
    async with message.process(requeue=False):
        envelope = parse_envelope(message)
        if await is_processed(envelope.message_id):
            return  # 멱등
        with trace_context(envelope.trace_id):      ← 이 함수가 존재한 적이 없다
            await resume_analyzer.handle(envelope.payload)
$ grep -rn "trace_context" ai/src ai/tests | grep -v CLAUDE.md
(0건)

문서를 따라 쓰면 ImportError 가 나고, 실제 컨슈머들은 traceId 를 로그에 전혀 싣지 않았다.

오늘만 세 번째다 — infra/backup/README 의 Discord 알림(#260), Core 의 "모든 후속 처리에
동일 traceId 전파"(#262), 그리고 이것.

구현 — 추측 대신 실측 위에

structlog 기본 프로세서 체인을 먼저 확인했다:

structlog 25.5.0
기본 프로세서: ['merge_contextvars', 'add_log_level', 'StackInfoRenderer', 'set_exc_info', 'TimeStamper', …]
  {'event': 'with_ctx',    'trace_id': 'abc-123', …}
  {'event': 'without_ctx',                        …}

merge_contextvars 가 첫 번째라서, 한 번 묶으면 그 구간의 모든 로그 줄에 자동으로
실린다 — 호출부마다 인자로 넘길 필요가 없다.

적용 지점 3곳: consume_with_failure_signal(생성·분석 컨슈머 공통) + voice/tts(직접-발행 모델).

  • 비어 있으면 새로 만든다 — 없는 것보다 낫고, 적어도 그 처리 한 건은 묶인다.
  • 끝나면 반드시 되돌린다 — 워커 태스크가 재사용되면 남은 값이 다음 메시지 로그에 묻는다.

테스트 — "바인딩했다"가 아니라 "출력에 나온다"

Core 에서 겪은 함정이 정확히 그거였다: MDC 는 채우는데 로그 패턴이 참조하지 않아 운영 로그
어디에도 traceId 가 없었다. 그래서 여기서는 실제 로그 엔트리를 캡처해서 검증한다.

테스트 왜
trace_id 가 로그 엔트리에 실린다 / 빠져나오면 사라진다 바인딩이 아니라 출력을 본다
비어 있으면 생성하고 서로 다르다 없는 것보다 낫다
예외로 빠져나와도 지워진다 컨슈머는 예외를 다시 던져 DLQ 로 보낸다 — 그 경로에서도 정리돼야
동시 메시지 3건이 서로를 오염시키지 않는다 contextvars 태스크 격리. 추적이 틀린 것은 없는 것보다 나쁘다

AI 전체 422건 통과, black·flake8 clean.

배포 후 확인할 것

실제 면접이 한 번 돌면 AI 로그가 이렇게 나와야 한다:

2026-09-28 … [info     ] voice.analyze.start   trace_id=3f2a…  message_id=…

그리고 그 trace_id 로 Core 로그([3f2a…])와 같은 요청이 이어지는지 확인할 수 있다 —
#262 의 큐 전파 수정과 합쳐져야 Core→AI 상관이 처음으로 성립한다.

남은 것

uvicorn 액세스 로그(GET /health)에는 여전히 traceId 가 없다. 요청 단위 미들웨어는 미도입이고,
AI 서버는 내부 통신 전용이라 우선순위가 낮다. 문서에 남겼다.

#262 로 Core 쪽 추적을 고치고 "AI 서버 로그에는 아직 traceId 가 없다" 를 남은
과제로 적어 뒀는데, 그 이유가 따로 있었다.

ai/CLAUDE.md 는 컨슈머 패턴으로 이렇게 안내해 왔다:

    with trace_context(envelope.trace_id):
        await resume_analyzer.handle(envelope.payload)

**그런데 trace_context 가 존재한 적이 없다.** 문서를 따라 쓰면 ImportError 가
나고, 실제 컨슈머들은 traceId 를 로그에 전혀 싣지 않았다.

오늘만 세 번째다 — infra/backup/README 의 Discord 알림(#260), Core 의 "동일
traceId 전파"(#262), 그리고 이것. 문서가 주장하는 동작은 grep 으로 확인해야 한다.

## 구현

observability/trace.py. structlog 기본 프로세서 체인의 첫 번째가
merge_contextvars 인 것을 실측으로 확인하고 그 위에 올렸다:

  기본 프로세서: ['merge_contextvars', 'add_log_level', 'StackInfoRenderer',
                 'set_exc_info', 'TimeStamper', ...]

한 번 묶으면 그 구간의 **모든 로그 줄에 자동으로** 실린다 — 호출부마다 인자로
넘길 필요가 없다. 적용 지점 3곳: consume_with_failure_signal(생성·분석 컨슈머
공통) + voice/tts(직접-발행 모델).

비어 있으면 새로 만든다. 끝나면 반드시 되돌린다 — 워커 태스크가 재사용되면
남은 값이 다음 메시지 로그에 묻는다.

## 테스트

"바인딩했다"가 아니라 **"출력에 나온다"** 를 본다. Core 에서 겪은 함정이 정확히
그거였다 — MDC 는 채우는데 로그 패턴이 참조하지 않아 아무 데도 안 나왔다.

  trace_id 가 실제 로그 엔트리에 실린다 / 빠져나오면 지워진다
  비어 있으면 생성하고 서로 다르다
  예외로 빠져나와도 지워진다(컨슈머는 예외를 다시 던져 DLQ 로 보낸다)
  **동시 메시지 3건이 서로의 traceId 를 오염시키지 않는다**
    — 추적이 틀린 것은 없는 것보다 나쁘다

AI 전체 422건 통과.
@i3months
i3months merged commit ef277f1 into dev Sep 28, 2026
6 checks passed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant