This is an automated email from the ASF dual-hosted git repository.
nic-6443 pushed a commit to branch master
in repository https://gitbox.apache.org/repos/asf/apisix.git
The following commit(s) were added to refs/heads/master by this push:
new 694fd352a1 fix(ext-plugin-post-resp): set upstream_addr and
upstream_response_time for loggers (#13940)
694fd352a1 is described below
commit 694fd352a15ec5ef0b34d1e9ece5e55e9daa2bfd
Author: Mohammad Izzraff Janius
<[email protected]>
AuthorDate: Thu Sep 17 15:41:53 2026 +0900
fix(ext-plugin-post-resp): set upstream_addr and upstream_response_time for
loggers (#13940)
---
apisix/plugins/ext-plugin-post-resp.lua | 18 +++++
t/plugin/ext-plugin/response.t | 129 ++++++++++++++++++++++++++++++++
2 files changed, 147 insertions(+)
diff --git a/apisix/plugins/ext-plugin-post-resp.lua
b/apisix/plugins/ext-plugin-post-resp.lua
index 40d3ca450c..12a743cdf7 100644
--- a/apisix/plugins/ext-plugin-post-resp.lua
+++ b/apisix/plugins/ext-plugin-post-resp.lua
@@ -141,6 +141,20 @@ local function send_response(ctx, res, code)
end
+-- The body is read lazily, by send_response or by the runner's RespBody
+-- request, so only time spent waiting on the upstream socket is added to
+-- upstream_response_time. Runner and client time stays in apisix_latency.
+local function timed_body_reader(ctx, reader)
+ return function(...)
+ local start_time = ngx.now()
+ local chunk, err = reader(...)
+ ctx.var.upstream_response_time = ctx.var.upstream_response_time
+ + ngx.now() - start_time
+ return chunk, err
+ end
+end
+
+
function _M.check_schema(conf)
return core.schema.check(_M.schema, conf)
end
@@ -148,12 +162,16 @@ end
function _M.before_proxy(conf, ctx)
local http_obj = http.new()
+ local start_time = ngx.now()
local res, err = get_response(ctx, http_obj)
+ ctx.var.upstream_addr = ctx.picked_server.host .. ":" ..
ctx.picked_server.port
+ ctx.var.upstream_response_time = ngx.now() - start_time
if not res or err then
core.log.error("failed to request: ", err or "")
close(http_obj)
return 502
end
+ res.body_reader = timed_body_reader(ctx, res.body_reader)
ctx.runner_ext_response = res
core.log.info("response info, status: ", res.status)
diff --git a/t/plugin/ext-plugin/response.t b/t/plugin/ext-plugin/response.t
index d8a2be2a56..482d197541 100644
--- a/t/plugin/ext-plugin/response.t
+++ b/t/plugin/ext-plugin/response.t
@@ -430,3 +430,132 @@ GET /plugin_proxy_rewrite_args?aaa=bbb&ccc=ddd
uri: /plugin_proxy_rewrite_args
aaa: bbb
ccc: ddd
+
+
+
+=== TEST 17: add route with http-logger to check upstream vars
+--- config
+ location /t {
+ content_by_lua_block {
+ local t = require("lib.test_admin")
+
+ local code, message = t.test('/apisix/admin/routes/1',
+ ngx.HTTP_PUT,
+ [[{
+ "uri": "/*",
+ "plugins": {
+ "ext-plugin-post-resp": {
+ },
+ "http-logger": {
+ "uri": "http://127.0.0.1:1980/log";,
+ "batch_max_size": 1
+ }
+ },
+ "upstream": {
+ "nodes": {
+ "127.0.0.1:1980": 1
+ },
+ "type": "roundrobin"
+ }
+ }]]
+ )
+
+ if code >= 300 then
+ ngx.status = code
+ end
+ ngx.say(message)
+ }
+ }
+--- response_body
+passed
+
+
+
+=== TEST 18: upstream and upstream_latency are logged
+--- request
+GET /hello
+--- error_code: 200
+--- response_body
+hello world
+--- error_log eval
+qr/request log: .*"upstream":"127\.0\.0\.1:1980".*"upstream_latency":\d+/
+
+
+
+=== TEST 19: add route whose upstream sends headers first and the body later
+--- config
+ location /t {
+ content_by_lua_block {
+ local t = require("lib.test_admin")
+ local code, message = t.test('/apisix/admin/routes/1',
+ ngx.HTTP_PUT,
+ [[{
+ "uri": "/hello",
+ "plugins": {
+ "proxy-rewrite": {"uri": "/delayed_body"},
+ "ext-plugin-post-resp": {},
+ "http-logger": {
+ "uri": "http://127.0.0.1:1980/log";,
+ "batch_max_size": 1
+ }
+ },
+ "upstream": {
+ "nodes": {"127.0.0.1:1984": 1},
+ "type": "roundrobin"
+ }
+ }]]
+ )
+ if code >= 300 then ngx.status = code end
+ ngx.say(message)
+ }
+ }
+--- response_body
+passed
+
+
+
+=== TEST 20: upstream_latency includes the body delay (body streamed to client)
+--- config
+ location /delayed_body {
+ content_by_lua_block {
+ ngx.print("head")
+ ngx.flush(true)
+ ngx.sleep(0.5)
+ ngx.say("tail")
+ }
+ }
+--- request
+GET /hello
+--- response_body
+headtail
+--- error_log eval
+qr/"upstream_latency":[4-9]\d\d\b/
+
+
+
+=== TEST 21: upstream_latency excludes runner time (body read for the runner)
+--- config
+ location /delayed_body {
+ content_by_lua_block {
+ ngx.print("head")
+ ngx.flush(true)
+ ngx.sleep(1)
+ ngx.say("tail")
+ }
+ }
+--- extra_stream_config
+ server {
+ listen unix:$TEST_NGINX_HTML_DIR/nginx.sock;
+
+ content_by_lua_block {
+ ngx.sleep(0.2)
+ local ext = require("lib.ext-plugin")
+ ext.go({extra_info = {{type = "respbody", result = "headtail\n"}}})
+ }
+ }
+--- request
+GET /hello
+--- response_body
+headtail
+--- error_log eval
+qr/"upstream_latency":[3-9]\d\d\b/
