apache / apache/apisix

bug: logger `_meta.filter` evaluates response-phase variables at access phase, breaking filters and caching `$status` as `0`

Open
#13,724 1 comment 0 reactions 0 assignees View on GitHub
bug
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

Open the contributing 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

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.