From 0a7237b998c2e06460272ca803c09f44a38592ad Mon Sep 17 00:00:00 2001 From: AlinsRan Date: Mon, 20 Jul 2026 12:30:48 +0800 Subject: [PATCH 1/6] fix(ai-proxy): report error-path latency vars in milliseconds 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 #13698 --- apisix/plugins/ai-proxy/base.lua | 21 +++ apisix/plugins/prometheus/exporter.lua | 5 +- docs/en/latest/plugins/ai-proxy-multi.md | 4 +- docs/en/latest/plugins/ai-proxy.md | 5 +- docs/zh/latest/plugins/ai-proxy-multi.md | 4 +- docs/zh/latest/plugins/ai-proxy.md | 4 +- t/plugin/ai-proxy-latency-vars.t | 203 +++++++++++++++++++++++ 7 files changed, 237 insertions(+), 9 deletions(-) create mode 100644 t/plugin/ai-proxy-latency-vars.t diff --git a/apisix/plugins/ai-proxy/base.lua b/apisix/plugins/ai-proxy/base.lua index 97c980dc5028..f16ffd34a6a1 100644 --- a/apisix/plugins/ai-proxy/base.lua +++ b/apisix/plugins/ai-proxy/base.lua @@ -23,6 +23,7 @@ local pcall = pcall local pairs = pairs local type = type local table = table +local math_floor = math.floor local exporter = require("apisix.plugins.prometheus.exporter") local protocols = require("apisix.plugins.ai-protocols") local transport_http = require("apisix.plugins.ai-transport.http") @@ -70,6 +71,23 @@ local function read_upstream_error_body(res) return body end + +-- Fill the AI latency vars in MILLISECONDS on the early-exit paths, using the +-- same clock as the success path (ctx.llm_request_start_time, reset at the +-- start of every attempt). Without this the log phase falls back to nginx +-- $upstream_response_time, which is in seconds, so a 429/5xx would report a +-- value 1000x off from a 200 for the same upstream latency. +local function set_error_latency_vars(ctx, upstream_responded) + local elapsed_ms = math_floor((ngx_now() - ctx.llm_request_start_time) * 1000) + ctx.var.apisix_upstream_response_time = elapsed_ms + if upstream_responded then + -- the error response is the only payload the upstream produced, so the + -- time until we knew it answered is this request's time to first token + ctx.var.llm_time_to_first_token = elapsed_ms + end +end + + function _M.set_logging(ctx, summaries, payloads) if summaries then ctx.llm_summary = { @@ -297,6 +315,7 @@ function _M.before_proxy(conf, ctx, on_error) }) end end + set_error_latency_vars(ctx, false) return transport_http.handle_error(transport_err) end @@ -338,6 +357,7 @@ function _M.before_proxy(conf, ctx, on_error) if res._httpc then res._httpc:close() end + set_error_latency_vars(ctx, true) return res.status, error_body end @@ -352,6 +372,7 @@ function _M.before_proxy(conf, ctx, on_error) if res._httpc then res._httpc:close() end + set_error_latency_vars(ctx, true) return 500 end diff --git a/apisix/plugins/prometheus/exporter.lua b/apisix/plugins/prometheus/exporter.lua index ca71a197230a..4b6ead0b719c 100644 --- a/apisix/plugins/prometheus/exporter.lua +++ b/apisix/plugins/prometheus/exporter.lua @@ -604,7 +604,10 @@ function _M.http_log(conf, ctx) if vars.request_type == "ai_stream" or vars.request_type == "ai_chat" then local llm_time_to_first_token = vars.llm_time_to_first_token - if llm_time_to_first_token ~= "0" then + -- error responses (429/5xx) also carry a real millisecond value in + -- llm_time_to_first_token, so filter them out here: llm_latency has no + -- status label and must keep measuring served responses only. + if llm_time_to_first_token ~= "0" and (tonumber(vars.status) or 0) < 400 then -- type="total": full response latency. For non-streaming this equals -- llm_time_to_first_token; for streaming, that var holds only the -- TTFT, so use apisix_upstream_response_time (refreshed on every diff --git a/docs/en/latest/plugins/ai-proxy-multi.md b/docs/en/latest/plugins/ai-proxy-multi.md index a91b0f43b160..88a1274ef491 100644 --- a/docs/en/latest/plugins/ai-proxy-multi.md +++ b/docs/en/latest/plugins/ai-proxy-multi.md @@ -2600,9 +2600,9 @@ For verification, the behaviours should be consistent with the verification in [ The following example demonstrates how you can log LLM request related information in the gateway's access log to improve analytics and audit. The following variables are available: * `request_llm_model`: LLM model name specified in the request. -* `apisix_upstream_response_time`: Time taken for APISIX to send the request to the upstream service and receive the full response. +* `apisix_upstream_response_time`: Time taken for APISIX to send the request to the upstream service and receive the full response, in milliseconds. Error responses from the LLM service (such as 429 or 5xx) are also recorded in milliseconds. * `request_type`: Type of request, where the value could be `traditional_http`, `ai_chat`, or `ai_stream`. -* `llm_time_to_first_token`: Duration from request sending to the first token received from the LLM service, in milliseconds. +* `llm_time_to_first_token`: Duration from request sending to the first token received from the LLM service, in milliseconds. For an error response from the LLM service, this is the duration until the error response was received. It stays `0` when the LLM service could not be reached at all. * `llm_model`: LLM model. * `llm_prompt_tokens`: Number of tokens in the prompt. * `llm_completion_tokens`: Number of chat completion tokens in the response. diff --git a/docs/en/latest/plugins/ai-proxy.md b/docs/en/latest/plugins/ai-proxy.md index 17992d03f6df..b93702ed00af 100644 --- a/docs/en/latest/plugins/ai-proxy.md +++ b/docs/en/latest/plugins/ai-proxy.md @@ -2077,8 +2077,9 @@ In the Kafka topic, you should also see a log entry corresponding to the request The following example demonstrates how you can log LLM request related information in the gateway's access log to improve analytics and audit. The following variables are available: * `request_llm_model`: LLM model name specified in the request. +* `apisix_upstream_response_time`: Time taken for APISIX to send the request to the upstream service and receive the full response, in milliseconds. Error responses from the LLM service (such as 429 or 5xx) are also recorded in milliseconds. * `request_type`: Type of request, where the value could be `traditional_http`, `ai_chat`, or `ai_stream`. -* `llm_time_to_first_token`: Duration from request sending to the first token received from the LLM service, in milliseconds. +* `llm_time_to_first_token`: Duration from request sending to the first token received from the LLM service, in milliseconds. For an error response from the LLM service, this is the duration until the error response was received. It stays `0` when the LLM service could not be reached at all. * `llm_model`: LLM model. * `llm_prompt_tokens`: Number of tokens in the prompt. * `llm_completion_tokens`: Number of chat completion tokens in the response. @@ -2111,7 +2112,7 @@ Update the access log format in your configuration file to include additional LL ```yaml title="conf/config.yaml" nginx_config: http: - access_log_format: "$remote_addr - $remote_user [$time_local] $http_host \"$request_line\" $status $body_bytes_sent $request_time \"$http_referer\" \"$http_user_agent\" $upstream_addr $upstream_status $upstream_response_time \"$upstream_scheme://$upstream_host$upstream_uri\" \"$apisix_request_id\" \"$request_type\" \"$llm_time_to_first_token\" \"$llm_model\" \"$request_llm_model\" \"$llm_prompt_tokens\" \"$llm_completion_tokens\"" + access_log_format: "$remote_addr - $remote_user [$time_local] $http_host \"$request_line\" $status $body_bytes_sent $request_time \"$http_referer\" \"$http_user_agent\" $upstream_addr $upstream_status $apisix_upstream_response_time \"$upstream_scheme://$upstream_host$upstream_uri\" \"$apisix_request_id\" \"$request_type\" \"$llm_time_to_first_token\" \"$llm_model\" \"$request_llm_model\" \"$llm_prompt_tokens\" \"$llm_completion_tokens\"" ``` Reload APISIX for configuration changes to take effect. diff --git a/docs/zh/latest/plugins/ai-proxy-multi.md b/docs/zh/latest/plugins/ai-proxy-multi.md index 8f3ea99dc615..2e18dd9b9381 100644 --- a/docs/zh/latest/plugins/ai-proxy-multi.md +++ b/docs/zh/latest/plugins/ai-proxy-multi.md @@ -2710,9 +2710,9 @@ curl "http://127.0.0.1:9080/anything" -X POST \ 以下示例演示了如何在网关的访问日志中记录 LLM 请求相关信息，以改进分析和审计。以下变量可用： * `request_llm_model`：请求中指定的 LLM 模型名称。 -* `apisix_upstream_response_time`：APISIX 向上游服务发送请求并接收完整响应所花费的时间 +* `apisix_upstream_response_time`：APISIX 向上游服务发送请求并接收完整响应所花费的时间（毫秒）。LLM 服务返回的错误响应（如 429 或 5xx）同样以毫秒记录。 * `request_type`：请求类型，值可能是 `traditional_http`、`ai_chat` 或 `ai_stream`。 -* `llm_time_to_first_token`：从发送请求到从 LLM 服务接收第一个令牌的持续时间（毫秒）。 +* `llm_time_to_first_token`：从发送请求到从 LLM 服务接收第一个令牌的持续时间（毫秒）。当 LLM 服务返回错误响应时，该值为收到错误响应为止的持续时间；当完全无法连接到 LLM 服务时，该值保持为 `0`。 * `llm_model`：LLM 模型。 * `llm_prompt_tokens`：提示中的令牌数量。 * `llm_completion_tokens`：响应中的聊天完成令牌数量。 diff --git a/docs/zh/latest/plugins/ai-proxy.md b/docs/zh/latest/plugins/ai-proxy.md index aa5d0cce92d0..62a1b4eae41e 100644 --- a/docs/zh/latest/plugins/ai-proxy.md +++ b/docs/zh/latest/plugins/ai-proxy.md @@ -2076,9 +2076,9 @@ curl "http://127.0.0.1:9080/anything" -X POST \ 以下示例演示了如何在网关的访问日志中记录 LLM 请求相关信息，以改进分析和审计。以下变量可用： * `request_llm_model`：请求中指定的 LLM 模型名称。 -* `apisix_upstream_response_time`：APISIX 向上游服务发送请求并接收完整响应所花费的时间 +* `apisix_upstream_response_time`：APISIX 向上游服务发送请求并接收完整响应所花费的时间（毫秒）。LLM 服务返回的错误响应（如 429 或 5xx）同样以毫秒记录。 * `request_type`：请求类型，值可能是 `traditional_http`、`ai_chat` 或 `ai_stream`。 -* `llm_time_to_first_token`：从发送请求到从 LLM 服务接收第一个令牌的持续时间（毫秒）。 +* `llm_time_to_first_token`：从发送请求到从 LLM 服务接收第一个令牌的持续时间（毫秒）。当 LLM 服务返回错误响应时，该值为收到错误响应为止的持续时间；当完全无法连接到 LLM 服务时，该值保持为 `0`。 * `llm_model`：LLM 模型。 * `llm_prompt_tokens`：提示中的令牌数量。 * `llm_completion_tokens`：响应中的聊天完成令牌数量。 diff --git a/t/plugin/ai-proxy-latency-vars.t b/t/plugin/ai-proxy-latency-vars.t new file mode 100644 index 000000000000..1c4dc965ec68 --- /dev/null +++ b/t/plugin/ai-proxy-latency-vars.t @@ -0,0 +1,203 @@ +# +# Licensed to the Apache Software Foundation (ASF) under one or more +# contributor license agreements. See the NOTICE file distributed with +# this work for additional information regarding copyright ownership. +# The ASF licenses this file to You under the Apache License, Version 2.0 +# (the "License"); you may not use this file except in compliance with +# the License. You may obtain a copy of the License at +# +# http://www.apache.org/licenses/LICENSE-2.0 +# +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an "AS IS" BASIS, +# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +# See the License for the specific language governing permissions and +# limitations under the License. +# + +use t::APISIX 'no_plan'; + +log_level("info"); +repeat_each(1); +no_long_string(); +no_root_location(); + + +add_block_preprocessor(sub { + my ($block) = @_; + + if (!defined $block->request) { + $block->set_value("request", "GET /t"); + } + + my $http_config = $block->http_config // <<_EOC_; + server { + server_name openai; + listen 18724; + + default_type 'application/json'; + + location /v1/chat/completions { + content_by_lua_block { + ngx.sleep(0.2) + ngx.req.read_body() + local body = ngx.req.get_body_data() or "" + local status = ngx.req.get_headers()["x-test-status"] + if status == "500" or body:find("FAIL", 1, true) then + ngx.status = 500 + ngx.say('{"error":"internal"}') + return + end + if status == "429" then + ngx.status = 429 + ngx.say('{"error":"rate limited"}') + return + end + ngx.say('{"choices":[{"finish_reason":"stop","index":0,"message":{"content":"2","role":"assistant"}}],"model":"gpt-4","object":"chat.completion","usage":{"completion_tokens":5,"prompt_tokens":8,"total_tokens":13}}') + } + } + } +_EOC_ + + $block->set_value("http_config", $http_config); +}); + +run_tests(); + +__DATA__ + +=== TEST 1: set up a route with ai-proxy and a log-phase printer of both vars +--- config + location /t { + content_by_lua_block { + local t = require("lib.test_admin").test + local code, body = t('/apisix/admin/routes/1', + ngx.HTTP_PUT, + [[{ + "uri": "/anything", + "plugins": { + "ai-proxy": { + "provider": "openai", + "auth": {"header": {"Authorization": "Bearer token"}}, + "options": {"model": "gpt-4"}, + "override": {"endpoint": "http://localhost:18724"}, + "ssl_verify": false + }, + "serverless-post-function": { + "phase": "log", + "functions": ["return function(conf, ctx) ngx.log(ngx.WARN, \"LATENCYVARS status=\", ngx.status, \" aurt=\", tostring(ctx.var.apisix_upstream_response_time), \" ttft=\", tostring(ctx.var.llm_time_to_first_token)) end"] + } + } + }]] + ) + if code >= 300 then + ngx.status = code + end + ngx.say(body) + } + } +--- response_body +passed + + + +=== TEST 2: 200 response records both vars in milliseconds +--- request +POST /anything +{ "messages": [ { "role": "user", "content": "What is 1+1?"} ] } +--- error_code: 200 +--- error_log eval +qr/LATENCYVARS status=200 aurt=\d{3,4}(?![\.\d]) ttft=\d{3,4}(?![\.\d])/ + + + +=== TEST 3: 500 early exit records both vars in milliseconds, not seconds +--- request +POST /anything +{ "messages": [ { "role": "user", "content": "What is 1+1?"} ] } +--- more_headers +x-test-status: 500 +--- error_code: 500 +--- error_log eval +qr/LATENCYVARS status=500 aurt=\d{3,4}(?![\.\d]) ttft=\d{3,4}(?![\.\d])/ + + + +=== TEST 4: 429 early exit records both vars in milliseconds +--- request +POST /anything +{ "messages": [ { "role": "user", "content": "What is 1+1?"} ] } +--- more_headers +x-test-status: 429 +--- error_code: 429 +--- error_log eval +qr/LATENCYVARS status=429 aurt=\d{3,4}(?![\.\d]) ttft=\d{3,4}(?![\.\d])/ + + + +=== TEST 5: the unit no longer flips between a 200 and a 500 in one lifecycle +--- config + location /t { + content_by_lua_block { + local http = require "resty.http" + local uri = "http://127.0.0.1:" .. ngx.var.server_port .. "/anything" + local body_ok = [[{ "messages": [ { "role": "user", "content": "ok"} ] }]] + local body_fail = [[{ "messages": [ { "role": "user", "content": "FAIL"} ] }]] + local res1 = http.new():request_uri(uri, {method = "POST", body = body_ok}) + local res2 = http.new():request_uri(uri, {method = "POST", body = body_fail}) + ngx.sleep(0.5) + ngx.say(res1.status, " ", res2.status) + } + } +--- request +GET /t +--- response_body +200 500 +--- error_log eval +[qr/LATENCYVARS status=200 aurt=\d{3,4}(?![\.\d]) ttft=\d{3,4}(?![\.\d])/, + qr/LATENCYVARS status=500 aurt=\d{3,4}(?![\.\d]) ttft=\d{3,4}(?![\.\d])/] + + + +=== TEST 6: set up a route pointing at a dead upstream +--- config + location /t { + content_by_lua_block { + local t = require("lib.test_admin").test + local code, body = t('/apisix/admin/routes/1', + ngx.HTTP_PUT, + [[{ + "uri": "/anything", + "plugins": { + "ai-proxy": { + "provider": "openai", + "auth": {"header": {"Authorization": "Bearer token"}}, + "options": {"model": "gpt-4"}, + "override": {"endpoint": "http://localhost:18725"}, + "ssl_verify": false + }, + "serverless-post-function": { + "phase": "log", + "functions": ["return function(conf, ctx) ngx.log(ngx.WARN, \"LATENCYVARS status=\", ngx.status, \" aurt=\", tostring(ctx.var.apisix_upstream_response_time), \" ttft=\", tostring(ctx.var.llm_time_to_first_token)) end"] + } + } + }]] + ) + if code >= 300 then + ngx.status = code + end + ngx.say(body) + } + } +--- response_body +passed + + + +=== TEST 7: transport error records a millisecond value, ttft stays 0 +--- request +POST /anything +{ "messages": [ { "role": "user", "content": "What is 1+1?"} ] } +--- error_code: 500 +--- error_log eval +qr/LATENCYVARS status=500 aurt=\d+(?![\.\d]) ttft=0(?![\.\d])/ From 45098037fe271c488a29d915c9f4c0aec4809ed2 Mon Sep 17 00:00:00 2001 From: AlinsRan Date: Mon, 20 Jul 2026 14:05:20 +0800 Subject: [PATCH 2/6] test(ai-proxy): cover the prometheus status guard for llm_latency 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. --- t/plugin/ai-proxy-latency-vars.t | 80 ++++++++++++++++++++++++++++++++ 1 file changed, 80 insertions(+) diff --git a/t/plugin/ai-proxy-latency-vars.t b/t/plugin/ai-proxy-latency-vars.t index 1c4dc965ec68..e6d74160ce08 100644 --- a/t/plugin/ai-proxy-latency-vars.t +++ b/t/plugin/ai-proxy-latency-vars.t @@ -201,3 +201,83 @@ POST /anything --- error_code: 500 --- error_log eval qr/LATENCYVARS status=500 aurt=\d+(?![\.\d]) ttft=0(?![\.\d])/ + + + +=== TEST 8: set up a route with prometheus enabled, plus the metrics endpoint +--- config + location /t { + content_by_lua_block { + local t = require("lib.test_admin").test + local code = t('/apisix/admin/routes/1', + ngx.HTTP_PUT, + [[{ + "uri": "/anything", + "plugins": { + "prometheus": {}, + "ai-proxy": { + "provider": "openai", + "auth": {"header": {"Authorization": "Bearer token"}}, + "options": {"model": "gpt-4"}, + "override": {"endpoint": "http://localhost:18724"}, + "ssl_verify": false + } + } + }]] + ) + if code >= 300 then + ngx.status = code + ngx.say("route failed") + return + end + + code = t('/apisix/admin/routes/metrics', + ngx.HTTP_PUT, + [[{ + "uri": "/apisix/prometheus/metrics", + "plugins": {"public-api": {}} + }]] + ) + if code >= 300 then + ngx.status = code + ngx.say("metrics route failed") + return + end + ngx.say("passed") + } + } +--- response_body +passed + + + +=== TEST 9: only the served response is observed in llm_latency +--- config + location /t { + content_by_lua_block { + local http = require "resty.http" + local base = "http://127.0.0.1:" .. ngx.var.server_port + local body = [[{ "messages": [ { "role": "user", "content": "hi"} ] }]] + + local function call(status_hdr) + local headers = {["Content-Type"] = "application/json"} + if status_hdr then + headers["x-test-status"] = status_hdr + end + local res = http.new():request_uri(base .. "/anything", + {method = "POST", body = body, headers = headers}) + return res.status + end + + local s_ok = call(nil) + local s_500 = call("500") + local s_429 = call("429") + ngx.sleep(0.5) + + local res = http.new():request_uri(base .. "/apisix/prometheus/metrics") + local count = res.body:match("apisix_llm_latency_count%b{}%s+(%d+)") + ngx.say(s_ok, " ", s_500, " ", s_429, " llm_latency_count=", tostring(count)) + } + } +--- response_body +200 500 429 llm_latency_count=1 From c233d680f81aeeb20535d822e07ca72d849dc173 Mon Sep 17 00:00:00 2001 From: AlinsRan Date: Mon, 20 Jul 2026 15:32:34 +0800 Subject: [PATCH 3/6] test(ai-proxy): poll for the prometheus counter instead of a fixed sleep 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. --- t/plugin/ai-proxy-latency-vars.t | 14 +++++++++++--- 1 file changed, 11 insertions(+), 3 deletions(-) diff --git a/t/plugin/ai-proxy-latency-vars.t b/t/plugin/ai-proxy-latency-vars.t index e6d74160ce08..c2e05ee12eb7 100644 --- a/t/plugin/ai-proxy-latency-vars.t +++ b/t/plugin/ai-proxy-latency-vars.t @@ -272,10 +272,18 @@ passed local s_ok = call(nil) local s_500 = call("500") local s_429 = call("429") - ngx.sleep(0.5) - local res = http.new():request_uri(base .. "/apisix/prometheus/metrics") - local count = res.body:match("apisix_llm_latency_count%b{}%s+(%d+)") + -- the prometheus counters are buffered per worker and only reach + -- the shared dict on the sync interval, so poll rather than guess + local count + for _ = 1, 20 do + ngx.sleep(0.3) + local res = http.new():request_uri(base .. "/apisix/prometheus/metrics") + count = res.body:match("apisix_llm_latency_count%b{}%s+(%d+)") + if count then + break + end + end ngx.say(s_ok, " ", s_500, " ", s_429, " llm_latency_count=", tostring(count)) } } From c5f67642b917c6f3dba7e3ceee7907187af95153 Mon Sep 17 00:00:00 2001 From: AlinsRan Date: Mon, 20 Jul 2026 16:34:29 +0800 Subject: [PATCH 4/6] test(ai-proxy): give the polling block an explicit timeout 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. --- t/plugin/ai-proxy-latency-vars.t | 1 + 1 file changed, 1 insertion(+) diff --git a/t/plugin/ai-proxy-latency-vars.t b/t/plugin/ai-proxy-latency-vars.t index c2e05ee12eb7..bc6c1e44b612 100644 --- a/t/plugin/ai-proxy-latency-vars.t +++ b/t/plugin/ai-proxy-latency-vars.t @@ -252,6 +252,7 @@ passed === TEST 9: only the served response is observed in llm_latency +--- timeout: 20 --- config location /t { content_by_lua_block { From 9fc685ea570cf3c10a6da5d96c8e095598daee6f Mon Sep 17 00:00:00 2001 From: AlinsRan Date: Tue, 21 Jul 2026 07:28:56 +0800 Subject: [PATCH 5/6] test(ai-proxy): drop the prometheus assertion from the latency test 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. --- t/plugin/ai-proxy-latency-vars.t | 89 -------------------------------- 1 file changed, 89 deletions(-) diff --git a/t/plugin/ai-proxy-latency-vars.t b/t/plugin/ai-proxy-latency-vars.t index bc6c1e44b612..1c4dc965ec68 100644 --- a/t/plugin/ai-proxy-latency-vars.t +++ b/t/plugin/ai-proxy-latency-vars.t @@ -201,92 +201,3 @@ POST /anything --- error_code: 500 --- error_log eval qr/LATENCYVARS status=500 aurt=\d+(?![\.\d]) ttft=0(?![\.\d])/ - - - -=== TEST 8: set up a route with prometheus enabled, plus the metrics endpoint ---- config - location /t { - content_by_lua_block { - local t = require("lib.test_admin").test - local code = t('/apisix/admin/routes/1', - ngx.HTTP_PUT, - [[{ - "uri": "/anything", - "plugins": { - "prometheus": {}, - "ai-proxy": { - "provider": "openai", - "auth": {"header": {"Authorization": "Bearer token"}}, - "options": {"model": "gpt-4"}, - "override": {"endpoint": "http://localhost:18724"}, - "ssl_verify": false - } - } - }]] - ) - if code >= 300 then - ngx.status = code - ngx.say("route failed") - return - end - - code = t('/apisix/admin/routes/metrics', - ngx.HTTP_PUT, - [[{ - "uri": "/apisix/prometheus/metrics", - "plugins": {"public-api": {}} - }]] - ) - if code >= 300 then - ngx.status = code - ngx.say("metrics route failed") - return - end - ngx.say("passed") - } - } ---- response_body -passed - - - -=== TEST 9: only the served response is observed in llm_latency ---- timeout: 20 ---- config - location /t { - content_by_lua_block { - local http = require "resty.http" - local base = "http://127.0.0.1:" .. ngx.var.server_port - local body = [[{ "messages": [ { "role": "user", "content": "hi"} ] }]] - - local function call(status_hdr) - local headers = {["Content-Type"] = "application/json"} - if status_hdr then - headers["x-test-status"] = status_hdr - end - local res = http.new():request_uri(base .. "/anything", - {method = "POST", body = body, headers = headers}) - return res.status - end - - local s_ok = call(nil) - local s_500 = call("500") - local s_429 = call("429") - - -- the prometheus counters are buffered per worker and only reach - -- the shared dict on the sync interval, so poll rather than guess - local count - for _ = 1, 20 do - ngx.sleep(0.3) - local res = http.new():request_uri(base .. "/apisix/prometheus/metrics") - count = res.body:match("apisix_llm_latency_count%b{}%s+(%d+)") - if count then - break - end - end - ngx.say(s_ok, " ", s_500, " ", s_429, " llm_latency_count=", tostring(count)) - } - } ---- response_body -200 500 429 llm_latency_count=1 From f88fe11eff0e8e9979e4976ca54e4eac8353261a Mon Sep 17 00:00:00 2001 From: AlinsRan Date: Tue, 21 Jul 2026 08:30:23 +0800 Subject: [PATCH 6/6] test(prometheus): assert llm_latency excludes error responses 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. --- t/plugin/prometheus-ai-proxy.t | 76 ++++++++++++++++++++++++++++++++++ 1 file changed, 76 insertions(+) diff --git a/t/plugin/prometheus-ai-proxy.t b/t/plugin/prometheus-ai-proxy.t index 0e58f1c2fe12..6e7002e217e4 100644 --- a/t/plugin/prometheus-ai-proxy.t +++ b/t/plugin/prometheus-ai-proxy.t @@ -503,3 +503,79 @@ GET /apisix/prometheus/metrics qr/apisix_llm_prompt_tokens\{.*request_llm_model="",llm_model=""\}/ --- response_body_unlike eval qr/apisix_llm_prompt_tokens\{.*request_llm_model="distinct-model-/ + + + +=== TEST 27: create a route to check llm_latency excludes error responses +--- config + location /t { + content_by_lua_block { + local data = { + { + url = "/apisix/admin/routes/5", + data = [[{ + "plugins": { + "prometheus": {}, + "ai-proxy-multi": { + "instances": [ + { + "name": "openai-gpt4", + "provider": "openai", + "weight": 1, + "auth": { + "header": { + "Authorization": "Bearer token" + } + }, + "options": { + "model": "gpt-4" + }, + "override": { + "endpoint": "http://127.0.0.1:1980" + } + } + ] + } + }, + "uri": "/chat-guard" + }]], + }, + } + local t = require("lib.test_admin").test + for _, data in ipairs(data) do + local _, body = t(data.url, ngx.HTTP_PUT, data.data) + ngx.say(body) + end + } + } +--- response_body +passed + + + +=== TEST 28: a served response records one llm_latency observation +--- request +POST /chat-guard +{"messages":[{"role":"user","content":"What is 1+1?"}], "model": "gpt-3"} +--- more_headers +X-AI-Fixture: prometheus/chat-basic.json +--- error_code: 200 + + + +=== TEST 29: a 429 error response goes through the same route +--- request +POST /chat-guard +{"messages":[{"role":"user","content":"What is 1+1?"}], "model": "gpt-3"} +--- more_headers +X-AI-Fixture: prometheus/chat-basic.json +X-AI-Fixture-Status: 429 +--- error_code: 429 + + + +=== TEST 30: the error response is excluded, so the count stays 1 not 2 +--- request +GET /apisix/prometheus/metrics +--- response_body eval +qr/apisix_llm_latency_count\{type="total",.*route_id="5",.*,node="openai-gpt4".*request_type="ai_chat",request_llm_model="gpt-3",llm_model="gpt-4"\} 1\n/