nic-6443 opened a new pull request, #13996:
URL: https://github.com/apache/apisix/pull/13996
`$rate_limiting_info` only carries the key, limit, remaining and reset,
which isn't enough to tell from an access log why a request was let through or
rejected, or when exactly a window started. This PR appends the window the
request was counted in, with millisecond timestamps. The four existing fields
are unchanged and still come first.
Fixed window:
```json
{"rate_limiting_key":"/apisix/routes/1:1:127.0.0.1","rate_limiting_limit":10,"rate_limiting_remaining":3,"rate_limiting_reset":42,"window_type":"fixed","window_size_ms":60000,"decision":"allowed","cost":1,"evaluated_at_ms":1759212345678,"current_window":{"start_ms":1759212300123,"end_ms":1759212360123,"count":7,"created":false}}
```
Sliding window:
```json
{"rate_limiting_key":"/apisix/routes/1:1:127.0.0.1","rate_limiting_limit":10,"rate_limiting_remaining":3,"rate_limiting_reset":14,"window_type":"sliding","window_size_ms":60000,"decision":"allowed","cost":1,"evaluated_at_ms":1759212345678,"current_window":{"id":29320205,"start_ms":1759212300000,"end_ms":1759212360000,"count":4},"previous_window":{"count":10,"weight":0.238700,"weighted_count":2.387}}
```
With `sync_interval`, a
`"delayed_sync":{"synced_at_ms":…,"synced_count":…,"local_delta":…}` object is
added after `evaluated_at_ms`, and `current_window.count` becomes the estimate
`synced_count + local_delta + cost`. `decision` is `allowed`, `rejected` or
`error`, and an `error` only carries `window_type`, `window_size_ms` and
`decision`, so a Redis failure no longer looks like a rejection in the log.
`count` is the counter after this request and `cost` is what this request added
to it, which is needed to reconstruct the decision: a fixed window counts
rejected requests too, a sliding window and delayed sync don't.
This is observability only. The limiters just pass out values they already
have, as an extra return value of `incoming()`/`commit()`, plus three more
fields in the quota JSON that the delayed syncer already writes to the shared
dict. There is no extra shared dict or Redis call, no Redis script change, and
no change to any decision. So a few fields are `null` where the code path
doesn't have the value:
- `current_window.created` with the Redis policies
- `current_window.count` when the local fixed window rejects
(`resty.limit.count` drops the counter on rejection)
- the delayed-sync snapshot fields (`synced_count`, and the sliding window
fields) until the first sync after an upgrade
`delayed_sync.local_delta` is the local delta the decision subtracted. Right
after a refresh of an expired cached quota, that delta was already flushed into
`synced_count`, which is the double count #13950 fixes. With #13950 it is 0
there, as it should be.
The JSON is built in `core.utils.set_var_rate_limiting_info`, which still
accepts the old five arguments.
Two small fixes found along the way, in their own commits:
- The key wasn't JSON-escaped, so a quote or backslash in, for example, a
header-based key made the variable invalid JSON.
- Local fixed window: the end time was recorded whenever the counter equaled
the request's cost. ai-rate-limiting's zero-cost access check matches that on
every call while the counter is 0, and so does the first real charge after it,
so each of them pushed the recorded end time later while the counter kept its
original TTL, and `X-AI-RateLimit-Reset` over-reported. The end time is now
only recorded when the window has none yet (`add` instead of `set`).
`t/plugin/ai-rate-limiting.t` TEST 42 fails without it (reset `3` instead of
~`1.5`).
Per-request overhead: I ran wrk2 at a fixed 10k req/s against a single
worker with one local rule and the access log off, so this is the cost every
request pays whether or not the variable is logged. Over 8 interleaved rounds
against master, worker CPU per request was 52.1 vs 52.2 µs for the fixed window
and 54.6 vs 54.6 µs for the sliding window (medians). The paired per-round
differences stay within the ±3 µs run-to-run noise. Benchmarking
`set_var_rate_limiting_info` alone puts the added formatting at about 0.7 µs
(fixed) and 1.1 µs (sliding) per call with the JIT off, and 0.1 / 0.3 µs with
it on. The common cases are formatted in a single `string.format` over integers
for that reason.
Tests: `t/plugin/limit-count-rate-limiting-info.t` covers local, redis and
redis-cluster × fixed/sliding, delayed sync for both window types, and the
degraded error path. It decodes the variable in the log phase and checks the
timestamps against each other, so it doesn't depend on wall-clock values. The
existing access-log assertions in `limit-count-variable.t` and `limit-count5.t`
are adjusted for the appended fields. The docs gain a section on the variable
in `limit-count.md` (en/zh).
- [x] I have explained the need for this PR and the problem it solves
- [x] I have explained the changes or the new features added to this PR
- [x] I have added tests corresponding to this change
- [x] I have updated the documentation to reflect this change
- [x] I have verified that this change is backward compatible
--
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]
