bug: logger `_meta.filter` evaluates response-phase variables at access phase, breaking filters and caching `$status` as `0`
- Dominant language
- Lua
- Stars
- 17.1k
- Forks
- 2.9k
- Avg merge
- 3d 16h
- Merged PRs (30d)
- 63
Description
### 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.
Contributor guide
Research direction
Start in apisix/plugin.lua at meta_filter and apisix/core/ctx.lua at the no_cacheable_var_names and variable-cache logic. Reproduce the issue with the supplied config.yaml, docker-compose.yml, and three scenarios, then verify that response-phase filters run with final values, $status is not cached as 0, and one plugin's filter does not affect another plugin's log.
Written by the indexing model from the issue text.
Assessment
- Tech stack
- docker-compose, lua, nginx
- Domain
- api, backend, observability
- Issue type
- Bug
- Difficulty
- 4/5
- Estimated time
- 3-5 days
- Activity status
- Quiet
- Clarity
- Mostly clear
- Newbie friendliness
- 52/100