DEV Community

Yusuke Shiki
Yusuke Shiki

Posted on Originally published at zenn.dev AI-assisted

The Cost Wasn't $0: My AI Coding Measurement Timed Out at 30 Seconds

#ai #claudecode #observability #opensource

I was recording usage and cost for AI coding sessions when I noticed something odd: one session had no cost entry at all.

My first assumption was that the measurement tool had failed. But when I ran agent-cost directly against the same Claude Code session, it completed successfully in 36.454 seconds. Through the spec-lane adapter, however, the same measurement failed after 30.019 seconds.

The reason was simple: the caller had a 30-second timeout.

What mattered more than the timeout itself was what happened afterward. The failed measurement did not produce a $0 record. It produced no measurement record at all.

That distinction became the main lesson from this incident:

Measurement failed != $0

Failing to measure something is not the same as measuring it as zero.

The same session succeeded directly and failed through the adapter

I first reran the session from Issue #42 directly with agent-cost:

agent-cost measure \
  --format json \
  --session-id <session-id>
Enter fullscreen mode Exit fullscreen mode

The result:

exit: 0
wall: 36.454s
JSON parse: success
protocol: measure/v1
Enter fullscreen mode Exit fullscreen mode

The measurement took longer than 30 seconds, but it completed normally.

I then passed the same session through an AgentCostTelemetryAdapter built from the pre-fix Git revision cca0338....

30.019s
TelemetryImportFailed
Command failed
Enter fullscreen mode Exit fullscreen mode

This time it stopped around the 30-second mark.

For comparison:

Path Result Time
Direct agent-cost measure Success 36.454s
Pre-fix adapter Timeout 30.019s
Post-fix adapter Success 35.410s

The pre-fix adapter had this default:

this.timeoutMs = opts.timeoutMs ?? 30_000;
Enter fullscreen mode Exit fullscreen mode

So the underlying measurement could finish in roughly 36 seconds, while the caller terminated it after 30.

There was another problem: the error message was only Command failed. It did not say that a timeout had occurred or that the process had been stopped after 30 seconds.

From that message alone, it was difficult to distinguish a failure inside agent-cost from a timeout imposed by its caller.

No record is not a zero-dollar record

I wanted to know what a failed measurement left behind.

For this part, I used a separate controlled reproduction with a deliberately short timeout. This was not the same real session used in the timing comparison above.

When lane calibrate failed during measurement, the result was:

CalibrationObservation: 0
cost_ledger: 0
Enter fullscreen mode Exit fullscreen mode

It did not write a record such as:

{
  "cost_usd": 0
}
Enter fullscreen mode Exit fullscreen mode

There was simply no record.

The source code matched that behavior. If adapter.measure() fails, the command returns before generating the observation and before writing the cost ledger.

Running emit-metrics against the empty ledger produced:

built 0 record(s), coverage.status=no_data
Enter fullscreen mode Exit fullscreen mode

Here, no_data does not mean "the measured cost was zero." It means there is no measured record available.

That matters once the numbers are aggregated. If ten failed measurements in a hundred tasks are silently converted to $0, the resulting average can look lower than the evidence actually supports.

Zero is a value. Missing measurement evidence is a different state.

The fix was more than changing 30 seconds to 180

PR #43 changed the default timeout from 30 seconds to 180 seconds:

DEFAULT_AGENT_COST_TIMEOUT_MS = 180_000
Enter fullscreen mode Exit fullscreen mode

It also added a CLI override:

--agent-cost-timeout-ms <n>
Enter fullscreen mode Exit fullscreen mode

The option is available for four commands:

  • calibrate
  • emit-metrics
  • next
  • usage-import

The accepted range is from 1ms through 3_600_000ms.

The timeout error was also made explicit. For example, a controlled 200ms timeout now reports:

timed out after 200 ms (killed with SIGTERM)
Enter fullscreen mode Exit fullscreen mode

That makes it much easier to tell the difference between a measurement command failing on its own and the caller terminating it because of its deadline.

There is still a boundary here: 180 seconds is not a strict wall-clock guarantee. The implementation sends SIGTERM when the timeout is reached. A child process that does not terminate immediately after that signal can continue beyond the nominal timeout.

After the fix, a 38-second run persisted the measurement

Increasing the timeout is useful only if the measurement can actually finish and its evidence is saved.

I reran another historical session and lane snapshot using the v0.10.1 CLI with the default 180-second timeout.

exit: 0
wall: 38.01s
Enter fullscreen mode Exit fullscreen mode

This time the process did more than return successfully:

CalibrationObservation: 1
cost_ledger: scope=lane
emit-metrics: coverage.status=complete
Enter fullscreen mode Exit fullscreen mode

The observation was created, the cost ledger was written, and metrics coverage reached complete.

There is also a historical PR record reporting a successful run of roughly 39 seconds. I treat that separately: the raw log containing the exact historical wall time is no longer available, so that reported value is not the same evidence as the independently reproduced 38.01-second run.

Completing a measurement does not prove the number is correct

Another boundary became important while checking the fix.

What I verified here is that the measurement process can complete, return a protocol payload, and persist its result.

That does not prove all of the following:

  • that the estimated dollar amount is correct
  • that the pricing catalog is correct
  • that a session has been attributed to the correct task

In fact, the historical record and the new reproduction produced different token counts and estimated costs. They also used different agent-cost versions.

I did not investigate the cause of that difference as part of this timeout work.

Measurement completion, cost accuracy, and task attribution are separate claims. A successful run only establishes the first one.

exit 0 can still mean measurement incomplete

There was one more edge case worth keeping.

calibrate exits with code 2 when measurement fails. usage-import, however, has a different contract.

In some measurement-failure cases it records:

measurement-incomplete
matched: false
Enter fullscreen mode Exit fullscreen mode

and writes no ledger entry, while still returning exit 0.

So this is not a safe equivalence either:

exit 0 == measurement succeeded
Enter fullscreen mode Exit fullscreen mode

The exit code, measurement state, and persisted evidence need to be interpreted separately.

Don't collapse unknown into zero

The immediate bug was a 30-second timeout. The more useful lesson for me was about state representation.

For measurement systems, these are not interchangeable:

0
unknown
failed
not measured
Enter fullscreen mode Exit fullscreen mode

Collapsing all of them into zero makes aggregation easier. It also destroys information about what actually happened.

This applies beyond AI coding cost: test results, evaluation scores, usage metrics, and observability pipelines can all run into the same problem.

The rule I kept from Issue #42 is still the simplest description:

Measurement failed != $0

As more of an engineering workflow becomes automated, preserving the difference between "the value was zero" and "we never obtained a value" becomes more important, not less.

References

A note on the version reported in the original issue

Issue #42 records the historical runtime as:

lane 0.9.1, cca0338 on main
Enter fullscreen mode Exit fullscreen mode

In Git, however, cca0338... is the peeled commit for the v0.10.0 tag, and packages/cli/package.json at that revision reports version 0.10.0.

The 30.019-second reproduction in this article was built from the cca0338... source revision.

I have not established why the historical executable reported 0.9.1, so I do not claim that the original incident occurred on the v0.10.0 CLI.

Top comments (0)