feat(logging): unified request/response log with configurable retention (v1.11.0)

Until now the only record of what happened was `user_activity_logs`, which
stores non-GET 2xx operations with no bodies. When something failed you could
see that a counter went up, never what was sent or what came back.

This adds one queryable timeline covering both directions:

- inbound: every API call, including GETs and including 4xx/5xx, with the
  user, client IP, status, duration and — redacted, size-capped — the request
  and response bodies.
- outbound: every 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 underneath.

Implementation notes:

- Capture is a pure-ASGI middleware that TEES the request and response streams
  rather than draining them. `await request.body()` inside a BaseHTTPMiddleware
  would consume the receive channel and break the raw-body agent heartbeat
  handler. Registered last so it is outermost: it then sees the final
  client-visible response and seeds correlation_id_context before the error
  handler reads it.
- Rows are written by a batching background writer with a bounded queue, so the
  request path never awaits the database and a saturated logger drops rows
  visibly (surfaced on the page) instead of blocking. Redaction runs on the
  writer, off the request coroutine.
- Secrets never land: headers are an allowlist with Authorization/Cookie kept
  only as a presence marker; body keys and value shapes are redacted
  (passwords, tokens, api_token, API keys, private-key PEMs, JWTs); the ACME
  JWS request body is never stored, because a stored protected+signature pair
  is a replayable credential — a summary is logged instead; DNS-provider errors
  record only the exception type; 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 (7 / 30) plus a hard row cap (500k),
  whichever is reached first. Pruned in batches under a Postgres advisory lock,
  with the day counts bound as parameters, never interpolated.
- New permissions requestlog.read / requestlog.manage. super_admin and
  security_admin get both, operator gets read, viewer gets neither.

Schema: one new table (request_logs) plus 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 (middleware never registered)
or the `enabled` toggle in Settings.

Tests: 245 new (7 backend files + 1 frontend), full suite 1655 backend +
17 frontend passing.
This commit is contained in:
mustafa.ulukaya
2026-08-11 02:36:03 +03:00
parent 02667bbda4
commit ef26860df9
38 changed files with 6289 additions and 158 deletions
+31
View File
@@ -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)
# ============================================================================
+47
View File
@@ -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
+2
View File
@@ -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.
+49
View File
@@ -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 = <defaults> 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
+30 -19
View File
@@ -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({
+45 -1
View File
@@ -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"
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)
+189 -5
View File
@@ -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',
+20 -7
View File
@@ -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()
+83 -2
View File
@@ -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
+293
View File
@@ -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,
)
)
+13 -3
View File
@@ -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}")
+489
View File
@@ -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.<action>`.
`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)
+28 -19
View File
@@ -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:
+17 -6
View File
@@ -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"
+94 -48
View File
@@ -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")
+35 -19
View File
@@ -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:
+38 -23
View File
@@ -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 <key>:<secret>` 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:
@@ -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
@@ -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"
)
+251
View File
@@ -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 <resource>.<action> 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."
)
+261
View File
@@ -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)
+262
View File
@@ -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
@@ -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"
)
+258
View File
@@ -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)
+276
View File
@@ -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
+302
View File
@@ -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:<task>` 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
+201
View File
@@ -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
+342
View File
@@ -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"
+256
View File
@@ -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)
+320
View File
@@ -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
)
+3 -3
View File
@@ -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"
}
+1 -1
View File
@@ -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": {
+20
View File
@@ -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;
}
+15 -1
View File
@@ -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: <FileTextOutlined />,
label: <Link to="/configuration">Config Versions</Link>,
},
{
key: '/request-log',
icon: <FileSearchOutlined />,
label: (
<Tooltip placement="right" title="Request Log — every API call in, and every HTTP call this backend made out (ACME, DNS, agents)">
<Link to="/request-log">Request Log</Link>
</Tooltip>
),
},
{
key: '/clusters',
icon: <CloudServerOutlined />,
@@ -469,6 +480,9 @@ function AppContent() {
<Route path="/security" element={<Security />} />
<Route path="/agents" element={<AgentManagement />} />
<Route path="/configuration" element={<Configuration />} />
{/* v1.11.0 the page gates itself on requestlog.read; the route
is unconditional like every other route in this app. */}
<Route path="/request-log" element={<RequestLog />} />
<Route path="/api-docs" element={<APIDocumentation />} />
<Route path="/pools" element={<PoolManagement />} />
<Route path="/settings" element={<Settings />} />
+606
View File
@@ -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 <Text type="secondary">Not captured</Text>;
}
return (
<pre
style={{
fontSize: 11,
margin: 0,
maxHeight: 260,
overflow: 'auto',
whiteSpace: 'pre-wrap',
wordBreak: 'break-word',
background: token.colorFillQuaternary,
border: `1px solid ${token.colorBorderSecondary}`,
borderRadius: token.borderRadius,
padding: 8,
}}
>
{typeof value === 'string' ? value : JSON.stringify(value, null, 2)}
</pre>
);
};
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: <DeleteOutlined />,
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) => <Text style={{ fontSize: 12 }}>{formatTime(v)}</Text>,
},
{
title: 'Direction',
dataIndex: 'direction',
width: 110,
render: (v) => (
<Tag color={v === 'inbound' ? 'blue' : 'purple'}>{v === 'inbound' ? 'IN' : 'OUT'}</Tag>
),
},
{
title: 'Method',
dataIndex: 'method',
width: 90,
render: (v) => <Tag>{v}</Tag>,
},
{
title: 'URL',
dataIndex: 'url',
ellipsis: true,
render: (v) => (
<Tooltip title={v} placement="topLeft">
<Text style={{ fontSize: 12 }} ellipsis>{v}</Text>
</Tooltip>
),
},
{
title: 'Status',
dataIndex: 'status_code',
width: 100,
render: (v, row) => (
<Tag color={statusColor(row.status_class)}>{v ?? 'ERR'}</Tag>
),
},
{
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".
<Text type={v > 1000 ? 'danger' : undefined} style={{ fontSize: 12 }}>{v} ms</Text>
),
},
{
title: 'Who / Where',
key: 'who',
width: 200,
render: (_, row) => {
if (row.direction === 'inbound') {
return (
<Space size={4}>
<UserOutlined />
<Text style={{ fontSize: 12 }}>{row.username || (row.user_id ? `#${row.user_id}` : 'anonymous')}</Text>
</Space>
);
}
return (
<Tooltip title={TARGET_LABELS[row.target] || row.target}>
<Tag icon={<ApiOutlined />}>{row.target || '—'}</Tag>
</Tooltip>
);
},
},
{
title: 'Error',
dataIndex: 'error',
width: 200,
ellipsis: true,
render: (v) => (v ? (
<Tooltip title={v}><Text type="danger" style={{ fontSize: 12 }}>{v}</Text></Tooltip>
) : <Text type="secondary"></Text>),
},
{
title: '',
key: 'actions',
width: 90,
fixed: 'right',
render: (_, row) => (
<Button size="small" icon={<EyeOutlined />} onClick={() => openDetail(row.id)}>
Detail
</Button>
),
},
]), [openDetail]);
if (!canRead) {
return (
<Card>
<Alert
type="error"
showIcon
message="Access denied"
description="You need the requestlog.read permission to view the request log."
/>
</Card>
);
}
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 (
<div>
<Card
title={<Space><ClockCircleOutlined />Request Log</Space>}
extra={
<Space>
<Button icon={<ReloadOutlined />} onClick={() => { fetchLogs(); fetchStats(); }} loading={loading}>
Refresh
</Button>
{canManage && (
<Button icon={<DeleteOutlined />} onClick={runPurge} loading={purging}>
Apply retention now
</Button>
)}
</Space>
}
>
<Alert
type="info"
showIcon
style={{ marginBottom: 16 }}
message="Every API call in, and every HTTP call out"
description={
<>
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 <strong>redacted and size-capped</strong> credentials,
tokens, private keys and ACME signatures are never stored. Retention is
configured in <Text code>Settings Request Log</Text>.
</>
}
/>
{scopedToSelf && (
<Alert
type="warning"
showIcon
style={{ marginBottom: 16 }}
message="Showing your own requests only"
description="Seeing every user's traffic, and all outbound calls, requires the requestlog.manage permission."
/>
)}
{dropped > 0 && (
<Alert
type="warning"
showIcon
icon={<WarningOutlined />}
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 && (
<Space size="large" wrap style={{ marginBottom: 16 }}>
<Statistic
title="Inbound (24h)"
value={inboundStats?.total || 0}
suffix={inboundStats?.errors ? <Text type="danger" style={{ fontSize: 14 }}>{`/ ${inboundStats.errors} failed`}</Text> : null}
/>
<Statistic
title="Outbound (24h)"
value={outboundStats?.total || 0}
suffix={outboundStats?.errors ? <Text type="danger" style={{ fontSize: 14 }}>{`/ ${outboundStats.errors} failed`}</Text> : null}
/>
<Statistic title="Rows stored" value={stats.total_rows || 0} />
<Statistic title="Oldest entry" valueRender={() => <span style={{ fontSize: 16 }}>{formatTime(stats.oldest_at)}</span>} />
</Space>
)}
<Space style={{ marginBottom: 16 }} wrap>
<Select
placeholder="All directions"
allowClear
style={{ width: 220 }}
value={direction}
onChange={(v) => { setDirection(v); setPage(1); }}
options={DIRECTION_OPTIONS}
/>
<Select
placeholder="All statuses"
allowClear
style={{ width: 210 }}
value={statusClass}
onChange={(v) => { setStatusClass(v); setPage(1); }}
options={STATUS_OPTIONS}
/>
<Select
placeholder="All methods"
allowClear
mode="multiple"
maxTagCount={1}
style={{ width: 180 }}
value={methods}
onChange={(v) => { setMethods(v); setPage(1); }}
options={METHOD_OPTIONS}
/>
<Select
placeholder="All targets"
allowClear
style={{ width: 220 }}
value={target}
disabled={direction === 'inbound'}
onChange={(v) => { setTarget(v); setPage(1); }}
options={Object.entries(TARGET_LABELS).map(([value, label]) => ({ value, label }))}
/>
<DatePicker.RangePicker
showTime
value={range}
onChange={(v) => { setRange(v); setPage(1); }}
/>
<Input.Search
placeholder="Search URL…"
allowClear
enterButton
style={{ width: 300 }}
value={searchTyped}
onChange={(e) => setSearchTyped(e.target.value)}
onSearch={(v) => { setSearch(v); setPage(1); }}
/>
<Space size={4}>
<Switch
checked={errorsOnly}
onChange={(v) => { setErrorsOnly(v); setPage(1); }}
checkedChildren="Errors"
unCheckedChildren="All"
/>
</Space>
</Space>
{loadError && (
<Alert type="error" showIcon style={{ marginBottom: 16 }} message={loadError} />
)}
<Table
rowKey="id"
size="small"
loading={loading}
dataSource={rows}
columns={columns}
scroll={{ x: 1400 }}
rowClassName={(row) => (isFailure(row) ? 'request-log-error-row' : '')}
locale={{
emptyText: <Empty description="No requests match these filters" />,
}}
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); },
}}
/>
</Card>
<Modal
open={detailOpen}
onCancel={() => setDetailOpen(false)}
width={960}
destroyOnClose
title="Request detail"
footer={<Button onClick={() => setDetailOpen(false)}>Close</Button>}
>
{detailLoading ? (
<div style={{ textAlign: 'center', padding: 48 }}><Spin /></div>
) : detailError ? (
<Alert type="error" showIcon message={detailError} />
) : !detailRow ? (
<Empty description="Nothing to show" />
) : (
<Space direction="vertical" size="middle" style={{ width: '100%' }}>
<Descriptions size="small" column={2} bordered>
<Descriptions.Item label="Time">{formatTime(detailRow.created_at)}</Descriptions.Item>
<Descriptions.Item label="Direction">
<Tag color={detailRow.direction === 'inbound' ? 'blue' : 'purple'}>{detailRow.direction}</Tag>
</Descriptions.Item>
<Descriptions.Item label="Method"><Tag>{detailRow.method}</Tag></Descriptions.Item>
<Descriptions.Item label="Status">
<Tag color={statusColor(detailRow.status_class)}>{detailRow.status_code ?? 'no response'}</Tag>
</Descriptions.Item>
<Descriptions.Item label="URL" span={2}>
<Text copyable style={{ fontSize: 12 }}>{detailRow.url}</Text>
</Descriptions.Item>
<Descriptions.Item label="Duration">{detailRow.duration_ms} ms</Descriptions.Item>
<Descriptions.Item label="Target">
{detailRow.target ? (TARGET_LABELS[detailRow.target] || detailRow.target) : '—'}
</Descriptions.Item>
<Descriptions.Item label="User">
{detailRow.username || (detailRow.user_id ? `#${detailRow.user_id}` : 'anonymous')}
</Descriptions.Item>
<Descriptions.Item label="Client IP">{detailRow.client_ip || '—'}</Descriptions.Item>
<Descriptions.Item label="Request id" span={2}>
<Text code copyable style={{ fontSize: 11 }}>{detailRow.request_id}</Text>
</Descriptions.Item>
{detailRow.error && (
<Descriptions.Item label="Error" span={2}>
<Text type="danger">{detailRow.error}</Text>
</Descriptions.Item>
)}
</Descriptions>
{detailRow.truncated && (
<Alert
type="warning"
showIcon
message="Body truncated"
description={
`Only the first part of the body was captured (request ${detailRow.request_body_bytes} bytes, ` +
`response ${detailRow.response_body_bytes} bytes on the wire). Raise the body cap in ` +
`Settings → Request Log if you need more.`
}
/>
)}
<Card size="small" title="Request headers">
<JsonBlock value={detailRow.request_headers} token={token} />
</Card>
<Card size="small" title="Request body">
<JsonBlock value={detailRow.request_body} token={token} />
</Card>
<Card size="small" title="Response headers">
<JsonBlock value={detailRow.response_headers} token={token} />
</Card>
<Card size="small" title="Response body">
<JsonBlock value={detailRow.response_body} token={token} />
</Card>
<Card
size="small"
title={<Space><CloudDownloadOutlined />Calls triggered by this request</Space>}
>
{detail?.related?.length ? (
<Table
rowKey="id"
size="small"
pagination={false}
dataSource={detail.related}
columns={[
{ title: 'Dir', dataIndex: 'direction', width: 70,
render: (v) => <Tag color={v === 'inbound' ? 'blue' : 'purple'}>{v === 'inbound' ? 'IN' : 'OUT'}</Tag> },
{ 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) => <Tag color={statusColor(r.status_class)}>{v ?? 'ERR'}</Tag> },
{ title: '', key: 'go', width: 70,
render: (_, r) => <Button size="small" type="link" onClick={() => openDetail(r.id)}>Open</Button> },
]}
/>
) : (
<Paragraph type="secondary" style={{ margin: 0 }}>
No other calls share this request id.
</Paragraph>
)}
</Card>
</Space>
)}
</Modal>
</div>
);
};
export default RequestLog;
+192 -1
View File
@@ -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 = () => {
</Spin>
),
},
{
key: 'requestlog',
label: (
<span><FileSearchOutlined /> Request Log</span>
),
children: (
<Spin spinning={rlLoading}>
<Card>
<Alert
message="Request / Response Log"
description="Records every inbound API call and every outbound HTTP call this backend makes (ACME, DNS providers, agents), with redacted and size-capped request and response bodies. Browse it under Request Log in the sidebar."
type="info"
showIcon
icon={<FileSearchOutlined />}
style={{ marginBottom: 24 }}
/>
{rlDenied && (
<Alert
message="Read-only"
description="Changing the request log policy requires the requestlog.manage permission."
type="warning"
showIcon
style={{ marginBottom: 24 }}
/>
)}
<Form
form={rlForm}
layout="vertical"
onFinish={onRequestLogSave}
disabled={rlDenied}
initialValues={{
enabled: true,
capture_inbound: true,
capture_outbound: true,
capture_get: true,
capture_bodies: true,
max_body_bytes: 8192,
sample_rate: 1.0,
success_retention_days: 7,
error_retention_days: 30,
max_rows: 500000,
prune_interval_minutes: 60,
exclude_paths: [],
}}
>
<Card size="small" title="Capture" style={{ marginBottom: 24 }}>
<Form.Item
name="enabled"
label="Enable request log"
valuePropName="checked"
tooltip="Turning this off stops all capture immediately, without a restart. To remove the middleware entirely set REQUEST_LOG_ENABLED=false in the backend environment."
>
<Switch />
</Form.Item>
<Form.Item name="capture_inbound" label="Log inbound API calls" valuePropName="checked">
<Switch />
</Form.Item>
<Form.Item
name="capture_outbound"
label="Log outbound HTTP calls"
valuePropName="checked"
tooltip="Calls this backend makes to Let's Encrypt / ACME, Cloudflare, GoDaddy, agents and HAProxy stats."
>
<Switch />
</Form.Item>
<Form.Item
name="capture_get"
label="Include GET requests"
valuePropName="checked"
tooltip="GETs are the bulk of the traffic. Turning this off keeps writes and errors only."
>
<Switch />
</Form.Item>
<Form.Item
name="capture_bodies"
label="Capture bodies (redacted)"
valuePropName="checked"
tooltip="Passwords, tokens, API keys, private-key PEMs and ACME signatures are never stored, whatever this is set to."
>
<Switch />
</Form.Item>
<Form.Item name="max_body_bytes" label="Maximum body size captured (bytes)">
<InputNumber min={0} max={262144} step={1024} style={{ width: 200 }} />
</Form.Item>
<Form.Item
name="sample_rate"
label="Sampling rate for successful requests"
tooltip="1.0 logs everything. Errors are always captured at 100%, whatever this is set to."
>
<InputNumber min={0} max={1} step={0.05} style={{ width: 200 }} />
</Form.Item>
</Card>
<Card size="small" title="Retention" style={{ marginBottom: 24 }}>
<Alert
type="warning"
showIcon
style={{ marginBottom: 16 }}
message="Whichever limit is reached first wins"
description="Rows are removed when they pass their retention window OR when the table exceeds the row cap — the cap is the backstop for a sudden traffic spike."
/>
<Form.Item name="success_retention_days" label="Keep successful requests for (days)">
<InputNumber min={1} max={365} style={{ width: 200 }} />
</Form.Item>
<Form.Item
name="error_retention_days"
label="Keep failed requests for (days)"
tooltip="4xx, 5xx and calls that got no response at all. Usually set longer than the success window."
>
<InputNumber min={1} max={365} style={{ width: 200 }} />
</Form.Item>
<Form.Item name="max_rows" label="Maximum stored rows">
<InputNumber min={1000} max={50000000} step={10000} style={{ width: 200 }} />
</Form.Item>
<Form.Item name="prune_interval_minutes" label="Minimum interval between prune passes (minutes)">
<InputNumber min={5} max={1440} style={{ width: 200 }} />
</Form.Item>
</Card>
<Card size="small" title="Excluded paths" style={{ marginBottom: 24 }}>
<Form.Item
name="exclude_paths"
label="Never log these path prefixes"
tooltip="Health checks, the API docs, the ACME challenge endpoint and the agent heartbeat are excluded by default. The log viewer's own endpoints are always excluded and cannot be re-enabled."
>
<Select
mode="tags"
tokenSeparators={[',', ' ']}
placeholder="/api/health"
style={{ width: '100%' }}
/>
</Form.Item>
</Card>
<Button type="primary" htmlType="submit" loading={rlSaving} disabled={rlDenied}>
Save Request Log Settings
</Button>
</Form>
</Card>
</Spin>
),
},
];
return (
+11
View File
@@ -216,6 +216,17 @@ const PERMISSION_TREE = [
{ title: 'Export Activity Logs', key: 'activity.export' }
]
},
// v1.11.0 — the API does no server-side whitelist of permission strings, so
// this tree is the ONLY catalogue an admin can grant from. Without an entry
// here the permission exists but is unreachable for custom roles.
{
title: '🧾 Request Log',
key: 'requestlog',
children: [
{ title: 'View Request/Response Logs', key: 'requestlog.read' },
{ title: 'Manage Retention & Purge', key: 'requestlog.manage' }
]
},
{
title: '⚙️ Settings',
key: 'settings',
@@ -0,0 +1,274 @@
/**
* v1.11.0 regression tests for the Request Log page.
*
* Three properties matter here and none of them are visible from a snapshot:
*
* 1. Pagination is SERVER-side. Every other table in this app fetches once and
* slices in the browser; this table can hold millions of rows, so changing
* the page MUST issue a new request with a new offset. A client-side slice
* would look identical on a two-row fixture and fall over in production.
* 2. The page gates itself on requestlog.read. The sidebar and the router are
* unconditional (App.js has no hook access at module level), so this
* component is the only gate and it must not even call the API when the
* caller lacks the permission.
* 3. Redacted values are what the modal shows. A test that only asserted the
* modal opens would still pass if the UI un-redacted anything.
*/
import React from 'react';
import { render, screen, fireEvent, waitFor, act } from '@testing-library/react';
import axios from 'axios';
import RequestLog from '../RequestLog';
// Rendering the antd Table + filter row + modal is slow; keep the limit here so
// plain `npm test` passes as shipped rather than needing --testTimeout.
jest.setTimeout(30000);
jest.mock('axios');
let mockPermissions = { read: true, manage: true, admin: false };
jest.mock('../../contexts/AuthContext', () => ({
useAuth: () => ({
hasPermission: (resource, action) =>
resource === 'requestlog' && Boolean(mockPermissions[action]),
isAdmin: () => mockPermissions.admin,
}),
}));
const INBOUND_ROW = {
id: 2,
request_id: 'abc123',
direction: 'inbound',
target: null,
method: 'POST',
url: '/api/letsencrypt/certificates',
path: '/api/letsencrypt/certificates',
status_code: 500,
status_class: 5,
duration_ms: 2431,
user_id: 1,
username: 'admin',
client_ip: '10.0.0.5',
error: null,
request_body_bytes: 120,
response_body_bytes: 88,
truncated: false,
created_at: '2026-08-11T09:00:00+00:00',
};
const OUTBOUND_ROW = {
id: 1,
request_id: 'abc123',
direction: 'outbound',
target: 'acme',
method: 'POST',
url: 'https://acme-v02.api.letsencrypt.org/acme/new-order',
path: '/acme/new-order',
status_code: 429,
status_class: 4,
duration_ms: 812,
user_id: null,
username: null,
client_ip: null,
error: null,
request_body_bytes: 0,
response_body_bytes: 210,
truncated: false,
created_at: '2026-08-11T09:00:01+00:00',
};
const LIST_RESPONSE = {
logs: [INBOUND_ROW, OUTBOUND_ROW],
total: 2,
total_is_estimate: false,
limit: 50,
offset: 0,
scoped_to_self: false,
};
const DETAIL_RESPONSE = {
log: {
...INBOUND_ROW,
query_params: null,
request_headers: { 'content-type': 'application/json', authorization: '***REDACTED***' },
request_body: { domains: ['example.com'], eab_hmac_key: '***REDACTED***' },
response_headers: { 'content-type': 'application/json' },
response_body: { error: { message: 'ACME rate limited' } },
},
related: [OUTBOUND_ROW],
};
const STATS_RESPONSE = {
window_hours: 24,
by_direction: [
{ direction: 'inbound', total: 120, errors: 3, avg_duration_ms: 45, max_duration_ms: 2431 },
{ direction: 'outbound', total: 18, errors: 1, avg_duration_ms: 300, max_duration_ms: 812 },
],
by_status_class: [],
by_target: [],
total_rows: 138,
oldest_at: '2026-08-04T09:00:00+00:00',
newest_at: '2026-08-11T09:00:01+00:00',
sink: { queued: 0, queue_capacity: 2000, written: 138, dropped: 0, failed_batches: 0, running: 1 },
retention: { success_retention_days: 7, error_retention_days: 30, max_rows: 500000 },
};
const listCalls = () => axios.get.mock.calls.filter((c) => c[0] === '/api/request-logs');
beforeEach(() => {
jest.clearAllMocks();
mockPermissions = { read: true, manage: true, admin: false };
axios.get.mockImplementation((url) => {
if (url === '/api/request-logs') return Promise.resolve({ data: LIST_RESPONSE });
if (url === '/api/request-logs/stats') return Promise.resolve({ data: STATS_RESPONSE });
if (url.startsWith('/api/request-logs/')) return Promise.resolve({ data: DETAIL_RESPONSE });
return Promise.resolve({ data: {} });
});
axios.post.mockResolvedValue({ data: { removed: { success: 1, error: 0, overflow: 0 } } });
});
async function renderPage() {
render(<RequestLog />);
await waitFor(() => expect(listCalls().length).toBeGreaterThan(0));
await act(async () => {});
}
test('renders both directions of a request from the list endpoint', async () => {
await renderPage();
expect(await screen.findByText('/api/letsencrypt/certificates')).toBeInTheDocument();
expect(screen.getByText('https://acme-v02.api.letsencrypt.org/acme/new-order')).toBeInTheDocument();
// Inbound shows the user; outbound shows the target it called.
expect(screen.getByText('admin')).toBeInTheDocument();
expect(screen.getByText('acme')).toBeInTheDocument();
expect(screen.getByText('500')).toBeInTheDocument();
expect(screen.getByText('429')).toBeInTheDocument();
});
test('a caller without requestlog.read sees a denial and the API is never called', async () => {
mockPermissions = { read: false, manage: false, admin: false };
render(<RequestLog />);
expect(await screen.findByText('Access denied')).toBeInTheDocument();
expect(axios.get).not.toHaveBeenCalled();
});
test('an admin without an explicit grant still gets in', async () => {
mockPermissions = { read: false, manage: false, admin: true };
await renderPage();
expect(await screen.findByText('/api/letsencrypt/certificates')).toBeInTheDocument();
});
test('the errors-only switch is sent to the server, not applied in the browser', async () => {
await renderPage();
const before = listCalls().length;
await act(async () => {
fireEvent.click(document.querySelector('.ant-switch'));
});
await waitFor(() => expect(listCalls().length).toBeGreaterThan(before));
const params = listCalls()[listCalls().length - 1][1].params;
expect(params.errors_only).toBe(true);
});
test('the direction filter is sent as a query parameter', async () => {
await renderPage();
const before = listCalls().length;
await act(async () => {
fireEvent.mouseDown(document.querySelectorAll('.ant-select-selector')[0]);
});
await act(async () => {
const option = Array.from(document.querySelectorAll('.ant-select-item-option'))
.find((el) => el.textContent.includes('Outbound'));
fireEvent.click(option);
});
await waitFor(() => expect(listCalls().length).toBeGreaterThan(before));
const params = listCalls()[listCalls().length - 1][1].params;
expect(params.direction).toBe('outbound');
});
test('the first request asks for a bounded page, not the whole table', async () => {
await renderPage();
const params = listCalls()[0][1].params;
expect(params.limit).toBe(50);
expect(params.offset).toBe(0);
});
test('opening a row fetches the detail and shows the REDACTED body', async () => {
await renderPage();
await act(async () => {
fireEvent.click(screen.getAllByText('Detail')[0]);
});
await waitFor(() =>
expect(axios.get).toHaveBeenCalledWith(expect.stringMatching(/\/api\/request-logs\/\d+$/))
);
const modal = await waitFor(() => document.querySelector('.ant-modal-content'));
expect(modal.textContent).toContain('***REDACTED***');
// The redaction happens server-side; the UI must not attempt to show a raw value.
expect(modal.textContent).not.toContain('eab_hmac_key":"');
expect(modal.textContent).toContain('ACME rate limited');
});
test('the detail modal lists the outbound calls triggered by the same request', async () => {
await renderPage();
await act(async () => {
fireEvent.click(screen.getAllByText('Detail')[0]);
});
const modal = await waitFor(() => document.querySelector('.ant-modal-content'));
await waitFor(() => expect(modal.textContent).toContain('Calls triggered by this request'));
expect(modal.textContent).toContain('acme');
});
test('a self-scoped response explains why the list is narrower', async () => {
axios.get.mockImplementation((url) => {
if (url === '/api/request-logs') {
return Promise.resolve({ data: { ...LIST_RESPONSE, scoped_to_self: true } });
}
if (url === '/api/request-logs/stats') return Promise.resolve({ data: STATS_RESPONSE });
return Promise.resolve({ data: {} });
});
await renderPage();
expect(await screen.findByText('Showing your own requests only')).toBeInTheDocument();
});
test('dropped rows are surfaced as a warning', async () => {
axios.get.mockImplementation((url) => {
if (url === '/api/request-logs') return Promise.resolve({ data: LIST_RESPONSE });
if (url === '/api/request-logs/stats') {
return Promise.resolve({ data: { ...STATS_RESPONSE, sink: { ...STATS_RESPONSE.sink, dropped: 42 } } });
}
return Promise.resolve({ data: {} });
});
await renderPage();
expect(await screen.findByText(/42 row\(s\) dropped/)).toBeInTheDocument();
});
test('a failed load surfaces the server message instead of a blank table', async () => {
axios.get.mockImplementation((url) => {
if (url === '/api/request-logs') {
return Promise.reject({
response: { status: 500, data: { error: { message: 'Failed to list request logs' } } },
});
}
return Promise.resolve({ data: STATS_RESPONSE });
});
await renderPage();
expect(await screen.findByText('Failed to list request logs')).toBeInTheDocument();
});
test('the retention button is hidden without requestlog.manage', async () => {
mockPermissions = { read: true, manage: false, admin: false };
await renderPage();
expect(screen.queryByText('Apply retention now')).not.toBeInTheDocument();
});