From 839a44656602d55527dbf3ac070b2590ee5f123d Mon Sep 17 00:00:00 2001 From: Martin Dobrev Date: Fri, 7 Aug 2026 16:54:22 +0100 Subject: [PATCH 1/4] feat: Record enforcement decisions with per-mechanism attribution (#C2) Groundwork for "why was this blocked?". The engine already computed a rich verdict and then reduced it to one log line, so a customer with a request id and a complaint could only be answered by grepping the error log. Three parts. The executor now returns a per-node trace. It built node_results and threw them away, so the aggregate score was all that survived: 65 points, with nothing to say which of eight mechanisms produced them. The trace is built where the score and flags are already accumulated, so it always adds up to the aggregate rather than being a parallel calculation that can disagree. Live, a blocked request now reads keyword_filter blocked on kw:viagra, pattern_scan +5 for email:1, fingerprint +30 for suspicious-bot, total 35. Recording happens in the log phase, not in the enforcement branches. There are six of them -- block, captcha, tarpit, flag, monitor, allow -- and covering five is exactly the mistake made in shadow mode, where one of two would-block branches was missed at first. process_request stashes the verdict on ngx.ctx and one log_by_lua call records it with the response status attached. That also makes the record honest about monitoring mode: verdict "block", status 200, action "would_block". The buffering is now shared. shadow_recorder's buffer carried two concurrency defects' worth of hard-won detail -- the multi-worker drain that duplicated records, and the range claim that overshot the head and silently lost them. A second hand-rolled copy would likely have reproduced one, so it is extracted into decision_buffer and both recorders use it. The refactor is proven by the existing 76 specs passing unchanged, including the two that guard those defects. Retention is configurable and bounded: WAF_DECISION_LOG_ENABLED, _MAX, _TTL and _MIN_SCORE, declared in both nginx.conf and the Helm ConfigMap and held there by the drift gate. Off is a legitimate setting -- the log stores paths and client IPs, which some deployments would rather not retain. Not every request is kept. Anything acted on is, plus anything scoring above the threshold so a near-miss stays explicable; a clean allowed request is not, since recording those would evict the decisions somebody needs. Gates: 88 unit specs (12 new), helm drift clean at 33/33 and 15/15, config contracts hold, integration 42 passed / 2 known gaps / 0 failed. --- .../templates/openresty-configmap.yaml | 5 + openresty/conf/nginx.conf | 21 ++ openresty/lua/decision_buffer.lua | 186 +++++++++++++++ openresty/lua/decision_recorder.lua | 216 ++++++++++++++++++ openresty/lua/defense_profile_executor.lua | 30 ++- .../lua/defense_profile_multi_executor.lua | 5 +- openresty/lua/redis_sync.lua | 11 + openresty/lua/shadow_recorder.lua | 164 +++---------- openresty/lua/waf_handler.lua | 89 ++++++++ openresty/spec/decision_recorder_spec.lua | 153 +++++++++++++ 10 files changed, 750 insertions(+), 130 deletions(-) create mode 100644 openresty/lua/decision_buffer.lua create mode 100644 openresty/lua/decision_recorder.lua create mode 100644 openresty/spec/decision_recorder_spec.lua diff --git a/helm/forms-waf/templates/openresty-configmap.yaml b/helm/forms-waf/templates/openresty-configmap.yaml index 7ff1866..0615ea7 100644 --- a/helm/forms-waf/templates/openresty-configmap.yaml +++ b/helm/forms-waf/templates/openresty-configmap.yaml @@ -34,6 +34,10 @@ data: env WAF_LOG_HMAC_KEY; env WAF_SESSION_TTL; env WAF_TRUSTED_PROXIES; + env WAF_DECISION_LOG_ENABLED; + env WAF_DECISION_LOG_MAX; + env WAF_DECISION_LOG_TTL; + env WAF_DECISION_LOG_MIN_SCORE; env http_proxy; env https_proxy; env no_proxy; @@ -107,6 +111,7 @@ data: lua_shared_dict coordinator_cache 1m; lua_shared_dict shadow_cache 10m; lua_shared_dict suppression_cache 1m; + lua_shared_dict decision_cache 10m; # Initialize modules on worker start init_worker_by_lua_block { diff --git a/openresty/conf/nginx.conf b/openresty/conf/nginx.conf index 5c557f5..55c54e6 100644 --- a/openresty/conf/nginx.conf +++ b/openresty/conf/nginx.conf @@ -37,6 +37,10 @@ env HOSTNAME; # Security: Trusted proxy configuration (F01) # Comma-separated list of trusted proxy CIDRs env WAF_TRUSTED_PROXIES; +env WAF_DECISION_LOG_ENABLED; +env WAF_DECISION_LOG_MAX; +env WAF_DECISION_LOG_TTL; +env WAF_DECISION_LOG_MIN_SCORE; # Log integrity HMAC key (F08) env WAF_LOG_HMAC_KEY; # F15: SSRF protection configuration @@ -137,6 +141,7 @@ http { lua_shared_dict coordinator_cache 1m; # Instance coordinator state lua_shared_dict shadow_cache 10m; # Shadow-mode would-block buffer (flushed to Redis by a timer) lua_shared_dict suppression_cache 1m; # Rule suppressions, read on every defense node + lua_shared_dict decision_cache 10m; # Decision log buffer (flushed to Redis by a timer) # Initialize modules on worker start init_worker_by_lua_block { @@ -308,6 +313,14 @@ http { waf.process_request() } + # Records the decision stashed during the access phase. In the log + # phase because that is the one place that sees exactly one outcome + # per request, and the outcome that actually reached the client. + log_by_lua_block { + local waf = require "waf_handler" + waf.log_decision() + } + # Dynamic proxy based on vhost routing config (set by waf_handler) proxy_pass $upstream_url$request_uri; proxy_http_version 1.1; @@ -400,6 +413,14 @@ http { waf.process_request() } + # Records the decision stashed during the access phase. In the log + # phase because that is the one place that sees exactly one outcome + # per request, and the outcome that actually reached the client. + log_by_lua_block { + local waf = require "waf_handler" + waf.log_decision() + } + # Dynamic proxy based on vhost routing config (set by waf_handler) proxy_pass $upstream_url$request_uri; proxy_http_version 1.1; diff --git a/openresty/lua/decision_buffer.lua b/openresty/lua/decision_buffer.lua new file mode 100644 index 0000000..ff10307 --- /dev/null +++ b/openresty/lua/decision_buffer.lua @@ -0,0 +1,186 @@ +--[[ + Decision buffer + =============== + Shared machinery for "record something in the request path, write it to Redis + from a timer". Extracted from shadow_recorder when a second recorder needed + the same thing, because what it holds is not boilerplate -- it is two + concurrency defects that were each found the hard way: + + * redis_sync's timer runs on EVERY worker (24 on a typical box). Reading + the tail, draining, then writing it back let every worker drain the same + slots, turning one decision into one record per worker. + + * Claiming a range with incr(TAIL, pending) fixed the duplicates and + introduced something worse. A second worker claiming the same `pending` + pushed the tail past the head, into slots the writer had not filled yet. + Those claims drained nothing, and every record written into the gap was + skipped for good -- no duplicates, so the obvious test passed, while + records were silently lost. + + A second hand-rolled copy of this would very likely reproduce one of them. + + The design that survives both: a single drainer holds an atomic add() lock, + and the tail advances one slot at a time as each is written, so a drain that + dies part-way resumes exactly where it stopped -- neither replaying a record + nor losing one. + + Callers supply the Redis writes, which is the only part that differs between + recorders. +]] + +local cjson = require "cjson.safe" + +local _M = {} + +local Buffer = {} +Buffer.__index = Buffer + +--- @param opts table +-- dict_name name of the lua_shared_dict to buffer in (required) +-- prefix key namespace within that dict (required) +-- max_buffered records held between flushes, beyond which new ones are dropped +-- slot_ttl seconds a buffered record survives, so a stalled flush cannot +-- pin memory indefinitely +-- lock_ttl seconds the drain lock survives a worker that dies outright +function _M.new(opts) + assert(type(opts) == "table" and opts.dict_name and opts.prefix, + "decision_buffer.new requires dict_name and prefix") + + return setmetatable({ + dict_name = opts.dict_name, + prefix = opts.prefix, + max_buffered = opts.max_buffered or 500, + slot_ttl = opts.slot_ttl or 600, + lock_ttl = opts.lock_ttl or 30, + head_key = opts.prefix .. ":head", + tail_key = opts.prefix .. ":tail", + dropped_key = opts.prefix .. ":dropped", + lock_key = opts.prefix .. ":draining", + slot_prefix = opts.prefix .. ":rec:", + }, Buffer) +end + +-- Resolved per call rather than at construction: the dict does not exist when a +-- module is required at init, only once nginx has set up shared memory. +function Buffer:dict() + return ngx.shared[self.dict_name] +end + +--- Buffer one record. Called from the request path, so it must stay +--- allocation-light and must never touch Redis. +-- @return true, or false plus a reason +function Buffer:record(entry) + local dict = self:dict() + if not dict or type(entry) ~= "table" then + return false + end + + local head = dict:incr(self.head_key, 1, 0) + if not head then + return false + end + + local tail = dict:get(self.tail_key) or 0 + if head - tail > self.max_buffered then + -- Drop the new record rather than evicting an older one, and count the + -- loss so a consumer can say "showing a sample" instead of implying + -- completeness. + dict:incr(self.dropped_key, 1, 0) + return false, "buffer full" + end + + local encoded = cjson.encode(entry) + if not encoded then + return false + end + + dict:set(self.slot_prefix .. head, encoded, self.slot_ttl) + return true +end + +--- Write one slot range. Called under the drain lock, and separated out so +--- flush() can run it under pcall and still release that lock. +local function drain_range(self, dict, red, from, to, write_record) + local flushed = 0 + for slot = from, to do + local key = self.slot_prefix .. slot + local raw = dict:get(key) + if raw then + local decoded = cjson.decode(raw) + if type(decoded) == "table" then + write_record(red, decoded, raw) + flushed = flushed + 1 + end + dict:delete(key) + end + -- One slot at a time, not a jump at the end: this is what makes a + -- failed drain resumable rather than lossy. + dict:set(self.tail_key, slot) + end + return flushed +end + +--- Drain into Redis. Timer context only. +-- @param red an open Redis connection +-- @param write_record function(red, decoded, raw) called per record +-- @return flushed count, dropped-since-last-flush count +function Buffer:flush(red, write_record) + local dict = self:dict() + if not dict or not red or type(write_record) ~= "function" then + return 0, 0 + end + + local head = dict:get(self.head_key) or 0 + local tail = dict:get(self.tail_key) or 0 + if head <= tail then + return 0, 0 + end + + -- add() is atomic and fails when the key already exists, so exactly one + -- worker drains and the rest return immediately. + if not dict:add(self.lock_key, 1, self.lock_ttl) then + return 0, 0 + end + + local ok, flushed = pcall(drain_range, self, dict, red, tail + 1, head, write_record) + if not ok then + -- Release rather than leaving the buffer wedged until the lock TTL. The + -- tail already advanced per completed slot, so the next drain resumes + -- where this one stopped. + dict:delete(self.lock_key) + ngx.log(ngx.ERR, "decision_buffer(", self.prefix, + ") flush failed, resuming from last completed slot: ", tostring(flushed)) + return 0, 0 + end + + local dropped = dict:get(self.dropped_key) or 0 + if dropped > 0 then + dict:set(self.dropped_key, 0) + end + + dict:delete(self.lock_key) + return flushed, dropped +end + +--- Records buffered but not yet written. +function Buffer:depth() + local dict = self:dict() + if not dict then return 0 end + local head = dict:get(self.head_key) or 0 + local tail = dict:get(self.tail_key) or 0 + local depth = head - tail + return depth > 0 and depth or 0 +end + +--- Trim a value that originates from the request, so a long or hostile field +--- cannot bloat storage. Shared because every recorder needs it. +function _M.clip(value, limit) + if value == nil then return nil end + value = tostring(value) + if #value > limit then + return value:sub(1, limit) .. "..." + end + return value +end + +return _M diff --git a/openresty/lua/decision_recorder.lua b/openresty/lua/decision_recorder.lua new file mode 100644 index 0000000..d77a816 --- /dev/null +++ b/openresty/lua/decision_recorder.lua @@ -0,0 +1,216 @@ +--[[ + Decision recorder + ================= + Answers "why was this blocked?" without a log grep. + + The engine already computes a rich verdict -- a score, a flag per detection, + and now a per-node trace of which mechanism contributed what. All of it was + being reduced to one log line and discarded. Support questions about a + specific blocked request had no better answer than "look for it in the error + log", which does not survive contact with a customer who has a request id and + a complaint. + + Recorded in the log phase, deliberately + --------------------------------------- + process_request has several enforcement branches -- block by profile, block by + threshold, CAPTCHA challenge, tarpit, monitoring pass-through, plain allow -- + and hooking each one is how you end up with a recorder that covers most of + them. That exact mistake was made in shadow mode, where one of two would-block + branches was missed at first. + + So process_request stashes the verdict on ngx.ctx and a single log-phase call + records it with the response status attached. One record per request, with + the outcome that actually happened rather than the one predicted mid-pipeline. + + What is kept + ------------ + Not every request: a busy site would fill Redis with successful form posts + that nobody will ever look up. By default only decisions that did something -- + blocked, challenged, tarpitted, or would-have-blocked -- plus anything scoring + above a threshold, so a near-miss is still explicable. Both bounded and both + configurable, because "why did this get through?" is as common a question as + "why was this blocked?". +]] + +local buffer_lib = require "decision_buffer" + +local _M = {} + +local KEYS = { + decisions = "waf:decisions", -- capped list, newest first + stats = "waf:decisions:stats", -- HASH totals +} + +-- Bounds. Ceilings, not tuning knobs: each is what stops the decision log +-- becoming its own incident on a busy site. +local MAX_BUFFERED = 500 +local MAX_TRACE = 20 -- nodes itemised per record +local MAX_FLAGS = 30 +local MAX_FLAG_LENGTH = 120 +local MAX_PATH_LENGTH = 256 +local MAX_UA_LENGTH = 200 + +local DEFAULT_MAX_RECORDS = 2000 +local DEFAULT_TTL = 7 * 24 * 3600 +local DEFAULT_MIN_SCORE = 1 + +local clip = buffer_lib.clip + +local buffer = buffer_lib.new({ + dict_name = "decision_cache", + prefix = "decision", + max_buffered = MAX_BUFFERED, +}) + +--- Retention is configurable because the right answer differs by deployment: a +--- high-traffic site wants a short window, an audited one wants a long tail. +--- Read once per worker -- these do not change without a restart. +local _config +local function config() + if _config then return _config end + + local function num(name, default, min, max) + local v = tonumber(os.getenv(name)) + if not v then return default end + if v < min then return min end + if max and v > max then return max end + return v + end + + _config = { + -- Off is a legitimate choice: the decision log stores request paths and + -- client IPs, which some deployments would rather not retain at all. + enabled = os.getenv("WAF_DECISION_LOG_ENABLED") ~= "false", + max_records = num("WAF_DECISION_LOG_MAX", DEFAULT_MAX_RECORDS, 10, 50000), + ttl = num("WAF_DECISION_LOG_TTL", DEFAULT_TTL, 60), + -- Below this score an allowed request is not worth a record. 0 records + -- everything, which is supported but will fill the buffer on a busy site. + min_score = num("WAF_DECISION_LOG_MIN_SCORE", DEFAULT_MIN_SCORE, 0), + } + return _config +end + +--- Reset the memoised config. Tests only. +function _M._reset_config() + _config = nil +end + +local function clip_list(list, limit, max_len) + if type(list) ~= "table" then return nil end + local out = {} + for i = 1, math.min(#list, limit) do + out[i] = clip(list[i], max_len) + end + return out +end + +--- Trim a trace to what is useful in a detail view: the mechanisms that did +--- something. A profile with 30 nodes mostly reports zeros, and storing them +--- crowds out the entries that explain the verdict. +local function compact_trace(trace) + if type(trace) ~= "table" then return nil end + + local significant = {} + for _, entry in ipairs(trace) do + if type(entry) == "table" then + local contributed = (entry.score or 0) ~= 0 or entry.blocked + or (entry.flags and #entry.flags > 0) + or entry.suppressed + if contributed then + significant[#significant + 1] = { + node = entry.node, + defense = entry.defense, + score = entry.score or 0, + blocked = entry.blocked or nil, + flags = clip_list(entry.flags, 8, MAX_FLAG_LENGTH), + suppressed = clip_list(entry.suppressed, 8, MAX_FLAG_LENGTH), + } + if #significant >= MAX_TRACE then break end + end + end + end + return significant +end + +--- Should this decision be kept? +function _M.should_record(action, score) + local cfg = config() + if not cfg.enabled then return false end + if action and action ~= "allowed" then return true end + return (score or 0) >= cfg.min_score +end + +--- Record one enforcement decision. Log phase only -- must not touch Redis. +-- @param decision table request_id, vhost_id, endpoint_id, client_ip, host, +-- path, method, user_agent, action, status, mode, score, +-- flags, blocked_by, block_reason, trace +function _M.record(decision) + if type(decision) ~= "table" then + return false + end + if not _M.should_record(decision.action, decision.score) then + return false + end + + return buffer:record({ + ts = ngx.time(), + request_id = decision.request_id, + vhost_id = decision.vhost_id or "unknown", + endpoint_id = decision.endpoint_id or "global", + client_ip = decision.client_ip, + host = clip(decision.host, MAX_PATH_LENGTH), + path = clip(decision.path, MAX_PATH_LENGTH), + method = decision.method, + user_agent = clip(decision.user_agent, MAX_UA_LENGTH), + action = decision.action, + status = decision.status, + mode = decision.mode, + score = decision.score or 0, + block_reason = clip(decision.block_reason, MAX_FLAG_LENGTH), + blocked_by = clip_list(decision.blocked_by, 10, MAX_FLAG_LENGTH), + flags = clip_list(decision.flags, MAX_FLAGS, MAX_FLAG_LENGTH), + trace = compact_trace(decision.trace), + }) +end + +local function write_record(red, decoded, raw) + red:lpush(KEYS.decisions, raw) + red:hincrby(KEYS.stats, "total", 1) + red:hincrby(KEYS.stats, "action:" .. (decoded.action or "unknown"), 1) +end + +--- Drain into Redis. Timer context only. +function _M.flush(red) + if not red then + return 0 + end + + local cfg = config() + local flushed, dropped = buffer:flush(red, write_record) + + if flushed > 0 then + red:ltrim(KEYS.decisions, 0, cfg.max_records - 1) + red:expire(KEYS.decisions, cfg.ttl) + red:expire(KEYS.stats, cfg.ttl) + end + + if dropped > 0 then + red:hincrby(KEYS.stats, "dropped_total", dropped) + end + + return flushed +end + +function _M.get_keys() + return KEYS +end + +function _M.get_config() + return config() +end + +function _M.buffer_depth() + return buffer:depth() +end + +return _M diff --git a/openresty/lua/defense_profile_executor.lua b/openresty/lua/defense_profile_executor.lua index 8de65be..4e67156 100644 --- a/openresty/lua/defense_profile_executor.lua +++ b/openresty/lua/defense_profile_executor.lua @@ -583,9 +583,20 @@ function _M.execute(profile, request_context) details = {}, final_action = nil, action_config = nil, - would_block_reasons = {} -- Track what would have blocked in monitoring mode + would_block_reasons = {}, -- Track what would have blocked in monitoring mode + -- Per-node record of what each mechanism contributed. The aggregate score + -- alone cannot answer "why was this blocked?" -- 65 points tells an + -- operator nothing about which of eight mechanisms produced them. Built + -- at the same place the score and flags are accumulated, so the trace + -- always adds up to the aggregate rather than being a parallel guess. + trace = {} } + -- A pathological or looping graph must not turn the trace into the memory + -- problem. Nodes executed past this still count toward the score; they just + -- stop being individually itemised. + local MAX_TRACE_ENTRIES = 50 + -- Node results cache local node_results = {} @@ -633,6 +644,20 @@ function _M.execute(profile, request_context) table.insert(exec_context.flags, flag) end end + + if #exec_context.trace < MAX_TRACE_ENTRIES then + table.insert(exec_context.trace, { + node = node.id, + defense = node.defense, + score = result.score or 0, + flags = result.flags, + blocked = result.blocked or false, + -- Carried through so the explorer can show "this fired but + -- was suppressed", which is otherwise indistinguishable + -- from never having fired at all. + suppressed = result.details and result.details.suppressed or nil, + }) + end end if result.details then for k, v in pairs(result.details) do @@ -754,7 +779,8 @@ function _M.execute(profile, request_context) execution_time_ms = elapsed_ms, nodes_executed = iterations, would_block_reasons = exec_context.would_block_reasons, -- What would have blocked (useful in monitoring mode) - is_monitoring_mode = is_monitoring_mode + is_monitoring_mode = is_monitoring_mode, + trace = exec_context.trace } end diff --git a/openresty/lua/defense_profile_multi_executor.lua b/openresty/lua/defense_profile_multi_executor.lua index a23b66c..42e2562 100644 --- a/openresty/lua/defense_profile_multi_executor.lua +++ b/openresty/lua/defense_profile_multi_executor.lua @@ -353,7 +353,10 @@ function _M.aggregate(results, config, start_time) action = r.result.action, score = r.result.score, flags = r.result.flags, - execution_time_ms = r.result.execution_time_ms + execution_time_ms = r.result.execution_time_ms, + -- Per-node breakdown, so a decision can be explained down to the + -- mechanism rather than stopping at "profile X scored 65". + trace = r.result.trace } end diff --git a/openresty/lua/redis_sync.lua b/openresty/lua/redis_sync.lua index dd2befd..7f15775 100644 --- a/openresty/lua/redis_sync.lua +++ b/openresty/lua/redis_sync.lua @@ -1205,6 +1205,17 @@ local function do_sync() -- Drain the shadow-mode buffer here rather than on its own timer: this -- function already holds an open connection and runs on a predictable -- interval. + -- Same treatment for the enforcement decision log. + local ok_dec, decision_recorder = pcall(require, "decision_recorder") + if ok_dec and decision_recorder then + local ok_flush, flushed = pcall(decision_recorder.flush, red) + if not ok_flush then + ngx.log(ngx.ERR, "decision recorder flush failed: ", tostring(flushed)) + elseif flushed > 0 then + ngx.log(ngx.INFO, "decision recorder: flushed ", flushed, " decisions") + end + end + local ok_shadow, shadow_recorder = pcall(require, "shadow_recorder") if ok_shadow and shadow_recorder then local ok_flush, flushed = pcall(shadow_recorder.flush, red) diff --git a/openresty/lua/shadow_recorder.lua b/openresty/lua/shadow_recorder.lua index 02e6342..e130f51 100644 --- a/openresty/lua/shadow_recorder.lua +++ b/openresty/lua/shadow_recorder.lua @@ -16,16 +16,18 @@ starve redis_sync (R-03). A single periodic flush is used instead, the same shape field_learner already uses for its batching. + The buffering itself lives in decision_buffer, shared with the enforcement + recorder -- it carries two concurrency defects' worth of hard-won detail, and + a second copy would likely reproduce one of them. + Storage is bounded on purpose. A WAF in monitoring mode on a busy site sees everything, and an unbounded recorder becomes its own outage. ]] -local cjson = require "cjson.safe" +local buffer_lib = require "decision_buffer" local _M = {} -local shadow_cache = ngx.shared.shadow_cache - -- Redis keys local KEYS = { decisions = "waf:shadow:decisions", -- capped list of recent records @@ -44,49 +46,26 @@ local DECISION_TTL = 7 * 24 * 3600 local MAX_FLAG_LENGTH = 120 local MAX_PATH_LENGTH = 256 -local BUFFER_HEAD = "shadow:head" -- next write slot -local BUFFER_TAIL = "shadow:tail" -- last slot successfully flushed -local DROPPED = "shadow:dropped" -local DRAIN_LOCK = "shadow:draining" --- Long enough that a real drain never trips it, short enough that a worker --- killed mid-drain cannot wedge the buffer for more than one sync interval or two. -local DRAIN_LOCK_TTL = 30 - ---- Trim a value that originates from the request, so a long or hostile field ---- cannot bloat storage. -local function clip(value, limit) - if value == nil then return nil end - value = tostring(value) - if #value > limit then - return value:sub(1, limit) .. "..." - end - return value -end +local clip = buffer_lib.clip + +-- Keys stay "shadow:*" so an in-flight buffer survives the upgrade to the +-- shared implementation rather than being stranded and expiring unflushed. +local buffer = buffer_lib.new({ + dict_name = "shadow_cache", + prefix = "shadow", + max_buffered = MAX_BUFFERED, +}) --- Record one would-block decision. Called from the request path, so this must --- stay allocation-light and must never touch Redis. -- @param decision table vhost_id, endpoint_id, client_ip, host, path, method, -- score, blocked_by (array), flags (array) function _M.record(decision) - if not shadow_cache or type(decision) ~= "table" then + if type(decision) ~= "table" then return false end - local head = shadow_cache:incr(BUFFER_HEAD, 1, 0) - if not head then - return false - end - - local tail = shadow_cache:get(BUFFER_TAIL) or 0 - if head - tail > MAX_BUFFERED then - -- Buffer is full: drop this record rather than evicting an older one, and - -- count the loss so the UI can say "showing a sample" instead of implying - -- completeness. - shadow_cache:incr(DROPPED, 1, 0) - return false, "buffer full" - end - - local record = cjson.encode({ + return buffer:record({ ts = ngx.time(), vhost_id = decision.vhost_id or "unknown", endpoint_id = decision.endpoint_id or "global", @@ -98,100 +77,37 @@ function _M.record(decision) blocked_by = decision.blocked_by, flags = decision.flags, }) - if not record then - return false - end - - -- Slots expire well after a flush would have consumed them, so a stalled - -- flush cannot pin memory indefinitely. - shadow_cache:set("shadow:rec:" .. head, record, 600) - return true end ---- Write one slot range to Redis. Called under the drain lock. --- Separated out so flush() can run it under pcall and still release the lock: --- otherwise a failure part-way wedges the buffer until the lock TTL expires. -local function drain_range(red, from, to) - local flushed = 0 - for slot = from, to do - local key = "shadow:rec:" .. slot - local record = shadow_cache:get(key) - if record then - local decoded = cjson.decode(record) - if decoded then - red:lpush(KEYS.decisions, record) - - local scope = (decoded.vhost_id or "unknown") .. "|" .. (decoded.endpoint_id or "global") - red:hincrby(KEYS.endpoints, scope, 1) - red:hincrby(KEYS.stats, "would_block_total", 1) - - for _, rule in ipairs(decoded.blocked_by or {}) do - red:hincrby(KEYS.rules, clip(rule, MAX_FLAG_LENGTH), 1) - end - - -- blocked_by names the profile ("legacy"), which tells an - -- operator nothing about what to suppress. The flags carry the - -- actual reason -- kw:viagra, fp_flag:suspicious-bot -- so count - -- those too; they are what the diff view is for. - for _, flag in ipairs(decoded.flags or {}) do - red:hincrby(KEYS.flags, clip(flag, MAX_FLAG_LENGTH), 1) - end - flushed = flushed + 1 - end - shadow_cache:delete(key) - end - -- Advance one slot at a time rather than jumping the tail at the end: a - -- drain that dies part-way resumes from the last completed slot, with - -- neither a replayed record nor a lost one. - shadow_cache:set(BUFFER_TAIL, slot) +local function write_record(red, decoded, raw) + red:lpush(KEYS.decisions, raw) + + local scope = (decoded.vhost_id or "unknown") .. "|" .. (decoded.endpoint_id or "global") + red:hincrby(KEYS.endpoints, scope, 1) + red:hincrby(KEYS.stats, "would_block_total", 1) + + for _, rule in ipairs(decoded.blocked_by or {}) do + red:hincrby(KEYS.rules, clip(rule, MAX_FLAG_LENGTH), 1) + end + + -- blocked_by names the profile ("legacy"), which tells an operator nothing + -- about what to suppress. The flags carry the actual reason -- kw:viagra, + -- fp_flag:suspicious-bot -- so count those too; they are what the diff view + -- is for. + for _, flag in ipairs(decoded.flags or {}) do + red:hincrby(KEYS.flags, clip(flag, MAX_FLAG_LENGTH), 1) end - return flushed end --- Drain the buffer into Redis. Timer context only. -- @param red an open Redis connection -- @return number of records flushed function _M.flush(red) - if not shadow_cache or not red then + if not red then return 0 end - local head = shadow_cache:get(BUFFER_HEAD) or 0 - local tail = shadow_cache:get(BUFFER_TAIL) or 0 - if head <= tail then - return 0 - end - - -- redis_sync's timer runs on EVERY worker, so several of them reach this at - -- the same moment. Reading the tail, draining, then writing the tail back - -- lets each worker drain the same slots -- three workers turned one - -- would-block decision into three recorded copies, which overstated the - -- impact of promoting an endpoint by 3x. - -- - -- Claiming a range with incr(TAIL, pending) fixed the duplicates and - -- introduced something worse: a second worker claiming the same `pending` - -- pushed the tail past the head, into slots the writer had not filled yet. - -- Those claims drained nothing, and every record written into that gap was - -- then skipped for good, because the head <= tail guard above reports an - -- empty buffer. Silent loss in the thing whose whole job is to be a - -- trustworthy sample. - -- - -- add() is atomic and fails when the key already exists, so exactly one - -- worker drains and the rest return immediately. - if not shadow_cache:add(DRAIN_LOCK, 1, DRAIN_LOCK_TTL) then - return 0 - end - - -- The TTL on the lock only covers a worker that dies outright. A drain that - -- merely fails -- Redis going away mid-range -- releases here instead, so the - -- next sync interval retries rather than waiting the TTL out. - local ok, flushed = pcall(drain_range, red, tail + 1, head) - if not ok then - shadow_cache:delete(DRAIN_LOCK) - ngx.log(ngx.ERR, "shadow flush failed, resuming from last completed slot: ", - tostring(flushed)) - return 0 - end + local flushed, dropped = buffer:flush(red, write_record) if flushed > 0 then red:ltrim(KEYS.decisions, 0, MAX_DECISIONS - 1) @@ -202,13 +118,10 @@ function _M.flush(red) red:expire(KEYS.stats, DECISION_TTL) end - local dropped = shadow_cache:get(DROPPED) - if dropped and dropped > 0 then + if dropped > 0 then red:hincrby(KEYS.stats, "dropped_total", dropped) - shadow_cache:set(DROPPED, 0) end - shadow_cache:delete(DRAIN_LOCK) return flushed end @@ -218,10 +131,7 @@ end --- Exposed for tests and for the API's "is anything buffered" check. function _M.buffer_depth() - if not shadow_cache then return 0 end - local head = shadow_cache:get(BUFFER_HEAD) or 0 - local tail = shadow_cache:get(BUFFER_TAIL) or 0 - return math.max(0, head - tail) + return buffer:depth() end return _M diff --git a/openresty/lua/waf_handler.lua b/openresty/lua/waf_handler.lua index 1bdaa31..bc436c8 100644 --- a/openresty/lua/waf_handler.lua +++ b/openresty/lua/waf_handler.lua @@ -47,6 +47,8 @@ end -- F08: HMAC key for log integrity (optional) local LOG_HMAC_KEY = os.getenv("WAF_LOG_HMAC_KEY") +local collect_trace + -- Keep a would-block decision so "what happens if I switch this to blocking?" -- becomes a query rather than a log grep. -- @@ -72,6 +74,35 @@ local function get_shadow_recorder() return _shadow_recorder end +-- The executor returns a per-node trace per profile. Flatten them into one list +-- so a detail view can read the decision top to bottom without knowing how many +-- profiles ran. +collect_trace = function(profile_result) + if type(profile_result) ~= "table" then return nil end + + -- Single-profile results carry the trace directly; multi-profile results + -- nest one per profile. + if profile_result.trace then + return profile_result.trace + end + + local results = profile_result.profile_results + if type(results) ~= "table" then return nil end + + local flat = {} + for profile_id, r in pairs(results) do + if type(r) == "table" and type(r.trace) == "table" then + for _, entry in ipairs(r.trace) do + if type(entry) == "table" then + entry.profile = profile_id + flat[#flat + 1] = entry + end + end + end + end + return flat +end + local function record_shadow_decision(summary, client_ip, host, path, method, profile_result) local shadow_recorder = get_shadow_recorder() if not shadow_recorder then @@ -344,6 +375,41 @@ local function detect_field_anomalies(form_data, security_settings, ignore_field end -- Process incoming request +--- Called from log_by_lua. Records the decision stashed during the access +--- phase, with the status the client actually received attached. +function _M.log_decision() + local decision = ngx.ctx.waf_decision + if not decision then + return + end + + local ok, recorder = pcall(require, "decision_recorder") + if not ok or not recorder then + return + end + + local status = ngx.status + -- What happened, from the response rather than from what the pipeline + -- intended: monitoring mode returns 200 on a verdict of "block", and the + -- record has to say the request was allowed through. + local action + if status == 403 then + action = "blocked" + elseif status == 429 then + action = "tarpit" + elseif ngx.ctx.captcha_challenged then + action = "challenged" + elseif decision.profile_action == "block" then + action = "would_block" + else + action = "allowed" + end + + decision.action = action + decision.status = status + pcall(recorder.record, decision) +end + function _M.process_request() local method = ngx.req.get_method() local path = ngx.var.uri @@ -681,6 +747,29 @@ function _M.process_request() end end + -- Stash the verdict for the log phase. Recording happens there, not in + -- the branches below, because there are six of them -- block, captcha, + -- tarpit, flag, monitor, allow -- and covering five is the failure this + -- feature exists to avoid. The log phase sees exactly one outcome per + -- request, and the real one. + ngx.ctx.waf_decision = { + request_id = ngx.var.request_id, + vhost_id = summary.vhost_id, + endpoint_id = summary.endpoint_id, + client_ip = client_ip, + host = host, + path = path, + method = method, + user_agent = ngx.var.http_user_agent, + mode = summary.mode, + score = profile_result.score, + flags = profile_result.flags, + blocked_by = profile_result.blocked_by, + block_reason = profile_result.block_reason, + profile_action = profile_result.action, + trace = collect_trace(profile_result), + } + -- Handle profile result actions if profile_result.action == "block" then local should_block = vhost_resolver.should_block(context) diff --git a/openresty/spec/decision_recorder_spec.lua b/openresty/spec/decision_recorder_spec.lua new file mode 100644 index 0000000..a67730f --- /dev/null +++ b/openresty/spec/decision_recorder_spec.lua @@ -0,0 +1,153 @@ +--[[ + The decision log exists to answer "why was this blocked?", so the properties + that matter are the ones that keep it answerable and bounded: + + * It must not record everything. A busy site posting valid forms would + otherwise fill the buffer with records nobody will look up, and evict the + ones somebody will. + + * The trace must stay small without dropping the entries that explain the + verdict. A profile with thirty nodes mostly reports zeros; those are + noise, and keeping them crowds out the mechanism that actually fired. +]] +local helper = require "spec_helper" + +describe("decision_recorder", function() + local recorder + + local function fake_redis() + local calls = { lpush = {}, hincrby = {}, ltrim = 0, expire = 0 } + return { + calls = calls, + lpush = function(_, _, v) table.insert(calls.lpush, v); return 1 end, + hincrby = function(_, k, f, n) + calls.hincrby[k .. "/" .. f] = (calls.hincrby[k .. "/" .. f] or 0) + n + return 1 + end, + ltrim = function() calls.ltrim = calls.ltrim + 1; return true end, + expire = function() calls.expire = calls.expire + 1; return true end, + } + end + + local function a_decision(over) + local d = { + request_id = "req-1", vhost_id = "site", endpoint_id = "contact", + client_ip = "203.0.113.10", host = "example.com", path = "/submit", + method = "POST", action = "blocked", status = 403, score = 40, + flags = { "kw:viagra" }, + } + for k, v in pairs(over or {}) do d[k] = v end + return d + end + + before_each(function() + helper.install_ngx() + helper.stub_external_modules() + package.loaded["decision_recorder"] = nil + package.loaded["decision_buffer"] = nil + recorder = require "decision_recorder" + recorder._reset_config() + end) + + describe("what is worth keeping", function() + it("records anything that was acted on", function() + assert.is_true(recorder.should_record("blocked", 0)) + assert.is_true(recorder.should_record("challenged", 0)) + assert.is_true(recorder.should_record("tarpit", 0)) + assert.is_true(recorder.should_record("would_block", 0)) + end) + + it("skips a clean allowed request", function() + -- The common case on a healthy site. Recording it would evict the + -- decisions somebody actually needs to look up. + assert.is_false(recorder.should_record("allowed", 0)) + end) + + it("keeps an allowed request that scored, so a near-miss is explicable", function() + assert.is_true(recorder.should_record("allowed", 5)) + end) + end) + + describe("recording", function() + it("buffers a decision without touching Redis", function() + assert.is_true(recorder.record(a_decision())) + assert.equals(1, recorder.buffer_depth()) + end) + + it("ignores anything that is not a decision table", function() + assert.is_false(recorder.record(nil)) + assert.is_false(recorder.record("not a table")) + assert.equals(0, recorder.buffer_depth()) + end) + + it("flushes to Redis and counts by action", function() + recorder.record(a_decision()) + recorder.record(a_decision({ action = "allowed", score = 10 })) + local red = fake_redis() + assert.equals(2, recorder.flush(red)) + assert.equals(2, #red.calls.lpush) + assert.equals(1, red.calls.hincrby["waf:decisions:stats/action:blocked"]) + assert.equals(1, red.calls.hincrby["waf:decisions:stats/action:allowed"]) + assert.equals(2, red.calls.hincrby["waf:decisions:stats/total"]) + end) + + it("clips a hostile path so one request cannot bloat the log", function() + recorder.record(a_decision({ path = string.rep("A", 5000) })) + local red = fake_redis() + recorder.flush(red) + assert.is_true(#red.calls.lpush[1] < 2000) + end) + end) + + describe("trace compaction", function() + local function traced(trace) + recorder.record(a_decision({ trace = trace })) + local red = fake_redis() + recorder.flush(red) + local cjson = require "cjson.safe" + return cjson.decode(red.calls.lpush[1]).trace + end + + it("drops nodes that contributed nothing", function() + local kept = traced({ + { node = "n1", defense = "honeypot", score = 0 }, + { node = "n2", defense = "keyword_filter", score = 30, flags = { "kw:viagra" } }, + { node = "n3", defense = "geoip", score = 0 }, + }) + assert.equals(1, #kept) + assert.equals("keyword_filter", kept[1].defense) + end) + + it("keeps a node that blocked without scoring", function() + -- result_blocked carries score 0, so a score-only filter would throw + -- away the very node that produced the verdict. + local kept = traced({ { node = "n1", defense = "keyword_filter", score = 0, blocked = true } }) + assert.equals(1, #kept) + assert.is_true(kept[1].blocked) + end) + + it("keeps a node whose detections were suppressed", function() + -- "Fired but suppressed" and "never fired" look identical without + -- this, and they are the two different answers to "why did this get + -- through?". + local kept = traced({ + { node = "n1", defense = "keyword_filter", score = 0, suppressed = { "kw:viagra" } }, + }) + assert.equals(1, #kept) + assert.same({ "kw:viagra" }, kept[1].suppressed) + end) + + it("caps a runaway trace", function() + local big = {} + for i = 1, 100 do + big[i] = { node = "n" .. i, defense = "d", score = 1, flags = { "f" } } + end + assert.is_true(#traced(big) <= 20) + end) + + it("survives a malformed trace rather than erroring", function() + local kept = traced({ 42, "nonsense", { node = "n", defense = "d", score = 5 } }) + assert.equals(1, #kept) + end) + end) +end) From 3ae81893d65852f6645562c48587818a725a7491 Mon Sep 17 00:00:00 2001 From: Martin Dobrev Date: Fri, 7 Aug 2026 17:05:45 +0100 Subject: [PATCH 2/4] feat: Add the request explorer (#C2) Search the decision log, and explain any one decision down to the mechanism. The trace had to be made honest first. My previous commit claimed it "always adds up to the aggregate"; it did not. Three scoring paths bypassed it -- the defense-line merge in both its blocking and non-blocking branches, and vhost keywords added after the executor returns -- so a wp-login block reported score 113 against a breakdown summing to 30. Each was silent, because a plausible-looking breakdown that omits a contributor is indistinguishable from a complete one. All three now emit trace entries, and five sampled decisions reconcile exactly. Rather than leave that as an invariant to be trusted, the API reports it: unattributed_score is score minus the trace sum, and the detail view says the explanation is partial when it is non-zero. The next scoring path added outside the trace announces itself instead of quietly making the explanation wrong. The API is a filtered scan of the capped list -- vhost, endpoint, client IP, outcome, detection flag, path substring, min score, time range -- plus GET /decisions/{request_id} for one decision. Filtering happens in Lua rather than via Redis indexes because the list is bounded and a second write path to keep consistent would be the more expensive thing to get wrong. The UI renders the breakdown as a running tally rather than a list of badges, because the question is "where did 113 come from" and a column that adds up answers it. Suppressed detections appear struck through, so "fired but suppressed" stays distinguishable from "never fired". A monitoring-mode record explains why it was allowed through despite the verdict. Also fixed while verifying: the operator role had no decisions permission, so every route 403'd for it. Admin and viewer had been granted it and operator missed, which the live per-role check caught. The contract checker now skips path-templated endpoints and prints what it skipped. A request id is ephemeral so there is no fixed example returning 200, and a check that silently covers less than it appears to is worse than one that admits the gap. Gates: 88 unit specs, helm drift clean, config contracts hold, contract check 13 validated / 1 skipped, integration 42 passed / 2 known gaps / 0 failed, typecheck 0 errors, lint 0 errors / 59 warnings. --- admin-ui/src/App.tsx | 2 + admin-ui/src/api/client.ts | 83 ++++ admin-ui/src/api/generated.ts | 172 +++++++ admin-ui/src/components/layout/Sidebar.tsx | 2 + .../src/pages/analytics/RequestExplorer.tsx | 456 ++++++++++++++++++ docs/API_HANDLERS.md | 25 + docs/openapi.yaml | 139 ++++++ openresty/lua/admin_api.lua | 12 + openresty/lua/api_handlers/decisions.lua | 214 ++++++++ .../lua/defense_profile_multi_executor.lua | 50 ++ openresty/lua/rbac.lua | 15 + openresty/lua/waf_handler.lua | 34 +- scripts/check-api-contract.py | 16 + 13 files changed, 1219 insertions(+), 1 deletion(-) create mode 100644 admin-ui/src/pages/analytics/RequestExplorer.tsx create mode 100644 openresty/lua/api_handlers/decisions.lua diff --git a/admin-ui/src/App.tsx b/admin-ui/src/App.tsx index 47afcc3..68809d0 100644 --- a/admin-ui/src/App.tsx +++ b/admin-ui/src/App.tsx @@ -29,6 +29,7 @@ import BehavioralAnalytics from '@/pages/analytics/BehavioralAnalytics' import ClusterStatus from '@/pages/cluster/ClusterStatus' import ShadowMode from '@/pages/shadow/ShadowMode' import Suppressions from '@/pages/security/Suppressions' +import RequestExplorer from '@/pages/analytics/RequestExplorer' import { About } from '@/pages/About' import { Users } from '@/pages/admin/Users' import { AuthProviders } from '@/pages/admin/AuthProviders' @@ -91,6 +92,7 @@ export default function App() { } /> } /> } /> + } /> } /> } /> } /> diff --git a/admin-ui/src/api/client.ts b/admin-ui/src/api/client.ts index 1d127bd..c41ae7d 100644 --- a/admin-ui/src/api/client.ts +++ b/admin-ui/src/api/client.ts @@ -1548,3 +1548,86 @@ export const suppressionsApi = { clear: () => request<{ cleared: boolean }>('/suppressions', { method: 'DELETE' }), } + +// --------------------------------------------------------------------------- +// Request explorer +// +// "Why was this blocked?" as a query. trace is the per-mechanism breakdown; +// unattributed_score reports how much of the score it fails to account for. +// --------------------------------------------------------------------------- + +export type DecisionAction = 'blocked' | 'allowed' | 'challenged' | 'tarpit' | 'would_block' + +export interface DecisionTraceEntry { + node?: string + defense?: string + profile?: string + score?: number + blocked?: boolean + flags?: string[] + suppressed?: string[] +} + +export interface Decision { + ts: number + request_id?: string + vhost_id: string + endpoint_id: string + client_ip?: string + host?: string + path?: string + method?: string + user_agent?: string + action: DecisionAction + status?: number + mode?: string + score: number + block_reason?: string + blocked_by?: string[] + flags?: string[] + trace?: DecisionTraceEntry[] + traced_score?: number + unattributed_score?: number +} + +export interface DecisionRetention { + enabled?: boolean + max_records?: number + ttl_seconds?: number + min_score?: number +} + +export interface DecisionSearch { + vhost_id?: string + endpoint_id?: string + client_ip?: string + action?: string + flag?: string + path?: string + min_score?: number + limit?: number +} + +export const decisionsApi = { + search: (params: DecisionSearch = {}) => { + const q = new URLSearchParams() + Object.entries(params).forEach(([k, v]) => { + if (v !== undefined && v !== null && v !== '') q.set(k, String(v)) + }) + const qs = q.toString() + return request<{ + decisions: Decision[] + count: number + limit?: number + scanned?: number + dropped_total?: number + recorded_total?: number + retention?: DecisionRetention + }>(`/decisions${qs ? `?${qs}` : ''}`) + }, + + get: (requestId: string) => + request<{ decision: Decision }>(`/decisions/${encodeURIComponent(requestId)}`), + + clear: () => request<{ cleared: boolean }>('/decisions', { method: 'DELETE' }), +} diff --git a/admin-ui/src/api/generated.ts b/admin-ui/src/api/generated.ts index 2782024..7bb9a8f 100644 --- a/admin-ui/src/api/generated.ts +++ b/admin-ui/src/api/generated.ts @@ -195,6 +195,131 @@ export interface paths { patch?: never; trace?: never; }; + "/decisions": { + parameters: { + query?: never; + header?: never; + path?: never; + cookie?: never; + }; + /** Search the enforcement decision log */ + get: { + parameters: { + query?: { + vhost_id?: string; + endpoint_id?: string; + client_ip?: string; + action?: "blocked" | "allowed" | "challenged" | "tarpit" | "would_block"; + flag?: string; + path?: string; + min_score?: number; + since?: number; + until?: number; + limit?: number; + }; + header?: never; + path?: never; + cookie?: never; + }; + requestBody?: never; + responses: { + /** @description Matching decisions, newest first */ + 200: { + headers: { + [name: string]: unknown; + }; + content: { + "application/json": { + decisions: components["schemas"]["Decision"][]; + count: number; + limit?: number; + scanned?: number; + /** @description Non-zero means the buffer overflowed and the log has holes. */ + dropped_total?: number; + recorded_total?: number; + retention?: components["schemas"]["DecisionRetention"]; + }; + }; + }; + }; + }; + put?: never; + post?: never; + /** Discard the decision log */ + delete: { + parameters: { + query?: never; + header?: never; + path?: never; + cookie?: never; + }; + requestBody?: never; + responses: { + /** @description Cleared */ + 200: { + headers: { + [name: string]: unknown; + }; + content: { + "application/json": { + cleared: boolean; + }; + }; + }; + }; + }; + options?: never; + head?: never; + patch?: never; + trace?: never; + }; + "/decisions/{request_id}": { + parameters: { + query?: never; + header?: never; + path?: never; + cookie?: never; + }; + /** Explain one decision */ + get: { + parameters: { + query?: never; + header?: never; + path: { + request_id: string; + }; + cookie?: never; + }; + requestBody?: never; + responses: { + /** @description The decision and its per-mechanism breakdown */ + 200: { + headers: { + [name: string]: unknown; + }; + content: { + "application/json": { + decision: components["schemas"]["Decision"]; + }; + }; + }; + /** @description Not retained. The log is capped and time-limited, so this means the request aged out rather than that it never happened. */ + 404: { + headers: { + [name: string]: unknown; + }; + content?: never; + }; + }; + }; + put?: never; + post?: never; + delete?: never; + options?: never; + head?: never; + patch?: never; + trace?: never; + }; "/suppressions": { parameters: { query?: never; @@ -651,6 +776,53 @@ export interface components { high_event_rate?: number; }; }; + DecisionTraceEntry: { + node?: string; + /** @description The mechanism */ + defense?: string; + profile?: string; + /** @description What this mechanism contributed */ + score?: number; + blocked?: boolean; + flags?: string[]; + /** @description Detections this mechanism raised that a suppression removed. Present so "fired but suppressed" is distinguishable from "never fired". */ + suppressed?: string[]; + }; + DecisionRetention: { + enabled?: boolean; + max_records?: number; + ttl_seconds?: number; + /** @description Allowed requests below this score are not recorded. */ + min_score?: number; + }; + Decision: { + ts: number; + /** @description Matches the X-WAF-Request-Id response header */ + request_id?: string; + vhost_id: string; + endpoint_id: string; + client_ip?: string; + host?: string; + path?: string; + method?: string; + user_agent?: string; + /** + * @description What happened, taken from the response rather than from what the pipeline intended: monitoring mode records would_block with status 200. + * @enum {string} + */ + action: "blocked" | "allowed" | "challenged" | "tarpit" | "would_block"; + status?: number; + mode?: string; + score: number; + block_reason?: string; + blocked_by?: string[]; + flags?: string[]; + trace?: components["schemas"]["DecisionTraceEntry"][]; + /** @description Sum of the trace entries. */ + traced_score?: number; + /** @description score minus traced_score. Should be 0. Non-zero means some scoring path is not represented in the trace, so the breakdown is incomplete -- reported rather than assumed, because that has happened. */ + unattributed_score?: number; + }; Suppression: { /** @description Digest of scope and flag, so adding the same one twice is idempotent. */ id: string; diff --git a/admin-ui/src/components/layout/Sidebar.tsx b/admin-ui/src/components/layout/Sidebar.tsx index 7f73f10..2414cc8 100644 --- a/admin-ui/src/components/layout/Sidebar.tsx +++ b/admin-ui/src/components/layout/Sidebar.tsx @@ -25,6 +25,7 @@ import { Fingerprint, EyeOff, BellOff, + Search, MessageSquare, Workflow, Target, @@ -65,6 +66,7 @@ const navigation = [ { name: 'Analytics', children: [ + { name: 'Request Explorer', href: '/analytics/requests', icon: Search }, { name: 'Behavioral', href: '/analytics/behavioral', icon: Activity }, ], }, diff --git a/admin-ui/src/pages/analytics/RequestExplorer.tsx b/admin-ui/src/pages/analytics/RequestExplorer.tsx new file mode 100644 index 0000000..2609f8b --- /dev/null +++ b/admin-ui/src/pages/analytics/RequestExplorer.tsx @@ -0,0 +1,456 @@ +import { useState } from 'react' +import { useQuery, useMutation, useQueryClient } from '@tanstack/react-query' +import { decisionsApi } from '@/api/client' +import type { Decision, DecisionTraceEntry } from '@/api/client' +import { Card, CardContent, CardDescription, CardHeader, CardTitle } from '@/components/ui/card' +import { Badge } from '@/components/ui/badge' +import { Button } from '@/components/ui/button' +import { Input } from '@/components/ui/input' +import { Label } from '@/components/ui/label' +import { Alert, AlertTitle, AlertDescription } from '@/components/ui/alert' +import { + Select, + SelectContent, + SelectItem, + SelectTrigger, + SelectValue, +} from '@/components/ui/select' +import { + Dialog, + DialogContent, + DialogDescription, + DialogHeader, + DialogTitle, +} from '@/components/ui/dialog' +import { + Table, + TableBody, + TableCell, + TableHead, + TableHeader, + TableRow, +} from '@/components/ui/table' +import { useToast } from '@/components/ui/use-toast' +import { Search, AlertTriangle, RefreshCw, Trash2, Info, BellOff } from 'lucide-react' + +const ACTIONS = ['blocked', 'would_block', 'challenged', 'tarpit', 'allowed'] as const + +function actionVariant(action: string): 'destructive' | 'warning' | 'secondary' | 'success' { + if (action === 'blocked') return 'destructive' + if (action === 'would_block' || action === 'tarpit' || action === 'challenged') return 'warning' + if (action === 'allowed') return 'success' + return 'secondary' +} + +function formatWhen(ts: number): string { + if (!ts) return '-' + return new Date(ts * 1000).toLocaleString() +} + +/** + * The breakdown. Rendered as a running tally rather than a flat list because the + * question is "where did 113 come from", and a column of numbers that adds up is + * the answer to that in a way a set of badges is not. + */ +function TraceTable({ decision }: { decision: Decision }) { + const trace = decision.trace ?? [] + if (!trace.length) { + return ( +

+ No mechanism breakdown recorded for this decision. +

+ ) + } + + let running = 0 + return ( +
+ + + + Mechanism + Contributed + Running + Detections + + + + {trace.map((entry: DecisionTraceEntry, i) => { + running += entry.score ?? 0 + return ( + + + {entry.defense || entry.node} + {entry.blocked && ( + + blocked + + )} + {entry.profile && ( +
profile: {entry.profile}
+ )} + + + {entry.score ? `+${entry.score}` : '—'} + + + {running} + + +
+ {(entry.flags ?? []).map((f) => ( + + {f} + + ))} + {(entry.suppressed ?? []).map((f) => ( + + {f} + + ))} +
+ + + ) + })} + +
+
+ ) +} + +export default function RequestExplorer() { + const { toast } = useToast() + const queryClient = useQueryClient() + + const [action, setAction] = useState('any') + const [clientIp, setClientIp] = useState('') + const [path, setPath] = useState('') + const [flag, setFlag] = useState('') + const [minScore, setMinScore] = useState('') + const [applied, setApplied] = useState>({}) + const [selected, setSelected] = useState(null) + + const { data, isLoading, refetch, isFetching } = useQuery({ + queryKey: ['decisions', applied], + queryFn: () => decisionsApi.search({ ...applied, limit: 100 }), + }) + + const clearMutation = useMutation({ + mutationFn: decisionsApi.clear, + onSuccess: () => { + toast({ title: 'Decision log discarded' }) + queryClient.invalidateQueries({ queryKey: ['decisions'] }) + }, + onError: (err: Error) => + toast({ title: 'Could not clear', description: err.message, variant: 'destructive' }), + }) + + const applyFilters = () => { + const next: Record = {} + if (action !== 'any') next.action = action + if (clientIp.trim()) next.client_ip = clientIp.trim() + if (path.trim()) next.path = path.trim() + if (flag.trim()) next.flag = flag.trim() + if (minScore.trim() && !Number.isNaN(Number(minScore))) next.min_score = Number(minScore) + setApplied(next) + } + + const retention = data?.retention + const incomplete = (data?.dropped_total ?? 0) > 0 + + return ( +
+
+
+

+ + Request Explorer +

+

+ Why a request was blocked — or why it was not — down to the mechanism. +

+
+
+ + +
+
+ + {retention?.enabled === false && ( + + + The decision log is turned off + + Nothing new is being recorded. Set + WAF_DECISION_LOG_ENABLED=true + {' '} + to start. + + + )} + + {incomplete && ( + + + This log has holes + + {data?.dropped_total} decision(s) were dropped because the recorder's buffer filled + up. A request you are looking for may be missing rather than never having happened. + + + )} + + + + Filters + + {retention + ? `Keeping up to ${retention.max_records} decisions for ${Math.round( + (retention.ttl_seconds ?? 0) / 86400 + )} days. Allowed requests scoring under ${retention.min_score} are not recorded.` + : 'Search the recorded decisions.'} + + + +
+
+ + +
+
+ + setClientIp(e.target.value)} /> +
+
+ + setPath(e.target.value)} /> +
+
+ + setFlag(e.target.value)} + placeholder="kw:viagra" + /> +
+
+ + setMinScore(e.target.value)} + /> +
+
+
+ +
+ + + + + + + Decisions{' '} + + ({data?.count ?? 0} + {data?.scanned ? ` of ${data.scanned} scanned` : ''}) + + + Newest first. Select a row to see why. + + + {isLoading ? ( +

Loading...

+ ) : data?.decisions?.length ? ( +
+ + + + When + Outcome + Request + Client + Score + Detections + + + + {data.decisions.map((d, i) => ( + setSelected(d)} + > + + {formatWhen(d.ts)} + + + {d.action} + {d.status ? ( + {d.status} + ) : null} + + + + {d.method} {d.path} + +
+ {d.vhost_id} / {d.endpoint_id} +
+ + + {d.client_ip || '-'} + + {d.score} + +
+ {(d.flags ?? []).slice(0, 3).map((f) => ( + + {f} + + ))} + {(d.flags?.length ?? 0) > 3 && ( + + +{(d.flags?.length ?? 0) - 3} + + )} +
+ + + ))} + +
+
+ ) : ( +

+ No decisions match. Clean allowed requests are not recorded, so an empty result + can simply mean nothing was flagged. +

+ )} + + + + !open && setSelected(null)}> + + + + {selected?.action} + + {selected?.method} {selected?.path} + + + + {selected?.request_id ? ( + <> + Request {selected.request_id} —{' '} + + ) : null} + {selected ? formatWhen(selected.ts) : ''} + + + + {selected && ( +
+
+
+
Score
+
{selected.score}
+
+
+
Status
+
+ {selected.status ?? '-'} +
+
+
+
Mode
+
{selected.mode ?? '-'}
+
+
+
Client
+
{selected.client_ip ?? '-'}
+
+
+ + {selected.action === 'would_block' && ( + + + + This vhost is in monitoring mode, so the request was allowed through despite + the verdict. Shadow Mode shows what promoting it would change. + + + )} + + {!!selected.unattributed_score && ( + + + Breakdown is incomplete + + {selected.unattributed_score} of {selected.score} points are not accounted + for by the mechanisms below, so some scoring path is not reporting itself. + Treat this explanation as partial. + + + )} + +
+

Why

+ +
+ + {!!selected.trace?.some((t) => t.suppressed?.length) && ( +

+ + Struck-through detections were raised and then removed by a suppression. +

+ )} + + {selected.user_agent && ( +
+
User agent
+ {selected.user_agent} +
+ )} +
+ )} + + +
+ ) +} diff --git a/docs/API_HANDLERS.md b/docs/API_HANDLERS.md index 13c3608..fd1496b 100644 --- a/docs/API_HANDLERS.md +++ b/docs/API_HANDLERS.md @@ -335,6 +335,30 @@ local ok, err = utils.validate_required(data, {"field1", "field2"}) --- +### Request Explorer (`api_handlers/decisions.lua`) + +Answers "why was this blocked?" as a query rather than a log grep. + +| Method | Endpoint | Description | +|--------|----------|-------------| +| GET | /decisions | Search: vhost, endpoint, client_ip, action, flag, path, min_score, since/until | +| GET | /decisions/{request_id} | One decision with its per-mechanism breakdown | +| DELETE | /decisions | Discard the log | + +Records are written by `decision_recorder` from `log_by_lua`, not from the +enforcement branches — there are six of those and covering five is the failure +mode. The log phase sees one outcome per request, and the real one, which is +why a monitoring-mode record reads `action: would_block` with `status: 200`. + +`trace` is the per-mechanism breakdown, built in `defense_profile_executor` +where score and flags are already accumulated. `unattributed_score` reports +`score - sum(trace)` and should be 0; anything else means a scoring path is +not represented in the trace. It is reported rather than assumed because that +invariant broke three times during development, each time silently. + +Retention: `WAF_DECISION_LOG_ENABLED`, `_MAX`, `_TTL`, `_MIN_SCORE`. Disabled +is legitimate — the log stores request paths and client IPs. + ### Rule Suppressions (`api_handlers/suppressions.lua`) The counterpart to shadow mode. Shadow mode names the rule that would have @@ -399,6 +423,7 @@ Each endpoint requires specific permissions. See [RBAC Guide](RBAC.md) for full | slack | read, update, test | | shadow | read, promote, delete | | suppressions | create, read, delete | +| decisions | read, delete | --- diff --git a/docs/openapi.yaml b/docs/openapi.yaml index ddb3e31..10275be 100644 --- a/docs/openapi.yaml +++ b/docs/openapi.yaml @@ -113,6 +113,70 @@ components: high_event_count: { type: integer } high_event_rate: { type: integer } + DecisionTraceEntry: + type: object + properties: + node: { type: string } + defense: { type: string, description: The mechanism, e.g. keyword_filter } + profile: { type: string } + score: { type: integer, description: What this mechanism contributed } + blocked: { type: boolean } + flags: { type: array, items: { type: string } } + suppressed: + type: array + items: { type: string } + description: > + Detections this mechanism raised that a suppression removed. Present + so "fired but suppressed" is distinguishable from "never fired". + + DecisionRetention: + type: object + properties: + enabled: { type: boolean } + max_records: { type: integer } + ttl_seconds: { type: integer } + min_score: + type: integer + description: Allowed requests below this score are not recorded. + + Decision: + type: object + required: [ts, vhost_id, endpoint_id, action, score] + properties: + ts: { type: integer } + request_id: { type: string, description: Matches the X-WAF-Request-Id response header } + vhost_id: { type: string } + endpoint_id: { type: string } + client_ip: { type: string } + host: { type: string } + path: { type: string } + method: { type: string } + user_agent: { type: string } + action: + type: string + enum: [blocked, allowed, challenged, tarpit, would_block] + description: > + What happened, taken from the response rather than from what the + pipeline intended: monitoring mode records would_block with status 200. + status: { type: integer } + mode: { type: string } + score: { type: integer } + block_reason: { type: string } + blocked_by: { type: array, items: { type: string } } + flags: { type: array, items: { type: string } } + trace: + type: array + items: { $ref: "#/components/schemas/DecisionTraceEntry" } + traced_score: + type: integer + description: Sum of the trace entries. + unattributed_score: + type: integer + description: > + score minus traced_score. Should be 0. Non-zero means some scoring + path is not represented in the trace, so the breakdown is incomplete + -- reported rather than assumed, because that has happened. + Suppression: type: object required: [id, scope_type, flag] @@ -291,6 +355,81 @@ paths: emitted_events: { type: array, items: { type: string } } unavailable_events: { type: array, items: { type: string } } + /decisions: + get: + summary: Search the enforcement decision log + parameters: + - { name: vhost_id, in: query, schema: { type: string } } + - { name: endpoint_id, in: query, schema: { type: string } } + - { name: client_ip, in: query, schema: { type: string } } + - name: action + in: query + schema: { type: string, enum: [blocked, allowed, challenged, tarpit, would_block] } + - { name: flag, in: query, schema: { type: string } } + - { name: path, in: query, schema: { type: string, description: Substring match } } + - { name: min_score, in: query, schema: { type: integer } } + - { name: since, in: query, schema: { type: integer, description: Unix time } } + - { name: until, in: query, schema: { type: integer, description: Unix time } } + - { name: limit, in: query, schema: { type: integer, default: 50, maximum: 500 } } + responses: + "200": + description: Matching decisions, newest first + content: + application/json: + schema: + type: object + required: [decisions, count] + properties: + decisions: + type: array + items: { $ref: "#/components/schemas/Decision" } + count: { type: integer } + limit: { type: integer } + scanned: { type: integer } + dropped_total: + type: integer + description: Non-zero means the buffer overflowed and the log has holes. + recorded_total: { type: integer } + retention: { $ref: "#/components/schemas/DecisionRetention" } + delete: + summary: Discard the decision log + responses: + "200": + description: Cleared + content: + application/json: + schema: + type: object + required: [cleared] + properties: + cleared: { type: boolean } + + /decisions/{request_id}: + get: + summary: Explain one decision + x-contract-skip: > + request_id is ephemeral, so there is no fixed example that returns 200. + Exercised by the integration path instead. + parameters: + - name: request_id + in: path + required: true + schema: { type: string } + responses: + "200": + description: The decision and its per-mechanism breakdown + content: + application/json: + schema: + type: object + required: [decision] + properties: + decision: { $ref: "#/components/schemas/Decision" } + "404": + description: > + Not retained. The log is capped and time-limited, so this means the + request aged out rather than that it never happened. + /suppressions: get: summary: Detections that no longer count, and where diff --git a/openresty/lua/admin_api.lua b/openresty/lua/admin_api.lua index 15fb377..bfe66bf 100644 --- a/openresty/lua/admin_api.lua +++ b/openresty/lua/admin_api.lua @@ -21,6 +21,7 @@ local webhooks_handler = require "api_handlers.webhooks" local slack_handler = require "api_handlers.slack" local shadow_handler = require "api_handlers.shadow" local suppressions_handler = require "api_handlers.suppressions" +local decisions_handler = require "api_handlers.decisions" local geoip_handler = require "api_handlers.geoip" local reputation_handler = require "api_handlers.reputation" local bulk_handler = require "api_handlers.bulk" @@ -72,6 +73,7 @@ register_handlers(webhooks_handler) register_handlers(slack_handler) register_handlers(shadow_handler) register_handlers(suppressions_handler) +register_handlers(decisions_handler) register_handlers(geoip_handler) register_handlers(reputation_handler) register_handlers(bulk_handler) @@ -203,6 +205,16 @@ function _M.handle_request() end end + -- Check for parameterized decision routes: GET /decisions/{request_id}. + -- Hex-only, so it cannot swallow a future /decisions/ sub-route. + local decision_request_id = path:match("^/decisions/([a-fA-F0-9]+)$") + if decision_request_id then + local handler = decisions_handler.resource_handlers[method] + if handler then + return handler(decision_request_id) + end + end + -- Check for parameterized suppression routes: DELETE /suppressions/{id} local suppression_id = path:match("^/suppressions/([a-fA-F0-9]+)$") if suppression_id then diff --git a/openresty/lua/api_handlers/decisions.lua b/openresty/lua/api_handlers/decisions.lua new file mode 100644 index 0000000..6dad0ba --- /dev/null +++ b/openresty/lua/api_handlers/decisions.lua @@ -0,0 +1,214 @@ +-- api_handlers/decisions.lua +-- The request explorer: search enforcement decisions, and explain one. +-- +-- Reads the capped list decision_recorder writes. Filtering happens here rather +-- than in Redis because the list is bounded (2000 by default) and a LIST has no +-- secondary indexes -- adding them would mean a second write path to keep +-- consistent, for a dataset small enough to scan. + +local _M = {} + +local utils = require "api_handlers.utils" +local cjson = require "cjson.safe" +local decision_recorder = require "decision_recorder" + +local KEYS = decision_recorder.get_keys() + +local DEFAULT_LIMIT = 50 +local MAX_LIMIT = 500 +-- Scanned per search. The list is capped at the configured retention, so this +-- only bounds the work when retention is raised a long way. +local MAX_SCAN = 5000 + +--- How much of the score the trace actually accounts for. +-- +-- This is reported rather than assumed. The invariant "the trace sums to the +-- score" was broken in three separate places while building this -- defense +-- lines in two merge paths, and vhost keywords added after the executor +-- returned -- each time silently, because a plausible-looking breakdown that +-- happens to omit a contributor looks exactly like a complete one. Surfacing +-- the shortfall means the next scoring path added outside the trace announces +-- itself instead of quietly making the explanation wrong. +local function attribute(record) + local traced = 0 + for _, entry in ipairs(record.trace or {}) do + traced = traced + (tonumber(entry.score) or 0) + end + record.traced_score = traced + record.unattributed_score = (record.score or 0) - traced + return record +end + +local function as_array(t) + if type(t) ~= "table" then + return setmetatable({}, cjson.array_mt) + end + return setmetatable(t, cjson.array_mt) +end + +local function query_arg(name, default) + local args = ngx.req.get_uri_args() + local value = args[name] + if type(value) == "table" then value = value[1] end + if value == nil or value == "" then return default end + return value +end + +local function clamp(value, default, min, max) + local n = tonumber(value) or default + n = math.floor(n) + if n < min then return min end + if n > max then return max end + return n +end + +--- Does this record match every supplied filter? +local function matches(record, f) + if f.vhost_id and record.vhost_id ~= f.vhost_id then return false end + if f.endpoint_id and record.endpoint_id ~= f.endpoint_id then return false end + if f.client_ip and record.client_ip ~= f.client_ip then return false end + if f.action and record.action ~= f.action then return false end + if f.min_score and (record.score or 0) < f.min_score then return false end + if f.since and (record.ts or 0) < f.since then return false end + if f.until_ts and (record.ts or 0) > f.until_ts then return false end + + if f.flag then + local found = false + for _, flag in ipairs(record.flags or {}) do + if flag == f.flag or flag:find(f.flag, 1, true) then + found = true + break + end + end + if not found then return false end + end + + -- Plain substring, not a pattern: an operator pasting a path from a log + -- should not have to escape it, and a bad pattern here would error rather + -- than simply not match. + if f.path and not (record.path or ""):find(f.path, 1, true) then return false end + + return true +end + +--- Walk the list, newest first, collecting matches. +local function search(red, filters, limit) + local raw = red:lrange(KEYS.decisions, 0, MAX_SCAN - 1) + if type(raw) ~= "table" then + return {}, 0 + end + + local out, scanned = {}, 0 + for _, entry in ipairs(raw) do + scanned = scanned + 1 + local record = cjson.decode(entry) + if type(record) == "table" and matches(record, filters) then + out[#out + 1] = attribute(record) + if #out >= limit then break end + end + end + return out, scanned +end + +local function collect_filters() + return { + vhost_id = query_arg("vhost_id"), + endpoint_id = query_arg("endpoint_id"), + client_ip = query_arg("client_ip"), + action = query_arg("action"), + flag = query_arg("flag"), + path = query_arg("path"), + min_score = tonumber(query_arg("min_score")), + since = tonumber(query_arg("since")), + until_ts = tonumber(query_arg("until")), + } +end + +_M.handlers = {} + +-- GET /decisions - search the decision log +_M.handlers["GET:/decisions"] = function() + local limit = clamp(query_arg("limit", DEFAULT_LIMIT), DEFAULT_LIMIT, 1, MAX_LIMIT) + + local red, err = utils.get_redis() + if not red then + return utils.error_response("Redis connection failed: " .. (err or "unknown")) + end + + local decisions, scanned = search(red, collect_filters(), limit) + local stats = red:hgetall(KEYS.stats) + local total = 0 + local dropped = 0 + if type(stats) == "table" then + for i = 1, #stats, 2 do + if stats[i] == "total" then total = tonumber(stats[i + 1]) or 0 end + if stats[i] == "dropped_total" then dropped = tonumber(stats[i + 1]) or 0 end + end + end + utils.close_redis(red) + + local cfg = decision_recorder.get_config() + + return utils.json_response({ + decisions = as_array(decisions), + count = #decisions, + limit = limit, + scanned = scanned, + -- Non-zero means the recorder's buffer overflowed and the log has holes. + dropped_total = dropped, + recorded_total = total, + retention = { + enabled = cfg.enabled, + max_records = cfg.max_records, + ttl_seconds = cfg.ttl, + min_score = cfg.min_score, + }, + }) +end + +-- DELETE /decisions - discard the log +_M.handlers["DELETE:/decisions"] = function() + local red, err = utils.get_redis() + if not red then + return utils.error_response("Redis connection failed: " .. (err or "unknown")) + end + + red:del(KEYS.decisions) + red:del(KEYS.stats) + utils.close_redis(red) + + ngx.log(ngx.WARN, "DECISION_LOG_CLEARED by=", + (ngx.ctx.admin_user and ngx.ctx.admin_user.username) or "unknown") + + return utils.json_response({ cleared = true }) +end + +-- Parametric: GET /decisions/{request_id} - explain one decision +_M.resource_handlers = {} + +_M.resource_handlers["GET"] = function(request_id) + local red, err = utils.get_redis() + if not red then + return utils.error_response("Redis connection failed: " .. (err or "unknown")) + end + + local raw = red:lrange(KEYS.decisions, 0, MAX_SCAN - 1) + utils.close_redis(red) + + if type(raw) == "table" then + for _, entry in ipairs(raw) do + local record = cjson.decode(entry) + if type(record) == "table" and record.request_id == request_id then + return utils.json_response({ decision = attribute(record) }) + end + end + end + + -- 404 here means "not retained", which is a different thing from "never + -- happened" -- the log is capped and time-limited by design. + return utils.error_response( + "No decision recorded for request id '" .. tostring(request_id) .. + "'. The log is capped and time-limited, so an older request may have aged out.", 404) +end + +return _M diff --git a/openresty/lua/defense_profile_multi_executor.lua b/openresty/lua/defense_profile_multi_executor.lua index 42e2562..75221ac 100644 --- a/openresty/lua/defense_profile_multi_executor.lua +++ b/openresty/lua/defense_profile_multi_executor.lua @@ -446,6 +446,33 @@ function _M.execute(config, request_context) lines_result.blocked_by_line or "none" )) + -- The base result of a multi-profile run carries no top-level trace: the + -- per-node entries sit under profile_results[id].trace. Setting a trace on + -- the merged result makes the consumer read that and stop looking, so the + -- base entries have to be folded in here or they are lost -- a wp-login + -- decision reported score 113 against a trace summing to 83, the difference + -- being the fingerprint node the base profile had already scored. + local function base_trace(result) + local flat = {} + if type(result.trace) == "table" then + for _, entry in ipairs(result.trace) do + flat[#flat + 1] = entry + end + return flat + end + for profile_id, r in pairs(result.profile_results or {}) do + if type(r) == "table" and type(r.trace) == "table" then + for _, entry in ipairs(r.trace) do + if type(entry) == "table" then + entry.profile = profile_id + flat[#flat + 1] = entry + end + end + end + end + return flat + end + -- Merge results: if defense lines block, the final action is block if lines_result.action == "block" then -- Combine flags from base and defense lines @@ -457,11 +484,20 @@ function _M.execute(config, request_context) table.insert(all_flags, flag) end + local merged_trace = base_trace(base_result) + table.insert(merged_trace, { + defense = "defense_line:" .. (lines_result.blocked_by_line or "unknown"), + score = lines_result.score or 0, + blocked = true, + flags = lines_result.flags, + }) + return { action = "block", action_config = lines_result.action_config or base_result.action_config, score = base_result.score + lines_result.score, flags = all_flags, + trace = merged_trace, details = { base_profile = base_result.details, defense_lines = lines_result.details @@ -487,11 +523,25 @@ function _M.execute(config, request_context) table.insert(all_flags, flag) end + -- Defense lines contribute score even when they do not block, so this merge + -- needs the same trace entry as the blocking branch above. Tracing only the + -- blocking one left a wp-login decision reporting score 113 against a trace + -- summing to 30. + local merged_trace = base_trace(base_result) + if (lines_result.score or 0) ~= 0 or (lines_result.flags and #lines_result.flags > 0) then + table.insert(merged_trace, { + defense = "defense_line:" .. (lines_result.blocked_by_line or "evaluated"), + score = lines_result.score or 0, + flags = lines_result.flags, + }) + end + return { action = "allow", action_config = base_result.action_config, score = base_result.score + lines_result.score, flags = all_flags, + trace = merged_trace, details = { base_profile = base_result.details, defense_lines = lines_result.details diff --git a/openresty/lua/rbac.lua b/openresty/lua/rbac.lua index 537147b..e4bfa46 100644 --- a/openresty/lua/rbac.lua +++ b/openresty/lua/rbac.lua @@ -39,6 +39,7 @@ local DEFAULT_ROLES = { slack = {"read", "update", "test", "reset"}, shadow = {"read", "promote", "delete"}, suppressions = {"create", "read", "delete"}, + decisions = {"read", "delete"}, geoip = {"read", "update", "reload"}, reputation = {"read", "update"}, timing = {"read", "update"}, @@ -72,6 +73,7 @@ local DEFAULT_ROLES = { slack = {"read"}, shadow = {"read"}, suppressions = {"create", "read", "delete"}, + decisions = {"read", "delete"}, geoip = {"read"}, reputation = {"read"}, timing = {"read"}, @@ -102,6 +104,7 @@ local DEFAULT_ROLES = { slack = {"read"}, shadow = {"read"}, suppressions = {"read"}, + decisions = {"read"}, geoip = {"read"}, reputation = {"read"}, timing = {"read"}, @@ -198,6 +201,8 @@ local ENDPOINT_PERMISSIONS = { ["GET:/suppressions"] = {resource = "suppressions", action = "read"}, ["POST:/suppressions"] = {resource = "suppressions", action = "create"}, ["DELETE:/suppressions"] = {resource = "suppressions", action = "delete"}, + ["GET:/decisions"] = {resource = "decisions", action = "read"}, + ["DELETE:/decisions"] = {resource = "decisions", action = "delete"}, -- Slack notifications ["GET:/slack/config"] = {resource = "slack", action = "read"}, @@ -309,6 +314,11 @@ local PARAMETRIC_PERMISSIONS = { suppressions = { ["DELETE"] = {resource = "suppressions", action = "delete"}, }, + -- Decisions. Not vhost-scoped: the id is a request id, not a vhost. A + -- scoped role still sees every vhost's decisions, which is worth knowing. + decisions = { + ["GET"] = {resource = "decisions", action = "read"}, + }, -- Endpoints endpoints = { ["GET"] = {resource = "endpoints", action = "read", scoped = true}, @@ -542,6 +552,11 @@ function _M.get_endpoint_permission(method, path) return PARAMETRIC_PERMISSIONS.endpoints[handler_key], endpoint_id, "endpoint" end + local decision_request_id = path:match("^/decisions/([a-fA-F0-9]+)$") + if decision_request_id then + return PARAMETRIC_PERMISSIONS.decisions[method], decision_request_id, "decision" + end + local suppression_id = path:match("^/suppressions/([a-fA-F0-9]+)$") if suppression_id then return PARAMETRIC_PERMISSIONS.suppressions[method], suppression_id, "suppression" diff --git a/openresty/lua/waf_handler.lua b/openresty/lua/waf_handler.lua index bc436c8..8121c57 100644 --- a/openresty/lua/waf_handler.lua +++ b/openresty/lua/waf_handler.lua @@ -49,6 +49,24 @@ local LOG_HMAC_KEY = os.getenv("WAF_LOG_HMAC_KEY") local collect_trace +-- Append to whichever trace a result carries. Scores added outside the profile +-- executor -- vhost keywords here, defense lines in the multi-executor -- have +-- to land in the trace too, or the detail view shows a total that its own +-- breakdown does not account for. +local function add_trace_entry(profile_result, entry) + if type(profile_result) ~= "table" then return end + + if type(profile_result.trace) == "table" then + table.insert(profile_result.trace, entry) + return + end + + -- Multi-profile result: no top-level trace, so carry these in a list the + -- flattener folds in alongside the per-profile ones. + profile_result.extra_trace = profile_result.extra_trace or {} + table.insert(profile_result.extra_trace, entry) +end + -- Keep a would-block decision so "what happens if I switch this to blocking?" -- becomes a query rather than a log grep. -- @@ -87,7 +105,7 @@ collect_trace = function(profile_result) end local results = profile_result.profile_results - if type(results) ~= "table" then return nil end + if type(results) ~= "table" then return profile_result.extra_trace end local flat = {} for profile_id, r in pairs(results) do @@ -100,6 +118,9 @@ collect_trace = function(profile_result) end end end + for _, entry in ipairs(profile_result.extra_trace or {}) do + flat[#flat + 1] = entry + end return flat end @@ -686,6 +707,12 @@ function _M.process_request() profile_result.action = "block" profile_result.blocked_by = profile_result.blocked_by or {} table.insert(profile_result.blocked_by, "additional_keyword") + add_trace_entry(profile_result, { + defense = "additional_keyword", + score = 0, + blocked = true, + flags = { "vhost:add_block:" .. kw }, + }) ngx.log(ngx.INFO, "ADDITIONAL_KEYWORD_BLOCK: keyword=", kw) end end @@ -699,6 +726,11 @@ function _M.process_request() checked_flagged[kw_lower] = true profile_result.score = (profile_result.score or 0) + kw_score table.insert(profile_result.flags, "vhost:add_flag:" .. kw) + add_trace_entry(profile_result, { + defense = "additional_keyword", + score = kw_score, + flags = { "vhost:add_flag:" .. kw }, + }) end end end diff --git a/scripts/check-api-contract.py b/scripts/check-api-contract.py index 25e6e7e..665650b 100755 --- a/scripts/check-api-contract.py +++ b/scripts/check-api-contract.py @@ -113,6 +113,7 @@ def main(): base = "/" + base.split("/", 3)[3] if len(base.split("/", 3)) > 3 else "" failures, checked = [], 0 + skipped = [] for path, methods in spec["paths"].items(): if "get" not in methods: continue @@ -123,6 +124,17 @@ def main(): example_query = methods["get"].get("x-contract-example-query") if example_query: url = f"{url}?{example_query}" + + # A path template with no fixed example -- a request id, say -- cannot be + # fetched. Skip it, but print it: a check that silently covers less than + # it appears to is worse than one that admits the gap. + skip_reason = methods["get"].get("x-contract-skip") + if skip_reason: + skipped.append(f"GET {path}: {skip_reason}") + continue + if "{" in path: + skipped.append(f"GET {path}: templated path with no x-contract-skip reason given") + continue try: status, raw, _ = request(url, cookie=cookie) except urllib.error.HTTPError as exc: @@ -153,6 +165,10 @@ def main(): print("API contract check") print("==================") print(f" endpoints validated : {checked}") + if skipped: + print(f" endpoints skipped : {len(skipped)}") + for entry in skipped: + print(f" - {entry}") for f in failures: print(f" MISMATCH : {f}") From d3ccb266258c9c106f6ca641697e68f8f914027e Mon Sep 17 00:00:00 2001 From: Martin Dobrev Date: Fri, 7 Aug 2026 17:09:43 +0100 Subject: [PATCH 3/4] fix: Read $request_id once per request, and return it on responses Completes #C2's deep-link criterion, and fixes a bug it exposed. $request_id is not cached by this nginx build. Every read of ngx.var.request_id mints a fresh value, so two adjacent reads in the same request return different ids. This was found because the id on a blocked response never matched the id recorded for it -- one request, one record, two different ids -- and confirmed by logging two consecutive reads: a=744565d2... b=5dcba40f... The consequence is wider than this feature. audit_log and the webhook payload each read it independently, so the audit entry and the webhook for the same request have always carried different "request ids", and neither matched anything else. An id that correlates with nothing is worse than no id, because it invites a correlation that will not work. Read once now, cached on ngx.ctx, shared by the audit log, the webhook payload, the decision record and the response header. X-WAF-Request-Id is returned on every response and deliberately not gated behind WAF_EXPOSE_HEADERS: it is the handle support needs to look a decision up, and unlike the score and flag headers it reveals nothing about the verdict, which is what that flag exists to withhold. Verified end to end: a blocked response returned 3d733798..., and GET /decisions/3d733798... returned that decision with its breakdown. Gates: 88 unit specs, helm drift clean, config contracts hold, integration 42 passed / 2 known gaps / 0 failed. --- openresty/lua/waf_handler.lua | 27 +++++++++++++++++++++++++-- openresty/lua/webhooks.lua | 5 ++++- 2 files changed, 29 insertions(+), 3 deletions(-) diff --git a/openresty/lua/waf_handler.lua b/openresty/lua/waf_handler.lua index 8121c57..29acf79 100644 --- a/openresty/lua/waf_handler.lua +++ b/openresty/lua/waf_handler.lua @@ -49,6 +49,23 @@ local LOG_HMAC_KEY = os.getenv("WAF_LOG_HMAC_KEY") local collect_trace +--- The request id, stable for the life of the request. +-- +-- $request_id is NOT cached by this nginx build: every read of +-- ngx.var.request_id mints a fresh value. Two adjacent reads in one request +-- return different ids, which quietly made every id the WAF emitted useless for +-- correlation -- the audit log entry and the webhook for the same request +-- carried different "request ids", and neither matched the response header. +-- Read once, cached on ngx.ctx, shared by everything that reports an id. +local function request_id() + local rid = ngx.ctx.waf_request_id + if not rid then + rid = ngx.var.request_id or tostring(ngx.now()) + ngx.ctx.waf_request_id = rid + end + return rid +end + -- Append to whichever trace a result carries. Scores added outside the profile -- executor -- vhost keywords here, defense lines in the multi-executor -- have -- to land in the trace too, or the detail view shows a total that its own @@ -149,7 +166,7 @@ local function audit_log(event_type, event_data) local log_entry = { ["@timestamp"] = os.date("!%Y-%m-%dT%H:%M:%SZ"), event_type = event_type, - request_id = ngx.var.request_id or tostring(ngx.now()), + request_id = request_id(), client_ip = trusted_proxies.get_client_ip(), -- F01: Use secure IP extraction host = ngx.var.http_host or ngx.var.host, path = ngx.var.uri, @@ -784,8 +801,14 @@ function _M.process_request() -- tarpit, flag, monitor, allow -- and covering five is the failure this -- feature exists to avoid. The log phase sees exactly one outcome per -- request, and the real one. + -- Returned on every response, not gated behind WAF_EXPOSE_HEADERS. It is + -- the handle support needs to look a decision up, and it reveals nothing + -- about the verdict -- unlike the score and flag headers, which is what + -- that flag exists to keep in. + ngx.header["X-WAF-Request-Id"] = request_id() + ngx.ctx.waf_decision = { - request_id = ngx.var.request_id, + request_id = request_id(), vhost_id = summary.vhost_id, endpoint_id = summary.endpoint_id, client_ip = client_ip, diff --git a/openresty/lua/webhooks.lua b/openresty/lua/webhooks.lua index 412ac8e..9686d5d 100644 --- a/openresty/lua/webhooks.lua +++ b/openresty/lua/webhooks.lua @@ -278,7 +278,10 @@ end -- F14: Use trusted_proxies for secure IP extraction function _M.create_event_data(context, extra_data) local data = { - request_id = ngx.var.request_id or ngx.now(), + -- ngx.ctx first: $request_id is not cached by this nginx build, so + -- reading it again here would produce an id matching nothing else + -- reported for this request. waf_handler sets the shared one. + request_id = ngx.ctx.waf_request_id or ngx.var.request_id or ngx.now(), client_ip = trusted_proxies.get_client_ip(), host = ngx.var.http_host or ngx.var.host, path = ngx.var.uri, From a371380d56ab1110c3851a9045ded16bcbdd7d1b Mon Sep 17 00:00:00 2001 From: Martin Dobrev Date: Fri, 7 Aug 2026 18:33:12 +0100 Subject: [PATCH 4/4] fix: Address Copilot review on PR #41 Five findings, all valid. Empty lists were encoded as JSON objects. cjson encodes an empty Lua table as {} rather than [], so a decision with no flags stored "flags":{}. This is worse than a type inconsistency: the UI writes `flags ?? []`, which does not catch {} because it is neither null nor undefined, so .slice() on it is undefined and the page crashes rather than showing an empty column. Same for blocked_by, suppressed, and a trace with nothing significant in it. Empty lists are now omitted, keeping the optional-array contract the generated types already describe. Four specs pin it, including one asserting a populated list still encodes as an array. ngx.ctx.captcha_challenged was never set. I read a flag I had invented, so a CAPTCHA challenge was recorded as allowed or would_block -- the one outcome the log could not describe. Now set at the single serve_challenge site. The request-id fallback produced a decimal string. tostring(ngx.now()) gives "1786126789.12", and the route and RBAC patterns for /decisions/{id} are hex-only, so a decision recorded under that id could never be looked up -- the one thing the id exists for. Falls back to ngx.md5, matching $request_id's shape. The webhook fallback emitted a number, so request_id changed type depending on where it came from. That is a correlation key that cannot be matched on. Hex string in every case now. Verified live: no field in the stored records is an empty object, and the blocked-response round trip still resolves (id 4a81cfbc..., hex, found). Gates: 92 unit specs (4 new), helm drift clean, config contracts hold, contract check 13 validated / 1 skipped, integration 42 passed / 2 known gaps / 0 failed, typecheck 0 errors. --- openresty/lua/decision_recorder.lua | 11 ++++++- openresty/lua/waf_handler.lua | 16 +++++++-- openresty/lua/webhooks.lua | 6 +++- openresty/spec/decision_recorder_spec.lua | 40 +++++++++++++++++++++++ 4 files changed, 69 insertions(+), 4 deletions(-) diff --git a/openresty/lua/decision_recorder.lua b/openresty/lua/decision_recorder.lua index d77a816..b8e1001 100644 --- a/openresty/lua/decision_recorder.lua +++ b/openresty/lua/decision_recorder.lua @@ -95,8 +95,15 @@ function _M._reset_config() _config = nil end +--- Clip a list, or return nil if there is nothing in it. +-- +-- nil rather than {} on purpose: cjson encodes an empty Lua table as {}, not [], +-- so an empty flags list would arrive at the UI as an object. `flags ?? []` does +-- not catch that -- {} is neither null nor undefined -- and .slice() on it is +-- undefined, which is a crashed page rather than an empty column. Omitting the +-- field keeps the optional-array contract the generated types already describe. local function clip_list(list, limit, max_len) - if type(list) ~= "table" then return nil end + if type(list) ~= "table" or #list == 0 then return nil end local out = {} for i = 1, math.min(#list, limit) do out[i] = clip(list[i], max_len) @@ -129,6 +136,8 @@ local function compact_trace(trace) end end end + -- Same reasoning as clip_list: an empty trace must be absent, not {}. + if #significant == 0 then return nil end return significant end diff --git a/openresty/lua/waf_handler.lua b/openresty/lua/waf_handler.lua index 29acf79..6bca387 100644 --- a/openresty/lua/waf_handler.lua +++ b/openresty/lua/waf_handler.lua @@ -60,7 +60,15 @@ local collect_trace local function request_id() local rid = ngx.ctx.waf_request_id if not rid then - rid = ngx.var.request_id or tostring(ngx.now()) + rid = ngx.var.request_id + if not rid or rid == "" then + -- Hex, matching $request_id's shape. A decimal timestamp would be + -- unqueryable: the route and RBAC patterns for /decisions/{id} are + -- hex-only, so an id that is not hex records a decision nobody can + -- look up -- the one thing the id exists for. + rid = ngx.md5(string.format("%s:%s:%s", + ngx.now(), ngx.worker.pid(), ngx.var.connection or "0")) + end ngx.ctx.waf_request_id = rid end return rid @@ -435,7 +443,7 @@ function _M.log_decision() action = "blocked" elseif status == 429 then action = "tarpit" - elseif ngx.ctx.captcha_challenged then + elseif ngx.ctx.waf_captcha_challenged then action = "challenged" elseif decision.profile_action == "block" then action = "would_block" @@ -943,6 +951,10 @@ function _M.process_request() profile_result.score or 0 )) metrics.record_request(summary.vhost_id, summary.endpoint_id, "captcha_challenged", profile_result.score or 0) + -- Read by log_decision to record action "challenged". + -- Without it a challenge is indistinguishable from a plain + -- allow in the decision log. + ngx.ctx.waf_captcha_challenged = true return captcha_handler.serve_challenge(context, nil, "defense_profile", client_ip) end end diff --git a/openresty/lua/webhooks.lua b/openresty/lua/webhooks.lua index 9686d5d..feed82b 100644 --- a/openresty/lua/webhooks.lua +++ b/openresty/lua/webhooks.lua @@ -281,7 +281,11 @@ function _M.create_event_data(context, extra_data) -- ngx.ctx first: $request_id is not cached by this nginx build, so -- reading it again here would produce an id matching nothing else -- reported for this request. waf_handler sets the shared one. - request_id = ngx.ctx.waf_request_id or ngx.var.request_id or ngx.now(), + request_id = ngx.ctx.waf_request_id or ngx.var.request_id + -- Hex string in every case. ngx.now() here emitted a number, so a + -- payload's request_id changed type depending on where it came + -- from, which is a correlation key that cannot be matched on. + or ngx.md5(tostring(ngx.now())), client_ip = trusted_proxies.get_client_ip(), host = ngx.var.http_host or ngx.var.host, path = ngx.var.uri, diff --git a/openresty/spec/decision_recorder_spec.lua b/openresty/spec/decision_recorder_spec.lua index a67730f..cee5c94 100644 --- a/openresty/spec/decision_recorder_spec.lua +++ b/openresty/spec/decision_recorder_spec.lua @@ -99,6 +99,46 @@ describe("decision_recorder", function() end) end) + describe("empty lists are omitted, not encoded as objects", function() + -- cjson encodes an empty Lua table as {}, not []. The UI writes + -- `flags ?? []`, which does not catch {} -- it is neither null nor + -- undefined -- so .slice() on it is undefined and the page crashes. + -- Omitting the field is what keeps the optional-array contract true. + local function stored(decision) + recorder.record(decision) + local red = fake_redis() + recorder.flush(red) + return red.calls.lpush[1] + end + + it("omits an empty flags list rather than storing {}", function() + local raw = stored(a_decision({ flags = {} })) + assert.is_nil(raw:find('"flags":{}', 1, true), + "an empty flags list must not be stored as a JSON object") + local cjson = require "cjson.safe" + assert.is_nil(cjson.decode(raw).flags) + end) + + it("omits an empty blocked_by list", function() + local raw = stored(a_decision({ blocked_by = {} })) + assert.is_nil(raw:find('"blocked_by":{}', 1, true)) + end) + + it("omits a trace with nothing significant in it", function() + local raw = stored(a_decision({ + trace = { { node = "n1", defense = "honeypot", score = 0 } }, + })) + assert.is_nil(raw:find('"trace":{}', 1, true)) + local cjson = require "cjson.safe" + assert.is_nil(cjson.decode(raw).trace) + end) + + it("still encodes a populated list as an array", function() + local raw = stored(a_decision({ flags = { "kw:viagra" } })) + assert.is_not_nil(raw:find('"flags":["kw:viagra"]', 1, true)) + end) + end) + describe("trace compaction", function() local function traced(trace) recorder.record(a_decision({ trace = trace }))