janiussyafiq opened a new issue, #13724:
URL: https://github.com/apache/apisix/issues/13724
## Current Behavior
Since 3.16.0 every logger plugin carries an `access`-phase handler
(`_M.access = log_util.check_and_read_req_body`, introduced in #13034). Because
the plugin now runs in `access`, `run_plugin("access", ...)` invokes
`meta_filter()`, which evaluates the plugin's `_meta.filter` **and caches the
verdict for the rest of the request**.
At `access` time the request has not been proxied yet: `$status` is `0` and
`$upstream_status` is empty. This produces two distinct problems.
**A. Filter conditions on response-phase variables are decided before those
variables have values.**
A filter referencing `$status` or `$upstream_status` is evaluated against
`0` / empty, and that verdict is reused at log phase. The filter silently makes
the wrong decision — either keeping entries it was written to drop, or dropping
every entry.
**B. `$status` is cached as `0`, corrupting the output of every plugin on
the request.**
`status` is not in `no_cacheable_var_names`, so the access-phase read stores
`0` into `ctx.var` for the remainder of the request. Every plugin that later
reads `$status` gets `0` — **including logger plugins that have no
`_meta.filter` of their own**. A filter on one plugin silently corrupts a
different plugin's log output.
Neither problem emits any error or warning.
**Blast radius.** In 3.17.0, 14 logger plugins carry this `access` handler,
so any of them can trigger both problems:
`clickhouse-logger`, `elasticsearch-logger`, `file-logger`, `http-logger`,
`kafka-logger`, `loggly`, `loki-logger`, `rocketmq-logger`,
`skywalking-logger`, `sls-logger`, `syslog`, `tcp-logger`, `tencent-cloud-cls`,
`udp-logger`
(12 assign `_M.access = log_util.check_and_read_req_body` directly;
`elasticsearch-logger` and `tencent-cloud-cls` call
`log_util.check_and_read_req_body` from a wrapper `_M.access`.)
**First bad version: 3.16.0.** 3.15.0 behaves correctly; 3.16.0 and 3.17.0
both reproduce. This boundary was established with the same filter and upstream
using standalone (`APISIX_STAND_ALONE`) config rather than the Admin API steps
below.
## Expected Behavior
1. A `_meta.filter` condition on `$status` / `$upstream_status` should be
evaluated when those variables have values, i.e. at log phase — not decided in
`access` and cached.
2. `$status` in `log_format` should be the real response status, never `0`
for a request that completed.
3. A `_meta.filter` on one plugin must never change what a different plugin
logs.
## Error Logs
None. This is the core of the problem — it fails completely silently.
Across all scenarios below, `error.log` contained **zero** lines mentioning
`vars`, `filter`, or `expression`. No `failed to run the 'vars' expression`, no
warning of any kind. The only `[warn]`/`[error]` lines present were unrelated
startup messages (plugin loading, a `saml-auth` load failure, and an
http-logger TLS advisory).
## Steps to Reproduce
### Setup
Two files in an empty directory named `apisix-repro` (the directory name
fixes the container names used below):
`config.yaml`
```yaml
deployment:
role: traditional
role_traditional:
config_provider: etcd
admin:
admin_key:
- name: admin
key: edd1c9f034335f136f87ad84b625c8f1
role: admin
allow_admin:
- 0.0.0.0/0
etcd:
host:
- "http://etcd:2379";
prefix: /apisix
timeout: 30
```
`docker-compose.yml`
```yaml
services:
apisix:
image: apache/apisix:3.17.0-debian
volumes:
- ./config.yaml:/usr/local/apisix/conf/config.yaml:ro
depends_on: [etcd]
ports:
- "9080:9080"
- "9180:9180"
etcd:
image: bitnamilegacy/etcd:3.5.11
environment:
ETCD_ENABLE_V2: "true"
ALLOW_NONE_AUTHENTICATION: "yes"
ETCD_ADVERTISE_CLIENT_URLS: "http://etcd:2379";
ETCD_LISTEN_CLIENT_URLS: "http://0.0.0.0:2379";
httpbin:
image: mccutchen/go-httpbin
```
```sh
docker compose up -d
sleep 15
```
One route, used by every scenario:
```sh
curl -s -X PUT http://127.0.0.1:9180/apisix/admin/routes/1 \
-H 'X-API-KEY: edd1c9f034335f136f87ad84b625c8f1' -d '{
"uri": "/status/*",
"upstream": {"type":"roundrobin","nodes":{"httpbin:8080":1}}
}'
```
The same three requests are sent in every scenario:
```sh
curl -s -o /dev/null -w 'gw404 -> %{http_code}\n'
http://127.0.0.1:9080/not-routed -H 'X-Case: gw404'
curl -s -o /dev/null -w 'up200 -> %{http_code}\n'
http://127.0.0.1:9080/status/200 -H 'X-Case: up200'
curl -s -o /dev/null -w 'up404 -> %{http_code}\n'
http://127.0.0.1:9080/status/404 -H 'X-Case: up404'
sleep 3
```
`gw404` is a gateway-generated 404 that never reaches an upstream, so its
`$upstream_status` is empty. `up200` and `up404` are proxied.
### Scenario A — filter on `$status` / `$upstream_status` makes the wrong
decision
The filter says: drop an entry when the status is 404 **and** no upstream
was reached — i.e. drop gateway-generated 404s, keep upstream 404s.
```sh
curl -s -X PUT http://127.0.0.1:9180/apisix/admin/global_rules/1 \
-H 'X-API-KEY: edd1c9f034335f136f87ad84b625c8f1' -d '{
"plugins": {
"file-logger": {
"path": "/usr/local/apisix/logs/a.log",
"log_format": {
"case": "$http_x_case", "uri": "$uri",
"status": "$status", "upstream_status": "$upstream_status"
},
"_meta": {
"filter": [["!AND", ["status", "==", 404], ["upstream_status", "!",
"~~", "."]]]
}
}
}
}'
sleep 3
docker exec apisix-repro-apisix-1 sh -c 'cat /usr/local/apisix/logs/a.log'
```
```
{"uri":"/not-routed","status":0,"case":"gw404"}
{"uri":"/status/200","route_id":"1","upstream_status":"200","status":0,"case":"up200"}
{"uri":"/status/404","route_id":"1","upstream_status":"404","status":0,"case":"up404"}
```
`gw404` — the single entry this filter exists to drop — was kept, because
`status == 404` was evaluated as `0 == 404`. Every entry also has `status: 0`,
though the requests returned 404/200/404.
### Scenario B — a filter on one plugin corrupts a different plugin
The filter moves to `http-logger`. `file-logger` has **no `_meta.filter` at
all**.
```sh
curl -s -X PUT http://127.0.0.1:9180/apisix/admin/global_rules/1 \
-H 'X-API-KEY: edd1c9f034335f136f87ad84b625c8f1' -d '{
"plugins": {
"http-logger": {
"uri": "http://httpbin:8080/post";,
"batch_max_size": 1, "inactive_timeout": 1,
"_meta": {
"filter": [["!AND", ["status", "==", 404], ["upstream_status", "!",
"~~", "."]]]
}
},
"file-logger": {
"path": "/usr/local/apisix/logs/b.log",
"log_format": {
"case": "$http_x_case", "uri": "$uri",
"status": "$status", "upstream_status": "$upstream_status"
}
}
}
}'
sleep 3
docker exec apisix-repro-apisix-1 sh -c 'cat /usr/local/apisix/logs/b.log'
```
```
{"uri":"/not-routed","status":0,"case":"gw404"}
{"uri":"/status/200","route_id":"1","upstream_status":"200","status":0,"case":"up200"}
{"uri":"/status/404","route_id":"1","upstream_status":"404","status":0,"case":"up404"}
```
`file-logger` is unfiltered, yet all of its `status` values are `0`.
**Control** — same config with `_meta.filter` removed from `http-logger`,
everything else identical:
```sh
curl -s -X PUT http://127.0.0.1:9180/apisix/admin/global_rules/1 \
-H 'X-API-KEY: edd1c9f034335f136f87ad84b625c8f1' -d '{
"plugins": {
"http-logger": {
"uri": "http://httpbin:8080/post";,
"batch_max_size": 1, "inactive_timeout": 1
},
"file-logger": {
"path": "/usr/local/apisix/logs/c.log",
"log_format": {
"case": "$http_x_case", "uri": "$uri",
"status": "$status", "upstream_status": "$upstream_status"
}
}
}
}'
sleep 3
docker exec apisix-repro-apisix-1 sh -c 'cat /usr/local/apisix/logs/c.log'
```
```
{"uri":"/not-routed","status":404,"case":"gw404"}
{"uri":"/status/200","route_id":"1","upstream_status":"200","status":200,"case":"up200"}
{"uri":"/status/404","route_id":"1","upstream_status":"404","status":404,"case":"up404"}
```
(JSON key order within each line varies between runs; the values are what
matter.)
Statuses are correct. The only difference between the two runs is the
presence of a `_meta.filter` on a **different** plugin.
### Scenario C — a filter on `$upstream_status` drops everything
Keep only requests that reached an upstream:
```sh
curl -s -X PUT http://127.0.0.1:9180/apisix/admin/global_rules/1 \
-H 'X-API-KEY: edd1c9f034335f136f87ad84b625c8f1' -d '{
"plugins": {
"file-logger": {
"path": "/usr/local/apisix/logs/d.log",
"log_format": {
"case": "$http_x_case", "uri": "$uri",
"status": "$status", "upstream_status": "$upstream_status"
},
"_meta": {"filter": [["upstream_status", "~~", "^[0-9]+"]]}
}
}
}'
sleep 3
docker exec apisix-repro-apisix-1 sh -c 'cat /usr/local/apisix/logs/d.log'
```
```
(file is empty — nothing logged at all)
```
Two of the three requests were proxied with `$upstream_status` of `200` and
`404`, but at `access` time `$upstream_status` was empty for all of them, so
the filter dropped everything. This scenario isolates problem A from problem B:
the filter never reads `$status`, so no `status` corruption is involved —
logging simply stops, with no error anywhere.
### Cleanup
```sh
docker compose down -v
```
## Environment
- APISIX version (run `apisix version`): **3.17.0**
(`apache/apisix:3.17.0-debian`); also reproduced on 3.16.0, not reproducible on
3.15.0
- Operating system (run `uname -a`): `Linux 3e1fdcdbc403
7.0.11-orbstack-00360-gc9bc4d96ac70 #1 SMP PREEMPT Thu Jun 4 16:40:25 UTC 2026
aarch64 GNU/Linux`
- OpenResty / Nginx version (run `openresty -V` or `nginx -V`):
`openresty/1.29.2.4`, built by gcc 12.2.0 (Debian 12.2.0-14+deb12u1)
- etcd version, if relevant: `bitnamilegacy/etcd:3.5.11` (the image used by
`apache/apisix-docker/example`)
- APISIX Dashboard version, if relevant: n/a
- Plugin runner version, for issues related to plugin runners: n/a
- LuaRocks version, for installation issues (run `luarocks --version`): n/a
(official Docker image)
## Root cause
Two independent caches combine to produce this.
**1. The filter verdict is cached from the access phase.**
`apisix/plugin.lua`:
```lua
local function meta_filter(ctx, plugin_name, plugin_conf)
local filter = plugin_conf._meta and plugin_conf._meta.filter
if not filter then
return true
end
local match_cache_key =
ctx.conf_type .. "#" .. ctx.conf_id .. "#"
.. ctx.conf_version .. "#" .. plugin_name ..
"#meta_filter_matched"
if ctx[match_cache_key] ~= nil then
return ctx[match_cache_key] -- access-phase verdict, reused at
log phase
end
```
Before #13034 loggers had no `access` handler, so `meta_filter` first ran at
log phase, when response variables were populated. Now the access-phase call
populates the cache and the log-phase call returns it unchanged. This is
problem A.
**2. `status` is cached into `ctx.var`.** `apisix/core/ctx.lua`:
```lua
local no_cacheable_var_names = {
-- var.args should not be cached as it can be changed via set_uri_args
args = true,
is_args = true,
}
```
`status` is not listed, so the access-phase read of `$status` is cached by:
```lua
if val ~= nil and not no_cacheable_var_names[key] then
t._cache[key] = val
end
```
At access phase `$status` is `0` — not `nil` — so it passes the guard and is
cached. Every later reader of `$status` on that request gets `0`. Because
`ctx.var` is shared across all plugins on the request, this leaks into plugins
that never had a filter. This is problem B, and it is why the control in
Scenario B isolates the cause so cleanly.
The same guard explains why `$upstream_status` stays correct in Scenario A:
at access phase it is `nil`, so it is never cached, and the log phase re-reads
the real value. `$status` is corrupted precisely because `0` is a value rather
than an absence.
The two problems need fixes in different places (`plugin.lua`'s meta_filter
caching vs. `no_cacheable_var_names` in `core/ctx.lua`), so a fix addressing
only one would leave the other reproducible.
Note that this re-introduces the class of problem previously addressed in
#8162 / #8256.
--
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]
