diff --git a/apisix/core/utils.lua b/apisix/core/utils.lua index 0b8198bc7011..ce17f547b21d 100644 --- a/apisix/core/utils.lua +++ b/apisix/core/utils.lua @@ -494,19 +494,186 @@ function _M.check_tls_bool(fields, conf, plugin_name) end -function _M.set_var_rate_limiting_info(ctx, key, limit, remaining, reset) +local json_escapes = { + ['"'] = '\\"', + ['\\'] = '\\\\', + ['\b'] = '\\b', + ['\f'] = '\\f', + ['\n'] = '\\n', + ['\r'] = '\\r', + ['\t'] = '\\t', +} +local function json_escape_char(c) + return json_escapes[c] or str_format("\\u%04x", str_byte(c)) +end + + +local function to_ms(seconds) + return math_floor(seconds * 1000 + 0.5) +end + + +local function int_or_null(value) + if value == nil then + return "null" + end + return str_format("%d", value) +end + + +local function ms_or_null(seconds) + if seconds == nil then + return "null" + end + return str_format("%d", to_ms(seconds)) +end + + +local function bool_or_null(value) + if value == nil then + return "null" + end + return value and "true" or "false" +end + + +-- a non-negative number with `digits` decimals +local function fixed_point(value, digits) + local scale = 10 ^ digits + local scaled = math_floor(value * scale + 0.5) + return str_format("%d.%0" .. digits .. "d", math_floor(scaled / scale), scaled % scale) +end + + +-- sliding windows are aligned to the clock: the window containing `now` is +-- the id-th one since the epoch, and the previous window's count is weighted +-- by the share of it still inside the sliding range +local function sliding_window_of(now, window_size) + local id = math_floor(now / window_size) + return id, id * window_size, (window_size - now % window_size) / window_size +end + + +-- handles every case, including the null values, see format_common_detail +-- for the common ones +local function format_detail(detail) + local window_type = detail.window_type + local window_size = detail.window_size + local fields = str_format(',"window_type":"%s","window_size_ms":%d,"decision":"%s"', + window_type, to_ms(window_size), detail.decision) + if detail.decision == "error" then + return fields + end + + fields = fields .. str_format(',"cost":%d,"evaluated_at_ms":%d', + detail.cost, to_ms(detail.now)) + + local delayed = detail.delayed_sync + if delayed then + fields = fields .. str_format( + ',"delayed_sync":{"synced_at_ms":%s,"synced_count":%s,"local_delta":%s}', + ms_or_null(delayed.synced_at), int_or_null(delayed.synced_count), + int_or_null(delayed.local_delta)) + end + + if window_type ~= "sliding" then + local window_end = detail.window_end + return fields .. str_format( + ',"current_window":{"start_ms":%s,"end_ms":%s,"count":%s,"created":%s}', + ms_or_null(window_end and window_end - window_size), ms_or_null(window_end), + int_or_null(detail.count), bool_or_null(detail.created)) + end + + local id, window_start, weight + if detail.window_now then + id, window_start, weight = sliding_window_of(detail.window_now, window_size) + end + local last_count = detail.last_count + return fields .. str_format( + ',"current_window":{"id":%s,"start_ms":%s,"end_ms":%s,"count":%s}' + .. ',"previous_window":{"count":%s,"weight":%s,"weighted_count":%s}', + int_or_null(id), ms_or_null(window_start), + ms_or_null(window_start and window_start + window_size), + int_or_null(detail.count), int_or_null(last_count), + weight and fixed_point(weight, 6) or "null", + (weight and last_count) and fixed_point(last_count * weight, 3) or "null") +end + + +-- The variable is set on every rate limited request, so the common cases, +-- where the counter is not synced with a delay and every value is known, are +-- formatted in a single string.format call and with integers only, which +-- keeps their cost close to the four original fields alone. +local function format_common_detail(key, limit, remaining, reset, detail) + local decision = detail.decision + local count = detail.count + if decision == "error" or detail.delayed_sync or not count then + return nil + end + + local window_size = detail.window_size + local window_size_ms = to_ms(window_size) + if detail.window_type ~= "sliding" then + local window_end = detail.window_end + if not window_end then + return nil + end + local end_ms = to_ms(window_end) + return str_format( + '{"rate_limiting_key":"%s","rate_limiting_limit":%d,' + .. '"rate_limiting_remaining":%d,"rate_limiting_reset":%d,' + .. '"window_type":"fixed","window_size_ms":%d,"decision":"%s","cost":%d,' + .. '"evaluated_at_ms":%d,"current_window":{"start_ms":%d,"end_ms":%d,' + .. '"count":%d,"created":%s}}', + key, limit, remaining, reset, window_size_ms, decision, detail.cost, + to_ms(detail.now), end_ms - window_size_ms, end_ms, count, + bool_or_null(detail.created)) + end + + local window_now = detail.window_now + local last_count = detail.last_count + if not window_now or not last_count then + return nil + end + local id, window_start, weight = sliding_window_of(window_now, window_size) + local start_ms = to_ms(window_start) + local weight_e6 = math_floor(weight * 1000000 + 0.5) + local weighted_e3 = math_floor(last_count * weight * 1000 + 0.5) + return str_format( + '{"rate_limiting_key":"%s","rate_limiting_limit":%d,' + .. '"rate_limiting_remaining":%d,"rate_limiting_reset":%d,' + .. '"window_type":"sliding","window_size_ms":%d,"decision":"%s","cost":%d,' + .. '"evaluated_at_ms":%d,"current_window":{"id":%d,"start_ms":%d,"end_ms":%d,' + .. '"count":%d},"previous_window":{"count":%d,"weight":%d.%06d,' + .. '"weighted_count":%d.%03d}}', + key, limit, remaining, reset, window_size_ms, decision, detail.cost, + to_ms(detail.now), id, start_ms, start_ms + window_size_ms, count, last_count, + math_floor(weight_e6 / 1000000), weight_e6 % 1000000, + math_floor(weighted_e3 / 1000), weighted_e3 % 1000) +end + + +-- `detail` (optional) describes the window the request was counted in, see +-- the $rate_limiting_info section of the limit-count plugin docs +function _M.set_var_rate_limiting_info(ctx, key, limit, remaining, reset, detail) if not ctx then return end - key = key or "" + -- the key usually comes from a request variable, so escape it to keep + -- the value valid JSON + key = str_gsub(tostring(key or ""), '[%c"\\]', json_escape_char) limit = limit or 0 remaining = tonumber(remaining) or 0 reset = reset or 0 - ctx.var.rate_limiting_info = str_format( - '{"rate_limiting_key":"%s","rate_limiting_limit":%d,' - .. '"rate_limiting_remaining":%d,"rate_limiting_reset":%d}', - key, limit, remaining, reset) + local info = detail and format_common_detail(key, limit, remaining, reset, detail) + if not info then + info = str_format( + '{"rate_limiting_key":"%s","rate_limiting_limit":%d,' + .. '"rate_limiting_remaining":%d,"rate_limiting_reset":%d%s}', + key, limit, remaining, reset, detail and format_detail(detail) or "") + end + ctx.var.rate_limiting_info = info end diff --git a/apisix/plugins/limit-count/delayed-syncer.lua b/apisix/plugins/limit-count/delayed-syncer.lua index 61f0b5570202..3699759253d9 100644 --- a/apisix/plugins/limit-count/delayed-syncer.lua +++ b/apisix/plugins/limit-count/delayed-syncer.lua @@ -98,12 +98,18 @@ function _M.key_remote_quota(self, key) end -function _M.sync_to_shm(self, key, remaining, reset, local_delta) +function _M.sync_to_shm(self, key, remaining, reset, local_delta, info) local quota = { remaining = remaining, reset = reset, sync_at = ngx_now(), } + -- window details of the synced counter, only reported in $rate_limiting_info + if info then + quota.count = info.count + quota.last_count = info.last_count + quota.window_now = info.now + end local _, err, quota_json @@ -124,6 +130,8 @@ function _M.sync_to_shm(self, key, remaining, reset, local_delta) core.log.error("incr local delta shm to failed: ", err, ", key: ", key) return err end + + return nil, quota end @@ -147,7 +155,8 @@ function _M.delayed_sync(self, key, cost, syncer_id) end -- wrap the delayed syncer call in a pcall to avoid the lock being held forever - local ok, remaining, reset, err = pcall(self._delayed_sync, self, key, cost, syncer_id) + local ok, remaining, reset, err, info = pcall(self._delayed_sync, self, key, cost, + syncer_id) if not ok then err = remaining remaining = nil @@ -159,12 +168,12 @@ function _M.delayed_sync(self, key, cost, syncer_id) core.log.error("unlock key(" .. key .. ") failed: ", err_unlock) end - return remaining, reset, err + return remaining, reset, err, info end function _M._delayed_sync(self, key, cost, syncer_id) - local _, reset, remote_quota_json + local _, reset, remote_quota_json, info local local_delta, err = self.shd:get(self:key_local_delta(key)) if err then return nil, nil, err @@ -209,7 +218,7 @@ function _M._delayed_sync(self, key, cost, syncer_id) -- is at/over the limit; the fixed-window backend has no commit() and its -- incoming() already increments before reporting "rejected". local flush = self.limiter.commit or self.limiter.incoming - _, remaining_or_err, reset = flush(self.limiter, key, local_delta) + _, remaining_or_err, reset, info = flush(self.limiter, key, local_delta) if type(remaining_or_err) ~= "string" then remote_remaining = remaining_or_err remote_reset = reset @@ -217,7 +226,7 @@ function _M._delayed_sync(self, key, cost, syncer_id) core.log.error("sync to redis failed: ", remaining_or_err, ", key: ", key) if self.limiter.fallback_limiter then core.log.warn("try use fallback limiter to do rate limiting") - _, remaining_or_err, reset = + _, remaining_or_err, reset, info = self.limiter.fallback_limiter:incoming(key, local_delta) if type(remaining_or_err) ~= "string" then remote_remaining = remaining_or_err @@ -240,7 +249,7 @@ function _M._delayed_sync(self, key, cost, syncer_id) core.log.info("sync to shm, key: ", key, ", remote_remaining: ", remote_remaining, ", remote_reset: ", remote_reset) - err = self:sync_to_shm(key, remote_remaining, remote_reset, local_delta) + err, quota = self:sync_to_shm(key, remote_remaining, remote_reset, local_delta, info) if err then return nil, nil, err end @@ -330,7 +339,15 @@ function _M._delayed_sync(self, key, cost, syncer_id) end end - return remaining, reset + return remaining, reset, nil, { + delayed_sync = { + synced_at = quota.sync_at, + synced_count = quota.count, + local_delta = local_delta, + }, + last_count = quota.last_count, + window_now = quota.window_now, + } end @@ -342,10 +359,10 @@ local function sync_key(self, key) if delta then local flush = self.limiter.commit or self.limiter.incoming - local _, remaining_or_err, reset = flush(self.limiter, key, delta) + local _, remaining_or_err, reset, info = flush(self.limiter, key, delta) -- compat if type(remaining_or_err) ~= "string" then - self:sync_to_shm(key, remaining_or_err, reset, delta) + self:sync_to_shm(key, remaining_or_err, reset, delta, info) elseif remaining_or_err ~= "rejected" then core.log.error("sync to redis failed: ", remaining_or_err, ", key: ", key) if self.limiter.fallback_limiter then @@ -353,19 +370,19 @@ local function sync_key(self, key) if delta < 1 then delta = 1 end - _, remaining_or_err, reset = + _, remaining_or_err, reset, info = self.limiter.fallback_limiter:incoming(key, delta) if type(remaining_or_err) ~= "string" then - self:sync_to_shm(key, remaining_or_err, reset, delta) + self:sync_to_shm(key, remaining_or_err, reset, delta, info) elseif remaining_or_err ~= "rejected" then core.log.error("sync to fallback_limiter failed: ", remaining_or_err, ", key: ", key) else - self:sync_to_shm(key, 0, reset, delta) + self:sync_to_shm(key, 0, reset, delta, info) end end else - self:sync_to_shm(key, 0, reset, delta) + self:sync_to_shm(key, 0, reset, delta, info) end end end diff --git a/apisix/plugins/limit-count/init.lua b/apisix/plugins/limit-count/init.lua index 48d93cfd9278..d64d8245443f 100644 --- a/apisix/plugins/limit-count/init.lua +++ b/apisix/plugins/limit-count/init.lua @@ -24,6 +24,7 @@ local type = type local tostring = tostring local redis_schema = require("apisix.utils.redis-schema") local get_phase = ngx.get_phase +local ngx_now = ngx.now local math_floor = math.floor local str_format = string.format @@ -486,6 +487,47 @@ local function construct_rate_limiting_headers(conf, rule, metadata) end +-- Collects what $rate_limiting_info reports about the window this request was +-- counted in. `info` is what the limiter returned next to the decision; the +-- request's own figures are added to it. +local function rate_limiting_detail(conf, rule, cost, delay, remaining, reset, info) + local detail = info or {} + detail.window_type = conf.window_type == "sliding" and "sliding" or "fixed" + detail.window_size = rule.time_window + if delay then + detail.decision = "allowed" + elseif remaining == "rejected" then + detail.decision = "rejected" + else + detail.decision = "error" + return detail + end + + local delayed = detail.delayed_sync + -- a fixed window counts the cost even when it rejects the request, the + -- sliding window and the delayed sync only count what they allow + if delay or (detail.window_type == "fixed" and not delayed) then + detail.cost = cost + else + detail.cost = 0 + end + + if not detail.now then + detail.now = ngx_now() + end + if detail.window_type == "fixed" then + detail.window_end = reset and detail.now + reset + elseif not delayed then + detail.window_now = detail.now + end + if delayed and delayed.synced_count then + detail.count = delayed.synced_count + delayed.local_delta + detail.cost + end + + return detail +end + + local function run_rate_limit(conf, rule, ctx, name, cost, dry_run) local lim, err if conf.group then @@ -547,9 +589,9 @@ local function run_rate_limit(conf, rule, ctx, name, cost, dry_run) local is_log_phase = phase == "log" local commit_cost = dry_run and 0 or cost - local delay, remaining, reset + local delay, remaining, reset, info if not conf.policy or conf.policy == "local" then - delay, remaining, reset = lim:incoming(key, commit_cost) + delay, remaining, reset, info = lim:incoming(key, commit_cost) else local enable_delayed_sync = conf.sync_interval and (conf.sync_interval ~= NO_DELAYED_SYNC) -- a dynamic time_window may resolve to a value <= sync_interval at request @@ -566,9 +608,10 @@ local function run_rate_limit(conf, rule, ctx, name, cost, dry_run) extra_key = extra_key .. '#' .. conf._vid end local plugin_instance_id = core.lrucache.plugin_ctx_id(ctx, extra_key) - delay, remaining, reset = lim:incoming_delayed(key, commit_cost, plugin_instance_id) + delay, remaining, reset, info = lim:incoming_delayed(key, commit_cost, + plugin_instance_id) else - delay, remaining, reset = lim:incoming(key, commit_cost) + delay, remaining, reset, info = lim:incoming(key, commit_cost) end end @@ -576,9 +619,10 @@ local function run_rate_limit(conf, rule, ctx, name, cost, dry_run) delay = nil remaining = "rejected" end + local detail = rate_limiting_detail(conf, rule, commit_cost, delay, remaining, reset, info) reset = reset and (math_floor(reset * 100) / 100) - core.utils.set_var_rate_limiting_info(ctx, key, lim.limit, remaining, reset) + core.utils.set_var_rate_limiting_info(ctx, key, lim.limit, remaining, reset, detail) local metadata = apisix_plugin.plugin_metadata(name) if metadata then diff --git a/apisix/plugins/limit-count/limit-count-local.lua b/apisix/plugins/limit-count/limit-count-local.lua index d6d0eb7d6a9d..68d0e4046614 100644 --- a/apisix/plugins/limit-count/limit-count-local.lua +++ b/apisix/plugins/limit-count/limit-count-local.lua @@ -32,28 +32,32 @@ local mt = { __index = _M } +local function read_reset(self, key) + -- read from dict + local end_time = (self.dict:get(key) or 0) + local reset = end_time - ngx_now() + if reset < 0 then + reset = 0 + end + return reset +end + local function set_endtime(self, key, time_window) -- set an end time local end_time = ngx_now() + time_window - -- save to dict by key - local success, err = self.dict:set(key, end_time, time_window) + -- save to dict by key. A zero-cost request (a dry-run check) may have + -- started this window already, so keep the end time it recorded. + local success, err = self.dict:add(key, end_time, time_window) if not success then + if err == "exists" then + return read_reset(self, key), false + end core.log.error("dict set key ", key, " error: ", err) end local reset = time_window - return reset -end - -local function read_reset(self, key) - -- read from dict - local end_time = (self.dict:get(key) or 0) - local reset = end_time - ngx_now() - if reset < 0 then - reset = 0 - end - return reset + return reset, true end function _M.new(plugin_name, limit, window, window_type) @@ -115,13 +119,15 @@ function _M.incoming(self, key, flag_or_cost, _conf, cost_arg) remaining_or_err = self.limit - consumed_or_err end + local created = false if remaining_or_err == self.limit - cost then - reset = set_endtime(self, key, self.window) + reset, created = set_endtime(self, key, self.window) else reset = read_reset(self, key) end - return delay, remaining_or_err, reset + return delay, remaining_or_err, reset, + {count = delay and consumed_or_err or nil, created = created} end return _M diff --git a/apisix/plugins/limit-count/limit-count-redis-cluster.lua b/apisix/plugins/limit-count/limit-count-redis-cluster.lua index d0d55e338934..fa5378b12547 100644 --- a/apisix/plugins/limit-count/limit-count-redis-cluster.lua +++ b/apisix/plugins/limit-count/limit-count-redis-cluster.lua @@ -96,14 +96,14 @@ function _M.new(plugin_name, limit, window, conf, key_version) end function _M.incoming_delayed(self, key, cost, syncer_id) - local remaining, reset, err = self.delayed_syncer:delayed_sync(key, cost, syncer_id) + local remaining, reset, err, info = self.delayed_syncer:delayed_sync(key, cost, syncer_id) if not remaining then return nil, err, 0 end if remaining < 0 then - return nil, "rejected", reset + return nil, "rejected", reset, info end - return 0, remaining, reset + return 0, remaining, reset, info end function _M.incoming(self, key, cost) diff --git a/apisix/plugins/limit-count/limit-count-redis-sentinel.lua b/apisix/plugins/limit-count/limit-count-redis-sentinel.lua index dfe20e508ee5..428e676548e4 100644 --- a/apisix/plugins/limit-count/limit-count-redis-sentinel.lua +++ b/apisix/plugins/limit-count/limit-count-redis-sentinel.lua @@ -87,14 +87,14 @@ end function _M.incoming_delayed(self, key, cost, syncer_id) - local remaining, reset, err = self.delayed_syncer:delayed_sync(key, cost, syncer_id) + local remaining, reset, err, info = self.delayed_syncer:delayed_sync(key, cost, syncer_id) if not remaining then return nil, err, 0 end if remaining < 0 then - return nil, "rejected", reset + return nil, "rejected", reset, info end - return 0, remaining, reset + return 0, remaining, reset, info end diff --git a/apisix/plugins/limit-count/limit-count-redis.lua b/apisix/plugins/limit-count/limit-count-redis.lua index 20b62707809f..f2088077bd98 100644 --- a/apisix/plugins/limit-count/limit-count-redis.lua +++ b/apisix/plugins/limit-count/limit-count-redis.lua @@ -93,14 +93,14 @@ function _M.new(plugin_name, limit, window, conf, key_version) end function _M.incoming_delayed(self, key, cost, syncer_id) - local remaining, reset, err = self.delayed_syncer:delayed_sync(key, cost, syncer_id) + local remaining, reset, err, info = self.delayed_syncer:delayed_sync(key, cost, syncer_id) if not remaining then return nil, err, 0 end if remaining < 0 then - return nil, "rejected", reset + return nil, "rejected", reset, info end - return 0, remaining, reset + return 0, remaining, reset, info end function _M.incoming(self, key, cost) @@ -114,12 +114,12 @@ function _M.incoming(self, key, cost) end self.red_cli = red - local delay, remaining, ttl = util.redis_incoming(self, key, cost, true) + local delay, remaining, ttl, info = util.redis_incoming(self, key, cost, true) if not delay and remaining ~= "rejected" then return nil, remaining, ttl end - return delay, remaining, ttl + return delay, remaining, ttl, info end function _M.log_phase_incoming(self, key, cost) diff --git a/apisix/plugins/limit-count/sliding-window/sliding-window.lua b/apisix/plugins/limit-count/sliding-window/sliding-window.lua index 7e65926278f4..ce0506db2e47 100644 --- a/apisix/plugins/limit-count/sliding-window/sliding-window.lua +++ b/apisix/plugins/limit-count/sliding-window/sliding-window.lua @@ -145,17 +145,18 @@ function _M.incoming(self, key, cost) local last_rate = last_count / self.window_size local estimated_last_window_count = last_rate * remaining_time log.debug("accepted: ", accepted, ", count: ", count, ", limit: ", self.limit) + local info = {now = now, count = count, last_count = last_count} if accepted == 0 then if count >= self.limit then - return nil, "rejected", round_off_decimal_places(remaining_time, 2) + return nil, "rejected", round_off_decimal_places(remaining_time, 2), info end local desired_delay = get_desired_delay(self, remaining_time, last_rate, count) - return nil, "rejected", round_off_decimal_places(desired_delay, 2) + return nil, "rejected", round_off_decimal_places(desired_delay, 2), info end local remaining = self.limit - count - estimated_last_window_count - return 0, math_floor(remaining), round_off_decimal_places(remaining_time, 2) + return 0, math_floor(remaining), round_off_decimal_places(remaining_time, 2), info end @@ -212,7 +213,8 @@ function _M.commit(self, key, cost) -- every window start, degrading the sliding window to a fixed one local estimated_last_window_count = last_count / self.window_size * remaining_time local remaining = math_floor(self.limit - new_count - estimated_last_window_count) - return 0, remaining, round_off_decimal_places(remaining_time, 2) + return 0, remaining, round_off_decimal_places(remaining_time, 2), + {now = now, count = new_count, last_count = last_count} end return _M diff --git a/apisix/plugins/limit-count/util.lua b/apisix/plugins/limit-count/util.lua index 7b66c89e3b79..0e5b606b6a3c 100644 --- a/apisix/plugins/limit-count/util.lua +++ b/apisix/plugins/limit-count/util.lua @@ -22,6 +22,7 @@ local crc32 = ngx.crc32_long local _M = {} local tostring = tostring +local tonumber = tonumber local commit_script = core.string.compress_script([=[ assert(tonumber(ARGV[3]) >= 0, "cost must be at least 0") @@ -183,6 +184,7 @@ function _M.redis_incoming(self, key, cost, keepalive) local remaining = limit - res[1] local ttl = res[2] / 1000.0 + local info = {count = tonumber(res[1])} if keepalive then local conf = self.conf or {} @@ -195,10 +197,10 @@ function _M.redis_incoming(self, key, cost, keepalive) if remaining < 0 then - return nil, "rejected", ttl + return nil, "rejected", ttl, info end - return 0, remaining, ttl + return 0, remaining, ttl, info end diff --git a/docs/en/latest/plugins/limit-count.md b/docs/en/latest/plugins/limit-count.md index c1b938c8e95a..0b66805c419c 100644 --- a/docs/en/latest/plugins/limit-count.md +++ b/docs/en/latest/plugins/limit-count.md @@ -2151,3 +2151,50 @@ X-Custom-RateLimit-Limit: 1 X-Custom-RateLimit-Remaining: 0 X-Custom-RateLimit-Reset: 28 ``` + +### Log Why a Request Was Allowed or Rejected + +The Plugin records its decision in the `$rate_limiting_info` variable as a JSON object, which you can add to the access log or to the `log_format` of a logger Plugin. For example, add it to the access log in `config.yaml`: + +```yaml +nginx_config: + http: + access_log_format: '$remote_addr - [$time_local] "$request" $status "$rate_limiting_info"' +``` + +A request counted in a fixed window logs a value like this: + +```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}} +``` + +A request counted in a sliding window logs a value like this: + +```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}} +``` + +All `*_ms` fields are Unix timestamps or durations in milliseconds, taken from the clock of the APISIX instance. A field that applies to the window type but is unknown for the request is `null`. The fields are: + +* `rate_limiting_key`, `rate_limiting_limit`, `rate_limiting_remaining`, `rate_limiting_reset`: the counter key, the quota, the remaining quota and the seconds until the reset, as in the rate limiting headers. When a sliding window rejects a request, `rate_limiting_reset` is the time until a request can be allowed again, which may be earlier than the end of the window. +* `window_type`: `fixed` or `sliding`. +* `window_size_ms`: the `time_window` in milliseconds. +* `decision`: `allowed`, `rejected`, or `error` when the counter could not be updated, for example because Redis is unreachable. An `error` value only carries the fields above. +* `cost`: what this request added to the counter. A fixed window counts a request even when it rejects it. A sliding window and delayed synchronization only count allowed requests, so a rejected request has a `cost` of `0`. +* `evaluated_at_ms`: when the request was checked. +* `current_window.count`: the counter of the current window after this request, including its `cost`. It is `null` when the local fixed window rejects the request. +* `current_window.start_ms` and `current_window.end_ms`: the boundaries of the current window. + +A fixed window is not aligned to the clock: it starts with the first request counted under the key and ends `time_window` seconds later. `current_window.created` is `true` for the request that started the window. It is only known with the `local` policy and is `null` with the Redis policies, where the window end is derived from the TTL of the Redis counter and may differ by a few milliseconds from one request to another. + +A sliding window is aligned to the clock: `current_window.id` counts the windows since the Unix epoch, so the current window starts at `id * window_size_ms`. A request is allowed while the current window's count plus the previous window's count weighted by the share of the previous window still inside the sliding range stays below the quota. `previous_window.count` is that previous count, capped at the quota, `previous_window.weight` is the share, from 0 to 1, and `previous_window.weighted_count` is their product. + +With delayed synchronization (`sync_interval`), the counter shared through Redis is only read once per interval, and a `delayed_sync` object describes what the request was checked against: + +* `delayed_sync.synced_at_ms`: when this APISIX instance last synchronized the counter. +* `delayed_sync.synced_count`: the count of the current window in Redis at that time. +* `delayed_sync.local_delta`: what this APISIX instance counted since then and has not synchronized yet, excluding this request. + +`current_window.count` is then an estimate, `synced_count + local_delta + cost`, that does not include what other instances counted since their last synchronization. For a sliding window, `current_window` and `previous_window` describe the windows at the time of the last synchronization: the weight applied to the previous window is fixed at synchronization time, so `previous_window.weight` is the weight that was used for this request, not the weight at `evaluated_at_ms`. The snapshot is only refreshed after its window has ended, so a request arriving a few milliseconds after the window boundary is still checked against the previous snapshot, and its `evaluated_at_ms` is then later than `current_window.end_ms`. + +When multiple `rules` are configured, the variable describes the last rule that was checked, which is the rule that rejected the request if any did. diff --git a/docs/zh/latest/plugins/limit-count.md b/docs/zh/latest/plugins/limit-count.md index 2029f3e29b6f..ece77c88f4b2 100644 --- a/docs/zh/latest/plugins/limit-count.md +++ b/docs/zh/latest/plugins/limit-count.md @@ -2152,3 +2152,50 @@ X-Custom-RateLimit-Limit: 1 X-Custom-RateLimit-Remaining: 0 X-Custom-RateLimit-Reset: 28 ``` + +### 记录请求被放行或拒绝的原因 + +插件会把本次判定写入 `$rate_limiting_info` 变量,值为一个 JSON 对象,可以加入访问日志,或加入日志类插件的 `log_format`。例如,在 `config.yaml` 中把它加入访问日志: + +```yaml +nginx_config: + http: + access_log_format: '$remote_addr - [$time_local] "$request" $status "$rate_limiting_info"' +``` + +计入固定窗口的请求记录的值类似如下: + +```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}} +``` + +计入滑动窗口的请求记录的值类似如下: + +```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}} +``` + +所有 `*_ms` 字段都是以毫秒为单位的 Unix 时间戳或时长,取自 APISIX 实例的时钟。适用于该窗口类型、但对本次请求未知的字段为 `null`。各字段含义如下: + +* `rate_limiting_key`、`rate_limiting_limit`、`rate_limiting_remaining`、`rate_limiting_reset`:计数器的键、配额、剩余配额以及距重置的秒数,与限流响应头一致。滑动窗口拒绝请求时,`rate_limiting_reset` 是距离可以再次放行请求的时间,可能早于窗口结束时间。 +* `window_type`:`fixed` 或 `sliding`。 +* `window_size_ms`:以毫秒表示的 `time_window`。 +* `decision`:`allowed`、`rejected`,或在无法更新计数器(例如 Redis 不可达)时为 `error`。值为 `error` 时只包含以上字段。 +* `cost`:本次请求计入计数器的值。固定窗口即使拒绝请求也会计数;滑动窗口和延迟同步只对放行的请求计数,因此被拒绝请求的 `cost` 为 `0`。 +* `evaluated_at_ms`:检查本次请求的时间。 +* `current_window.count`:计入本次请求(含其 `cost`)之后当前窗口的计数。本地固定窗口拒绝请求时为 `null`。 +* `current_window.start_ms` 和 `current_window.end_ms`:当前窗口的起止时间。 + +固定窗口不与时钟对齐:它从该键下计入的第一个请求开始,持续 `time_window` 秒。`current_window.created` 在开启该窗口的请求上为 `true`。它只在 `local` 策略下可知,在 Redis 策略下为 `null`;Redis 策略下窗口结束时间由 Redis 计数器的 TTL 推算,不同请求之间可能相差几毫秒。 + +滑动窗口与时钟对齐:`current_window.id` 是自 Unix 纪元以来的窗口序号,当前窗口从 `id * window_size_ms` 开始。当前窗口的计数加上上一个窗口按其仍处于滑动范围内的比例加权后的计数,只要低于配额,请求就会被放行。`previous_window.count` 是上一个窗口的计数(不超过配额),`previous_window.weight` 是该比例(0 到 1),`previous_window.weighted_count` 是两者的乘积。 + +启用延迟同步(`sync_interval`)时,通过 Redis 共享的计数器每个间隔只读取一次,`delayed_sync` 对象描述了本次请求所依据的数据: + +* `delayed_sync.synced_at_ms`:该 APISIX 实例上一次同步计数器的时间。 +* `delayed_sync.synced_count`:当时 Redis 中当前窗口的计数。 +* `delayed_sync.local_delta`:该 APISIX 实例自那以后计入、尚未同步的值,不含本次请求。 + +此时 `current_window.count` 是估算值,即 `synced_count + local_delta + cost`,不包含其他实例自各自上次同步以来的计数。对于滑动窗口,`current_window` 和 `previous_window` 描述的是上一次同步时的窗口:上一个窗口的权重在同步时就已确定,因此 `previous_window.weight` 是本次请求实际使用的权重,而不是 `evaluated_at_ms` 时刻的权重。快照只在其窗口结束之后才会刷新,因此在窗口边界之后几毫秒内到达的请求仍按上一次的快照判定,此时它的 `evaluated_at_ms` 会晚于 `current_window.end_ms`。 + +配置多条 `rules` 时,该变量描述最后一条被检查的规则;如果有规则拒绝了请求,就是该规则。 diff --git a/t/lib/rate_limiting_info.lua b/t/lib/rate_limiting_info.lua new file mode 100644 index 000000000000..0c3ce1969305 --- /dev/null +++ b/t/lib/rate_limiting_info.lua @@ -0,0 +1,102 @@ +-- +-- Licensed to the Apache Software Foundation (ASF) under one or more +-- contributor license agreements. See the NOTICE file distributed with +-- this work for additional information regarding copyright ownership. +-- The ASF licenses this file to You under the Apache License, Version 2.0 +-- (the "License"); you may not use this file except in compliance with +-- the License. You may obtain a copy of the License at +-- +-- http://www.apache.org/licenses/LICENSE-2.0 +-- +-- Unless required by applicable law or agreed to in writing, software +-- distributed under the License is distributed on an "AS IS" BASIS, +-- WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +-- See the License for the specific language governing permissions and +-- limitations under the License. +-- +local cjson = require("cjson.safe") +local concat = table.concat + +-- Logs the time-independent part of $rate_limiting_info as one line, and +-- checks the timestamps against each other instead of printing them. +local _M = {} + + +local function show(value) + if value == nil then + return "absent" + end + if value == cjson.null then + return "null" + end + return tostring(value) +end + + +local function window_ok(info, window) + local size = info.window_size_ms + if window.end_ms - window.start_ms ~= size then + return "bad-size" + end + if info.evaluated_at_ms < window.start_ms or info.evaluated_at_ms > window.end_ms then + return "outside" + end + return "ok" +end + + +function _M.log() + local raw = ngx.var.rate_limiting_info + local info, err = cjson.decode(raw) + if not info then + ngx.log(ngx.ERR, "invalid rate_limiting_info: ", err, ": ", raw) + return + end + + local out = { + info.window_type, info.decision, + "cost=" .. show(info.cost), + } + + local delayed = info.delayed_sync + if type(delayed) == "table" then + out[#out + 1] = "synced_count=" .. show(delayed.synced_count) + out[#out + 1] = "local_delta=" .. show(delayed.local_delta) + out[#out + 1] = "synced_at=" .. (delayed.synced_at_ms <= info.evaluated_at_ms + and "ok" or "later") + end + + local cur = info.current_window + if type(cur) ~= "table" then + out[#out + 1] = "current_window=" .. show(cur) + ngx.log(ngx.WARN, "rate limiting info: ", concat(out, " ")) + return + end + + out[#out + 1] = "count=" .. show(cur.count) + if info.window_type == "fixed" then + out[#out + 1] = "created=" .. show(cur.created) + out[#out + 1] = "window=" .. window_ok(info, cur) + if cur.created == true and cur.start_ms ~= info.evaluated_at_ms then + out[#out + 1] = "created-not-at-start" + end + out[#out + 1] = "previous_window=" .. show(info.previous_window) + else + out[#out + 1] = "window=" .. window_ok(info, cur) + if cur.start_ms ~= cur.id * info.window_size_ms then + out[#out + 1] = "not-aligned" + end + local prev = info.previous_window + out[#out + 1] = "previous_count=" .. show(prev.count) + local weight = prev.weight + if weight < 0 or weight > 1 + or math.abs(prev.weighted_count - prev.count * weight) > 0.001 then + out[#out + 1] = "bad-weight" + end + end + + ngx.log(ngx.WARN, "rate limiting info: ", concat(out, " ")) +end + + +return _M diff --git a/t/plugin/ai-rate-limiting.t b/t/plugin/ai-rate-limiting.t index d4fad74991c1..c5ea8877bc36 100644 --- a/t/plugin/ai-rate-limiting.t +++ b/t/plugin/ai-rate-limiting.t @@ -1783,3 +1783,102 @@ apisix: --- response_body somepassword encrypted + + + +=== TEST 41: set route for checking the reset time after a request that consumed nothing +--- config + location /t { + content_by_lua_block { + local t = require("lib.test_admin").test + local code, body = t('/apisix/admin/routes/1', + ngx.HTTP_PUT, + [[{ + "uri": "/ai", + "plugins": { + "ai-proxy": { + "provider": "openai", + "auth": { + "header": { + "Authorization": "Bearer token" + } + }, + "options": { + "model": "gpt-35-turbo-instruct" + }, + "override": { + "endpoint": "http://127.0.0.1:1980" + }, + "ssl_verify": false + }, + "ai-rate-limiting": { + "limit": 100, + "time_window": 3 + } + }, + "upstream": { + "type": "roundrobin", + "nodes": { + "canbeanything.com": 1 + } + } + }]] + ) + + if code >= 300 then + ngx.status = code + end + ngx.say(body) + } + } +--- response_body +passed + + + +=== TEST 42: the window end stays put when a request charges no tokens +--- config + location /t { + content_by_lua_block { + local http = require("resty.http") + local uri = "http://127.0.0.1:" .. ngx.var.server_port .. "/ai" + local function send(fixture, status) + local httpc = http.new() + return httpc:request_uri(uri, { + method = "POST", + body = [[{"messages": [{"role": "user", "content": "hi"}]}]], + headers = { + ["Content-Type"] = "application/json", + ["Authorization"] = "Bearer token", + ["X-AI-Fixture"] = fixture, + ["X-AI-Fixture-Status"] = status, + }, + }) + end + + -- the upstream fails, so this request starts the window without + -- charging any token + local res, err = send("openai/chat-error.json", "500") + if not res then + ngx.say("request failed: ", err) + return + end + + ngx.sleep(1.5) + res, err = send("openai/chat-model-echo.json", "200") + if not res then + ngx.say("request failed: ", err) + return + end + local reset = tonumber(res.headers["X-AI-RateLimit-Reset-ai-proxy-openai"]) + if not reset or reset > 2 then + ngx.say("unexpected reset: ", res.headers["X-AI-RateLimit-Reset-ai-proxy-openai"]) + return + end + ngx.say("passed") + } + } +--- response_body +passed +--- error_log +failed to get token usage for llm service diff --git a/t/plugin/limit-count-rate-limiting-info.t b/t/plugin/limit-count-rate-limiting-info.t new file mode 100644 index 000000000000..dd6a6e2d6dee --- /dev/null +++ b/t/plugin/limit-count-rate-limiting-info.t @@ -0,0 +1,287 @@ +# +# Licensed to the Apache Software Foundation (ASF) under one or more +# contributor license agreements. See the NOTICE file distributed with +# this work for additional information regarding copyright ownership. +# The ASF licenses this file to You under the Apache License, Version 2.0 +# (the "License"); you may not use this file except in compliance with +# the License. You may obtain a copy of the License at +# +# http://www.apache.org/licenses/LICENSE-2.0 +# +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an "AS IS" BASIS, +# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +# See the License for the specific language governing permissions and +# limitations under the License. +# +use t::APISIX 'no_plan'; + +repeat_each(1); +no_long_string(); +no_shuffle(); +no_root_location(); +log_level('info'); + +add_block_preprocessor(sub { + my ($block) = @_; + + # `--- limit_count` holds the plugin conf of a route whose log phase logs + # $rate_limiting_info through lib.rate_limiting_info + my $limit_count = $block->limit_count; + if ($limit_count) { + $block->set_value("config", <<_EOC_); + location /t { + content_by_lua_block { + local core = require("apisix.core") + local t = require("lib.test_admin").test + local conf = core.json.decode([=[$limit_count]=]) + -- a fresh counter on every run, so that a rerun sees the same counts + conf.key_type = "constant" + conf.key = "rl-info-" .. ngx.now() .. "-" .. math.random(1e9) + local code, body = t('/apisix/admin/routes/1', ngx.HTTP_PUT, + core.json.encode({ + uri = "/hello", + plugins = { + ["limit-count"] = conf, + ["serverless-post-function"] = { + phase = "log", + functions = { + "return function() require('lib.rate_limiting_info').log() end" + }, + }, + }, + upstream = { + nodes = {["127.0.0.1:1980"] = 1}, + type = "roundrobin", + }, + })) + if code >= 300 then + ngx.status = code + end + ngx.say(body) + } + } +_EOC_ + $block->set_value("response_body", "passed\n"); + } + + # `--- send_requests` sends that many requests to the route one by one, + # and prints their status codes + my $send_requests = $block->send_requests; + if ($send_requests) { + $block->set_value("config", <<_EOC_); + location /t { + content_by_lua_block { + local http = require("resty.http") + local uri = "http://127.0.0.1:" .. ngx.var.server_port .. "/hello" + -- keep the requests inside one 60s sliding window + local left = 60 - ngx.now() % 60 + if left < 2 then + ngx.sleep(left + 0.1) + end + local codes = {} + for i = 1, $send_requests do + local httpc = http.new() + local res, err = httpc:request_uri(uri) + if not res then + ngx.say(err) + return + end + codes[i] = res.status + end + ngx.say(table.concat(codes, " ")) + } + } +_EOC_ + } + + if (!$block->request) { + $block->set_value("request", "GET /t"); + } + + if (!$block->error_log && !$block->no_error_log) { + $block->set_value("no_error_log", "[error]\n[alert]"); + } +}); + +run_tests; + +__DATA__ + +=== TEST 1: local fixed window +--- limit_count +{"count": 2, "time_window": 60, "policy": "local", "window_type": "fixed"} + + + +=== TEST 2: the first request creates the window, the rejected one has no count +--- send_requests: 3 +--- response_body +200 200 503 +--- grep_error_log eval +qr/rate limiting info: .*?(?= while logging request)/ +--- grep_error_log_out +rate limiting info: fixed allowed cost=1 count=1 created=true window=ok previous_window=absent +rate limiting info: fixed allowed cost=1 count=2 created=false window=ok previous_window=absent +rate limiting info: fixed rejected cost=1 count=null created=false window=ok previous_window=absent + + + +=== TEST 3: local sliding window +--- limit_count +{"count": 2, "time_window": 60, "policy": "local", "window_type": "sliding"} + + + +=== TEST 4: a rejected request adds nothing to the sliding window +--- send_requests: 3 +--- response_body +200 200 503 +--- grep_error_log eval +qr/rate limiting info: .*?(?= while logging request)/ +--- grep_error_log_out +rate limiting info: sliding allowed cost=1 count=1 window=ok previous_count=0 +rate limiting info: sliding allowed cost=1 count=2 window=ok previous_count=0 +rate limiting info: sliding rejected cost=0 count=2 window=ok previous_count=0 + + + +=== TEST 5: redis fixed window +--- limit_count +{"count": 2, "time_window": 60, "policy": "redis", "redis_host": "127.0.0.1", + "window_type": "fixed"} + + + +=== TEST 6: the redis counter also counts the rejected request +--- send_requests: 3 +--- response_body +200 200 503 +--- grep_error_log eval +qr/rate limiting info: .*?(?= while logging request)/ +--- grep_error_log_out +rate limiting info: fixed allowed cost=1 count=1 created=null window=ok previous_window=absent +rate limiting info: fixed allowed cost=1 count=2 created=null window=ok previous_window=absent +rate limiting info: fixed rejected cost=1 count=3 created=null window=ok previous_window=absent + + + +=== TEST 7: redis sliding window +--- limit_count +{"count": 2, "time_window": 60, "policy": "redis", "redis_host": "127.0.0.1", + "window_type": "sliding"} + + + +=== TEST 8: redis sliding window details +--- send_requests: 3 +--- response_body +200 200 503 +--- grep_error_log eval +qr/rate limiting info: .*?(?= while logging request)/ +--- grep_error_log_out +rate limiting info: sliding allowed cost=1 count=1 window=ok previous_count=0 +rate limiting info: sliding allowed cost=1 count=2 window=ok previous_count=0 +rate limiting info: sliding rejected cost=0 count=2 window=ok previous_count=0 + + + +=== TEST 9: redis fixed window with delayed sync +--- limit_count +{"count": 2, "time_window": 60, "policy": "redis", "redis_host": "127.0.0.1", + "window_type": "fixed", "sync_interval": 10} + + + +=== TEST 10: delayed sync reports the synced count and the unsynced local delta +--- send_requests: 3 +--- response_body +200 200 503 +--- grep_error_log eval +qr/rate limiting info: .*?(?= while logging request)/ +--- grep_error_log_out +rate limiting info: fixed allowed cost=1 synced_count=0 local_delta=0 synced_at=ok count=1 created=null window=ok previous_window=absent +rate limiting info: fixed allowed cost=1 synced_count=0 local_delta=1 synced_at=ok count=2 created=null window=ok previous_window=absent +rate limiting info: fixed rejected cost=0 synced_count=0 local_delta=2 synced_at=ok count=2 created=null window=ok previous_window=absent + + + +=== TEST 11: redis sliding window with delayed sync +--- limit_count +{"count": 2, "time_window": 60, "policy": "redis", "redis_host": "127.0.0.1", + "window_type": "sliding", "sync_interval": 10} + + + +=== TEST 12: delayed sync reports the sliding window as of the last sync +--- send_requests: 3 +--- response_body +200 200 503 +--- grep_error_log eval +qr/rate limiting info: .*?(?= while logging request)/ +--- grep_error_log_out +rate limiting info: sliding allowed cost=1 synced_count=0 local_delta=0 synced_at=ok count=1 window=ok previous_count=0 +rate limiting info: sliding allowed cost=1 synced_count=0 local_delta=1 synced_at=ok count=2 window=ok previous_count=0 +rate limiting info: sliding rejected cost=0 synced_count=0 local_delta=2 synced_at=ok count=2 window=ok previous_count=0 + + + +=== TEST 13: redis-cluster fixed window +--- limit_count +{"count": 2, "time_window": 60, "policy": "redis-cluster", + "redis_cluster_nodes": ["127.0.0.1:5000", "127.0.0.1:5001"], + "redis_cluster_name": "redis-cluster-1", "window_type": "fixed"} + + + +=== TEST 14: redis-cluster fixed window details +--- send_requests: 3 +--- response_body +200 200 503 +--- grep_error_log eval +qr/rate limiting info: .*?(?= while logging request)/ +--- grep_error_log_out +rate limiting info: fixed allowed cost=1 count=1 created=null window=ok previous_window=absent +rate limiting info: fixed allowed cost=1 count=2 created=null window=ok previous_window=absent +rate limiting info: fixed rejected cost=1 count=3 created=null window=ok previous_window=absent + + + +=== TEST 15: redis-cluster sliding window with delayed sync +--- limit_count +{"count": 2, "time_window": 60, "policy": "redis-cluster", + "redis_cluster_nodes": ["127.0.0.1:5000", "127.0.0.1:5001"], + "redis_cluster_name": "redis-cluster-1", "window_type": "sliding", "sync_interval": 10} + + + +=== TEST 16: redis-cluster sliding window details with delayed sync +--- send_requests: 3 +--- response_body +200 200 503 +--- grep_error_log eval +qr/rate limiting info: .*?(?= while logging request)/ +--- grep_error_log_out +rate limiting info: sliding allowed cost=1 synced_count=0 local_delta=0 synced_at=ok count=1 window=ok previous_count=0 +rate limiting info: sliding allowed cost=1 synced_count=0 local_delta=1 synced_at=ok count=2 window=ok previous_count=0 +rate limiting info: sliding rejected cost=0 synced_count=0 local_delta=2 synced_at=ok count=2 window=ok previous_count=0 + + + +=== TEST 17: redis unreachable, degraded +--- limit_count +{"count": 2, "time_window": 60, "policy": "redis", "redis_host": "127.0.0.1", + "redis_port": 16379, "allow_degradation": true} + + + +=== TEST 18: a failed limiter reports only the decision +--- send_requests: 1 +--- response_body +200 +--- grep_error_log eval +qr/rate limiting info: .*?(?= while logging request)/ +--- grep_error_log_out +rate limiting info: fixed error cost=absent current_window=absent +--- error_log +failed to limit count diff --git a/t/plugin/limit-count-variable.t b/t/plugin/limit-count-variable.t index e879a871c8b5..c6bda2b7ef58 100644 --- a/t/plugin/limit-count-variable.t +++ b/t/plugin/limit-count-variable.t @@ -283,7 +283,7 @@ nginx_config: access_log_format: main '$rate_limiting_info'; --- error_code: 200 --- access_log eval -qr/\{\\x22rate_limiting_key\\x22:\\x22\/apisix\/routes\/1:\d+:test\.com\\x22,\\x22rate_limiting_limit\\x22:2,\\x22rate_limiting_remaining\\x22:1,\\x22rate_limiting_reset\\x22:10}/ +qr/\{\\x22rate_limiting_key\\x22:\\x22\/apisix\/routes\/1:\d+:test\.com\\x22,\\x22rate_limiting_limit\\x22:2,\\x22rate_limiting_remaining\\x22:1,\\x22rate_limiting_reset\\x22:10,\\x22window_type\\x22:\\x22fixed\\x22,\\x22window_size_ms\\x22:10000,\\x22decision\\x22:\\x22allowed\\x22,\\x22cost\\x22:1,/ @@ -452,3 +452,55 @@ GET /t passed --- error_log resolved value must be a positive number + + + +=== TEST 14: set up route keyed on a request header, decoding rate_limiting_info in log phase +--- config + location /t { + content_by_lua_block { + local t = require("lib.test_admin").test + local code, body = t('/apisix/admin/routes/1', + ngx.HTTP_PUT, + [[{ + "plugins": { + "limit-count": { + "count": 2, + "time_window": 60, + "key_type": "var", + "key": "http_x_client" + }, + "serverless-post-function": { + "phase": "log", + "functions": ["return function(conf, ctx) local info = require('cjson.safe').decode(ngx.var.rate_limiting_info) ngx.log(ngx.WARN, 'decoded rate limiting key: ', info and info.rate_limiting_key) end"] + } + }, + "upstream": { + "nodes": { + "127.0.0.1:1980": 1 + }, + "type": "roundrobin" + }, + "uri": "/hello" + }]] + ) + + if code >= 300 then + ngx.status = code + end + ngx.say(body) + } + } +--- response_body +passed + + + +=== TEST 15: rate_limiting_info stays valid JSON when the key has quotes and backslashes +--- request +GET /hello +--- more_headers +x-client: a"b\c +--- error_code: 200 +--- error_log eval +qr/decoded rate limiting key: \/apisix\/routes\/1:\d+:a"b\\c/ diff --git a/t/plugin/limit-count5.t b/t/plugin/limit-count5.t index 15a3e0ba4467..aa9b2055a2b3 100644 --- a/t/plugin/limit-count5.t +++ b/t/plugin/limit-count5.t @@ -252,7 +252,7 @@ nginx_config: access_log_format: main '$rate_limiting_info'; --- error_code: 200 --- access_log eval -qr/\{\\x22rate_limiting_key\\x22:\\x22\/apisix\/routes\/1:\d+:test\.com\\x22,\\x22rate_limiting_limit\\x22:2,\\x22rate_limiting_remaining\\x22:1,\\x22rate_limiting_reset\\x22:10}/ +qr/\{\\x22rate_limiting_key\\x22:\\x22\/apisix\/routes\/1:\d+:test\.com\\x22,\\x22rate_limiting_limit\\x22:2,\\x22rate_limiting_remaining\\x22:1,\\x22rate_limiting_reset\\x22:10,\\x22window_type\\x22:\\x22fixed\\x22,\\x22window_size_ms\\x22:10000,\\x22decision\\x22:\\x22allowed\\x22,\\x22cost\\x22:1,/