fix(ai-proxy): report error-path latency vars in milliseconds

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
 

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

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.

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.

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`：响应中的聊天完成令牌数量。

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`：响应中的聊天完成令牌数量。

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])/