You are viewing a plain text version of this content. The canonical link for it is here.
Posted to notifications@apisix.apache.org by "janiussyafiq (via GitHub)" <gi...@apache.org> on 2026/07/21 03:43:06 UTC
[I] bug: logger `_meta.filter` evaluates response-phase variables at access phase, breaking filters and caching `$status` as `0` [apisix]
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: notifications-unsubscribe@apisix.apache.org.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
Re: [I] bug: logger `_meta.filter` evaluates response-phase variables at access phase, breaking filters and caching `$status` as `0` [apisix]
Posted by "goutamadwant (via GitHub)" <gi...@apache.org>.
goutamadwant commented on issue #13724:
URL: https://github.com/apache/apisix/issues/13724#issuecomment-5053184628
@janiussyafiq i added a PR to address this. Let me know if you have any suggestions or this makes sense. thanks!
--
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: notifications-unsubscribe@apisix.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org