fix: emit dynamic metadata on error responses for access-log attribution - #2441
fix: emit dynamic metadata on error responses for access-log attribution#2441Aias00 wants to merge 1 commit into
Conversation
Codecov Report✅ All modified and coverable lines are covered by tests. Additional details and impacted files@@ Coverage Diff @@
## main #2441 +/- ##
==========================================
+ Coverage 84.86% 84.89% +0.03%
==========================================
Files 154 154
Lines 22419 22427 +8
==========================================
+ Hits 19026 19040 +14
+ Misses 2237 2233 -4
+ Partials 1156 1154 -2 ☔ View full report in Codecov by Harness. 🚀 New features to boost your workflow:
|
|
@kanurag94 can you take a look? |
| // behavioral change. responseModel is empty because error responses carry no model. | ||
| if body.EndOfStream && u.parent.config != nil && | ||
| (len(u.parent.config.GlobalRequestCosts) > 0 || len(u.parent.config.RequestCosts) > 0) { | ||
| metadata, mdErr := buildDynamicMetadata(u.parent.config.GlobalRequestCosts, u.parent.config.RequestCosts, &u.costs, u.requestHeaders, u.backendName, u.routeName, internalapi.ResponseModel("")) |
There was a problem hiding this comment.
I am worried about division by zero for CEL expressions since input_tokens/ total_tokens can become 0 now and this will error. Can you see if we can skip and log it confidently instead of returning an error?
There was a problem hiding this comment.
Good catch. The error path now logs a warning and skips emitting metadata instead of returning the error: if mdErr != nil { u.logger.Warn(...); } else { resp.DynamicMetadata = metadata }.
One nuance worth noting: llmcostcel.NewProgram sanity-checks every CEL expression at all-zero token counts (cel.go), which is the exact state of a failed request (the error path never parses tokens, so all costs stay 0). So a division-by-zero on zero tokens is already rejected at program creation time, before it can ever reach the error path. The log-and-skip guard is defensive against any other CEL runtime error (e.g. unsigned integer overflow), and there is now a unit test that pre-sets costs to trigger such an overflow and asserts the response still succeeds with nil metadata.
| // access log. backend_name and model_name_override are known from the request | ||
| // phase (SetBackend), so unlike token usage they do not depend on a successful | ||
| // response body. Token costs are 0 on errors (no tokens consumed), so the | ||
| // rate-limit stream-done hits_addend stays 0 — observability only, no quota |
There was a problem hiding this comment.
The hits_addend stays 0, but I don't think the descriptor stays out of it.
baseDescriptorActions() builds the stream-done entry from the ai_service_backend_name and model_name_override metadata keys and neither action sets default_value or skip_if_absent, so today those keys are absent on a non-2xx and Envoy never populates that descriptor - no stream-done ratelimit call goes out at all.
After this change all three keys are present (quota_cost renders as "0" since the controller injects the quota cost expression as an LLMRequestCost), so the apply_on_stream_done entry will fire on every failed request.
Can we get an e2e confirming a 500 doesn't decrement quota?
There was a problem hiding this comment.
You are right — the stream-done descriptor does fire on failed requests now, whereas before it never did (backend_name/model_name_override were absent). The token-cost hits_addend is still 0, so no token quota is charged, but the descriptor is sent.
To confirm the user-visible effect is unchanged, I added an e2e in tests/e2e/backend_quota_ratelimit_test.go: "non-2xx response does not charge token quota". It makes the upstream return 500 with a body claiming 100 total_tokens, then asserts the next request still succeeds (200). If those 100 tokens were charged, the 10-token-per-hour limit would be exceeded and the next request would 429. CI runs this as part of Test_Examples_BackendQuotaRateLimit.
| t.Run("non-2xx status emits dynamic metadata at end of stream", func(t *testing.T) { | ||
| inBody := &extprocv3.HttpBody{Body: []byte("error-body"), EndOfStream: true} | ||
| mm := &mockMetrics{} | ||
| mt := &mockTranslator{t: t, expResponseBody: inBody, |
There was a problem hiding this comment.
| mt := &mockTranslator{t: t, expResponseBody: inBody, | |
| mt := &mockTranslator{ | |
| t: t, expResponseBody: inBody, |
| require.False(t, ok) | ||
| mm.RequireRequestFailure(t) | ||
| }) | ||
|
|
There was a problem hiding this comment.
Can you please add:
- Case with
EndOfStream: falseasserting we don't emit metadata - Case with
GlobalRequestCosts
There was a problem hiding this comment.
Added both:
- "non-2xx status does not emit metadata before end of stream" — EndOfStream:false, asserts res.DynamicMetadata is nil.
- "non-2xx status emits global request costs" — uses GlobalRequestCosts (OutputToken + TotalToken) and asserts the keys are present with 0 and backend_name is set.
Also added "non-2xx status skips metadata on CEL error" covering the skip-and-log path above.
ProcessResponseBody returned early on non-2xx responses after calling translator.ResponseError, skipping buildDynamicMetadata. As a result resp.DynamicMetadata stayed nil for failed requests and the access log read every LLM dimension as null: gen_ai.provider.name, gen_ai.response.model and all gen_ai.usage.* token fields (input/output/total/reasoning), even though the request had been routed to a backend (upstream_host was populated). Operators could not attribute failed LLM calls to a backend, route, or model from the access log alone, and the recently surfaced gen_ai.usage.reasoning_tokens was null precisely for the failed reasoning calls that are hardest to debug. backend_name and model_name_override are known at request time (SetBackend) and do not depend on a successful response body, so there is no reason to withhold them on errors. On the error branch, when body.EndOfStream and request costs are configured, call buildDynamicMetadata with responseModel empty and attach it to resp.DynamicMetadata, mirroring the success path. Token costs are 0 on errors (no tokens consumed), so the rate-limit stream-done hits_addend stays 0: observability only, no quota behavioral change. response_model stays absent on errors because error responses carry no model. Verified live: a gpt-4o-mini request rejected by the upstream with 400 previously produced an access log with gen_ai.provider.name=null and gen_ai.usage.input_tokens=null; after the fix the same 400 carries gen_ai.provider.name="default/openai/route/aigw-run/rule/0/ref/0" and gen_ai.usage.input_tokens=0. Fixes envoyproxy#2440 Signed-off-by: liuhy <liuhongyu@apache.org>
cef6b4b to
8bf1cc8
Compare
Description
When an upstream LLM returns a non-2xx response, ProcessResponseBody returns
early after translator.ResponseError and never calls buildDynamicMetadata.
resp.DynamicMetadata stays nil, so the access log reads every LLM dimension as
null for failed requests: gen_ai.provider.name, gen_ai.response.model, and all
gen_ai.usage.* token fields (input/output/total/reasoning), even though the
request was routed to a backend (upstream_host is populated).
This defeats the access log for exactly the requests operators most need to
debug, and nullifies gen_ai.usage.reasoning_tokens for failed reasoning-model
calls.
backend_name and model_name_override are known at request time (SetBackend) and
do not depend on a successful response body, so withholding them on errors is
unjustified.
Fix
On the error branch of ProcessResponseBody, when body.EndOfStream and request
costs are configured, call buildDynamicMetadata with responseModel empty and
attach it to resp.DynamicMetadata, mirroring the success path. Updated the
buildDynamicMetadata doc comment accordingly.
stream-done hits_addend (which reads the cost via quotaHitsAddend) stays 0:
observability only, no quota behavioral change.
(buildDynamicMetadata only emits it when non-empty).
Test
Added a subtest "non-2xx status emits dynamic metadata at end of stream"
asserting backend_name, ai_service_backend_name, model_name_override, route_name
are present and token costs are 0, response_model absent, on a 500 response.
go test ./internal/extproc/... passes.
Verified live
aigw run against an OpenAI-compatible backend, sending a request the upstream
rejects (gpt-4o-mini, 400):
Before: gen_ai.provider.name=null, gen_ai.usage.input_tokens=null,
gen_ai.usage.output_tokens=null, gen_ai.usage.reasoning_tokens=null
(upstream_host present).
After: gen_ai.provider.name="default/openai/route/aigw-run/rule/0/ref/0",
gen_ai.usage.input_tokens=0, gen_ai.usage.output_tokens=0.
reasoning_tokens is null on this branch only because the reasoning cost rule
itself is added by a separate change (#2438); once configured, it follows the
same path and will read 0 on errors instead of null.
Fixes #2440