44% 확률로 멈추는 버그를 쫓다가 성급한 결론이 세 번 무너진 기록

0. 들어가며

로컬 LLM 위임 파이프라인을 구축하던 중, CLI 도구 하나가 아무 메시지도 없이 멈추는 증상을 만났습니다.

에러도, 스택트레이스도, 타임아웃 메시지도 없었습니다. 프로세스는 살아 있고, 표준출력은 0바이트이고, 외부에서 죽이지 않으면 영원히 그 상태였습니다.

원인을 찾는 데 반나절이 걸렸습니다. 그런데 그 반나절의 절반은 문제 자체가 아니라, 제가 잘못 내린 결론을 되돌리는 데 썼습니다. 이 글은 그 과정을 미화 없이 기록한 것입니다.

결론부터 말하면, 이 버그는 아직 완전히 해결되지 않았습니다. 대신 "확률적으로 실패하는 현상을 어떻게 검증해야 하는가" 에 대한 값비싼 교훈이 남았습니다.

1. 증상: 조용히 멈추는 실행

문제의 명령은 단순했습니다.

opencode run "한 단어로만 답해라: 1+1은?"

정상일 때는 19초 만에 답이 돌아옵니다. 그런데 어느 순간부터 같은 명령이 응답하지 않았습니다.

가장 곤란한 점은 에러가 없다는 것이었습니다. 실패가 실패처럼 보이지 않으면 디버깅은 시작조차 어렵습니다.

1.1 첫 번째 함정, 종료 코드는 거짓말을 한다

처음에는 셸에서 이렇게 확인했습니다.

timeout 60 opencode run "..." | tail -5
echo "종료코드: $?"

$? 가 0 으로 나왔습니다. 성공한 줄 알았습니다.

틀렸습니다. 파이프라인에서 $? 는 마지막 명령(tail)의 종료 코드입니다. timeout 이 실제로 무엇을 반환했는지와 무관합니다. 이 실수를 저는 세 번 반복했습니다.

거기에 더해, 이 CLI는 표준출력을 완료 시점까지 버퍼링합니다. 파일로 리다이렉트해두면 실행 중에는 0바이트로 보이고, 끝나야 한꺼번에 쏟아집니다. 즉:

"0바이트"는 "실패"가 아니라 "아직 안 끝났다"일 수도 있습니다.

두 함정이 겹치면서, 저는 "느린 실행"과 "멈춘 실행"을 한동안 구분하지 못했습니다.

1.2 제대로 된 판별 기준 찾기

로그를 비교해보니 정상 실행과 정지 실행의 차이가 명확했습니다.

정상 실행의 로그 시퀀스:

init → created → event → loop → shell → init → booting → stream → loop → exiting loop → disposing instance

정지 실행:

timestamp=... message="creating instance" directory=/tmp/repro
timestamp=... message=bootstrapping
timestamp=... message=loading path=~/.config/opencode/opencode.jsonc
timestamp=... message="all LSPs are disabled"
timestamp=... message="all formatters are disabled"
timestamp=... message=init
<이후 아무것도 없음>

init 에서 정확히 멈추고, 세션 생성(created)에 도달하지 못합니다.

그래서 판별 기준을 종료 코드가 아니라 세션 생성 여부로 바꿨습니다.

grep -c 'message=created' ~/.local/share/opencode/log/opencode.log

실행 전후의 이 값을 비교하면, 버퍼링이나 파이프에 속지 않고 "진짜 진행했는지"를 알 수 있습니다. 이 판별 기준을 세운 것이 이 조사에서 처음으로 제대로 한 일이었습니다.

2. 첫 번째 결론과 그것이 무너진 과정

당시 저는 이 CLI의 권한 설정을 바꾸는 작업을 하고 있었습니다. permission.bash 값을 allow 에서 ask 로 바꾸면 어떻게 되는지 확인하던 중이었습니다.

실험 결과는 이랬습니다.

저는 여기서 결론을 냈습니다.

"bash: ask 로 두면 헤드리스 실행이 승인 프롬프트에서 무한 대기한다. 비대화형 환경이라 응답할 주체가 없으니 당연하다."

논리적으로 그럴듯했습니다. 프롬프트를 띄우는 설정 → 응답할 사람이 없음 → 영원히 대기. 인과가 자연스럽게 이어집니다.

그리고 이 결론 위에 이후 작업 전체를 쌓았습니다. 샌드박스 격리가 필요한 이유, 에이전트별 권한을 분리해야 하는 이유, 그 우선순위까지 전부 이 전제에서 나왔습니다.

2.1 무너진 지점

한참 뒤에야 로그 전체를 시간순으로 다시 뒤졌습니다. 그리고 이걸 발견했습니다.

01:41:20  정지    ← 그날 첫 실행
02:56:29  정지
03:06:02  정지
10:14:54  정지    ← "bash: ask 때문"이라고 결론 낸 실행
10:16:07  정지    ← 같음
10:33:05  정지
10:37:16  정지

정지는 그날 첫 실행부터 있었습니다. 설정을 바꾸기 훨씬 전부터요.

그날 전체 성공률을 세어보니 61회 중 27회, 44% 였습니다. 즉 저는 뒷면이 56% 나오는 동전을 세 번 던져놓고 "이 설정이 원인"이라고 단정한 것이었습니다.

2번 실패 + 1번 성공은, 기저 실패율이 56%인 환경에서는 아무것도 의미하지 않습니다. 그 정도 패턴은 우연히 나올 확률이 충분히 높습니다.

첫 번째 교훈: 기저 발생률을 모르면 어떤 관측도 증거가 되지 못한다.

3. 두 번째 결론과 그것이 무너진 과정

권한 값을 deny 로 바꿔서도 테스트했습니다. 역시 멈췄습니다. "역시 권한 설정이 문제구나" 싶었습니다.

그런데 대조군을 돌려봤습니다. 권한과 무관한, bash를 전혀 쓰지 않는 작업을 같은 에이전트에 던졌습니다.

역시 멈췄습니다.

권한 문제가 아니었습니다. 그 에이전트가 쓰는 모델이 18GB짜리라 콜드 로드가 느렸을 뿐이고, 타임아웃을 600초로 늘리자 정상 완료됐습니다.

두 번째 교훈: "조건 A에서 실패했다"를 주장하려면 "조건 A가 아닐 때는 성공한다"를 같이 보여야 한다.

4. 계층별로 배제해도 되는 게 하나도 없었다

원인을 특정하지 못한 채, 의심 가는 계층을 하나씩 제거해나갔습니다. 전부 실패했습니다.

재설치 도중 하나 배웠습니다. npm의 allowScripts 정책이 켜져 있으면 전역 설치 시 postinstall 스크립트가 조용히 건너뛰어집니다.

npm install -g <package>@latest
# → "1 package had install scripts blocked"
# → 설치는 "성공"했지만 바이너리가 제대로 배치되지 않음

해결은 명시적 허용입니다.

npm install -g --allow-scripts=<package> <package>@latest

이 도구는 autoupdate: true 가 기본값입니다. 즉 자가 업데이트가 이 정책 아래에서 돌면 설치가 깨진 채로 남을 수 있습니다. 이번 정지의 원인은 아니었지만(제대로 재설치한 뒤에도 증상이 남았습니다) 별도로 보고할 가치가 있는 문제였습니다.

5. 세 번째 결론과 그것이 무너진 과정

웹 조사로 유력한 가설을 하나 얻었습니다.

이 CLI는 시작할 때마다 모델 카탈로그 서버(models.dev)와 패키지 레지스트리에 네트워크 요청을 보내는데, 런타임의 fetch 에 타임아웃이 없어서 응답이 늦으면 조용히 멈춘다.

관측과 잘 맞았습니다. 읽기 전용 명령(--version, agent list)이 항상 정상이었던 것도 그 경로를 타지 않아서라고 설명됩니다. 로컬 계층을 아무리 뒤져도 안 나온 이유도 자연스럽게 설명됩니다.

제안된 우회책은 OPENCODE_OFFLINE=1 환경변수였습니다. 6회 돌렸고 6회 모두 성공했습니다.

여기서 "가설 확정"이라고 보고할 뻔했습니다. 그런데 대조군을 같이 돌렸습니다.

대조군(환경변수 없음)도 3/3 성공했습니다. 소요 시간까지 19초로 동일했습니다.

증상 자체가 그 시간대에 재현되지 않고 있었던 겁니다. 환경변수의 효과가 아니라, 그냥 잘 되는 구간이었습니다.

세 번째 교훈: 대조군 없는 성공률은 아무 의미가 없다. 6/6이라는 숫자는 매력적이지만, 비교 대상이 없으면 그건 그냥 "그때 잘 됐다"는 기록일 뿐입니다.

6. 이번엔 눈으로 직접 관측했다

성공률 비교로는 판별이 안 되니, 네트워크 연결을 직접 들여다보기로 했습니다. 성공률은 조건에 따라 흔들리지만, "요청을 보내는가"는 그 자리에서 확인할 수 있습니다.

lsof -nP -a -p <pid> -i

여기서도 함정이 하나 있었습니다. lsof 는 -p 와 -i 를 기본적으로 OR로 묶습니다. -a 를 붙여야 AND가 됩니다. 이걸 빼먹으면 시스템 전체의 무관한 연결이 쏟아집니다.

6.1 정지 중인 프로세스에서 잡힌 것

COMMAND     PID  USER   FD   TYPE  NODE NAME
opencode. 14462 user    15u  IPv4   TCP 192.168.x.x:50476->172.67.69.147:443 (ESTABLISHED)

이 IP를 확인해보니:

$ dig +short models.dev
104.26.9.108
104.26.8.108
172.67.69.147   ← 일치

models.dev 로의 연결이 30초 내내 ESTABLISHED 상태로 붙잡혀 있었고, 그동안 실행은 한 발짝도 진행하지 않았습니다.

같은 시각, 같은 머신에서 그 호스트는 멀쩡했습니다.

$ curl -s -o /dev/null -w "namelookup=%{time_namelookup} connect=%{time_connect} tls=%{time_appconnect} total=%{time_total}\n" https://models.dev/
namelookup=0.001497 connect=0.140799 tls=0.287761 total=1.107086   # HTTP 200

DNS 1.5ms, TLS 288ms, 전체 1.1초. 서버는 정상인데 이 프로세스만 그 연결 위에서 멈춰 있었습니다.

6.2 그런데 설명되지 않는 두 번째 양상

같은 정지라도 다른 모습이 있었습니다.

t=2   PID=14286  연결=[없음]
t=4   PID=14286  연결=[없음]
...
t=30  PID=14286  연결=[없음]

소켓이 하나도 없습니다. models.dev 는 물론이고, 로컬 백엔드로 가는 연결조차 없습니다.

연결을 시도 중이라면 최소한 SYN_SENT 라도 보여야 합니다. 소켓 자체가 없다는 건 소켓 생성 이전 단계에서 막혔다는 뜻인데, 시스템 리졸버는 0.00초에 응답하니 DNS 지연으로도 설명되지 않습니다.

이 두 번째 양상은 지금도 설명하지 못합니다. 정지 경로가 최소 두 개라는 뜻일 수 있습니다.

관측에서 중요한 원칙 하나: 음성 결과는 "없음"이 아니라 "검출되지 않음"입니다. 2초 간격 샘플링으로는 짧게 열렸다 닫히는 연결을 놓칩니다. 그래서 저는 이 데이터를 "연결이 있었다"는 양성 신호로만 쓰고, 0을 부재의 근거로는 쓰지 않았습니다.

7. 제대로 된 검증: 40회 대조 실험

이제야 실험다운 실험을 설계했습니다. 이전 측정들의 결함을 전부 반영했습니다.

그리고 결과를 보기 전에 판정 기준을 선언했습니다. 데이터를 본 뒤 기준을 정하면 자의적이 되니까요.

7.1 결과

OFFLINE  세션생성 20/20 | 완주 20/20 | models.dev 관측 4
CONTROL  세션생성 20/20 | 완주 20/20 | models.dev 관측 4
소요시간 전 구간 18~19초 (min 18, max 19)

40회 중 정지가 한 번도 나오지 않았습니다.

두 팔 모두 20/20이므로 비교할 차이가 없습니다. 선언한 기준대로 결론은 "효과 없음"이 아니라 "판별 불가" 입니다. 측정하려던 현상이 나타나지 않았으니까요.

직전 1시간에는 6회 연속 정지였는데, 그 10분 뒤부터 42분간 40회 연속 성공했습니다. 그 사이 아무 설정도 바꾸지 않았습니다.

7.2 그래도 건진 것

models.dev 연결 관측이 양쪽 각각 4회로 완전히 동일했습니다.

환경변수가 그 요청을 억제한다면 한쪽이 0에 가까워야 합니다. 같다는 건 OPENCODE_OFFLINE=1 이 이 요청을 막지 못한다는 뜻입니다. 이건 성공률과 무관하게 성립하는 결론입니다.

7.3 타이밍이 이분법이라는 사실

40회 전부 18~19초, 편차 1초 이내였습니다. 정지 시에는 900초까지도 진행이 없었습니다.

이 현상은 "느려짐"이 아니라 명확한 이분법입니다. 19초에 끝나거나, 아예 진행하지 않거나. 중간이 없습니다. 점진적 성능 저하와는 다른 종류의 문제라는 뜻입니다.

8. 최종 상태: 해결되지 않았다

정직하게 정리하면 이렇습니다.

처음부터 지금까지 계속 간헐적으로 실패해 왔으며, 실패율이 시간대에 따라 8%~77% 사이로 크게 요동칩니다. 어떤 조치로도 해소된 적이 없고, 나아진 것처럼 보였던 구간들은 조치와 무관한 우연한 호전이었습니다.

시간대별 성공률은 이랬습니다.

조치와 결과를 나란히 놓으면 인과가 없다는 게 더 분명합니다.

확보한 증거는 업스트림 이슈로 등록했습니다. 재현 절차, 환경 정보, 전 계층 배제 목록, 101회 표본 데이터, 네트워크 관측 증거, 그리고 재현율이 낮다는 사실까지 포함했습니다.

원인 추정은 "가설이지 결론이 아니다"라고 명시하고, 설명하지 못하는 두 번째 정지 양상도 그대로 남겼습니다. 모르는 것을 모른다고 적는 게 이슈의 신뢰도를 높입니다.

9. 마무리: 반나절에서 남은 것

기술적으로 확정한 것은 많지 않습니다. 원인은 여전히 미확정이고, 우회책도 없습니다.

대신 방법론에서 남은 게 있습니다.

1. 기저 발생률을 먼저 구하라.
44% 확률로 실패하는 환경에서 3회 관측으로 인과를 주장하면 안 됩니다. 저는 이걸 두 번 어겼고, 그 위에 이후 작업 설계를 쌓았습니다. 되돌리는 비용이 원래 조사보다 컸습니다.

2. 대조군은 선택이 아니다.
6/6 성공을 "확정"으로 보고할 뻔한 걸 대조군이 막았습니다. 대조군 없이 관측한 성공률은 조건의 효과가 아니라 그날 운을 측정한 것일 수 있습니다.

3. 판정 기준을 데이터보다 먼저 정하라.
결과를 보고 기준을 정하면 원하는 결론이 나옵니다. 저는 40회 실험 전에 "차이가 안 나오면 '효과 없음'이 아니라 '검출되지 않음'으로 쓴다"를 선언해뒀고, 실제로 그렇게 나왔을 때 결론을 왜곡하지 않을 수 있었습니다.

4. 측정 도구부터 의심하라.
$? 가 파이프 뒤에서는 다른 명령의 값이라는 것, lsof 의 -p와 -i가 OR라는 것, 출력이 버퍼링되면 진행 중과 정지가 구분되지 않는다는 것. 이 셋 때문에 저는 잘못된 데이터로 몇 시간을 판단했습니다. 도구가 틀리면 그 위의 모든 분석이 틀립니다.

5. 음성 결과를 부재로 읽지 마라.
샘플링에서 안 잡힌 것은 없는 것이 아닙니다. 양성만 증거로 쓰고 음성은 판단 보류로 두는 편이 안전합니다.

"재현되지 않는 버그를 쫓을 때 가장 위험한 것은 버그가 아니라, 몇 번의 관측으로 인과를 확신하는 자신이다."

이 조사는 아직 끝나지 않았습니다. 7분 간격으로 계속 실행하며 실패 구간을 포착하는 장기 샘플러를 돌려두었고, 데이터가 쌓이면 업스트림에 후속으로 붙일 예정입니다.