AI 코딩 사용량을 기록하던 중, 특정 세션에 대해서만 비용 기록이 남아있지 않은 것을 발견했습니다. 처음에는 측정 도구 측의 오류를 의심했지만, 같은 Claude Code 세션을 agent-cost에서 직접 측정하면 정상적으로 완료되었습니다. 소요 시간은 36.454초였습니다. 반면, spec-lane 어댑터를 거치면 30.019초로 실패했습니다.
원인은 호출 측에 설정된 30초의 타임아웃이었습니다. 문제가 된 것은 단순히 시간이 초과되었다는 사실 그 자체보다, 그 결과가 '0원'이 아니라 '측정할 수 없는 상태(計測できていない状態)'가 된다는 점입니다. 조사 과정을 통해 가장 명확하게 구분한 것이 바로 이 차이였습니다.
Measurement failed != $0 측정할 수 없었다는 것과, 0이라는 측정 결과는 같지 않습니다.
직접 실행하면 36초 만에 끝난다
Issue #42에서 사용된 세션을 남아있는 데이터로 다시 측정했습니다. 먼저 agent-cost를 직접 실행합니다.
agent-cost measure \
--format json \
--session-id <session-id>
결과는 다음과 같습니다.
exit: 0
wall: 36.454s
JSON parse: success
...
30초를 초과했지만, 측정 자체는 성공했습니다. 다음으로, 수정 전의 Git 리비전 cca0338...에서 빌드한 AgentCostTelemetryAdapter에 같은 세션을 전달했습니다.
30.019s
TelemetryImportFailed
Command failed
이번에는 30초 근처에서 실패했습니다. 수정 후 어댑터의 결과까지 나열하면 다음과 같습니다.
| 경로 | 결과 | 시간 |
|---|
agent-cost measure를 직접 실행 | 성공 | 36.454초 |
| 수정 전 어댑터 | 타임아웃 | 30.019초 |
| 수정 후 어댑터 | 성공 | 35.410초 |
수정 전 어댑터를 보면, 기본 타임아웃은 30_000ms였습니다.
this.timeoutMs = opts.timeoutMs ?? 30_000;
측정에 약 36초가 필요한데, 그 직전에 30초가 경과하면서 프로세스를 중단시키고 있었습니다. 게다가 당시의 에러 메시지는 Command failed만었습니다. 타임아웃이 발생했다는 사실도, 30초에서 중지되었다는 사실도 표시되지 않았습니다. 이 정보만으로는 agent-cost 자체가 실패했는지, 입력 데이터에 문제가 있었는지, 아니면 호출 측에서 중단시킨 것인지 판단할 수 없었습니다.
측정에 실패하면 '0원'이 아닌 '기록 없음(記録なし)' 상태가 된다
실패한 후의 데이터도 확인했습니다. 이 데이터는 앞서 언급된 실제 세션과는 별개로, 짧은 타임아웃을 지정하여 격리 환경에서 재현한 것입니다. lane calibrate의 측정을 의도적으로 실패시키자, 실행 후의 CalibrationObservation과 cost_ledger 모두 0건이었습니다.
이는 cost_usd: 0이라는 기록이 작성된 것이 아닙니다. 기록 자체가 없습니다. 소스 코드에서도 adapter.measure()가 실패하는 시점에서 처리를 빠져나가므로, 그 이후의 관측 데이터 생성이나 원장(台帳)에 쓰기 작업은 진행되지 않음을 확인했습니다.
더 나아가, 이 빈 원장에 대해 emit-metrics를 실행한 결과는 다음과 같았습니다.
built 0 record(s), coverage.status=no_data
이 no_data는 '0달러였다'는 의미가 아니라, '측정된 기록이 없다'는 상태입니다. 비용을 나중에 집계할 때 이것을 0으로 처리해버리면 데이터의 의미가 바뀝니다. 0은 측정 결과이지만, 여기서는 값을 얻지 못한 것입니다. 집계 시에도 분리하여 보관해야 합니다.
타임아웃을 180초로 변경하고 외부에서 수정할 수 있게 했다
PR #43에서는 기본 타임아웃을 30초에서 180초로 변경했습니다.
DEFAULT_AGENT_COST_TIMEOUT_MS = 180_000
동시에 CLI(Command Line Interface)에서 변경할 수 있는 옵션도 추가했습니다.
--agent-cost-timeout-ms <n>
대상은 calibrate, emit-metrics입니다.
、next
、usage-import
의 4가지 명령어입니다. 지정 가능한 범위는 1ms부터 3_600_000ms까지로 설정했습니다.
타임아웃 시 메시지도 변경했습니다. 예를 들어 200ms를 지정하여 의도적으로 시간 초과가 발생하면, timed out after 200 ms (killed with SIGTERM)와 표시됩니다. 이렇게 하면 측정 명령어 자체의 오류인지, 호출 측의 타임아웃인지를 구분하기 쉬워집니다.
다만, 180초로 설정했다고 해서 모든 경우에 해결되는 것은 아닙니다. 이 타임아웃은 180초 후에 SIGTERM을 보내는 메커니즘입니다. 서브 프로세스가 시그널을 무시하는 경우까지 포함하여 엄격한 실행 시간 상한선은 아닙니다.
수정 후에는 38초가 걸려도 기록이 남았습니다
타임아웃 시간을 늘리는 것만으로는 확인에 충분하지 않기 때문에, PR 검증에서 사용되었던 다른 세션과 레인의 스냅샷으로 재실행했습니다. v0.10.1 CLI를 기본 180초(180_000ms) 타임아웃으로 구동한 결과입니다.
이 재실행에서는 측정만 끝난 것이 아니라, 결과 저장까지 진행되었습니다.
CalibrationObservation: 1건
cost_ledger: scope=lane
emit-metrics: coverage.status=complete
관측 데이터가 생성되고, 장부(ledger)에도 기록되었으며, emit-metrics까지 complete 상태가 되었습니다. 수정 전에는 30초 만에 측정이 멈추고, 관측 데이터도 장부 기록도 없이 no_data 상태였기 때문에, 그 이후 단계로 진행할 수 있음을 확인할 수 있었습니다.
참고로, PR 작성 당시에도 약 39초 만에 성공했다는 기록이 있습니다. 다만, 그때의 정확한 실행 시간을 보여주는 원본 로그는 남아있지 않습니다. 이는 재실행으로 얻은 38.01초와 별개의 증거로 취급하고 있습니다.
'측정 가능'과 '금액이 정확함'도 분리해서 생각해야 합니다
확인할 수 있었던 것은, 측정 처리가 끝까지 작동하여 프로토콜에 따른 데이터를 얻고 장부까지 저장할 수 있다는 점입니다. 거기서 더 나아가 다음 지점까지 증명한 것은 아닙니다.
- 추정 비용 자체가 정확한지
- 요금 카탈로그가 정확한지
- 세션과 태스크의 연결이 의미적으로 올바른지
실제로, 이 재실행 기록과 과거 기록에서는 토큰 수나 추정 비용에 차이가 있습니다. 사용된 agent-cost 버전도 다르지만, 그 차이의 원인은 조사 대상에 포함하지 않았습니다. 측정이 완료되었다는 것, 금액이 정확하다는 것, 태스크 귀속이 정확하다는 것은 자동화하면 연속적으로 보여도 각각 별도의 확인이 필요합니다.
exit 0이라도 측정 성공이라고 단정할 수 없습니다
또 하나 신경 쓰인 부분은 usage-import의 동작 방식입니다. calibrate는 측정에 실패하면 exit 2가 되지만, usage-import는 실패를 measurement-incomplete, matched: false로 기록하고 장부에 기록하지 않은 채 exit 0을 반환하는 경우가 있습니다.
따라서 종료 코드만 보고 '측정 성공'이라고 판단할 수 없습니다. 타임아웃과는 조금 떨어진 이야기지만, 이것 역시 상태 처리에 관련된 문제라고 생각합니다. '성공인지 실패인지'만으로는 상태가 너무 거칩니다.
값이 없는 것을 0으로 처리하지 말아야 합니다
직접 수정한 것은 30초 타임아웃이었습니다. 하지만 개인적으로는 초 단위 변경보다, 그 전후에서 데이터의 의미를 훼손하지 않는 것이 더 중요했습니다. 측정 결과에는 적어도 0, unknown, failed, not measured와 같은 차이가 있습니다.
이것들을 모두 0으로 통일하면 집계는 쉬워집니다. 대신, 나중에 '정말로 0이었는지, 아니면 측정되지 않았던 것인지'를 알 수 없게 됩니다. AI 코딩 비용뿐만 아니라, 테스트 결과나 평가 값, 이용량 측정에서도 같은 일이 발생합니다.
Issue #42를 통해 저는 이 한 줄을 마음속에 새겼습니다.
Measurement failed != $0
자동화하는 범위가 넓어질수록, 집계하기 쉬운 값으로 맞추기 전에 무엇을 측정했고 무엇을 측정하지 못했는지를 남겨두고 싶습니다.
관련 링크
- Issue #42 — agent-cost timeout
- PR #43 — default 180s / timeout override / diagnostic
- spec-lane v0.10.1
버전 표기(バージョン表記)에 대하여
Issue #42에는 당시의 실행 환경으로 lane 0.9.1, cca0338 on main이라고 기록되어 있습니다. 한편, Git 상에서는 cca0338...이 v0.10.0 태그가 제거된 커밋(peeled commit)이며, packages/cli/package.json의 버전 역시 0.10.0입니다.
30.019초 재현은 이 cca0338...의 소스코드로부터 빌드하여 진행했습니다. 당시 실행 CLI가 0.9.1로 표시되었던 이유까지는 확인할 수 없었기 때문에, 최초의 현상이 v0.10.0 CLI에서 발생했다고 취급하지 않았습니다.
논의(Discussion)
