diff --git a/.env.template b/.env.template index d6b23ab..c5d39dc 100644 --- a/.env.template +++ b/.env.template @@ -99,6 +99,37 @@ UVICORN_WORKERS=1 # Example: http://haproxy-manager.example.com,http://localhost:8080 CORS_ORIGINS= +# ============================================================================ +# REQUEST / RESPONSE LOG (v1.11.0) +# ============================================================================ +# Records every inbound API call and every outbound HTTP call the backend makes +# (ACME, DNS providers, agents) into the `request_logs` table, browsable under +# "Request Log" in the UI. +# +# Only the four settings below are environment-level, because they decide +# whether the middleware is registered at all and how much memory the writer +# queue may hold. Everything an operator tunes day to day — retention windows, +# body capture, sampling, excluded paths — lives in the database and is edited +# in Settings -> Request Log. + +# Hard kill-switch. When false the logging middleware is NEVER added to the ASGI +# stack and neither the writer nor the retention task starts: zero overhead, not +# even a settings lookup. Requires a restart to change. +# (The `enabled` toggle in Settings is the no-restart equivalent.) +REQUEST_LOG_ENABLED=true + +# Per-worker in-process queue depth. When it fills, rows are DROPPED and counted +# rather than blocking the request — the drop count is shown on the Request Log +# page. Raise it if you see drops under normal load. +REQUEST_LOG_QUEUE_MAX=2000 + +# Rows per batched INSERT. One connection is taken from the pool per batch, not +# per request. +REQUEST_LOG_BATCH_SIZE=100 + +# Maximum wait before a partial batch is flushed, in milliseconds. +REQUEST_LOG_FLUSH_MS=500 + # ============================================================================ # FRONTEND CONFIGURATION (React) # ============================================================================ diff --git a/CONFIG.md b/CONFIG.md index f2d61bc..a65e530 100644 --- a/CONFIG.md +++ b/CONFIG.md @@ -131,6 +131,53 @@ if (window.location) { } ``` +### REQUEST_LOG_ENABLED (v1.11.0) + +**Ne İşe Yarar**: Request/Response Log özelliğinin sert (hard) kill-switch'i. `false` yapıldığında +loglama middleware'i ASGI zincirine **hiç eklenmez**, yazıcı ve retention görevleri başlatılmaz — +yani sıfır ek yük, ayar okuması bile yapılmaz. Değişiklik için restart gerekir. + +**Örnekler**: +```bash +# Varsayılan: açık +REQUEST_LOG_ENABLED=true + +# Tamamen kapat (ör. çok yüksek trafikli kurulum, veya regülasyon gereği) +REQUEST_LOG_ENABLED=false +``` + +**Nasıl Kullanılır**: +1. Restart gerektirmeden kapatmak isterseniz bunun yerine **Settings → Request Log → Enable request + log** anahtarını kullanın; o anında etkili olur. +2. Retention süreleri, gövde (body) yakalama, örnekleme oranı ve hariç tutulan path'ler bu env + değişkeniyle değil, veritabanındaki `requestlog.*` ayarlarıyla yönetilir — arayüzden düzenlenir. +3. Disk büyümesi asıl operasyonel konudur: sırasıyla `sample_rate`'i düşürün, `capture_get`'i + kapatın, `capture_bodies`'i kapatın, sonra `success_retention_days`'i kısaltın. + +### REQUEST_LOG_QUEUE_MAX / REQUEST_LOG_BATCH_SIZE / REQUEST_LOG_FLUSH_MS (v1.11.0) + +**Ne İşe Yarar**: Log satırlarını yazan arka plan görevinin ayarları. Satırlar sınırlı bir kuyruğa +konur ve toplu (batch) INSERT ile yazılır; böylece istek yolu asla veritabanını beklemez. + +**Örnekler**: +```bash +# Worker başına kuyruk derinliği. Dolduğunda satırlar DÜŞÜRÜLÜR (sayılır ve +# Request Log sayfasında gösterilir), istek bloklanmaz. +REQUEST_LOG_QUEUE_MAX=2000 + +# Tek INSERT'te kaç satır yazılacağı (havuzdan istek başına değil, batch başına +# bir bağlantı alınır) +REQUEST_LOG_BATCH_SIZE=100 + +# Yarım dolu bir batch'in en fazla ne kadar bekletileceği (ms) +REQUEST_LOG_FLUSH_MS=500 +``` + +**Nasıl Kullanılır**: +1. Request Log sayfasında "rows dropped" uyarısı görüyorsanız önce `REQUEST_LOG_QUEUE_MAX`'ı + artırın; sorun devam ederse `sample_rate`'i düşürün. +2. Bu üç değer worker başınadır — `UVICORN_WORKERS` arttıkça toplam bellek de o oranda artar. + ## 🚀 Deployment Senaryoları ### Docker Compose diff --git a/README.md b/README.md index 449ac3e..320dcba 100644 --- a/README.md +++ b/README.md @@ -116,6 +116,7 @@ This architecture provides better security (no inbound connections to HAProxy se ✅ **HA / VIP (Keepalived) Management** - Create virtual IPs from the UI; the agent installs & configures Keepalived (unicast VRRP) with a HAProxy health-check so the VIP fails over automatically; live MASTER/BACKUP detection per node ✅ **Role-Based User Management** - Admin and user roles with granular permissions and access control ✅ **User Activity Audit Logs** - Complete audit trail of all system events +✅ **Request/Response Log** *(v1.11.0)* - Every inbound API call (GETs and errors included) and every outbound HTTP call the backend makes (ACME, Cloudflare, GoDaddy, agents) in one filterable timeline, with redacted, size-capped bodies and operator-configurable retention ✅ **REST API** - Full programmatic access for automation and CI/CD integration @@ -2474,6 +2475,7 @@ Developed with ❤️ for the HAProxy community ## Release Notes +- **v1.11.0** (2026-08-11) — **Unified request/response log with configurable retention**: until now the only record of what happened was `user_activity_logs`, which stores non-GET **2xx** operations with no bodies — so when something failed you could see *that* the count went up, never *what was sent or what came back*. This release adds one queryable timeline covering **both directions**: every inbound API call (**including GETs and including 4xx/5xx**) with the user, client IP, status, duration and — redacted and size-capped — the request and response bodies; and every **outbound** HTTP call the backend makes, tagged with who it went to (ACME/Let's Encrypt, Cloudflare, GoDaddy, HAProxy stats, agents, the ACME diagnostics probe). Outbound rows **inherit the inbound request's id**, so one operator action and the CA/DNS calls it triggered read as a single trace — opening a failed *Request Certificate* shows the exact `POST /acme/new-order` and the CA's `429` body underneath it. Capture is a **pure-ASGI middleware that tees** the request and response streams rather than draining them, so no downstream handler is affected (notably the raw-body agent heartbeat), and rows are written by a **batching background writer** with a bounded queue, so the request path never waits on the database and a saturated logger drops rows visibly instead of blocking. Secrets never land: headers are an allowlist (`Authorization`/`Cookie` reduced to a presence marker), body keys and value shapes are redacted (passwords, tokens, API keys, private-key PEMs, JWTs), the **ACME JWS request body is never stored** (a stored `protected`+`signature` pair is a replayable credential — a summary is logged instead), DNS-provider errors record only the exception **type**, and the ACME HTTP-01 challenge endpoint is excluded so `key_authorization` is never captured. **Retention is operator-configurable** in *Settings → Request Log*: separate day counts for successful and failed rows (defaults 7 and 30) plus a hard row cap (500 000), whichever is reached first, pruned in **batches** under a Postgres advisory lock so a multi-million-row table cannot time out the delete or have every replica scan it at once. New **Request Log** page (`requestlog.read`) and retention/purge permission (`requestlog.manage`); `super_admin` and `security_admin` get both, `operator` gets read, `viewer` gets neither. Adds one new table (`request_logs`) and its settings seed — SCHEMA_VERSION 10 → 11, auto-migrated, no existing table altered, no agent or rendered-config change. Kill switches: `REQUEST_LOG_ENABLED=false` (environment — the middleware is then never registered and costs nothing) or the `enabled` toggle in Settings (no restart). - **v1.10.3** (2026-08-08) — **Multi-account ACME: the certificate wizard honours the account you pick**: with more than one ACME account registered, picking an **HTTP-01** account in *Request ACME Certificate* still produced a **DNS-01** request. Three faults compounded. (1) `Form.useWatch` reports only fields that are currently **rendered**, and the account `Select` lives on the *Configuration* step — so as soon as the wizard advanced to *Review* the watch read `undefined` and the wizard silently reverted to the default account, even though the value was still in the form store; the watches now pass `preserve: true`. The same fault disabled the **wildcard guard** on *Review*, the one step where Submit lives. (2) The UI and the backend disagreed on which account is the *default*: the backend takes the **newest** valid account (`ORDER BY created_at DESC`), the UI took the **oldest** entry of a list ordered by id — the opposite account whenever the two differ. The wizard now resolves the same one, and sends `account_id` **explicitly** so there is no guess left to disagree about. (3) `account_id` was read from the form store while `challenge_type` came from the reverted account object, so the request asked for DNS-01 validation on an HTTP-01 account and the API answered `The selected ACME account has no DNS provider configured for DNS-01.` — both are now derived from one resolved account. The *Review* step also showed the default account's address instead of the chosen one, and Submit stayed enabled for a deactivated account; both fixed. Frontend only — no schema, API-shape, agent or rendered-config changes, and single-account installations behave exactly as before. - **v1.10.2** (2026-08-08) — **Dark mode fixes on Apply Management**: several panels on the Apply Management page were painted with light-mode colour literals, so in dark mode the **Pending Changes** box rendered as a cream panel with light text on it — measured contrast **1.03:1**, effectively unreadable, now **11.50:1**. The same bug affected the added/removed rows in the *View Change* diff (2.21:1 and 2.99:1, now 5.49:1 and 4.01:1), the ACME and pending-version panels, the VIP pending-delete row, and the agent-error recommendation box; all now derive from theme tokens. Separately, **static confirm dialogs came up white in dark mode**: in Ant Design 5 the static `Modal.confirm` / `message` / `notification` APIs render into their own detached root and never see the app's `ConfigProvider`, so they always used the light algorithm. Registering `ConfigProvider.config({ holderRender })` once at the app root fixes **every** static dialog in the application (12 components use them), not only this page. Light mode is byte-identical — each token resolves under the default algorithm to exactly the literal it replaced. Frontend only: no schema, API, environment or agent change. - **v1.10.1** (2026-08-08) — **CSR private key encrypted at rest** (Issue #53): the private key of a **pending** CSR is now Fernet-encrypted in the database instead of stored as PEM. It is the one key in the system worth protecting this way — it sits idle for the entire signing window (days to weeks), is never transmitted to an agent, and is destroyed the moment the signed certificate is imported; `ssl_certificates.private_key_content` and the ACME order keys are unchanged, because agents must receive those in plaintext on every poll. The token replaces the PEM in the **same column**, so there is **no schema change and no `SCHEMA_VERSION` bump** (and therefore no re-seed of the built-in roles). CSRs created before this release keep a raw PEM and are still read transparently, so anything already out for signature imports normally with no data migration. The key derives from `SECRET_KEY` via HKDF with its own info string, independent of the VIP/MFA/DNS keys, and an optional `CSR_ENCRYPTION_KEY` enables independent rotation — rotating `SECRET_KEY` without it makes pending CSR keys unrecoverable, which now fails with an explicit "delete and re-create this CSR" error rather than a misleading key-mismatch. `.env.template` now documents all four per-purpose encryption keys. No API, UI or agent change. diff --git a/UPGRADE_GUIDE.md b/UPGRADE_GUIDE.md index c3a1a95..7718ee1 100644 --- a/UPGRADE_GUIDE.md +++ b/UPGRADE_GUIDE.md @@ -1,3 +1,52 @@ +# Upgrade Notes — v1.11.0 (Unified request/response log) + +**Adds one new table and bumps `SCHEMA_VERSION` 10 → 11. The migration runs automatically on the +first backend start.** No agent impact, no rendered-config change, no change to any existing API +shape or response body. + +- **New table `request_logs`** (BIGSERIAL primary key, 9 indexes). Created empty and starts filling + immediately. Budget for it as **one row per API call**. The shipped defaults keep 7 days of + successful requests, 30 days of failed ones, and at most 500 000 rows — whichever limit is reached + first. Change any of it in *Settings → Request Log*. +- **New permissions `requestlog.read` and `requestlog.manage`.** Both are granted to `super_admin` + and `security_admin`; `operator` gets `requestlog.read` only; `viewer` gets neither, because + captured request/response bodies are a broader disclosure surface than the read-only configuration + views a viewer is meant to have. Custom roles can be granted either from **Users → Roles**. +- **⚠️ Built-in roles are re-seeded to their defaults.** This is the pre-existing behaviour of every + `SCHEMA_VERSION` bump, not something new in this release, but it bites here because this release + bumps: the version gate re-runs the whole sequence and + `update_system_roles_to_enterprise_rbac()` issues an unconditional + `UPDATE roles SET … permissions = WHERE name = …` for the four **built-in** roles + (`super_admin`, `operator`, `security_admin`, `viewer`). **Any customisation you made to a + built-in role is reverted.** Roles you created yourself are untouched (the update matches on + name). To preserve customisation, export with `GET /api/roles` before upgrading and re-apply with + `PUT /api/roles/{id}`, or move the customisation into a custom role. +- **Bodies are captured, redacted and capped at 8 KB.** Passwords, tokens, API keys, private-key + PEMs, JWT-shaped values, `Authorization` / `Cookie` headers, ACME JWS payloads and DNS-provider + credentials are never stored. Headers use an allowlist — anything not on it is dropped rather than + saved. Review *Settings → Request Log* before enabling body capture in a regulated environment; + `capture_bodies` can be turned off while still recording who called what, with what result. +- **Excluded by default:** health checks, the API docs, the ACME HTTP-01 challenge endpoint (it + returns `key_authorization`), the agent heartbeat (the highest-volume POST in the system), static + assets, and the log viewer's own endpoints. The list is editable, except the log viewer itself, + which is a hard floor so the page cannot end up logging you reading it. +- **Disk growth is the main operational consideration.** On a busy install, in order of bluntness: + lower `sample_rate` (errors are always kept at 100 %), turn off `capture_get`, turn off + `capture_bodies`, or shorten `success_retention_days`. +- **New environment variables**, all optional: `REQUEST_LOG_ENABLED` (default `true`), + `REQUEST_LOG_QUEUE_MAX` (2000), `REQUEST_LOG_BATCH_SIZE` (100), `REQUEST_LOG_FLUSH_MS` (500). See + `.env.template`. +- **To disable entirely:** set `REQUEST_LOG_ENABLED=false` in the backend environment and restart — + the middleware is then not registered at all and costs nothing, not even a settings lookup. The + `enabled` toggle in Settings is the no-restart equivalent (it takes effect immediately). +- **Default admin password is not reset** by this bump; user seeding is guarded by an existence + check, not an upsert. +- **Rollback:** downgrade the backend image freely. `request_logs` is purely additive and is simply + ignored by v1.10.x. Drop the table manually if you want the space back: + `DROP TABLE IF EXISTS request_logs;` + +--- + # Upgrade Notes — v1.10.3 (Multi-account ACME wizard fix) **Frontend only. Nothing to do on upgrade.** No schema, no `SCHEMA_VERSION` bump, no API change, no diff --git a/backend/agent_notifications.py b/backend/agent_notifications.py index 089a371..09271c5 100644 --- a/backend/agent_notifications.py +++ b/backend/agent_notifications.py @@ -25,31 +25,42 @@ async def notify_agents_config_change(cluster_id: int, version_name: str) -> Lis for agent in agents: try: agent_url = f"http://{agent['ip_address']}:8081" # Agent default port - + async with aiohttp.ClientSession(timeout=aiohttp.ClientTimeout(total=10)) as session: payload = { "cluster_id": cluster_id, "version_name": version_name, "action": "config_update" } - - async with session.post(f"{agent_url}/api/config/update", json=payload) as response: - if response.status == 200: - results.append({ - 'node': agent['name'], - 'success': True, - 'message': f'Configuration updated successfully', - 'version': version_name - }) - logger.info(f"✅ Agent {agent['name']} notified successfully") - else: - error_text = await response.text() - results.append({ - 'node': agent['name'], - 'success': False, - 'error': f'HTTP {response.status}: {error_text}' - }) - logger.error(f"❌ Agent {agent['name']} notification failed: {response.status}") + + # v1.11.0: instrumented so the code stays correct if the push + # architecture is ever reverted. Unreachable today — see the + # unconditional early return above. + from utils.http_instrumentation import outbound_span, TARGET_AGENT + + push_url = f"{agent_url}/api/config/update" + async with outbound_span( + target=TARGET_AGENT, method="POST", url=push_url, request_body=payload + ) as span: + async with session.post(push_url, json=payload) as response: + if response.status == 200: + span.set_response(response.status, getattr(response, "headers", None)) + results.append({ + 'node': agent['name'], + 'success': True, + 'message': f'Configuration updated successfully', + 'version': version_name + }) + logger.info(f"✅ Agent {agent['name']} notified successfully") + else: + error_text = await response.text() + span.set_response(response.status, getattr(response, "headers", None), error_text) + results.append({ + 'node': agent['name'], + 'success': False, + 'error': f'HTTP {response.status}: {error_text}' + }) + logger.error(f"❌ Agent {agent['name']} notification failed: {response.status}") except asyncio.TimeoutError: results.append({ diff --git a/backend/config.py b/backend/config.py index 8c4559c..2fb00ae 100644 --- a/backend/config.py +++ b/backend/config.py @@ -37,4 +37,48 @@ AGENT_CONFIG_SYNC_INTERVAL_SECONDS = 30 # Entity snapshot enabled by default (rollback functionality) # Set to "false" only if you need to disable snapshot temporarily -ENTITY_SNAPSHOT_ENABLED = os.getenv("ENTITY_SNAPSHOT_ENABLED", "true").lower() == "true" \ No newline at end of file +ENTITY_SNAPSHOT_ENABLED = os.getenv("ENTITY_SNAPSHOT_ENABLED", "true").lower() == "true" + + +# --------------------------------------------------------------------------- +# v1.11.0 — unified request/response log +# --------------------------------------------------------------------------- +# These four are deliberately ENV-only (not database settings): they decide +# whether the middleware is even registered and how much memory the writer +# queue may hold, so they must be resolvable before the DB pool exists. +# Everything the operator tunes at runtime (retention, body capture, sampling, +# excluded paths) lives in `system_settings` under the `requestlog.` category +# and is editable from Settings → Request Log. + +def _bool_env(name: str, default: bool) -> bool: + raw = os.getenv(name) + if raw is None: + return default + return raw.strip().lower() not in ("0", "false", "no", "off", "") + + +def _int_env(name: str, default: int, minimum: int, maximum: int) -> int: + """Read an int env var, clamped. A malformed value falls back to the + default rather than crashing the process at import time.""" + raw = os.getenv(name) + if raw is None or not raw.strip(): + return default + try: + value = int(raw.strip()) + except (TypeError, ValueError): + return default + return max(minimum, min(maximum, value)) + + +# Hard kill-switch. When false the logging middleware is never added to the +# ASGI stack and neither the writer nor the prune task is started — literally +# zero overhead, not even a settings lookup. +REQUEST_LOG_ENABLED = _bool_env("REQUEST_LOG_ENABLED", True) +# Per-worker in-process queue depth. When full, rows are DROPPED (counted, and +# reported through GET /api/request-logs/stats) — the request path never blocks +# on the database. +REQUEST_LOG_QUEUE_MAX = _int_env("REQUEST_LOG_QUEUE_MAX", 2000, 100, 100000) +# Rows per batched INSERT: one pool acquire per batch, not per request. +REQUEST_LOG_BATCH_SIZE = _int_env("REQUEST_LOG_BATCH_SIZE", 100, 1, 1000) +# Max wait before a partial batch is flushed (milliseconds). +REQUEST_LOG_FLUSH_MS = _int_env("REQUEST_LOG_FLUSH_MS", 500, 50, 10000) \ No newline at end of file diff --git a/backend/database/migrations.py b/backend/database/migrations.py index de0f437..02e752b 100644 --- a/backend/database/migrations.py +++ b/backend/database/migrations.py @@ -1365,6 +1365,10 @@ async def update_system_roles_to_enterprise_rbac(): 'roles.read', 'roles.create', 'roles.update', 'roles.delete', 'roles.permissions', 'statistics.read', 'statistics.performance', 'statistics.agents', 'statistics.health', 'statistics.export', 'activity.read', 'activity.all', 'activity.export', + # v1.11.0 — request/response log. `read` browses the log, + # `manage` edits retention/capture settings and triggers a + # manual purge. + 'requestlog.read', 'requestlog.manage', 'settings.read', 'settings.update', 'settings.system', 'settings.security', 'system.restart', 'system.logs', 'system.database', 'system.services', 'system.emergency' ] @@ -1384,7 +1388,11 @@ async def update_system_roles_to_enterprise_rbac(): 'vip.read', 'vip.create', 'vip.update', 'vip.delete', 'vip.apply', 'config.read', 'config.update', 'config.download', 'config.history', 'config.bulk_import', 'config.view_request', 'config.download_request', 'statistics.read', 'statistics.performance', 'statistics.agents', 'statistics.health', - 'activity.read' + 'activity.read', + # v1.11.0 — operators debug failing applies and ACME orders, + # so they get read access to the request log; retention and + # purge stay with the admins. + 'requestlog.read' ] }, 'security_admin': { @@ -1403,9 +1411,16 @@ async def update_system_roles_to_enterprise_rbac(): 'config.read', 'config.history', 'config.view_request', 'config.download_request', 'statistics.read', 'statistics.performance', 'statistics.agents', 'statistics.health', 'activity.read', 'activity.all', 'activity.export', + # v1.11.0 — the request log is a security-forensics surface, + # so the security admin gets both read and retention control. + 'requestlog.read', 'requestlog.manage', 'settings.read', 'settings.security' ] }, + # NOTE (v1.11.0): `viewer` deliberately gets NEITHER requestlog + # permission. Even redacted, captured request/response bodies are a + # far broader disclosure surface than the read-only configuration + # views a viewer is meant to have. 'viewer': { 'display_name': 'Viewer', 'description': 'Read-only access to view configurations, statistics, and monitor system status', @@ -1758,7 +1773,15 @@ async def ensure_agent_activity_logs_table(): # until the operator imports the CA-signed certificate; the import creates a # normal ssl_certificates row and NULLs the key copy here. Additive + idempotent; # no existing table is altered, agents never read this table. -SCHEMA_VERSION = 10 +# v1.11.0 (unified request/response log): bumped 10 -> 11 for the brand-new +# `request_logs` table (ensure_request_logs_table), its retention-settings seed +# (ensure_request_log_settings), and the new `requestlog.read` / +# `requestlog.manage` permissions added to the built-in roles in +# update_system_roles_to_enterprise_rbac(). Without the bump, already-deployed +# databases (version >= 10) skip the whole run and neither the table nor the +# permissions ever land. Additive + idempotent; no existing table is altered, +# agents never read this table. +SCHEMA_VERSION = 11 async def run_all_migrations(): @@ -1902,6 +1925,12 @@ async def _run_all_migrations_inner(): # ssl_certificates/users, both created above. await ensure_ssl_csrs_table() + # v1.11.0 — unified request/response log: brand-new request_logs table + # (no FK targets) plus the seed for its operator-tunable retention + # settings. Both are additive and idempotent. + await ensure_request_logs_table() + await ensure_request_log_settings() + logger.info("Database migrations completed successfully.") @@ -1973,6 +2002,161 @@ async def ensure_ssl_csrs_table(): await close_database_connection(conn) +async def ensure_request_logs_table(): + """v1.11.0 — unified inbound/outbound request/response log. + + Additive only: one brand-new table (request_logs) + indexes. No ALTER of + any existing table; agents never read this table. + + Deliberately has NO foreign key on user_id. This is the highest-volume + table in the system — one row per API call — and per-insert FK validation + is not worth it here; `username` is a denormalized snapshot so a row stays + readable after the user who made the request is deleted. That is also the + correct audit semantics: the record should outlive the account. + + Fully idempotent (CREATE TABLE/INDEX IF NOT EXISTS). Uses only PostgreSQL + 9.5+ features (BIGSERIAL, JSONB, partial indexes, varchar_pattern_ops) so + there is no server-version floor beyond what the rest of the schema needs. + """ + conn = None + try: + conn = await get_database_connection() + + await conn.execute(""" + CREATE TABLE IF NOT EXISTS request_logs ( + id BIGSERIAL PRIMARY KEY, + request_id VARCHAR(64) NOT NULL, + direction VARCHAR(8) NOT NULL, + target VARCHAR(32), + method VARCHAR(10) NOT NULL, + url TEXT NOT NULL, + path VARCHAR(512), + query_params JSONB, + status_code INTEGER, + status_class SMALLINT NOT NULL DEFAULT 0, + duration_ms INTEGER NOT NULL DEFAULT 0, + user_id INTEGER, + username VARCHAR(50), + client_ip INET, + user_agent TEXT, + request_headers JSONB, + request_body JSONB, + request_body_bytes INTEGER NOT NULL DEFAULT 0, + response_headers JSONB, + response_body JSONB, + response_body_bytes INTEGER NOT NULL DEFAULT 0, + error TEXT, + truncated BOOLEAN NOT NULL DEFAULT FALSE, + created_at TIMESTAMPTZ NOT NULL DEFAULT NOW(), + CONSTRAINT request_logs_direction_check + CHECK (direction IN ('inbound', 'outbound')) + ); + """) + + # Indexes run UNCONDITIONALLY on every startup, not only on first + # creation (the R16-2 rule established for acme_order_events): an older + # deploy that raced ahead of an index would otherwise be stuck doing + # sequential scans forever. All are IF NOT EXISTS, so re-running is free. + + # --- read paths: the filters the log viewer actually issues --- + await conn.execute( + "CREATE INDEX IF NOT EXISTS idx_request_logs_created_at " + "ON request_logs(created_at DESC);" + ) + await conn.execute( + "CREATE INDEX IF NOT EXISTS idx_request_logs_dir_created " + "ON request_logs(direction, created_at DESC);" + ) + await conn.execute( + "CREATE INDEX IF NOT EXISTS idx_request_logs_status_created " + "ON request_logs(status_class, created_at DESC);" + ) + await conn.execute( + "CREATE INDEX IF NOT EXISTS idx_request_logs_user_created " + "ON request_logs(user_id, created_at DESC) WHERE user_id IS NOT NULL;" + ) + await conn.execute( + "CREATE INDEX IF NOT EXISTS idx_request_logs_target_created " + "ON request_logs(target, created_at DESC) WHERE target IS NOT NULL;" + ) + # Correlates one inbound row with the outbound calls it caused — this is + # what makes "which request went where" readable as a single trace. + await conn.execute( + "CREATE INDEX IF NOT EXISTS idx_request_logs_request_id " + "ON request_logs(request_id);" + ) + # Prefix search on path (LIKE 'x%') needs pattern_ops to be usable under + # a non-C collation. + await conn.execute( + "CREATE INDEX IF NOT EXISTS idx_request_logs_path_prefix " + "ON request_logs(path varchar_pattern_ops);" + ) + + # --- prune paths: the TTL delete is split by outcome, so a plain + # (status_class, created_at) index would still range-scan the half it + # is not interested in. + await conn.execute( + "CREATE INDEX IF NOT EXISTS idx_request_logs_prune_ok " + "ON request_logs(created_at) WHERE status_class BETWEEN 1 AND 3;" + ) + await conn.execute( + "CREATE INDEX IF NOT EXISTS idx_request_logs_prune_err " + "ON request_logs(created_at) WHERE status_class = 0 OR status_class >= 4;" + ) + + logger.info("request_logs table ensured (v1.11.0 request/response log)") + except Exception as e: + logger.error(f"Error ensuring request_logs table: {e}") + # Re-raise (ssl_csrs precedent): this step is part of the + # SCHEMA_VERSION=11 bump and the version marker is written only after + # the inner sequence completes cleanly. Swallowing here would stamp + # version 11 with no request_logs table, and the version gate would + # then skip every future retry — permanently. + raise + finally: + if conn: + await close_database_connection(conn) + + +async def ensure_request_log_settings(): + """v1.11.0 — seed the request/response-log retention defaults. + + Runs UNCONDITIONALLY rather than inside an `if not table_exists:` branch, + so an install that already has `system_settings` picks the rows up too. + ON CONFLICT DO NOTHING means an operator's tuning is never overwritten by a + later upgrade. + + Defaults are mirrored in utils/request_log_settings.py; the pair is pinned + by backend/tests/test_request_log_settings.py so they cannot drift apart. + """ + conn = None + try: + conn = await get_database_connection() + await conn.execute(""" + INSERT INTO system_settings (key, value, category, description) VALUES + ('requestlog.enabled', 'true', 'requestlog', 'Master switch for the request/response log'), + ('requestlog.capture_inbound', 'true', 'requestlog', 'Log inbound API calls'), + ('requestlog.capture_outbound', 'true', 'requestlog', 'Log outbound HTTP calls made by the backend'), + ('requestlog.capture_bodies', 'true', 'requestlog', 'Capture redacted, size-capped request/response bodies'), + ('requestlog.capture_get', 'true', 'requestlog', 'Log inbound GET requests'), + ('requestlog.max_body_bytes', '8192', 'requestlog', 'Per-body capture cap in bytes'), + ('requestlog.sample_rate', '1.0', 'requestlog', 'Sampling rate for successful inbound requests (errors always 1.0)'), + ('requestlog.exclude_paths', '["/api/request-logs","/api/health","/api/docs","/api/redoc","/api/openapi.json","/.well-known/acme-challenge","/api/agents/heartbeat","/static","/favicon.ico"]', 'requestlog', 'Path prefixes that are never logged'), + ('requestlog.success_retention_days', '7', 'requestlog', 'Retention for 1xx/2xx/3xx rows, in days'), + ('requestlog.error_retention_days', '30', 'requestlog', 'Retention for 4xx/5xx/transport-error rows, in days'), + ('requestlog.max_rows', '500000', 'requestlog', 'Hard row cap; oldest rows are pruned beyond this'), + ('requestlog.prune_interval_minutes', '60', 'requestlog', 'Minimum interval between retention prune passes') + ON CONFLICT (key) DO NOTHING + """) + logger.info("request_log retention settings seeded (v1.11.0)") + except Exception as e: + logger.error(f"Error seeding request_log settings: {e}") + raise + finally: + if conn: + await close_database_connection(conn) + + async def ensure_mfa_columns(): """Issue #18 — TOTP MFA (v1.6.0): additive columns on users + 3 new tables. @@ -2303,19 +2487,19 @@ async def create_initial_system_data(conn): 'name': 'super_admin', 'display_name': 'Super Administrator', 'description': 'Full system access with all permissions', - 'permissions': ["dashboard.read","dashboard.statistics","frontends.read","frontends.create","frontends.update","frontends.delete","backends.read","backends.create","backends.update","backends.delete","waf.read","waf.create","waf.update","waf.delete","ssl.read","ssl.create","ssl.update","ssl.delete","apply.read","apply.execute","agents.read","agents.create","agents.update","agents.delete","clusters.read","clusters.create","clusters.update","clusters.delete","config.read","config.update","config.bulk_import","config.view_request","config.download_request","users.read","users.create","users.update","users.delete","roles.read","roles.create","roles.update","roles.delete"] + 'permissions': ["dashboard.read","dashboard.statistics","frontends.read","frontends.create","frontends.update","frontends.delete","backends.read","backends.create","backends.update","backends.delete","waf.read","waf.create","waf.update","waf.delete","ssl.read","ssl.create","ssl.update","ssl.delete","apply.read","apply.execute","agents.read","agents.create","agents.update","agents.delete","clusters.read","clusters.create","clusters.update","clusters.delete","config.read","config.update","config.bulk_import","config.view_request","config.download_request","users.read","users.create","users.update","users.delete","roles.read","roles.create","roles.update","roles.delete","requestlog.read","requestlog.manage"] }, { 'name': 'operator', 'display_name': 'Operator', 'description': 'Daily operational access for managing HAProxy configurations', - 'permissions': ["dashboard.read","dashboard.statistics","frontends.read","frontends.create","frontends.update","backends.read","backends.create","backends.update","waf.read","waf.create","waf.update","ssl.read","ssl.create","ssl.update","apply.read","apply.execute","agents.read","clusters.read","config.read","config.update","config.bulk_import","config.view_request","config.download_request"] + 'permissions': ["dashboard.read","dashboard.statistics","frontends.read","frontends.create","frontends.update","backends.read","backends.create","backends.update","waf.read","waf.create","waf.update","ssl.read","ssl.create","ssl.update","apply.read","apply.execute","agents.read","clusters.read","config.read","config.update","config.bulk_import","config.view_request","config.download_request","requestlog.read"] }, { 'name': 'security_admin', 'display_name': 'Security Administrator', 'description': 'Security-focused access for WAF rules and SSL certificates', - 'permissions': ["dashboard.read","frontends.read","backends.read","waf.read","waf.create","waf.update","waf.delete","ssl.read","ssl.create","ssl.update","ssl.delete","apply.read","apply.execute","agents.read","clusters.read","config.read","config.view_request","config.download_request"] + 'permissions': ["dashboard.read","frontends.read","backends.read","waf.read","waf.create","waf.update","waf.delete","ssl.read","ssl.create","ssl.update","ssl.delete","apply.read","apply.execute","agents.read","clusters.read","config.read","config.view_request","config.download_request","requestlog.read","requestlog.manage"] }, { 'name': 'viewer', diff --git a/backend/haproxy_client.py b/backend/haproxy_client.py index 3111a24..0e3f169 100644 --- a/backend/haproxy_client.py +++ b/backend/haproxy_client.py @@ -61,14 +61,27 @@ class HAProxyClient: if self.stats_username and self.stats_password: auth = aiohttp.BasicAuth(self.stats_username, self.stats_password) + # v1.11.0: instrumented for completeness. NOTE the CSV body is + # deliberately NOT handed to the span — a full stats dump is large, + # changes every poll, and has no diagnostic value in an audit row; + # status + duration is what matters. `auth` is likewise never logged: + # aiohttp.BasicAuth is a NamedTuple whose repr contains the cleartext + # password. + from utils.http_instrumentation import outbound_span, TARGET_HAPROXY_STATS + async with aiohttp.ClientSession() as session: - async with session.get(url, auth=auth, timeout=aiohttp.ClientTimeout(total=10)) as response: - if response.status == 200: - csv_data = await response.text() - return self._parse_csv_stats(csv_data) - else: - logger.warning(f"HTTP stats request failed with status {response.status}") - return self._get_fallback_stats() + async with outbound_span( + target=TARGET_HAPROXY_STATS, method="GET", url=url, + capture_body=False, capture_response_body=False, + ) as span: + async with session.get(url, auth=auth, timeout=aiohttp.ClientTimeout(total=10)) as response: + span.set_response(response.status, getattr(response, "headers", None)) + if response.status == 200: + csv_data = await response.text() + return self._parse_csv_stats(csv_data) + else: + logger.warning(f"HTTP stats request failed with status {response.status}") + return self._get_fallback_stats() except Exception as e: logger.error(f"HTTP stats request failed: {e}") return self._get_fallback_stats() diff --git a/backend/main.py b/backend/main.py index 7c87d9a..a5f4318 100644 --- a/backend/main.py +++ b/backend/main.py @@ -29,7 +29,7 @@ for _vpath in [os.path.join(os.path.dirname(__file__), "version.json"), "/app/ve # Import configurations and database -from config import CORS_ORIGINS, REDIS_URL, LOG_LEVEL +from config import CORS_ORIGINS, REDIS_URL, LOG_LEVEL, REQUEST_LOG_ENABLED from database.connection import redis_client, get_database_connection, close_database_connection, init_database_pool, close_database_pool from database.migrations import run_all_migrations @@ -48,6 +48,7 @@ from routers.site_wizard import router as site_wizard_router from routers.mfa import router as mfa_router from routers.vip import router as vip_router # Issue #27 — HA/VIP (Keepalived) management from routers.csr import router as csr_router # v1.9.0 — CSR creation (in-app key+CSR generation, signed-cert import) +from routers.request_logs import router as request_logs_router # v1.11.0 — unified request/response log # Production logging configuration from utils.logging_config import setup_production_logging @@ -56,6 +57,9 @@ from middleware.error_handler import ( GlobalExceptionHandler, get_error_statistics ) from middleware.activity_logger import log_activity_middleware +from middleware.request_logger import RequestResponseLogMiddleware # v1.11.0 +from utils.request_log_settings import refresh_config as refresh_request_log_config +from utils.request_log_sink import request_log_sink # Setup structured logging logger = setup_production_logging(LOG_LEVEL) @@ -842,6 +846,41 @@ async def cleanup_stuck_agent_upgrades(): # Wait 120 seconds (2 minutes) before next check await asyncio.sleep(120) +async def prune_request_logs_loop(): + """v1.11.0 — retention prune for `request_logs`. + + Kept independent of the ACME prune loop on purpose: that one is gated on + the `letsencrypt_orders` table existing, which would silently disable this + prune on an install that never uses ACME. + + The 5-minute tick is only a heartbeat — the real gate is the DB watermark + plus `requestlog.prune_interval_minutes`, so N replicas ticking every 5 + minutes still produce one pass per configured interval. + """ + # Stagger past startup so migrations and the first request burst are done. + await asyncio.sleep(180) + + while True: + try: + conn = await get_database_connection() + try: + table_exists = await conn.fetchval(""" + SELECT EXISTS ( + SELECT 1 FROM information_schema.tables + WHERE table_name = 'request_logs' + ) + """) + finally: + await close_database_connection(conn) + + if table_exists: + from utils.request_log_prune import prune_request_logs_if_due + await prune_request_logs_if_due() + except Exception as e: + logger.error(f"Error in request_logs prune loop: {e}") + + await asyncio.sleep(300) + # Production middleware stack (order matters!) app.add_middleware(PerformanceMonitoringMiddleware, slow_request_threshold_ms=1000) app.add_middleware(RequestLoggingMiddleware, exclude_paths=["/api/health/", "/docs", "/redoc"]) @@ -849,15 +888,35 @@ app.add_middleware(RequestLoggingMiddleware, exclude_paths=["/api/health/", "/do # Activity logging middleware - must be before CORS app.middleware("http")(log_activity_middleware) -# CORS middleware +# CORS middleware app.add_middleware( CORSMiddleware, allow_origins=CORS_ORIGINS, allow_credentials=True, allow_methods=["*"], allow_headers=["*"], + # v1.11.0: without an explicit expose list, browser JS on a cross-origin + # deployment cannot read ANY of these — so an operator could see the + # X-Request-ID in devtools but the app could never quote it back. Same-origin + # (nginx) deployments were already fine; this fixes the split-origin case. + expose_headers=["X-Correlation-ID", "X-Response-Time", "X-Request-ID"], ) +# v1.11.0 — unified request/response log. +# +# MUST be the LAST add_middleware call: Starlette inserts each new middleware at +# index 0, so the last registration ends up OUTERMOST. Outermost is what we want: +# (a) we see the exact status/headers/body the client receives, including the +# JSONResponse that RequestLoggingMiddleware fabricates from an exception +# it swallowed, and +# (b) we seed correlation_id_context BEFORE RequestLoggingMiddleware calls +# get_correlation_id(), so X-Correlation-ID matches request_logs.request_id. +# +# REQUEST_LOG_ENABLED=false keeps it out of the ASGI stack entirely — not a +# runtime branch, genuinely zero overhead. +if REQUEST_LOG_ENABLED: + app.add_middleware(RequestResponseLogMiddleware) + # Global exception handlers from fastapi.exceptions import RequestValidationError from starlette.exceptions import HTTPException as StarletteHTTPException @@ -894,6 +953,7 @@ app.include_router(agent_router) app.include_router(waf_router) app.include_router(ssl_router) app.include_router(csr_router) # v1.9.0: CSR creation (in-app key+CSR generation, signed-cert import) +app.include_router(request_logs_router) # v1.11.0: unified request/response log app.include_router(security_router) app.include_router(configuration_router) app.include_router(settings_router) @@ -1031,6 +1091,17 @@ async def startup_event(): # Decoupled from auto_renew_enabled flag so user-initiated orders also complete. asyncio.create_task(complete_pending_acme_orders()) logger.info("ACME order auto-completion task started (60s checks, replica-safe)") + + # v1.11.0 — request/response log: load the operator's capture/retention + # policy, then start the batching writer and the retention prune. + # Guarded by the env kill-switch so a deployment that turned the log off + # pays for neither task. + if REQUEST_LOG_ENABLED: + await refresh_request_log_config() + asyncio.create_task(request_log_sink.run()) + logger.info("Request/response log sink started (batching writer)") + asyncio.create_task(prune_request_logs_loop()) + logger.info("Request/response log retention prune task started") # Create test activity log entry to verify system is working try: @@ -1059,6 +1130,16 @@ async def shutdown_event(): """Cleanup on shutdown""" logger.info("HAProxy OpenManager API shutting down...") + # v1.11.0: flush queued request-log rows FIRST. The sink's writer is a + # `while True` loop, so it can never satisfy the asyncio.wait below — the + # rows still sitting in its queue would be lost when the pool closes. + try: + flushed = await request_log_sink.flush(timeout=3.0) + if flushed: + logger.info(f"Flushed {flushed} queued request-log row(s)") + except Exception as flush_err: + logger.warning(f"request-log flush skipped: {flush_err}") + # R18c audit fix (round 3 #5): drain pending fire-and-forget # background tasks BEFORE closing the DB pool. The audit # logger middleware (`activity_logger.py`) and the wizard diff --git a/backend/middleware/request_logger.py b/backend/middleware/request_logger.py new file mode 100644 index 0000000..7cfc6ce --- /dev/null +++ b/backend/middleware/request_logger.py @@ -0,0 +1,293 @@ +"""v1.11.0 — inbound half of the unified request/response log. + +Pure ASGI on purpose, NOT BaseHTTPMiddleware: + + * `BaseHTTPMiddleware` hands the response back as a + `starlette.middleware.base._StreamingResponse`, which has no `.body` to + read, and + * `await request.body()` inside a `dispatch()` DRAINS the receive channel. + `POST /api/agents/heartbeat` (routers/agent.py) reads the raw stream + itself, as does the validation-error body preview in + middleware/error_handler.py — draining it here would break both. + +So we never consume anything: we TEE. `receive` and `send` are wrapped, every +message is forwarded verbatim, and a size-capped copy is kept for the log row. +Cost per in-flight request is therefore bounded at ~2 × max_body_bytes (8 KB +by default), not the size of the upload. + +Registration: this MUST be the LAST `app.add_middleware(...)` call, because +Starlette inserts at index 0 — the last registration is the OUTERMOST +middleware. Outermost is what we want: we then see the exact status and body +the client receives (including the JSONResponse that RequestLoggingMiddleware +fabricates out of a swallowed exception), and we can seed +`correlation_id_context` before anything downstream reads it. +""" +import logging +import time +import uuid +from typing import Any, Dict, List, Optional, Tuple + +from starlette.types import ASGIApp, Receive, Scope, Send + +from utils.logging_config import correlation_id_context +from utils.request_log_redaction import is_capturable_content_type, scrub_query_string +from utils.request_log_settings import get_config +from utils.request_log_sink import RequestLogRow, request_id_context, request_log_sink + +logger = logging.getLogger("haproxy_openmanager.request_log") + +# Hard floor, NOT settable away through `requestlog.exclude_paths`. Without it +# an operator who clears the exclude list turns the log viewer into a machine +# that logs itself reading its own logs. +_ALWAYS_EXCLUDED: Tuple[str, ...] = ("/api/request-logs",) + + +def _header(scope: Scope, name: bytes) -> Optional[str]: + for key, value in scope.get("headers") or (): + if key == name: + try: + return value.decode("latin-1") + except Exception: + return None + return None + + +def _identify(scope: Scope) -> Tuple[Optional[int], Optional[str]]: + """Resolve the caller from the JWT locally — NO database round-trip. + + `log_activity_middleware` already pays a `SELECT ... FROM users` per + non-GET request; this middleware runs on every request including GETs, so a + second lookup per call is not acceptable. The token issued at + routers/auth.py carries both `user_id` and `username`, which is everything + the log row needs. + + A token that fails to decode simply yields (None, None): this is a logging + path, not an authorization path — the real auth check still runs + downstream. + """ + raw = _header(scope, b"authorization") + if not raw: + return None, None + token = raw[7:].strip() if raw.lower().startswith("bearer ") else raw.strip() + if not token or token in ("null", "undefined") or token.count(".") != 2: + return None, None + try: + from jose import jwt + from config import JWT_SECRET_KEY, JWT_ALGORITHM + + payload = jwt.decode(token, JWT_SECRET_KEY, algorithms=[JWT_ALGORITHM]) + except Exception: + return None, None + + raw_uid = payload.get("user_id") or payload.get("sub") + try: + user_id = int(raw_uid) if raw_uid is not None else None + except (TypeError, ValueError): + user_id = None + username = payload.get("username") + return user_id, (str(username) if username else None) + + +def _client_ip(scope: Scope) -> Optional[str]: + """The peer address only. + + `request_logs.client_ip` is an INET column, so a comma-joined + X-Forwarded-For string would raise on INSERT (the same trap as + `user_activity_logs.ip_address`). The XFF header is still captured — it is + on the header allowlist — so the original client is not lost behind a proxy. + """ + client = scope.get("client") + if not client: + return None + try: + return str(client[0]) + except Exception: + return None + + +class RequestResponseLogMiddleware: + def __init__(self, app: ASGIApp): + self.app = app + + async def __call__(self, scope: Scope, receive: Receive, send: Send) -> None: + if scope.get("type") != "http": + await self.app(scope, receive, send) + return + + cfg = get_config() + path = scope.get("path", "") or "" + method = scope.get("method", "") or "" + + if ( + not cfg.enabled + or not cfg.capture_inbound + # OPTIONS never reaches a handler — CORSMiddleware short-circuits + # it below us — and a preflight carries no information worth a row. + or method == "OPTIONS" + or (method == "GET" and not cfg.capture_get) + or any(path.startswith(prefix) for prefix in _ALWAYS_EXCLUDED) + or any(path.startswith(prefix) for prefix in cfg.exclude_paths) + ): + await self.app(scope, receive, send) + return + + request_id = uuid.uuid4().hex + # Seed the id BEFORE the downstream app runs so error_handler's + # get_correlation_id() adopts ours instead of minting a second one; the + # X-Correlation-ID header then matches request_logs.request_id. + cid_token = correlation_id_context.set(request_id[:8]) + rid_token = request_id_context.set(request_id) + + cap = cfg.max_body_bytes if cfg.capture_bodies else 0 + req_ctype = _header(scope, b"content-type") + req_capturable = is_capturable_content_type(req_ctype) + + req_buf = bytearray() + res_buf = bytearray() + state = { + "req_bytes": 0, + "res_bytes": 0, + "status": None, + "res_headers": {}, + "res_ctype": None, + "res_capturable": True, + } + + async def tee_receive() -> Dict[str, Any]: + message = await receive() + try: + if message.get("type") == "http.request": + chunk = message.get("body", b"") or b"" + state["req_bytes"] += len(chunk) + if cap and req_capturable and len(req_buf) < cap: + req_buf.extend(chunk[: cap - len(req_buf)]) + except Exception: + pass + return message # forwarded verbatim, always + + async def tee_send(message: Dict[str, Any]) -> None: + try: + mtype = message.get("type") + if mtype == "http.response.start": + state["status"] = message.get("status") + raw_headers: List[Tuple[bytes, bytes]] = message.get("headers") or [] + headers = {} + for key, value in raw_headers: + try: + headers[key.decode("latin-1").lower()] = value.decode("latin-1") + except Exception: + continue + state["res_headers"] = headers + state["res_ctype"] = headers.get("content-type") + state["res_capturable"] = is_capturable_content_type(state["res_ctype"]) + # Hand the id to the client so a user reporting a problem can + # quote it and an operator can find the exact row. + if isinstance(raw_headers, list): + raw_headers.append((b"x-request-id", request_id.encode("latin-1"))) + elif mtype == "http.response.body": + chunk = message.get("body", b"") or b"" + state["res_bytes"] += len(chunk) + if cap and state["res_capturable"] and len(res_buf) < cap: + res_buf.extend(chunk[: cap - len(res_buf)]) + except Exception: + pass + await send(message) # forwarded verbatim, always + + started = time.perf_counter() + error_text: Optional[str] = None + try: + await self.app(scope, tee_receive, tee_send) + except Exception as exc: + # Almost never taken: RequestLoggingMiddleware sits below us and + # converts exceptions into a JSONResponse first. It IS taken for + # paths on that middleware's own exclude list, so the row still has + # to be recorded before the exception continues upward. + error_text = f"{type(exc).__name__}: {exc}"[:2000] + raise + finally: + duration_ms = int((time.perf_counter() - started) * 1000) + try: + self._record( + scope=scope, + request_id=request_id, + method=method, + path=path, + duration_ms=duration_ms, + status=state["status"], + req_buf=bytes(req_buf), + req_bytes=state["req_bytes"], + req_ctype=req_ctype, + res_buf=bytes(res_buf), + res_bytes=state["res_bytes"], + res_ctype=state["res_ctype"], + res_headers=state["res_headers"], + error_text=error_text, + ) + except Exception as exc: # pragma: no cover - defensive + logger.debug(f"request_log: failed to record inbound row: {exc}") + try: + correlation_id_context.reset(cid_token) + request_id_context.reset(rid_token) + except Exception: + pass + + @staticmethod + def _record( + *, + scope: Scope, + request_id: str, + method: str, + path: str, + duration_ms: int, + status: Optional[int], + req_buf: bytes, + req_bytes: int, + req_ctype: Optional[str], + res_buf: bytes, + res_bytes: int, + res_ctype: Optional[str], + res_headers: Dict[str, str], + error_text: Optional[str], + ) -> None: + raw_query = scope.get("query_string") or b"" + try: + query = raw_query.decode("latin-1") + except Exception: + query = "" + scrubbed_query, query_params = scrub_query_string(query) + + user_id, username = _identify(scope) + + req_headers = {} + for key, value in scope.get("headers") or (): + try: + req_headers[key.decode("latin-1").lower()] = value.decode("latin-1") + except Exception: + continue + + request_log_sink.offer( + RequestLogRow( + request_id=request_id, + direction="inbound", + method=method, + url=path + (("?" + scrubbed_query) if scrubbed_query else ""), + path=path, + query_string=scrubbed_query or None, + query_params=query_params, + status_code=status, + duration_ms=duration_ms, + user_id=user_id, + username=username, + client_ip=_client_ip(scope), + user_agent=req_headers.get("user-agent"), + request_headers=req_headers or None, + response_headers=res_headers or None, + request_body_raw=req_buf or None, + request_body_bytes=req_bytes, + request_content_type=req_ctype, + response_body_raw=res_buf or None, + response_body_bytes=res_bytes, + response_content_type=res_ctype, + error=error_text, + ) + ) diff --git a/backend/routers/letsencrypt.py b/backend/routers/letsencrypt.py index 4978fb5..e143a2c 100644 --- a/backend/routers/letsencrypt.py +++ b/backend/routers/letsencrypt.py @@ -926,12 +926,22 @@ async def import_le_ca_chain(authorization: str = Header(None)): ("https://letsencrypt.org/certs/r11.pem", "R11 Intermediate"), ] chain_parts = [] + # v1.11.0: each download is recorded as an outbound row. The bodies are + # public CA certificates, not secrets, and the 8 KB body cap truncates them — + # what matters here is which URL failed, with what status. + from utils.http_instrumentation import outbound_span, TARGET_LETSENCRYPT_CA + async with aiohttp.ClientSession() as session: for url, name in ca_urls: try: - async with session.get(url, timeout=aiohttp.ClientTimeout(total=10)) as resp: - if resp.status == 200: - chain_parts.append(await resp.text()) + async with outbound_span( + target=TARGET_LETSENCRYPT_CA, method="GET", url=url + ) as span: + async with session.get(url, timeout=aiohttp.ClientTimeout(total=10)) as resp: + text = await resp.text() if resp.status == 200 else None + span.set_response(resp.status, getattr(resp, "headers", None), text) + if resp.status == 200: + chain_parts.append(text) except Exception as e: logger.warning(f"Failed to download {name}: {e}") diff --git a/backend/routers/request_logs.py b/backend/routers/request_logs.py new file mode 100644 index 0000000..7ba6a35 --- /dev/null +++ b/backend/routers/request_logs.py @@ -0,0 +1,489 @@ +"""v1.11.0 — the read/administration API for the unified request/response log. + +Endpoints (declaration order matters — see below): + + GET /api/request-logs/settings requestlog.manage + PUT /api/request-logs/settings requestlog.manage + GET /api/request-logs/stats requestlog.read + POST /api/request-logs/purge requestlog.manage + GET /api/request-logs requestlog.read + GET /api/request-logs/{log_id} requestlog.read + +`/{log_id}` is a single-segment path, so FastAPI — which matches in declaration +order — would shadow `/settings`, `/stats` and `/purge` if it came first. The +literals are therefore declared before it. (This is the mirror image of the +trap in routers/settings.py, where `GET /{category}` sits at the top of the +file and swallows every literal route added after it.) + +Settings are stored in `system_settings` under the `requestlog` category, so +`GET /api/settings/requestlog` still reads them, but writes go through THIS +router: the generic `PUT /api/settings/{category}` stringifies values with +`str(value)`, which turns `True` into `'True'` — not valid JSON, and the +`::jsonb` cast then fails. +""" +import json +import logging +from datetime import datetime +from typing import Any, Dict, List, Optional + +from fastapi import APIRouter, Header, HTTPException, Query +from pydantic import BaseModel, Field, field_validator + +from auth_middleware import check_user_permission, get_current_user_from_token +from database.connection import get_database_connection, close_database_connection +from utils.request_log_settings import ( + DEFAULT_CONFIG, + DEFAULT_EXCLUDE_PATHS, + MAX_EXCLUDE_PATHS, + MAX_EXCLUDE_PATH_LENGTH, + SETTINGS_CATEGORY, + config_from_mapping, + get_config, + load_settings_rows, + refresh_config, + set_config, +) +from utils.request_log_sink import request_log_sink + +logger = logging.getLogger(__name__) + +router = APIRouter(prefix="/api/request-logs", tags=["Request Logs"]) + +# Columns returned by the list endpoint. Bodies and headers are detail-only: +# a 200-row page carrying two 8 KB JSONB blobs per row is a 3 MB response. +_LIST_COLUMNS = """ + id, request_id, direction, target, method, url, path, status_code, + status_class, duration_ms, user_id, username, host(client_ip) AS client_ip, + error, request_body_bytes, response_body_bytes, truncated, created_at +""" + +_JSONB_COLUMNS = ("query_params", "request_headers", "request_body", + "response_headers", "response_body") + + +class RequestLogSettings(BaseModel): + """Operator-tunable capture + retention policy.""" + + enabled: bool = True + capture_inbound: bool = True + capture_outbound: bool = True + capture_bodies: bool = True + capture_get: bool = True + max_body_bytes: int = Field(8192, ge=0, le=262144) + sample_rate: float = Field(1.0, ge=0.0, le=1.0) + exclude_paths: List[str] = Field( + default_factory=lambda: list(DEFAULT_EXCLUDE_PATHS), + max_length=MAX_EXCLUDE_PATHS, + ) + success_retention_days: int = Field(7, ge=1, le=365) + error_retention_days: int = Field(30, ge=1, le=365) + max_rows: int = Field(500000, ge=1000, le=50_000_000) + prune_interval_minutes: int = Field(60, ge=5, le=1440) + + @field_validator("exclude_paths") + @classmethod + def _validate_paths(cls, value: List[str]) -> List[str]: + for entry in value: + if not entry.startswith("/"): + raise ValueError("exclude_paths entries must start with '/'") + if len(entry) > MAX_EXCLUDE_PATH_LENGTH: + raise ValueError( + f"exclude_paths entries must be <= {MAX_EXCLUDE_PATH_LENGTH} characters" + ) + return value + + +async def _require(authorization: Optional[str], action: str) -> Dict[str, Any]: + """Authenticate, then enforce `requestlog.`. + + `current_user=` is passed through so the admin bypass in + check_user_permission short-circuits without a second DB round-trip. + """ + current_user = await get_current_user_from_token(authorization) + allowed = await check_user_permission( + current_user["id"], "requestlog", action, current_user=current_user + ) + if not allowed: + raise HTTPException( + status_code=403, + detail=f"Insufficient permissions: requestlog.{action} required", + ) + return current_user + + +async def _can_manage(current_user: Dict[str, Any]) -> bool: + return await check_user_permission( + current_user["id"], "requestlog", "manage", current_user=current_user + ) + + +def _parse_jsonb(value: Any) -> Any: + """asyncpg has no JSONB codec on this pool, so JSONB comes back as raw + text. This router is a new contract, so it parses server-side and returns + real JSON rather than pushing a JSON.parse() into the UI.""" + if isinstance(value, str): + try: + return json.loads(value) + except (json.JSONDecodeError, ValueError): + return value + return value + + +def _row_to_dict(row) -> Dict[str, Any]: + out = dict(row) + for key in _JSONB_COLUMNS: + if key in out: + out[key] = _parse_jsonb(out[key]) + created = out.get("created_at") + if isinstance(created, datetime): + out["created_at"] = created.isoformat() + return out + + +# --------------------------------------------------------------------------- +# Literal paths FIRST — see the module docstring. +# --------------------------------------------------------------------------- + + +@router.get("/settings") +async def get_request_log_settings(authorization: Optional[str] = Header(None)): + """Current capture + retention policy, plus the shipped defaults so the UI + can offer a 'reset' without hardcoding them.""" + await _require(authorization, "manage") + + conn = None + try: + conn = await get_database_connection() + values = await load_settings_rows(conn) + config = config_from_mapping(values) if values else DEFAULT_CONFIG + return { + "settings": config.as_dict(), + "defaults": DEFAULT_CONFIG.as_dict(), + "category": SETTINGS_CATEGORY, + } + except HTTPException: + raise + except Exception as e: + logger.error(f"Error fetching request log settings: {e}") + raise HTTPException(status_code=500, detail="Failed to fetch request log settings") + finally: + if conn is not None: + await close_database_connection(conn) + + +@router.put("/settings") +async def update_request_log_settings( + body: RequestLogSettings, + authorization: Optional[str] = Header(None), +): + """Persist the policy and apply it immediately. + + `refresh_config()` at the end is what makes an operator's change take + effect on the very next request instead of up to 30 seconds later, when + the writer loop would otherwise pick it up. + """ + current_user = await _require(authorization, "manage") + + conn = None + try: + conn = await get_database_connection() + updated = [] + for suffix, value in body.model_dump().items(): + await conn.execute( + """ + INSERT INTO system_settings (key, value, category, updated_at, updated_by) + VALUES ($1, $2::jsonb, $3, $4, $5) + ON CONFLICT (key) DO UPDATE SET + value = EXCLUDED.value, + updated_at = EXCLUDED.updated_at, + updated_by = EXCLUDED.updated_by + """, + f"{SETTINGS_CATEGORY}.{suffix}", + json.dumps(value), + SETTINGS_CATEGORY, + datetime.utcnow(), + current_user.get("id"), + ) + updated.append(suffix) + + # Apply in-process right away, then re-read so this worker's snapshot + # is exactly what is on disk. + set_config(config_from_mapping(body.model_dump())) + await refresh_config() + + logger.info( + f"Request log settings updated by {current_user.get('username')}: {len(updated)} keys" + ) + return {"message": f"Updated {len(updated)} settings", "settings": get_config().as_dict()} + except HTTPException: + raise + except Exception as e: + logger.error(f"Error updating request log settings: {e}") + raise HTTPException(status_code=500, detail="Failed to update request log settings") + finally: + if conn is not None: + await close_database_connection(conn) + + +@router.get("/stats") +async def get_request_log_stats( + authorization: Optional[str] = Header(None), + hours: int = Query(24, ge=1, le=720), +): + """Volume and error breakdown over a window, plus table-level totals and + this worker's sink counters (so a saturated queue is visible).""" + await _require(authorization, "read") + + conn = None + try: + conn = await get_database_connection() + + by_direction = await conn.fetch( + """ + SELECT direction, + COUNT(*) AS total, + COUNT(*) FILTER (WHERE status_class = 0 OR status_class >= 4) AS errors, + COALESCE(ROUND(AVG(duration_ms))::int, 0) AS avg_duration_ms, + COALESCE(MAX(duration_ms), 0) AS max_duration_ms + FROM request_logs + WHERE created_at > NOW() - ($1 || ' hours')::INTERVAL + GROUP BY direction + """, + str(hours), + ) + + by_status = await conn.fetch( + """ + SELECT status_class, COUNT(*) AS total + FROM request_logs + WHERE created_at > NOW() - ($1 || ' hours')::INTERVAL + GROUP BY status_class + ORDER BY status_class + """, + str(hours), + ) + + by_target = await conn.fetch( + """ + SELECT target, + COUNT(*) AS total, + COUNT(*) FILTER (WHERE status_class = 0 OR status_class >= 4) AS errors + FROM request_logs + WHERE target IS NOT NULL + AND created_at > NOW() - ($1 || ' hours')::INTERVAL + GROUP BY target + ORDER BY total DESC + LIMIT 20 + """, + str(hours), + ) + + totals = await conn.fetchrow( + "SELECT COUNT(*) AS total_rows, MIN(created_at) AS oldest_at, " + "MAX(created_at) AS newest_at FROM request_logs" + ) + + return { + "window_hours": hours, + "by_direction": [dict(r) for r in by_direction], + "by_status_class": [dict(r) for r in by_status], + "by_target": [dict(r) for r in by_target], + "total_rows": (totals or {}).get("total_rows", 0), + "oldest_at": totals["oldest_at"].isoformat() if totals and totals["oldest_at"] else None, + "newest_at": totals["newest_at"].isoformat() if totals and totals["newest_at"] else None, + "sink": request_log_sink.stats, + "retention": { + "success_retention_days": get_config().success_retention_days, + "error_retention_days": get_config().error_retention_days, + "max_rows": get_config().max_rows, + }, + } + except HTTPException: + raise + except Exception as e: + logger.error(f"Error fetching request log stats: {e}") + raise HTTPException(status_code=500, detail="Failed to fetch request log stats") + finally: + if conn is not None: + await close_database_connection(conn) + + +@router.post("/purge") +async def purge_request_logs(authorization: Optional[str] = Header(None)): + """Run a retention pass now, ignoring the watermark. + + This applies the CONFIGURED retention — it is not a 'delete everything' + button. It exists so an operator who has just lowered the retention does + not have to wait for the next scheduled pass to reclaim the space. + """ + current_user = await _require(authorization, "manage") + from utils.request_log_prune import prune_request_logs_if_due + + counts = await prune_request_logs_if_due(force=True) + logger.info(f"Manual request log purge by {current_user.get('username')}: {counts}") + return { + "message": "Retention pass completed", + "removed": { + "success": counts.get("success", 0), + "error": counts.get("error", 0), + "overflow": counts.get("overflow", 0), + }, + "ran": bool(counts.get("ran")), + } + + +# --------------------------------------------------------------------------- +# List, then the catch-all detail route LAST. +# --------------------------------------------------------------------------- + + +@router.get("") +async def list_request_logs( + authorization: Optional[str] = Header(None), + direction: Optional[str] = Query(None, pattern="^(inbound|outbound)$"), + status_class: Optional[int] = Query(None, ge=0, le=5), + method: Optional[str] = Query(None, max_length=10), + target: Optional[str] = Query(None, max_length=32), + user_id: Optional[int] = Query(None, ge=1), + path_prefix: Optional[str] = Query(None, max_length=200), + q: Optional[str] = Query(None, max_length=200), + request_id: Optional[str] = Query(None, max_length=64), + errors_only: bool = Query(False), + since: Optional[datetime] = Query(None), + until: Optional[datetime] = Query(None), + min_duration_ms: Optional[int] = Query(None, ge=0), + limit: int = Query(50, ge=1, le=500), + offset: int = Query(0, ge=0), +): + """Filtered, server-paginated list. Bodies are not included — use the + detail endpoint for those.""" + current_user = await _require(authorization, "read") + can_manage = await _can_manage(current_user) + + where: List[str] = [] + params: List[Any] = [] + + def add(clause_template: str, value: Any) -> None: + params.append(value) + where.append(clause_template.format(n=len(params))) + + if direction: + add("direction = ${n}", direction) + if status_class is not None: + add("status_class = ${n}", status_class) + if method: + add("method = ${n}", method.upper()) + if target: + add("target = ${n}", target) + if user_id is not None: + add("user_id = ${n}", user_id) + if path_prefix: + add("path LIKE ${n} || '%'", path_prefix) + if q: + # Substring search has no index to lean on; it is the deliberately slow + # filter and should be combined with a time window. + add("url ILIKE '%' || ${n} || '%'", q) + if request_id: + add("request_id = ${n}", request_id) + if errors_only: + where.append("(status_class = 0 OR status_class >= 4)") + if since: + add("created_at >= ${n}", since) + if until: + add("created_at <= ${n}", until) + if min_duration_ms is not None: + add("duration_ms >= ${n}", min_duration_ms) + + # Self-scoping. Captured bodies are a broader disclosure surface than the + # existing activity log, so a caller holding only `requestlog.read` sees + # their OWN inbound requests and nothing else. `requestlog.manage` (and the + # is_admin bypass inside it) lifts the restriction. + if not can_manage: + params.append(current_user["id"]) + where.append(f"(direction = 'inbound' AND user_id = ${len(params)})") + + where_sql = (" WHERE " + " AND ".join(where)) if where else "" + + conn = None + try: + conn = await get_database_connection() + + rows = await conn.fetch( + f"SELECT {_LIST_COLUMNS} FROM request_logs{where_sql} " + f"ORDER BY id DESC LIMIT ${len(params) + 1} OFFSET ${len(params) + 2}", + *params, limit, offset, + ) + + # Bounded count: an unfiltered COUNT(*) over a multi-million-row table + # is a sequential scan on every page change. Cap it and tell the client + # the number is a floor. + count_cap = 10001 + counted = await conn.fetchval( + f"SELECT COUNT(*) FROM (SELECT 1 FROM request_logs{where_sql} LIMIT {count_cap}) t", + *params, + ) + total = int(counted or 0) + + return { + "logs": [_row_to_dict(r) for r in rows], + "total": total, + "total_is_estimate": total >= count_cap, + "limit": limit, + "offset": offset, + "scoped_to_self": not can_manage, + } + except HTTPException: + raise + except Exception as e: + logger.error(f"Error listing request logs: {e}") + raise HTTPException(status_code=500, detail="Failed to list request logs") + finally: + if conn is not None: + await close_database_connection(conn) + + +@router.get("/{log_id}") +async def get_request_log(log_id: int, authorization: Optional[str] = Header(None)): + """One exchange in full, plus every other row sharing its `request_id`. + + That `related` list is the point of the feature: one inbound API call and + the ACME / DNS / agent calls it triggered read as a single trace. + """ + current_user = await _require(authorization, "read") + can_manage = await _can_manage(current_user) + + conn = None + try: + conn = await get_database_connection() + row = await conn.fetchrow( + "SELECT *, host(client_ip) AS client_ip_text FROM request_logs WHERE id = $1", + log_id, + ) + if not row: + raise HTTPException(status_code=404, detail="Request log entry not found") + + record = _row_to_dict(row) + record["client_ip"] = record.pop("client_ip_text", None) + + if not can_manage and not ( + record.get("direction") == "inbound" and record.get("user_id") == current_user["id"] + ): + # Same self-scoping rule as the list endpoint. 404 rather than 403 + # so the endpoint does not confirm that a given id exists. + raise HTTPException(status_code=404, detail="Request log entry not found") + + related = await conn.fetch( + f"SELECT {_LIST_COLUMNS} FROM request_logs " + "WHERE request_id = $1 AND id <> $2 ORDER BY id ASC LIMIT 100", + record["request_id"], log_id, + ) + + return {"log": record, "related": [_row_to_dict(r) for r in related]} + except HTTPException: + raise + except Exception as e: + logger.error(f"Error fetching request log {log_id}: {e}") + raise HTTPException(status_code=500, detail="Failed to fetch request log entry") + finally: + if conn is not None: + await close_database_connection(conn) diff --git a/backend/routers/settings.py b/backend/routers/settings.py index 74f9aa2..ceb8266 100644 --- a/backend/routers/settings.py +++ b/backend/routers/settings.py @@ -121,26 +121,35 @@ async def test_acme_connection(authorization: str = Header(None), directory_url: _KNOWN_ACME_FIELDS = ["newNonce", "newAccount", "newOrder", "newAuthz", "revokeCert", "keyChange"] try: import aiohttp + # v1.11.0: this handler returns str(e) to the caller and logs nothing — + # the span gives the failed probe a durable record. + from utils.http_instrumentation import outbound_span, TARGET_SETTINGS_PROBE + async with aiohttp.ClientSession(connector=safe_connector()) as session: - async with session.get( - directory_url, - timeout=aiohttp.ClientTimeout(total=10), - allow_redirects=False, - ) as resp: - if resp.status == 200: - data = await resp.json(content_type=None) - if not isinstance(data, dict): - return {"success": False, "error": "Directory URL did not return a JSON object"} - present = [k for k in _KNOWN_ACME_FIELDS if k in data] - if not present: - return {"success": False, "error": "Response is not a valid ACME directory"} - return { - "success": True, - "directory": directory_url, - "endpoints": present, - } - else: - return {"success": False, "error": f"HTTP {resp.status} from directory URL"} + async with outbound_span( + target=TARGET_SETTINGS_PROBE, method="GET", url=directory_url + ) as span: + async with session.get( + directory_url, + timeout=aiohttp.ClientTimeout(total=10), + allow_redirects=False, + ) as resp: + if resp.status == 200: + data = await resp.json(content_type=None) + span.set_response(resp.status, getattr(resp, "headers", None), data) + if not isinstance(data, dict): + return {"success": False, "error": "Directory URL did not return a JSON object"} + present = [k for k in _KNOWN_ACME_FIELDS if k in data] + if not present: + return {"success": False, "error": "Response is not a valid ACME directory"} + return { + "success": True, + "directory": directory_url, + "endpoints": present, + } + else: + span.set_response(resp.status, getattr(resp, "headers", None)) + return {"success": False, "error": f"HTTP {resp.status} from directory URL"} except HTTPException: raise except Exception as e: diff --git a/backend/services/acme_diagnostics.py b/backend/services/acme_diagnostics.py index 8154a83..3ffa490 100644 --- a/backend/services/acme_diagnostics.py +++ b/backend/services/acme_diagnostics.py @@ -398,12 +398,23 @@ async def check_port80(domains: List[str], *, http_timeout: float = 5.0) -> Dict continue url = f"http://{d}/.well-known/acme-challenge/diagnostic-probe" try: - async with session.head(url, allow_redirects=False) as resp: - targets.append({ - "domain": d, - "status": resp.status, - "ok": resp.status in (200, 404), - }) + # v1.11.0: recorded as an outbound row so a failing port-80 probe + # is diagnosable after the fact, not only while the panel is open. + # HEAD, so there is no request body to capture. + from utils.http_instrumentation import outbound_span, TARGET_ACME_DIAG + + async with outbound_span( + target=TARGET_ACME_DIAG, method="HEAD", url=url, capture_body=False + ) as span: + async with session.head(url, allow_redirects=False) as resp: + # getattr, not resp.headers: this probe is driven in tests + # by a minimal fake response that only exposes `.status`. + span.set_response(resp.status, getattr(resp, "headers", None)) + targets.append({ + "domain": d, + "status": resp.status, + "ok": resp.status in (200, 404), + }) except asyncio.TimeoutError: targets.append({"domain": d, "error": "egress timeout", "warn": True}) skip_reason = "egress timeout" diff --git a/backend/services/acme_service.py b/backend/services/acme_service.py index 3ab7020..782480a 100644 --- a/backend/services/acme_service.py +++ b/backend/services/acme_service.py @@ -75,16 +75,23 @@ class ACMEService: from utils.ssrf_guard import assert_public_url, safe_connector await assert_public_url(directory_url) - async with aiohttp.ClientSession(connector=safe_connector()) as session: - async with session.get(directory_url, timeout=aiohttp.ClientTimeout(total=15), allow_redirects=False) as resp: - if resp.status != 200: - raise Exception(f"Failed to fetch ACME directory: HTTP {resp.status}") - data = await resp.json() - if 'Replay-Nonce' in resp.headers: - self._nonce_by_dir[directory_url] = resp.headers['Replay-Nonce'] - data['_fetched_at'] = time.time() - self._directory_cache[directory_url] = data - return data + # v1.11.0: recorded in request_logs as an outbound call so an operator + # can see exactly which CA was contacted and what it answered. + from utils.http_instrumentation import outbound_span, TARGET_ACME + + async with outbound_span(target=TARGET_ACME, method="GET", url=directory_url) as span: + async with aiohttp.ClientSession(connector=safe_connector()) as session: + async with session.get(directory_url, timeout=aiohttp.ClientTimeout(total=15), allow_redirects=False) as resp: + if resp.status != 200: + span.set_response(resp.status, dict(resp.headers)) + raise Exception(f"Failed to fetch ACME directory: HTTP {resp.status}") + data = await resp.json() + span.set_response(resp.status, dict(resp.headers), data) + if 'Replay-Nonce' in resp.headers: + self._nonce_by_dir[directory_url] = resp.headers['Replay-Nonce'] + data['_fetched_at'] = time.time() + self._directory_cache[directory_url] = data + return data async def _get_nonce(self, directory_url: str) -> str: # Use a cached nonce for THIS CA only; otherwise fetch a fresh one from THIS CA's newNonce. @@ -104,9 +111,19 @@ class ACMEService: from utils.ssrf_guard import assert_public_url, safe_connector nonce_url = directory['newNonce'] await assert_public_url(nonce_url) - async with aiohttp.ClientSession(connector=safe_connector()) as session: - async with session.head(nonce_url, timeout=aiohttp.ClientTimeout(total=15), allow_redirects=False) as resp: - return resp.headers['Replay-Nonce'] + + # v1.11.0: a HEAD with no body and no status check — capture the status + # and the allowlisted headers only. `Replay-Nonce` itself is redacted by + # the header rules: it is a single-use credential. + from utils.http_instrumentation import outbound_span, TARGET_ACME + + async with outbound_span( + target=TARGET_ACME, method="HEAD", url=nonce_url, capture_body=False + ) as span: + async with aiohttp.ClientSession(connector=safe_connector()) as session: + async with session.head(nonce_url, timeout=aiohttp.ClientTimeout(total=15), allow_redirects=False) as resp: + span.set_response(resp.status, dict(resp.headers)) + return resp.headers['Replay-Nonce'] def _generate_account_key(self) -> Tuple[str, dict]: private_key = rsa.generate_private_key( @@ -208,46 +225,75 @@ class ACMEService: from utils.ssrf_guard import assert_public_url, safe_connector await assert_public_url(url) + # v1.11.0: instrument each ATTEMPT separately (the span goes inside the + # retry loop, the session stays outside it) so a badNonce retry shows up + # as its own row instead of being folded into the successful one. + # + # capture_body=False is mandatory here. The JWS body is + # {protected, payload, signature}: `protected` carries the nonce and the + # account kid/jwk, and `signature` is made with the account private key. + # The key itself never crosses the wire, but a stored (protected, + # signature) pair is a REPLAYABLE ACME credential for the lifetime of the + # nonce. We log a description of the request instead of the request. + from utils.http_instrumentation import outbound_span, TARGET_ACME + async with aiohttp.ClientSession(connector=safe_connector()) as session: for attempt in range(3): - async with session.post( - url, - json=body, - headers={"Content-Type": "application/jose+json"}, - timeout=aiohttp.ClientTimeout(total=30), - allow_redirects=False, - ) as resp: - if 'Replay-Nonce' in resp.headers: - self._nonce_by_dir[directory_url] = resp.headers['Replay-Nonce'] + jws_summary = { + "jws": True, + "acme_url": protected.get("url"), + "kid_present": bool(protected.get("kid")), + "jwk_present": bool(protected.get("jwk")), + "payload_empty": payload == "", + "attempt": attempt + 1, + } + async with outbound_span( + target=TARGET_ACME, + method="POST", + url=url, + request_body=jws_summary, + capture_body=False, + ) as span: + async with session.post( + url, + json=body, + headers={"Content-Type": "application/jose+json"}, + timeout=aiohttp.ClientTimeout(total=30), + allow_redirects=False, + ) as resp: + if 'Replay-Nonce' in resp.headers: + self._nonce_by_dir[directory_url] = resp.headers['Replay-Nonce'] - if resp.status == 400 and attempt < 2: - err = await resp.json() - etype = (err.get('type') or '') - edetail = (err.get('detail') or '').lower() - # Retry on badNonce, and on any nonce-related malformed rejection (e.g. - # "The Replay Nonce could not be base64url-decoded") — refetch a FRESH nonce - # from the target CA and resign. With per-CA scoping the cross-CA cause is gone; - # this is defense-in-depth so a stale/rejected nonce always self-heals. - if etype.endswith('badNonce') or 'nonce' in edetail: - nonce = resp.headers.get('Replay-Nonce') or await self._get_nonce(directory_url) - protected['nonce'] = nonce - body = self._sign_jws(private_key, protected, payload) - continue + if resp.status == 400 and attempt < 2: + err = await resp.json() + etype = (err.get('type') or '') + edetail = (err.get('detail') or '').lower() + # Retry on badNonce, and on any nonce-related malformed rejection (e.g. + # "The Replay Nonce could not be base64url-decoded") — refetch a FRESH nonce + # from the target CA and resign. With per-CA scoping the cross-CA cause is gone; + # this is defense-in-depth so a stale/rejected nonce always self-heals. + if etype.endswith('badNonce') or 'nonce' in edetail: + span.set_response(resp.status, dict(resp.headers), err) + nonce = resp.headers.get('Replay-Nonce') or await self._get_nonce(directory_url) + protected['nonce'] = nonce + body = self._sign_jws(private_key, protected, payload) + continue - resp_data = {} - content_type = resp.headers.get('Content-Type', '') - if 'json' in content_type: - resp_data = await resp.json() - elif resp.status < 300: - text = await resp.text() - if text: - try: - resp_data = json.loads(text) - except json.JSONDecodeError: - resp_data = {"raw": text} + resp_data = {} + content_type = resp.headers.get('Content-Type', '') + if 'json' in content_type: + resp_data = await resp.json() + elif resp.status < 300: + text = await resp.text() + if text: + try: + resp_data = json.loads(text) + except json.JSONDecodeError: + resp_data = {"raw": text} - headers = dict(resp.headers) - return resp.status, resp_data, headers + headers = dict(resp.headers) + span.set_response(resp.status, headers, resp_data) + return resp.status, resp_data, headers raise Exception(f"ACME request to {url} failed after retries") diff --git a/backend/services/dns_providers/cloudflare.py b/backend/services/dns_providers/cloudflare.py index 775122c..7457562 100644 --- a/backend/services/dns_providers/cloudflare.py +++ b/backend/services/dns_providers/cloudflare.py @@ -73,26 +73,42 @@ class CloudflareDNSProvider(DnsProvider): """One Cloudflare API call. Returns the parsed JSON body. Raises a SANITIZED DnsProviderError on transport/HTTP/API error (never echoes the token or raw headers).""" url = f"{CLOUDFLARE_API_BASE}{path}" + # v1.11.0: single funnel for every Cloudflare call, so instrumenting here + # covers all five logical endpoints. `safe_error_only=True` records only + # the exception TYPE — the same stance the handlers below already take, + # because a raw message can carry the request URL and through it the zone + # identifier. The Authorization header is dropped to a presence marker by + # the header allowlist. + from utils.http_instrumentation import outbound_span, TARGET_DNS_CLOUDFLARE + try: - async with session.request( - method, url, headers=self._headers(), allow_redirects=False, **kwargs - ) as resp: - try: - body = await resp.json() - except Exception: # noqa: BLE001 - body = {} - if resp.status in (401, 403): - raise DnsProviderError("Cloudflare rejected the API token (check it has Zone:DNS:Edit + Zone:Read).") - if resp.status >= 400 or not body.get("success", False): - # Cloudflare returns {"errors":[{"code":..,"message":..}]} — surface only the - # human message text, never the request (which carries the token header). - msgs = "; ".join( - str(e.get("message")) for e in (body.get("errors") or []) if e.get("message") - ) - raise DnsProviderError( - f"Cloudflare API error (HTTP {resp.status}){': ' + msgs if msgs else ''}" - ) - return body + async with outbound_span( + target=TARGET_DNS_CLOUDFLARE, + method=method, + url=url, + request_body=kwargs.get("json"), + safe_error_only=True, + ) as span: + async with session.request( + method, url, headers=self._headers(), allow_redirects=False, **kwargs + ) as resp: + try: + body = await resp.json() + except Exception: # noqa: BLE001 + body = {} + span.set_response(resp.status, getattr(resp, "headers", None), body) + if resp.status in (401, 403): + raise DnsProviderError("Cloudflare rejected the API token (check it has Zone:DNS:Edit + Zone:Read).") + if resp.status >= 400 or not body.get("success", False): + # Cloudflare returns {"errors":[{"code":..,"message":..}]} — surface only the + # human message text, never the request (which carries the token header). + msgs = "; ".join( + str(e.get("message")) for e in (body.get("errors") or []) if e.get("message") + ) + raise DnsProviderError( + f"Cloudflare API error (HTTP {resp.status}){': ' + msgs if msgs else ''}" + ) + return body except DnsProviderError: raise except aiohttp.ClientError as exc: diff --git a/backend/services/dns_providers/godaddy.py b/backend/services/dns_providers/godaddy.py index 139b1ed..ebe5052 100644 --- a/backend/services/dns_providers/godaddy.py +++ b/backend/services/dns_providers/godaddy.py @@ -343,30 +343,45 @@ class GoDaddyDNSProvider(DnsProvider): request, never a response body verbatim. """ url = f"{GODADDY_API_BASE}{path}" + # v1.11.0: single funnel for every GoDaddy call. `safe_error_only=True` + # keeps the recorded error to the exception TYPE, matching the stance the + # handlers below already take — a raw message can carry the request URL. + # The `Authorization: sso-key :` header never reaches the log: + # the header allowlist reduces it to a presence marker. + from utils.http_instrumentation import outbound_span, TARGET_DNS_GODADDY + try: - async with session.request( - method, url, headers=self._headers(), allow_redirects=False, **kwargs - ) as resp: - try: - # content_type=None: every GoDaddy write answers 200/204 with an EMPTY body, and - # aiohttp would otherwise raise on the missing/other content type before parsing. - body = await resp.json(content_type=None) - except ValueError: - # ONLY a decode failure (JSONDecodeError subclasses ValueError) is swallowed — - # an empty write body, or an HTML error page on a >=400. A transport failure - # mid-read (ClientPayloadError, TimeoutError) must NOT land here: it would look - # identical to "empty body", and a caller that reads an RRset would then see - # None and could mistake it for an empty RRset. Those propagate to the handlers - # below and become a real DnsProviderError. - body = None - # 2xx only. Redirects are deliberately not followed (aiohttp would forward the - # Authorization header), so a 3xx is a failed call — treating `< 400` as success - # would report a redirected write as a silent no-op. - if 200 <= resp.status < 300: - return body - code, message = _error_fields(body) - retry_after = _retry_after_seconds(resp.headers, body) if resp.status == 429 else None - raise self._http_error(resp.status, code, message, retry_after) + async with outbound_span( + target=TARGET_DNS_GODADDY, + method=method, + url=url, + request_body=kwargs.get("json"), + safe_error_only=True, + ) as span: + async with session.request( + method, url, headers=self._headers(), allow_redirects=False, **kwargs + ) as resp: + try: + # content_type=None: every GoDaddy write answers 200/204 with an EMPTY body, and + # aiohttp would otherwise raise on the missing/other content type before parsing. + body = await resp.json(content_type=None) + except ValueError: + # ONLY a decode failure (JSONDecodeError subclasses ValueError) is swallowed — + # an empty write body, or an HTML error page on a >=400. A transport failure + # mid-read (ClientPayloadError, TimeoutError) must NOT land here: it would look + # identical to "empty body", and a caller that reads an RRset would then see + # None and could mistake it for an empty RRset. Those propagate to the handlers + # below and become a real DnsProviderError. + body = None + span.set_response(resp.status, getattr(resp, "headers", None), body) + # 2xx only. Redirects are deliberately not followed (aiohttp would forward the + # Authorization header), so a 3xx is a failed call — treating `< 400` as success + # would report a redirected write as a silent no-op. + if 200 <= resp.status < 300: + return body + code, message = _error_fields(body) + retry_after = _retry_after_seconds(resp.headers, body) if resp.status == 429 else None + raise self._http_error(resp.status, code, message, retry_after) except DnsProviderError: raise except aiohttp.ClientError as exc: diff --git a/backend/tests/test_outbound_instrumentation.py b/backend/tests/test_outbound_instrumentation.py new file mode 100644 index 0000000..5939094 --- /dev/null +++ b/backend/tests/test_outbound_instrumentation.py @@ -0,0 +1,327 @@ +"""v1.11.0: every outbound HTTP call is recorded, and instrumentation can never +become the failure. + +Two independent risks: + +**Secrets.** The outbound calls carry the most sensitive material in the +system: the ACME JWS (a replayable signed capability for the lifetime of its +nonce) and the DNS provider API credentials. Those call sites must opt out of +request-body capture and out of verbatim error text — the tests below assert +that at the call site, not just in the helper. + +**Availability.** Both DNS provider funnels end in +`except Exception: raise DnsProviderError("Unexpected ... failure")`, and in +GoDaddy's publish path that reverts `dns_record_published` and stalls the ACME +order. So an exception escaping `outbound_span` would be reported to the +operator as a provider outage. It must never raise — and it must never swallow. +""" +import asyncio +import os +import sys + +import pytest + +sys.path.insert(0, os.path.dirname(os.path.dirname(os.path.abspath(__file__)))) + +from dataclasses import replace # noqa: E402 +from unittest.mock import patch # noqa: E402 + +from utils import http_instrumentation # noqa: E402 +from utils import request_log_settings # noqa: E402 +from utils.http_instrumentation import ( # noqa: E402 + TARGET_ACME, + TARGET_DNS_CLOUDFLARE, + TARGET_DNS_GODADDY, + outbound_span, +) +from utils.request_log_settings import DEFAULT_CONFIG # noqa: E402 + +_BACKEND = os.path.dirname(os.path.dirname(os.path.abspath(__file__))) + + +def _read(*parts): + with open(os.path.join(_BACKEND, *parts), encoding="utf-8") as f: + return f.read() + + +def _function_body(src, signature): + start = src.index(signature) + rest = src[start:] + # Next def at the same or lower indentation ends the body. + end = rest.find("\n async def ", 1) + alt = rest.find("\n def ", 1) + if alt != -1 and (end == -1 or alt < end): + end = alt + return rest if end == -1 else rest[:end] + + +@pytest.fixture +def captured(monkeypatch): + rows = [] + monkeypatch.setattr(http_instrumentation.request_log_sink, "offer", rows.append) + monkeypatch.setattr(request_log_settings, "_CACHE", DEFAULT_CONFIG) + monkeypatch.setattr(http_instrumentation, "get_config", lambda: request_log_settings._CACHE) + return rows + + +# -------------------------------------------------------------------------- +# outbound_span behaviour +# -------------------------------------------------------------------------- + +def test_records_a_successful_call(captured): + async def run(): + async with outbound_span(target=TARGET_ACME, method="POST", + url="https://acme-v02.api.letsencrypt.org/acme/new-order") as span: + span.set_response(201, {"content-type": "application/json"}, {"status": "pending"}) + + asyncio.run(run()) + + row = captured[0] + assert row.direction == "outbound" + assert row.target == TARGET_ACME + assert row.method == "POST" + assert row.status_code == 201 + assert row.status_class == 2 + assert row.response_body_value == {"status": "pending"} + + +def test_exception_is_recorded_and_reraised_unchanged(captured): + async def run(): + async with outbound_span(target=TARGET_ACME, method="GET", url="https://example.com/x"): + raise ValueError("connection reset") + + with pytest.raises(ValueError, match="connection reset"): + asyncio.run(run()) + + row = captured[0] + assert row.status_code is None + assert row.status_class == 0, ( + "a call that never got a response must be status_class 0 — the sentinel the " + "error-retention window keys off" + ) + assert row.error.startswith("ValueError") + + +def test_safe_error_only_records_the_type_not_the_message(captured): + async def run(): + async with outbound_span(target=TARGET_DNS_GODADDY, method="PUT", + url="https://api.godaddy.com/v1/domains/example.com/records/TXT/_acme-challenge", + safe_error_only=True): + raise RuntimeError("failed talking to https://api.godaddy.com/v1/domains/secret-zone") + + with pytest.raises(RuntimeError): + asyncio.run(run()) + + assert captured[0].error == "RuntimeError" + assert "secret-zone" not in (captured[0].error or "") + + +def test_instrumentation_failure_never_becomes_a_provider_failure(captured, monkeypatch): + """A bug in row construction must not surface to the operator as + 'Unexpected GoDaddy API failure' and stall an ACME order.""" + def explode(row): + raise RuntimeError("sink is broken") + + monkeypatch.setattr(http_instrumentation.request_log_sink, "offer", explode) + + async def run(): + async with outbound_span(target=TARGET_DNS_CLOUDFLARE, method="GET", + url="https://api.cloudflare.com/client/v4/zones") as span: + span.set_response(200, {}, {"success": True}) + return "provider-result" + + assert asyncio.run(run()) == "provider-result", ( + "a broken sink propagated out of outbound_span; both DNS funnels would convert " + "that into DnsProviderError('Unexpected ... failure'), and in GoDaddy's publish " + "path that reverts dns_record_published and stalls the ACME order" + ) + + +def test_block_exception_still_propagates_when_the_sink_is_broken(monkeypatch): + monkeypatch.setattr(http_instrumentation.request_log_sink, "offer", + lambda row: (_ for _ in ()).throw(RuntimeError("sink is broken"))) + + async def run(): + async with outbound_span(target=TARGET_ACME, method="GET", url="https://example.com"): + raise KeyError("original") + + with pytest.raises(KeyError, match="original"): + asyncio.run(run()) + + +def test_capture_body_false_stores_the_summary_not_the_payload(captured): + async def run(): + async with outbound_span( + target=TARGET_ACME, method="POST", url="https://acme/new-order", + request_body={"jws": True, "kid_present": True, "payload_empty": False}, + capture_body=False, + ) as span: + span.set_response(200, {}, {"status": "valid"}) + + asyncio.run(run()) + + row = captured[0] + assert row.request_body_value == {"jws": True, "kid_present": True, "payload_empty": False} + assert row.request_body_raw is None + # The CA's RESPONSE is still captured — that is the half operators need. + assert row.response_body_value == {"status": "valid"} + + +def test_urls_are_scrubbed_before_storage(captured): + async def run(): + async with outbound_span( + target=TARGET_DNS_CLOUDFLARE, method="GET", + url="https://user:hunter2@api.cloudflare.com/client/v4/zones?api_key=abc&page=1", + ) as span: + span.set_response(200, {}, {}) + + asyncio.run(run()) + + url = captured[0].url + assert "hunter2" not in url + assert "abc" not in url + assert "page=1" in url + + +def test_outbound_rows_inherit_the_inbound_request_id(captured): + from utils.request_log_sink import request_id_context + + async def run(): + token = request_id_context.set("abc123def456") + try: + async with outbound_span(target=TARGET_ACME, method="GET", url="https://acme/dir") as span: + span.set_response(200, {}, {}) + finally: + request_id_context.reset(token) + + asyncio.run(run()) + + assert captured[0].request_id == "abc123def456", ( + "an outbound call must carry the inbound request's id, otherwise the detail view " + "cannot show which API call triggered which CA/DNS call" + ) + + +def test_background_calls_get_a_task_scoped_id(captured): + async def run(): + async with outbound_span(target=TARGET_ACME, method="GET", url="https://acme/dir") as span: + span.set_response(200, {}, {}) + + asyncio.run(run()) + assert captured[0].request_id.startswith("bg:") + + +def test_disabled_outbound_capture_produces_no_row(captured, monkeypatch): + monkeypatch.setattr(request_log_settings, "_CACHE", + replace(DEFAULT_CONFIG, capture_outbound=False)) + + async def run(): + async with outbound_span(target=TARGET_ACME, method="GET", url="https://acme/dir") as span: + # The call site keeps working — set_response must still be callable. + span.set_response(200, {}, {}) + + asyncio.run(run()) + assert captured == [] + + +def test_set_response_tolerates_a_response_without_headers(captured): + """Some call sites are driven in tests by minimal fakes exposing only + `.status`.""" + async def run(): + async with outbound_span(target=TARGET_ACME, method="HEAD", url="https://acme/nonce") as span: + span.set_response(200, None) + + asyncio.run(run()) + assert captured[0].status_code == 200 + + +# -------------------------------------------------------------------------- +# Call-site coverage +# -------------------------------------------------------------------------- + +@pytest.mark.parametrize("path,target", [ + (("services", "acme_service.py"), "TARGET_ACME"), + (("services", "acme_diagnostics.py"), "TARGET_ACME_DIAG"), + (("services", "dns_providers", "cloudflare.py"), "TARGET_DNS_CLOUDFLARE"), + (("services", "dns_providers", "godaddy.py"), "TARGET_DNS_GODADDY"), + (("routers", "letsencrypt.py"), "TARGET_LETSENCRYPT_CA"), + (("routers", "settings.py"), "TARGET_SETTINGS_PROBE"), + (("haproxy_client.py",), "TARGET_HAPROXY_STATS"), + (("agent_notifications.py",), "TARGET_AGENT"), +]) +def test_every_outbound_module_is_instrumented(path, target): + src = _read(*path) + assert "outbound_span(" in src, f"{'/'.join(path)} makes HTTP calls but records nothing" + assert target in src, f"{'/'.join(path)} does not tag its rows with {target}" + + +def test_acme_signed_request_never_captures_the_jws_body(): + """The JWS body is {protected, payload, signature}: `protected` carries the + nonce and account kid, `signature` is made with the account private key. A + stored (protected, signature) pair is a replayable ACME credential.""" + src = _read("services", "acme_service.py") + body = _function_body(src, " async def _signed_request(") + + assert "capture_body=False" in body, ( + "the ACME JWS request body would be written to request_logs verbatim — that is a " + "replayable signed credential sitting in an audit table" + ) + assert '"jws": True' in body, "no synthetic summary replaces the suppressed JWS body" + + +def test_acme_span_is_inside_the_retry_loop(): + """The session is built outside `for attempt in range(3)`; the span must be + inside it, so a badNonce retry is its own row rather than being folded into + the successful attempt.""" + src = _read("services", "acme_service.py") + body = _function_body(src, " async def _signed_request(") + + loop_at = body.index("for attempt in range(3):") + span_at = body.index("async with outbound_span(") + assert loop_at < span_at, ( + "outbound_span wraps the retry loop instead of sitting inside it, so three " + "attempts collapse into one log row and a nonce retry becomes invisible" + ) + + +@pytest.mark.parametrize("path", [ + ("services", "dns_providers", "cloudflare.py"), + ("services", "dns_providers", "godaddy.py"), +]) +def test_dns_providers_record_error_types_only(path): + src = _read(*path) + body = _function_body(src, " async def _request(") + assert "safe_error_only=True" in body, ( + f"{'/'.join(path)} would record the full exception text, which can carry the " + f"request URL and through it the tenant/zone identifier" + ) + + +def test_godaddy_narrow_value_error_handling_is_preserved(): + """R-round hardening: only a JSON decode failure may be swallowed. Widening + it would make a mid-read transport failure look like an empty RRset, and the + follow-up full-RRset PUT would then destroy coexisting TXT values.""" + src = _read("services", "dns_providers", "godaddy.py") + body = _function_body(src, " async def _request(") + assert "except ValueError:" in body + assert "except Exception:\n body = None" not in body + + +def test_acme_diagnostics_keeps_its_ipv4_pinned_connector(): + """Duplicates an existing assertion on purpose: instrumenting this module + must not have refactored the SSRF-guard connector away.""" + src = _read("services", "acme_diagnostics.py") + assert "TCPConnector(family=socket.AF_INET" in src, ( + "the IPv4 pin was removed from the port-80 probe — that reopens the dual-stack " + "AAAA bypass the SSRF guard closes" + ) + + +def test_haproxy_stats_never_logs_basic_auth_or_the_csv(): + """aiohttp.BasicAuth is a NamedTuple whose repr contains the cleartext + password, and a full stats CSV has no audit value.""" + src = _read("haproxy_client.py") + body = _function_body(src, " async def _get_stats_via_http(") + assert "capture_body=False" in body + assert "capture_response_body=False" in body + assert "auth=auth" in body and "request_body=auth" not in body diff --git a/backend/tests/test_request_log_middleware.py b/backend/tests/test_request_log_middleware.py new file mode 100644 index 0000000..017aa68 --- /dev/null +++ b/backend/tests/test_request_log_middleware.py @@ -0,0 +1,432 @@ +"""v1.11.0: the request/response logger must be invisible to everything below it. + +This is the highest-risk piece of the feature. A logging middleware that reads +the request body the naive way DRAINS the ASGI receive channel, and the handler +underneath then sees an empty body — `POST /api/agents/heartbeat` reads the raw +stream itself, so every agent in the fleet would start failing its heartbeat +because someone wanted nicer logs. + +The implementation therefore TEES rather than consumes. These tests drive the +middleware over a stub ASGI app and assert that property directly: the +downstream app sees the full body, the client sees the full response, and only +a capped copy is kept. +""" +import asyncio +import json +import os +import re +import sys + +import pytest + +sys.path.insert(0, os.path.dirname(os.path.dirname(os.path.abspath(__file__)))) + +from dataclasses import replace # noqa: E402 + +from middleware.request_logger import RequestResponseLogMiddleware # noqa: E402 +from utils.logging_config import correlation_id_context # noqa: E402 +from utils import request_log_settings # noqa: E402 +from utils.request_log_settings import DEFAULT_CONFIG # noqa: E402 +from utils import request_log_sink as sink_module # noqa: E402 + + +_MAIN = os.path.join(os.path.dirname(os.path.dirname(os.path.abspath(__file__))), "main.py") + + +@pytest.fixture +def captured(monkeypatch): + """Collect the rows the middleware hands to the sink, instead of writing them.""" + rows = [] + monkeypatch.setattr(sink_module.request_log_sink, "offer", rows.append) + # The middleware imports `request_log_sink` by value, so patch there too. + import middleware.request_logger as rl + monkeypatch.setattr(rl.request_log_sink, "offer", rows.append) + return rows + + +@pytest.fixture(autouse=True) +def default_config(monkeypatch): + """Every test starts from the shipped defaults, with a small body cap so the + truncation paths are exercised without megabyte fixtures.""" + cfg = replace(DEFAULT_CONFIG, max_body_bytes=1024) + monkeypatch.setattr(request_log_settings, "_CACHE", cfg) + import middleware.request_logger as rl + monkeypatch.setattr(rl, "get_config", lambda: request_log_settings._CACHE) + return cfg + + +def set_config(monkeypatch, **overrides): + cfg = replace(request_log_settings._CACHE, **overrides) + monkeypatch.setattr(request_log_settings, "_CACHE", cfg) + return cfg + + +# -------------------------------------------------------------------------- +# A minimal ASGI harness — no TestClient, no HTTP stack, just the protocol. +# -------------------------------------------------------------------------- + +async def drive(app, *, method="POST", path="/api/backends", body=b"", query=b"", + headers=None, content_type="application/json"): + """Run one request through `app` and return (status, headers, body).""" + raw_headers = [(b"host", b"testserver")] + if content_type: + raw_headers.append((b"content-type", content_type.encode())) + for k, v in (headers or {}).items(): + raw_headers.append((k.encode().lower(), v.encode())) + + scope = { + "type": "http", + "asgi": {"version": "3.0"}, + "http_version": "1.1", + "method": method, + "scheme": "http", + "path": path, + "raw_path": path.encode(), + "query_string": query, + "root_path": "", + "headers": raw_headers, + "client": ("10.1.2.3", 51234), + "server": ("testserver", 80), + } + + # Deliver the body in three chunks so the tee is exercised across messages. + chunks = [body[i:i + max(1, len(body) // 3 or 1)] for i in range(0, len(body), max(1, len(body) // 3 or 1))] or [b""] + pending = list(chunks) + + async def receive(): + if pending: + chunk = pending.pop(0) + return {"type": "http.request", "body": chunk, "more_body": bool(pending)} + return {"type": "http.request", "body": b"", "more_body": False} + + sent = {"status": None, "headers": [], "body": b""} + + async def send(message): + if message["type"] == "http.response.start": + sent["status"] = message["status"] + sent["headers"] = message.get("headers", []) + elif message["type"] == "http.response.body": + sent["body"] += message.get("body", b"") or b"" + + await app(scope, receive, send) + return sent + + +def echo_length_app(status=200, content_type=b"application/json"): + """Stub app that CONSUMES the whole request body and reports its length. + + This is the regression shape: if the middleware drained the stream, the app + below it would see 0 bytes. + """ + async def app(scope, receive, send): + total = 0 + while True: + message = await receive() + total += len(message.get("body", b"") or b"") + if not message.get("more_body"): + break + payload = json.dumps({"received_bytes": total}).encode() + await send({"type": "http.response.start", "status": status, + "headers": [(b"content-type", content_type)]}) + await send({"type": "http.response.body", "body": payload}) + return app + + +def chunked_app(chunks, content_type=b"application/json"): + async def app(scope, receive, send): + await send({"type": "http.response.start", "status": 200, + "headers": [(b"content-type", content_type)]}) + for i, chunk in enumerate(chunks): + await send({"type": "http.response.body", "body": chunk, + "more_body": i < len(chunks) - 1}) + return app + + +# -------------------------------------------------------------------------- +# The transparency guarantees +# -------------------------------------------------------------------------- + +def test_request_body_reaches_downstream_intact(captured): + """THE regression guard: draining the receive channel would break the raw-body + agent heartbeat handler.""" + body = b"x" * 100_000 + app = RequestResponseLogMiddleware(echo_length_app()) + + sent = asyncio.run(drive(app, body=body)) + + assert json.loads(sent["body"])["received_bytes"] == 100_000, ( + "the handler below the logger saw a different body length than the client sent — " + "the middleware consumed the receive channel instead of teeing it" + ) + + +def test_response_body_reaches_client_intact(captured): + chunks = [b'{"part":', b'"one",', b'"n":2}'] + app = RequestResponseLogMiddleware(chunked_app(chunks)) + + sent = asyncio.run(drive(app, method="GET", body=b"")) + + assert sent["body"] == b"".join(chunks), "a response chunk was swallowed by the logger" + assert sent["status"] == 200 + + +def test_only_the_capped_prefix_is_captured(captured): + body = b"y" * 100_000 + app = RequestResponseLogMiddleware(echo_length_app()) + + asyncio.run(drive(app, body=body)) + + row = captured[0] + assert row.request_body_bytes == 100_000, "the on-the-wire size must be recorded in full" + assert len(row.request_body_raw) <= 1024, ( + "the middleware buffered more than max_body_bytes — memory is unbounded per request" + ) + + +def test_non_capturable_content_type_is_counted_but_not_buffered(captured): + app = RequestResponseLogMiddleware(chunked_app([b"\x00\x01\x02" * 500], + content_type=b"application/octet-stream")) + + asyncio.run(drive(app, method="GET", content_type=None)) + + row = captured[0] + assert row.response_body_bytes == 1500 + assert row.response_body_raw is None, ( + "a binary response body was buffered — this is what keeps streaming/file " + "responses safe" + ) + + +# -------------------------------------------------------------------------- +# What gets logged, and what does not +# -------------------------------------------------------------------------- + +def test_basic_row_fields(captured): + app = RequestResponseLogMiddleware(echo_length_app()) + + asyncio.run(drive(app, method="POST", path="/api/backends", + body=b'{"name":"web"}', query=b"cluster_id=2&token=secret")) + + row = captured[0] + assert row.direction == "inbound" + assert row.method == "POST" + assert row.path == "/api/backends" + assert row.status_code == 200 + assert row.status_class == 2 + assert row.client_ip == "10.1.2.3" + assert row.duration_ms >= 0 + # The query string is scrubbed before it is stored, in the URL and the dict. + assert "secret" not in row.url + assert row.query_params["token"] == "***REDACTED***" + assert row.query_params["cluster_id"] == "2" + + +@pytest.mark.parametrize("path", [ + "/api/health", + "/api/health/deep", + "/api/docs", + "/api/openapi.json", + "/.well-known/acme-challenge/abc123", + "/api/agents/heartbeat", + "/favicon.ico", +]) +def test_excluded_paths_produce_no_row(captured, path): + app = RequestResponseLogMiddleware(echo_length_app()) + asyncio.run(drive(app, method="GET", path=path)) + assert captured == [], f"{path} must not be logged by default" + + +def test_log_viewer_path_cannot_be_un_excluded(captured, monkeypatch): + """`exclude_paths` is operator-editable, so the viewer's own endpoints have a + hard floor — otherwise reading the log generates log entries about reading + the log.""" + set_config(monkeypatch, exclude_paths=()) + + app = RequestResponseLogMiddleware(echo_length_app()) + asyncio.run(drive(app, method="GET", path="/api/request-logs?limit=50")) + + assert captured == [], ( + "clearing exclude_paths re-enabled logging of the log viewer itself" + ) + + +def test_options_preflight_is_skipped(captured): + app = RequestResponseLogMiddleware(echo_length_app()) + asyncio.run(drive(app, method="OPTIONS", path="/api/backends")) + assert captured == [] + + +def test_get_can_be_turned_off(captured, monkeypatch): + set_config(monkeypatch, capture_get=False) + app = RequestResponseLogMiddleware(echo_length_app()) + + asyncio.run(drive(app, method="GET", path="/api/backends")) + assert captured == [] + + asyncio.run(drive(app, method="POST", path="/api/backends", body=b"{}")) + assert len(captured) == 1, "turning GETs off must not silence writes" + + +def test_disabled_config_short_circuits_but_still_serves(captured, monkeypatch): + set_config(monkeypatch, enabled=False) + app = RequestResponseLogMiddleware(echo_length_app()) + + sent = asyncio.run(drive(app, body=b"hello")) + + assert captured == [] + assert sent["status"] == 200, "the kill-switch must not break request serving" + + +def test_capture_bodies_off_keeps_sizes_but_drops_content(captured, monkeypatch): + set_config(monkeypatch, capture_bodies=False) + app = RequestResponseLogMiddleware(echo_length_app()) + + asyncio.run(drive(app, body=b'{"secret":"x"}')) + + row = captured[0] + assert row.request_body_raw is None + assert row.request_body_bytes == 14, "size accounting must survive with bodies off" + + +# -------------------------------------------------------------------------- +# Errors and correlation +# -------------------------------------------------------------------------- + +def test_exception_is_recorded_as_status_class_zero_and_reraised(captured): + async def boom(scope, receive, send): + raise RuntimeError("handler exploded") + + app = RequestResponseLogMiddleware(boom) + + with pytest.raises(RuntimeError): + asyncio.run(drive(app, method="GET")) + + row = captured[0] + assert row.status_code is None + assert row.status_class == 0, ( + "a request that produced no HTTP response must be status_class 0 — that is the " + "sentinel the error-retention prune keys off" + ) + assert row.error.startswith("RuntimeError") + + +def test_correlation_id_is_seeded_before_downstream_and_reset_after(captured): + seen = {} + + async def app(scope, receive, send): + seen["cid"] = correlation_id_context.get() + await send({"type": "http.response.start", "status": 204, "headers": []}) + await send({"type": "http.response.body", "body": b""}) + + wrapped = RequestResponseLogMiddleware(app) + asyncio.run(drive(wrapped, method="GET")) + + row = captured[0] + assert seen["cid"] == row.request_id[:8], ( + "the downstream error handler would mint its own id, so X-Correlation-ID would " + "not match request_logs.request_id" + ) + assert correlation_id_context.get() is None, ( + "the ContextVar token was not reset — the next request on this task would inherit " + "a stale correlation id" + ) + + +def test_x_request_id_header_is_returned_to_the_client(captured): + app = RequestResponseLogMiddleware(echo_length_app()) + sent = asyncio.run(drive(app, method="GET")) + + names = {k.decode().lower() for k, _ in sent["headers"]} + assert "x-request-id" in names, ( + "without this header a user reporting a problem has no id to quote" + ) + + +def test_error_responses_are_logged_with_their_status(captured): + app = RequestResponseLogMiddleware(echo_length_app(status=422)) + asyncio.run(drive(app, body=b'{"bad":true}')) + + row = captured[0] + assert row.status_code == 422 + assert row.status_class == 4, "4xx must be classed as an error for retention purposes" + + +def test_jwt_identity_is_resolved_without_a_database(captured): + """The middleware runs on every request; a DB lookup per call is not + acceptable, so the user is read straight out of the token claims.""" + from datetime import datetime, timedelta + + from jose import jwt + from config import JWT_ALGORITHM, JWT_SECRET_KEY + + token = jwt.encode( + {"user_id": 42, "username": "ops", "exp": datetime.utcnow() + timedelta(minutes=10)}, + JWT_SECRET_KEY, algorithm=JWT_ALGORITHM, + ) + + app = RequestResponseLogMiddleware(echo_length_app()) + asyncio.run(drive(app, body=b"{}", headers={"authorization": f"Bearer {token}"})) + + row = captured[0] + assert row.user_id == 42 + assert row.username == "ops" + + +def test_malformed_token_yields_an_anonymous_row(captured): + app = RequestResponseLogMiddleware(echo_length_app()) + asyncio.run(drive(app, body=b"{}", headers={"authorization": "Bearer not.a.jwt"})) + + row = captured[0] + assert row.user_id is None + assert row.username is None + # Logging is not an auth path — a bad token must not turn into an exception. + + +def test_authorization_header_is_never_stored_verbatim(captured): + app = RequestResponseLogMiddleware(echo_length_app()) + asyncio.run(drive(app, body=b"{}", headers={"authorization": "Bearer super-secret"})) + + params = captured[0].to_params() + assert "super-secret" not in json.dumps(params, default=str) + + +# -------------------------------------------------------------------------- +# Registration order in main.py +# -------------------------------------------------------------------------- + +def test_middleware_is_registered_last_so_it_is_outermost(): + with open(_MAIN, encoding="utf-8") as f: + src = f.read() + + log_at = src.index("app.add_middleware(RequestResponseLogMiddleware)") + cors_at = src.index(" CORSMiddleware,") + + assert log_at > cors_at, ( + "Starlette's add_middleware inserts at index 0, so the LAST registration is the " + "OUTERMOST middleware. Registering the request logger before CORS would put it " + "inside the stack, where it can no longer see the final client-visible response " + "and can no longer seed the correlation id before the error handler reads it." + ) + + +def test_env_kill_switch_guards_the_registration(): + with open(_MAIN, encoding="utf-8") as f: + src = f.read() + + assert re.search( + r"if REQUEST_LOG_ENABLED:\s*\n\s*app\.add_middleware\(RequestResponseLogMiddleware\)", + src, + ), ( + "REQUEST_LOG_ENABLED must gate the add_middleware call itself, not a branch inside " + "the middleware — the whole point is that a disabled log costs nothing" + ) + + +def test_cors_exposes_the_request_id_header(): + with open(_MAIN, encoding="utf-8") as f: + src = f.read() + + assert "expose_headers=" in src and "X-Request-ID" in src, ( + "without expose_headers the browser cannot read X-Request-ID on a cross-origin " + "deployment, so the id is unusable from the app" + ) diff --git a/backend/tests/test_request_log_migration.py b/backend/tests/test_request_log_migration.py new file mode 100644 index 0000000..8cd6905 --- /dev/null +++ b/backend/tests/test_request_log_migration.py @@ -0,0 +1,251 @@ +"""v1.11.0: the request_logs migration actually runs on existing installs. + +Source-scan tests (the sanctioned pattern here — there is no database in this +suite). The failure mode being pinned is specific and silent: migrations are +gated on `applied_version >= SCHEMA_VERSION`, so forgetting the bump means the +whole sequence is skipped on every already-deployed database and neither the +table nor the new permissions ever appear — while a fresh install works fine, +so it looks correct in development. +""" +import os +import re +import sys + +import pytest + +sys.path.insert(0, os.path.dirname(os.path.dirname(os.path.abspath(__file__)))) + +_BACKEND = os.path.dirname(os.path.dirname(os.path.abspath(__file__))) +_MIGRATIONS = os.path.join(_BACKEND, "database", "migrations.py") +_MAIN = os.path.join(_BACKEND, "main.py") + + +@pytest.fixture(scope="module") +def src(): + with open(_MIGRATIONS, encoding="utf-8") as f: + return f.read() + + +@pytest.fixture(scope="module") +def runner_body(src): + """The body of _run_all_migrations_inner, where steps are registered.""" + assert "async def _run_all_migrations_inner" in src + return src.split("async def _run_all_migrations_inner", 1)[1].split("\nasync def ", 1)[0] + + +@pytest.fixture(scope="module") +def rbac_body(src): + return src.split("async def update_system_roles_to_enterprise_rbac", 1)[1].split("\nasync def ", 1)[0] + + +def _role_block(rbac_body, role): + """Slice one role's permission list out of the enterprise_roles literal.""" + start = rbac_body.index(f"'{role}': {{") + end = rbac_body.index("]", rbac_body.index("'permissions': [", start)) + return rbac_body[start:end] + + +# -------------------------------------------------------------------------- +# The version gate +# -------------------------------------------------------------------------- + +def test_schema_version_bumped_to_at_least_11(src): + match = re.search(r"^SCHEMA_VERSION\s*=\s*(\d+)", src, re.MULTILINE) + assert match, "SCHEMA_VERSION assignment not found in migrations.py" + assert int(match.group(1)) >= 11, ( + "SCHEMA_VERSION was not bumped for the request_logs table. run_all_migrations() " + "returns early when the recorded version is already >= SCHEMA_VERSION, so every " + "existing deployment would skip the whole run: no request_logs table, no " + "requestlog.* permissions, and the feature would silently do nothing in production " + "while working perfectly on a fresh database." + ) + + +# -------------------------------------------------------------------------- +# Registration +# -------------------------------------------------------------------------- + +def test_both_migration_steps_are_registered(runner_body): + assert "await ensure_request_logs_table()" in runner_body, ( + "ensure_request_logs_table is defined but never called from the migration runner" + ) + assert "await ensure_request_log_settings()" in runner_body, ( + "the retention defaults are never seeded, so an upgraded install has no " + "requestlog.* rows and Settings shows blanks" + ) + + +def test_table_is_created_before_its_settings_are_seeded(runner_body): + table_at = runner_body.index("await ensure_request_logs_table()") + seed_at = runner_body.index("await ensure_request_log_settings()") + assert table_at < seed_at, ( + "the settings seed runs before the table step; if the table step then raises, the " + "run aborts with settings but no table" + ) + + +# -------------------------------------------------------------------------- +# The DDL itself +# -------------------------------------------------------------------------- + +@pytest.fixture(scope="module") +def ddl_body(src): + return src.split("async def ensure_request_logs_table", 1)[1].split("\nasync def ", 1)[0] + + +@pytest.mark.parametrize("fragment", [ + "CREATE TABLE IF NOT EXISTS request_logs", + "id BIGSERIAL PRIMARY KEY", + "request_id VARCHAR(64) NOT NULL", + "direction VARCHAR(8) NOT NULL", + "status_class SMALLINT", + "created_at TIMESTAMPTZ NOT NULL DEFAULT NOW()", + "request_logs_direction_check", + "client_ip INET", +]) +def test_ddl_essentials(ddl_body, fragment): + assert fragment in ddl_body, f"request_logs DDL is missing {fragment!r}" + + +def test_ddl_is_idempotent(ddl_body): + assert "CREATE TABLE IF NOT EXISTS" in ddl_body + creates = re.findall(r"CREATE INDEX(?: IF NOT EXISTS)?", ddl_body) + assert creates, "no indexes are created for request_logs" + assert all(c == "CREATE INDEX IF NOT EXISTS" for c in creates), ( + "an index is created without IF NOT EXISTS — the second startup would raise and " + "abort the whole migration run" + ) + + +def test_prune_partial_indexes_are_present(ddl_body): + """The retention delete is split by outcome, so a plain + (status_class, created_at) index would still range-scan the half it does not + want.""" + assert "idx_request_logs_prune_ok" in ddl_body + assert "idx_request_logs_prune_err" in ddl_body + assert "WHERE status_class BETWEEN 1 AND 3" in ddl_body + assert "WHERE status_class = 0 OR status_class >= 4" in ddl_body + + +def test_request_id_index_exists_for_the_trace_view(ddl_body): + assert "idx_request_logs_request_id" in ddl_body, ( + "without this index, opening one request to see the outbound calls it triggered " + "is a sequential scan" + ) + + +def test_no_foreign_key_on_user_id(ddl_body): + """Deliberate deviation from the house style — see the docstring in + migrations.py. Pinned so it is not 'fixed' back into an FK later.""" + user_id_line = [line for line in ddl_body.splitlines() if "user_id " in line and "INTEGER" in line] + assert user_id_line, "user_id column not found" + assert "REFERENCES" not in user_id_line[0], ( + "an FK was added to request_logs.user_id — per-insert FK validation on the " + "highest-volume table in the system, and audit rows must outlive the account" + ) + + +def test_migration_step_reraises_on_failure(ddl_body): + """The version marker is written only after the inner sequence completes, so + swallowing here would stamp version 11 with no table and the gate would then + skip every retry, permanently.""" + assert re.search(r"\n\s+raise\n", ddl_body), ( + "ensure_request_logs_table swallows its exception instead of re-raising" + ) + + +def test_settings_seed_does_not_overwrite_operator_tuning(src): + seed_body = src.split("async def ensure_request_log_settings", 1)[1].split("\nasync def ", 1)[0] + assert "ON CONFLICT (key) DO NOTHING" in seed_body, ( + "the seed uses DO UPDATE, so every upgrade would reset the operator's retention " + "settings back to the defaults" + ) + + +# -------------------------------------------------------------------------- +# Permission seeding +# -------------------------------------------------------------------------- + +def test_super_admin_gets_both_permissions(rbac_body): + block = _role_block(rbac_body, "super_admin") + assert "'requestlog.read'" in block + assert "'requestlog.manage'" in block + + +def test_security_admin_gets_both_permissions(rbac_body): + block = _role_block(rbac_body, "security_admin") + assert "'requestlog.read'" in block + assert "'requestlog.manage'" in block + + +def test_operator_gets_read_only(rbac_body): + block = _role_block(rbac_body, "operator") + assert "'requestlog.read'" in block + assert "'requestlog.manage'" not in block, ( + "operators should be able to read the log to debug an apply or an ACME order, but " + "retention policy and purge belong to the admins" + ) + + +def test_viewer_gets_neither(rbac_body): + block = _role_block(rbac_body, "viewer") + assert "requestlog" not in block, ( + "viewer was granted a requestlog permission. Even redacted, captured request and " + "response bodies are a far broader disclosure surface than the read-only config " + "views a viewer is meant to have." + ) + + +def test_permission_strings_have_exactly_one_dot(rbac_body): + """get_user_permissions splits on the FIRST dot and silently drops any + string without one.""" + for perm in re.findall(r"'(requestlog[^']*)'", rbac_body): + assert perm.count(".") == 1, f"{perm!r} is not a . pair" + + +def test_initial_seed_lists_stay_in_sync(src): + """create_initial_system_data() is overwritten by the enterprise seeder on + every run, but that seeder swallows all exceptions — keeping the two in sync + is the safety net.""" + initial = src.split("system_roles = [", 1)[1].split("\n ]", 1)[0] + assert '"requestlog.read"' in initial + assert '"requestlog.manage"' in initial + + +# -------------------------------------------------------------------------- +# Runtime wiring +# -------------------------------------------------------------------------- + +def test_prune_loop_is_started_and_independent_of_the_acme_loop(): + with open(_MAIN, encoding="utf-8") as f: + main_src = f.read() + + assert "async def prune_request_logs_loop" in main_src + assert "asyncio.create_task(prune_request_logs_loop())" in main_src, ( + "the retention prune task is defined but never started, so request_logs grows " + "without bound" + ) + loop_body = main_src.split("async def prune_request_logs_loop", 1)[1].split("\n# Production middleware", 1)[0] + assert "table_name = 'request_logs'" in loop_body, ( + "the prune loop does not check for its own table, so it would log an error every " + "tick on a database where the migration has not run yet" + ) + assert "table_name = 'letsencrypt_orders'" not in loop_body, ( + "the prune loop was gated on the ACME table, which would disable retention " + "entirely on an install that never uses ACME" + ) + + +def test_sink_is_flushed_before_the_pool_closes(): + with open(_MAIN, encoding="utf-8") as f: + main_src = f.read() + + body = main_src.split("async def shutdown_event", 1)[1] + flush_at = body.find("request_log_sink.flush") + close_at = body.find("close_database_pool()") + assert flush_at != -1, "queued request-log rows are never flushed on shutdown" + assert flush_at < close_at, ( + "the sink is flushed after the pool is closed, so the queued rows are lost. The " + "sink's writer is a `while True` loop and can never satisfy the generic " + "asyncio.wait drain, so it needs its own explicit flush first." + ) diff --git a/backend/tests/test_request_log_prune.py b/backend/tests/test_request_log_prune.py new file mode 100644 index 0000000..8ee1ef7 --- /dev/null +++ b/backend/tests/test_request_log_prune.py @@ -0,0 +1,261 @@ +"""v1.11.0: retention actually reclaims space, and cannot be turned into an +injection point or a 60-second lock. + +`request_logs` is the highest-volume table in the system, so the prune has +three properties that are easy to get wrong and expensive to get wrong: + + * the operator-supplied retention day counts are BIND PARAMETERS, never + string-interpolated into the SQL; + * deletes are BATCHED, because the pool's command_timeout is 60s and an + unbounded DELETE over millions of rows raises and then nothing is ever + pruned; + * the watermark is stamped only after a COMPLETE pass, so a pass that dies + half-way is retried instead of being recorded as done. + +The fake connection dispatches on the SQL text rather than on call order — an +ordered side_effect list silently passes tests for the wrong reason as soon as +the number of statements changes. +""" +import asyncio +import json +import os +import sys +from datetime import datetime, timedelta +from unittest.mock import AsyncMock, patch + +import pytest + +sys.path.insert(0, os.path.dirname(os.path.dirname(os.path.abspath(__file__)))) + +from dataclasses import replace # noqa: E402 + +from utils import request_log_prune # noqa: E402 +from utils.request_log_prune import ( # noqa: E402 + BATCH_SIZE, + MAX_BATCHES, + PRUNE_LOCK_KEY, + prune_request_logs_if_due, +) +from utils.request_log_settings import DEFAULT_CONFIG # noqa: E402 + +_SUCCESS_MARKER = "status_class BETWEEN 1 AND 3" +_ERROR_MARKER = "status_class = 0 OR status_class >= 4" +_CAP_MARKER = "id <= $1" + + +def _conn(*, lock=True, watermark_age_minutes=None, cutoff_id=None, + success_batches=None, error_batches=None, cap_batches=None, + fail_on=None): + """A fake asyncpg connection that answers by SQL shape.""" + conn = AsyncMock() + + def fetchval(sql, *args): + text = str(sql) + if "pg_try_advisory_lock" in text: + return lock + if "ORDER BY id DESC OFFSET" in text: + return cutoff_id + return None + + conn.fetchval = AsyncMock(side_effect=fetchval) + + if watermark_age_minutes is None: + conn.fetchrow = AsyncMock(return_value=None) + else: + stamp = (datetime.utcnow() - timedelta(minutes=watermark_age_minutes)).isoformat() + "Z" + conn.fetchrow = AsyncMock(return_value={"value": json.dumps(stamp)}) + + queues = { + _SUCCESS_MARKER: list(success_batches or ["DELETE 0"]), + _ERROR_MARKER: list(error_batches or ["DELETE 0"]), + _CAP_MARKER: list(cap_batches or ["DELETE 0"]), + } + + def execute(sql, *args): + text = str(sql) + if fail_on and fail_on in text: + raise RuntimeError("statement timeout") + for marker, queue in queues.items(): + if marker in text: + return queue.pop(0) if queue else "DELETE 0" + return "" + + conn.execute = AsyncMock(side_effect=execute) + return conn + + +def _run(conn, *, force=False, **cfg_overrides): + cfg = replace(DEFAULT_CONFIG, **cfg_overrides) + with patch.object(request_log_prune, "get_config", lambda: cfg), \ + patch.object(request_log_prune, "get_database_connection", AsyncMock(return_value=conn)), \ + patch.object(request_log_prune, "close_database_connection", AsyncMock()): + return asyncio.run(prune_request_logs_if_due(force=force)) + + +def _delete_sql(conn): + return [str(c.args[0]) for c in conn.execute.call_args_list + if "DELETE FROM request_logs" in str(c.args[0])] + + +def test_skips_entirely_when_another_replica_holds_the_lock(): + conn = _conn(lock=False) + counts = _run(conn) + + assert counts == {"success": 0, "error": 0, "overflow": 0, "ran": 0} + assert _delete_sql(conn) == [], ( + "a second replica ran the prune concurrently — pg_try_advisory_lock is what keeps " + "N pods from all scanning the same table at once" + ) + + +def test_skips_when_the_watermark_is_still_fresh(): + conn = _conn(watermark_age_minutes=10) + counts = _run(conn, prune_interval_minutes=60) + + assert counts["ran"] == 0 + assert _delete_sql(conn) == [] + + +def test_runs_all_three_limits_when_due(): + conn = _conn( + watermark_age_minutes=120, cutoff_id=999, + success_batches=["DELETE 3"], error_batches=["DELETE 4"], cap_batches=["DELETE 5"], + ) + counts = _run(conn, prune_interval_minutes=60, success_retention_days=7, + error_retention_days=30, max_rows=500000) + + sqls = _delete_sql(conn) + assert len(sqls) == 3, f"expected success TTL + error TTL + row cap, got {len(sqls)}" + assert _SUCCESS_MARKER in sqls[0] + assert _ERROR_MARKER in sqls[1] + assert _CAP_MARKER in sqls[2] + + assert counts["success"] == 3 + assert counts["error"] == 4 + assert counts["overflow"] == 5 + assert counts["ran"] == 1 + + +def test_retention_days_travel_as_bind_parameters(): + """Injection guard: the day counts come straight from an operator-editable + setting, so they must never be formatted into the SQL text.""" + conn = _conn(watermark_age_minutes=120) + _run(conn, prune_interval_minutes=60, success_retention_days=7, error_retention_days=30) + + ttl_calls = [c for c in conn.execute.call_args_list + if "created_at < NOW()" in str(c.args[0])] + assert len(ttl_calls) == 2 + + for call in ttl_calls: + assert "($1 || ' days')::INTERVAL" in str(call.args[0]), ( + "the retention window is interpolated into the SQL string instead of bound — " + "an operator-supplied value reaching the parser is an injection point" + ) + + assert ttl_calls[0].args[1] == "7" + assert ttl_calls[1].args[1] == "30" + assert ttl_calls[0].args[2] == BATCH_SIZE + + +def test_deletes_are_batched_until_a_short_batch(): + conn = _conn( + watermark_age_minutes=120, + success_batches=[f"DELETE {BATCH_SIZE}", f"DELETE {BATCH_SIZE}", "DELETE 12"], + ) + counts = _run(conn, prune_interval_minutes=60) + + assert counts["success"] == BATCH_SIZE * 2 + 12, ( + "the batch loop stopped early or double-counted" + ) + success_calls = [s for s in _delete_sql(conn) if _SUCCESS_MARKER in s] + assert len(success_calls) == 3, "the loop must stop on the first short batch" + + +def test_batch_loop_respects_the_ceiling(): + """A table so far behind that every batch comes back full must still hand the + connection back rather than looping forever.""" + conn = _conn( + watermark_age_minutes=120, + success_batches=[f"DELETE {BATCH_SIZE}"] * (MAX_BATCHES * 3), + ) + counts = _run(conn, prune_interval_minutes=60) + + assert counts["success"] == BATCH_SIZE * MAX_BATCHES + success_calls = [s for s in _delete_sql(conn) if _SUCCESS_MARKER in s] + assert len(success_calls) == MAX_BATCHES + + +def test_watermark_is_not_stamped_when_a_step_fails(): + conn = _conn(watermark_age_minutes=120, cutoff_id=42, fail_on=_CAP_MARKER) + counts = _run(conn, prune_interval_minutes=60) + + stamps = [c for c in conn.execute.call_args_list + if "INSERT INTO system_settings" in str(c.args[0])] + assert stamps == [], ( + "a partially-completed pass stamped the watermark, so the remainder would not be " + "retried until the next interval" + ) + assert counts["ran"] == 0 + + +def test_watermark_is_stamped_after_a_complete_pass(): + conn = _conn(watermark_age_minutes=120, cutoff_id=None) + counts = _run(conn, prune_interval_minutes=60) + + stamps = [c for c in conn.execute.call_args_list + if "INSERT INTO system_settings" in str(c.args[0])] + assert len(stamps) == 1 + # args = (sql, key, json_value) + assert stamps[0].args[1] == "requestlog.last_pruned_at" + assert stamps[0].args[2].startswith('"'), ( + "the watermark must be stored as a JSON string — the ::jsonb cast rejects a bare " + "timestamp, and the reader json.loads() it back" + ) + assert counts["ran"] == 1 + + +def test_advisory_lock_is_released_even_on_failure(): + conn = _conn(watermark_age_minutes=120, fail_on=_SUCCESS_MARKER) + _run(conn, prune_interval_minutes=60) + + unlocks = [c for c in conn.execute.call_args_list if "pg_advisory_unlock" in str(c.args[0])] + assert unlocks, "the advisory lock was leaked — every later pass on any replica would skip" + assert unlocks[0].args[1] == PRUNE_LOCK_KEY + + +def test_never_raises_when_the_pool_is_exhausted(): + with patch.object(request_log_prune, "get_database_connection", + AsyncMock(side_effect=RuntimeError("pool exhausted"))), \ + patch.object(request_log_prune, "close_database_connection", AsyncMock()): + counts = asyncio.run(prune_request_logs_if_due()) + + assert counts == {"success": 0, "error": 0, "overflow": 0, "ran": 0} + + +def test_row_cap_is_a_noop_when_the_table_is_smaller_than_the_cap(): + conn = _conn(watermark_age_minutes=120, cutoff_id=None, cap_batches=["DELETE 77"]) + counts = _run(conn, prune_interval_minutes=60) + + assert counts["overflow"] == 0, ( + "the cap deleted rows even though OFFSET max_rows found no cutoff — that would " + "truncate a table that is under the limit" + ) + assert not any(_CAP_MARKER in s for s in _delete_sql(conn)) + + +def test_force_bypasses_the_watermark(): + """The manual purge button must not be a no-op just because the scheduled + pass ran a minute ago.""" + conn = _conn(watermark_age_minutes=1, cutoff_id=None, + success_batches=["DELETE 1"], error_batches=["DELETE 2"]) + counts = _run(conn, force=True, prune_interval_minutes=1440) + + assert counts["ran"] == 1 + assert counts["success"] == 1 + assert counts["error"] == 2 + + +def test_lock_key_does_not_collide_with_the_existing_ones(): + # 18181818 drafts cap, 18181819 wizard create, 18181820 apply, + # 0x41434D45 per-ACME-order, 1836016242 migration. + assert PRUNE_LOCK_KEY not in (18181818, 18181819, 18181820, 0x41434D45, 1836016242) diff --git a/backend/tests/test_request_log_redaction.py b/backend/tests/test_request_log_redaction.py new file mode 100644 index 0000000..04e032a --- /dev/null +++ b/backend/tests/test_request_log_redaction.py @@ -0,0 +1,262 @@ +"""v1.11.0: nothing secret reaches request_logs. + +The request/response log stores bodies and headers, so redaction is the single +control standing between "operators can debug a failing ACME order" and "the +audit table is a credential store". These tests pin both halves of that: the +things that MUST be redacted, and the innocent field names that must NOT be +(over-matching would silently blank out the fields the feature exists to show). +""" +import json +import os +import sys + +import pytest + +sys.path.insert(0, os.path.dirname(os.path.dirname(os.path.abspath(__file__)))) + +from utils.request_log_redaction import ( # noqa: E402 + REDACTED, + decode_body, + is_capturable_content_type, + is_secret_key, + redact, + redact_headers, + safe_error_text, + scrub_query_string, + scrub_url, +) + + +# -------------------------------------------------------------------------- +# Key matching +# -------------------------------------------------------------------------- + +@pytest.mark.parametrize("key", [ + "password", "PASSWORD", "Pass_Word", "passwd", "pwd", + # api_token is the literal field name of the Cloudflare provider credential + # (services/dns_providers/cloudflare.py) — it must never survive a round trip. + "token", "access_token", "refreshToken", "MFA_TOKEN", + "api_token", "agent_token", "csrf_token", "session_token", + "api_key", "API-KEY", "apiKey", "x-api-key", + "secret", "client_secret", "eab_hmac_key", + "private_key", "cert_private_key", "csr_private_key", "jwk_private_key", + "authorization", "cookie", "set-cookie", + "signature", "protected", "payload", "nonce", "replay-nonce", + "key_authorization", "backup_codes", "totp_secret", + "stats_password", "credentials", "encryption_key", +]) +def test_secret_keys_are_detected(key): + assert is_secret_key(key), f"{key!r} must be treated as a secret field name" + + +@pytest.mark.parametrize("key", [ + # Every one of these has a secret-looking substring but is innocent. If any + # starts redacting, the log stops being useful for the exact debugging it + # was built for. + "key_suffix", "monkey", "keyboard", "turkey", + "payload_size", "nonce_count", + "public_key_id", "keys_total", + "name", "status_code", "duration_ms", "domain", "directory_url", +]) +def test_innocent_keys_are_not_redacted(key): + assert not is_secret_key(key), ( + f"{key!r} was redacted by over-matching — the log would blank out a field " + f"operators need" + ) + + +# -------------------------------------------------------------------------- +# Recursive body redaction +# -------------------------------------------------------------------------- + +def test_nested_dicts_and_lists_are_redacted_recursively(): + body = { + "user": {"username": "admin", "password": "hunter2"}, + "accounts": [ + {"email": "a@example.com", "eab_hmac_key": "s3cr3t"}, + {"email": "b@example.com", "api_token": "cf-token"}, + ], + "cluster_id": 3, + } + out = redact(body) + + assert out["user"]["username"] == "admin" + assert out["user"]["password"] == REDACTED + assert out["accounts"][0]["email"] == "a@example.com" + assert out["accounts"][0]["eab_hmac_key"] == REDACTED + assert out["accounts"][1]["api_token"] == REDACTED + assert out["cluster_id"] == 3 + + +def test_depth_limit_stops_runaway_nesting(): + deep = current = {} + for _ in range(20): + current["child"] = {} + current = current["child"] + current["password"] = "leak" + + out = redact(deep) + flattened = json.dumps(out) + assert "***DEPTH_LIMIT***" in flattened + assert "leak" not in flattened + + +def test_node_budget_bounds_a_very_wide_body(): + wide = {f"field_{i}": i for i in range(5000)} + out = redact(wide) + assert out.get("_node_limit") is True + assert len(out) < 5000, "node budget did not bound a pathologically wide body" + + +def test_pem_private_key_is_redacted_by_value_shape(): + body = {"blob": "-----BEGIN RSA PRIVATE KEY-----\n" + "A" * 200 + "\n-----END RSA PRIVATE KEY-----"} + out = redact(body) + assert out["blob"] == REDACTED, ( + "a PEM private key under an innocent key name was stored verbatim" + ) + + +def test_jwt_shaped_string_is_redacted_by_value_shape(): + jwt_like = "eyJhbGciOiJIUzI1NiJ9." + "a" * 40 + "." + "b" * 40 + out = redact({"data": jwt_like}) + assert out["data"] == REDACTED + + +def test_long_strings_are_truncated_with_a_marker(): + out = redact({"note": "x" * 9000}) + assert out["note"].endswith("chars]") + assert len(out["note"]) < 9000 + + +def test_redact_never_raises_on_odd_input(): + class Weird: + def __repr__(self): + raise RuntimeError("boom") + + # Non-serializable leaf values must pass straight through, not explode. + assert redact({"x": Weird()}) is not None + + +# -------------------------------------------------------------------------- +# Headers (allowlist) +# -------------------------------------------------------------------------- + +def test_headers_use_an_allowlist_with_presence_markers(): + out = redact_headers({ + "Content-Type": "application/json", + "User-Agent": "curl/8.0", + "Authorization": "Bearer super-secret-token", + "Cookie": "session=abc", + "X-Custom-Internal": "some value", + }) + + assert out["content-type"] == "application/json" + assert out["user-agent"] == "curl/8.0" + # Presence is useful when debugging a 401; the value is not. + assert out["authorization"] == REDACTED + assert out["cookie"] == REDACTED + # Not on the allowlist and not a known credential header -> dropped entirely. + assert "x-custom-internal" not in out + + +def test_redact_headers_handles_none(): + assert redact_headers(None) is None + assert redact_headers({}) is None + + +# -------------------------------------------------------------------------- +# URLs and query strings +# -------------------------------------------------------------------------- + +def test_query_string_secrets_are_scrubbed(): + scrubbed, as_dict = scrub_query_string("token=abc123&page=2&api_key=xyz") + assert "abc123" not in scrubbed + assert "xyz" not in scrubbed + assert "page=2" in scrubbed + assert as_dict["token"] == REDACTED + assert as_dict["page"] == "2" + + +def test_scrub_url_strips_userinfo_and_query_secrets(): + out = scrub_url("https://user:hunter2@api.example.com:8443/v1/zones?api_key=abc&page=1") + assert "hunter2" not in out + assert "user" not in out.split("/v1")[0].replace("api.example.com", "") + assert "abc" not in out + assert "api.example.com:8443" in out + assert "page=1" in out + + +def test_scrub_url_drops_the_fragment(): + # Fragments never reach a server, and they are a classic token carrier. + assert "#" not in scrub_url("https://example.com/x?a=1#access_token=leak") + + +# -------------------------------------------------------------------------- +# Body decoding, capping, truncation marker +# -------------------------------------------------------------------------- + +def test_decode_body_parses_and_redacts_json(): + raw = json.dumps({"username": "admin", "password": "hunter2"}).encode() + value, truncated = decode_body(raw, "application/json", len(raw)) + assert value["username"] == "admin" + assert value["password"] == REDACTED + assert truncated is False + + +def test_decode_body_marks_truncation_with_the_original_size(): + full = b"x" * 20000 + captured = full[:1024] + value, truncated = decode_body(captured, "text/plain", len(full)) + assert truncated is True + assert value["_truncated"] is True + assert value["_original_bytes"] == 20000 + + +def test_decode_body_wraps_non_json_as_raw_object(): + value, _ = decode_body(b"plain text response", "text/plain", 19) + assert value == {"_raw": "plain text response"} + + +def test_decode_body_survives_truncated_json(): + # A JSON body cut off at the cap will not parse — keep the prefix rather + # than losing the field entirely. + value, truncated = decode_body(b'{"a": "bb', "application/json", 500) + assert truncated is True + assert "_raw" in value + + +def test_decode_body_parses_form_encoded(): + value, _ = decode_body(b"username=admin&password=hunter2", + "application/x-www-form-urlencoded", 30) + assert value["username"] == "admin" + assert value["password"] == REDACTED + + +def test_decode_body_returns_none_for_empty(): + assert decode_body(b"", "application/json", 0) == (None, False) + assert decode_body(None, "application/json", 0) == (None, False) + + +def test_binary_content_types_are_not_capturable(): + assert is_capturable_content_type("application/json") + assert is_capturable_content_type("application/json; charset=utf-8") + assert is_capturable_content_type("text/plain") + assert not is_capturable_content_type("application/octet-stream") + assert not is_capturable_content_type("image/png") + assert not is_capturable_content_type("text/event-stream") + + +# -------------------------------------------------------------------------- +# Error rendering +# -------------------------------------------------------------------------- + +def test_safe_error_text_type_only_hides_the_message(): + exc = ValueError("https://api.godaddy.com/v1/domains/secret-zone/records failed") + assert safe_error_text(exc, type_only=True) == "ValueError" + assert "godaddy" not in safe_error_text(exc, type_only=True) + + +def test_safe_error_text_includes_the_message_when_allowed(): + text = safe_error_text(RuntimeError("connection refused")) + assert text.startswith("RuntimeError") + assert "connection refused" in text diff --git a/backend/tests/test_request_log_router_auth.py b/backend/tests/test_request_log_router_auth.py new file mode 100644 index 0000000..e498885 --- /dev/null +++ b/backend/tests/test_request_log_router_auth.py @@ -0,0 +1,176 @@ +"""v1.11.0: the request log API is gated, and its routes resolve. + +Two distinct failure modes are pinned here. + +**Auth.** The table holds redacted-but-real request and response bodies for +every user, so an unauthenticated or under-privileged caller must never get a +row. There is no database in this suite, so the behavioural checks assert only +that an anonymous call is rejected before any DB work — which is exactly the +property that matters — and a source scan covers the per-endpoint permission. + +**Route order.** `/{log_id}` is a single-segment path and FastAPI matches in +declaration order, so declaring it before `/settings`, `/stats` or `/purge` +makes those three unreachable (they parse as a log id and 422). This is the +mirror image of the shadowing trap already present in routers/settings.py. +""" +import os +import re +import sys + +import pytest + +sys.path.insert(0, os.path.dirname(os.path.dirname(os.path.abspath(__file__)))) + +_BACKEND = os.path.dirname(os.path.dirname(os.path.abspath(__file__))) +_ROUTER = os.path.join(_BACKEND, "routers", "request_logs.py") +_MAIN = os.path.join(_BACKEND, "main.py") + +REJECT = (401, 403, 422) + + +@pytest.fixture(scope="module") +def src(): + with open(_ROUTER, encoding="utf-8") as f: + return f.read() + + +# -------------------------------------------------------------------------- +# Behavioural: nothing is readable without credentials +# -------------------------------------------------------------------------- + +@pytest.mark.parametrize("method,path", [ + ("get", "/api/request-logs"), + ("get", "/api/request-logs/1"), + ("get", "/api/request-logs/stats"), + ("get", "/api/request-logs/settings"), + ("put", "/api/request-logs/settings"), + ("post", "/api/request-logs/purge"), +]) +def test_anonymous_access_is_rejected(client, method, path): + res = getattr(client, method)(path) if method != "put" else client.put(path, json={}) + assert res.status_code in REJECT, ( + f"{method.upper()} {path} returned {res.status_code} without an Authorization " + f"header — the request log contains captured bodies for every user" + ) + + +def test_a_garbage_token_is_rejected(client): + res = client.get("/api/request-logs", headers={"authorization": "Bearer not-a-token"}) + assert res.status_code in REJECT + + +# -------------------------------------------------------------------------- +# Source scan: per-endpoint permission +# -------------------------------------------------------------------------- + +def _handler_body(src, decorator): + start = src.index(decorator) + rest = src[start + len(decorator):] + end = rest.find("\n@router.") + return rest if end == -1 else rest[:end] + + +@pytest.mark.parametrize("decorator,action", [ + ('@router.get("/settings")', "manage"), + ('@router.put("/settings")', "manage"), + ('@router.get("/stats")', "read"), + ('@router.post("/purge")', "manage"), + ('@router.get("")', "read"), + ('@router.get("/{log_id}")', "read"), +]) +def test_every_endpoint_enforces_its_permission(src, decorator, action): + body = _handler_body(src, decorator) + assert f'_require(authorization, "{action}")' in body, ( + f"{decorator} does not enforce requestlog.{action}" + ) + + +def test_require_helper_raises_403_not_a_silent_pass(src): + helper = src.split("async def _require", 1)[1].split("\nasync def ", 1)[0] + assert "check_user_permission" in helper + assert "status_code=403" in helper + assert "current_user=current_user" in helper, ( + "the admin bypass is skipped, so every call pays an extra SELECT on users" + ) + + +# -------------------------------------------------------------------------- +# Route declaration order +# -------------------------------------------------------------------------- + +@pytest.mark.parametrize("literal", ['@router.get("/settings")', '@router.put("/settings")', + '@router.get("/stats")', '@router.post("/purge")']) +def test_literal_routes_are_declared_before_the_catch_all(src, literal): + catch_all = src.index('@router.get("/{log_id}")') + assert src.index(literal) < catch_all, ( + f"{literal} is declared after GET /{{log_id}}. FastAPI matches in declaration " + f"order and /{{log_id}} is a single-segment path, so it would swallow this route " + f"and the request would fail parsing 'settings' as an int." + ) + + +def test_list_route_is_declared_before_the_catch_all(src): + assert src.index('@router.get("")') < src.index('@router.get("/{log_id}")') + + +# -------------------------------------------------------------------------- +# Query construction +# -------------------------------------------------------------------------- + +def test_filters_are_bound_never_interpolated(src): + """User-supplied filters reach the WHERE clause; they must arrive as $n + parameters.""" + body = _handler_body(src, '@router.get("")') + # The only f-string interpolation allowed into SQL is the placeholder index + # and the assembled clause list, never a raw value. + for match in re.findall(r'add\("([^"]+)"', body): + assert "{n}" in match, f"filter clause {match!r} does not use a bound placeholder" + + +def test_list_endpoint_scopes_non_privileged_callers_to_themselves(src): + body = _handler_body(src, '@router.get("")') + assert "if not can_manage:" in body + assert "direction = 'inbound' AND user_id =" in body, ( + "a caller with only requestlog.read can see every other user's captured request " + "bodies" + ) + + +def test_detail_endpoint_applies_the_same_scoping(src): + body = _handler_body(src, '@router.get("/{log_id}")') + assert "can_manage" in body + assert "404" in body, ( + "the detail endpoint should 404 rather than 403 for a row the caller may not see, " + "so it does not confirm which ids exist" + ) + + +def test_list_response_omits_bodies(src): + """A 200-row page carrying two 8 KB JSONB blobs per row is a multi-megabyte + response; bodies belong to the detail endpoint.""" + columns = src.split("_LIST_COLUMNS = ", 1)[1].split('"""', 2)[1] + assert "request_body," not in columns + assert "response_body," not in columns + assert "request_body_bytes" in columns, "the size is still useful in the list" + + +def test_count_is_bounded(src): + body = _handler_body(src, '@router.get("")') + assert "LIMIT {count_cap}" in body or "count_cap" in body, ( + "an unbounded COUNT(*) over request_logs is a sequential scan on every page change" + ) + assert "total_is_estimate" in body + + +# -------------------------------------------------------------------------- +# Registration +# -------------------------------------------------------------------------- + +def test_router_is_registered_in_main(): + with open(_MAIN, encoding="utf-8") as f: + main_src = f.read() + + assert "from routers.request_logs import router as request_logs_router" in main_src + assert "app.include_router(request_logs_router)" in main_src, ( + "the router is imported but never mounted, so every endpoint 404s" + ) diff --git a/backend/tests/test_request_log_settings.py b/backend/tests/test_request_log_settings.py new file mode 100644 index 0000000..1c3db77 --- /dev/null +++ b/backend/tests/test_request_log_settings.py @@ -0,0 +1,258 @@ +"""v1.11.0: the retention policy the operator sees is the policy that runs. + +Two things drift silently and are caught here: + + 1. The defaults live in TWO places — the seed SQL in migrations.py and the + dataclass in utils/request_log_settings.py. If they disagree, a fresh + install and an upgraded install behave differently, which is the worst + kind of bug to chase. + 2. Values in `system_settings` are operator-editable and arrive from asyncpg + as raw JSON *strings*. Anything out of range, mistyped or hand-edited must + be clamped rather than crash the writer loop. +""" +import asyncio +import json +import os +import re +import sys +from unittest.mock import AsyncMock, patch + +import pytest + +sys.path.insert(0, os.path.dirname(os.path.dirname(os.path.abspath(__file__)))) + +from utils import request_log_settings # noqa: E402 +from utils.request_log_settings import ( # noqa: E402 + DEFAULT_CONFIG, + DEFAULT_EXCLUDE_PATHS, + RequestLogConfig, + config_from_mapping, + get_config, + normalize_exclude_paths, + refresh_config, + set_config, +) + +_MIGRATIONS = os.path.join( + os.path.dirname(os.path.dirname(os.path.abspath(__file__))), "database", "migrations.py" +) + + +def _seeded_defaults(): + """Parse the ('requestlog.x', 'value', ...) tuples out of the seed SQL.""" + with open(_MIGRATIONS, encoding="utf-8") as f: + src = f.read() + + body = src.split("async def ensure_request_log_settings", 1)[1].split("\nasync def ", 1)[0] + out = {} + for key, raw in re.findall(r"\('requestlog\.(\w+)', '(.*?)', 'requestlog'", body): + try: + out[key] = json.loads(raw) + except json.JSONDecodeError: + out[key] = raw + return out + + +# -------------------------------------------------------------------------- +# Defaults must not drift between the seed and the code +# -------------------------------------------------------------------------- + +def test_seed_and_dataclass_defaults_agree(): + seeded = _seeded_defaults() + assert seeded, "could not parse the requestlog seed rows out of migrations.py" + + code = DEFAULT_CONFIG.as_dict() + for key, seed_value in seeded.items(): + assert key in code, f"migrations seeds requestlog.{key} but RequestLogConfig has no such field" + assert code[key] == seed_value, ( + f"requestlog.{key} default drifted: migrations.py seeds {seed_value!r} but " + f"RequestLogConfig has {code[key]!r}. A fresh install and an upgraded install " + f"would then behave differently." + ) + + for key in code: + assert key in seeded, ( + f"RequestLogConfig has {key!r} but migrations.py does not seed requestlog.{key} — " + f"existing installs would silently fall back to the in-code default" + ) + + +def test_log_viewer_is_excluded_by_default(): + assert "/api/request-logs" in DEFAULT_EXCLUDE_PATHS + assert "/api/health" in DEFAULT_EXCLUDE_PATHS + assert "/.well-known/acme-challenge" in DEFAULT_EXCLUDE_PATHS, ( + "the ACME challenge endpoint returns key_authorization — logging it would store " + "the challenge secret" + ) + assert "/api/agents/heartbeat" in DEFAULT_EXCLUDE_PATHS, ( + "the agent heartbeat is the highest-volume POST in the system; logging it by " + "default would dominate the table" + ) + + +def test_error_retention_defaults_longer_than_success_retention(): + assert DEFAULT_CONFIG.error_retention_days > DEFAULT_CONFIG.success_retention_days, ( + "the whole point of splitting the two is to keep failures around after the " + "ordinary traffic has aged out" + ) + + +# -------------------------------------------------------------------------- +# Coercion and clamping +# -------------------------------------------------------------------------- + +def test_raw_json_strings_from_asyncpg_are_parsed(): + cfg = config_from_mapping({ + "enabled": True, + "max_body_bytes": 4096, + "sample_rate": 0.25, + "success_retention_days": 3, + "exclude_paths": ["/api/health", "/metrics"], + }) + assert cfg.enabled is True + assert cfg.max_body_bytes == 4096 + assert cfg.sample_rate == 0.25 + assert cfg.success_retention_days == 3 + assert cfg.exclude_paths == ("/api/health", "/metrics") + + +@pytest.mark.parametrize("raw,expected", [ + ("true", True), ("false", False), ("1", True), ("0", False), + ("on", True), ("off", False), (1, True), (0, False), (True, True), +]) +def test_boolean_coercion_accepts_hand_written_values(raw, expected): + cfg = config_from_mapping({"enabled": raw}) + assert cfg.enabled is expected + + +@pytest.mark.parametrize("field,value,expected", [ + ("max_body_bytes", 10_000_000, 262144), + ("max_body_bytes", -5, 0), + ("success_retention_days", 0, 1), + ("success_retention_days", 9999, 365), + ("error_retention_days", 0, 1), + ("max_rows", 10, 1000), + ("prune_interval_minutes", 1, 5), + ("prune_interval_minutes", 99999, 1440), +]) +def test_out_of_range_values_are_clamped_not_rejected(field, value, expected): + """A bad value in the table must not disable logging or crash the writer — + it is clamped to the nearest sane bound.""" + cfg = config_from_mapping({field: value}) + assert getattr(cfg, field) == expected + + +@pytest.mark.parametrize("value,expected", [(1.5, 1.0), (-0.2, 0.0), ("0.4", 0.4)]) +def test_sample_rate_is_clamped(value, expected): + assert config_from_mapping({"sample_rate": value}).sample_rate == expected + + +def test_garbage_values_fall_back_to_the_default(): + cfg = config_from_mapping({"max_body_bytes": "not-a-number", "sample_rate": "abc"}) + assert cfg.max_body_bytes == DEFAULT_CONFIG.max_body_bytes + assert cfg.sample_rate == DEFAULT_CONFIG.sample_rate + + +def test_exclude_paths_shape_is_enforced(): + out = normalize_exclude_paths( + ["/good", "no-leading-slash", "/" + "x" * 500, 42, "/also-good"], + DEFAULT_EXCLUDE_PATHS, + ) + assert out == ("/good", "/also-good") + + +def test_exclude_paths_count_is_bounded(): + out = normalize_exclude_paths([f"/p{i}" for i in range(500)], DEFAULT_EXCLUDE_PATHS) + assert len(out) <= 64 + + +def test_empty_exclude_paths_falls_back_rather_than_logging_everything(): + """An empty list would re-enable logging of health checks and the docs, and + flood the table — treat it as 'not configured'.""" + assert normalize_exclude_paths([], DEFAULT_EXCLUDE_PATHS) == DEFAULT_EXCLUDE_PATHS + assert normalize_exclude_paths(None, DEFAULT_EXCLUDE_PATHS) == DEFAULT_EXCLUDE_PATHS + + +def test_partial_mapping_keeps_the_other_defaults(): + cfg = config_from_mapping({"sample_rate": 0.5}) + assert cfg.sample_rate == 0.5 + assert cfg.success_retention_days == DEFAULT_CONFIG.success_retention_days + assert cfg.enabled is DEFAULT_CONFIG.enabled + + +# -------------------------------------------------------------------------- +# refresh_config +# -------------------------------------------------------------------------- + +def test_refresh_config_parses_the_raw_jsonb_strings_asyncpg_returns(): + conn = AsyncMock() + conn.fetch = AsyncMock(return_value=[ + {"key": "requestlog.enabled", "value": "false"}, + {"key": "requestlog.max_body_bytes", "value": "4096"}, + {"key": "requestlog.sample_rate", "value": "0.5"}, + {"key": "requestlog.exclude_paths", "value": '["/api/health","/metrics"]'}, + ]) + + with patch.object(request_log_settings, "get_database_connection", AsyncMock(return_value=conn)), \ + patch.object(request_log_settings, "close_database_connection", AsyncMock()): + cfg = asyncio.run(refresh_config()) + + assert cfg.enabled is False + assert cfg.max_body_bytes == 4096 + assert cfg.sample_rate == 0.5 + assert cfg.exclude_paths == ("/api/health", "/metrics") + + set_config(DEFAULT_CONFIG) + + +def test_refresh_config_keeps_the_previous_snapshot_on_db_failure(): + """A transient pool error must not silently flip logging on or off.""" + known = RequestLogConfig(enabled=False, sample_rate=0.1) + set_config(known) + + with patch.object(request_log_settings, "get_database_connection", + AsyncMock(side_effect=RuntimeError("pool exhausted"))), \ + patch.object(request_log_settings, "close_database_connection", AsyncMock()): + cfg = asyncio.run(refresh_config()) + + assert cfg.enabled is False + assert cfg.sample_rate == 0.1 + set_config(DEFAULT_CONFIG) + + +def test_get_config_is_synchronous_and_needs_no_database(): + """The middleware calls this on every request; it must never await.""" + assert not asyncio.iscoroutinefunction(get_config) + assert isinstance(get_config(), RequestLogConfig) + + +# -------------------------------------------------------------------------- +# The Pydantic model the API exposes +# -------------------------------------------------------------------------- + +def test_api_model_defaults_match_the_dataclass(): + from routers.request_logs import RequestLogSettings + + model = RequestLogSettings().model_dump() + code = DEFAULT_CONFIG.as_dict() + for key, value in code.items(): + assert model[key] == value, f"API model default for {key} disagrees with RequestLogConfig" + + +@pytest.mark.parametrize("payload", [ + {"max_body_bytes": 999999}, + {"success_retention_days": 0}, + {"error_retention_days": 400}, + {"sample_rate": 1.5}, + {"max_rows": 10}, + {"prune_interval_minutes": 1}, + {"exclude_paths": ["no-slash"]}, + {"exclude_paths": ["/" + "x" * 300]}, +]) +def test_api_model_rejects_out_of_range_input(payload): + from pydantic import ValidationError + + from routers.request_logs import RequestLogSettings + + with pytest.raises(ValidationError): + RequestLogSettings(**payload) diff --git a/backend/tests/test_request_log_sink.py b/backend/tests/test_request_log_sink.py new file mode 100644 index 0000000..20357ce --- /dev/null +++ b/backend/tests/test_request_log_sink.py @@ -0,0 +1,276 @@ +"""v1.11.0: the batching writer must never slow down or break a request. + +One row per API call is the highest write volume in the system and the asyncpg +pool (min=10/max=50) is shared with every handler and four background loops. So +the hot path enqueues and returns; a single writer task batches and inserts. +The properties pinned here: + + * `offer()` never blocks and never raises — a full queue drops and counts; + * the parameter list stays aligned with the INSERT placeholders (a column + added to one and not the other would fail every write at runtime, in + production, with the migration already applied); + * a failed batch is dropped with a warning rather than killing the loop. +""" +import asyncio +import json +import os +import re +import sys +from datetime import datetime, timezone +from unittest.mock import AsyncMock, patch + +import pytest + +sys.path.insert(0, os.path.dirname(os.path.dirname(os.path.abspath(__file__)))) + +from dataclasses import replace # noqa: E402 + +from utils import request_log_settings # noqa: E402 +from utils import request_log_sink as sink_module # noqa: E402 +from utils.request_log_sink import ( # noqa: E402 + RequestLogRow, + RequestLogSink, + _INSERT_SQL, +) +from utils.request_log_settings import DEFAULT_CONFIG # noqa: E402 + + +def _row(**overrides): + base = dict( + request_id="abc123", + direction="inbound", + method="POST", + url="/api/backends", + path="/api/backends", + status_code=200, + duration_ms=12, + created_at=datetime(2026, 8, 11, 9, 0, tzinfo=timezone.utc), + ) + base.update(overrides) + return RequestLogRow(**base) + + +@pytest.fixture(autouse=True) +def defaults(monkeypatch): + monkeypatch.setattr(request_log_settings, "_CACHE", DEFAULT_CONFIG) + monkeypatch.setattr(sink_module, "get_config", lambda: request_log_settings._CACHE) + + +def _set(monkeypatch, **overrides): + monkeypatch.setattr(request_log_settings, "_CACHE", replace(DEFAULT_CONFIG, **overrides)) + + +# -------------------------------------------------------------------------- +# SQL / parameter alignment +# -------------------------------------------------------------------------- + +def test_insert_placeholders_match_the_column_list(): + columns = _INSERT_SQL.split("(", 1)[1].split(")", 1)[0] + n_columns = len([c for c in columns.split(",") if c.strip()]) + n_placeholders = len(set(re.findall(r"\$(\d+)", _INSERT_SQL))) + + assert n_columns == n_placeholders, ( + f"the INSERT names {n_columns} columns but binds {n_placeholders} placeholders — " + f"every write would fail at runtime, on a database where the migration has " + f"already succeeded" + ) + + +def test_row_produces_exactly_as_many_params_as_the_insert_binds(): + n_placeholders = len(set(re.findall(r"\$(\d+)", _INSERT_SQL))) + assert len(_row().to_params()) == n_placeholders, ( + "RequestLogRow.to_params() drifted from _INSERT_SQL" + ) + + +def test_jsonb_params_are_serialized_strings_not_dicts(): + """No JSONB codec is registered on this pool, so JSONB values travel as text + and are cast in SQL — handing asyncpg a dict raises.""" + row = _row( + query_params={"page": "2"}, + request_headers={"content-type": "application/json"}, + request_body_value={"name": "web"}, + ) + params = row.to_params() + + for value in params: + assert not isinstance(value, (dict, list)), ( + f"{value!r} was passed as a Python container; asyncpg cannot bind it to a " + f"jsonb parameter" + ) + + assert json.loads(params[6]) == {"page": "2"} + + +def test_client_ip_is_never_a_placeholder_string(): + """client_ip is an INET column: 'unknown' or a comma-joined X-Forwarded-For + raises on INSERT.""" + params = _row(client_ip=None).to_params() + assert params[12] is None + + +def test_status_class_is_zero_when_there_was_no_response(): + assert _row(status_code=None).status_class == 0 + assert _row(status_code=204).status_class == 2 + assert _row(status_code=503).status_class == 5 + + +# -------------------------------------------------------------------------- +# offer(): the hot path +# -------------------------------------------------------------------------- + +def test_offer_drops_and_counts_when_the_queue_is_full(): + sink = RequestLogSink(maxsize=3, batch_size=10, flush_ms=10) + + async def run(): + for _ in range(10): + sink.offer(_row()) + + asyncio.run(run()) + + assert sink.stats["queued"] == 3 + assert sink.stats["dropped"] == 7, ( + "a full queue must drop and count, never block the request or raise" + ) + + +def test_offer_never_raises_on_a_broken_row(): + sink = RequestLogSink(maxsize=10, batch_size=10, flush_ms=10) + + async def run(): + sink.offer(None) # not a RequestLogRow at all + + asyncio.run(run()) # must not raise + + +def test_offer_respects_the_kill_switch(monkeypatch): + _set(monkeypatch, enabled=False) + sink = RequestLogSink(maxsize=10, batch_size=10, flush_ms=10) + + asyncio.run(_offer(sink, _row())) + assert sink.stats["queued"] == 0 + + +def test_offer_respects_the_per_direction_switches(monkeypatch): + _set(monkeypatch, capture_outbound=False) + sink = RequestLogSink(maxsize=10, batch_size=10, flush_ms=10) + + async def run(): + sink.offer(_row(direction="outbound", target="acme")) + sink.offer(_row(direction="inbound")) + + asyncio.run(run()) + assert sink.stats["queued"] == 1 + + +def test_sampling_never_drops_errors(monkeypatch): + """A sample rate of zero must still capture every failure — that is the whole + point of sampling successes only.""" + _set(monkeypatch, sample_rate=0.0) + sink = RequestLogSink(maxsize=100, batch_size=10, flush_ms=10) + + async def run(): + for _ in range(20): + sink.offer(_row(status_code=200)) + for _ in range(5): + sink.offer(_row(status_code=500)) + for _ in range(5): + sink.offer(_row(status_code=None)) + + asyncio.run(run()) + assert sink.stats["queued"] == 10, ( + "sampling removed error rows; only 1xx/2xx/3xx inbound traffic may be sampled out" + ) + + +def test_sampling_does_not_touch_outbound_rows(monkeypatch): + _set(monkeypatch, sample_rate=0.0) + sink = RequestLogSink(maxsize=100, batch_size=10, flush_ms=10) + + async def run(): + for _ in range(5): + sink.offer(_row(direction="outbound", target="acme", status_code=200)) + + asyncio.run(run()) + assert sink.stats["queued"] == 5, ( + "outbound calls are low-volume and high-value; sampling them away hides which CA " + "or DNS call was made" + ) + + +def test_capture_bodies_off_strips_the_payload_before_queueing(monkeypatch): + _set(monkeypatch, capture_bodies=False) + sink = RequestLogSink(maxsize=10, batch_size=10, flush_ms=10) + row = _row(request_body_raw=b'{"a":1}', request_body_bytes=7) + + asyncio.run(_offer(sink, row)) + + assert row.request_body_raw is None + assert row.request_body_bytes == 7, "the size must survive so growth is still measurable" + + +async def _offer(sink, row): + sink.offer(row) + + +# -------------------------------------------------------------------------- +# The writer +# -------------------------------------------------------------------------- + +def test_a_batch_is_written_with_one_executemany(): + conn = AsyncMock() + sink = RequestLogSink(maxsize=100, batch_size=10, flush_ms=10) + + async def run(): + for _ in range(5): + sink.offer(_row()) + with patch.object(sink_module, "get_database_connection", AsyncMock(return_value=conn)), \ + patch.object(sink_module, "close_database_connection", AsyncMock()): + return await sink.flush(timeout=1.0) + + written = asyncio.run(run()) + + assert written == 5 + assert conn.executemany.await_count == 1, ( + "rows were inserted one at a time; that is one pool acquire per API call and the " + "pool has 50 connections" + ) + sql, params = conn.executemany.await_args.args + assert "INSERT INTO request_logs" in sql + assert len(params) == 5 + + +def test_a_failed_batch_does_not_kill_the_writer(): + conn = AsyncMock() + conn.executemany = AsyncMock(side_effect=RuntimeError("relation does not exist")) + sink = RequestLogSink(maxsize=100, batch_size=10, flush_ms=10) + + async def run(): + sink.offer(_row()) + with patch.object(sink_module, "get_database_connection", AsyncMock(return_value=conn)), \ + patch.object(sink_module, "close_database_connection", AsyncMock()): + await sink.flush(timeout=1.0) + + asyncio.run(run()) # must not raise + assert sink.stats["failed_batches"] == 1 + + +def test_the_connection_is_released_even_when_the_write_fails(): + conn = AsyncMock() + conn.executemany = AsyncMock(side_effect=RuntimeError("boom")) + release = AsyncMock() + sink = RequestLogSink(maxsize=100, batch_size=10, flush_ms=10) + + async def run(): + sink.offer(_row()) + with patch.object(sink_module, "get_database_connection", AsyncMock(return_value=conn)), \ + patch.object(sink_module, "close_database_connection", release): + await sink.flush(timeout=1.0) + + asyncio.run(run()) + assert release.await_count == 1, "a failed batch leaked a pooled connection" + + +def test_flush_on_an_empty_queue_is_a_noop(): + sink = RequestLogSink(maxsize=10, batch_size=10, flush_ms=10) + assert asyncio.run(sink.flush(timeout=0.1)) == 0 diff --git a/backend/utils/http_instrumentation.py b/backend/utils/http_instrumentation.py new file mode 100644 index 0000000..17e65e4 --- /dev/null +++ b/backend/utils/http_instrumentation.py @@ -0,0 +1,302 @@ +"""v1.11.0 — outbound half of the unified request/response log. + +This is deliberately NOT a session or connector factory. Three incompatible +connector policies coexist in this codebase: + + * `utils.ssrf_guard.safe_connector()` — IPv4-pinned, TLS verification on; + returns a NEW connector per call because `ClientSession` closes the one it + owns, so a shared long-lived connector would raise "Connector is closed". + * `services/acme_diagnostics.py` — IPv4-pinned with `ssl=False` for the + plain-HTTP port-80 probe. + * the DNS providers and the CA-chain import — the default dual-stack + connector. + +On top of that, `backend/tests/test_acme_diagnostics.py` monkeypatches +`aiohttp.ClientSession` globally with fakes that implement only +`__aenter__/__aexit__/head(...)`. Centralising session construction would break +all of it. So this module wraps the CALL, never the session. + +Two hard rules, both load-bearing: + +1. `outbound_span` NEVER raises. Both DNS provider funnels end in + `except Exception: raise DnsProviderError("Unexpected ... failure")`, and in + GoDaddy's publish path that reverts `dns_record_published` and stalls the + ACME order — an instrumentation bug must not masquerade as a provider + outage. +2. `outbound_span` NEVER swallows. An exception raised inside the block is + recorded (status_class 0) and re-raised unchanged. +""" +import asyncio +import logging +import time +from contextlib import asynccontextmanager +from typing import Any, Dict, Optional + +from utils.request_log_redaction import safe_error_text, scrub_query_string, scrub_url +from utils.request_log_settings import get_config +from utils.request_log_sink import RequestLogRow, request_id_context, request_log_sink + +logger = logging.getLogger("haproxy_openmanager.request_log") + +# Stable identifiers for the `request_logs.target` column — this is the +# "kime gitti" (who did we call) axis of the log. +TARGET_ACME = "acme" +TARGET_ACME_DIAG = "acme_diag" +TARGET_LETSENCRYPT_CA = "letsencrypt_ca" +TARGET_DNS_CLOUDFLARE = "dns_cloudflare" +TARGET_DNS_GODADDY = "dns_godaddy" +TARGET_AGENT = "agent" +TARGET_HAPROXY_STATS = "haproxy_stats" +TARGET_SETTINGS_PROBE = "settings_probe" + + +def _correlation_id() -> str: + """Inherit the inbound request's id when there is one, so an API call and + the CA/DNS calls it triggered share a trace. Background loops (ACME + renewal, order completion) get a `bg:` id instead.""" + existing = request_id_context.get() + if existing: + return existing + try: + task = asyncio.current_task() + name = task.get_name() if task else "unknown" + except Exception: + name = "unknown" + return f"bg:{name}"[:64] + + +class OutboundSpan: + """Handle passed to the `async with` body so the call site can attach the + response it just read.""" + + __slots__ = ( + "target", "method", "url", "capture_request_body", "capture_response_body", + "safe_error_only", + "_status", "_response_headers", "_response_body", "_response_bytes", + "_response_content_type", "_request_body", "_request_headers", "_error", + ) + + def __init__( + self, + *, + target: str, + method: str, + url: str, + capture_request_body: bool, + capture_response_body: bool, + safe_error_only: bool, + request_body: Any = None, + request_headers: Optional[Dict[str, str]] = None, + ): + self.target = target + self.method = (method or "GET").upper() + self.url = url + # Two independent switches on purpose: the ACME JWS request body is a + # replayable credential and must never be stored, but the CA's RESPONSE + # (problem JSON, order state) is exactly what an operator needs to see. + self.capture_request_body = capture_request_body + self.capture_response_body = capture_response_body + self.safe_error_only = safe_error_only + self._request_body = request_body + self._request_headers = request_headers + self._status: Optional[int] = None + self._response_headers: Optional[Dict[str, str]] = None + self._response_body: Any = None + self._response_bytes: int = 0 + self._response_content_type: Optional[str] = None + self._error: Optional[str] = None + + def set_response( + self, + status: Optional[int], + headers: Optional[Dict[str, str]] = None, + body: Any = None, + ) -> None: + """Record what came back. Safe to call with a partially-read response; + never raises, so a call site can hand us whatever it happens to have.""" + try: + self._status = int(status) if status is not None else None + except (TypeError, ValueError): + self._status = None + try: + if headers: + self._response_headers = {str(k).lower(): str(v) for k, v in dict(headers).items()} + self._response_content_type = self._response_headers.get("content-type") + except Exception: + self._response_headers = None + + if body is None or not self.capture_response_body: + return + try: + if isinstance(body, (bytes, bytearray)): + self._response_bytes = len(body) + cap = get_config().max_body_bytes + self._response_body = bytes(body[:cap]) if cap else None + elif isinstance(body, str): + encoded = body.encode("utf-8", "replace") + self._response_bytes = len(encoded) + cap = get_config().max_body_bytes + self._response_body = encoded[:cap] if cap else None + else: + # Already-decoded JSON (the common case: `await resp.json()`). + self._response_body = body + except Exception: + self._response_body = None + + def set_error(self, exc: BaseException, *, type_only: Optional[bool] = None) -> None: + try: + only = self.safe_error_only if type_only is None else type_only + self._error = safe_error_text(exc, type_only=only) + except Exception: + self._error = "UnknownError" + + def to_row(self, duration_ms: int) -> RequestLogRow: + scrubbed = scrub_url(self.url) + path = None + query_params = None + try: + import urllib.parse + + parts = urllib.parse.urlsplit(self.url) + path = parts.path or "/" + _, query_params = scrub_query_string(parts.query) + except Exception: + pass + + row = RequestLogRow( + request_id=_correlation_id(), + direction="outbound", + target=self.target, + method=self.method, + url=scrubbed, + path=path, + query_params=query_params, + status_code=self._status, + duration_ms=duration_ms, + request_headers=self._request_headers, + response_headers=self._response_headers, + error=self._error, + ) + + if self._request_body is not None: + if not self.capture_request_body: + # The call site handed us a synthetic SUMMARY instead of the real + # payload (the ACME JWS case) — store the summary as-is. + row.request_body_value = _redacted_value(self._request_body) + elif isinstance(self._request_body, (bytes, bytearray)): + row.request_body_bytes = len(self._request_body) + cap = get_config().max_body_bytes + row.request_body_raw = bytes(self._request_body[:cap]) if cap else None + else: + row.request_body_value = _redacted_value(self._request_body) + + if isinstance(self._response_body, (bytes, bytearray)): + row.response_body_raw = bytes(self._response_body) + row.response_body_bytes = self._response_bytes or len(self._response_body) + row.response_content_type = self._response_content_type + elif self._response_body is not None: + row.response_body_value = _redacted_value(self._response_body) + + return row + + +def _redacted_value(value: Any) -> Any: + from utils.request_log_redaction import redact + + return redact(value) + + +@asynccontextmanager +async def outbound_span( + *, + target: str, + method: str, + url: str, + request_body: Any = None, + request_headers: Optional[Dict[str, str]] = None, + capture_body: bool = True, + capture_response_body: bool = True, + safe_error_only: bool = False, +): + """Time an outbound HTTP call and record one `direction='outbound'` row. + + `capture_body=False` applies to the REQUEST body only, for payloads that + are themselves credentials — the ACME JWS body is a replayable, signed + capability for the lifetime of its nonce, so the call site passes a + description of it instead. The CA's response is still captured, because + that is the half an operator actually needs when an order fails. + + `safe_error_only=True` reduces a recorded exception to its type name, for + the DNS providers whose own error handling already refuses to surface + `str(exc)` (it can carry the request URL and, through it, zone identifiers). + """ + span: Optional[OutboundSpan] = None + started = time.perf_counter() + try: + cfg = get_config() + if cfg.enabled and cfg.capture_outbound: + span = OutboundSpan( + target=target, + method=method, + url=url, + capture_request_body=capture_body and cfg.capture_bodies, + capture_response_body=capture_response_body and cfg.capture_bodies, + safe_error_only=safe_error_only, + request_body=request_body, + request_headers=request_headers, + ) + except Exception as exc: # pragma: no cover - defensive + logger.debug(f"outbound_span: could not start span for {target}: {exc}") + span = None + + if span is None: + # Logging is off (or failed to initialise) — yield a throwaway span so + # the call site's `span.set_response(...)` still works. + span = OutboundSpan( + target=target, method=method, url=url, + capture_request_body=False, capture_response_body=False, + safe_error_only=safe_error_only, + ) + try: + yield span + finally: + pass + return + + try: + yield span + except BaseException as exc: + try: + span.set_error(exc) + except Exception: + pass + raise + finally: + try: + duration_ms = int((time.perf_counter() - started) * 1000) + request_log_sink.offer(span.to_row(duration_ms)) + except Exception as exc: # pragma: no cover - defensive + logger.debug(f"outbound_span: failed to record row for {target}: {exc}") + + +async def instrumented_request(session, method: str, url: str, *, target: str, + safe_error_only: bool = True, capture_body: bool = True, + **kwargs): + """Convenience wrapper for the call sites that already funnel through + `session.request(...)` (the two DNS providers). + + Returns `(status, headers, text)` and leaves error handling entirely to the + caller — this helper only adds the log row. + """ + async with outbound_span( + target=target, + method=method, + url=url, + request_body=kwargs.get("json"), + capture_body=capture_body, + safe_error_only=safe_error_only, + ) as span: + async with session.request(method, url, **kwargs) as resp: + text = await resp.text() + span.set_response(resp.status, dict(resp.headers), text) + return resp.status, dict(resp.headers), text diff --git a/backend/utils/request_log_prune.py b/backend/utils/request_log_prune.py new file mode 100644 index 0000000..ac32ff5 --- /dev/null +++ b/backend/utils/request_log_prune.py @@ -0,0 +1,201 @@ +"""v1.11.0 — retention prune for `request_logs`. + +Three independent limits, applied in order: + + 1. successful rows (`status_class` 1..3) older than `success_retention_days` + 2. errored rows (`status_class` 0, 4, 5 — 0 meaning "no HTTP response at + all") older than `error_retention_days` + 3. a hard row cap: anything below the `max_rows`-th newest id + +Splitting success from error is the point of the design: a busy install can +keep a week of ordinary traffic while still holding three months of failures +for forensics, without paying for both. + +Deliberately NOT folded into `utils/activity_log.prune_acme_events_and_drafts_if_due`: +that function is driven by tests with fixed `execute.side_effect` lists and an +exact return dict, and it is gated behind a `letsencrypt_orders`-exists check +that would silently disable this prune on an ACME-free install. + +Three safety properties, all of which matter at scale: + + * **Batched deletes.** The pool sets `command_timeout=60`; an unbounded + DELETE over a multi-million-row table raises `asyncpg.TimeoutError` and + then nothing is ever pruned. + * **Advisory lock.** `pg_try_advisory_lock` (try, never block) so N replicas + × M uvicorn workers do not all scan at once. + * **Watermark stamped only after a complete pass.** A pass that times out + mid-way is retried at the next tick instead of being recorded as done. +""" +import json +import logging +from datetime import datetime +from typing import Dict, Optional + +from database.connection import get_database_connection, close_database_connection +from utils.request_log_settings import get_config + +logger = logging.getLogger("haproxy_openmanager.request_log") + +# Fresh namespace. Already taken in this codebase: 18181818 (draft cap), +# 18181819 (wizard create), 18181820 (apply), 0x41434D45 (per-ACME-order), +# 1836016242 (migration lock). +PRUNE_LOCK_KEY = 18181821 + +WATERMARK_KEY = "requestlog.last_pruned_at" + +BATCH_SIZE = 5000 +MAX_BATCHES = 40 # ceiling of 200k rows removed per pass + +# Retention days ALWAYS travel as a bind parameter. They are operator-supplied, +# so interpolating them into the SQL string would be an injection point. +_SQL_TTL_SUCCESS = """ +DELETE FROM request_logs +WHERE ctid IN ( + SELECT ctid FROM request_logs + WHERE status_class BETWEEN 1 AND 3 + AND created_at < NOW() - ($1 || ' days')::INTERVAL + LIMIT $2 +) +""" + +_SQL_TTL_ERROR = """ +DELETE FROM request_logs +WHERE ctid IN ( + SELECT ctid FROM request_logs + WHERE (status_class = 0 OR status_class >= 4) + AND created_at < NOW() - ($1 || ' days')::INTERVAL + LIMIT $2 +) +""" + +_SQL_CAP_CUTOFF = "SELECT id FROM request_logs ORDER BY id DESC OFFSET $1 LIMIT 1" + +_SQL_CAP_DELETE = """ +DELETE FROM request_logs +WHERE ctid IN ( + SELECT ctid FROM request_logs WHERE id <= $1 LIMIT $2 +) +""" + + +def _deleted_count(result) -> int: + """asyncpg returns the command tag ('DELETE 42') from execute().""" + if isinstance(result, str) and result.startswith("DELETE "): + try: + return int(result.split()[-1]) + except (ValueError, IndexError): + return 0 + return 0 + + +async def _batched_delete(conn, sql: str, first_param) -> int: + """Run `sql` repeatedly until a short batch comes back or the ceiling hits.""" + total = 0 + for _ in range(MAX_BATCHES): + result = await conn.execute(sql, first_param, BATCH_SIZE) + count = _deleted_count(result) + total += count + if count < BATCH_SIZE: + break + else: + logger.info( + f"request_logs prune hit the {MAX_BATCHES}-batch ceiling " + f"({total} rows this pass); the remainder is removed on the next run" + ) + return total + + +async def _is_due(conn, key: str, min_interval_seconds: int) -> bool: + """Watermark gate. Unlike the hardcoded 24h in utils/activity_log.py the + interval here is operator-configurable.""" + row = await conn.fetchrow("SELECT value FROM system_settings WHERE key = $1", key) + if not row or row["value"] is None: + return True + raw = row["value"] + if isinstance(raw, str): + try: + raw = json.loads(raw) + except (json.JSONDecodeError, ValueError): + return True + if not isinstance(raw, str): + return True + try: + last = datetime.fromisoformat(raw.replace("Z", "+00:00")) + except ValueError: + return True + age = (datetime.utcnow() - last.replace(tzinfo=None)).total_seconds() + return age >= min_interval_seconds + + +async def _stamp(conn, key: str) -> None: + await conn.execute( + """ + INSERT INTO system_settings (key, value, category, description) + VALUES ($1, $2::jsonb, 'requestlog', 'Internal: last request_logs prune timestamp') + ON CONFLICT (key) DO UPDATE + SET value = EXCLUDED.value, updated_at = CURRENT_TIMESTAMP + """, + key, + json.dumps(datetime.utcnow().isoformat() + "Z"), + ) + + +async def _prune_row_cap(conn, max_rows: int) -> int: + """Delete everything below the `max_rows`-th newest id.""" + cutoff: Optional[int] = await conn.fetchval(_SQL_CAP_CUTOFF, max_rows) + if cutoff is None: + return 0 # fewer rows than the cap — nothing to do + return await _batched_delete(conn, _SQL_CAP_DELETE, cutoff) + + +async def prune_request_logs_if_due(force: bool = False) -> Dict[str, int]: + """Run one retention pass if the watermark says it is due. + + Never raises: a prune failure must not take down the loop that calls it. + `force=True` skips the watermark gate (used by the manual purge endpoint). + """ + counts = {"success": 0, "error": 0, "overflow": 0, "ran": 0} + cfg = get_config() + + conn = None + locked = False + try: + conn = await get_database_connection() + + # One replica only. try-lock: never block a pod waiting on another's pass. + locked = await conn.fetchval("SELECT pg_try_advisory_lock($1)", PRUNE_LOCK_KEY) + if not locked: + return counts + + if not force and not await _is_due(conn, WATERMARK_KEY, cfg.prune_interval_minutes * 60): + return counts + + counts["success"] = await _batched_delete(conn, _SQL_TTL_SUCCESS, str(cfg.success_retention_days)) + counts["error"] = await _batched_delete(conn, _SQL_TTL_ERROR, str(cfg.error_retention_days)) + counts["overflow"] = await _prune_row_cap(conn, cfg.max_rows) + counts["ran"] = 1 + + # Only after all three steps completed — a partial pass must be retried, + # not recorded as done. + await _stamp(conn, WATERMARK_KEY) + + if counts["success"] or counts["error"] or counts["overflow"]: + logger.info( + f"request_logs prune: {counts['success']} successful, {counts['error']} errored, " + f"{counts['overflow']} over-cap row(s) removed" + ) + return counts + except Exception as exc: + logger.warning(f"prune_request_logs_if_due: {exc}") + return counts + finally: + if conn is not None: + if locked: + try: + await conn.execute("SELECT pg_advisory_unlock($1)", PRUNE_LOCK_KEY) + except Exception: + pass + try: + await close_database_connection(conn) + except Exception: + pass diff --git a/backend/utils/request_log_redaction.py b/backend/utils/request_log_redaction.py new file mode 100644 index 0000000..26c2afc --- /dev/null +++ b/backend/utils/request_log_redaction.py @@ -0,0 +1,342 @@ +"""v1.11.0 — redaction for the unified request/response log. + +Everything that lands in `request_logs.request_body` / `response_body` / +`request_headers` / `response_headers` / `query_params` passes through here +first. The rules, in order of how much they are trusted: + +1. **Headers are an ALLOWLIST.** Anything not explicitly listed is dropped. + A small set of high-signal headers (`Authorization`, `Cookie`, …) is kept + as a presence marker with the value replaced, so an operator debugging a + 401 can still see *that* a credential was sent. +2. **Body keys are matched by a normalized name** (lowercased, punctuation + stripped), against an exact set for short generic names that would + over-match as substrings (`key`, `payload`) and a contains set for the + compound ones (`cert_private_key`, `eab_hmac_key`, …). +3. **Values are shape-checked too.** A PEM private key or a JWT-shaped string + is redacted no matter what key it arrived under — this is the net that + catches a route echoing a secret under a renamed field. + +None of these functions raise: a redaction failure must never turn into a +failed request or a failed provider call, so callers get a safe placeholder +instead of an exception. +""" +import json +import logging +import re +import urllib.parse +from typing import Any, Dict, Optional, Tuple + +logger = logging.getLogger("haproxy_openmanager.request_log") + +REDACTED = "***REDACTED***" + +# Short, generic names. Matched EXACTLY after normalization, because as +# substrings they would swallow innocent fields (`key_suffix`, `monkey`, +# `payload_size`, `keyboard`, `nonce_count`). +REDACT_EXACT = { + "password", "passwd", "pwd", "secret", "token", "key", "auth", + "authorization", "cookie", "signature", "protected", "payload", + "nonce", "credentials", "credential", "otp", "pin", "jwk", "csr", +} + +# Compound names. Matched as SUBSTRINGS of the normalized key. +# +# `token` is in here on purpose, not just its compounds. In this domain EVERY +# field whose name contains "token" is a credential — api_token (the Cloudflare +# provider credential), agent_token, access_token, session_token — and the cost +# of over-redacting a hypothetical innocent one is a blanked field, while the +# cost of under-redacting is a live credential sitting in an audit table. +REDACT_CONTAINS = { + "password", "passwordhash", "secret", "apisecret", "clientsecret", + "token", "accesstoken", "refreshtoken", "mfatoken", "resettoken", + "sessiontoken", "apitoken", "agenttoken", "csrftoken", + "apikey", "xapikey", "privatekey", "publicprivate", "jwkprivatekey", + "certprivatekey", "csrprivatekey", "keypem", "privkey", + "hmac", "eabhmackey", "eabkid", + "credentialsencrypted", "encryptedcredentials", "dnscredentials", + "authorization", "cookie", "setcookie", "keyauthorization", + "backupcode", "backupcodes", "totp", "totpcode", "totpsecret", + "replaynonce", "sessionid", "statspassword", "encryptionkey", + "bearer", "signature", +} + +_NORMALIZE_RE = re.compile(r"[^a-z0-9]") + +# Value-shaped guards — these fire regardless of the key name. +_PEM_RE = re.compile(r"-----BEGIN [A-Z0-9 ]*PRIVATE KEY-----") +_JWT_RE = re.compile(r"^[A-Za-z0-9_-]{16,}\.[A-Za-z0-9_-]{16,}\.[A-Za-z0-9_-]{16,}$") + +_MAX_DEPTH = 6 +_MAX_NODES = 2000 +_MAX_STRING = 4096 +_MAX_LIST_ITEMS = 200 + +# Header handling. Allowlist wins; presence-only names are emitted with the +# value replaced so the operator knows the header was there. +HEADER_ALLOWLIST = { + "content-type", "content-length", "content-encoding", "accept", + "accept-encoding", "accept-language", "user-agent", "referer", "origin", + "host", "connection", "cache-control", "pragma", "date", "server", + "x-correlation-id", "x-request-id", "x-response-time", + "x-forwarded-for", "x-forwarded-proto", "x-forwarded-host", "x-real-ip", + "location", "retry-after", "ratelimit-reset", "ratelimit-remaining", + "link", "etag", "vary", +} + +HEADER_PRESENCE_ONLY = { + "authorization", "cookie", "set-cookie", "x-api-key", "api-key", + "proxy-authorization", "replay-nonce", "www-authenticate", + "x-auth-token", "x-agent-token", "x-agent-api-key", +} + +_MAX_HEADERS = 40 + + +class _NodeBudget: + """Shared mutable counter so a single body can't blow the CPU budget by + being wide as well as deep.""" + + __slots__ = ("remaining",) + + def __init__(self, remaining: int = _MAX_NODES): + self.remaining = remaining + + def spend(self) -> int: + self.remaining -= 1 + return self.remaining + + +def _normalize_key(key: Any) -> str: + try: + return _NORMALIZE_RE.sub("", str(key).lower()) + except Exception: + return "" + + +def is_secret_key(key: Any) -> bool: + """True when a dict key / query param name names a secret.""" + norm = _normalize_key(key) + if not norm: + return False + if norm in REDACT_EXACT: + return True + return any(needle in norm for needle in REDACT_CONTAINS) + + +def _is_secret_value(value: str) -> bool: + """Shape-based guard for secrets that arrive under an innocent key.""" + if len(value) < 32: + # Neither a PEM block nor a JWT fits in less than this; skip the + # regex work on the overwhelmingly common short-string case. + return False + if _PEM_RE.search(value): + return True + return bool(_JWT_RE.match(value.strip())) + + +def redact(value: Any, *, depth: int = 0, budget: Optional[_NodeBudget] = None) -> Any: + """Recursively redact a decoded body. + + Depth- and node-capped so a hostile or merely pathological payload cannot + burn CPU on the writer task. Never raises. + """ + if budget is None: + budget = _NodeBudget() + + try: + if depth > _MAX_DEPTH: + return "***DEPTH_LIMIT***" + + if isinstance(value, dict): + out: Dict[str, Any] = {} + for k, v in value.items(): + if budget.spend() <= 0: + out["_node_limit"] = True + break + if is_secret_key(k): + out[str(k)] = REDACTED + else: + out[str(k)] = redact(v, depth=depth + 1, budget=budget) + return out + + if isinstance(value, (list, tuple)): + out_list = [] + for item in list(value)[:_MAX_LIST_ITEMS]: + if budget.spend() <= 0: + out_list.append("_node_limit") + break + out_list.append(redact(item, depth=depth + 1, budget=budget)) + if len(value) > _MAX_LIST_ITEMS: + out_list.append(f"…[{len(value) - _MAX_LIST_ITEMS} more items]") + return out_list + + if isinstance(value, str): + if _is_secret_value(value): + return REDACTED + if len(value) > _MAX_STRING: + return value[:_MAX_STRING] + f"…[truncated {len(value) - _MAX_STRING} chars]" + return value + + return value + except Exception as exc: # pragma: no cover - defensive + logger.debug(f"redact() failed, substituting placeholder: {exc}") + return "***REDACTION_ERROR***" + + +def redact_headers(headers: Optional[Dict[str, str]]) -> Optional[Dict[str, str]]: + """Allowlist-filter a header mapping. + + Allowlisted headers keep their value, `HEADER_PRESENCE_ONLY` headers keep + only the fact they were present, everything else is dropped silently. + """ + if not headers: + return None + try: + out: Dict[str, str] = {} + for raw_name, raw_value in headers.items(): + name = str(raw_name).lower() + if name in HEADER_PRESENCE_ONLY: + out[name] = REDACTED + elif name in HEADER_ALLOWLIST: + value = str(raw_value) + out[name] = value[:1024] + if len(out) >= _MAX_HEADERS: + break + return out or None + except Exception as exc: # pragma: no cover - defensive + logger.debug(f"redact_headers() failed: {exc}") + return None + + +def scrub_query_string(query: Optional[str]) -> Tuple[str, Optional[Dict[str, str]]]: + """Return (scrubbed_query_string, scrubbed_dict) for a raw query string.""" + if not query: + return "", None + try: + pairs = urllib.parse.parse_qsl(query, keep_blank_values=True) + scrubbed = [(k, REDACTED if is_secret_key(k) else v) for k, v in pairs] + return urllib.parse.urlencode(scrubbed), dict(scrubbed) + except Exception as exc: # pragma: no cover - defensive + logger.debug(f"scrub_query_string() failed: {exc}") + return "", None + + +def scrub_url(url: str) -> str: + """Strip userinfo and scrub the query string of an absolute URL. + + `https://user:pass@api.example.com/v1?api_key=x` + → `https://api.example.com/v1?api_key=***REDACTED***` + """ + if not url: + return "" + try: + parts = urllib.parse.urlsplit(url) + netloc = parts.hostname or "" + if parts.port: + netloc = f"{netloc}:{parts.port}" + query, _ = scrub_query_string(parts.query) + # Fragments are dropped: they never reach a server and can carry tokens. + return urllib.parse.urlunsplit((parts.scheme, netloc, parts.path, query, "")) + except Exception as exc: # pragma: no cover - defensive + logger.debug(f"scrub_url() failed: {exc}") + return "***URL_PARSE_ERROR***" + + +# Content types whose bodies are worth buffering. Anything else (octet-stream, +# images, text/event-stream) is size-counted but never copied, which is what +# keeps streaming and file responses safe. +CAPTURABLE_CONTENT_TYPES = ( + "application/json", + "application/problem+json", + "application/jose+json", + "application/x-www-form-urlencoded", + "text/plain", + "text/html", + "text/xml", + "application/xml", +) + + +def is_capturable_content_type(content_type: Optional[str]) -> bool: + if not content_type: + # No Content-Type on a body-bearing message is rare; assume JSON-ish + # rather than dropping the one field the operator wanted to see. + return True + ct = content_type.split(";")[0].strip().lower() + return any(ct.startswith(prefix) for prefix in CAPTURABLE_CONTENT_TYPES) + + +def decode_body( + raw: Optional[bytes], + content_type: Optional[str], + total_bytes: int = 0, +) -> Tuple[Optional[Any], bool]: + """Decode + redact a captured body fragment. + + `raw` is what the middleware managed to buffer (already capped); + `total_bytes` is how large the body actually was on the wire. Returns + `(jsonb_value, truncated)`. Non-JSON payloads are wrapped as + `{"_raw": "..."}` so the column stays a uniform JSONB object that the + detail view and any future `->>` query can rely on. + """ + if not raw: + return None, False + + truncated = total_bytes > len(raw) + ct = (content_type or "").split(";")[0].strip().lower() + + try: + text = raw.decode("utf-8", "replace") + except Exception: # pragma: no cover - decode with 'replace' can't raise + return {"_raw": "***DECODE_ERROR***"}, truncated + + value: Any + if ct in ("application/json", "application/problem+json", "application/jose+json") or ( + not ct and text[:1] in ("{", "[") + ): + try: + value = redact(json.loads(text)) + except Exception: + # A truncated JSON body will not parse — keep the raw prefix so the + # operator still sees what was sent. + value = {"_raw": redact(text)} + elif ct == "application/x-www-form-urlencoded": + try: + value = redact(dict(urllib.parse.parse_qsl(text, keep_blank_values=True))) + except Exception: + value = {"_raw": redact(text)} + else: + value = {"_raw": redact(text)} + + if truncated: + if isinstance(value, dict): + value["_truncated"] = True + value["_original_bytes"] = total_bytes + else: + value = { + "_value": value, + "_truncated": True, + "_original_bytes": total_bytes, + } + + return value, truncated + + +def safe_error_text(exc: BaseException, *, type_only: bool = False, limit: int = 2000) -> str: + """Render an exception for the `error` column. + + `type_only=True` is used for the DNS providers, whose own error paths + deliberately never surface `str(exc)` — it can carry the request URL and, + through it, tenant/zone identifiers (see services/dns_providers/*.py). + """ + try: + name = type(exc).__name__ + if type_only: + return name + text = f"{name}: {exc}" + redacted = redact(text) + if not isinstance(redacted, str): + return name + return redacted[:limit] + except Exception: # pragma: no cover - defensive + return "UnknownError" diff --git a/backend/utils/request_log_settings.py b/backend/utils/request_log_settings.py new file mode 100644 index 0000000..6c351bf --- /dev/null +++ b/backend/utils/request_log_settings.py @@ -0,0 +1,256 @@ +"""v1.11.0 — operator-tunable settings for the request/response log. + +The middleware runs on EVERY request, so the hot path must not touch the +database. `get_config()` returns a module-global immutable snapshot with no +`await`; `refresh_config()` reloads it from `system_settings` and is called + + * once at startup, right after migrations, + * every `_TTL_SECONDS` from the sink's writer loop (off the request path), + * synchronously at the end of `PUT /api/request-logs/settings`, so an + operator's change takes effect immediately instead of up to 30s later. + +asyncpg has no JSONB codec registered on this pool (see +database/connection.py), so every value comes back as a raw JSON *string* and +needs the `isinstance(v, str)` + `json.loads` guard used elsewhere in this +codebase (services/acme_service.py, utils/activity_log.py). +""" +import json +import logging +import time +from dataclasses import dataclass, replace +from typing import Any, Dict, Optional, Tuple + +from database.connection import get_database_connection, close_database_connection + +logger = logging.getLogger("haproxy_openmanager.request_log") + +SETTINGS_CATEGORY = "requestlog" + +# Kept in sync with the seed in database/migrations.ensure_request_log_settings(). +# backend/tests/test_request_log_settings.py asserts the two agree, so a change +# here without a change there fails the suite rather than drifting silently. +DEFAULT_EXCLUDE_PATHS = ( + "/api/request-logs", + "/api/health", + "/api/docs", + "/api/redoc", + "/api/openapi.json", + "/.well-known/acme-challenge", + "/api/agents/heartbeat", + "/static", + "/favicon.ico", +) + + +@dataclass(frozen=True) +class RequestLogConfig: + enabled: bool = True + capture_inbound: bool = True + capture_outbound: bool = True + capture_bodies: bool = True + capture_get: bool = True + max_body_bytes: int = 8192 + sample_rate: float = 1.0 + exclude_paths: Tuple[str, ...] = DEFAULT_EXCLUDE_PATHS + success_retention_days: int = 7 + error_retention_days: int = 30 + max_rows: int = 500000 + prune_interval_minutes: int = 60 + + def as_dict(self) -> Dict[str, Any]: + return { + "enabled": self.enabled, + "capture_inbound": self.capture_inbound, + "capture_outbound": self.capture_outbound, + "capture_bodies": self.capture_bodies, + "capture_get": self.capture_get, + "max_body_bytes": self.max_body_bytes, + "sample_rate": self.sample_rate, + "exclude_paths": list(self.exclude_paths), + "success_retention_days": self.success_retention_days, + "error_retention_days": self.error_retention_days, + "max_rows": self.max_rows, + "prune_interval_minutes": self.prune_interval_minutes, + } + + +DEFAULT_CONFIG = RequestLogConfig() + +_CACHE: RequestLogConfig = DEFAULT_CONFIG +_CACHE_AT: float = 0.0 +_TTL_SECONDS: float = 30.0 + +# Bounds, mirrored by the Pydantic model in routers/request_logs.py. Kept here +# too because refresh_config() reads whatever is in the table, which may have +# been written by an older build or by hand. +_BOUNDS = { + "max_body_bytes": (0, 262144), + "success_retention_days": (1, 365), + "error_retention_days": (1, 365), + "max_rows": (1000, 50_000_000), + "prune_interval_minutes": (5, 1440), +} + +MAX_EXCLUDE_PATHS = 64 +MAX_EXCLUDE_PATH_LENGTH = 200 + + +def get_config() -> RequestLogConfig: + """Hot-path read: no await, no DB, no lock. Returns the last snapshot.""" + return _CACHE + + +def set_config(config: RequestLogConfig) -> None: + """Replace the snapshot directly. Used by the settings PUT handler (which + already has the validated values) and by tests.""" + global _CACHE, _CACHE_AT + _CACHE = config + _CACHE_AT = time.monotonic() + + +def _clamp_int(raw: Any, field: str, fallback: int) -> int: + try: + value = int(raw) + except (TypeError, ValueError): + return fallback + low, high = _BOUNDS[field] + return max(low, min(high, value)) + + +def _clamp_float(raw: Any, fallback: float, low: float, high: float) -> float: + try: + value = float(raw) + except (TypeError, ValueError): + return fallback + return max(low, min(high, value)) + + +def _as_bool(raw: Any, fallback: bool) -> bool: + if isinstance(raw, bool): + return raw + if isinstance(raw, (int, float)): + return bool(raw) + if isinstance(raw, str): + lowered = raw.strip().lower() + if lowered in ("true", "1", "yes", "on"): + return True + if lowered in ("false", "0", "no", "off"): + return False + return fallback + + +def normalize_exclude_paths(raw: Any, fallback: Tuple[str, ...]) -> Tuple[str, ...]: + """Coerce whatever is stored into a bounded tuple of path prefixes.""" + if not isinstance(raw, (list, tuple)): + return fallback + out = [] + for item in raw: + if not isinstance(item, str): + continue + candidate = item.strip() + if not candidate.startswith("/") or len(candidate) > MAX_EXCLUDE_PATH_LENGTH: + continue + out.append(candidate) + if len(out) >= MAX_EXCLUDE_PATHS: + break + return tuple(out) if out else fallback + + +def config_from_mapping(values: Dict[str, Any], base: Optional[RequestLogConfig] = None) -> RequestLogConfig: + """Build a config from a plain suffix→value mapping, clamping every field. + + Unknown keys are ignored and missing keys keep the value from `base` + (default: the shipped defaults), so a partially-seeded table still yields a + complete, usable config. + """ + base = base or DEFAULT_CONFIG + return replace( + base, + enabled=_as_bool(values.get("enabled", base.enabled), base.enabled), + capture_inbound=_as_bool(values.get("capture_inbound", base.capture_inbound), base.capture_inbound), + capture_outbound=_as_bool(values.get("capture_outbound", base.capture_outbound), base.capture_outbound), + capture_bodies=_as_bool(values.get("capture_bodies", base.capture_bodies), base.capture_bodies), + capture_get=_as_bool(values.get("capture_get", base.capture_get), base.capture_get), + max_body_bytes=_clamp_int(values.get("max_body_bytes", base.max_body_bytes), "max_body_bytes", base.max_body_bytes), + sample_rate=_clamp_float(values.get("sample_rate", base.sample_rate), base.sample_rate, 0.0, 1.0), + exclude_paths=normalize_exclude_paths(values.get("exclude_paths"), base.exclude_paths), + success_retention_days=_clamp_int( + values.get("success_retention_days", base.success_retention_days), + "success_retention_days", base.success_retention_days, + ), + error_retention_days=_clamp_int( + values.get("error_retention_days", base.error_retention_days), + "error_retention_days", base.error_retention_days, + ), + max_rows=_clamp_int(values.get("max_rows", base.max_rows), "max_rows", base.max_rows), + prune_interval_minutes=_clamp_int( + values.get("prune_interval_minutes", base.prune_interval_minutes), + "prune_interval_minutes", base.prune_interval_minutes, + ), + ) + + +def _decode_setting_value(raw: Any) -> Any: + """JSONB comes back as a raw string on this pool — parse it, but keep the + original text if it is not valid JSON (an operator may have hand-written + `7` or `seven`).""" + if isinstance(raw, str): + try: + return json.loads(raw) + except (json.JSONDecodeError, ValueError): + return raw + return raw + + +async def load_settings_rows(conn) -> Dict[str, Any]: + """Read the `requestlog.*` rows into a suffix→value mapping.""" + rows = await conn.fetch( + "SELECT key, value FROM system_settings WHERE category = $1", + SETTINGS_CATEGORY, + ) + values: Dict[str, Any] = {} + for row in rows: + key = row["key"] + suffix = key.split(".", 1)[1] if "." in key else key + values[suffix] = _decode_setting_value(row["value"]) + return values + + +async def refresh_config(force: bool = True) -> RequestLogConfig: + """Reload the snapshot from the database. + + Never raises and never leaves a half-built config behind: on any failure + the previous snapshot is kept, so a transient DB blip cannot silently turn + logging off (or on). + """ + global _CACHE_AT + if not force and (time.monotonic() - _CACHE_AT) < _TTL_SECONDS: + return _CACHE + + conn = None + try: + conn = await get_database_connection() + values = await load_settings_rows(conn) + if values: + set_config(config_from_mapping(values)) + else: + # Table not seeded yet (fresh install mid-migration) — keep the + # in-code defaults but stamp the timestamp so we don't re-query + # every tick. + _CACHE_AT = time.monotonic() + return _CACHE + except Exception as exc: + logger.debug(f"refresh_config: keeping previous snapshot ({exc})") + _CACHE_AT = time.monotonic() + return _CACHE + finally: + if conn is not None: + try: + await close_database_connection(conn) + except Exception: + pass + + +async def maybe_refresh_config() -> RequestLogConfig: + """TTL-gated refresh, called from the sink's writer loop.""" + return await refresh_config(force=False) diff --git a/backend/utils/request_log_sink.py b/backend/utils/request_log_sink.py new file mode 100644 index 0000000..9d27e04 --- /dev/null +++ b/backend/utils/request_log_sink.py @@ -0,0 +1,320 @@ +"""v1.11.0 — batching writer for the unified request/response log. + +One row per API call is the highest write volume in this system, and the +asyncpg pool (min=10/max=50, see database/connection.py) is shared with every +request handler and four background loops. Acquiring a connection per logged +request would exhaust it under any real load, so instead: + + hot path ──offer(row)──▶ bounded asyncio.Queue ──▶ single writer task + (drops when full) (executemany batches) + +The hot path never awaits I/O and never raises. When the queue is full rows are +counted as dropped and reported through `GET /api/request-logs/stats`, so a +saturated logger is visible rather than silent. + +Redaction deliberately happens HERE, on the writer task, not in the middleware: +the recursive walk is the most expensive part of building a row and it has no +business running inside the request coroutine. +""" +import asyncio +import json +import logging +import random +from contextvars import ContextVar +from dataclasses import dataclass, field +from datetime import datetime, timezone +from typing import Any, Dict, List, Optional + +from config import REQUEST_LOG_BATCH_SIZE, REQUEST_LOG_FLUSH_MS, REQUEST_LOG_QUEUE_MAX +from database.connection import get_database_connection, close_database_connection +from utils.request_log_redaction import decode_body, redact_headers +from utils.request_log_settings import get_config, maybe_refresh_config + +logger = logging.getLogger("haproxy_openmanager.request_log") + +# Set by the inbound middleware; read by outbound_span so an outbound call +# inherits the id of the inbound request that caused it. That is what turns +# "operator clicked Issue Certificate" and "we POSTed to Let's Encrypt" into +# one readable trace. +request_id_context: ContextVar[Optional[str]] = ContextVar( + "request_log_request_id", default=None +) + +_INSERT_SQL = """ +INSERT INTO request_logs ( + request_id, direction, target, method, url, path, query_params, + status_code, status_class, duration_ms, user_id, username, client_ip, + user_agent, request_headers, request_body, request_body_bytes, + response_headers, response_body, response_body_bytes, error, truncated, + created_at +) VALUES ( + $1, $2, $3, $4, $5, $6, $7::jsonb, + $8, $9, $10, $11, $12, $13::inet, + $14, $15::jsonb, $16::jsonb, $17, + $18::jsonb, $19::jsonb, $20, $21, $22, + $23 +) +""" + + +def _jsonb(value: Any) -> Optional[str]: + """asyncpg has no JSONB codec on this pool, so JSONB params travel as text + and are cast in SQL — the house idiom (utils/activity_log.py).""" + if value is None: + return None + try: + return json.dumps(value, default=str) + except Exception: + return json.dumps({"_serialize_error": True}) + + +@dataclass +class RequestLogRow: + """One captured exchange, still holding RAW body bytes. + + Decoding and redaction run in `to_params()` on the writer task. + """ + + request_id: str + direction: str + method: str + url: str + target: Optional[str] = None + path: Optional[str] = None + query_string: Optional[str] = None + query_params: Optional[Dict[str, Any]] = None + status_code: Optional[int] = None + duration_ms: int = 0 + user_id: Optional[int] = None + username: Optional[str] = None + client_ip: Optional[str] = None + user_agent: Optional[str] = None + request_headers: Optional[Dict[str, str]] = None + response_headers: Optional[Dict[str, str]] = None + request_body_raw: Optional[bytes] = None + request_body_bytes: int = 0 + request_content_type: Optional[str] = None + response_body_raw: Optional[bytes] = None + response_body_bytes: int = 0 + response_content_type: Optional[str] = None + # Pre-decoded body override, used by outbound spans that hold a dict/str + # rather than wire bytes (e.g. the synthetic JWS summary). + request_body_value: Optional[Any] = None + response_body_value: Optional[Any] = None + error: Optional[str] = None + created_at: datetime = field(default_factory=lambda: datetime.now(timezone.utc)) + + @property + def status_class(self) -> int: + """`status_code // 100`, or 0 when there was no HTTP response at all + (transport error / unhandled exception). 0 is what the error-retention + prune treats as an error alongside >= 4.""" + if not self.status_code: + return 0 + return int(self.status_code) // 100 + + def to_params(self) -> List[Any]: + req_body, req_truncated = (self.request_body_value, False) + if req_body is None: + req_body, req_truncated = decode_body( + self.request_body_raw, self.request_content_type, self.request_body_bytes + ) + + res_body, res_truncated = (self.response_body_value, False) + if res_body is None: + res_body, res_truncated = decode_body( + self.response_body_raw, self.response_content_type, self.response_body_bytes + ) + + return [ + self.request_id[:64], + self.direction, + self.target[:32] if self.target else None, + (self.method or "")[:10], + self.url or "", + self.path[:512] if self.path else None, + _jsonb(self.query_params), + self.status_code, + self.status_class, + max(0, int(self.duration_ms)), + self.user_id, + self.username[:50] if self.username else None, + self.client_ip, + self.user_agent[:1024] if self.user_agent else None, + _jsonb(redact_headers(self.request_headers)), + _jsonb(req_body), + max(0, int(self.request_body_bytes)), + _jsonb(redact_headers(self.response_headers)), + _jsonb(res_body), + max(0, int(self.response_body_bytes)), + self.error[:4000] if self.error else None, + bool(req_truncated or res_truncated), + self.created_at, + ] + + +class RequestLogSink: + """Bounded queue + single batching writer task (one per uvicorn worker).""" + + def __init__(self, maxsize: int, batch_size: int, flush_ms: int): + self._maxsize = maxsize + self._batch_size = batch_size + self._flush_seconds = flush_ms / 1000.0 + self._queue: Optional[asyncio.Queue] = None + self._dropped = 0 + self._written = 0 + self._failed = 0 + self._running = False + + # -- lifecycle --------------------------------------------------------- + + def _ensure_queue(self) -> asyncio.Queue: + # Created lazily so importing this module never needs a running loop + # (matters for the test suite, which imports main.py without one). + if self._queue is None: + self._queue = asyncio.Queue(maxsize=self._maxsize) + return self._queue + + @property + def stats(self) -> Dict[str, int]: + return { + "queued": self._queue.qsize() if self._queue is not None else 0, + "queue_capacity": self._maxsize, + "written": self._written, + "dropped": self._dropped, + "failed_batches": self._failed, + "running": 1 if self._running else 0, + } + + # -- producer side (hot path) ----------------------------------------- + + def offer(self, row: RequestLogRow) -> None: + """Enqueue a row. NEVER blocks, NEVER raises. + + Sampling is applied here rather than in the middleware so both + directions go through one policy: successful *inbound* traffic can be + sampled down, errors never are. + """ + try: + cfg = get_config() + if not cfg.enabled: + return + if row.direction == "inbound" and not cfg.capture_inbound: + return + if row.direction == "outbound" and not cfg.capture_outbound: + return + if ( + row.direction == "inbound" + and cfg.sample_rate < 1.0 + and row.status_class in (1, 2, 3) + and random.random() > cfg.sample_rate + ): + return + if not cfg.capture_bodies: + row.request_body_raw = None + row.response_body_raw = None + row.request_body_value = None + row.response_body_value = None + + self._ensure_queue().put_nowait(row) + except asyncio.QueueFull: + self._dropped += 1 + if self._dropped % 500 == 1: + logger.warning( + f"request_log: queue full, {self._dropped} row(s) dropped so far " + f"(capacity {self._maxsize}; raise REQUEST_LOG_QUEUE_MAX or lower " + f"requestlog.sample_rate)" + ) + except Exception as exc: + # Instrumentation must never break the thing it instruments. + logger.debug(f"request_log: offer() failed: {exc}") + + # -- consumer side (writer task) -------------------------------------- + + async def _collect(self) -> List[RequestLogRow]: + """Wait for at least one row, then drain up to batch_size or flush_ms.""" + queue = self._ensure_queue() + first = await queue.get() + batch = [first] + loop = asyncio.get_running_loop() + deadline = loop.time() + self._flush_seconds + while len(batch) < self._batch_size: + remaining = deadline - loop.time() + if remaining <= 0: + break + try: + batch.append(await asyncio.wait_for(queue.get(), timeout=remaining)) + except asyncio.TimeoutError: + break + return batch + + async def _write(self, batch: List[RequestLogRow]) -> None: + if not batch: + return + params = [] + for row in batch: + try: + params.append(row.to_params()) + except Exception as exc: + logger.debug(f"request_log: row serialization failed, skipped: {exc}") + if not params: + return + + conn = None + try: + conn = await get_database_connection() + await conn.executemany(_INSERT_SQL, params) + self._written += len(params) + except Exception as exc: + self._failed += 1 + # A missing table (pre-migration) or a transient pool error must not + # take the writer loop down — drop the batch and carry on. + logger.warning(f"request_log: batch write failed ({len(params)} rows): {exc}") + finally: + if conn is not None: + try: + await close_database_connection(conn) + except Exception: + pass + + async def run(self) -> None: + """Writer loop. Started once per worker from startup_event().""" + self._running = True + logger.info( + f"request_log sink started (queue={self._maxsize}, batch={self._batch_size}, " + f"flush={int(self._flush_seconds * 1000)}ms)" + ) + try: + while True: + try: + batch = await self._collect() + await self._write(batch) + await maybe_refresh_config() + except asyncio.CancelledError: + raise + except Exception as exc: # pragma: no cover - defensive + logger.error(f"request_log sink loop error: {exc}") + await asyncio.sleep(1) + finally: + self._running = False + + async def flush(self, timeout: float = 3.0) -> int: + """Drain and persist whatever is queued. Called on shutdown.""" + queue = self._queue + if queue is None or queue.empty(): + return 0 + written = 0 + loop = asyncio.get_running_loop() + deadline = loop.time() + timeout + while not queue.empty() and loop.time() < deadline: + batch: List[RequestLogRow] = [] + while not queue.empty() and len(batch) < self._batch_size: + batch.append(queue.get_nowait()) + await self._write(batch) + written += len(batch) + return written + + +request_log_sink = RequestLogSink( + REQUEST_LOG_QUEUE_MAX, REQUEST_LOG_BATCH_SIZE, REQUEST_LOG_FLUSH_MS +) diff --git a/backend/version.json b/backend/version.json index ef98c45..36de1e6 100644 --- a/backend/version.json +++ b/backend/version.json @@ -1,5 +1,5 @@ { - "version": "1.10.3", - "releaseName": "Multi-account ACME — the wizard honours the selected account", - "releaseDate": "2026-08-08" + "version": "1.11.0", + "releaseName": "Unified request/response log with configurable retention", + "releaseDate": "2026-08-11" } diff --git a/frontend/package.json b/frontend/package.json index 2c1eec2..5f368f8 100644 --- a/frontend/package.json +++ b/frontend/package.json @@ -1,6 +1,6 @@ { "name": "haproxy-openmanager-frontend", - "version": "1.10.3", + "version": "1.11.0", "description": "HAProxy Load Balancer Management UI", "license": "AGPL-3.0-or-later", "dependencies": { diff --git a/frontend/src/App.css b/frontend/src/App.css index e57a2fe..894d880 100644 --- a/frontend/src/App.css +++ b/frontend/src/App.css @@ -209,4 +209,24 @@ [data-theme='dark'] .agent-offline:hover > td { background-color: #321518 !important; +} + +/* v1.11.0 — Request Log: failed exchanges (4xx/5xx and transport errors) are + tinted so a page of traffic reads at a glance. Defined for BOTH themes here + rather than as an inline style, so the dark variant is not forgotten (the + v1.10.2 regression class). */ +.request-log-error-row > td { + background-color: #fff2f0; +} + +.request-log-error-row:hover > td { + background-color: #ffe7e5 !important; +} + +[data-theme='dark'] .request-log-error-row > td { + background-color: #2a1215 !important; +} + +[data-theme='dark'] .request-log-error-row:hover > td { + background-color: #321518 !important; } \ No newline at end of file diff --git a/frontend/src/App.js b/frontend/src/App.js index 447b8c3..2c09e6d 100644 --- a/frontend/src/App.js +++ b/frontend/src/App.js @@ -23,7 +23,8 @@ import { BulbOutlined, BulbFilled, PlusOutlined, - ThunderboltOutlined + ThunderboltOutlined, + FileSearchOutlined } from '@ant-design/icons'; import Dashboard from './components/DashboardV2'; @@ -49,6 +50,7 @@ import APIDocumentation from './components/APIDocumentation'; import IPInventory from './components/IPInventory'; import SiteWizard from './components/SiteWizard'; import SiteDrafts from './components/SiteDrafts'; +import RequestLog from './components/RequestLog'; // v1.11.0 — request/response log import { AuthProvider, useAuth } from './contexts/AuthContext'; import { ClusterProvider } from './contexts/ClusterContext'; import { ThemeProvider, useTheme } from './contexts/ThemeContext'; @@ -153,6 +155,15 @@ const { Text } = Typography; icon: , label: Config Versions, }, + { + key: '/request-log', + icon: , + label: ( + + Request Log + + ), + }, { key: '/clusters', icon: , @@ -469,6 +480,9 @@ function AppContent() { } /> } /> } /> + {/* v1.11.0 — the page gates itself on requestlog.read; the route + is unconditional like every other route in this app. */} + } /> } /> } /> } /> diff --git a/frontend/src/components/RequestLog.js b/frontend/src/components/RequestLog.js new file mode 100644 index 0000000..cacf672 --- /dev/null +++ b/frontend/src/components/RequestLog.js @@ -0,0 +1,606 @@ +/** + * v1.11.0 — Request Log. + * + * One timeline for both directions of HTTP traffic: + * - inbound: which user called which API endpoint, with what result + * - outbound: which CA / DNS provider / agent this backend called, and what + * came back + * + * Both live in the same table, so opening one inbound request shows the + * outbound calls it triggered (they share a request_id) — that "related" list + * is the whole point of the page. Bodies are captured redacted and size-capped + * by the backend; nothing is unredacted here. + * + * Pagination is SERVER-side (a first for this frontend — every other table + * filters an already-fetched array). The table can hold millions of rows, so + * fetching them to slice client-side is not an option. + */ +import React, { useCallback, useEffect, useMemo, useState } from 'react'; +import { + Alert, Button, Card, DatePicker, Descriptions, Empty, Input, Modal, Select, + Space, Spin, Statistic, Switch, Table, Tag, Tooltip, Typography, message, theme +} from 'antd'; +import { + ApiOutlined, ClockCircleOutlined, CloudDownloadOutlined, DeleteOutlined, + EyeOutlined, ReloadOutlined, UserOutlined, WarningOutlined +} from '@ant-design/icons'; +import axios from 'axios'; + +import { extractApiError } from '../utils/apiError'; +import { useAuth } from '../contexts/AuthContext'; + +const { Text, Paragraph } = Typography; + +const DIRECTION_OPTIONS = [ + { label: 'Inbound (API calls to us)', value: 'inbound' }, + { label: 'Outbound (calls we made)', value: 'outbound' }, +]; + +const STATUS_OPTIONS = [ + { label: '2xx Success', value: 2 }, + { label: '3xx Redirect', value: 3 }, + { label: '4xx Client error', value: 4 }, + { label: '5xx Server error', value: 5 }, + { label: 'No response (transport error)', value: 0 }, +]; + +const METHOD_OPTIONS = ['GET', 'POST', 'PUT', 'PATCH', 'DELETE', 'HEAD'].map((m) => ({ + label: m, value: m, +})); + +// Mirrors utils/http_instrumentation.py's TARGET_* constants. +const TARGET_LABELS = { + acme: "ACME / Let's Encrypt", + acme_diag: 'ACME diagnostics probe', + letsencrypt_ca: "Let's Encrypt CA chain", + dns_cloudflare: 'Cloudflare DNS', + dns_godaddy: 'GoDaddy DNS', + agent: 'HAProxy agent', + haproxy_stats: 'HAProxy stats', + settings_probe: 'ACME directory probe', +}; + +const statusColor = (statusClass) => { + if (statusClass === 2) return 'green'; + if (statusClass === 3) return 'blue'; + if (statusClass === 4) return 'orange'; + if (statusClass >= 5) return 'red'; + return 'red'; +}; + +const isFailure = (row) => row?.status_class === 0 || row?.status_class >= 4; + +const formatTime = (value) => { + if (!value) return '—'; + // created_at is TIMESTAMPTZ, so the ISO string already carries an offset — + // no manual 'Z' suffix needed here (unlike the naive-TIMESTAMP columns + // elsewhere in this app). + const d = new Date(value); + return Number.isNaN(d.getTime()) ? String(value) : d.toLocaleString(); +}; + +const JsonBlock = ({ value, token }) => { + if (value === null || value === undefined) { + return Not captured; + } + return ( + 
+      {typeof value === 'string' ? value : JSON.stringify(value, null, 2)}
+
+ ); +}; + +const RequestLog = () => { + const { token } = theme.useToken(); + const { hasPermission, isAdmin } = useAuth(); + + const canRead = hasPermission('requestlog', 'read') || isAdmin(); + const canManage = hasPermission('requestlog', 'manage') || isAdmin(); + + const [rows, setRows] = useState([]); + const [total, setTotal] = useState(0); + const [totalIsEstimate, setTotalIsEstimate] = useState(false); + const [scopedToSelf, setScopedToSelf] = useState(false); + const [loading, setLoading] = useState(false); + const [loadError, setLoadError] = useState(null); + + const [page, setPage] = useState(1); + const [pageSize, setPageSize] = useState(50); + + const [direction, setDirection] = useState(undefined); + const [statusClass, setStatusClass] = useState(undefined); + const [methods, setMethods] = useState([]); + const [target, setTarget] = useState(undefined); + const [errorsOnly, setErrorsOnly] = useState(false); + const [range, setRange] = useState(null); + const [searchTyped, setSearchTyped] = useState(''); + const [search, setSearch] = useState(''); + + const [stats, setStats] = useState(null); + const [purging, setPurging] = useState(false); + + const [detailOpen, setDetailOpen] = useState(false); + const [detailLoading, setDetailLoading] = useState(false); + const [detailError, setDetailError] = useState(null); + const [detail, setDetail] = useState(null); + + const params = useMemo(() => { + const p = { limit: pageSize, offset: (page - 1) * pageSize }; + if (direction) p.direction = direction; + if (statusClass !== undefined && statusClass !== null) p.status_class = statusClass; + // The API takes one method; a single selection is the common case and + // keeps the query index-friendly. + if (methods.length === 1) p.method = methods[0]; + if (target) p.target = target; + if (errorsOnly) p.errors_only = true; + if (search) p.q = search; + if (range && range[0]) p.since = range[0].toISOString(); + if (range && range[1]) p.until = range[1].toISOString(); + return p; + }, [page, pageSize, direction, statusClass, methods, target, errorsOnly, search, range]); + + const fetchLogs = useCallback(async () => { + if (!canRead) return; + setLoading(true); + setLoadError(null); + try { + const res = await axios.get('/api/request-logs', { params }); + setRows(res.data?.logs || []); + setTotal(res.data?.total || 0); + setTotalIsEstimate(Boolean(res.data?.total_is_estimate)); + setScopedToSelf(Boolean(res.data?.scoped_to_self)); + } catch (err) { + const msg = extractApiError(err, 'Failed to load request logs'); + setLoadError(msg); + setRows([]); + setTotal(0); + } finally { + setLoading(false); + } + }, [canRead, params]); + + const fetchStats = useCallback(async () => { + if (!canRead) return; + try { + const res = await axios.get('/api/request-logs/stats', { params: { hours: 24 } }); + setStats(res.data || null); + } catch (err) { + // Stats are a nice-to-have header; a failure here must not hide the table. + setStats(null); + } + }, [canRead]); + + useEffect(() => { fetchLogs(); }, [fetchLogs]); + useEffect(() => { fetchStats(); }, [fetchStats]); + + const openDetail = useCallback(async (id) => { + setDetailOpen(true); + setDetailLoading(true); + setDetailError(null); + setDetail(null); + try { + const res = await axios.get(`/api/request-logs/${id}`); + setDetail(res.data || null); + } catch (err) { + setDetailError(extractApiError(err, 'Failed to load this request')); + } finally { + setDetailLoading(false); + } + }, []); + + const runPurge = useCallback(() => { + Modal.confirm({ + title: 'Apply retention now?', + icon: , + content: + 'This runs the configured retention immediately instead of waiting for the next ' + + 'scheduled pass. It removes rows that are already past their retention window or ' + + 'beyond the row cap — it does not delete everything.', + okText: 'Run retention pass', + onOk: async () => { + setPurging(true); + try { + const res = await axios.post('/api/request-logs/purge'); + const removed = res.data?.removed || {}; + const count = (removed.success || 0) + (removed.error || 0) + (removed.overflow || 0); + message.success(`Retention pass completed — ${count} row(s) removed`); + fetchLogs(); + fetchStats(); + } catch (err) { + message.error(extractApiError(err, 'Retention pass failed')); + } finally { + setPurging(false); + } + }, + }); + }, [fetchLogs, fetchStats]); + + const columns = useMemo(() => ([ + { + title: 'Time', + dataIndex: 'created_at', + width: 180, + render: (v) => {formatTime(v)}, + }, + { + title: 'Direction', + dataIndex: 'direction', + width: 110, + render: (v) => ( + {v === 'inbound' ? 'IN' : 'OUT'} + ), + }, + { + title: 'Method', + dataIndex: 'method', + width: 90, + render: (v) => {v}, + }, + { + title: 'URL', + dataIndex: 'url', + ellipsis: true, + render: (v) => ( + + {v} + + ), + }, + { + title: 'Status', + dataIndex: 'status_code', + width: 100, + render: (v, row) => ( + {v ?? 'ERR'} + ), + }, + { + title: 'Duration', + dataIndex: 'duration_ms', + width: 110, + render: (v) => ( + // 1000ms matches the backend's slow-request threshold, so "red here" + // means "logged as slow there". + 1000 ? 'danger' : undefined} style={{ fontSize: 12 }}>{v} ms + ), + }, + { + title: 'Who / Where', + key: 'who', + width: 200, + render: (_, row) => { + if (row.direction === 'inbound') { + return ( + + + {row.username || (row.user_id ? `#${row.user_id}` : 'anonymous')} + + ); + } + return ( + + }>{row.target || '—'} + + ); + }, + }, + { + title: 'Error', + dataIndex: 'error', + width: 200, + ellipsis: true, + render: (v) => (v ? ( + {v} + ) : —), + }, + { + title: '', + key: 'actions', + width: 90, + fixed: 'right', + render: (_, row) => ( + + ), + }, + ]), [openDetail]); + + if (!canRead) { + return ( + + + + ); + } + + const inboundStats = stats?.by_direction?.find((d) => d.direction === 'inbound'); + const outboundStats = stats?.by_direction?.find((d) => d.direction === 'outbound'); + const dropped = stats?.sink?.dropped || 0; + + const detailRow = detail?.log; + + return ( +
+ Request Log} + extra={ + + + {canManage && ( + + )} + + } + > + + Inbound rows show which user called which endpoint and what came back. + Outbound rows show which CA, DNS provider or agent this backend contacted. + Bodies are captured redacted and size-capped — credentials, + tokens, private keys and ACME signatures are never stored. Retention is + configured in Settings → Request Log. + + } + /> + + {scopedToSelf && ( + + )} + + {dropped > 0 && ( + } + style={{ marginBottom: 16 }} + message={`${dropped} row(s) dropped by this worker`} + description="The writer queue filled up. Lower the sampling rate, turn off body capture, or raise REQUEST_LOG_QUEUE_MAX." + /> + )} + + {stats && ( + + {`/ ${inboundStats.errors} failed`} : null} + /> + {`/ ${outboundStats.errors} failed`} : null} + /> + + {formatTime(stats.oldest_at)}} /> + + )} + + + { setStatusClass(v); setPage(1); }} + options={STATUS_OPTIONS} + /> + { setTarget(v); setPage(1); }} + options={Object.entries(TARGET_LABELS).map(([value, label]) => ({ value, label }))} + /> + { setRange(v); setPage(1); }} + /> + setSearchTyped(e.target.value)} + onSearch={(v) => { setSearch(v); setPage(1); }} + /> + + { setErrorsOnly(v); setPage(1); }} + checkedChildren="Errors" + unCheckedChildren="All" + /> + + + + {loadError && ( + + )} + + (isFailure(row) ? 'request-log-error-row' : '')} + locale={{ + emptyText: , + }} + pagination={{ + current: page, + pageSize, + total, + showSizeChanger: true, + pageSizeOptions: ['25', '50', '100', '200'], + showTotal: (t, r) => `${r[0]}-${r[1]} of ${totalIsEstimate ? `${t}+` : t} requests`, + onChange: (p, ps) => { setPage(p); setPageSize(ps); }, + }} + /> + + + setDetailOpen(false)} + width={960} + destroyOnClose + title="Request detail" + footer={} + > + {detailLoading ? ( +
+ ) : detailError ? ( + + ) : !detailRow ? ( + + ) : ( + + + {formatTime(detailRow.created_at)} + + {detailRow.direction} + + {detailRow.method} + + {detailRow.status_code ?? 'no response'} + + + {detailRow.url} + + {detailRow.duration_ms} ms + + {detailRow.target ? (TARGET_LABELS[detailRow.target] || detailRow.target) : '—'} + + + {detailRow.username || (detailRow.user_id ? `#${detailRow.user_id}` : 'anonymous')} + + {detailRow.client_ip || '—'} + + {detailRow.request_id} + + {detailRow.error && ( + + {detailRow.error} + + )} + + + {detailRow.truncated && ( + + )} + + + + + + + + + + + + + + + Calls triggered by this request} + > + {detail?.related?.length ? ( +
{v === 'inbound' ? 'IN' : 'OUT'} }, + { title: 'Target', dataIndex: 'target', width: 140, render: (v) => v || '—' }, + { title: 'Method', dataIndex: 'method', width: 80 }, + { title: 'URL', dataIndex: 'url', ellipsis: true }, + { title: 'Status', dataIndex: 'status_code', width: 80, + render: (v, r) => {v ?? 'ERR'} }, + { title: '', key: 'go', width: 70, + render: (_, r) => }, + ]} + /> + ) : ( + + No other calls share this request id. + + )} + + + )} + + + ); +}; + +export default RequestLog; diff --git a/frontend/src/components/Settings.js b/frontend/src/components/Settings.js index e76201c..523e282 100644 --- a/frontend/src/components/Settings.js +++ b/frontend/src/components/Settings.js @@ -1,6 +1,6 @@ import React, { useEffect, useState } from 'react'; import { Card, Form, Switch, Button, InputNumber, message, Tabs, Input, Select, Collapse, Space, Alert, Tag, Spin, Tooltip } from 'antd'; -import { SafetyCertificateOutlined, ApiOutlined, CheckCircleOutlined, CloseCircleOutlined, InfoCircleOutlined } from '@ant-design/icons'; +import { SafetyCertificateOutlined, ApiOutlined, CheckCircleOutlined, CloseCircleOutlined, InfoCircleOutlined, FileSearchOutlined } from '@ant-design/icons'; import { useSearchParams } from 'react-router-dom'; import axios from 'axios'; @@ -43,6 +43,15 @@ const Settings = () => { const [testResult, setTestResult] = useState(null); const [testing, setTesting] = useState(false); + // v1.11.0 — request/response log retention. Read/written through + // /api/request-logs/settings, NOT the generic /api/settings/{category}: that + // endpoint stringifies values with str(), which turns True into 'True' and + // fails the ::jsonb cast. + const [rlForm] = Form.useForm(); + const [rlLoading, setRlLoading] = useState(false); + const [rlSaving, setRlSaving] = useState(false); + const [rlDenied, setRlDenied] = useState(false); + const onFinish = (values) => { try { localStorage.setItem('app_settings', JSON.stringify({ @@ -70,8 +79,46 @@ const Settings = () => { useEffect(() => { loadAcmeSettings(); + loadRequestLogSettings(); }, []); + const loadRequestLogSettings = async () => { + setRlLoading(true); + try { + const res = await axios.get('/api/request-logs/settings'); + rlForm.setFieldsValue(res.data?.settings || {}); + setRlDenied(false); + } catch (err) { + // A viewer can open Settings but has no requestlog.manage — show the tab + // read-only-with-explanation rather than a scary console error. + if (err?.response?.status === 403) { + setRlDenied(true); + } else { + console.error('Error loading request log settings:', err); + } + } finally { + setRlLoading(false); + } + }; + + const onRequestLogSave = async (values) => { + setRlSaving(true); + try { + await axios.put('/api/request-logs/settings', { + ...values, + // Values come back from the InputNumber controls as numbers already; + // the endpoint is properly typed, so no per-value JSON.stringify here + // (unlike the ACME form above, which talks to the legacy endpoint). + exclude_paths: values.exclude_paths || [], + }); + message.success('Request log settings saved'); + } catch (err) { + message.error(err?.response?.data?.detail || 'Failed to save request log settings'); + } finally { + setRlSaving(false); + } + }; + const loadAcmeSettings = async () => { setAcmeLoading(true); try { @@ -371,6 +418,150 @@ const Settings = () => { ), }, + { + key: 'requestlog', + label: ( + Request Log + ), + children: ( + + + } + style={{ marginBottom: 24 }} + /> + + {rlDenied && ( + + )} + +
+ + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + +