fix(ai-proxy): report error-path latency vars in milliseconds#13711
Merged
AlinsRan merged 6 commits intoJul 22, 2026
Conversation
The AI latency vars were only assigned on the success path, so a 429/5xx early exit left them empty and the log phase filled $apisix_upstream_response_time from nginx $upstream_response_time, which is in seconds. The same 0.2s upstream latency was therefore logged as `201` for a 200 and `0.200` for a 500, and $llm_time_to_first_token was stuck at 0 for every non-200. Assign both vars on the early-exit paths from the same clock the success path uses, so error responses are comparable with served ones. Requests that never reached the upstream stay unset, and $llm_time_to_first_token stays 0 on transport errors, where no first token ever arrived. Since llm_time_to_first_token now carries a real value on errors, guard the prometheus llm_latency observation with a status check: that histogram has no status label and must keep measuring served responses. Fixes apache#13698
dosubot
Bot
added
size:L
Assert that a 200, a 500 and a 429 through the same route produce exactly one llm_latency observation. Without the guard the count is 3.
The counters are buffered per worker and only reach the shared dict on the sync interval, so a 0.5s sleep raced with it and the metric came back missing in CI.
The poll for the prometheus counter can outlast the default 5s block timeout, so the block died on a client socket timeout rather than on its assertion.
The metric read depends on the prometheus counter reaching the shared dict, which needs the HUP + fixture harness that prometheus-ai-proxy.t uses; a bare mock does not flush reliably on the upstream CI, so the assertion failed there while passing locally. The latency-var behavior this file is about is fully covered by the log-phase cases; the exporter status guard was verified separately by fail-on-old.
The status < 400 guard added to the llm_latency observation had no CI coverage. Add a case that sends a served 200 and a 429 through the same route and asserts the observation count stays 1, not 2. Verified it is discriminating: it fails when the guard is removed.
nic-6443
approved these changes
Jul 21, 2026
shreemaan-abhishek
approved these changes
Jul 22, 2026
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
4 participants
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Description
Fixes #13698
$apisix_upstream_response_timeand$llm_time_to_first_tokenchanged unit depending on the upstream status code.The AI latency vars are only assigned on the success path (
ai-providers/base.lua), in milliseconds. The 429/5xx early exit inai-proxy/base.luareturns without setting them, so the log-phase fallback ininit.luafills$apisix_upstream_response_timefrom nginx$upstream_response_time— which is in seconds. For the same 0.2s upstream latency:A 1000x difference in the same log field, which breaks latency aggregation and alert rules.
This assigns both vars on the early-exit paths using the same clock source the success path uses (
ctx.llm_request_start_time), so an error response is comparable with a served one:apisix_upstream_response_timellm_time_to_first_token0— no first token ever arrivedpcall(do_request)init.lua's fallback is deliberately left alone: it also serves non-AI routes, where mirroring nginx$upstream_response_timein seconds is the existing documented behaviour. After this change the fallback is simply unreachable for AI routes that reached the upstream.Because
llm_time_to_first_tokennow carries a real value on errors, the prometheusllm_latencyobservation needed astatus < 400guard — that histogram has no status label, and letting fast 429 rejections in would skew the percentiles used for capacity planning. One small side effect of the guard: a request where the upstream returned 200 but the body could not be parsed (plugin ends up returning 500) is now excluded fromllm_latency; that sample was anomalous to begin with.Behaviour change to note in the changelog: on 429/5xx,
$apisix_upstream_response_timegoes from a seconds decimal to a milliseconds integer, and$llm_time_to_first_tokenfrom0to a real value. That is the unification the issue asks for, but anyone who wrote a dashboard specifically around the old error-path unit will need to adjust.Tests
New
t/plugin/ai-proxy-latency-vars.tcovers 200 / 500 / 429 / transport error, plus a case where a 200 and a 500 happen in one nginx lifecycle. Verified it is discriminating: on master 4 of its subtests fail (the 500, 429, mixed-lifecycle and transport-error cases) and pass with this change, while the 200 case passes either way, pinning the success path against regression.Existing
t/plugin/ai-proxy*.t,t/plugin/ai-proxy-multi*.tandt/plugin/prometheus-ai-proxy.twere run against this branch with no new failures.