lxbme commented on issue #13698:
URL: https://github.com/apache/apisix/issues/13698#issuecomment-5018436454
I spend some time and reproduced this on current master (9ba97699) and can
confirm the unit inconsistency, though the affected scope is narrower than
described. Details below.
## Reproduction
Test setup: an `ai-proxy` route pointing at a mock LLM upstream that sleeps
0.5s before responding, then returns a chosen status code. Access log format
logs `$upstream_addr $upstream_status $apisix_upstream_response_time ...
$llm_time_to_first_token`:
| Upstream status | Access log excerpt | `$apisix_upstream_response_time`
unit |
|---|---|---|
| 200 | `127.0.0.1:6724 200 503` | **milliseconds** (integer) |
| 400 | `127.0.0.1:6724 400 503` | **milliseconds** (integer) |
| 429 | `127.0.0.1:6724 429 0.509` | **seconds** (decimal) |
| 500 | `127.0.0.1:6724 500 0.5xx` | **seconds** (decimal) |
The same ~0.5s wall-clock duration is logged as `503` on success and `0.509`
on 429/5xx — a 1000x unit mismatch, exactly as reported.
## Root cause
1. **Success path**: `apisix/plugins/ai-providers/base.lua` explicitly
assigns `ctx.var.apisix_upstream_response_time` and
`ctx.var.llm_time_to_first_token` in milliseconds (e.g. `math.floor((ngx_now()
- ctx.llm_request_start_time) * 1000)`).
2. **429/5xx early-return path**: `apisix/plugins/ai-proxy/base.lua` (the
block quoted in the issue) only calls
`apisix_upstream.update_upstream_state({response_time = ms})`, which feeds
nginx's internal upstream state (the C API expects milliseconds —
`response_time_ms`), but never assigns either ctx var before `return
res.status`.
3. **Fallback introduces seconds**: in the log phase, `apisix/init.lua`
falls back to nginx's native `$upstream_response_time` when the ctx var is
empty — and nginx renders that variable in seconds with millisecond precision
(`0.509`).
## Two corrections to the report
- **It is not "all non-200 responses"**. Non-429 4xx (e.g. 400, 401) flow
through the normal response-handling path and get milliseconds (see the 400 row
above). The seconds fallback only hits the early-return paths in
`apisix/plugins/ai-proxy/base.lua`: the 429/5xx branch, the "no response body
-> 500" branch, and the transport-error branch (where no upstream response
exists at all).
- **`llm_time_to_first_token` does not switch to seconds — it stays at its
default `"0"`** on those paths (visible in the 429 row). A side effect worth
noting: the Prometheus exporter gates `llm_latency` observation on
`llm_time_to_first_token ~= "0"`, so all 429/5xx requests are silently dropped
from the `apisix_llm_latency` histogram — the latency of failing LLM requests
is currently unobservable there.
## Suggested fix direction
On the early-return paths, assign `ctx.var.apisix_upstream_response_time =
math.floor((ngx_now() - res._t0) * 1000)` alongside the existing
`update_upstream_state` calls, matching the success-path convention
(milliseconds is what the docs and the success path already use).
`llm_time_to_first_token` is arguably correct to leave at `0` for error
responses that never produce a token — TTFT is semantically undefined there —
but that choice affects whether `llm_latency` starts observing failed requests,
so it deserves an explicit decision in the fix.
I have a reproduction test and happy to send a PR .
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: [email protected]
For queries about this service, please contact Infrastructure at:
[email protected]
