▚Fieldnotes개발 현장 기록

헤드리스 AI CLI 의 인증 실패가 "정상 빈 결과"로 위장한다 — subprocess returncode 함정

cron 에서 돌던 AI CLI 배치가 열흘간 조용히 전량 실패했다. 로그엔 에러가 없었다. OAuth 세션이 만료됐는데 호출부가 종료코드를 안 봐서, 401 로 죽은 빈 stdout 이 도메인상 정상 결과와 구분 불가능하게 섞인 게 원인이었다.

글 rian발행

30분마다 도는 cron 작업이 있다. 어떤 텍스트에서 장소 정보를 뽑아 개인 데이터베이스에 채워 넣는 배치인데, 추출은 AI CLI 를 비대화형(-p)으로 subprocess 호출해서 한다. 어느 날 데이터베이스를 수동으로 열어봤다가, 열흘 전부터 들어온 행이 전부 failed 로 찍혀 있는 걸 발견했다. 로그에는 에러가 한 줄도 없었다.

subprocess 헬퍼가 returncode 를 안 본다

배치의 핵심은 이런 헬퍼였다. AI CLI 를 격리된 config 디렉터리로 subprocess 호출하고, stdout 을 그대로 파서에 넘긴다.

def _run_cli(prompt, extra_args=()):
    out = subprocess.run(
        [cli_bin, "-p", prompt, "--output-format", "text", *extra_args],
        env=env, capture_output=True, text=True, timeout=240,
        stdin=subprocess.DEVNULL,
    )
    return out.stdout.strip()   # returncode 체크 없음

-p 는 한 번 호출하고 끝나는 헤드리스 모드다. 사람이 붙어 있지 않으니 인증이 깨져도 아무도 프롬프트를 못 본다. 그리고 이 CLI 는 구독 계정을 브라우저 OAuth 로 인증하는데, 그 세션에는 만료가 있다.

로그는 완벽하게 정상이었다

로그만 보면 완벽하게 정상이었다. 매 행마다 “장소 0개 추출” 에 해당하는 결과가 찍혀서, 그냥 뽑을 게 없는 입력이 연속으로 들어온 것처럼 보였다. 실제로 데이터베이스를 열어보기 전까지는 장애를 인지할 신호가 아무것도 없었다.

재현은 세션을 만료시킨 뒤 CLI 를 직접 때려보면 된다.

$ CLAUDE_CONFIG_DIR=~/.cli-isolated cli -p "hi" --output-format text
Failed to authenticate. API Error: 401 Invalid authentication credentials
$ echo $?
1

여기서 중요한 건 이것이다. exit code 는 1 인데 stdout 은 빈 문자열이다. 에러 메시지는 stderr 로 나간다. 그래서 stdout 만 읽는 코드 입장에서는, 인증이 죽어서 아무것도 못 받은 상태와 “정상적으로 뽑을 게 없었던” 상태가 완전히 똑같이 빈 문자열로 도착한다.

파서를 의심했지만 범인은 따로 있었다

처음에는 파서나 입력 데이터를 의심했다. 특정 시점부터 입력 형식이 바뀌었나, 파싱 규칙이 깨졌나. 하지만 그쪽은 멀쩡했다. 로그의 “0개 추출” 을 곧이곧대로 믿고 “왜 갑자기 전부 0개인가” 를 파고든 게 잘못된 방향이었다. 로그 자체가 거짓말을 하고 있었다.

방향을 잡은 건 격리 config 의 자격증명 파일 수정 시각을 장애 시작 시각과 대조하면서였다.

stat -c "%y" ~/.cli-isolated/.credentials.json   # 마지막 갱신 = 세션 발급 시각
CLAUDE_CONFIG_DIR=~/.cli-isolated cli -p "hi" --output-format text; echo "rc=$?"

자격증명 발급 시각으로부터 계산되는 만료 시점이, 데이터베이스에서 실패가 시작된 시각과 정확히 맞물렸다.

원인 — 장애와 정상 결과가 같은 빈 문자열로 뭉개진다

원인은 인증 만료 그 자체가 아니라, 시스템 장애와 도메인상 정상 결과가 코드에서 구분 불가능하게 뒤섞인 것이다.

  • CLI 가 401 로 죽어도 stdout 은 빈 문자열이다.
  • 헬퍼가 returncode 를 안 봐서 그 빈 문자열을 그대로 반환한다.
  • 파서는 빈 문자열을 “추출 0건” 이라는 유효한 도메인 결과로 해석한다.
  • 파이프라인은 그걸 진짜 시스템 장애가 아니라 정상 결과로 취급해 행을 failed 로 낙인찍는다.

장애가 났는데 로그에는 에러가 안 남는다. 이게 열흘간 미인지된 이유다. subprocess 를 부르는 코드가 종료코드를 무시하면, 실패는 사라지는 게 아니라 “정상처럼 보이는 잘못된 데이터” 로 조용히 흘러 들어간다.

복구 · 재발 방지 · 알림 — 세 단계로 나눈다

즉시 복구

OAuth 재로그인은 브라우저 인터랙티브라 자동화가 안 된다. 원격 서버면 ssh 로 TTY 를 확보해서 직접 재인증하는 수밖에 없다.

CLAUDE_CONFIG_DIR=~/.cli-isolated cli   # 로그인 안내 따라 재인증

재발 방지 — 종료코드로 두 세계를 가른다

핵심 수정은 헬퍼가 종료코드를 봐서, “시스템 장애” 와 “정상 빈 결과” 를 아예 다른 타입으로 구분하게 만드는 것이다.

class CLIError(RuntimeError):
    pass

def _run_cli(prompt, extra_args=()):
    out = subprocess.run(...)
    if out.returncode != 0:
        raise CLIError(f"CLI failed rc={out.returncode}: {(out.stderr or '')[:500]}")
    return out.stdout.strip()

호출부의 처리 방식이 더 중요하다. CLIError 가 나면 그 행을 failed 로 낙인찍지 말고 원래 상태(pending)를 유지한다. 다음 cron 이 인증 복구 후 자동으로 재처리하도록 두는 것이다. 같은 배치의 나머지 pending 행도 같은 원인일 확률이 높으므로, 첫 CLIError 에서 루프를 즉시 중단해 유료 API 호출 낭비도 막았다.

이 “실패 시 pending 유지” 설계가 나중에 진짜로 값을 했다. 다음 장애 때 복구만 해주니 남아 있던 pending 행이 자동으로 정상 처리돼서 수동 재처리가 필요 없었다.

알림 — 어차피 또 만료된다

OAuth 세션 만료는 구조적으로 못 막는다. 브라우저 인터랙티브 재로그인이고 계정 세션 정책이라, 주기적으로 다시 만료된다. 그래서 로그를 직접 열어보지 않아도 알도록 CLIError 발생 시점에 웹훅 알림을 붙였다.

여기에 함정이 하나 더 있다. 장애는 다음 인증 복구까지 계속 지속되는데, cron 은 30분마다 돌기 때문에 알림을 그대로 두면 30분마다 같은 알림이 쏟아진다. 그래서 파일 기반 throttle 을 뒀다.

WEBHOOK_URL = os.environ.get("WEBHOOK_URL", "")   # 미설정 시 조용히 skip
ALERT_THROTTLE_SECONDS = 7200                      # 같은 장애 지속 중 재알림 억제

def _notify_auth_failure(err):
    if not WEBHOOK_URL:
        return
    # throttle 상태파일의 마지막 알림 시각 확인 → 임계 안이면 skip
    # 넘었으면 requests.post(WEBHOOK_URL, ..., timeout=10) 후 시각 갱신

알림 설계 원칙 셋: 설정 안 됐으면 조용히 넘어가고, 알림이 실패해도 본 작업은 안 죽이고, throttle 로 폭주를 막는다.

배포 스크립트를 rsync --delete 로 돌린다면 throttle 상태파일을 exclude 목록에 넣어야 한다. 안 그러면 배포마다 상태파일이 지워져 throttle 이 리셋되고, 장애 지속 중에 배포할 때마다 알림이 다시 나간다.

복구 후 검증

복구 후에는 CLI 를 직접 때려서 rc=0 과 실제 출력이 나오는지 본다.

CLAUDE_CONFIG_DIR=~/.cli-isolated cli -p "hi" --output-format text; echo "rc=$?"

그리고 배치를 한 번 돌려 pending 행이 실제로 소진되는지 확인한다. throttle 은 상태파일을 지운 뒤 인증을 다시 깨서, 알림이 첫 실패에 한 번 나가고 임계 시간 안에는 안 나가는지로 확인했다.

같은 알림, 다른 원인 — 토큰 문자열에 낀 개행

같은 알림이 또 왔는데 원인이 전혀 달랐던 적이 있다. 이번엔 세션 만료가 아니라 토큰 문자열 중간에 개행이 들어간 경우였다. 붙여넣기 줄바꿈이 그대로 환경변수에 저장돼서, HTTP 헤더 값으로 무효가 됐다.

API Error: Header 'Authorization' has invalid value: 'Bearer <token-first-half>
<token-second-half>'

진단이 헷갈렸던 지점 몇 개를 남겨둔다.

  • 비대화형 셸은 셸 rc 파일을 안 읽는다. zsh 기준 zsh -lc 같은 비대화형 login shell 은 .zshenv/.zprofile 만 소스하고 .zshrc 는 건너뛴다. ssh 로 env 를 점검하면 토큰 환경변수가 길이 0 으로 나와서 “환경변수 문제 아님” 으로 오판하기 쉽다. 확인은 rc 파일을 직접 grep 해야 한다.
  • 자격증명 파일이 빈 껍데기인 OS 가 있다. 어떤 플랫폼은 .credentials.json 에 accessToken 길이 0, expiresAt 0 이 정상이고 실제 값은 OS 키체인에 있다. 파일만 보고 만료/손상을 판단할 수 없다.
  • 원격 세션 특유의 신호를 cron 상태와 혼동하지 말 것. ssh 세션에서 키체인이 잠겨 있으면 “로그인 안 됨” 류 메시지가 뜨는데, 이건 원격 세션 특성이지 cron 이 죽은 이유와 별개다.

토큰을 파일로 관리한다면 저장할 때 공백류를 벗겨내는 게 이런 개행 사고의 재발 방지책이다.

printf 'TOKEN=%s\n' "$(pbpaste | tr -d '[:space:]')" >> ./.env

정리하면, 이 장애의 진짜 교훈은 인증이 아니다. subprocess 를 부르는 코드는 반드시 종료코드를 확인해서, 시스템 장애와 정상 빈 결과를 다른 타입으로 갈라야 한다. 그 둘이 코드에서 같은 빈 문자열로 뭉개지는 순간, 장애는 에러가 아니라 조용히 잘못된 데이터로 흘러 들어가 오래 들키지 않는다.