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

[janiussyafiq]

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

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

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

docker compose up -d
sleep 15

One route, used by every scenario:

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:

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.

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.

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:

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:

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

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:

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:

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:

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.

[goutamadwant]

@janiussyafiq i added a PR to address this. Let me know if you have any suggestions or this makes sense. thanks!