coilyco-flight-deck/agent-proxy

Watch

Streaming asks the provider for usage and never extracts it, so every streamed call records zeros #139

New issue

Closed

opened 2026-08-19 02:51:23 +00:00 by coilyco-ops · 2 comments

coilyco-ops commented

2026-08-19 02:51:23 +00:00

Member

Filed from the ops seat with a live repro, 2026-08-19. 50af3de is deployed on ser8 and the streaming path still records no usage.

Symptom

Post-roll spans on agent-proxy, upstream.chat_stream, route sirens-echo/deepseek:

gen_ai.usage.input_tokens max = 0, so the attribute is written with a zero rather than omitted
gen_ai.usage.cache_read_input_tokens = absent

The same route non-streaming records both correctly, including cache_read_input_tokens = 15616 on a repeated prefix. So parse_cache_usage and the attribute plumbing are fine. Only the streaming feed into them is not.

The two obvious causes are ruled out

The upstream does return the chunk. Called LiteLLM directly on ser8 with the agent-proxy key:

with    stream_options: 11 chunks, usage = {"completion_tokens":8,"prompt_tokens":86,
          "total_tokens":94,"prompt_tokens_details":{"cached_tokens":0}, ...}
without stream_options: 10 chunks, usage = NONE

So LiteLLM honors stream_options.include_usage and emits a usage-only final chunk carrying prompt_tokens_details.

The dialect is right. The deploy chart renders the litellm backend with "dialect" "openai", and _build_body in app/upstream.py sets stream_options for every non-ollama dialect when stream=true, which is what 50af3de added. The request is being made correctly.

Where it looks like it goes wrong

50af3de is four lines and all of them are on the request side:

+        # OpenAI-compatible streaming omits the usage block unless asked, and the
+        # cache attributes derive from it. See docs/proxy-prompt-cache.md.
+        if stream:
+            body["stream_options"] = {"include_usage": True}

parse_cache_usage is called inside chat_stream at app/upstream.py:655, but the usage it receives is evidently empty. A zero rather than a null on input_tokens is what an empty dict parsed into defaults looks like.

The usage chunk from an OpenAI-compatible stream is unusual in shape: it arrives last, after [DONE]-adjacent chunks, and carries "choices": [] with only a usage object. A normalizer that requires a choice, or that stops at the first chunk without a delta, would drop it silently. That is a guess about the mechanism. The measurements above are not a guess.

A caller-visible symptom that may be the same bug: a client streaming through agent-proxy receives no usage chunk either, 14 chunks and none carrying usage, so whatever drops it does so before the client as well as before the span.

Repro, about two minutes

# 1. streamed through agent-proxy, watch for a usage chunk and check the span after
curl -sN http://ser8:8080/v1/chat/completions \
  -H 'Content-Type: application/json' -H 'Accept: text/event-stream' \
  -d '{"model":"sirens-echo/deepseek","stream":true,"max_tokens":8,
       "messages":[{"role":"user","content":"Say ok."}]}'

# 2. the same thing one hop down, which does return usage
curl -sN http://ser8:4000/v1/chat/completions \
  -H "Authorization: Bearer $(aws ssm get-parameter --name /coilysiren/litellm/agent-proxy-key \
      --with-decryption --query Parameter.Value --output text)" \
  -H 'Content-Type: application/json' -H 'Accept: text/event-stream' \
  -d '{"model":"deploy-backend/deepseek-v4-flash","stream":true,"stream_options":{"include_usage":true},
       "max_tokens":8,"messages":[{"role":"user","content":"Say ok."}]}'

Step 2 returns a usage chunk. Step 1 does not, and its span records input_tokens = 0.

Why it matters beyond tidiness

coilyco-bridge/deploy#699 exists because the demo lane appeared to have a dead prompt cache. It does not: the cache reads at 99.3% on that route, measured non-streaming with a control. The lane is 230 of 233 streaming, so every token and cache number it produces is dark, and an entire incident review was built on a zero that only meant "not reported".

Until this is fixed, no token, cost, or cache question about any streaming consumer is answerable, and the zeros actively mislead.

Suggested acceptance

A streamed call records non-zero gen_ai.usage.input_tokens and output_tokens.
A streamed call on a repeated prefix records non-zero gen_ai.usage.cache_read_input_tokens, matching what the non-streaming path reports for the same prefix.
A test covering a usage-only final chunk with an empty choices array, since that shape is what the current code appears to drop. tests/test_prompt_cache.py already covers the request side from 50af3de and asserts nothing about the response side.

Refs coilyco-bridge/deploy#699, 50af3de

Filed from the ops seat with a live repro, 2026-08-19. `50af3de` is deployed on ser8 and the streaming path still records no usage. ## Symptom Post-roll spans on `agent-proxy`, `upstream.chat_stream`, route `sirens-echo/deepseek`: * `gen_ai.usage.input_tokens` max = **0**, so the attribute is written with a zero rather than omitted * `gen_ai.usage.cache_read_input_tokens` = **absent** The same route non-streaming records both correctly, including `cache_read_input_tokens = 15616` on a repeated prefix. So `parse_cache_usage` and the attribute plumbing are fine. Only the streaming feed into them is not. ## The two obvious causes are ruled out **The upstream does return the chunk.** Called LiteLLM directly on ser8 with the agent-proxy key: ``` with stream_options: 11 chunks, usage = {"completion_tokens":8,"prompt_tokens":86, "total_tokens":94,"prompt_tokens_details":{"cached_tokens":0}, ...} without stream_options: 10 chunks, usage = NONE ``` So LiteLLM honors `stream_options.include_usage` and emits a usage-only final chunk carrying `prompt_tokens_details`. **The dialect is right.** The deploy chart renders the litellm backend with `"dialect" "openai"`, and `_build_body` in `app/upstream.py` sets `stream_options` for every non-ollama dialect when `stream=true`, which is what `50af3de` added. The request is being made correctly. ## Where it looks like it goes wrong `50af3de` is four lines and all of them are on the request side: ```python + # OpenAI-compatible streaming omits the usage block unless asked, and the + # cache attributes derive from it. See docs/proxy-prompt-cache.md. + if stream: + body["stream_options"] = {"include_usage": True} ``` `parse_cache_usage` is called inside `chat_stream` at `app/upstream.py:655`, but the usage it receives is evidently empty. A zero rather than a null on `input_tokens` is what an empty dict parsed into defaults looks like. The usage chunk from an OpenAI-compatible stream is unusual in shape: it arrives last, after `[DONE]`-adjacent chunks, and carries `"choices": []` with only a `usage` object. A normalizer that requires a choice, or that stops at the first chunk without a delta, would drop it silently. That is a guess about the mechanism. **The measurements above are not a guess.** A caller-visible symptom that may be the same bug: a client streaming through agent-proxy receives no usage chunk either, 14 chunks and none carrying usage, so whatever drops it does so before the client as well as before the span. ## Repro, about two minutes ```sh # 1. streamed through agent-proxy, watch for a usage chunk and check the span after curl -sN http://ser8:8080/v1/chat/completions \ -H 'Content-Type: application/json' -H 'Accept: text/event-stream' \ -d '{"model":"sirens-echo/deepseek","stream":true,"max_tokens":8, "messages":[{"role":"user","content":"Say ok."}]}' # 2. the same thing one hop down, which does return usage curl -sN http://ser8:4000/v1/chat/completions \ -H "Authorization: Bearer $(aws ssm get-parameter --name /coilysiren/litellm/agent-proxy-key \ --with-decryption --query Parameter.Value --output text)" \ -H 'Content-Type: application/json' -H 'Accept: text/event-stream' \ -d '{"model":"deploy-backend/deepseek-v4-flash","stream":true,"stream_options":{"include_usage":true}, "max_tokens":8,"messages":[{"role":"user","content":"Say ok."}]}' ``` Step 2 returns a usage chunk. Step 1 does not, and its span records `input_tokens = 0`. ## Why it matters beyond tidiness `coilyco-bridge/deploy#699` exists because the demo lane appeared to have a dead prompt cache. It does not: the cache reads at 99.3% on that route, measured non-streaming with a control. The lane is **230 of 233 streaming**, so every token and cache number it produces is dark, and an entire incident review was built on a zero that only meant "not reported". Until this is fixed, no token, cost, or cache question about any streaming consumer is answerable, and the zeros actively mislead. ## Suggested acceptance * A streamed call records non-zero `gen_ai.usage.input_tokens` and `output_tokens`. * A streamed call on a repeated prefix records non-zero `gen_ai.usage.cache_read_input_tokens`, matching what the non-streaming path reports for the same prefix. * A test covering a usage-only final chunk with an empty `choices` array, since that shape is what the current code appears to drop. `tests/test_prompt_cache.py` already covers the request side from `50af3de` and asserts nothing about the response side. Refs `coilyco-bridge/deploy#699`, `50af3de`

coilyco-ops referenced this issue

2026-08-19 03:13:03 +00:00

Streaming requests never ask for usage, so the prompt-cache accounting cannot run on 94% of traffic #138

coilyco-ops commented

2026-08-19 03:13:06 +00:00

Author

Member

Fixed, and the fix landed 15 minutes after this was filed.

2026-08-19 02:51Z  this issue filed against 50af3de
2026-08-19 03:06Z  f4a59d3  fix(cache): read usage from the trailing chunk that carries it

f4a59d3 is on main and adds _fold_stream_usage, plus an elif payload.get("usage") branch beside the finish_reason one. That is exactly the mechanism this issue identified: the request was asking correctly and LiteLLM was answering correctly, and the normalizer read usage only in the branch that never sees it.

Verified deployed rather than assumed. SigNoz, agent-proxy, 3h window ending ~07:00Z:

upstream.chat_stream   max gen_ai.usage.input_tokens             66,812
upstream.chat_stream   sum gen_ai.usage.cache_read_input_tokens 178,688

This issue measured input_tokens max = 0 and cache_read_input_tokens absent. Both are now populated. The live repro and the ruling-out of the two obvious causes are what made the second half findable quickly - the direct LiteLLM call proving stream_options was honoured is what pointed at the normalizer rather than the request.

Closing.

**Fixed, and the fix landed 15 minutes after this was filed.** ``` 2026-08-19 02:51Z this issue filed against 50af3de 2026-08-19 03:06Z f4a59d3 fix(cache): read usage from the trailing chunk that carries it ``` `f4a59d3` is on `main` and adds `_fold_stream_usage`, plus an `elif payload.get("usage")` branch beside the `finish_reason` one. That is exactly the mechanism this issue identified: the request was asking correctly and LiteLLM was answering correctly, and the normalizer read usage only in the branch that never sees it. Verified deployed rather than assumed. SigNoz, agent-proxy, 3h window ending ~07:00Z: ``` upstream.chat_stream max gen_ai.usage.input_tokens 66,812 upstream.chat_stream sum gen_ai.usage.cache_read_input_tokens 178,688 ``` This issue measured `input_tokens` max = 0 and `cache_read_input_tokens` absent. Both are now populated. The live repro and the ruling-out of the two obvious causes are what made the second half findable quickly - the direct LiteLLM call proving `stream_options` was honoured is what pointed at the normalizer rather than the request. Closing.

coilyco-ops closed this issue

2026-08-19 03:13:09 +00:00

coilyco-ops referenced this issue

2026-08-19 03:13:46 +00:00

Token usage stops at LiteLLM: agent-proxy records 0 and the harness records nothing #135

coilyco-ops commented

2026-08-19 04:35:23 +00:00

Author

Member

Withdrawing this. It is wrong. 50af3de works and streaming usage extraction is fine. Olaf (ops seat), 2026-08-19.

I claimed agent-proxy asks the provider for usage on streaming and never extracts it, on the strength of spans showing input_tokens = 0 and no cache attribute after the roll.

Real lane traffic disproves it. Over 30 minutes on sirens-echo/deepseek, 49 streaming calls, all post-roll:

max gen_ai.usage.cache_read_input_tokens    99,456
max gen_ai.usage.input_tokens              100,262
sum cache_read_input_tokens              1,686,144
sum input_tokens                         2,550,772   -> 66.1% hit rate

upstream.chat_stream carries both attributes. The parse_cache_usage call at app/upstream.py:655 is doing its job.

Where I went wrong: I probed with two hand-written streaming requests immediately after the roll, saw no usage on their spans, and generalised from a sample of two synthetic calls to the entire code path. I then went looking for a mechanism to explain a defect that was not there, and found a plausible-sounding one in the shape of the usage-only final chunk. Plausible is not measured.

Why my specific probe produced no usage is unresolved. Candidates are the tiny max_tokens, the client closing early, or something about a direct caller versus the harness's path. None of it is worth chasing, and none of it is evidence about agent-proxy.

Nothing in this issue should inform work. The repro steps do not reproduce a defect. Closing.

Refs coilyco-bridge/deploy#699

**Withdrawing this. It is wrong. `50af3de` works and streaming usage extraction is fine.** Olaf (ops seat), 2026-08-19. I claimed agent-proxy asks the provider for usage on streaming and never extracts it, on the strength of spans showing `input_tokens = 0` and no cache attribute after the roll. Real lane traffic disproves it. Over 30 minutes on `sirens-echo/deepseek`, 49 streaming calls, all post-roll: ``` max gen_ai.usage.cache_read_input_tokens 99,456 max gen_ai.usage.input_tokens 100,262 sum cache_read_input_tokens 1,686,144 sum input_tokens 2,550,772 -> 66.1% hit rate ``` `upstream.chat_stream` carries both attributes. The `parse_cache_usage` call at `app/upstream.py:655` is doing its job. **Where I went wrong:** I probed with two hand-written streaming requests immediately after the roll, saw no usage on their spans, and generalised from a sample of two synthetic calls to the entire code path. I then went looking for a mechanism to explain a defect that was not there, and found a plausible-sounding one in the shape of the usage-only final chunk. Plausible is not measured. Why my specific probe produced no usage is unresolved. Candidates are the tiny `max_tokens`, the client closing early, or something about a direct caller versus the harness's path. None of it is worth chasing, and none of it is evidence about agent-proxy. Nothing in this issue should inform work. The repro steps do not reproduce a defect. Closing. Refs `coilyco-bridge/deploy#699`

No milestone

No project

No assignees

1 participant

Notifications

Due date

The due date is invalid or out of range. Please use the format "yyyy-mm-dd".

No due date set.

Dependencies

No dependencies set

Reference

coilyco-flight-deck/agent-proxy#139

No description provided.

Rows
Columns