Molayo

© 2026 Molayo

Dev.to헤드라인2026. 06. 25. 02:53

Claude CLI는 stderr가 아닌 stdout으로 에러를 기록합니다

요약

Claude CLI 사용 중 에러 메시지가 stderr가 아닌 stdout으로 출력되어 발생하는 디버깅 문제를 다룹니다. 서브프로세스 래퍼를 통해 자동화 봇을 운영할 때 발생할 수 있는 로그 누락 사례와 해결 방법을 설명합니다.

핵심 포인트

  • Claude CLI는 에러 메시지를 stderr가 아닌 stdout으로 출력함
  • subprocess.run 사용 시 에러 스트림 설정 주의 필요
  • 자동화 봇 운영 시 로그 파일 크기 모니터링의 중요성
  • 표준적인 에러 처리 관습이 특정 도구에서는 작동하지 않을 수 있음

제 인게이지먼트 봇(engagement bot)이 3일 동안 매일 아침 작동을 멈췄지만, 로그에는 아무런 정보도 남지 않았습니다. Claude CLI를 14번 호출했고, 14번 모두 rc=1이 발생했으며, 에러 메시지가 있어야 할 자리에는 14번 모두 빈 문자열만 있었습니다. 오전 08:06이 되었을 때, 봇은 부분적인 사이클을 실행한 뒤 일반적인 검색 쿼리로 회귀했고, 0글자의 지식 베이스(knowledge-base) 인덱스를 구축한 뒤, 단 하나의 답글도 게시하지 못한 채 조용히 종료되었습니다. 트레이스백(traceback)도 없었습니다. stderr 출력도 없었습니다. 그저 rc=1과 침묵뿐이었습니다.

로그-닥터(log-doctor) 에이전트가 로그 파일 크기를 감시하다가 일일 파일 크기가 의심스러울 정도로 작으면 티켓을 생성하기 때문에 이 문제를 인지할 수 있었습니다. 정상적인 아침에는 봇이 몇 천 줄의 로그를 작성합니다: 탐색(discovery), 점수 산정(scoring), 초안 작성(drafting), 게시(posting), 그리고 사이클 사이의 Waiting 14 min 하트비트(heartbeat) 로그 등 말입니다. 문제가 발생한 세 번의 아침 동안, 일일 로그는 claude CLI failed (rc=1): 뒤에 아무것도 붙지 않은 채 100줄 정도만 기록되어 있었습니다. 로그-닥터가 보드에 티켓을 올린 후에야 저는 조사를 시작했습니다.

당연한 것들을 먼저 확인했습니다. claude --version은 작동했습니다. claude auth status는 정상(green)이었습니다. which claude는 올바른 경로를 반환했습니다. ANTHROPIC_API_KEY 환경 변수도 설정되어 있었습니다. 같은 날 오후 15:14에 제가 수동으로 실행했을 때 봇은 잘 작동했습니다: KB 인덱스는 4865자로 구축되었고, 팩트 체크(fact-checking) 파이프라인은 정상이었으며, 3개의 답글이 게시되었습니다. 아침 실행을 방해했던 원인이 무엇이든, 제가 찾을 수 있는 흔적은 남기지 않았습니다.

정답은 서브프로세스(subprocess) 래퍼(wrapper)에 대한 한 줄의 수정이었습니다. Claude CLI는 구조화된 에러 출력을 stderr가 아닌 stdout에 기록합니다. 제 코드가 잘못된 스트림(stream)을 로깅하고 있었던 것입니다.

봇이 하는 일

저는 Claude CLI를 래핑(wrap)한 인게이지먼트 봇을 실행합니다. 세 가지 작업이 수행됩니다: 몇 가지 주제별 테마에 대한 검색 쿼리 생성, 찾은 내용을 작은 지식 베이스(knowledge base)에 인덱싱, 해당 지식 베이스에 근거한 답글 초안 작성. Claude 호출은 agent/claude_cli.py를 통해 이루어지며, 이는 다음과 같이 셸(shell)을 호출하는 얇은 subprocess.run 심(shim)입니다:

claude -p "$PROMPT" --output-format json --model sonnet --tools "" --no-session-persistence

이것은 JSON 응답을 파싱하여 result 필드를 반환합니다. 이것이 전체 래퍼(wrapper)입니다.

이 래퍼는 모든 Python subprocess 튜토리얼이 실패를 처리하는 방식대로 실패를 처리합니다:

try:
    result = subprocess.run(cmd, capture_output=True, text=True, timeout=120, ...)
except subprocess.TimeoutExpired:
...

FileNotFoundError와 TimeoutExpired를 포착하고, returncode를 확인하며, 0이 아닌 종료 코드일 경우 stderr에 기록합니다. 이 관습은 제 근육 기억 속에 너무 깊이 박혀 있어서 지난 15년간 같은 방식으로 작성해 왔습니다. stdout은 답변을 위한 것이고, stderr는 진단(diagnostics)을 위한 것입니다. 이 계약을 위반하는 모든 Unix 도구는 고장난 것입니다.

하지만 Claude CLI는 그것을 위반하기보다는 재협상합니다. --output-format json을 사용하면 전체 전송 과정이 stdout의 JSON 형태가 됩니다. 성공과 실패 모두 그렇습니다. 200 상태 코드에서는 {"type": "result", "is_error": false, "result": "...모델의 텍스트..."}를 얻게 됩니다. 429 상태 코드에서는 {"type": "result", "is_error": true, "api_error_status": 429, "result": "Rate limit hit"}를 얻습니다. 프로세스는 1로 종료되지만, 진단 세부 정보는 답변이 있어야 할 곳 옆의 stdout에 남아 있습니다. stderr는 비어 있게 됩니다. 제 코드는 실패 시 stdout을 읽지 않았기 때문에 429 오류를 볼 수 없었습니다.

아무것도 알려주지 않은 로그

이것이 6월 22일 아침 bot-2026-06-22.log에 기록된 내용입니다:

08:02:42 agent.claude_cli WARNING claude CLI failed (rc=1):
08:02:42 agent.knowledge_base INFO KB index built: 0 chars
08:03:24 agent.claude_cli WARNING claude CLI failed (rc=1):
...

rc=1): 뒤의 빈 문자열에 주목하세요. 그것은 result.stderr를 보간(interpolate)한 저의 경고 형식인 `

INFO KB index built: 0 chars라는 라인이 결정적인 단서입니다. 봇은 충돌(crash)하지 않았습니다. 아무것도 없는 상태에서 빈 지식 베이스 (knowledge base)를 구축했고, 빈 입력값으로 나머지 루프를 완료한 뒤, 평소의 Waiting X min 하트비트 (heartbeat)를 기록하지 않고 종료되었습니다. 침묵의 성능 저하 (Silent degradation). 최악의 유형입니다.

잘못된 가설들

저는 인정하고 싶지 않을 만큼 많은 시간을 표준적인 서브프로세스 (subprocess) 실패 모드들을 추적하는 데 소비했습니다:

  1. 인증 (Auth). claude auth status를 다시 실행했습니다. 토큰은 유효했고, 스코프 (scope)도 정확했습니다. 봇의 사용자는 대화형으로 실행하는 사용자와 동일했습니다. 괴리 (drift)는 없었습니다.
  2. PATH. 서비스 유닛 (service-unit)의 PATH와 제 셸 (shell)의 PATH를 비교했습니다. 동일했습니다.
  3. 환경 변수 (Env vars). ANTHROPIC_API_KEY는 두 컨텍스트 모두에 설정되어 있었습니다. Claude CLI는 claude auth가 설정되었을 때 실제로 해당 변수를 사용하지 않지만, 흔한 레드 헤링 (red herring, 혼란을 주는 정보)이기에 확인해 보았습니다.
  4. 타임아웃 (Timeout). 래퍼 (wrapper)에는 120초의 타임아웃이 설정되어 있습니다. 실패는 느리게 일어난 것이 아니라 즉각적이었습니다. TimeoutExpired가 발생했다면 별도의 except 분기에서 포착되었을 것입니다. 하지만 그렇지 않았습니다.
  5. 인코딩 (Encoding). PYTHONIOENCODING=utf-8은 이미 서브프로세스 환경에 포함되어 있었습니다. 이것도 아니었습니다.

이 중 어느 것도 해결책이 되지 않았는데, 그 이유는 실패가 로컬 (local)에서 발생한 것이 아니었기 때문입니다. 그것은 Claude API 자체에서 발생한 429 에러였으며, CLI를 통해 반환되었습니다. 제 래퍼는 실패 시 잘못된 파일 디스크립터 (file descriptor)를 읽었기 때문에 이를 확인할 방법이 없었습니다.

1줄짜리 수정이 15개의 테스트 수정이 된 과정

agent/claude_cli.py에서의 실제 변경 사항은 작습니다. returncode != 0일 때, result.stdout을 JSON으로 파싱하여 api_error_status와 result를 추출하고 이를 로그로 남깁니다:

if result.returncode != 0:
    error_msg = ""
    api_error_status = None
...

실제 에러 코드를 볼 수 있게 되자, 어떻게 대응할지 결정할 수 있었습니다. 속도 제한 (Rate limits) 및 5xx 에러는 일시적이므로, 이제 래퍼는 {429, 500, 502, 503} 에러 발생 시 30초간 대기(sleep)한 후 한 번 재시도하며, {401, 403, 404} 에러 발생 시에는 즉시 실패합니다:

_RETRYABLE_STATUSES = frozenset({429, 500, 502, 503})
_RETRY_DELAY_SECONDS = 30

...

이러한 동작 변경은 미미합니다. 하지만 그 주변의 테스트 범위는 그렇지 않습니다. 저는 tests/test_claude_cli.py에 15개의 테스트를 추가했으며, 그 이름들만 읽어봐도 전체 상황을 알 수 있습니다:

test_rc1_logs_stdout_error_not_stderr
test_rc1_no_retry_for_401
test_rc1_no_retry_for_403
...

저 이름 하나하나가 이전에는 제가 가정만 하고 강제하지 않았던 계약(contract)입니다. 첫 번째 테스트는 제가 첫날부터 작성했기를 가장 바랐던 것입니다.

첫 번째 버그가 숨기고 있던 두 번째 버그

main.py를 살펴보던 중, 왜 봇이 에러 없이 깔끔하게 종료되었는지도 발견했습니다. _find_one_candidate()에서 발생한 처리되지 않은 예외(uncaught exception)가 except KeyboardInterrupt를 지나 전파되어 프로세스를 종료시키고 있었습니다. 후보자 검색에는 Playwright를 사용하는데, Playwright는 느린 페이지에서 page.close()를 호출할 때 가끔 예외를 발생시킵니다. 그 예외는 처리될 곳이 없었습니다. 해결책은 여러분이 수백 번은 작성해 보았을 법한 방식입니다:

try:
    candidate = self._find_one_candidate(...)
except Exception:
...

이러한 래퍼(wrapper)가 없다면, 컨텍스트 해제(context teardown) 중 발생하는 Playwright 충돌은 깔끔한 종료와 동일하게 보입니다. 예외는 봇의 외부 while True: 루프를 타고 올라가 최상위 레벨의 except KeyboardInterrupt에 도달하여 일반적인 프로그램 종료처럼 처리됩니다. stderr가 침묵하는 문제와 결합되어, 두 가지 실패가 겹쳐져 하나의 증상을 만들어냈습니다: 봇은 사라졌고, 에러도 없고, 흔적도 없습니다. 재시도(retry) 수정 사항만 있었다면 속도 제한(rate-limit)으로 인한 고통은 저절로 사라졌을 것입니다. 오직 try/except Exception만이 속도 제한 문제에 가려져 있던 충돌로부터 봇을 생존하게 만들었습니다. 서로 관련 없는 두 개의 버그가 하나의 미스터리 안에 숨어 있는 것은, 제 경험상 운영 환경 디버깅(production debugging)에서 최악의 상황이 아니라 가장 흔한(median) 사례입니다.

제가 다르게 했을 방식

여러분이 래핑하는 모든 CLI의 에러 출력 계약(error output contract)을 래핑하는 첫날에 바로 테스트하십시오. 성공 경로(success path)가 아닙니다. 성공 경로는 사소합니다. 놀라운 일들은 실패 경로(failure path)에서 발생합니다. 래퍼는 도구의 실패 동작에 대해 여러분이 하는 모든 가정을 유닛 테스트(unit test)로 인코딩해야 하는 바로 그 계층입니다.

특히 Claude CLI의 경우, 구조화된 에러(structured errors)를 stdout에 배치하기로 한 설계 결정은 방어할 가치가 있습니다. stderr는 사람이 읽을 수 있는 경고(warnings)를 위한 것이고, stdout은 기계가 파싱할 수 있는 출력(machine-parseable output)을 위한 것이며, stdout에 구조화된 JSON과 함께 비제로 종료 코드(non-zero exit code)를 반환하는 것은 성공 계약(success contract)과 내부적으로 일관됩니다. 또한 이는 제가 래퍼(wrapper)를 배포하기 전, 의도적으로 망가진 프롬프트를 대상으로 claude -p "test" --output-format json을 5분 동안 실행해 보았다면 정확히 잡아냈을 계약이기도 합니다. 하지만 저는 그 계약을 당연하게 가정했기에 잡아내지 못했습니다.

위의 잘못된 가설 목록을 증거로 삼아 일반적인 교훈을 얻자면 다음과 같습니다. 표준 디버깅 체크리스트가 모두 녹색(정상)을 반환할 때, 버그는 아마도 그 체크리스트가 당연하게 여기는 무언가에 있을 가능성이 높습니다. 저의 경우, 체크리스트는 에러가 stderr로 전달된다는 점을 당연하게 여겼습니다. 하지만 그렇지 않았습니다. 에러는 내내 stdout에 JSON 형태로, HTTP 상태 코드가 명확하게 라벨링된 채로 누군가 읽어주기를 기다리며 도착하고 있었습니다.

가정의 대가는 재앙적이지는 않았습니다. 봇은 하루에 한 번 저하된 모닝 사이클(morning cycle)을 수행한 뒤 오후에 수동 재시작을 거쳐 복구되었습니다. 하지만 이를 찾아내는 데 드는 비용은 3일간의 추측이었습니다. 제 래퍼가 실패 시 출력한 로그 라인은 적극적으로 오해를 불러일으켰습니다. 에러 출력이 전혀 없다고 주장했기 때문입니다. rc=1 with empty stderr와 같이 소음이 섞인 메시지였다면 유용한 단서(breadcrumb)가 되었을 것입니다. 조용한 rc=1은 막다른 길이었습니다. 되돌아보면 잘못된 스트림(stream)에 로그를 남기는 것은 아무것도 남기지 않는 것보다 더 나쁩니다. 왜냐하면 로그를 읽는 미래의 나에게 찾아낼 것이 아무것도 없다는 메시지를 전달하기 때문입니다.

구조화된 에러를 stdout에 배치하는 CLI 때문에 피해를 본 다른 분이 계신가요? 이것이 Unix 관습을 따르는 사람들이 말하는 것보다 더 흔한 일인지 궁금합니다.

Repos

이 서브프로세스 래퍼 (subprocess wrapper)와 이 봇의 나머지 부분은 AccountBuildUp 프로젝트의 github.com/Ekioo/KittyClaw에 위치해 있습니다. MIT 라이선스이며, 유용하다면 별(star)을 눌러주세요. 또한 저는 제 컨설팅 사이트인 ekioo.com의 콘텐츠 파이프라인(content pipeline) 뒷단에서 Claude CLI를 셸 호출 (shell out) 하여 사용하고 있는데, 그곳에서도 동일한 주의 사항 (gotcha)이 기다리고 있었으며 현재는 동일한 방식으로 패치되었습니다.

AI 자동 생성 콘텐츠

본 콘텐츠는 Dev.to AI tag의 원문을 AI가 자동으로 요약·번역·분석한 것입니다. 원 저작권은 원저작자에게 있으며, 정확한 내용은 반드시 원문을 확인해 주세요.

원문 바로가기
0

댓글

0