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 ec1438767 change(debug): report executed plugins with phase in
execution order (#13710)
ec1438767 is described below
commit ec14387671fe362d571c3879b84bfedbbe3f1d12
Author: Nic <[email protected]>
AuthorDate: Mon Jul 20 15:11:04 2026 +0800
change(debug): report executed plugins with phase in execution order
(#13710)
---
apisix/init.lua | 19 ++++++----
apisix/plugin.lua | 83 +++++++++++++++++++++++++++++---------------
docs/en/latest/debug-mode.md | 8 +++--
docs/zh/latest/debug-mode.md | 10 +++---
t/debug/debug-mode.t | 63 ++++++++-------------------------
t/node/consumer-plugin2.t | 76 ++++++++++++++--------------------------
6 files changed, 119 insertions(+), 140 deletions(-)
diff --git a/apisix/init.lua b/apisix/init.lua
index 3c0ff689f..801944c36 100644
--- a/apisix/init.lua
+++ b/apisix/init.lua
@@ -1049,13 +1049,20 @@ function _M.http_header_filter_phase()
return
end
- local debug_headers = api_ctx.debug_headers
- if debug_headers then
- local deduplicate = core.table.new(core.table.nkeys(debug_headers), 0)
- for k, v in pairs(debug_headers) do
- core.table.insert(deduplicate, k)
+ if debug.enable_debug() then
+ -- report the plugin phase functions in the execution order: the ones
+ -- executed so far were traced at execution time, while the
+ -- post-header ones of the matched plugins have not run yet and are
+ -- inferred, so they may not fully match the real execution
+ plugin.trace_expected_plugins_for_debug(api_ctx)
+
+ local debug_plugins = api_ctx.debug_plugins
+ if debug_plugins then
+ core.response.set_header("Apisix-Plugins",
+ core.table.concat(debug_plugins, ", "))
+ else
+ core.response.set_header("Apisix-Plugins", "no plugin")
end
- core.response.set_header("Apisix-Plugins",
core.table.concat(deduplicate, ", "))
end
span:finish(ngx_ctx)
diff --git a/apisix/plugin.lua b/apisix/plugin.lua
index 84123d8a2..65179364e 100644
--- a/apisix/plugin.lua
+++ b/apisix/plugin.lua
@@ -461,38 +461,66 @@ function _M.exit_worker()
end
-local function trace_plugins_info_for_debug(ctx, plugins)
+-- Record an executed plugin phase function as "name#phase" in
+-- ctx.debug_plugins, keeping the execution order. The entries collected
+-- before the response header is sent are reported via the Apisix-Plugins
+-- response header, the rest are logged as a warn log instead.
+local function trace_plugin_exec_for_debug(ctx, plugin_name, phase)
if not enable_debug() then
return
end
- if not plugins then
- if is_http and not ngx.headers_sent then
- core.response.add_header("Apisix-Plugins", "no plugin")
- else
- core.log.warn("Apisix-Plugins: no plugin")
+ if not ctx then
+ return
+ end
+
+ local item = plugin_name .. "#" .. phase
+ local debug_plugins = ctx.debug_plugins
+ if not debug_plugins then
+ debug_plugins = core.table.new(4, 0)
+ ctx.debug_plugins = debug_plugins
+ else
+ -- a phase function may run more than once, e.g. the body_filter
+ -- one runs per response chunk, so record it only once
+ for i = 1, #debug_plugins do
+ if debug_plugins[i] == item then
+ return
+ end
end
+ end
+
+ core.table.insert(debug_plugins, item)
+
+ if not is_http or ngx.headers_sent then
+ core.log.warn("Apisix-Plugins: ", item)
+ end
+end
+
+local POST_RESP_HEADER_PHASES = {"body_filter", "delayed_body_filter", "log"}
+-- The phase functions running after the response header is sent can not be
+-- traced at execution time and reported in the Apisix-Plugins response
+-- header. Instead, infer them from the filtered plugin list right before
+-- the response header is generated: a plugin carrying such a phase function
+-- is expected to execute it. The inferred entries may not fully match the
+-- real execution, e.g. a plugin skipped at runtime by its `_meta.filter`
+-- is still reported.
+function _M.trace_expected_plugins_for_debug(api_ctx)
+ if not enable_debug() then
return
end
- local t = {}
- for i = 1, #plugins, 2 do
- core.table.insert(t, plugins[i].name)
+ local plugins = api_ctx.plugins
+ if not plugins then
+ return
end
- if is_http and not ngx.headers_sent then
- if ctx then
- local debug_headers = ctx.debug_headers
- if not debug_headers then
- debug_headers = core.table.new(0, 5)
- end
- for i, v in ipairs(t) do
- debug_headers[v] = true
+
+ for _, phase in ipairs(POST_RESP_HEADER_PHASES) do
+ for i = 1, #plugins, 2 do
+ if plugins[i][phase] then
+ trace_plugin_exec_for_debug(api_ctx, plugins[i].name, phase)
end
- ctx.debug_headers = debug_headers
end
- else
- core.log.warn("Apisix-Plugins: ", core.table.concat(t, ", "))
end
end
@@ -538,7 +566,6 @@ function _M.filter(ctx, conf, plugins, route_conf, phase)
local user_plugin_conf = conf.value.plugins
if user_plugin_conf == nil or
core.table.nkeys(user_plugin_conf) == 0 then
- trace_plugins_info_for_debug(nil, nil)
-- when 'plugins' is given, always return 'plugins' itself instead
-- of another one
return plugins or core.tablepool.fetch("plugins", 0, 0)
@@ -587,8 +614,6 @@ function _M.filter(ctx, conf, plugins, route_conf, phase)
::continue::
end
- trace_plugins_info_for_debug(ctx, plugins)
-
if custom_sort then
local tmp_plugin_objs = core.tablepool.fetch("tmp_plugin_objs", 0,
#plugins / 2)
local tmp_plugin_confs = core.tablepool.fetch("tmp_plugin_confs",
#plugins / 2, 0)
@@ -641,7 +666,6 @@ function _M.stream_filter(user_route, plugins)
plugins = plugins or core.table.new(#stream_local_plugins * 2, 0)
local user_plugin_conf = user_route.value.plugins
if user_plugin_conf == nil then
- trace_plugins_info_for_debug(nil, nil)
return plugins
end
@@ -656,8 +680,6 @@ function _M.stream_filter(user_route, plugins)
end
end
- trace_plugins_info_for_debug(nil, plugins)
-
-- resolve $secret:// and $env:// references in stream plugin confs
for i = 2, #plugins, 2 do
local resolved = resolve_plugin_conf(plugins[i])
@@ -1322,14 +1344,16 @@ function _M.run_plugin(phase, plugins, api_ctx)
and phase ~= "body_filter"
and phase ~= "delayed_body_filter"
then
+ -- in the "rewrite_in_consumer" phase, the executed functions
+ -- are the "rewrite" ones
+ local exec_phase = phase == "rewrite_in_consumer" and "rewrite" or
phase
for i = 1, #plugins, 2 do
if phase == "rewrite_in_consumer" and plugins[i +
1]._skip_rewrite_in_consumer then
goto CONTINUE
end
- local phase_func = phase == "rewrite_in_consumer" and
plugins[i]["rewrite"]
- or plugins[i][phase]
+ local phase_func = plugins[i][exec_phase]
if phase_func then
local conf = plugins[i + 1]
if not meta_filter(api_ctx, plugins[i]["name"], conf)then
@@ -1344,6 +1368,7 @@ function _M.run_plugin(phase, plugins, api_ctx)
run_meta_pre_function(conf, api_ctx, plugins[i]["name"])
plugin_run = true
api_ctx._plugin_name = plugins[i]["name"]
+ trace_plugin_exec_for_debug(api_ctx, plugins[i]["name"],
exec_phase)
local code, body = phase_func(conf, api_ctx)
api_ctx._plugin_name = nil
if code or body then
@@ -1386,6 +1411,7 @@ function _M.run_plugin(phase, plugins, api_ctx)
plugin_run = true
run_meta_pre_function(conf, api_ctx, plugins[i]["name"])
api_ctx._plugin_name = plugins[i]["name"]
+ trace_plugin_exec_for_debug(api_ctx, plugins[i]["name"], phase)
local span = tracer.start(api_ctx.ngx_ctx, "apisix.phase." .. phase
.. ".plugins." .. api_ctx._plugin_name)
phase_func(conf, api_ctx)
@@ -1515,6 +1541,7 @@ function _M.lua_response_filter(api_ctx, headers, body,
no_flush, wait)
end
run_meta_pre_function(conf, api_ctx, plugins[i]["name"])
+ trace_plugin_exec_for_debug(api_ctx, plugins[i]["name"],
"lua_body_filter")
local code, new_body = phase_func(conf, api_ctx, headers, body)
if code then
if code ~= ngx_ok then
diff --git a/docs/en/latest/debug-mode.md b/docs/en/latest/debug-mode.md
index 86dd228e7..33799415d 100644
--- a/docs/en/latest/debug-mode.md
+++ b/docs/en/latest/debug-mode.md
@@ -47,7 +47,7 @@ For APISIX releases prior to v2.10, basic debug mode is
enabled by setting `apis
:::
-If you have configured two Plugins `limit-conn` and `limit-count` on the Route
`/hello`, you will receive a response with the header `Apisix-Plugins:
limit-conn, limit-count` when you enable the basic debug mode.
+If you have configured two Plugins `limit-conn` and `limit-count` on the Route
`/hello`, you will receive a response with the header `Apisix-Plugins:
limit-conn#access, limit-count#access, limit-conn#log` when you enable the
basic debug mode. Each entry in the header is in the form `plugin-name#phase`,
and the entries are listed in the runtime execution order of the plugin phase
functions (for the phases running after the response header is generated, the
expected execution order — see t [...]
```shell
curl http://127.0.0.1:1984/hello -i
@@ -58,7 +58,7 @@ HTTP/1.1 200 OK
Content-Type: text/plain
Transfer-Encoding: chunked
Connection: keep-alive
-Apisix-Plugins: limit-conn, limit-count
+Apisix-Plugins: limit-conn#access, limit-count#access, limit-conn#log
X-RateLimit-Limit: 2
X-RateLimit-Remaining: 1
Server: openresty
@@ -68,7 +68,9 @@ hello world
:::info IMPORTANT
-If the debug information cannot be included in a response header (for example,
when the Plugin is in a stream subsystem), the debug information will be logged
as an error log at a `warn` level.
+Restricted by the HTTP protocol, the phase functions executed after the
response header is generated (such as `body_filter` and `log`) can not be
traced into the response header at execution time. Instead, their entries are
inferred right before the response header is generated: a matched plugin
carrying such a phase function is reported as if it would execute it. The
inferred entries may not fully reflect the real execution — for example, a
plugin skipped at runtime by its `_meta.filter [...]
+
+The phase functions that can be neither traced nor inferred this way (for
example, the ones of the plugins in global rules running after the response
header is sent) are logged as an error log at a `warn` level instead, for
example `Apisix-Plugins: response-rewrite#body_filter`.
:::
diff --git a/docs/zh/latest/debug-mode.md b/docs/zh/latest/debug-mode.md
index c9c0b10aa..d83747bc4 100644
--- a/docs/zh/latest/debug-mode.md
+++ b/docs/zh/latest/debug-mode.md
@@ -33,7 +33,8 @@ basic:
注意：在 APISIX 2.10 之前，开启基本调试模式曾经是设置 `conf/config.yaml` 中的 `apisix.enable_debug`
为 `true`。
-比如对 `/hello` 开启了 `limit-conn` 和 `limit-count` 插件，这时候应答头中会有 `Apisix-Plugins:
limit-conn, limit-count`。
+比如对 `/hello` 开启了 `limit-conn` 和 `limit-count` 插件，这时候应答头中会有 `Apisix-Plugins:
limit-conn#access, limit-count#access, limit-conn#log`。
+应答头中的每一项都是 `插件名#执行阶段` 的形式，按照插件阶段函数在运行时的执行顺序排列（应答头生成之后才执行的阶段按预期执行顺序给出，见下方说明）。
```shell
$ curl http://127.0.0.1:1984/hello -i
@@ -41,7 +42,7 @@ HTTP/1.1 200 OK
Content-Type: text/plain
Transfer-Encoding: chunked
Connection: keep-alive
-Apisix-Plugins: limit-conn, limit-count
+Apisix-Plugins: limit-conn#access, limit-count#access, limit-conn#log
X-RateLimit-Limit: 2
X-RateLimit-Remaining: 1
Server: openresty
@@ -49,8 +50,9 @@ Server: openresty
hello world
```
-如果这个信息无法通过 HTTP 应答头传递，比如插件在 stream 子系统里面执行，
-那么这个信息会以 warn 等级日志写入到错误日志中。
+受限于 HTTP 协议，在应答头生成之后才执行的插件阶段函数（如
`body_filter`、`log`）无法在执行时被记录到应答头中。应答头中的这类条目是在应答头生成前**推算**出来的：只要匹配到的插件带有对应的阶段函数，就会被记录。因此这些条目不完全代表真实的执行情况——例如某插件在运行时被
`_meta.filter` 跳过，它仍会出现在应答头中。
+
+无法通过执行记录或推算体现的阶段函数（例如 global rule 中的插件在应答头发送之后执行的阶段），会以 warn 等级日志写入到错误日志中，例如
`Apisix-Plugins: response-rewrite#body_filter`。
### 高级调试模式
diff --git a/t/debug/debug-mode.t b/t/debug/debug-mode.t
index a41dacb77..6d4768edd 100644
--- a/t/debug/debug-mode.t
+++ b/t/debug/debug-mode.t
@@ -180,33 +180,17 @@ passed
-=== TEST 5: hit routes
+=== TEST 5: hit routes, the header lists the executed plugins in the execution
order
--- debug_config eval: $::debug_config
---- config
- location /t {
- content_by_lua_block {
- local json = require("toolkit.json")
- local ngx_re = require("ngx.re")
- local http = require "resty.http"
- local httpc = http.new()
- local uri = "http://127.0.0.1:"; .. ngx.var.server_port .. "/hello"
- local res, err = httpc:request_uri(uri, {
- method = "GET",
- })
- local debug_header = res.headers["Apisix-Plugins"]
- local arr = ngx_re.split(debug_header, ", ")
- local hash = {}
- for i, v in ipairs(arr) do
- hash[v] = true
- end
- ngx.status = res.status
- ngx.say(json.encode(hash))
- }
- }
--- request
-GET /t
+GET /hello
--- response_body
-{"limit-conn":true,"limit-count":true}
+hello world
+--- response_headers
+Apisix-Plugins: limit-conn#access, limit-count#access, limit-conn#log
+--- no_error_log
+Apisix-Plugins: limit-conn#log
+[error]
@@ -240,35 +224,16 @@ passed
-=== TEST 7: hit routes
+=== TEST 7: phases which can be neither traced nor inferred are logged as warn
--- debug_config eval: $::debug_config
---- config
- location /t {
- content_by_lua_block {
- local json = require("toolkit.json")
- local ngx_re = require("ngx.re")
- local http = require "resty.http"
- local httpc = http.new()
- local uri = "http://127.0.0.1:"; .. ngx.var.server_port .. "/hello"
- local res, err = httpc:request_uri(uri, {
- method = "GET",
- })
- local debug_header = res.headers["Apisix-Plugins"]
- local arr = ngx_re.split(debug_header, ", ")
- local hash = {}
- for i, v in ipairs(arr) do
- hash[v] = true
- end
- ngx.status = res.status
- ngx.say(json.encode(hash))
- }
- }
--- request
-GET /t
+GET /hello
--- response_body
-{"limit-conn":true,"limit-count":true,"response-rewrite":true}
+yes
+--- response_headers
+Apisix-Plugins: limit-conn#access, limit-count#access,
response-rewrite#header_filter, limit-conn#log
--- error_log
-Apisix-Plugins: response-rewrite
+Apisix-Plugins: response-rewrite#body_filter
diff --git a/t/node/consumer-plugin2.t b/t/node/consumer-plugin2.t
index 6c79ad88d..e68cd20e3 100644
--- a/t/node/consumer-plugin2.t
+++ b/t/node/consumer-plugin2.t
@@ -116,32 +116,20 @@ x-real-ip: 127.0.0.1
=== TEST 3: trace plugins info for debug
--- debug_config eval: $::debug_config
---- config
- location /t {
- content_by_lua_block {
- local json = require("toolkit.json")
- local ngx_re = require("ngx.re")
- local http = require "resty.http"
- local httpc = http.new()
- local headers = {}
- headers["apikey"] = "auth-jack"
- local uri = "http://127.0.0.1:"; .. ngx.var.server_port .. "/hello"
- local res, err = httpc:request_uri(uri, {
- method = "GET",
- headers = headers,
- })
- local debug_header = res.headers["Apisix-Plugins"]
- local arr = ngx_re.split(debug_header, ", ")
- local hash = {}
- for i, v in ipairs(arr) do
- hash[v] = true
- end
- ngx.status = res.status
- ngx.say(json.encode(hash))
- }
- }
+--- request
+GET /hello
+--- more_headers
+apikey: auth-jack
--- response_body
-{"key-auth":true,"proxy-rewrite":true}
+uri: /uri/plugin_proxy_rewrite
+apikey: auth-jack
+host: localhost
+x-api-engine: APISIX
+x-consumer-id: 1
+x-consumer-username: jack
+x-real-ip: 127.0.0.1
+--- response_headers
+Apisix-Plugins: key-auth#rewrite, proxy-rewrite#rewrite
@@ -214,32 +202,20 @@ x-real-ip: 127.0.0.1
=== TEST 6: trace plugins info for debug
--- debug_config eval: $::debug_config
---- config
- location /t {
- content_by_lua_block {
- local json = require("toolkit.json")
- local ngx_re = require("ngx.re")
- local http = require "resty.http"
- local httpc = http.new()
- local headers = {}
- headers["apikey"] = "auth-jack"
- local uri = "http://127.0.0.1:"; .. ngx.var.server_port .. "/hello"
- local res, err = httpc:request_uri(uri, {
- method = "GET",
- headers = headers,
- })
- local debug_header = res.headers["Apisix-Plugins"]
- local arr = ngx_re.split(debug_header, ", ")
- local hash = {}
- for i, v in ipairs(arr) do
- hash[v] = true
- end
- ngx.status = res.status
- ngx.say(json.encode(hash))
- }
- }
+--- request
+GET /hello
+--- more_headers
+apikey: auth-jack
--- response_body
-{"key-auth":true,"proxy-rewrite":true}
+uri: /uri/plugin_proxy_rewrite
+apikey: auth-jack
+host: localhost
+x-api-engine: APISIX
+x-consumer-id: 1
+x-consumer-username: jack
+x-real-ip: 127.0.0.1
+--- response_headers
+Apisix-Plugins: key-auth#rewrite, proxy-rewrite#rewrite
