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/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/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/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..b8e1001 --- /dev/null +++ b/openresty/lua/decision_recorder.lua @@ -0,0 +1,225 @@ +--[[ + 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 + +--- 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" or #list == 0 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 + -- Same reasoning as clip_list: an empty trace must be absent, not {}. + if #significant == 0 then return nil 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..75221ac 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 @@ -443,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 @@ -454,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 @@ -484,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/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..6bca387 100644 --- a/openresty/lua/waf_handler.lua +++ b/openresty/lua/waf_handler.lua @@ -47,6 +47,51 @@ end -- F08: HMAC key for log integrity (optional) 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 + 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 +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 +-- 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. -- @@ -72,6 +117,38 @@ 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 profile_result.extra_trace 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 + for _, entry in ipairs(profile_result.extra_trace or {}) do + flat[#flat + 1] = entry + 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 @@ -97,7 +174,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, @@ -344,6 +421,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.waf_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 @@ -620,6 +732,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 @@ -633,6 +751,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 @@ -681,6 +804,35 @@ 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. + -- 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 = 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) @@ -799,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 412ac8e..feed82b 100644 --- a/openresty/lua/webhooks.lua +++ b/openresty/lua/webhooks.lua @@ -278,7 +278,14 @@ 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 + -- 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 new file mode 100644 index 0000000..cee5c94 --- /dev/null +++ b/openresty/spec/decision_recorder_spec.lua @@ -0,0 +1,193 @@ +--[[ + 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("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 })) + 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) 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}")