diff --git a/docs/BACKLOG.md b/docs/BACKLOG.md index 55cc19edd..a0c816785 100644 --- a/docs/BACKLOG.md +++ b/docs/BACKLOG.md @@ -2220,7 +2220,17 @@ lane; demand-gated on a first enterprise Windows/AD deployment. ## 122. Corrupted application-log detection, rollover, and connection-stop -> πŸ”’ **Re-scored 2026-08-20 -> P2.** Value **7/10** Β· Difficulty **6/10** Β· _big bet_. No enforcement ships: the only log handlers on main are the stdout StreamHandler at logging_setup.py:427 and the syslog family, and nothing anywhere reacts to a write failure by stopping work. The owner ruling of 2026-08-11 binds this to the count-and-log invariant, which is enforcement rather than the visibility the 2/10 priced. Difficulty 6 prices a fail-closed halt across the listener and the internal routed/outbound stages plus a console-seam change, with the eight branch commits unverified and carrying a seam bump #1220 obsoleted. _(was 2/10 Β· 6/10.)_ +> βœ… **SHIPPED 2026-09-04 β€” the enforcement is built, and the halt was VERIFIED BY EXECUTION rather than by reading the branch's commit subjects.** `messagefoundry/logging_guard.py` adds `LogWriteGuard` plus `GuardedStreamHandler` / `GuardedFileHandler`: detection is a `logging.Handler.handleError` override, so one seam covers every sink with no polling, and the response is two-stage β€” `_roll` renames the broken file aside, opens a fresh one, records the rollover in it and re-writes the failed record; only when the REPLACEMENT also refuses does `record_unwritable` escalate. Stage 1 is bounded (`_ROLL_FLAP_WINDOW_SECONDS` / `_MAX_ROLLS_PER_WINDOW`), because a sink needing rescue every few records is a failing log rather than a transient. `[logging].file` / `file_max_bytes` / `file_backup_count` / `on_write_failure` are real `LoggingSettings` fields, and the validator refuses a `file` inside `log_dir` so the engine and NSSM can never rotate one file. The stop reaches all three tiers, `SystemStatus.log_sinks` reports per-sink health from process memory, and a `log_write_failed` alert pages through the notifier rather than through the log that broke. +> +> **THE PARTIAL HALT WAS REAL, and the fix for it is load-bearing β€” measured, not argued.** Mutating `_halt_inbound_processing` to a no-op (the pre-fix shape: listener stop plus outbound pause only) put the committed ingress row on the **outbound stage** in BOTH claim modes, while the healthy-log negative control still delivered. Mutating `_log_recovery_ok` to always-true let `restart_inbound` + `start_outbound` disarm the halt in both modes. Both mutations were reverted and the tree verified clean. +> +> **A THIRD HOLE OF THE SAME CLASS WAS FOUND HERE, and it was NOT on the branch.** `RegistryRunner.start` cleared `_log_write_stopped` and `_log_halted` unconditionally, so it was the one re-arm path that never asked whether the log worked. Measured before the fix, both claim modes: with both sinks unwritable BEFORE the runner was built, a committed ingress row reached `PROCESSED` and was DELIVERED while `LogWriteGuard.can_log()` read False throughout. `Engine` starts a runner on leadership acquisition and on the reload that first builds one, so it is reachable plumbing. `start` now gates the clear on `revalidate`, `_start_pooled_dispatchers` replays the halt onto the fresh internal dispatchers before they seed lanes READY, and `_unbind_for_log_failure` takes the already-bound listeners back down. +> +> **ADR 0162's FILE IS NOT ON `main`, and that is a ledger-gate strand rather than an oversight β€” the number is NOT burned.** Its claim names a worktree that no longer exists, and the branch fallback names `w3-log-write-failure`, whose history shares **no root commit** with `main` (roots `5fa6db9f` and `72bfddfa`), so no commit made there can reach a mergeable pull request. Both documented recoveries β€” commit from the recorded tree, or check that branch out β€” are unreachable from an isolated worktree, and remedy 3 (allocate a fresh number) is not licensed while the branch still exists. Prose therefore cites `ADR 0162` with no relative link, so nothing dangles; the file and its index row are the one residual. The subject to file, unallocated: the ledger gate's branch fallback assumes the recorded branch can produce a mergeable commit, and an orphan-history branch cannot. +> +> **What the branch's own commits turned out to be worth, and the anchor below is stale.** The branch tip is `46b3a4437` on both `origin` and locally, not the `d26d66a6` recorded below -- it moved after that note was written, and it carries eight commits rather than five. The seam bump (`ENGINE_UI_SEAM: int = 19`) was obsoleted by #1220 and is replaced by the computed digest; the PHI-inventory anti-rot gates and the reload-recovery measurement both hold and their tests pass; the stdout hair-trigger fix holds. The `docs/testing/master-test-plan/` edit was dropped, that tree having been untracked under ADR 0160 D1. +> +> **Re-scored 2026-08-20 -> P2.** Value **7/10** Β· Difficulty **6/10** Β· _big bet_. No enforcement ships: the only log handlers on main are the stdout StreamHandler at logging_setup.py:427 and the syslog family, and nothing anywhere reacts to a write failure by stopping work. The owner ruling of 2026-08-11 binds this to the count-and-log invariant, which is enforcement rather than the visibility the 2/10 priced. Difficulty 6 prices a fail-closed halt across the listener and the internal routed/outbound stages plus a console-seam change, with the eight branch commits unverified and carrying a seam bump #1220 obsoleted. _(was 2/10 Β· 6/10.)_ > > **Re-scored 2026-08-03 β†’ DEMAND-GATE.** Value 2 stands β€” stdout + NSSM rotation, the RFC 5425 TLS syslog forwarder (`_TlsSysLogHandler`, logging_setup.py:281) and #50's disk metering already carry log durability and visibility, so this is marginal and substantially covered. But difficulty 5 prices the wrong shape of work. D5 is "a new connector/codec behind the transport registry" β€” this is not a connector. logging_setup.py's module docstring (lines 3-13) records that the engine "deliberately do[es] not add file handlers here" because NSSM owns rotation, and `grep FileHandler _(was 2/10 Β· 5/10.)_ > **On-trigger / demand-gate.** Numbered for tracking only β€” build when the trigger below fires (β€œdemand-gate, don’t schedule”). @@ -2228,8 +2238,8 @@ lane; demand-gated on a first enterprise Windows/AD deployment. > **The 2/10 was arrived at by conflating VISIBILITY with ENFORCEMENT.** stdout, NSSM rotation, the TLS syslog forwarder and #50's disk metering make the log *visible*; none of them makes processing *stop* when the log cannot be written. The item is the enforcement, and that is what the owner ruled in. **A guard that logs a warning and lets processing continue does not satisfy this item** β€” that is the specific defect to check for at review. > **Work exists and is UNVERIFIED.** `w3-log-write-failure` (`d26d66a6`, pushed and anchored) carries five commits whose subjects claim: the halt let the backlog keep routing so the internal stages are stopped too; a reload-recovery claim that *"was a guess"* was measured and three docs corrected; two PHI-inventory anti-rot gates found red on the branch; and a console-contract seam bump. **The lane died mid-flight on a usage limit, so none of it is verified.** It carries **ADR 0162**, whose number was independently confirmed to come from `alloc.ps1` β€” a real allocation record exists and `main`'s highest is 0161 β€” so the number is sound, but the index row should be re-checked before landing since a rebase can drop it. > **The claim most worth verifying by execution is the partial halt:** a halt that stops intake while routed and outbound rows keep draining would still violate the invariant this item exists to protect. -> Verdict: demand-gate -> Closing-act: owner-ruling +> Verdict: build +> Closing-act: code **Cluster:** Logging & Audit. **Priority:** P3. **Verdict:** demand-gate. **Severity (vs Corepoint):** minor. diff --git a/docs/CONFIGURATION.md b/docs/CONFIGURATION.md index 5a2b79129..510937857 100644 --- a/docs/CONFIGURATION.md +++ b/docs/CONFIGURATION.md @@ -33,7 +33,12 @@ > `[retention].audit_days` (**reserved/keep-forever by design**), `[reference].max_staleness_seconds`, > `[ai].baa_attested`, and `[update_check].index_url`/`index_allowed_hosts`. The former > "accepted-but-ignored" keys that were never fields at all β€” `[delivery].outbox_workers`/`dead_letter` -> and `[logging].file`/`max_bytes`/`backups` β€” now **refuse**. +> and `[logging].max_bytes`/`backups` β€” now **refuse**. **`[logging].file` is no longer one of them:** +> #122 / ADR 0162 made it a real, engine-owned field, and the two legacy spellings beside it refuse. +> **They refuse on BOTH layers, and only one of those is the general rule.** In the file they hit the +> unknown-key refusal above (`max_bytes` is even suggested onward as `file_max_bytes`; `backups` is +> refused naming nothing). From **env** β€” where a misspelled `MEFOR_*` is otherwise dropped in +> silence β€” they hit a dedicated `[logging]` validator that names the replacement for both. ## Principle β€” two kinds of configuration @@ -674,7 +679,7 @@ Only `baa_attested` is still a forward-compat placeholder (accepted-but-ignored) |---|---|---|---| | `level` | enum | `info` | log level. `debug` can surface full message bodies / raw field values into the general log. **`serve` refuses `debug` on a `production_instance` only** (Gate #1, keyed on the production tier alone β€” see `[security].production_instance`). It is **not** keyed on PHI: since [ADR 0148](adr/0148-phi-default-posture-and-an-explicit-security-enforcement-level.md) a `dev`/`staging` instance also carries PHI, and one of those **will start at `debug` with nothing refusing**. Don't raise any PHI box to `debug` β€” the gate will not stop you. | | `format` | enum | `text` | stdout rendering: `text` (default) or structured `json` (one object per line). Stdlib only β€” no structlog | -| `log_dir` | str | _unset_ | the directory NSSM (or another supervisor) **rotates the engine's captured stdout/stderr into**. The engine never writes log **files** itself (it logs to stdout); set this only to tell it where the supervisor parks them, and `GET /status` then **meters that directory's total bytes + filesystem free space** alongside the DB metrics (#50). Unset = stdout-only, no metering. **Metadata only** β€” the file contents are never read. | +| `log_dir` | str | _unset_ | the directory NSSM (or another supervisor) **rotates the engine's captured stdout/stderr into**. The engine writes no log **file** of its own unless `file` below is set (opt-in, off by default); set this only to tell it where the supervisor parks the captured stdout, and `GET /status` then **meters that directory's total bytes + filesystem free space** alongside the DB metrics (#50). Unset = stdout-only, no metering. **Metadata only** β€” the file contents are never read. | | `forward_enabled` | bool | _derived_ | ship a copy of every record off-box to a syslog/SIEM collector (sec-offbox-log) so evidence survives a host compromise. **Default-on-when-configured (ADR 0080):** unset β‡’ on iff `forward_host` is set. Set `false` to opt out even with a host; no `forward_host` β‡’ off (stdout-only, unchanged) | | `forward_host` | str | β€” | syslog/SIEM collector host. Setting it turns forwarding on by default (above) | | `forward_port` | int | `514` | collector port (1–65535) | @@ -689,7 +694,10 @@ Only `baa_attested` is still a forward-compat placeholder (accepted-but-ignored) | `ntp_peer` | str | β€” | NTP/SNTP host to compare the local clock against (**required** when `require_time_sync`) | | `time_sync_max_skew_seconds` | float | `2.0` | \|local βˆ’ peer\| above this is "skewed" (must be > 0) | | `time_sync_fail_closed` | bool | `false` | **refuse to start** (instead of warn) on skew or an unreachable peer. Further opt-in; requires `require_time_sync` | -| `file`, `max_bytes`, `backups` | str/int | β€” | **REFUSED** β€” none is a `LoggingSettings` field, and an unrecognized key now fails the start rather than loading silently. The engine logs to stdout and NSSM rotates it; `log_dir` above is how you point the engine at where it lands | +| `file` | str | _unset_ | **opt-in application-log file the ENGINE owns end to end** (#122, ADR 0162) β€” it opens it, size-rotates it, and rolls it aside on a write failure. Distinct from `log_dir` above, which is where the **supervisor** parks the captured stdout: **one file, one rotation owner**, so a `file` inside `log_dir` is **refused at load** rather than left to fight NSSM. Unset (the default) = stdout-only, unchanged. A path the engine cannot open **refuses startup** β€” an engine that starts unable to log is the blindness this closes | +| `file_max_bytes` | int | `50000000` | size-rotate `file` at ~50 MB (`0` = never rotate on size). Engine-side rotation, unrelated to NSSM's. The legacy planned spelling `max_bytes` is **refused at load** naming this key, rather than silently ignored -- from the file by the unknown-key refusal, and from `MEFOR_LOGGING_MAX_BYTES` by a `[logging]` validator, which is the layer the general file refusal does not reach | +| `file_backup_count` | int | `5` | how many `file.1` … `file.N` backups to keep. The legacy planned spelling `backups` is likewise refused on both layers, though only the env one names this key: the file refusal's nearest-name hint does not reach it. The `*.broken-*` files a write failure rolls aside are **deliberately outside** this chain β€” they are incident evidence, and a rotation that could delete them would delete the record of the failure | +| `on_write_failure` | enum | `stop` | **fail-closed control (#122):** when a log sink cannot be written **and** the fresh sink rolled into its place cannot be written either, stop every connection this engine **process** owns, in all three tiers β€” inbounds stop accepting, messages already accepted stop being routed and transformed, and outbounds pause with their queued rows **retained** (never dead-lettered). Recover by **fixing the log and then** restarting the affected connections, inbound **and** outbound (or the service): a `/config/reload` re-arms the inbounds it re-binds but deliberately never resumes a paused outbound, so on its own it moves the backlog one stage and stops. Every re-arm path is **gated on the log working again** β€” the engine re-checks by writing a real record to each dead sink at the moment you ask, and a restart issued against a still-unwritable log is **refused** (the connection stays halted, its listener stays down, and another `log_write_failed` names the refusal), so restarting repeatedly is not a way around the control. A first failure alone never stops anything; the roll absorbs the transient. Scope is the process because the application log is process-global and no per-connection attribution exists (ADR 0162 Β§4); under engine sharding that is the shard's connections. `continue` is the documented opt-out β€” it still rolls and still alerts, it just keeps processing with no log. The stop is announced by a `log_write_failed` alert through the notifier, a `connection_stopped` per halted connection naming the cause, and `GET /status`'s `log_sinks` block | > PHI redaction + control-char scrubbing are **always-on handler filters** (not a toggle) applied to > **every** sink, including the off-box forwarder ([`logging_setup.py`](../messagefoundry/logging_setup.py), diff --git a/docs/PHI.md b/docs/PHI.md index 941e5ac52..c202fa6f4 100644 --- a/docs/PHI.md +++ b/docs/PHI.md @@ -99,7 +99,7 @@ destruction) are documented in [Β§3](#3-encryption-at-rest) under the matching h | `[backup].destination/mefor-backup-*.mfbak` (ADR 0049 DR backup) | **SQLite only** carries bodies | **SQLite: Yes** β€” a consistent store snapshot (full inbound + outbound bodies) + the config bundle. **SQL Server / Postgres: No** β€” config bundle only | **Yes** β€” `.mfbak` chunked-AEAD codec under the **store DEK** (`resolve_active_key`); an identity-cipher (no-key) box is **refused** unless `[backup].allow_unencrypted` writes a `.mfbak.plain` | **PL-1** (SQLite) / **PL-4** (server backends) | On a **server-DB store `snapshot_to` raises `DbaDelegatedError`**, so the BackupRunner writes a **config-only** archive β€” or skips entirely when `[backup].config_only_on_server_db = false`. There is therefore **no `.mfbak` containing message bodies on SQL Server or Postgres**; the DB-tier backup there is `BACKUP DATABASE` / Always On / `pg_dump` / PITR, infra-owned. Where bodies *are* present it is a second at-rest PHI copy, bounded by keep-N retention; like `uploads_dir` it is **not** re-encrypted by `rotate-key`. The share's own ACLs are infra-owned | ``keep-N `[backup].retention_keep` `` | | `mefor-backup-*` / `mefor-tar-*` / `mefor-verify-*` staging dirs (OS temp dir, ADR 0049) | SQLite carries bodies; server backends config-only | **Yes** β€” a full store snapshot, and on verify a **decrypted** archive | **No** β€” the snapshot keeps the store's own column cipher, but the staging tar and the verify extraction are **plaintext on disk**; no engine ACL (`_secure_file` is never called on these paths) | **PL-1** | `run_backup` snapshots the store to `/store.db` and tars it **plaintext** before sealing it into the `.mfbak` (`pipeline/dr_backup.py`), and `[backup].verify_after_backup` (**default `true`**) decrypts the archive straight back out to a second temp dir on **every** run β€” independent of `full_restore_verify`. Transient (the `TemporaryDirectory` unlinks on exit) but **not** on a crash or `SIGKILL`. Lives under `%TEMP%` / `TMPDIR`, **not** the ACL'd data dir: cover the temp volume with FDE and point `TMP`/`TMPDIR` at an owner-only path ([Β§10](#10-secure-deployment--operations-checklist)) | `UNBOUNDED β€” honest gap` | | File-connector output / spill dirs (`.hl7`, `.processed`, `.error`) | all | **Yes** β€” plaintext on disk | **No** β€” no cipher at all on this path | **PL-1** | Written by the File transport; treat the directory as PHI and cover it with volume/share encryption + an ACL | `UNBOUNDED β€” honest gap` | -| Application log files (`[logging].log_dir`; under NSSM, `\logs\service.out.log` and `service.err.log`) | all (filesystem, not the DB) | **Possibly** β€” redaction is best-effort; a single-token identifier can survive it | **No** β€” plaintext on disk, no app-level cipher | **PL-1** | The engine installs no file handler; NSSM captures stdout/stderr. The defence is the three handler filters + `safe_exc()`/`safe_text()` + the never-log-bodies rule ([Β§7](#7-logging--phi-redaction) row 1), and the residual is stated there. The directory ACL is the NSSM installer's **best-effort** `icacls /inheritance:r`; age deletion is `[retention].app_log_days` (files by **mtime** β€” content is never read, so nothing selective happens here) and optional in-place gzip is `[retention].app_log_compress_days` (the compressor **does** read a file's bytes to archive + integrity-verify them, but only in-process β€” nothing is logged, and the archive stays inside the same ACL'd directory at the source's mtime). A support bundle copies a 500-line tail of this file out of the ACL'd directory entirely ([Β§7](#7-logging--phi-redaction)). Cover the volume with FDE ([Β§10](#10-secure-deployment--operations-checklist)) | `` `[retention].app_log_days` `` | +| Application log files (`[logging].log_dir`; under NSSM, `\logs\service.out.log` and `service.err.log`) | all (filesystem, not the DB) | **Possibly** β€” redaction is best-effort; a single-token identifier can survive it | **No** β€” plaintext on disk, no app-level cipher | **PL-1** | NSSM captures stdout/stderr; the engine writes a log file of its own only when the opt-in `[logging].file` is set (#122, ADR 0162 β€” same three handler filters, engine-owned rotation, refused inside `log_dir`), together with the `*.broken-*` files a write failure rolls aside, which sit outside `log_dir` and are therefore NOT swept by `[retention].app_log_days`. The defence is the three handler filters + `safe_exc()`/`safe_text()` + the never-log-bodies rule ([Β§7](#7-logging--phi-redaction) row 1), and the residual is stated there. The directory ACL is the NSSM installer's **best-effort** `icacls /inheritance:r`; age deletion is `[retention].app_log_days` (files by **mtime** β€” content is never read, so nothing selective happens here) and optional in-place gzip is `[retention].app_log_compress_days` (the compressor **does** read a file's bytes to archive + integrity-verify them, but only in-process β€” nothing is logged, and the archive stays inside the same ACL'd directory at the source's mtime). A support bundle copies a 500-line tail of this file out of the ACL'd directory entirely ([Β§7](#7-logging--phi-redaction)). Cover the volume with FDE ([Β§10](#10-secure-deployment--operations-checklist)) | `` `[retention].app_log_days` `` | | `messages.summary` | all three | **Yes** β€” MRN / patient name / order | **Yes, when a key is set** β€” store cipher; AAD `("messages","summary",id)`; store DEK (EF-3) | **PL-2** | Ingest-derived; no SQL search or index exists on it, so encrypting it costs nothing. NULL/blank stay as-is | ``rides `[security].delete_message_bodies_after_days` `` | | `messages.metadata` | all three | **Yes** β€” operator/handler-attached values | **Yes, when a key is set** β€” store cipher; AAD `("messages","metadata",id)`; store DEK (EF-3) | **PL-2** | **Nulled by `purge_message_bodies` on the `[retention].messages_days` window, in the same statement as the body** (ASVS 14.2.7) β€” see [Β§8](#8-retention--purge) | ``rides `[security].delete_message_bodies_after_days` `` | | `messages.error` | all three | **Possibly** β€” may embed raw fragments from exceptions | **Yes, when a key is set** β€” store cipher; AAD `("messages","error",id)`; store DEK (WP-5) | **PL-2** | Also `safe_exc()`-redacted **before** write. NULL/blank values stay as-is | ``rides `[security].delete_message_bodies_after_days` `` | @@ -1002,14 +1002,14 @@ with materially different PHI profiles, so they get their own rows; stream 4 is | Stream | Events logged | Format | Where stored | How used | Access control | Retention | PHI / sensitive free text + redaction | |---|---|---|---|---|---|---|---| -| **1. General application log** | operational events, worker/connection lifecycle, exception **types**, warnings, every alert that the `LoggingAlertSink` fallback implements when no `[alerts]` transport is configured (see row 13 for the two it does not) | single-line text (`[logging].format = "text"`, the default) or one JSON object per line (`"json"`); UTC `Z` timestamps in both | stdout only β€” the engine installs **no file handler**; under NSSM the supervisor captures stdout/stderr to `\logs\service.out.log` / `service.err.log` | day-to-day operations, incident triage, and the source of the support-bundle tail in row 14 | at rest: the NSSM installer creates `\logs` and locks the whole DataDir with `icacls /inheritance:r` to SYSTEM + Administrators + the service account (best-effort β€” a failure warns, never aborts). Over the API: `GET /logs/tail` requires the dedicated **`logs:view`** permission **and** `require_phi_read`, and every served page writes a `logs_view` audit row (line **count** only, never content) | NSSM rotates by **size** (`AppRotateBytes` 10 MB) and never deletes by age; age deletion is `[retention].app_log_days` over `[logging].log_dir` (`.log`/`.txt`, by mtime, **content never read**), optionally preceded by in-place gzip on `[retention].app_log_compress_days` (integrity-validated before the original is removed; the archive keeps the source's mtime, so the same delete window ages it out). Both default 0 = keep forever, uncompressed | **Can contain PHI.** The engine's own permission catalog classifies this as a PHI read surface (`logs:view`: "best-effort redaction, residual single-token PHI possible"). Defence: never-log-bodies rule, `safe_exc()` at the source, the three handler filters, python-hl7 loggers silenced. **Residual:** a single-token identifier is not scrubbed | +| **1. General application log** | operational events, worker/connection lifecycle, exception **types**, warnings, every alert that the `LoggingAlertSink` fallback implements when no `[alerts]` transport is configured (see row 13 for the two it does not) | single-line text (`[logging].format = "text"`, the default) or one JSON object per line (`"json"`); UTC `Z` timestamps in both | stdout by default β€” under NSSM the supervisor captures stdout/stderr to `\logs\service.out.log` / `service.err.log`; **plus** the opt-in engine-owned `[logging].file` when configured (#122, ADR 0162), which carries the identical filter chain and whose write failures roll it aside and, on a second failure, stop this process's connections | day-to-day operations, incident triage, and the source of the support-bundle tail in row 14 | at rest: the NSSM installer creates `\logs` and locks the whole DataDir with `icacls /inheritance:r` to SYSTEM + Administrators + the service account (best-effort β€” a failure warns, never aborts). Over the API: `GET /logs/tail` requires the dedicated **`logs:view`** permission **and** `require_phi_read`, and every served page writes a `logs_view` audit row (line **count** only, never content) | NSSM rotates by **size** (`AppRotateBytes` 10 MB) and never deletes by age; age deletion is `[retention].app_log_days` over `[logging].log_dir` (`.log`/`.txt`, by mtime, **content never read**), optionally preceded by in-place gzip on `[retention].app_log_compress_days` (integrity-validated before the original is removed; the archive keeps the source's mtime, so the same delete window ages it out). Both default 0 = keep forever, uncompressed | **Can contain PHI.** The engine's own permission catalog classifies this as a PHI read surface (`logs:view`: "best-effort redaction, residual single-token PHI possible"). Defence: never-log-bodies rule, `safe_exc()` at the source, the three handler filters, python-hl7 loggers silenced. **Residual:** a single-token identifier is not scrubbed | | **2. `uvicorn` request/access log** (sub-stream of 1) | one line per HTTP request β€” method, **full request line including the query string**, status, timing | inherits stream 1's format | inherits stream 1's sink | request tracing, latency and error triage | inherits stream 1's | inherits stream 1's | **Can contain PHI.** `configure_logging` clears uvicorn's own handlers and propagates to the root, so the three filters apply; `serve` passes `log_config=None` and never disables `access_log`, so at the default `INFO` level every request is logged. OIDC `code`/`state` **are** scrubbed. **Not** scrubbed: PHI-shaped search needles on GET routes (`?content=…`, `?field_value=…`) β€” the single-token residual above | | **3. `messagefoundry.audit` off-box tee** (sub-stream of 1) | one JSON object per **committed** `audit_log` row: `event`/`ts`/`action`/`actor`/`channel_id`/`client`/`detail` | JSON | emitted after the row is durably committed and **outside** the store write lock; rides stream 1's handlers | shipping audit evidence to a SIEM so it survives a host compromise | inherits stream 1's | inherits stream 1's | `detail` is passed through the `safe_text` PHI chokepoint **before** it leaves the process; `client` is forwarded verbatim as a discrete field so a SIEM can index it. Best-effort: a logging failure is caught, never raised into the audit write. **Pinned to `INFO`** β€” it is emitted even at `[logging].level = WARNING` | | **4. Off-box syslog/SIEM forwarder** β€” the shared **transport** for 1–3 | a copy of every record from 1–3 | `forward_format`, default **JSON** (independent of the stdout format) | the operator's collector (`forward_host`/`_port`) | off-box evidence retention / SIEM correlation | **default-on when a collector is named.** Transport: `udp` (default) / `tcp` / **`tls`** (RFC 5425, CA-anchored, verified by default). `serve` gates the hop on the shared posture gradient before the handler is installed: verified TLS ungated; otherwise loopback / attested / synthetic ALLOW, non-enforcing PHI WARN, **enforcing PHI REFUSE (exit 2)** | the collector's, not the engine's | the identical three filters are installed on this handler, so the forwarded copy is PHI-redacted β€” but it still carries usernames, connection names, message ids, client addresses and the audit chain. That is the engine's own stated reason for gating the hop | | **5. `audit_log` table** (SQLite, Postgres, SQL Server) | who / what / **where-from** / when of auth + PHI *access* and admin actions β€” plus, while `[security].audit_all_authorization_decisions` is on (**default `true`** since BACKLOG #1277, 2026-09-02, which reversed the ADR 0118 Β§5 `false`; the internal field it desugars to is `audit_all_authz`, whose old `[diagnostics]` TOML spelling is **refused at load** β€” ADR 0118), an `authz` row for **every** authorization decision including successes. That is the shipped volume of this stream, not an opt-in addition to it: one row per authenticated request on each `require()`-gated route, and this row's retention cell records that **nothing prunes the table** β€” `actor`, `action`, `channel_id`, `client`, `detail`, `row_hash` | JSON `detail`; **tamper-evident hash chain** over `prev_hash` + the row (the `client` address is **inside** the chained payload β€” ADR 0150) | the store database | HIPAA Β§164.312(b) audit controls; incident response; `verify_audit_chain` integrity checks | `GET /audit` requires **`audit:read`**; `GET /audit/export` requires the separate **`audit:export`** and streams CSV with formula-injection neutralisation, recording its own `audit.export` row *before* streaming; `GET /me/security-events` is a per-user view of the same table | **`[retention].audit_days` is reserved and NOT enforced β€” keep-forever by design** (the audit-retention requirement, ~6 years β€” **not** chain-breakage; [Β§8](#8-retention--purge) states the position and cites its source of record) | `detail` is stored **in the clear** (it is not a cipher-covered column): its protection is that writers only ever store filter shapes, counts and ids β€” never bodies or credentials β€” plus the store ACL and the volume layer | | **6. `message_events` table** | the per-message disposition timeline β€” the **complete** vocabulary is `received`, `routed`, `unrouted`, `filtered`, `transformed`, `delivered`, `failed`, `dead`, `error`, `replayed`, `resent`, `reingressed`, `passthrough`, `passthrough_dropped`, `cancelled`, `edit_resend`, `edit_resubmit`, `viewed`, `not_deployed`, and the ADR 0154 synchronous-reply pair `reply_returned` / `reply_timeout` (names, counts and `waited_ms` only β€” **never** a fragment of the partner's reply body) (CI asserts this list against the engine's own `MESSAGE_EVENT_KINDS`). `[diagnostics].message_events` can thin the set, but never below the compliance floor `viewed` / `dead` / `error` / `failed` / `not_deployed` / `reply_timeout` | rows: `message_id`, `ts`, `event`, `destination`, `detail` | the store database | operator timeline on the message-detail view; the `viewed` row is the HIPAA PHI-access record | `GET /messages/{id}` under **`messages:view_raw`** + `require_phi_read`; the read itself writes a `viewed` event **and** a `message_view` audit row | no dedicated window β€” `purge_message_bodies` sets `message_events.detail` to `NULL` in the same transaction that blanks the body, so it inherits `[retention].messages_days` | `detail` is `safe_text()`-scrubbed **then** cipher-encrypted (AAD `("message_events","detail",message_id,ts,event)`). Verbosity gate `[diagnostics].message_events` = `all` (default) / `errors` / `off`, with a **compliance floor that can never be thinned**: `viewed`, `dead`, `error`, `failed`, `not_deployed`, `reply_timeout` are retained at every level (`reply_timeout` is the one row that explains a "we called you and got a 504" complaint, so an instance that thinned its logs would lose exactly the record it is later asked for) | | **7. `connection_event` table β€” DEFAULT ON** (`[diagnostics].connection_events = true`) | transport/lifecycle events per connection: `established`, `closed` (reason `eof` or `idle_timeout` β€” no path produces any other), `idle_timeout`, `at_capacity`, `peer_not_allowlisted`, `frame_oversize`, `framing_error`, `peer_reset`, the inbound-HTTP intake-auth refusals `intake_auth_failed` / `auth_subject_denied` / `auth_rate_limited` (ADR 0154 D6 β€” peer address and mode only; **never** the credential, a prefix of it, or its length. Each of these also writes a tamper-evident audit-log row β€” the copy that survives an operator turning this diagnostics stream off), plus the runner's `connection_lost` / `connection_restored`. That is the whole vocabulary, asserted in CI against the literal emit call sites in `transports/` and the pipeline runner **and** cross-checked against the console's own filter tuple. The MLLP, raw-TCP and HTTP listeners emit these; the **DICOM inbound C-STORE SCP** and the **`ISA`/`IEA`-framed X12 inbound** emit none β€” the runner injects the sink onto **every** source (`wiring_runner.py`, over the base-class `on_connection_event` field), so both connectors *have* the wiring and simply never call it β€” so this stream covers those three listeners plus the runner's outbound-lane transitions β€” not literally every connection. An X12 feed's connects, allow-list refusals and at-capacity refusals are therefore **absent** from this stream | rows: `ts`, `connection`, `transport`, `direction`, `kind`, `peer_host`, `message_id` (correlation hint), `reason` | the store database, **all three backends** | Corepoint-style transport diagnostics β€” "did the sender connect, and why did it drop" | `GET /events` and `GET /connections/{name}/events` under **`monitoring:read`** (**not** a PHI permission) with per-channel RBAC β€” an out-of-scope `connection=` is 403'd *and* audited β€” server-clamped to ≀1000 rows | `[retention].connection_event_retention_hours` (its own **hours** window); 0 inherits `[retention].messages_days`; both 0 = keep forever. Plain age `DELETE` (metadata-only) | **`reason` is free text that can carry sensitive fragments.** Defended twice β€” `safe_exc()` at the source, `safe_text(reason)[:200]` at the store β€” then cipher-encrypted (AAD `("connection_event","reason",connection,ts,kind)`). Every other column is config metadata; the table is documented **metadata-only** β€” never a frame, body or HL7 field value. Writes are a pure side observer: a bounded in-memory queue drained by a background task outside any handoff transaction, so a flood can never block a listener or pin a message disposition | -| **8. `alert_instance` table β€” default on wherever an `[alerts]` notifier exists** | resolvable operator alerts: `connection_stopped`, `queue_buildup`, `lane_stuck`, `message_stall`, `saturation`, `connection_error`, `content_match`, `storage_threshold`, `cert_expiry`, `secret_rotation`, `bootstrap_admin_expiring` (the UNCLAIMED first-run bootstrap admin nearing its auto-disable deadline β€” ASVS 6.4.5; its payload carries only the ISO deadline plus whole hours remaining, never the password or any secret), `integrity_drift`, `update_available`, `backup_failed`, `rcsi_off_degraded`, `leadership_acquired`, `dr_activated`, `gcm_invocations` (the per-key AES-GCM invocation bound crossing its 2^31 soft warn β€” ASVS 11.3.4; its payload carries a one-way `key_id` fingerprint plus counters, never key bytes) The three reachable **inverse** signals β€” `connection_restored`, `leadership_lost`, `dr_released` β€” are never rows here: `_record_state` routes an inverse through `_AUTO_RESOLVE` to `resolve_alert_instances_for`, never to `upsert_alert_instance`. (A fourth mapped key, `connection_started`, is emitted by no code path today.) | rows: `event_type`, `connection`, `severity`, `status`, `first_seen`, `last_seen`, `count`, `reason`, `acked_by`, `acked_at`, `resolved_at`, `suspended_until`, `escalation_tier` | the store database, **all three backends** | the operator alert list β€” acknowledge / resolve / suspend. Durable state is recorded **before** any suppression or throttle return, so a muted alert still leaves a record | `GET /alerts/active` under **`monitoring:diagnose`** (**not** a PHI permission) with the same per-channel scope; ack/resolve/suspend/**resume** are POSTs on the same tier, and the separate read-only `GET /alerts/rules` view sits on its own gate | shares the connection-event window; **only RESOLVED instances are DELETEd**, by `resolved_at` β€” an open or acknowledged condition is never aged out from under an operator | **`reason` is free text** taken from the event's `detail`/`reason`/`label`: `safe_text(reason)[:200]` then cipher-encrypted (AAD `("alert_instance","reason",event_type,connection)` β€” the de-dup grain, so one AAD covers both the INSERT and the re-fire UPDATE). `content_match` is **PHI-free by contract**: the sink method takes no value parameter, only the connection, an operator label and an optional rule id | +| **8. `alert_instance` table β€” default on wherever an `[alerts]` notifier exists** | resolvable operator alerts: `connection_stopped`, `queue_buildup`, `lane_stuck`, `message_stall`, `saturation`, `connection_error`, `content_match`, `storage_threshold`, `cert_expiry`, `secret_rotation`, `bootstrap_admin_expiring` (the UNCLAIMED first-run bootstrap admin nearing its auto-disable deadline β€” ASVS 6.4.5; its payload carries only the ISO deadline plus whole hours remaining, never the password or any secret), `integrity_drift`, `update_available`, `backup_failed`, `rcsi_off_degraded`, `leadership_acquired`, `dr_activated`, `log_write_failed` (an application-log sink was rolled after a write failure, or is UNWRITABLE and this process's connections were stopped -- BACKLOG #122, ADR 0162; the payload is the sink LABEL, the stage, a `safe_exc` reason and a count of connections stopped, never the record whose write failed), `gcm_invocations` (the per-key AES-GCM invocation bound crossing its 2^31 soft warn β€” ASVS 11.3.4; its payload carries a one-way `key_id` fingerprint plus counters, never key bytes) The three reachable **inverse** signals β€” `connection_restored`, `leadership_lost`, `dr_released` β€” are never rows here: `_record_state` routes an inverse through `_AUTO_RESOLVE` to `resolve_alert_instances_for`, never to `upsert_alert_instance`. (A fourth mapped key, `connection_started`, is emitted by no code path today.) | rows: `event_type`, `connection`, `severity`, `status`, `first_seen`, `last_seen`, `count`, `reason`, `acked_by`, `acked_at`, `resolved_at`, `suspended_until`, `escalation_tier` | the store database, **all three backends** | the operator alert list β€” acknowledge / resolve / suspend. Durable state is recorded **before** any suppression or throttle return, so a muted alert still leaves a record | `GET /alerts/active` under **`monitoring:diagnose`** (**not** a PHI permission) with the same per-channel scope; ack/resolve/suspend/**resume** are POSTs on the same tier, and the separate read-only `GET /alerts/rules` view sits on its own gate | shares the connection-event window; **only RESOLVED instances are DELETEd**, by `resolved_at` β€” an open or acknowledged condition is never aged out from under an operator | **`reason` is free text** taken from the event's `detail`/`reason`/`label`: `safe_text(reason)[:200]` then cipher-encrypted (AAD `("alert_instance","reason",event_type,connection)` β€” the de-dup grain, so one AAD covers both the INSERT and the re-fire UPDATE). `content_match` is **PHI-free by contract**: the sink method takes no value parameter, only the connection, an operator label and an optional rule id | | **9. `response` rows with `kind='ack_sent'` β€” DEFAULT ON** (`[diagnostics].response_sent = true`) | the ACK/NAK the engine returned to an inbound sender, under a sentinel destination `\x1fack:` | rows: `ack_code` (`AA`/`AE`/`AR`/`CA`/`CE`/`CR`), `ack_phase` (`decode`/`parse`/`strict`/`ingest`), `outcome`, `body`, `detail` | the store database | "what did we actually reply, and why" β€” the operator's answer to a sender disputing an ACK | `GET /messages/{id}/responses` under `messages:read` + `require_phi_read`; the `body` only for a caller who also holds `messages:view_raw`; every read writes a `response.read` audit row | `body`, `detail` and `resp_headers` are set to `NULL` in place by `purge_message_bodies` on the message-body window, on all three backends | **PHI fail-safe:** the ACK **body** is stored **only when the store cipher is active** β€” on a keyless store it is `NULL` rather than plaintext β€” and every NAK passes no body at all, so the offending field value is never persisted. The disposition metadata (`ack_code`/`ack_phase`/`outcome`) is non-PHI and always captured; `detail` is `safe_text`-scrubbed, 200-char bounded and encrypted | | **10. `[alerts]` webhook transport** (off by default β€” `webhook_url` unset) | one HTTPS POST per alert, carrying every non-underscore event key as JSON | JSON | the operator's webhook endpoint (Slack/Teams/PagerDuty/custom) | operator notification | **`https` only** β€” a plaintext `http://` webhook URL is refused at construction unless the `MEFOR_ALLOW_INSECURE_TLS` escape is set (and then a warning is logged); since #329 this path routes that escape through the clamped `weakened_tls_escape_permitted(posture)` (the instance posture threaded from the API lifespan), so on an enforcing-PHI instance the escape is inert and a cleartext webhook POST stays refused β€” the same clamp as the connectors, no longer the raw escape. Redirects are refused; an optional `webhook_allowed_hosts` egress allowlist gates the host | the endpoint's | **carries the alert's `detail`/`reason` free text** (`safe_exc()`-scrubbed at the emit sites, but **not** re-run through `safe_text` on this path). Internal `_`-prefixed keys (per-rule recipients, rule id, cooldown) are stripped before send, so recipient addresses never cross the wire | | **11. `[alerts]` SMTP transport β€” operator alert list** (off unless `email_smtp_host` + `email_from` + β‰₯1 `email_to`) | one email per alert; default subject `[MessageFoundry] β€” `, default body every non-underscore event key as `k: v` | plain text (always kept β€” never HTML-only); optional HTML alternative | the operators' mailboxes | operator notification | `smtp_allowed_hosts` egress allowlist; the SMTP password comes from `MEFOR_ALERTS_EMAIL_PASSWORD` or a `[secrets]` provider, never the config file; per-send timeout `email_timeout` | the mail system's | carries the same `detail`/`reason` free text as the webhook. #138 operator templates are constrained to a **closed non-PHI variable allowlist** validated fail-closed at config load. **Transport posture:** `send_plain_email` builds an explicit **verifying** context (chain + hostname + strict RFC 5280, TLS 1.2 floor) via `tls_policy.build_smtp_tls_context()` and passes it to `starttls()`, anchored to the OS roots, `[alerts].email_tls_ca_file`, or `[tls].internal_ca_file` β€” the same factory the EMAIL and DIRECT *message destinations* use, so all three SMTP cells now share one policy ([#323](archive/backlog/BACKLOG-CLOSED.md#323-smtp-tls-is-unverified-on-all-three-send-paths), closed 2026-08-02). Before that this call passed **no** context and Python's stdlib default applied (`ssl._create_stdlib_context` **is** `ssl._create_unverified_context` β€” `CERT_NONE`, `check_hostname = False`), leaving the hop encrypted but unauthenticated. There is still **no hop gradient or attestation on this path** β€” unlike the connectors, this cell is constructed outside the `active_hop_posture` scope, so its deviations (`email_use_tls = false`, or `email_tls_verify = false`) are gated by a `[security].allow_unverified_alert_smtp_tls` **acknowledgment switch at the serve gate** rather than by the clamped escape: on an enforcing PHI instance `serve` refuses to start without it, and permits + `AUDIT`-logs the start with it. Both deviations are named by `security_loosenings()` and reported by `messagefoundry check`'s `alert-smtp-tls` advisory | diff --git a/docs/SERVICE.md b/docs/SERVICE.md index cd236da04..64a695733 100644 --- a/docs/SERVICE.md +++ b/docs/SERVICE.md @@ -390,6 +390,52 @@ icacls "C:\ProgramData\MessageFoundry\logs" /inheritance:r ` /grant "Administrators:(OI)(CI)F" "NT SERVICE\MessageFoundry:(OI)(CI)M" ``` +### Who owns which log file, and what happens when one cannot be written + +Two things can write log files here, and **each file has exactly one owner** β€” two rotators renaming +one file is how a log gets shredded, and the loser of that race is the log you read after an incident. + +| File | Owner | Rotation | Configured by | +|---|---|---|---| +| The captured stdout/stderr (`logs\service-*.log` above) | **NSSM** | NSSM, at ~10 MB | the install script; `[logging].log_dir` only *tells the engine where they are*, for `GET /status` metering (#50), log retention (#120) and the console's log viewer | +| `[logging].file` (optional, off by default) | **the engine** | the engine, at `[logging].file_max_bytes`, keeping `file_backup_count` backups | `[logging]` in your settings TOML | + +`[logging].file` is **opt-in and unset by default**; leave it unset and the engine is stdout-only +exactly as before. If you do set it, **put it outside `[logging].log_dir`** and do not point NSSM at +it β€” the engine refuses to start otherwise, naming the collision. + +**The engine stops processing when it cannot log** (BACKLOG #122, ADR 0162), in two stages: + +1. **Roll.** A write failure renames the broken file aside as `.broken--`, opens a fresh + file at the live path, records the rollover event in it and re-writes the record that failed. A + momentary lock or an antivirus scan heals here and **stops nothing**. +2. **Stop.** If the **replacement** cannot be written either, every connection this engine process + owns is stopped, in **all three tiers**: inbounds stop accepting, messages already accepted stop + being routed and transformed, and outbounds pause with their queued messages **retained** (not + dead-lettered). All three, because processing a message you cannot log is the thing being + prevented β€” not just accepting or sending one. You are told three ways β€” a `log_write_failed` + alert through the notifier (email/webhook, which does not go through the log that broke), a + `connection_stopped` alert per halted connection naming the log as the cause, and `GET /status`'s + `log_sinks` block, which is read from memory and still answers when the disk does not. + +Recover by fixing the disk or permissions and then **restarting the affected connections** β€” inbounds +*and* outbounds β€” from the web console, or by restarting the service; the retained queue then drains. +**Fix the disk first β€” the restart is refused while the log is still unwritable.** The engine +re-checks by writing a real record to each dead sink at the moment you ask, so a restart issued +against a still-broken disk leaves the connection halted (and its listener down) and raises another +`log_write_failed` naming the refusal, rather than quietly resuming with no log. That is deliberate: +otherwise "restart it again" would be a way around the control. +A `/config/reload` on its own is **not enough**: it re-arms the inbounds it re-binds, so messages +start being routed again, but it deliberately never resumes a paused **outbound** (that is an +operator decision), so the backlog moves one stage and stops. Restarting the service does both. +Set `[logging].on_write_failure = "continue"` if you would rather the engine keep +running with no log β€” it still rolls and still alerts, it just does not stop. The `*.broken-*` files +are incident evidence and are deliberately left for you to review and remove; nothing rotates them +away. + +**The message store is unaffected by any of this.** It is a separate durable record: a message already +accepted and committed was ACKed, and a log-write failure neither loses it nor re-delivers it. + ## Admin console (in a browser) This service is **headless**. Operators watch and run it from the **browser web console** served diff --git a/messagefoundry/__main__.py b/messagefoundry/__main__.py index a19cb1e81..387af731c 100644 --- a/messagefoundry/__main__.py +++ b/messagefoundry/__main__.py @@ -34,6 +34,7 @@ from messagefoundry import __version__ from messagefoundry.logging_setup import ( LOG_LEVELS, + LogFile, SyslogForward, configure_logging, query_sntp_offset, @@ -1260,6 +1261,7 @@ def _serve(args: argparse.Namespace) -> int: platform_memory_encryption_readout, ) from messagefoundry.config.settings import ( + LogWriteFailurePolicy, StoreBackend, SyslogProtocol, forward_hop_disposition, @@ -1701,9 +1703,37 @@ def _serve(args: argparse.Namespace) -> int: settings.logging.forward_port, _forward_why, ) - forwarder_live = configure_logging( - settings.logging.level, fmt=settings.logging.format.value, forward=log_forward + # #122 (ADR 0162): the OPT-IN engine-managed application-log file + the fail-closed write guard. + # `file` unset (the default) leaves this None and the engine stdout-only, exactly as before; the + # guard still wraps stdout, so the two-stage roll/stop applies either way. + _log_file = ( + LogFile( + path=settings.logging.file, + max_bytes=settings.logging.file_max_bytes, + backup_count=settings.logging.file_backup_count, + ) + if settings.logging.file is not None + else None ) + try: + forwarder_live = configure_logging( + settings.logging.level, + fmt=settings.logging.format.value, + forward=log_forward, + log_file=_log_file, + stop_on_write_failure=settings.logging.on_write_failure is LogWriteFailurePolicy.STOP, + ) + except OSError as exc: + # FAIL CLOSED at configuration time: the operator named an application-log path this process + # cannot open. Starting anyway is precisely the silent blindness #122 exists to end, so refuse + # β€” and say so on stderr, since the log we would normally warn on is the thing that failed. + print( + f"error: [logging].file ({settings.logging.file!r}) cannot be opened for writing: {exc}. " + "The engine refuses to start rather than run unable to log (BACKLOG #122, ADR 0162); fix " + "the path/permissions, or unset [logging].file to run stdout-only.", + file=sys.stderr, + ) + return 2 if forwarder_live and log_forward is not None: # Only announce forwarding when configure_logging actually installed the handler β€” a TCP # collector that is down at startup is skipped (it warns), so this must not contradict it. diff --git a/messagefoundry/api/_ui_seam.py b/messagefoundry/api/_ui_seam.py index f4069f051..67da1e647 100644 --- a/messagefoundry/api/_ui_seam.py +++ b/messagefoundry/api/_ui_seam.py @@ -129,12 +129,21 @@ #: for two independent contract changes. Skipping to 20 bought room but fixed nothing: the next pair #: of branches would collide identically. BACKLOG #1220 removed the hand-chosen number entirely. #: +#: BACKLOG #122 / ADR 0162: SystemStatus gained the additive ``log_sinks`` -- per-sink +#: application-log WRITE health (healthy / rolled / unwritable, a rollover count, a ``safe_exc`` +#: reason and the path a broken file was rolled aside to). The two log readings answer DIFFERENT +#: questions and that is the point: ``logs`` meters the SUPERVISOR's directory from the filesystem, +#: so it cannot observe a sink the engine failed to write; ``log_sinks`` is read from process +#: memory, so it still answers when the disk does not. Additive with a default of ``[]``, so the +#: payload is unchanged when logging was not configured through ``configure_logging``; the digest +#: below still moves, because it introspects SystemStatus's field set. +#: #: The digest below covers the surface DISCOVERED from the console's own imports and uses, which is #: strictly larger than the five hand-maintained tuples it replaced -- those had drifted, and the #: proof is that commit 40a4d5d9 added a REQUIRED ``UploadedFileList.scope`` field the console renders #: unconditionally while touching no seam file at all. Regenerate with #: ``python scripts/webconsole_seam_snapshot.py --write``; never hand-edit it to silence a gate. -ENGINE_UI_SEAM: str = "266cbfd342b22819" +ENGINE_UI_SEAM: str = "74ff1cc6b7b9cb8a" @dataclass(frozen=True, slots=True) diff --git a/messagefoundry/api/app.py b/messagefoundry/api/app.py index e6648d36d..773f717e1 100644 --- a/messagefoundry/api/app.py +++ b/messagefoundry/api/app.py @@ -127,6 +127,7 @@ LogInfo, LogLevelInfo, LogLevelUpdate, + LogSinkInfo, LogTailPage, MessageDetail, MessageExportRequest, @@ -276,6 +277,7 @@ ) from messagefoundry.integrity import run_startup_attestation from messagefoundry.last_resort import install_loop_exception_handler +from messagefoundry.logging_guard import active_guard as active_log_guard from messagefoundry.logging_setup import LOG_LEVELS, current_log_level, set_runtime_level from messagefoundry.parsing.sniff import attachment_mime_agrees, nontext_upload_reason from messagefoundry.pipeline import ConfigReloadDenied, Engine @@ -437,6 +439,28 @@ def _log_storage(log_dir: str | None) -> LogInfo | None: return LogInfo(path=str(path), size_bytes=total, disk_free_bytes=free) +def _log_sink_health() -> list[LogSinkInfo]: + """Per-sink application-log WRITE health (#122, ADR 0162) for ``GET /status``. + + In-memory only β€” no filesystem access, so unlike :func:`_log_storage` it cannot be defeated by the + very unwritable directory it is reporting on, and it is safe to call on the event loop. Empty when + logging was not configured through ``configure_logging`` (an embedding or a test).""" + guard = active_log_guard() + if guard is None: + return [] + return [ + LogSinkInfo( + sink=status.sink, + state=status.state, + rollovers=status.rollovers, + last_event=status.last_event, + last_event_at=status.last_event_at, + rolled_aside=status.rolled_aside, + ) + for status in guard.status() + ] + + def _read_log_tail(log_dir: str | None, *, limit: int, offset: int) -> tuple[list[str], int, bool]: """A **redacted** page of the newest app-log file's tail for the in-console viewer (#171, ADR 0130). @@ -5019,6 +5043,7 @@ async def system_status( synchronous=db.synchronous, ), logs=logs, + log_sinks=_log_sink_health(), update=update, pool=pool, claim_proc=claim_proc, diff --git a/messagefoundry/api/models.py b/messagefoundry/api/models.py index 4f8f7a929..e1703e93c 100644 --- a/messagefoundry/api/models.py +++ b/messagefoundry/api/models.py @@ -721,6 +721,26 @@ class LogInfo(BaseModel): disk_free_bytes: int # free space on the log directory's filesystem +class LogSinkInfo(BaseModel): + """Health of one guarded **application-log sink** (BACKLOG #122, ADR 0162). + + The pull-side counterpart of the ``log_write_failed`` alert, and the reason it is worth having: + the other two channels can both be down at once β€” a log line about a broken log sink may never + land, and an engine with no notifier configured sends no page β€” but ``/status`` answers over HTTP + from process memory, which an application-log failure does not touch. ``state`` is ``healthy`` / + ``rolled`` (stage 1 absorbed a write failure and healed) / ``unwritable`` (stage 2 β€” the + replacement failed too, and under ``[logging].on_write_failure="stop"`` this process's connections + were stopped). **Metadata only β€” never any log content** (no PHI): a sink label, a state, a count, + a scrubbed reason and a path.""" + + sink: str # "stdout" | "file" + state: str # "healthy" | "rolled" | "unwritable" + rollovers: int + last_event: str | None = None # safe_exc-scrubbed cause, never record content + last_event_at: str | None = None # ISO-8601 UTC + rolled_aside: str | None = None # where the broken file was renamed to + + class LogLevelInfo(BaseModel): """Runtime log-verbosity state (BACKLOG #171, ADR 0130). ``level`` is the current effective root level; ``configured`` is the startup ``[logging].level`` baseline a restart returns to; ``levels`` is @@ -840,6 +860,10 @@ class SystemStatus(BaseModel): # App-log disk metering (#50), alongside the DB metrics. ``None`` when no [logging].log_dir is # configured (the engine logs to stdout under NSSM) or the directory is unreadable β€” never raises. logs: LogInfo | None = None + # #122 (ADR 0162): per-sink application-log WRITE health β€” the "can the engine still log?" question, + # which the byte/free-space metering above deliberately does not answer. Empty when logging was not + # configured through configure_logging (an embedding/test), so the existing payload is unchanged. + log_sinks: list[LogSinkInfo] = [] # No-network version-update signal (#30, ADR 0026). Additive + ``None`` when [update_check] is # disabled or the runner hasn't produced a result yet, so the existing payload is unchanged when off. update: UpdateInfo | None = None diff --git a/messagefoundry/config/settings.py b/messagefoundry/config/settings.py index 4196aafe2..4c114cbed 100644 --- a/messagefoundry/config/settings.py +++ b/messagefoundry/config/settings.py @@ -94,6 +94,7 @@ "DiagnosticsSettings", "EnvironmentsSettings", "LoggingSettings", + "LogWriteFailurePolicy", "LogFormat", "SyslogProtocol", "ReferenceSettings", @@ -1410,6 +1411,17 @@ class LogFormat(str, Enum): # noqa: UP042 JSON = "json" # one JSON object per line β€” structured for a log shipper / SIEM +class LogWriteFailurePolicy(str, Enum): # noqa: UP042 + """What the engine does when an application-log sink is unwritable AND its replacement is too.""" + + # Fail-closed (the default): stop every connection this process owns. Never fires on a first + # failure β€” only when the rolled replacement is unwritable as well (#122 stage 2, ADR 0162). + STOP = "stop" + # Alert + roll, but keep running. The documented opt-out; an operator choosing it accepts that + # messages can be processed with no application-log record of the processing. + CONTINUE = "continue" + + class SyslogProtocol(str, Enum): # noqa: UP042 # RFC 5426; fire-and-forget, never blocks the engine (the default). UDP = "udp" @@ -1435,12 +1447,30 @@ class LoggingSettings(_Section): # a log shipper tailing NSSM's captured stdout). format: LogFormat = LogFormat.TEXT # Optional directory NSSM (or another supervisor) rotates the engine's captured stdout/stderr into. - # We never write log FILES ourselves (the engine logs to stdout β€” see logging_setup), but if an + # The engine writes no log FILE of its own unless `file` below is set (opt-in, #122), but if an # operator tells us where the supervisor parks them, GET /status meters that directory's total bytes # + filesystem free space alongside the DB metrics (#50). None (the default) = stdout-only, no # metering. Metadata only β€” the contents are never read. log_dir: str | None = None + # --- Engine-managed application log file + fail-closed write guard (#122, ADR 0162) ---------- + # OPT-IN second sink the ENGINE owns end to end: it opens it, it size-rotates it (file_max_bytes / + # file_backup_count) and it rolls it aside on a write failure. None (the default) = stdout-only, + # byte-identical to before, and NSSM stays the sole rotation owner of the captured stdout files. + # ONE FILE, ONE OWNER: the validator below refuses a `file` inside `log_dir` (the supervisor's + # rotation territory) β€” two rotation owners renaming one file is how a log gets shredded. See + # docs/SERVICE.md "Who owns which log file". + file: str | None = None + file_max_bytes: int = 50_000_000 # size-rotate at ~50 MB (0 = never rotate on size) + file_backup_count: int = 5 # keep app.log.1 .. app.log.N alongside the live file + # THE FAIL-CLOSED CONTROL (#122). "stop" (default): when a log sink cannot be written AND the + # replacement rolled into its place cannot be written either, every connection this PROCESS owns + # stops β€” an engine that cannot log must not keep processing (CLAUDE.md Β§1 count-and-log). A first + # failure alone NEVER stops anything; the roll absorbs the transient. "continue" is the documented + # opt-out for an operator who would rather run blind than stop a feed; it still alerts and still + # rolls, it just does not stop. + on_write_failure: LogWriteFailurePolicy = LogWriteFailurePolicy.STOP + # --- Off-box forwarding to a syslog/SIEM collector (ASVS 16.x; ADR 0080) ---------- # Ship a copy of every log record to a remote syslog collector so log evidence survives a host # compromise (the local audit_log is tamper-evident, but lives on the same host). PHI redaction @@ -1498,6 +1528,43 @@ class LoggingSettings(_Section): False # refuse to start on skew / unreachable peer (further opt-in) ) + @model_validator(mode="before") + @classmethod + def _refuse_renamed_file_keys(cls, data: Any) -> Any: + """Refuse the legacy planned spellings instead of silently ignoring them. + + ``[logging]`` is pydantic ``extra="ignore"`` and CONFIGURATION.md carried ``max_bytes`` / + ``backups`` as accepted-but-ignored *planned* keys while the engine-managed file was unbuilt. + Now that the sink is real, ignoring them would hand an operator the 50 MB / 5-backup defaults + while their config said otherwise β€” a control that reports success while doing something + else. ``mode="before"`` because ``extra="ignore"`` drops them before any field validator + could see them. + + **WHICH LAYER ACTUALLY REFUSES DEPENDS ON WHERE THE KEY CAME FROM, and this validator is not + the one an operator meets first.** :func:`_reject_unknown_file_keys` refuses an unrecognized + key in the TOML **file** before any model is built, so a file carrying either spelling never + reaches here. Measured: ``[logging].max_bytes`` in a file is refused by the loader *and* + suggested onward as ``file_max_bytes``, while ``[logging].backups`` is refused naming no + replacement β€” the loader's nearest-name heuristic does not reach ``file_backup_count``. + + **The layer this one covers is ENV, which the file refusal deliberately does not.** + ``_env_overrides`` scrapes ``MEFOR_LOGGING_*`` straight into the section dict, and a + misspelled env var is otherwise dropped in silence (docs/CONFIGURATION.md, "The refusal covers + the FILE"). Measured: ``MEFOR_LOGGING_MAX_BYTES`` and ``MEFOR_LOGGING_BACKUPS`` each reach + this validator and are refused naming their replacement. So the two spellings are the rare + env keys that fail loudly, and that is worth keeping rather than folding into the loader.""" + if isinstance(data, dict): + for legacy, actual in ( + ("max_bytes", "file_max_bytes"), + ("backups", "file_backup_count"), + ): + if legacy in data: + raise ValueError( + f"[logging].{legacy} is not a setting β€” the engine-managed application-log " + f"file uses [logging].{actual} (BACKLOG #122, ADR 0162)" + ) + return data + @field_validator("level") @classmethod def _normalize_level(cls, value: str) -> str: @@ -1562,6 +1629,24 @@ def _resolve_forwarding(self) -> LoggingSettings: ) if self.time_sync_fail_closed and not self.require_time_sync: raise ValueError("[logging].time_sync_fail_closed requires [logging].require_time_sync") + # ONE FILE, ONE ROTATION OWNER (#122, ADR 0162 Β§6). `log_dir` is where the SUPERVISOR (NSSM) + # parks and rotates the captured stdout; `file` is a log the ENGINE opens, rotates and rolls. + # Putting the engine's file inside the supervisor's directory points two rotators at one + # directory, and the loser of that race is the log an operator reads after an incident. + if self.file is not None and self.log_dir is not None: + engine_file = Path(self.file).expanduser().resolve(strict=False) + supervisor_dir = Path(self.log_dir).expanduser().resolve(strict=False) + if engine_file == supervisor_dir or supervisor_dir in engine_file.parents: + raise ValueError( + f"[logging].file ({self.file}) is inside [logging].log_dir ({self.log_dir}), " + "which the supervisor (NSSM) rotates. Two rotation owners on one directory " + "corrupt the log they are meant to preserve β€” put the engine-managed file " + "somewhere the supervisor does not rotate (docs/SERVICE.md)" + ) + if self.file_max_bytes < 0: + raise ValueError("[logging].file_max_bytes must be >= 0 (0 = never rotate on size)") + if self.file_backup_count < 0: + raise ValueError("[logging].file_backup_count must be >= 0") return self @@ -2711,6 +2796,11 @@ class AlertSeverity(str, Enum): # noqa: UP042 # ASVS 6.4.5 arm 2: an UNCLAIMED first-run bootstrap admin is nearing its auto-disable deadline # (payload is the ISO deadline + whole hours remaining β€” never the password; PHI-free) "bootstrap_admin_expiring", + # #122 (ADR 0162): an application-log sink was rolled after a write failure (stage 1) or is + # UNWRITABLE and this process's connections were stopped (stage 2). Routable on its own so an + # operator can page on "the engine went deaf" apart from the per-connection connection_stopped + # events the stop also emits. + "log_write_failed", # NOTE: the INVERSE events (leadership_lost / dr_released) are auto-resolve-only (alert_sinks # _AUTO_RESOLVE), NOT rule-targetable alert types β€” a step-down / fail-back needs no page. } diff --git a/messagefoundry/logging_guard.py b/messagefoundry/logging_guard.py new file mode 100644 index 000000000..d4d0d0c11 --- /dev/null +++ b/messagefoundry/logging_guard.py @@ -0,0 +1,608 @@ +# SPDX-License-Identifier: AGPL-3.0-or-later +# Copyright (C) 2026 MessageFoundry Organization and contributors +"""Fail-closed guard for the **application log** (BACKLOG #122, ADR 0162). + +CLAUDE.md section 1's count-and-log invariant says every message a connection takes in or puts out is +counted and **logged** β€” nothing is silently dropped. Applied to the application log that is: *the +engine must not keep processing what it cannot log.* Durability and visibility of the log (NSSM +rotation, the RFC 5425 off-box forwarder, the ``GET /status`` disk metering) all answer "can an +operator SEE that the log broke"; none of them answers "does the engine STOP when it breaks". This +module is that second half. + +**Two stages, and the split is the whole safety story:** + +* **Stage 1 β€” RECOVER.** On a write failure the sink is rolled: the broken file is renamed aside + (``.broken--``), a fresh file is opened at the live path, the **rollover event is + recorded** into it, and the record whose write failed is re-written. A transient condition β€” a + momentary lock, an antivirus scan, a rotation race β€” heals here and stops nothing. +* **Stage 2 β€” STOP.** Only when the **replacement** also cannot be written does the guard escalate. + A single-stage stop would take feeds down on a hiccup; that is an outage generator, not an invariant. + +**And a third thing, which is not a stage but is half the enforcement: UN-stopping.** Recovery is an +operator assertion β€” *"I fixed the disk"* β€” and a fail-closed control that simply believes it is a +control with an off switch. :meth:`LogWriteGuard.revalidate` therefore re-tests a dead sink **by +writing a real record to it**, because ``unwritable`` is only ever set by a failed write and nothing +clears it on its own: *repaired* and *still broken* are indistinguishable from memory, which is +exactly the distinction recovery has to make. The engine gates every re-arm path on that answer. + +**Scope of the stop is the PROCESS, and the code says so rather than pretending otherwise.** The +application log is a process-global handler set on the root logger β€” a write failure is a property of +the *sink*, not of any one connection, and no per-connection attribution exists to narrow it with. So +the escalation stops **every connection this process owns**: on a single-process engine that is all of +them; under engine sharding (ADR 0037) it is that shard's connections, which is the narrowest honest +scope available. See ADR 0162 section 4. + +**Boundaries this module must never cross:** + +* **The message store is untouched.** The store (SQLite/SQL Server/Postgres) is a *different* durable + record from the application log and is unaffected by an application-log failure. A message already + committed to the ingress stage has been ACKed (ACK-on-receipt); stopping intake leaves that row + exactly where it is β€” un-ACKed nothing, lost nothing, re-delivered nothing. This module performs **no + store I/O at all**. +* **No PHI on the error path.** :meth:`_GuardedSinkMixin.handleError` never reads ``record.msg`` or + ``record.args``; the only rendering of a record it performs is ``self.format(record)`` β€” the record + has already passed the handler's :class:`~messagefoundry.logging_setup.RedactionFilter` chain by then + (filters run in ``Handler.handle``, before ``emit``) β€” and that rendering is written only to the + sink's own stream, never to the last-resort channel. The stderr last-resort line carries the sink + label and a :func:`~messagefoundry.redaction.safe_exc` reason and **nothing from the record**. The + guard also never raises the service level to DEBUG. +* **Stdlib only, no engine imports.** The guard is reachable from ``logging_setup`` (which every + process configures) and must not drag ``pipeline``/``store``/``api`` in behind it. +""" + +from __future__ import annotations + +import contextlib +import logging +import logging.handlers +import os +import sys +import threading +import time +from collections.abc import Callable +from dataclasses import dataclass +from typing import TYPE_CHECKING, Literal, TextIO + +from messagefoundry.redaction import safe_exc + +__all__ = [ + "GuardedFileHandler", + "GuardedStreamHandler", + "LogSinkEvent", + "LogSinkStatus", + "LogWriteGuard", + "active_guard", + "set_active_guard", +] + +#: The synthetic logger name the guard stamps on the rollover notices it writes DIRECTLY to a sink +#: (bypassing the logging tree, which is what just failed). +_NOTICE_LOGGER = "messagefoundry.logging_guard" + +#: ``rolled`` β€” Stage 1 healed the sink. ``unwritable`` β€” Stage 2, the replacement failed too. +LogSinkStage = Literal["rolled", "unwritable"] + +#: Anti-flap bound on stage 1 (see :meth:`LogWriteGuard.record_rollover`). Generous enough that a real +#: transient β€” one lock, one rotation race, one antivirus pass β€” never trips it, and tight enough that +#: a sink failing every few records is declared unwritable instead of rolled forever. +_ROLL_FLAP_WINDOW_SECONDS = 60.0 +_MAX_ROLLS_PER_WINDOW = 5 + + +@dataclass(frozen=True, slots=True) +class LogSinkEvent: + """One two-stage transition on one application-log sink. PHI-free by construction: it carries the + sink label, the stage, a :func:`safe_exc` reason and a filesystem path β€” never record content.""" + + sink: str + stage: LogSinkStage + reason: str + rolled_aside: str | None = None + #: The configured ``[logging].on_write_failure`` policy, carried ON the event rather than looked up + #: by the responder, so the engine side is a pure function of what it is handed and never reaches + #: back into process-global state to decide whether to stop. Always False for ``rolled`` β€” stage 1 + #: stops nothing, ever. + stop_requested: bool = False + + +@dataclass(frozen=True, slots=True) +class LogSinkStatus: + """The guard's current view of one sink, for ``GET /status`` and operator triage.""" + + sink: str + state: Literal["healthy", "rolled", "unwritable"] + rollovers: int + last_event: str | None = None + last_event_at: str | None = None + rolled_aside: str | None = None + + +#: Called (synchronously, from whatever thread was logging) on every stage transition. It MUST be +#: cheap, non-blocking and never raise β€” the guard is already handling a failure. +EscalationCallback = Callable[[LogSinkEvent], None] + +#: One sink's "are you writable again?" self-test. Writes a real record to itself and RAISES if the +#: sink still refuses it β€” see :meth:`LogWriteGuard.revalidate`. +SinkProbe = Callable[[], None] + + +class LogWriteGuard: + """Process-wide state + escalation seam for the guarded application-log sinks. + + Thread-safe: log records are emitted from the event loop, from handler worker threads and from + connector threads alike, so every mutation is under one lock. Escalation is **latched per sink** β€” + a sink that is already ``unwritable`` does not re-fire on every subsequent record (that would turn + one broken disk into an unbounded alert storm), and a later successful Stage-1 roll clears the + latch so a genuine re-break pages again.""" + + def __init__(self, *, stop_on_unwritable: bool = True) -> None: + self._lock = threading.RLock() + self._sinks: dict[str, LogSinkStatus] = {} + #: sink -> (window start, rolls in window) β€” the anti-flap bound, see :meth:`record_rollover`. + self._roll_flap: dict[str, tuple[float, int]] = {} + #: sink -> "write one record to yourself and raise if you still cannot", see :meth:`revalidate`. + self._probes: dict[str, SinkProbe] = {} + self._escalation: EscalationCallback | None = None + #: ``[logging].on_write_failure == "stop"``. Stamped onto every stage-2 event. + self.stop_on_unwritable = stop_on_unwritable + + # --- registration / wiring ------------------------------------------------ + + def register(self, sink: str, probe: SinkProbe | None = None) -> None: + """Declare a guarded sink as healthy so ``GET /status`` can report it before anything breaks. + + ``probe`` is how this sink answers "can you accept a record again?" β€” see :meth:`revalidate`.""" + with self._lock: + self._sinks.setdefault(sink, LogSinkStatus(sink=sink, state="healthy", rollovers=0)) + if probe is not None: + self._probes[sink] = probe + + def set_escalation(self, callback: EscalationCallback | None) -> None: + """Wire (or clear) the engine-side responder. Cleared by default, so a CLI/test process that + configures logging without an engine degrades to the stderr last-resort line and stops + nothing. + + ONE RESPONDER, and a second one SAYS SO. A process runs one engine, so this is a single-slot + seam by design β€” but a second `RegistryRunner` starting in the same process would take the + slot and leave the first silently unguarded, which is the shape where a fail-closed control + disappears with every check still green. It is not made an error (a test process legitimately + starts runners back to back), so the honest handling is to be loud about it. The last-resort + channel rather than ``logging``: this class must not depend on the tree it guards.""" + with self._lock: + previous = self._escalation + self._escalation = callback + if callback is not None and previous is not None and previous != callback: + _last_resort( + "a second log-sink escalation responder replaced the first; the engine that " + "registered first is no longer guarded by this process's log write guard" + ) + + def clear_escalation(self, callback: EscalationCallback) -> None: + """Unwire ``callback`` β€” but ONLY if it is still the installed one. A runner tearing down must + not silently unwire a *different* runner that registered after it (the second engine in a test + process would then be unguarded, and nothing would say so).""" + with self._lock: + if self._escalation == callback: + self._escalation = None + + def status(self) -> list[LogSinkStatus]: + with self._lock: + return sorted(self._sinks.values(), key=lambda s: s.sink) + + # --- stage transitions ---------------------------------------------------- + + def record_rollover(self, sink: str, *, reason: str, rolled_aside: str | None) -> None: + """Stage 1 succeeded: ``sink`` was rolled and is writable again. + + **Bounded, because "heals" and "keeps needing to be healed" are not the same sink.** A sink + that accepts the notice and the re-written record and then fails again on the next one would + otherwise roll forever β€” one rename, one fresh file and one escalation per log record. Past + :data:`_MAX_ROLLS_PER_WINDOW` rolls inside :data:`_ROLL_FLAP_WINDOW_SECONDS` the sink is + declared unwritable instead: a log you must replace every few seconds is not a working log, + and stage 2 is the honest verdict on it.""" + with self._lock: + previous = self._sinks.get(sink) + now = time.monotonic() + first_at, streak = self._roll_flap.get(sink, (now, 0)) + if now - first_at > _ROLL_FLAP_WINDOW_SECONDS: + first_at, streak = now, 0 + streak += 1 + self._roll_flap[sink] = (first_at, streak) + self._sinks[sink] = LogSinkStatus( + sink=sink, + state="rolled", + rollovers=(previous.rollovers if previous else 0) + 1, + last_event=reason, + last_event_at=_utc_now(), + rolled_aside=rolled_aside, + ) + if streak > _MAX_ROLLS_PER_WINDOW: + self.record_unwritable( + sink, + reason=( + f"{reason}; the sink needed rolling {streak} times in " + f"{_ROLL_FLAP_WINDOW_SECONDS:.0f}s, which is a failing log rather than a transient" + ), + ) + return + self._fire( + LogSinkEvent(sink=sink, stage="rolled", reason=reason, rolled_aside=rolled_aside) + ) + + def record_unwritable(self, sink: str, *, reason: str) -> None: + """Stage 2: the replacement could not be written either. Escalates ONCE per break. + + **The STOP is asked for only when EVERY guarded sink is unwritable, and that is a + correctness point, not a softening.** The ruling is *"we never want to process stuff if the + processing cannot be logged"* β€” so the question the halt must answer is "can this process + still log?", not "did a sink break?". With ``[logging].file`` configured there are two sinks; + one of them failing while the other keeps accepting writes means the processing IS still + logged, and halting there would be a control resting on a false premise. When there is only + one sink (the default, stdout-only) the two questions coincide and the halt fires exactly as + before. The sink is still recorded unwritable, still alerted and still shown on + ``/status`` β€” visibility is unconditional; only the ENFORCEMENT is conditioned on the thing + the enforcement is about.""" + with self._lock: + previous = self._sinks.get(sink) + already_down = previous is not None and previous.state == "unwritable" + self._sinks[sink] = LogSinkStatus( + sink=sink, + state="unwritable", + rollovers=previous.rollovers if previous else 0, + last_event=reason, + last_event_at=_utc_now(), + rolled_aside=previous.rolled_aside if previous else None, + ) + all_down = all(s.state == "unwritable" for s in self._sinks.values()) + if already_down: + # Latched: one page per break, not one per dropped record. Without this a broken disk + # turns every subsequent log line into an alert AND a stderr line, and the storm buries + # the one message that mattered. + return + _last_resort( + f"LOG SINK {sink} IS UNWRITABLE after a rollover attempt: {reason}" + + ("" if all_down else "; another sink is still writable, so nothing is being stopped") + ) + self._fire( + LogSinkEvent( + sink=sink, + stage="unwritable", + reason=reason, + stop_requested=self.stop_on_unwritable and all_down, + ) + ) + + def record_healthy(self, sink: str) -> None: + """``sink`` accepted a record again β€” clear the unwritable latch so a LATER break pages afresh. + + Without this the ``unwritable`` state is terminal for the life of the process: nothing else + ever moves a sink out of it, so a repaired disk would still read as broken and (worse) a + genuine second break would be swallowed by :meth:`record_unwritable`'s ``already_down`` + return. The rollover COUNT is deliberately kept β€” it is the sink's history, and an operator + triaging a flapping disk needs to see that it has been rolled before.""" + with self._lock: + previous = self._sinks.get(sink) + self._sinks[sink] = LogSinkStatus( + sink=sink, + state="healthy", + rollovers=previous.rollovers if previous else 0, + last_event="the sink accepted a record again", + last_event_at=_utc_now(), + rolled_aside=previous.rolled_aside if previous else None, + ) + # The flap window is about a sink that keeps needing rescue. One that is writable again + # starts a fresh window, or a slow drip of unrelated transients would eventually trip it. + self._roll_flap.pop(sink, None) + + def can_log(self) -> bool: + """Can this PROCESS still write a log record anywhere? The question the #122 halt is about. + + Not "did a sink break" β€” with two sinks configured, one dead beside one healthy still means + the processing IS logged. A guard with no registered sinks (a process that never called + ``configure_logging``) answers True: it has nothing to say about a log it does not own, and + answering False would fail closed on a premise it cannot support.""" + with self._lock: + if not self._sinks: + return True + return not all(s.state == "unwritable" for s in self._sinks.values()) + + def revalidate(self) -> bool: + """Re-test every unwritable sink BY WRITING TO IT, and report whether the process can log. + + **A cached state cannot answer this, and that is the whole reason this exists.** ``unwritable`` + is only ever set by a failed write, and nothing clears it on its own β€” so after an operator + fixes the disk the guard still reads "broken", and before they fix it the guard reads "broken" + too. The two situations are indistinguishable from memory, which is exactly the distinction the + fail-closed recovery path has to make. Each sink's probe writes a real record through the real + formatter, rolling the sink first if its live handle is stale (a repaired directory still leaves + the old handle closed), so "writable" means *a record landed*, not *a stat call succeeded*. + + This is NOT the timer polling ADR 0162 rejected: it runs once, on an explicit operator recovery + action, at the moment the decision is made β€” never on a schedule and never on the hot path.""" + with self._lock: + dead = [name for name, status in self._sinks.items() if status.state == "unwritable"] + probes = [(name, self._probes.get(name)) for name in dead] + for name, probe in probes: + # A sink registered without a self-test stays exactly as it is: we cannot ask it, and + # guessing on its behalf is how a fail-closed control gets talked out of failing closed. + if probe is not None and _probe_lands(probe): + self.record_healthy(name) + return self.can_log() + + def _fire(self, event: LogSinkEvent) -> None: + with self._lock: + callback = self._escalation + if callback is None: + return + try: + callback(event) + except Exception as exc: # never-raise: we are already handling a logging failure + _last_resort(f"log-sink escalation for {event.sink} failed: {safe_exc(exc)}") + + +#: The guard the current process's handlers are wired to. Installed by ``configure_logging``. +_ACTIVE: LogWriteGuard | None = None +_ACTIVE_LOCK = threading.Lock() + + +def active_guard() -> LogWriteGuard | None: + """The process's installed guard, or None when logging was never configured through it.""" + with _ACTIVE_LOCK: + return _ACTIVE + + +def set_active_guard(guard: LogWriteGuard | None) -> None: + global _ACTIVE + with _ACTIVE_LOCK: + _ACTIVE = guard + + +def _probe_lands(probe: SinkProbe) -> bool: + """Run one sink's self-test and report whether the record LANDED. + + A raise is the answer, not an error: "this sink still refuses writes" is exactly what + :meth:`LogWriteGuard.revalidate` needs to learn, and it is called from a recovery path that has + to survive every sink being dead. Catching broadly is deliberate and bounded β€” the probe reaches + the filesystem through a handler the guard does not own, so the failure set is whatever the OS + and that handler can raise, and any of them mean the same thing here.""" + try: + probe() + except Exception: + return False + return True + + +def _utc_now() -> str: + return time.strftime("%Y-%m-%dT%H:%M:%SZ", time.gmtime()) + + +def _last_resort(message: str) -> None: + """Write one PHI-free line to stderr β€” the only channel left when a sink is unwritable. + + Deliberately NOT a ``logging`` call: the logging tree is what just failed, and re-entering it is + how a broken sink becomes an infinite loop. Carries the sink label and reason only; **no record + content ever reaches this line.**""" + stream = sys.stderr + if stream is None: # a pythonw.exe-style process with no stderr + return + with contextlib.suppress(Exception): + # stderr is the floor. If it is gone too there is nowhere left to say so, and raising here + # would turn a logging failure into an application crash. + stream.write(f"messagefoundry: {message}\n") + stream.flush() + + +# The mixin needs ``stream`` / ``terminator`` / ``format`` from the concrete handler it is mixed into. +# Re-DECLARING them on the mixin collides with the real definitions (a mixin listed first wins the MRO, +# so a stub there would shadow the actual formatter); inheriting the stdlib base only WHEN TYPE CHECKING +# gives mypy the real signatures while leaving the runtime MRO exactly as if the mixin were plain. +if TYPE_CHECKING: + _SinkBase = logging.StreamHandler[TextIO] +else: + _SinkBase = object + + +class _GuardedSinkMixin(_SinkBase): + """The two-stage ``handleError`` shared by every guarded sink. + + Subclasses supply :meth:`_roll` β€” how *this* kind of sink is rolled. Everything after the roll + (write the rollover notice, re-write the record whose emit failed, decide stage 1 vs stage 2) is + identical, because "is the replacement writable?" is answered the same way for every sink: by + writing to it and seeing whether that raises.""" + + _guard: LogWriteGuard + _sink_label: str + _reentry: threading.local + + def _init_guard(self, guard: LogWriteGuard, sink: str) -> None: + self._guard = guard + self._sink_label = sink + # Per-thread re-entrancy latch. A failure raised WHILE handling a failure must not recurse: + # the inner call returns immediately and the outer one converts the raise into Stage 2. + self._reentry = threading.local() + guard.register(sink, probe=self._probe_write) + + # --- subclass seam -------------------------------------------------------- + + def _roll(self) -> str | None: + """Roll this sink and leave a writable stream in place. Return the path the previous file was + renamed to, or None when this sink has no file to rename. Raise to force Stage 2.""" + raise NotImplementedError + + # --- the guard ------------------------------------------------------------ + + def handleError(self, record: logging.LogRecord) -> None: + """Two-stage response to a failed ``emit`` β€” the stdlib override that IS this control. + + Replaces :meth:`logging.Handler.handleError`, which prints a traceback, the call stack AND the + failing record's message/arguments to stderr, and which is a complete no-op when the process + global ``logging.raiseExceptions`` is False. Neither behaviour is acceptable here: a + fail-closed control an ambient setting can switch off is not a control, and no record content + leaves this method except through the sink's own (post-redaction-filter) formatter.""" + if getattr(self._reentry, "active", False): + return + self._reentry.active = True + try: + exc = sys.exception() + reason = ( + safe_exc(exc) if exc is not None else "log write failed (no exception recorded)" + ) + try: + rolled_aside = self._roll() + # STAGE 1 is only complete once the REPLACEMENT has actually accepted a write. Both + # writes below go to the fresh stream; either raising means the replacement is no + # better than the file it replaced, which is precisely the Stage 2 condition. + self._write_notice( + f"application log sink {self._sink_label!r} was rolled after a write failure " + f"({reason})" + + (f"; previous file renamed to {rolled_aside}" if rolled_aside else "") + ) + self._rewrite(record) + except Exception as roll_exc: + self._guard.record_unwritable( + self._sink_label, + reason=f"{reason}; the replacement failed too: {safe_exc(roll_exc)}", + ) + return + self._guard.record_rollover(self._sink_label, reason=reason, rolled_aside=rolled_aside) + finally: + self._reentry.active = False + + def _probe_write(self) -> None: + """:data:`SinkProbe` for this sink: answer "can you take a record again?" BY TAKING ONE. + + Raises when the sink still refuses, which is what :meth:`LogWriteGuard.revalidate` reads. The + roll on the retry is load-bearing rather than defensive: after a genuinely repaired + destination the handler is still holding the CLOSED handle it died with, so a bare re-write + would report the sink dead forever and a fixed disk would never recover. Rolling re-opens at + the live path β€” and if the destination is still broken the roll or the second write raises, + which is the correct answer. Deliberately :meth:`_emit_direct`, never ``emit``: an ``emit`` + failure would route into :meth:`handleError` and be converted into a stage-1/stage-2 + transition, so the probe would silently mutate the very state it is trying to measure.""" + message = f"application log sink {self._sink_label!r} accepted a record again" + try: + self._write_notice(message) + except Exception: + self._roll() + self._write_notice(message) + + def _write_notice(self, message: str) -> None: + """Record the rollover event ON the rolled sink, through the sink's own formatter so a JSON + sink stays one-object-per-line. Built here from a fixed string, so it carries no PHI.""" + notice = logging.LogRecord( + name=_NOTICE_LOGGER, + level=logging.WARNING, + pathname=__file__, + lineno=0, + msg=message, + args=(), + exc_info=None, + ) + self._emit_direct(notice) + + def _rewrite(self, record: logging.LogRecord) -> None: + """Re-write the record whose emit failed, so the roll does not cost a log line (count-and-log). + ``record`` already passed this handler's redaction/scrub filters β€” they run in + ``Handler.handle`` and mutate the record in place β€” so formatting it here yields the redacted + rendering, never the raw one.""" + self._emit_direct(record) + + def _emit_direct(self, record: logging.LogRecord) -> None: + """Format + write + flush WITHOUT going through ``emit`` β€” an ``emit`` failure would re-enter + ``handleError`` and be swallowed by the latch, hiding the very Stage 2 we are trying to detect. + Here the exception propagates to :meth:`handleError`'s caller and becomes Stage 2.""" + self.stream.write(self.format(record) + self.terminator) + self.stream.flush() + + +class GuardedStreamHandler(_GuardedSinkMixin, logging.StreamHandler[TextIO]): + """The guarded **stdout** sink (the engine's default, captured to disk by NSSM). + + Stage 1 here has **no file to rename** β€” the engine does not own the file NSSM captures stdout + into, and renaming a supervisor's file out from under it is how two rotation owners corrupt one + log. The roll is instead a **RE-RESOLVE**: rebind to whatever ``sys.stdout`` is *now* and write + to that. + + **A bare re-attempt on the SAME object was the original design and it could never heal, which + made this sink a hair trigger on the fail-closed halt.** The handler holds a reference to the + stream object it was constructed with; when that object is closed or replaced, every subsequent + write raises ``ValueError: I/O operation on closed file`` β€” including stage 1's own notice write, + so stage 1 failed by construction and *every* stdout write failure escalated to stage 2 and + stopped the engine. Measured, in the full test suite: a supervisor-like stream swap (pytest's + capture teardown) halted a running load engine's seven connections and the run sent zero + messages. The same shape in production is an NSSM capture-file swap or a closed pipe β€” routine + events that must not take feeds down. + + Re-resolving is the honest roll for a stream we did not open, and it is what "a re-attempt + clears the transient" was always claiming to do: the replacement handle is the live one. If + ``sys.stdout`` is itself gone or also refuses the write, the notice write raises and stage 2 + fires with exactly the fail-closed meaning it should have.""" + + def __init__(self, stream: TextIO, *, guard: LogWriteGuard, sink: str = "stdout") -> None: + super().__init__(stream) + self._init_guard(guard, sink) + + def _roll(self) -> str | None: + # No rename: nothing here is the engine's file. Rebind to the CURRENT sys.stdout, which is a + # different object from the one we were built with precisely in the case worth recovering + # from. `is not None` rather than truthiness: a stream object's __bool__ is not a liveness + # test. Nothing to return β€” there is no rolled-aside path for a stream. + live = sys.stdout + if live is not None and live is not self.stream: + self.stream = live + return None + + +class GuardedFileHandler(_GuardedSinkMixin, logging.handlers.RotatingFileHandler): + """The guarded **engine-managed** application-log file (``[logging].file``, opt-in). + + The engine is the *sole* rotation owner of this path (size-based, ``file_max_bytes`` / + ``file_backup_count``); NSSM keeps owning the captured stdout files, and the settings validator + refuses a ``file`` inside ``[logging].log_dir`` so the two can never fight over one file + (docs/SERVICE.md). Stage 1 is the real rename-and-roll: close, rename the broken file aside, open + a fresh file at the live path, write the rollover event, re-write the failed record.""" + + def __init__( + self, + filename: str, + *, + guard: LogWriteGuard, + sink: str = "file", + max_bytes: int = 0, + backup_count: int = 0, + ) -> None: + # delay=False: an unopenable path must fail HERE, at configuration time, rather than at the + # first record β€” the engine refusing to start beats an engine that starts unable to log. + super().__init__( + filename, + maxBytes=max_bytes, + backupCount=backup_count, + encoding="utf-8", + delay=False, + ) + self._init_guard(guard, sink) + self._roll_seq = 0 + + def _roll(self) -> str | None: + stream = self.stream + if stream is not None: + # Best-effort BY DEFINITION: we are here because this handle is broken, so closing it is + # allowed to fail. Suppressing is the point, not an oversight. + with contextlib.suppress(Exception): + stream.close() + # FileHandler.stream is Optional in practice (close() nulls it); typeshed agrees. + self.stream = None + self._roll_seq += 1 + aside = f"{self.baseFilename}.broken-{_utc_now().replace(':', '')}-{self._roll_seq}" + rolled: str | None = aside + try: + os.replace(self.baseFilename, aside) + except FileNotFoundError: + # Deleted out from under us (an over-eager cleaner, a shared mount): there is nothing to + # move aside and a fresh open IS the roll. + rolled = None + # Any OTHER OSError (locked, permission denied, the parent is no longer a directory) means we + # could NOT get the broken file out of the way. It propagates: rolling onto a file we could not + # move is a false recovery, and reporting a heal that did not happen is worse than stopping. + self.stream = self._open() + return rolled diff --git a/messagefoundry/logging_setup.py b/messagefoundry/logging_setup.py index 3070b9c74..19a0e9437 100644 --- a/messagefoundry/logging_setup.py +++ b/messagefoundry/logging_setup.py @@ -5,8 +5,14 @@ Stdlib ``logging`` only (no structlog): a stdout stream handler with a timestamped text format by default, optionally **structured JSON** (one object per line, ``[logging].format = "json"``), with uvicorn's own loggers routed through the same handler. When the engine runs under NSSM as a Windows -service, NSSM captures stdout/stderr to rotating files, so we deliberately do **not** add file handlers -here. A copy of every record can also be **forwarded off-box** to a syslog/SIEM collector +service, NSSM captures stdout/stderr to rotating files, so we add **no file handler by default** β€” the +supervisor owns those files. The one exception is opt-in and engine-owned end to end: +``[logging].file`` adds a second, size-rotating sink the engine itself opens, rotates and rolls +(BACKLOG #122, :mod:`messagefoundry.logging_guard`), and the settings validator refuses a path inside +``[logging].log_dir`` so the supervisor and the engine can never rotate the same file. Every sink is +wrapped in the two-stage write guard: a failed write rolls the sink, and only an unwritable +*replacement* stops this process's connections. +A copy of every record can also be **forwarded off-box** to a syslog/SIEM collector (``[logging].forward_*``; sec-offbox-log, ASVS 16.x) so log evidence survives a host compromise; PHI redaction + control-char scrubbing apply to the forwarded stream exactly as to stdout. The off-box transport is UDP (RFC 5426), plaintext TCP (RFC 6587), or **native TLS** (RFC 5425 β€” an ``ssl``-wrapped @@ -36,9 +42,16 @@ # A LEAF MODULE, imported for its DEFINITION rather than its behaviour (BACKLOG #1273). controlchars # imports nothing from this package, so there is no cycle -- checked by import, not assumed. from messagefoundry.controlchars import _is_control_char +from messagefoundry.logging_guard import ( + GuardedFileHandler, + GuardedStreamHandler, + LogWriteGuard, + set_active_guard, +) from messagefoundry.redaction import redact __all__ = [ + "LogFile", "build_stderr_handler", "configure_logging", "configure_stderr_logging", @@ -442,11 +455,27 @@ def _resolve_level(level: str) -> int: return resolved +@dataclass(frozen=True, slots=True) +class LogFile: + """``[logging].file`` β€” the OPT-IN application-log file the ENGINE owns end to end (#122, ADR 0162). + + Distinct from ``[logging].log_dir``, which is where the SUPERVISOR (NSSM) parks and rotates the + captured stdout: the engine opens this path, size-rotates it, and rolls it aside on a write + failure. The settings validator refuses a ``file`` inside ``log_dir`` so the two rotation owners + can never collide on one directory (docs/SERVICE.md).""" + + path: str + max_bytes: int = 50_000_000 + backup_count: int = 5 + + def configure_logging( level: str = "INFO", *, fmt: str = "text", forward: SyslogForward | None = None, + log_file: LogFile | None = None, + stop_on_write_failure: bool = True, ) -> bool: """Install the stdout handler on the root logger, route uvicorn through it, and optionally forward a copy of every record off-box to a syslog/SIEM collector. Returns whether the off-box forwarder @@ -464,13 +493,27 @@ def configure_logging( is then dropped) rather than blocking the event-loop thread the engine logs from. The send is still synchronous, so for a high-volume feed prefer UDP or a local forwarding agent. + ``log_file`` adds the OPT-IN engine-managed application-log file (``[logging].file``, #122/ADR + 0162) alongside stdout. Unlike the forwarder it is **NOT best-effort**: a path the engine cannot + open raises here, so the service refuses to start rather than starting unable to log β€” the same + fail-closed reasoning as ``stop_on_write_failure`` itself, applied at configuration time. + + Both sinks are wrapped in the two-stage write guard + (:mod:`~messagefoundry.logging_guard`): a write failure rolls the sink and heals; only an + unwritable *replacement* escalates, and ``stop_on_write_failure`` decides whether that escalation + stops this process's connections. The guard is installed process-wide + (:func:`~messagefoundry.logging_guard.set_active_guard`); the engine's ``RegistryRunner`` wires + itself to it at start, so a process with no engine (a CLI subcommand, a test) rolls and reports on + stderr but stops nothing. + Idempotent: replaces any handlers a previous call installed, so it is safe to call from tests as well as the CLI. Pair with ``uvicorn.run(..., log_config=None)`` so uvicorn's loggers propagate to these handlers instead of installing their own. """ numeric = _resolve_level(level) - stdout_handler = logging.StreamHandler(sys.stdout) + guard = LogWriteGuard(stop_on_unwritable=stop_on_write_failure) + stdout_handler = GuardedStreamHandler(sys.stdout, guard=guard, sink="stdout") stdout_handler.setFormatter(_make_formatter(fmt)) _install_phi_filters(stdout_handler) @@ -480,6 +523,23 @@ def configure_logging( root.addHandler(stdout_handler) root.setLevel(numeric) + if log_file is not None: + # No try/except: an OSError here means the operator named a path the engine cannot write, and + # starting anyway would ship exactly the silent blindness #122 exists to end. + file_handler = GuardedFileHandler( + log_file.path, + guard=guard, + sink="file", + max_bytes=log_file.max_bytes, + backup_count=log_file.backup_count, + ) + file_handler.setFormatter(_make_formatter(fmt)) + _install_phi_filters(file_handler) + root.addHandler(file_handler) + + # Published LAST, so a concurrently-starting engine never wires itself to a half-built guard. + set_active_guard(guard) + forwarder_installed = False if forward is not None: try: diff --git a/messagefoundry/pipeline/alert_sinks.py b/messagefoundry/pipeline/alert_sinks.py index 858c903d7..e1658a10c 100644 --- a/messagefoundry/pipeline/alert_sinks.py +++ b/messagefoundry/pipeline/alert_sinks.py @@ -791,6 +791,25 @@ def connection_error(self, name: str, *, kind: str, detail: str | None = None) - # retry storm on one lane collapses to one notification per cooldown. detail is safe_exc-scrubbed. self._emit({"type": "connection_error", "connection": name, "kind": kind, "detail": detail}) + def log_write_failed( + self, name: str, *, stage: str, reason: str, stopped: int | None = None + ) -> None: + # #122 (ADR 0162): an application-log sink was rolled (stage 1) or is unwritable (stage 2). The + # sink LABEL stands in for "connection" so the realert throttle + ADR 0044 dedup key per sink, + # exactly like storage_threshold does with a DB path. The payload is the sink label, the stage, + # a safe_exc reason and a count β€” never message content, and never the record that failed to + # write. This is the one alert whose delivery path must not depend on the application log, which + # is why it goes through the notifier's transports rather than a log line. + self._emit( + { + "type": "log_write_failed", + "connection": name, + "stage": stage, + "detail": reason, + "stopped": stopped, + } + ) + def content_match(self, connection: str, *, label: str, rule_id: str | None = None) -> None: # #81 (ADR 0133): a code-first Handler ("Action Point") inspected a message and decided to alert. # PHI-FREE BY CONTRACT: there is NO value parameter β€” the event carries ONLY the connection, an diff --git a/messagefoundry/pipeline/alerts.py b/messagefoundry/pipeline/alerts.py index 20d491e14..1c4e96ea1 100644 --- a/messagefoundry/pipeline/alerts.py +++ b/messagefoundry/pipeline/alerts.py @@ -77,6 +77,25 @@ def saturation_rising( the connection name + queue-shape derivative only. Emitted by the ``RegistryRunner``.""" ... + def log_write_failed( + self, name: str, *, stage: str, reason: str, stopped: int | None = None + ) -> None: + """An **application-log sink** failed a write (BACKLOG #122, ADR 0162). ``name`` labels the sink + (``"stdout"`` / ``"file"``); ``stage`` is ``"rolled"`` (stage 1 β€” the broken file was renamed + aside and a fresh one opened, nothing stopped) or ``"unwritable"`` (stage 2 β€” the replacement + failed too); ``reason`` is a ``safe_exc``-scrubbed cause; ``stopped`` is how many connections + the fail-closed stop halted (None when nothing was stopped). + + **This alert is the operator's channel of last resort, and that is the point:** the sink it + reports on is the one that just broke, so a log line about it may never land. The notifier's + email/webhook transports do not go through the application log, so the page survives the failure + the page is about. Carries the sink label, stage, reason and a count β€” never message content (no + PHI), and never the record whose write failed. Dedicated rather than reusing + :meth:`connection_stopped` so an operator can route "the engine went deaf" apart from one + stalled lane; the stage-2 stop ALSO emits :meth:`connection_stopped` per halted connection, so + the existing per-connection stop machinery still sees the stop and names its cause.""" + ... + def connection_error(self, name: str, *, kind: str, detail: str | None = None) -> None: """An outbound connection's delivery lane went **down** β€” the first transport failure (``DeliveryError``) after the lane was healthy, edge-triggered so a retry storm fires at most @@ -288,6 +307,21 @@ def saturation_rising( def connection_error(self, name: str, *, kind: str, detail: str | None = None) -> None: log.warning("ALERT connection_error: outbound %r %s: %s", name, kind, detail or "") + def log_write_failed( + self, name: str, *, stage: str, reason: str, stopped: int | None = None + ) -> None: + # The honest caveat, stated once where it lives: this default sink LOGS, and the thing that + # just failed is a log sink. If the failure is process-wide this line goes nowhere β€” which is + # exactly why the guard also writes a PHI-free stderr line of last resort, and why an operator + # who wants to be told routes this event to the email/webhook notifier instead. + log.warning( + "ALERT log_write_failed: application-log sink %r %s (%s)%s", + name, + stage, + reason, + "" if stopped is None else f"; {stopped} connection(s) stopped", + ) + def storage_threshold(self, path: str, *, size_bytes: int, limit_bytes: int) -> None: log.warning( "ALERT storage_threshold: store %r is %.1f MB, over the %.1f MB retention limit", diff --git a/messagefoundry/pipeline/wiring_runner.py b/messagefoundry/pipeline/wiring_runner.py index fcd806b95..b93db6663 100644 --- a/messagefoundry/pipeline/wiring_runner.py +++ b/messagefoundry/pipeline/wiring_runner.py @@ -30,7 +30,7 @@ import logging import time import urllib.parse -from collections.abc import Callable, Mapping, Sequence +from collections.abc import Callable, Iterable, Mapping, Sequence from concurrent.futures import ThreadPoolExecutor from contextlib import ExitStack from dataclasses import dataclass @@ -87,6 +87,8 @@ resolve_env_settings, resolve_listener_binding, ) +from messagefoundry.logging_guard import LogSinkEvent +from messagefoundry.logging_guard import active_guard as active_log_guard from messagefoundry.parsing import ( HL7PeekError, Peek, @@ -1124,6 +1126,15 @@ def __init__( self._conn_events_dropped = 0 # ADR 0073: sharded-only read-only watchdog over NON-owned outbound lanes (hung-owner paging). self._shard_watchdog: asyncio.Task[None] | None = None + # #122 (ADR 0162): fail-closed application-log write guard. The escalation arrives on whatever + # thread was logging, so the response is bounced onto this runner's loop as a task; the latch + # makes the stop fire once per break rather than once per dropped record. + self._log_guard_tasks: set[asyncio.Task[None]] = set() + self._log_write_stopped = False + # Inbounds whose INTERNAL stages (router / transform / loopback response) the halt shut down. + # Per-inbound rather than one process-wide flag because the RE-ARM is per-connection: a + # restart of inbound A must not silently re-arm B's processing while B's listener stays down. + self._log_halted: set[str] = set() self._running = False self._reload_lock = asyncio.Lock() # serialize concurrent reloads # B11 read-only worker-loop instrumentation: empty-claim counts (router/transform/delivery), @@ -1834,9 +1845,19 @@ def _require_owned_destination(self, name: str) -> None: async def start_outbound(self, name: str) -> None: """RESUME delivery on one outbound connection (no-op if not paused). The OPPOSITE primitive to the inbound stop/start: it un-pauses DELIVERY, keeping the connector WARM. Takes the reload lock - so it can't race a concurrent reload/stop (review M-10). Sharded: owner-only (ADR 0073).""" + so it can't race a concurrent reload/stop (review M-10). Sharded: owner-only (ADR 0073). + + **REFUSES while a #122 log-failure halt is in force and the log is still unwritable** (ADR + 0162). Delivery is processing: a paused outbound holds rows the halt retained, and un-pausing + it would ship them with no application log behind them β€” the same violation as re-arming an + inbound, reached by the other door. Gated HERE rather than in ``_start_outbound_unsafe`` so a + reload's outbound reconciliation is untouched; a reload never un-pauses an operator-paused + lane (#115/#233), so this public entry point is the only way delivery resumes.""" async with self._reload_lock: self._require_owned_destination(name) + if not self._log_recovery_ok(): + self._log_write_refused_restart(name) + return await self._start_outbound_unsafe(name) async def stop_outbound(self, name: str) -> None: @@ -2324,6 +2345,18 @@ async def _start_inbound_unsafe(self, name: str) -> None: # ACK-on-receipt into an ingress/routed backlog with nothing draining it. Idempotent (same guard # reload() uses); only runs once the runner is up so start()'s own spawn loop owns first boot. if self._running: + # #122 (ADR 0162): BEFORE the spawn, or a worker respawned into a still-halted inbound + # would hit its loop-top gate and exit again β€” a restart that reports success and re-arms + # nothing. + if not self._resume_inbound_processing(name): + # The log is STILL unwritable, so this connection must not come back. The listener is + # already bound by the time we get here, so undo that too: leaving intake up with the + # internal stages halted would ACK a sender into a lane nothing is draining. Deliberately + # not a raise β€” reload() rolls the WHOLE graph back on an exception from here, and one + # unwritable log must not turn a routine reload into a full intake rollback. + self._log_write_refused_restart(name) + await self._stop_inbound_unsafe(name) + return self._ensure_inbound_workers(name) async def _stop_inbound_unsafe(self, name: str) -> None: @@ -2353,6 +2386,283 @@ def _record_failed(self, name: str, exc: BaseException, *, kind: str) -> None: except Exception: log.exception("alert sink raised on connection_stopped for %r", name) + # --- #122 / ADR 0162: fail-closed application-log write guard ------------ + + def _on_log_sink_event(self, event: LogSinkEvent) -> None: + """The guard's escalation, called SYNCHRONOUSLY from whatever thread emitted the record that + could not be written β€” the event loop, a handler worker thread, a connector thread. It does one + thing: hand the event to this runner's loop. Never blocks (we are inside a failing + ``logging.Handler.emit``) and never raises (the guard is already handling a failure).""" + loop = self._loop + if loop is None or loop.is_closed(): + return # not started, or already torn down β€” nothing to stop + try: + loop.call_soon_threadsafe(self._spawn_log_sink_response, event) + except RuntimeError: + return # the loop closed between the check and the call + + def _spawn_log_sink_response(self, event: LogSinkEvent) -> None: + task = asyncio.ensure_future(self._respond_to_log_sink_event(event)) + self._log_guard_tasks.add(task) + task.add_done_callback(self._log_guard_tasks.discard) + + async def _respond_to_log_sink_event(self, event: LogSinkEvent) -> None: + """Alert on every stage; STOP only on stage 2 under the ``stop`` policy.""" + try: + if event.stage != "unwritable" or not event.stop_requested: + # Stage 1 rolled and healed, or the operator chose the "continue" opt-out. Page either + # way β€” a sink that rolls repeatedly is a disk about to become stage 2 β€” but stop nothing. + self._alert_sink.log_write_failed( + event.sink, stage=event.stage, reason=event.reason + ) + return + await self._stop_all_for_log_failure(sink=event.sink, reason=event.reason) + except Exception: + # NEVER-RAISE: this runs as a bare task off a logging failure. A raise here would be an + # unretrieved-exception warning at best and would lose the alert at worst. + log.exception("log-sink escalation response failed for sink %r", event.sink) + + async def _stop_all_for_log_failure(self, *, sink: str, reason: str) -> None: + """FAIL CLOSED (the #122 ruling): the application log cannot be written, so this process stops + processing. CLAUDE.md Β§1 counts and logs every message a connection takes in or puts out; + processing a message that cannot be logged IS the violation, so **all three tiers** halt β€” + intake (the listener unbinds), the INTERNAL stages (router / transform / loopback response, + via :meth:`_halt_inbound_processing`), and delivery (each owned outbound is paused). Stopping + only the first and last is what a listener-only halt looks like, and it leaves the backlog + being routed and transformed with no application log behind it. + + **Scope is the process, and pretending otherwise would be a lie.** The application log is a + process-global handler set on the root logger β€” the failure is a property of the SINK, and no + per-connection attribution exists to narrow it with. So this stops every connection this + process owns: all of them on a single-process engine, this shard's on a sharded fleet (ADR + 0037), which is the narrowest honest scope available. + + **ACK-on-receipt is preserved, and the boundary is worth stating in the code.** The message + STORE is a different durable record from the application log and is untouched by an + application-log failure β€” this method performs no store I/O. A message already committed to the + ingress stage stays committed: stopping an inbound unbinds the LISTENER (nothing already ACKed + is un-ACKed, lost, or re-delivered), and pausing an outbound RETAINS its queued rows PENDING + un-errored rather than dead-lettering them. Fix the disk, reload, and the backlog drains.""" + if self._log_write_stopped: + return # latched: one halt per break + self._log_write_stopped = True + detail = f"application log sink {sink!r} is unwritable ({reason})" + inbounds = [name for name in self.registry.inbound if name in self._sources] + outbounds = [ + name + for name in self.registry.outbound + if self._owns_destination(name) and name not in self._outbound_paused + ] + # Alert BEFORE stopping, and through the NOTIFIER rather than a log line: the sink this is + # about is the one that just broke, so a log line may never land. If the stop itself wedges, + # the operator has already been told why the engine is going quiet. + self._alert_sink.log_write_failed( + sink, + stage="unwritable", + reason=reason, + stopped=len(inbounds) + len(outbounds), + ) + async with self._reload_lock: + # THE INTERNAL STAGES FIRST, and they are not an afterthought β€” they are the half that + # makes this an enforcement. See :meth:`_halt_inbound_processing`. + # + # EVERY REGISTRY INBOUND, deliberately wider than `inbounds` above (which is the BOUND + # ones, for the alert count and the per-connection stop): an inbound whose listener never + # bound β€” isolated by ADR 0031, stopped by an operator, outside its active window β€” still + # has router/transform workers draining whatever is already in its lanes. Halting only + # the bound ones would leave exactly those backlogs processing unlogged. + self._halt_inbound_processing(self.registry.inbound) + for name in inbounds: + try: + await self._stop_inbound_unsafe(name) + except Exception: + # One connection refusing to stop must not leave the others running: this is a + # fail-closed halt, so a partial stop is strictly better than an abandoned one. + log.exception("log-failure stop: inbound %r did not stop cleanly", name) + for name in outbounds: + try: + self._stop_outbound_unsafe(name) + except Exception: + log.exception("log-failure stop: outbound %r did not pause cleanly", name) + for name in inbounds + outbounds: + try: + # ADR 0014's connection_stopped reports a stop but was never DRIVEN by a log-write + # failure (#122's own Nearest-existing-mechanism note). Driving it here is what makes + # the halt legible to the machinery an operator already has β€” alert rules, ADR 0044 + # durable alert state, the console's stopped view β€” with the CAUSE in the detail. + self._alert_sink.connection_stopped(name, detail=detail) + except Exception: + log.exception("alert sink raised on connection_stopped for %r", name) + + def _pause_internal_lanes(self, names: Iterable[str]) -> None: + """Pause the pooled INGRESS / ROUTED / RESPONSE lanes for ``names``. Sync and await-free. + + The one place that knows WHICH stages the #122 halt covers, because three callers need + exactly this loop and a fourth copy is how they drift: the halt itself + (:meth:`_halt_inbound_processing`), the fresh dispatchers at start + (:meth:`_start_pooled_dispatchers` step 2.6), and the reload re-apply + (:meth:`_reconcile_pooled_dispatchers`). A stage with no dispatcher is skipped -- per_lane + mode builds none, and a graph with no loopback inbound has no RESPONSE dispatcher. + ``pause_lane`` on an unregistered key registers it ALREADY-PAUSED, so calling this before a + dispatcher starts is what makes step 2.6 work at all (#115).""" + halted = list(names) # materialised: callers pass registry.inbound, a live dict + for stage in (Stage.INGRESS, Stage.ROUTED, Stage.RESPONSE): + dispatcher = self._dispatchers.get(stage) + if dispatcher is None: + continue # not pooled, or no loopback inbound => no RESPONSE dispatcher + for name in halted: + dispatcher.pause_lane(name) + + def _halt_inbound_processing(self, names: Iterable[str]) -> None: + """Shut down the INTERNAL stages β€” router, transform, and a loopback's response re-ingress β€” + for these inbounds. Sync + await-free; callers hold the reload lock. + + **This is the half of "refuse to process" that stopping the listener does not cover, and its + absence was measured rather than reasoned about.** The router/transform workers are + registry-tied, not source-tied (see :meth:`_ensure_inbound_workers`), and ``stop_inbound`` is + documented as halting intake *while delivery keeps draining*. So with only the listener + stopped, a message already durably on the ingress stage still flowed ingress -> routed -> + outbound with no application log behind it: a message that reached the outbound stage after + the halt, which is exactly "processing stuff that cannot be logged". The outbound pause meant + it was never delivered, which makes the gap quiet rather than harmless. + + **Cooperative in both claim modes, and NEVER a ``task.cancel``** β€” a cancelled mid-item worker + strands its claimed row INFLIGHT and ``reset_stale_inflight`` is startup/DR-only: + + * **pooled** (the default): ``pause_lane`` per stage, the same primitive + :meth:`_stop_outbound_unsafe` uses. A lane mid-episode reaches PAUSED at its quiesce point, + so **at most the one in-flight head completes** β€” bounded, and strictly better than + stranding its row. + * **per_lane**: the loop-top gate in the router/transform/response workers reads + :attr:`_log_halted` and returns at the worker's next turn, the same terminal state a + STOP-policy halt leaves behind. The wake below is why "next turn" is immediate rather than + up to a whole ``poll_interval`` of further processing. + """ + halted = list(names) # materialised: registry.inbound is a live dict we iterate twice + self._log_halted.update(halted) + self._pause_internal_lanes(halted) + if self._claim_mode != "pooled": + # per_lane only: a worker parked in _wait_for_work must be woken to reach its gate. NOT + # via _wake_lane, whose pooled branch is mark_ready() β€” re-readying a lane we just paused. + self._wake_all(Stage.INGRESS, Stage.ROUTED, Stage.RESPONSE) + + def _log_recovery_ok(self) -> bool: + """May this process resume processing? Only if it can LOG again β€” re-tested by writing. + + **The halt is not the whole control; refusing to un-halt on a false premise is the other + half.** Recovery is an operator action ("I fixed the disk"), and a control that simply + believes them is a control with an off switch. So every path that would lift the halt asks + the guard to re-validate its dead sinks by writing a real record to them, and a process that + still cannot log stays halted no matter how many times it is restarted. + + On success the latch is cleared, which matters as much as the refusal: ``_log_write_stopped`` + is a one-shot, so leaving it set after a genuine recovery would mean a LATER break never + halted anything again. Cheap by construction β€” it does nothing until a halt has fired. + + The re-validation write is SYNCHRONOUS on the calling (event-loop) thread. That is the same + posture as every other log write in this engine β€” stdlib logging is synchronous throughout, + including the syslog forwarder β€” and this one runs at most once per operator recovery action, + never on the hot path, so it is not the blocking-the-loop hazard the async rules are about.""" + if not self._log_write_stopped: + return True + guard = active_log_guard() + if guard is None or guard.revalidate(): + self._log_write_stopped = False + return True + return False + + def _log_write_refused_restart(self, name: str) -> None: + """Page that a recovery attempt was REFUSED because the application log is still unwritable. + + Through the notifier, not a log line, for the same reason the halt itself alerts that way: the + thing that is broken is the log. Without this the refusal is invisible β€” the operator asked for + a restart, got no error (a raise here would roll a reload back), and the connection simply + stays down. ``stopped=0``: nothing was newly stopped, the point is that nothing was STARTED.""" + guard = active_log_guard() + dead = ( + ",".join(s.sink for s in guard.status() if s.state == "unwritable") + if guard is not None + else "unknown" + ) + try: + self._alert_sink.log_write_failed( + dead or "unknown", + stage="unwritable", + reason=( + f"refused to restart connection {name!r}: the application log is still " + "unwritable, so the engine would be processing what it cannot log" + ), + stopped=0, + ) + except Exception: + log.exception("alert sink raised on a refused log-failure restart for %r", name) + + async def _unbind_for_log_failure(self) -> None: + """Take intake back down when :meth:`start` came up into an unwritable application log (#122). + + The counterpart of :meth:`_stop_all_for_log_failure`'s inbound half, for the one case that + method cannot cover: at ``start`` there was no halt to fire, the log was *already* dead. Called + with the reload lock held, AFTER the dispatchers exist, so the internal stages are halted + before the listeners go down rather than after. + + **Unbinding is not belt-and-braces.** Leaving intake up with the internal stages halted would + ACK a sender into a lane nothing is draining β€” the same reason + :meth:`_start_inbound_unsafe`'s own refusal path stops the listener it just bound. Pages + through the NOTIFIER rather than a log line, for the reason the whole control does: the thing + that is broken is the log.""" + bound = [name for name in self.registry.inbound if name in self._sources] + for name in bound: + try: + await self._stop_inbound_unsafe(name) + except Exception: + # One listener refusing to unbind must not leave the others up: a fail-closed halt is + # better partial than abandoned (same rule as _stop_all_for_log_failure). + log.exception("log-failure start: inbound %r did not stop cleanly", name) + guard = active_log_guard() + dead = ( + ",".join(s.sink for s in guard.status() if s.state == "unwritable") + if guard is not None + else "unknown" + ) + try: + self._alert_sink.log_write_failed( + dead or "unknown", + stage="unwritable", + reason=( + "the engine started while the application log was unwritable, so it is running " + "HALTED: intake is down and nothing is being routed or transformed. Fix the log, " + "then restart the connections" + ), + stopped=len(bound), + ) + except Exception: + log.exception("alert sink raised on a log-failure start halt") + + def _resume_inbound_processing(self, name: str) -> bool: + """Re-arm one inbound's internal stages after a log-failure halt (#122, ADR 0162). Returns + whether it re-armed. + + The recovery path the ADR promises β€” fix the disk, restart the connection, the backlog drains + β€” and it must live HERE rather than in a reload: a reload deliberately never rebuilds the + dispatchers, so a paused ingress lane would otherwise stay paused for the life of the process + and the halt would be unrecoverable without a restart. Per-inbound, so restarting A leaves B + halted until B is restarted too. A no-op when this inbound was never halted. + + **REFUSES while the log is still unwritable** (:meth:`_log_recovery_ok`). Re-arming there + would hand back exactly the state the halt exists to prevent β€” measured: a restart with the + sinks still dead resumed the whole pipeline and drove a message to PROCESSED with no + application log behind it, and neither latch could ever fire again.""" + if name not in self._log_halted: + return True + if not self._log_recovery_ok(): + return False + self._log_halted.discard(name) + for stage in (Stage.INGRESS, Stage.ROUTED, Stage.RESPONSE): + dispatcher = self._dispatchers.get(stage) + if dispatcher is not None: + dispatcher.resume_lane(name) + return True + async def _start_outbound(self, name: str, oc: OutboundConnection) -> None: """Build one outbound connector + spawn its delivery worker. A build failure (unresolvable ``env()`` / cert, an egress-allowlist refusal, a capture/backend mismatch) is ISOLATED @@ -2481,6 +2791,37 @@ async def start(self) -> None: self._stop.clear() # Capture the engine loop so a handler's worker thread can bridge a db_lookup back onto it. self._loop = asyncio.get_running_loop() + # #122 (ADR 0162): subscribe to the application-log write guard. Done here, after the loop + # is captured, because the escalation's ONLY job is to bounce onto that loop. A process + # whose logging was never configured through configure_logging has no guard, and the + # subscription is simply skipped β€” no engine behaviour depends on the guard existing. + guard = active_log_guard() + if guard is not None: + # A START IS A RE-ARM, SO IT IS GATED ON THE LOG LIKE EVERY OTHER ONE. This used to + # clear both latches unconditionally, and that made `start` the single door back into + # processing that never asked whether the log worked β€” the exact shape + # :meth:`_resume_inbound_processing` was gated for, reached by the one path that + # bypasses it. MEASURED, in both claim modes, with both sinks made unwritable BEFORE + # the runner was built: a committed ingress row went to ``PROCESSED`` and was + # delivered while ``guard.can_log()`` read False throughout. + # + # :meth:`~messagefoundry.logging_guard.LogWriteGuard.revalidate` re-tests each DEAD + # sink by writing a real record to it, so the ordinary case β€” a guard + # ``configure_logging`` built moments ago, with nothing dead β€” has nothing to probe, + # answers True, and the clear happens exactly as before. + if guard.revalidate(): + self._log_write_stopped = False # a restart re-arms the halt + self._log_halted.clear() # …and un-halts every inbound's internal stages + else: + # START HALTED rather than refuse to start: ``/status``, the alert state and every + # recovery path live in a RUNNING engine, and tearing them down is how an operator + # loses the explanation for why the engine went quiet β€” the same reason ADR 0162 + # rejects halting the whole engine. The per_lane workers read this set at their + # loop top; the pooled lanes are paused in :meth:`_start_pooled_dispatchers`, and + # the listeners that bound above come back down in :meth:`_unbind_for_log_failure`. + self._log_write_stopped = True + self._log_halted.update(self.registry.inbound) + guard.set_escalation(self._on_log_sink_event) # Connection-event drain task (#46): created before any source binds so an early accept's # enqueued event has a consumer. Skipped entirely when capture is off (no sink, no queue). if self._connection_events: @@ -2568,6 +2909,11 @@ async def start(self) -> None: # ADR 0075: resolve per-hop statement batching on the store (SQL-Server-only, fail-closed). # Independent of claim_mode, so it runs for both pooled and per_lane. self._activate_statement_batching() + # #122 (ADR 0162): this runner came up into an unwritable application log, so the + # listeners that bound above have to come back down. LAST, because the halt is only + # complete once the dispatchers exist to be paused (step 2.6). + if self._log_write_stopped: + await self._unbind_for_log_failure() except Exception: # A truly fatal startup error (store / lookup executor β€” NOT a single connection, which # is isolated above) must not leave half the graph wired with _running still False: @@ -2864,6 +3210,16 @@ async def _teardown_body(self, demote: bool, budget: float) -> None: """The teardown sequence itself. Split out ONLY so the ``finally`` above contains no await β€” an external cancel therefore cannot interrupt the one statement that must always run.""" self._stop.set() + # #122 (ADR 0162): unsubscribe from the log guard FIRST, so a record emitted during teardown + # cannot schedule a stop against a runner that is already stopping. clear_escalation is a + # no-op unless WE are still the installed responder (a second runner that registered after us + # keeps its subscription β€” silently unwiring it would leave that engine unguarded). + guard = active_log_guard() + if guard is not None: + guard.clear_escalation(self._on_log_sink_event) + for _guard_task in list(self._log_guard_tasks): + _guard_task.cancel() + self._log_guard_tasks.clear() # #147 (ADR 0095): cancel the active-window scheduler tasks FIRST so no schedule tick calls # start/stop_inbound/outbound while the rest of teardown runs (a task blocked awaiting the reload # lock is interrupted by cancel). Empty in the always-on case, so this is a no-op there. @@ -3244,6 +3600,13 @@ async def _start_pooled_dispatchers(self) -> None: if out is not None: for n in self._outbound_paused: out.pause_lane(n) + # (2.6) THE #122 SIBLING OF (2.5), and it fails the same way if it is missing: replay an + # in-force log-failure halt onto the FRESH INGRESS/ROUTED/RESPONSE dispatchers before step (3) + # seeds every lane READY. Without it a runner that came up into an unwritable application log + # starts DRAINING under pooled, because the halt then survives only in the per_lane workers' + # loop-top gate β€” which pooled mode does not run. Measured: a committed ingress row reached + # PROCESSED with both sinks dead. + self._pause_internal_lanes(self._log_halted) # (3) start each (seed-all-READY + immediate sweep). reset_stale_inflight already ran (engine). for dispatcher in self._dispatchers.values(): await dispatcher.start() @@ -3403,6 +3766,11 @@ async def _reload_pooled_dispatchers(self, new_registry: Registry) -> None: if out is not None: for n in self._outbound_paused: out.pause_lane(n) + # …and the #122 halt on the INTERNAL stages, for the same reason and in the same gap. A + # reload never LIFTS a halt (that rides _resume_inbound_processing, which is gated on the log + # working again), so re-applying it here can only ever be a no-op or a repair; a lane whose + # PAUSED phase was lost while the log is still dead would otherwise start draining unlogged. + self._pause_internal_lanes(self._log_halted) async def _pooled_maybe_buildup(self, lane: str, stage: str) -> None: """Pooled INGRESS/ROUTED buildup-alert hook (ADR 0066 D1). The per_lane buildup depth check lives @@ -4921,6 +5289,11 @@ async def _router_worker(self, name: str) -> None: self._lane_event(Stage.INGRESS, name) if self._per_lane_wake else self._ingress_work ) while not self._stop.is_set(): + # #122 (ADR 0162): the application log is unwritable and this process has fail-closed. + # Return BEFORE the claim so no row is left INFLIGHT β€” the same terminal state a + # STOP-policy halt leaves, re-armed by restarting this inbound. + if name in self._log_halted: + return try: # FIFO per inbound: claim the due head (ingress rows never back off, so this is # effectively the oldest pending row for this inbound). Under active-passive HA the graph @@ -5255,6 +5628,8 @@ async def _response_worker(self, name: str) -> None: self._lane_event(Stage.RESPONSE, name) if self._per_lane_wake else self._response_work ) while not self._stop.is_set(): + if name in self._log_halted: # #122 (ADR 0162) β€” see _router_worker's gate + return try: item = await self.store.claim_next_fifo(name, stage=Stage.RESPONSE.value) if item is None: @@ -5336,6 +5711,8 @@ async def _transform_worker(self, name: str) -> None: # shared singleton (byte-identical). Resolved once. wait_ev = self._lane_event(Stage.ROUTED, name) if self._per_lane_wake else self._routed_work while not self._stop.is_set(): + if name in self._log_halted: # #122 (ADR 0162) β€” see _router_worker's gate + return try: # FIFO per inbound at the routed stage. Under active-passive HA the graph runs on the # leader ONLY, so a single node drains this lane. ADR 0058: single head when diff --git a/messagefoundry_webconsole/__init__.py b/messagefoundry_webconsole/__init__.py index e98767b2f..36f475c7c 100644 --- a/messagefoundry_webconsole/__init__.py +++ b/messagefoundry_webconsole/__init__.py @@ -45,7 +45,7 @@ # If cross-seam support is ever genuinely wanted, re-widen this set AND add the CI matrix that # installs the MIN and MAX supported engine builds β€” the claim and its test land together, or not # at all. -SUPPORTED_ENGINE_SEAMS: frozenset[str] = frozenset({"266cbfd342b22819"}) +SUPPORTED_ENGINE_SEAMS: frozenset[str] = frozenset({"74ff1cc6b7b9cb8a"}) #: The vendored static assets shipped in THIS wheel (mounted at /ui/static by :func:`mount_ui`). STATIC_DIR = Path(__file__).parent / "static" diff --git a/tests/golden/webconsole_seam.snapshot b/tests/golden/webconsole_seam.snapshot index ecad57e77..0f3b2b8a6 100644 --- a/tests/golden/webconsole_seam.snapshot +++ b/tests/golden/webconsole_seam.snapshot @@ -7,7 +7,7 @@ # by hand (BACKLOG #1220) - so a newly rendered DTO is covered with nobody editing a list. ## ENGINE_UI_SEAM -266cbfd342b22819 +74ff1cc6b7b9cb8a ## dataclass messagefoundry.api._ui_seam.UiDeps engine_seam @@ -199,6 +199,7 @@ messagefoundry.api.models.GraphNode: kind, name, status messagefoundry.api.models.GraphResponse: dynamic, edges, nodes messagefoundry.api.models.IntegrityResult: detail, ok messagefoundry.api.models.LogInfo: disk_free_bytes, path, size_bytes +messagefoundry.api.models.LogSinkInfo: last_event, last_event_at, rolled_aside, rollovers, sink, state messagefoundry.api.models.MessageDetail: attachments, channel_id, control_id, error, event, events, id, message_type, metadata, outbox, raw, received_at, source_type, status, summary messagefoundry.api.models.MessageList: limit, messages, offset, total messagefoundry.api.models.MessageSearchResults: limit, matched, messages, scan_limit, scanned, truncated @@ -218,7 +219,7 @@ messagefoundry.api.models.SecurityPosture: allow_unencrypted_phi, backend, clien messagefoundry.api.models.ServiceStatusInfo: enabled, service_name, state messagefoundry.api.models.StatsResetRequest: all, targets messagefoundry.api.models.StatsResetTarget: channel_id, destination, role -messagefoundry.api.models.SystemStatus: claim_proc, db, engine, kpis, logs, pool, update +messagefoundry.api.models.SystemStatus: claim_proc, db, engine, kpis, log_sinks, logs, pool, update messagefoundry.api.models.UpdateInfo: current_version, pinned_version, update_available messagefoundry.api.models.UploadResendRequest: index, to messagefoundry.api.models.UploadedFileInfo: content_type, file_id, filename, message_count, sha256, size, uploaded_at, uploader diff --git a/tests/test_log_write_guard.py b/tests/test_log_write_guard.py new file mode 100644 index 000000000..f6eaa4f72 --- /dev/null +++ b/tests/test_log_write_guard.py @@ -0,0 +1,1247 @@ +# SPDX-License-Identifier: AGPL-3.0-or-later +# Copyright (C) 2026 MessageFoundry Organization and contributors +"""Fail-closed application-log write guard (BACKLOG #122, ADR 0162). + +The control is fail-closed, so a passing test proves nothing on its own β€” a guard that never fires +passes every "nothing broke" assertion. Every stage here is therefore driven by a **genuinely broken +sink** (a real closed OS handle; a real path whose parent directory has been replaced by a file), and +each direction carries its negative control: + +* stage 1 rolls and heals, and a HEALTHY run rolls nothing and stops nothing; +* stage 2 stops, and the ``continue`` policy under the SAME failure stops nothing; +* the error path writes no record content to the last-resort channel, and the stdlib handler it + replaces demonstrably DOES β€” so the assertion is proven able to see that class of leak. + +**The last block is the one that decides the item.** Everything before it drives the guard directly +or hands the runner a synthesized ``LogSinkEvent``; neither shows that the ENGINE refuses to process. +``test_an_unwritable_log_makes_the_engine_refuse_to_process`` runs the whole chain β€” a real +unwritable file, the real handler ``configure_logging`` installs, the real guard, a real running +``RegistryRunner`` β€” and asserts a committed ingress row is still ``RECEIVED`` with no outbound rows, +against a negative control on the identical rig that shows the row IS processed when the log is +healthy, and a recovery test that shows a restart drains it. Both claim modes, because pooled and +per_lane halt the internal stages by different mechanisms. +""" + +from __future__ import annotations + +import asyncio +import io +import logging +import shutil +from collections.abc import Callable +from pathlib import Path + +import pytest +from pydantic import ValidationError + +from messagefoundry.config.models import ConnectorType +from messagefoundry.config.settings import LoggingSettings, LogWriteFailurePolicy, load_settings +from messagefoundry.config.wiring import ( + ConnectionSpec, + InboundConnection, + OutboundConnection, + Registry, + Send, +) +from messagefoundry.logging_guard import ( + _MAX_ROLLS_PER_WINDOW, + GuardedFileHandler, + GuardedStreamHandler, + LogSinkEvent, + LogWriteGuard, + active_guard, + set_active_guard, +) +from messagefoundry.logging_setup import LogFile, configure_logging +from messagefoundry.pipeline.alerts import LoggingAlertSink +from messagefoundry.pipeline.wiring_runner import RegistryRunner +from messagefoundry.store import MessageStore +from messagefoundry.store.store import MessageStatus, Stage + +RAW = "MSH|^~\\&|A|B|C|D|20260101||ADT^A01|M1|P|2.5.1\rPID|1||100^^^H^MR||DOE^JANE\r" +INBOUND = "IB_TEST" +OUTBOUND = "OB_TEST" + + +# --- helpers ----------------------------------------------------------------- + + +def _record(message: str, *args: object) -> logging.LogRecord: + return logging.LogRecord("t", logging.INFO, "caller.py", 1, message, args, None) + + +def _file_handler(path: Path, guard: LogWriteGuard) -> GuardedFileHandler: + handler = GuardedFileHandler(str(path), guard=guard, sink="file") + handler.setFormatter(logging.Formatter("%(message)s")) + return handler + + +def _break_the_open_handle(handler: logging.FileHandler) -> None: + """Make the sink GENUINELY unwritable, not stubbed: close the real file object the handler holds, + so the next write raises out of CPython's io layer exactly as a yanked handle would.""" + assert handler.stream is not None + handler.stream.close() + + +def _replace_directory_with_a_file(directory: Path) -> None: + """Make the REPLACEMENT genuinely impossible to open: put a regular FILE where the log's parent + directory belongs. Both the rename-aside and the fresh open then fail at the OS, on Windows and + POSIX alike, with no permission fixture and no monkeypatching of the code under test.""" + shutil.rmtree(directory) + directory.write_text("not a directory", encoding="utf-8") + + +# --- stage 1: RECOVER -------------------------------------------------------- + + +def test_healthy_sink_never_rolls_and_never_escalates(tmp_path: Path) -> None: + # THE NEGATIVE CONTROL. An ordinary run must not roll a file, must not stop anything, and must + # leave every sink 'healthy' β€” a guard that fires on a working log is an outage generator. + events: list[LogSinkEvent] = [] + guard = LogWriteGuard() + guard.set_escalation(events.append) + handler = _file_handler(tmp_path / "app.log", guard) + + for i in range(25): + handler.emit(_record("ordinary line %d", i)) + handler.close() + + assert events == [] + assert [s.state for s in guard.status()] == ["healthy"] + assert [s.rollovers for s in guard.status()] == [0] + assert list(tmp_path.iterdir()) == [tmp_path / "app.log"] # nothing rolled aside + assert "ordinary line 24" in (tmp_path / "app.log").read_text(encoding="utf-8") + + +def test_stage1_renames_the_broken_file_aside_rolls_fresh_and_keeps_running(tmp_path: Path) -> None: + # A write failure on a sink whose DIRECTORY is still writable heals: the broken file is renamed + # aside (its prior content preserved for the operator), a fresh file takes the live path, the + # rollover event is RECORDED in it, and the record whose write failed is re-written rather than + # lost (count-and-log). Nothing stops. + events: list[LogSinkEvent] = [] + guard = LogWriteGuard() + guard.set_escalation(events.append) + log_path = tmp_path / "app.log" + handler = _file_handler(log_path, guard) + handler.emit(_record("before the break")) + + _break_the_open_handle(handler) + handler.emit(_record("after the break")) + + assert [e.stage for e in events] == ["rolled"] + assert events[0].stop_requested is False # stage 1 stops NOTHING, ever + status = guard.status()[0] + assert status.state == "rolled" and status.rollovers == 1 + + aside = [p for p in tmp_path.iterdir() if ".broken-" in p.name] + assert len(aside) == 1 + assert aside[0].read_text(encoding="utf-8") == "before the break\n" # evidence preserved + assert str(aside[0]) == status.rolled_aside + + fresh = log_path.read_text(encoding="utf-8") + assert "was rolled after a write failure" in fresh # the rollover event is RECORDED + assert aside[0].name in fresh # …and it names where the evidence went + assert "after the break" in fresh # the failed record is re-written, not dropped + + # And the sink KEEPS WORKING afterwards β€” a heal that leaves a dead handler is not a heal. + handler.emit(_record("after the heal")) + assert "after the heal" in log_path.read_text(encoding="utf-8") + + +def test_stage1_heals_the_latch_so_a_later_break_escalates_again(tmp_path: Path) -> None: + events: list[LogSinkEvent] = [] + guard = LogWriteGuard() + guard.set_escalation(events.append) + handler = _file_handler(tmp_path / "app.log", guard) + + for _ in range(3): + _break_the_open_handle(handler) + handler.emit(_record("break")) + + assert [e.stage for e in events] == ["rolled", "rolled", "rolled"] + assert guard.status()[0].rollovers == 3 + + +def test_a_sink_that_keeps_needing_a_roll_is_declared_unwritable(tmp_path: Path) -> None: + # "Heals" and "keeps needing to be healed" are not the same sink. Rolling per record would mean + # one rename, one fresh file and one page per log line forever; past the flap bound the honest + # verdict is stage 2. Driven by real rolls, not by poking the counter. + events: list[LogSinkEvent] = [] + guard = LogWriteGuard() + guard.set_escalation(events.append) + handler = _file_handler(tmp_path / "app.log", guard) + + for _ in range(_MAX_ROLLS_PER_WINDOW + 1): + _break_the_open_handle(handler) + handler.emit(_record("break")) + + assert [e.stage for e in events[:-1]] == ["rolled"] * _MAX_ROLLS_PER_WINDOW + assert events[-1].stage == "unwritable" + assert "is a failing log rather than a transient" in events[-1].reason + assert guard.status()[0].state == "unwritable" + + +def test_the_flap_bound_does_not_fire_on_an_ordinary_transient(tmp_path: Path) -> None: + # …and the bound is loose enough that a genuine one-off never trips it (the negative control for + # the test above β€” otherwise a bound of 1 would pass it and be an outage generator). + events: list[LogSinkEvent] = [] + guard = LogWriteGuard() + guard.set_escalation(events.append) + handler = _file_handler(tmp_path / "app.log", guard) + _break_the_open_handle(handler) + handler.emit(_record("break")) + + assert [e.stage for e in events] == ["rolled"] + + +# --- stage 2: STOP ----------------------------------------------------------- + + +def test_stage2_fires_only_when_the_replacement_is_also_unwritable(tmp_path: Path) -> None: + # The whole point of the two-stage split: this is the SAME initial failure as the stage-1 test, + # and it escalates only because the replacement cannot be written either. + events: list[LogSinkEvent] = [] + guard = LogWriteGuard() + guard.set_escalation(events.append) + log_dir = tmp_path / "logs" + log_dir.mkdir() + handler = _file_handler(log_dir / "app.log", guard) + handler.emit(_record("before the break")) + + _break_the_open_handle(handler) + _replace_directory_with_a_file(log_dir) + handler.emit(_record("after the break")) + + assert [e.stage for e in events] == ["unwritable"] + assert events[0].stop_requested is True # the default policy asks for the fail-closed stop + assert "the replacement failed too" in events[0].reason + assert guard.status()[0].state == "unwritable" + + +def test_stage2_escalation_is_latched_to_one_page_per_break(tmp_path: Path) -> None: + # A broken disk emits a log line per message; without the latch that is one page per message. + events: list[LogSinkEvent] = [] + guard = LogWriteGuard() + guard.set_escalation(events.append) + log_dir = tmp_path / "logs" + log_dir.mkdir() + handler = _file_handler(log_dir / "app.log", guard) + _break_the_open_handle(handler) + _replace_directory_with_a_file(log_dir) + + for i in range(10): + handler.emit(_record("line %d", i)) + + assert len(events) == 1 + + +def test_continue_policy_reports_the_same_failure_without_asking_for_a_stop(tmp_path: Path) -> None: + # The documented opt-out, driven by the IDENTICAL genuine failure: still detected, still alerted, + # simply not asked to stop. + events: list[LogSinkEvent] = [] + guard = LogWriteGuard(stop_on_unwritable=False) + guard.set_escalation(events.append) + log_dir = tmp_path / "logs" + log_dir.mkdir() + handler = _file_handler(log_dir / "app.log", guard) + _break_the_open_handle(handler) + _replace_directory_with_a_file(log_dir) + handler.emit(_record("after the break")) + + assert [e.stage for e in events] == ["unwritable"] + assert events[0].stop_requested is False + + +# --- PHI on the error path --------------------------------------------------- + +PHI_TOKEN = "DOE^JANE^Q^^^^L" + + +def test_the_stdlib_handler_this_guard_replaces_does_write_record_content_to_stderr( + tmp_path: Path, capsys: pytest.CaptureFixture[str], monkeypatch: pytest.MonkeyPatch +) -> None: + # RED FIRST, in the "prove the instrument can see it" direction. logging.Handler.handleError + # writes 'Message: %r' / 'Arguments: %s' straight to stderr, BELOW the handler's filter chain. + # Without this test, the assertion in the next one could pass because the token never reaches + # stderr at all β€” this proves stderr is exactly where such a leak WOULD land. + # + # PIN raiseExceptions=True, and the pin is the whole reason this test is trustworthy. THIS SUITE + # sets it to False for the entire session (tests/conftest.py + # `_tolerate_logging_on_closed_capture_streams`, a session-scoped autouse fixture), under which the + # stdlib handleError is a NO-OP and this assertion could never pass β€” measured: it failed here + # exactly that way. Reading the ambient value would have made the leak-detector look broken; the + # honest reading is that a control asserting what a mechanism DOES must pin the setting that + # enables the mechanism, or it is measuring the fixture rather than the stdlib. + monkeypatch.setattr(logging, "raiseExceptions", True) + unguarded = logging.FileHandler(tmp_path / "plain.log", encoding="utf-8") + unguarded.setFormatter(logging.Formatter("%(message)s")) + assert unguarded.stream is not None + unguarded.stream.close() + unguarded.emit(_record("patient %s admitted", PHI_TOKEN)) + + assert PHI_TOKEN in capsys.readouterr().err + + +def test_the_guard_writes_no_record_content_to_the_last_resort_channel( + tmp_path: Path, capsys: pytest.CaptureFixture[str] +) -> None: + # The guarded sink's stage-2 path must name the SINK and the CAUSE and nothing from the record. + guard = LogWriteGuard() + log_dir = tmp_path / "logs" + log_dir.mkdir() + handler = _file_handler(log_dir / "app.log", guard) + _break_the_open_handle(handler) + _replace_directory_with_a_file(log_dir) + handler.emit(_record("patient %s admitted", PHI_TOKEN)) + + captured = capsys.readouterr().err + assert PHI_TOKEN not in captured + assert "admitted" not in captured + assert "IS UNWRITABLE" in captured # the operator still learns the sink is down + + +def test_stage1_rewrites_the_failed_record_through_the_handlers_filter_chain( + tmp_path: Path, +) -> None: + # The re-write on the stage-1 path goes through self.format on a record the handler's filters + # already mutated in place, so the rolled-to file carries the REDACTED rendering β€” the same text + # the sink would have written had it not failed, never the raw one. + from messagefoundry.logging_setup import RedactionFilter + + guard = LogWriteGuard() + log_path = tmp_path / "app.log" + handler = _file_handler(log_path, guard) + handler.addFilter(RedactionFilter()) + _break_the_open_handle(handler) + handler.handle(_record("received %s", RAW)) + + rolled_to = log_path.read_text(encoding="utf-8") + assert "DOE^JANE" not in rolled_to + assert guard.status()[0].state == "rolled" + + +# --- hostile ambient environment -------------------------------------------- + + +@pytest.mark.parametrize("raise_exceptions", [False, True]) +def test_the_guard_fires_with_logging_raiseexceptions_switched_off( + tmp_path: Path, monkeypatch: pytest.MonkeyPatch, raise_exceptions: bool +) -> None: + # AMBIENT PIN. logging.raiseExceptions is a process-global that any library (or a deployment + # convention) can flip to False, and the stdlib handleError is a NO-OP when it is. Our override + # deliberately does not consult it, so the two-stage control cannot be silently disabled by an + # ambient setting we do not own. Run the whole stage-1 path under the hostile value. + # + # PARAMETRIZED OVER BOTH VALUES, because this suite's own session fixture sets it to False for + # every test in this file: pinning only False would re-assert the ambient value and never + # exercise the default True at all. "The guard is indifferent to this flag" is a claim about + # both settings, so both are measured. + monkeypatch.setattr(logging, "raiseExceptions", raise_exceptions) + events: list[LogSinkEvent] = [] + guard = LogWriteGuard() + guard.set_escalation(events.append) + handler = _file_handler(tmp_path / "app.log", guard) + handler.emit(_record("before")) + _break_the_open_handle(handler) + handler.emit(_record("after")) + + assert [e.stage for e in events] == ["rolled"] + assert "after" in (tmp_path / "app.log").read_text(encoding="utf-8") + + +def test_the_pin_is_load_bearing_the_stdlib_handler_goes_silent_under_the_same_value( + tmp_path: Path, capsys: pytest.CaptureFixture[str], monkeypatch: pytest.MonkeyPatch +) -> None: + # …and the pin above is load-bearing rather than decorative: the handler it replaces reports + # NOTHING AT ALL under the same ambient value. That is the failure mode the guard removes. + # The monkeypatch is deliberately explicit even though this suite's session fixture already + # sets False β€” a control must state the value it is asserting under, not inherit it. + monkeypatch.setattr(logging, "raiseExceptions", False) + unguarded = logging.FileHandler(tmp_path / "plain.log", encoding="utf-8") + unguarded.setFormatter(logging.Formatter("%(message)s")) + assert unguarded.stream is not None + unguarded.stream.close() + unguarded.emit(_record("dropped without a trace")) + + assert capsys.readouterr().err == "" + + +def test_stdout_sink_is_guarded_and_reports_when_the_stream_is_gone( + monkeypatch: pytest.MonkeyPatch, +) -> None: + # The default engine sink is stdout, whose file the engine does NOT own (NSSM does). There is + # nothing to rename, so the roll RE-RESOLVES ``sys.stdout`` β€” and a genuinely dead stdout, with + # nothing live to rebind to, still reaches stage 2 rather than vanishing. + # + # sys.stdout is PINNED to the dead stream on purpose. Without the pin this test passed for the + # wrong reason: the handler could never heal because it re-attempted the same closed object, so + # "stage 2 fires" was true of every stdout failure including the recoverable ones. That is the + # hair trigger measured in the full suite (see the swapped-stream test below); the pin is what + # makes this assert the UNRECOVERABLE case it names. + events: list[LogSinkEvent] = [] + guard = LogWriteGuard() + guard.set_escalation(events.append) + stream = io.StringIO() + handler = GuardedStreamHandler(stream, guard=guard, sink="stdout") + handler.setFormatter(logging.Formatter("%(message)s")) + handler.emit(_record("healthy")) + assert stream.getvalue() == "healthy\n" + + monkeypatch.setattr("sys.stdout", stream) + stream.close() + handler.emit(_record("after the break")) + assert [e.stage for e in events] == ["unwritable"] + assert events[0].sink == "stdout" + assert events[0].stop_requested is True # the only sink, and it is gone + + +# --- configure_logging wiring ------------------------------------------------ + + +@pytest.fixture(autouse=True) +def _restore_process_logging(): # type: ignore[no-untyped-def] + """configure_logging replaces the ROOT handlers and publishes a process-wide guard. Snapshot and + restore both, so a test here cannot leak a rolled/unwritable sink into the rest of the suite.""" + root = logging.getLogger() + handlers = list(root.handlers) + level = root.level + guard = active_guard() + yield + root.handlers[:] = handlers + root.setLevel(level) + set_active_guard(guard) + + +def test_configure_logging_installs_a_guarded_file_sink_beside_stdout(tmp_path: Path) -> None: + path = tmp_path / "engine.log" + configure_logging("INFO", log_file=LogFile(path=str(path))) + logging.getLogger("t").info("a line the engine wrote") + + assert "a line the engine wrote" in path.read_text(encoding="utf-8") + guard = active_guard() + assert guard is not None + assert sorted(s.sink for s in guard.status()) == ["file", "stdout"] + assert all(s.state == "healthy" for s in guard.status()) + + +def test_configure_logging_refuses_a_log_file_it_cannot_open(tmp_path: Path) -> None: + # FAIL CLOSED AT CONFIGURATION TIME, on a genuinely impossible path (the parent is a file). + # Starting an engine that cannot log is the silent blindness #122 exists to end. + parent = tmp_path / "not-a-dir" + parent.write_text("regular file", encoding="utf-8") + with pytest.raises(OSError): + configure_logging("INFO", log_file=LogFile(path=str(parent / "engine.log"))) + + +def test_configure_logging_threads_the_stop_policy_onto_the_guard() -> None: + configure_logging("INFO", stop_on_write_failure=False) + guard = active_guard() + assert guard is not None and guard.stop_on_unwritable is False + + +# --- settings: one file, one rotation owner ---------------------------------- + + +def test_settings_refuse_an_engine_log_file_inside_the_supervisor_rotation_dir( + tmp_path: Path, +) -> None: + with pytest.raises(ValueError, match="rotates"): + LoggingSettings(log_dir=str(tmp_path), file=str(tmp_path / "engine.log")) + + +def test_settings_accept_an_engine_log_file_outside_the_supervisor_rotation_dir( + tmp_path: Path, +) -> None: + supervisor = tmp_path / "nssm" + supervisor.mkdir() + settings = LoggingSettings(log_dir=str(supervisor), file=str(tmp_path / "engine.log")) + assert settings.on_write_failure is LogWriteFailurePolicy.STOP # fail-closed by default + + +def test_settings_refuse_the_legacy_planned_rotation_key_names(tmp_path: Path) -> None: + # `[logging]` is pydantic extra="ignore", and CONFIGURATION.md carried `max_bytes`/`backups` as + # accepted-but-ignored planned keys. Silently ignoring them now that the sink is REAL would give + # an operator the 50 MB / 5-backup defaults while their file said otherwise β€” a control that + # reports success while doing something else. Refuse, naming the real keys. + with pytest.raises(ValueError, match="file_max_bytes"): + LoggingSettings(file=str(tmp_path / "engine.log"), max_bytes=1000) + with pytest.raises(ValueError, match="file_backup_count"): + LoggingSettings(file=str(tmp_path / "engine.log"), backups=2) + + +@pytest.mark.parametrize( + ("env_var", "names"), + [("MEFOR_LOGGING_MAX_BYTES", "file_max_bytes"), ("MEFOR_LOGGING_BACKUPS", "file_backup_count")], +) +def test_the_legacy_rotation_key_is_refused_from_env_where_the_file_gate_does_not_reach( + tmp_path: Path, monkeypatch: pytest.MonkeyPatch, env_var: str, names: str +) -> None: + # WHICH LAYER REFUSES DEPENDS ON WHERE THE KEY CAME FROM, and the model validator above is not + # the one a file reaches. `_reject_unknown_file_keys` refuses an unrecognized key in the TOML + # before any model is built, so a FILE carrying either spelling stops there. The env layer is + # different: `docs/CONFIGURATION.md` states plainly that the refusal "covers the FILE. It does not + # cover env or CLI", so a misspelled `MEFOR_*` is normally dropped in SILENCE. + # + # These two spellings are the exception, and that is the whole point of keeping the model + # validator once the loader gained a generic refusal. Without this test the docstring's claim + # about the env layer is unpinned prose, and the validator looks like dead weight next to the + # loader β€” which is exactly how a second line of defence gets deleted as redundant. + config = tmp_path / "messagefoundry.toml" + config.write_text('[logging]\nlevel = "INFO"\n', encoding="utf-8") + monkeypatch.setenv(env_var, "7") + with pytest.raises(ValidationError, match=names): + load_settings(config_path=config) + + +def test_the_legacy_rotation_key_is_refused_in_the_file_by_the_loader(tmp_path: Path) -> None: + # The other half of the pair, so the docs cannot go stale in either direction. A file spelling is + # refused by the LOADER, not by the model validator, and the message an operator actually reads + # is the loader's. Pinned as a pair with the env test so a future loader change that swallowed + # one of these lands here rather than in a deployment. + config = tmp_path / "messagefoundry.toml" + for legacy in ("max_bytes", "backups"): + config.write_text(f"[logging]\n{legacy} = 7\n", encoding="utf-8") + with pytest.raises(ValueError, match=f"unrecognized config key.*{legacy}"): + load_settings(config_path=config) + + +# --- the engine response: stop this process's connections, and say why ------- + + +class _RecordingSink(LoggingAlertSink): + def __init__(self) -> None: + self.stopped: list[tuple[str, str]] = [] + self.log_failures: list[tuple[str, str, str, int | None]] = [] + + def connection_stopped(self, name: str, *, detail: str) -> None: + self.stopped.append((name, detail)) + + def log_write_failed( + self, name: str, *, stage: str, reason: str, stopped: int | None = None + ) -> None: + self.log_failures.append((name, stage, reason, stopped)) + + +class _StubSource: + def __init__(self) -> None: + self.stopped = False + + async def stop(self) -> None: + self.stopped = True + + +def _graph(store: MessageStore, sink: _RecordingSink) -> tuple[RegistryRunner, _StubSource]: + reg = Registry() + reg.add_inbound( + InboundConnection( + INBOUND, + ConnectionSpec(ConnectorType.MLLP, {"host": "127.0.0.1", "port": 0}), + router="r", + ) + ) + reg.add_router("r", lambda m: []) + reg.add_outbound( + OutboundConnection(OUTBOUND, ConnectionSpec(ConnectorType.MLLP, {"host": "h", "port": 1})) + ) + runner = RegistryRunner(reg, store, poll_interval=0.02, alert_sink=sink) + source = _StubSource() + runner._sources[INBOUND] = source # type: ignore[assignment] + return runner, source + + +@pytest.fixture +async def store(tmp_path: Path): # type: ignore[no-untyped-def] + s = await MessageStore.open(tmp_path / "guard.db") + yield s + await s.close() + + +async def test_unwritable_log_stops_intake_and_delivery_and_names_the_cause( + store: MessageStore, +) -> None: + sink = _RecordingSink() + runner, source = _graph(store, sink) + + await runner._respond_to_log_sink_event( + LogSinkEvent(sink="file", stage="unwritable", reason="disk full", stop_requested=True) + ) + + assert source.stopped is True # intake halted β€” nothing new is accepted that cannot be logged + assert ( + OUTBOUND in runner._outbound_paused + ) # delivery paused, queue RETAINED (not dead-lettered) + # The WHY, on the channel that does not depend on the broken log. + assert sink.log_failures == [("file", "unwritable", "disk full", 2)] + # …and the per-connection stop the operator's existing machinery already understands (ADR 0014), + # now actually DRIVEN by a log-write failure and carrying the cause. + assert sorted(name for name, _ in sink.stopped) == [INBOUND, OUTBOUND] + assert all("application log sink 'file' is unwritable" in d for _, d in sink.stopped) + + +async def test_stage1_roll_alerts_but_stops_nothing(store: MessageStore) -> None: + # THE NEGATIVE CONTROL at the engine level: a transient that healed must not take feeds down. + sink = _RecordingSink() + runner, source = _graph(store, sink) + + await runner._respond_to_log_sink_event( + LogSinkEvent( + sink="file", stage="rolled", reason="momentary lock", rolled_aside="/x/a.broken" + ) + ) + + assert source.stopped is False + assert OUTBOUND not in runner._outbound_paused + assert sink.stopped == [] + assert sink.log_failures == [("file", "rolled", "momentary lock", None)] + + +async def test_continue_policy_alerts_but_stops_nothing(store: MessageStore) -> None: + sink = _RecordingSink() + runner, source = _graph(store, sink) + + await runner._respond_to_log_sink_event( + LogSinkEvent(sink="file", stage="unwritable", reason="disk full", stop_requested=False) + ) + + assert source.stopped is False + assert OUTBOUND not in runner._outbound_paused + assert sink.stopped == [] + assert sink.log_failures == [("file", "unwritable", "disk full", None)] + + +async def test_the_halt_is_latched_so_a_second_event_does_not_restop(store: MessageStore) -> None: + sink = _RecordingSink() + runner, _source = _graph(store, sink) + event = LogSinkEvent(sink="file", stage="unwritable", reason="disk full", stop_requested=True) + + await runner._respond_to_log_sink_event(event) + await runner._respond_to_log_sink_event(event) + + assert len(sink.log_failures) == 1 + + +async def test_the_escalation_bridges_from_a_worker_thread_onto_the_engine_loop( + store: MessageStore, +) -> None: + # The failure surfaces inside logging.Handler.emit, on WHATEVER thread logged β€” a handler worker + # thread, a connector thread, the loop itself. The bridge must hand the event to the loop rather + # than mutate runner state off-loop, and it must not block the thread that was logging. + sink = _RecordingSink() + runner, source = _graph(store, sink) + runner._loop = asyncio.get_running_loop() + + await asyncio.to_thread( + runner._on_log_sink_event, + LogSinkEvent(sink="file", stage="unwritable", reason="disk full", stop_requested=True), + ) + for _ in range(200): + if source.stopped: + break + await asyncio.sleep(0.01) + + assert source.stopped is True + assert [f[1] for f in sink.log_failures] == ["unwritable"] + + +async def test_the_runner_subscribes_at_start_and_unsubscribes_at_stop(store: MessageStore) -> None: + # Without this the whole control is inert in the shipped engine while every unit test above + # still passes β€” the "green signal that means nothing" shape (ADR 0158). + guard = LogWriteGuard() + set_active_guard(guard) + runner = RegistryRunner(Registry(), store, poll_interval=0.02) + await runner.start() + try: + assert guard._escalation == runner._on_log_sink_event + finally: + await runner.stop() + assert guard._escalation is None + + +async def test_the_store_is_untouched_so_ack_on_receipt_still_holds(store: MessageStore) -> None: + # ACK-ON-RECEIPT BOUNDARY. A message already durably committed to the ingress stage was ACKed to + # its sender. The application log and the message STORE are different durable records, and an + # application-log failure is not a store failure: the row must survive the halt exactly as it was + # β€” still pending, still claimable, never dead-lettered and never re-enqueued. + message_id = await store.enqueue_ingress(channel_id=INBOUND, raw=RAW, now=0.0) + before = await store.stats() + + sink = _RecordingSink() + runner, _source = _graph(store, sink) + await runner._respond_to_log_sink_event( + LogSinkEvent(sink="file", stage="unwritable", reason="disk full", stop_requested=True) + ) + + assert await store.stats() == before + claimed = await store.claim_next_fifo(INBOUND, stage=Stage.INGRESS.value, now=1.0) + assert claimed is not None and claimed.message_id == message_id + + +# --- THE END-TO-END CONTROL: does the engine actually REFUSE TO PROCESS? ----- +# +# Everything above this line either drives the guard directly or hands the runner a hand-built +# LogSinkEvent. Both are necessary and neither is sufficient: a synthesized event proves the +# RESPONSE, not that a genuinely broken sink ever produces one, and none of it proves the outcome +# the owner's ruling is actually about β€” "we never want to process stuff if the processing cannot be +# logged". These two tests close that gap as a PAIR, over the whole chain (real unwritable file -> +# real GuardedFileHandler installed by configure_logging -> real guard -> real running +# RegistryRunner -> the pipeline), and the negative control is what makes the positive one mean +# anything: a rig where nothing ever drains would pass the "nothing was processed" assertion for the +# wrong reason. + + +def _installed_file_sink() -> GuardedFileHandler: + """The guarded file handler configure_logging just put on the root logger.""" + sinks = [h for h in logging.getLogger().handlers if isinstance(h, GuardedFileHandler)] + assert len(sinks) == 1, f"expected one guarded file sink, found {len(sinks)}" + return sinks[0] + + +def _break_sink_and_replacement(handler: GuardedFileHandler, directory: Path) -> None: + """Make the sink AND everything it could roll to genuinely unwritable, at the OS. + + Closes the live handle and puts a regular FILE where the log's parent directory belongs, so the + rename-aside and the fresh open both fail. Deliberately ONE call with no await and no I/O between + the two steps: a stage-1 roll landing in the gap would open a fresh handle inside the directory + and make the rmtree fail on Windows, turning a race into a confusing error instead of the + condition under test.""" + stream = handler.stream + if stream is not None: + stream.close() + shutil.rmtree(directory) + directory.write_text("not a directory", encoding="utf-8") + + +def _e2e_registry(outdir: Path) -> Registry: + """A real graph: MLLP inbound -> router -> handler -> FILE outbound writing into ``outdir``. + + The inbound binds an ephemeral port and is never connected to; every message in these tests is + put on the ingress stage directly, because the question is what the ROUTER and TRANSFORM workers + do with a message that is already durably in the store β€” the listener stopping is the easy half.""" + reg = Registry() + reg.add_outbound( + OutboundConnection( + OUTBOUND, + ConnectionSpec( + ConnectorType.FILE, {"directory": str(outdir), "filename": "{MSH-10}.hl7"} + ), + ) + ) + reg.add_inbound( + InboundConnection( + INBOUND, + ConnectionSpec(ConnectorType.MLLP, {"host": "127.0.0.1", "port": 0}), + router="r", + ) + ) + reg.add_router("r", lambda m: ["h"]) + reg.add_handler("h", lambda m: Send(OUTBOUND, m)) + return reg + + +async def _until(predicate: Callable[[], bool], timeout: float = 5.0) -> bool: + elapsed = 0.0 + while not predicate(): + if elapsed > timeout: + return False + await asyncio.sleep(0.02) + elapsed += 0.02 + return True + + +async def _until_outbound_row(store: MessageStore, message_id: str, timeout: float = 5.0) -> bool: + """Wait for the message to reach the OUTBOUND stage β€” i.e. the router and transform ran.""" + elapsed = 0.0 + while not await store.outbox_for(message_id): + if elapsed > timeout: + return False + await asyncio.sleep(0.02) + elapsed += 0.02 + return True + + +async def _until_processed(store: MessageStore, message_id: str, timeout: float = 5.0) -> bool: + """Wait for the TERMINAL disposition, not for the delivered file. + + The file appearing means the connector wrote it; ``PROCESSED`` means the store finalizer has since + resolved every stage's rows, and it lands strictly later. Asserting the status right after the + file appears is a race, and it is one this test hit: measured 'routed' where 'processed' was + expected, three times out of four, on a rig that had passed on the first run.""" + elapsed = 0.0 + while (await store.get_message(message_id))["status"] != MessageStatus.PROCESSED.value: + if elapsed > timeout: + return False + await asyncio.sleep(0.02) + elapsed += 0.02 + return True + + +def _kill_every_sink(logdir: Path, monkeypatch: pytest.MonkeyPatch) -> None: + """Make the process genuinely unable to log ANYWHERE β€” the condition the halt is actually about. + + BOTH sinks, because a stop is asked for only when no guarded sink can accept a record: a healthy + stdout beside a dead file means the processing IS still being logged, and halting there would be + a control resting on a false premise. ``configure_logging`` installs stdout AND the opt-in file, + so a file-only break is not the condition under test. + + The stdout handler is re-pointed at an already-closed stream rather than having pytest's own + capture object closed underneath it β€” killing the sink under test must not also kill the harness + that reports the result. ``sys.stdout`` is pinned to the same closed object so the stage-1 + re-resolve has nothing live to rebind to.""" + _break_sink_and_replacement(_installed_file_sink(), logdir) + dead = io.StringIO() + dead.close() + for handler in logging.getLogger().handlers: + if isinstance(handler, GuardedStreamHandler): + handler.stream = dead + monkeypatch.setattr("sys.stdout", dead) + + +def _revive_every_sink(logdir: Path, monkeypatch: pytest.MonkeyPatch) -> None: + """The operator's ACTUAL repair, and the exact inverse of :func:`_kill_every_sink`: give the log + back a real directory and a live stdout. + + Every recovery test must call this, because "the operator fixed the disk" and "the operator + restarted and hoped" are different situations with different correct outcomes β€” and a recovery + test that skips it is asserting the second while claiming the first. The handlers are left holding + their DEAD handles on purpose: re-opening them is the guard's job (a repaired directory does not + un-close a file object), so this also exercises the roll inside the re-validation probe.""" + logdir.unlink() # the regular FILE _kill_every_sink left where the directory belongs + logdir.mkdir() + monkeypatch.setattr("sys.stdout", io.StringIO()) + + +def _e2e_runner(store: MessageStore, outdir: Path, logdir: Path, claim_mode: str) -> RegistryRunner: + configure_logging("INFO", log_file=LogFile(path=str(logdir / "engine.log"))) + return RegistryRunner(_e2e_registry(outdir), store, poll_interval=0.02, claim_mode=claim_mode) + + +# BOTH CLAIM MODES, because the halt reaches the internal stages by two DIFFERENT mechanisms and a +# single-mode test would leave one of them unexercised: pooled (the shipped default) pauses each +# stage dispatcher's lane; per_lane returns out of the router/transform worker at its loop-top gate. +# "The engine refuses to process" is a claim about the engine, not about one claim mode. +CLAIM_MODES = ["pooled", "per_lane"] + + +@pytest.mark.parametrize("claim_mode", CLAIM_MODES) +async def test_a_healthy_log_lets_the_engine_process_a_committed_row( + store: MessageStore, tmp_path: Path, claim_mode: str +) -> None: + # THE NEGATIVE CONTROL, and it is the load-bearing half of the pair. It proves this rig DOES + # process a row put on the ingress stage β€” so when the hostile test asserts the row was NOT + # processed, that assertion is capable of failing. + outdir, logdir = tmp_path / "out", tmp_path / "logs" + outdir.mkdir() + logdir.mkdir() + runner = _e2e_runner(store, outdir, logdir, claim_mode) + await runner.start() + try: + message_id = await store.enqueue_ingress(channel_id=INBOUND, raw=RAW) + assert await _until(lambda: any(outdir.iterdir())), "the healthy engine never delivered" + assert await _until_processed(store, message_id), "delivered but never finalized" + finally: + await runner.stop() + + +@pytest.mark.parametrize("claim_mode", CLAIM_MODES) +async def test_an_unwritable_log_makes_the_engine_refuse_to_process( + store: MessageStore, tmp_path: Path, claim_mode: str, monkeypatch: pytest.MonkeyPatch +) -> None: + # THE TEST THAT MATTERS. Same rig, same message, one difference: the application log is + # GENUINELY unwritable and so is anything the guard could roll to. The owner's ruling β€” "we never + # want to process stuff if the processing cannot be logged" β€” is an ENFORCEMENT claim, so the + # assertion is about the message, not about a warning: after the halt the committed ingress row + # must still be sitting there, unrouted and undelivered, rather than quietly flowing through a + # pipeline with no application log behind it. + # + # MEASURED RED before the runner learned to halt its internal stages: the row reached the + # OUTBOUND stage anyway, because stopping the listener leaves the router and transform workers + # draining the backlog. Only the outbound pause kept it from being delivered. + outdir, logdir = tmp_path / "out", tmp_path / "logs" + outdir.mkdir() + logdir.mkdir() + runner = _e2e_runner(store, outdir, logdir, claim_mode) + await runner.start() + try: + _kill_every_sink(logdir, monkeypatch) + logging.getLogger("t").warning("a record this engine cannot write anywhere") + assert await _until(lambda: runner._log_write_stopped), "the halt never fired" + + # A message durably committed to the ingress stage β€” the ACK-on-receipt state a sender was + # already told AA for. The engine must now leave it alone. + message_id = await store.enqueue_ingress(channel_id=INBOUND, raw=RAW) + # Generous next to the control above, which delivers in well under this at poll_interval 0.02. + await asyncio.sleep(1.0) + + assert list(outdir.iterdir()) == [] # nothing was delivered + assert await store.outbox_for(message_id) == [] # nothing even reached the outbound stage + # RECEIVED, not ROUTED/FILTERED/UNROUTED/PROCESSED: the router never ran on it. + assert (await store.get_message(message_id))["status"] == MessageStatus.RECEIVED.value + # …and the row is intact and still claimable, so fixing the disk and restarting drains it. + claimed = await store.claim_next_fifo(INBOUND, stage=Stage.INGRESS.value) + assert claimed is not None and claimed.message_id == message_id + await store.release_claimed([claimed.id]) # leave it exactly as the halt left it + finally: + await runner.stop() + + +@pytest.mark.parametrize("claim_mode", CLAIM_MODES) +async def test_restarting_the_connections_re_arms_processing_after_the_halt( + store: MessageStore, tmp_path: Path, claim_mode: str, monkeypatch: pytest.MonkeyPatch +) -> None: + # THE RECOVERY HALF, and it is not optional: a fail-closed halt whose re-arm is broken is an + # engine that stays deaf after the disk is fixed, and nothing above would notice. The ADR promises + # "fix the disk, restart, and the backlog drains" β€” this is that sentence, measured. It also + # covers the ordering trap in _start_inbound_unsafe: resume BEFORE the worker respawn, or the + # respawned worker hits its own gate and exits while the restart reports success. + outdir, logdir = tmp_path / "out", tmp_path / "logs" + outdir.mkdir() + logdir.mkdir() + runner = _e2e_runner(store, outdir, logdir, claim_mode) + await runner.start() + try: + _kill_every_sink(logdir, monkeypatch) + logging.getLogger("t").warning("a record this engine cannot write anywhere") + assert await _until(lambda: runner._log_write_stopped), "the halt never fired" + message_id = await store.enqueue_ingress(channel_id=INBOUND, raw=RAW) + await asyncio.sleep(0.3) + assert await store.outbox_for(message_id) == [] # still halted + + _revive_every_sink(logdir, monkeypatch) # the operator actually fixes the disk + await runner.restart_inbound(INBOUND) # …and only THEN restarts + await runner.start_outbound(OUTBOUND) + + assert await _until(lambda: any(outdir.iterdir())), ( + "the backlog never drained after the restart" + ) + assert await _until_processed(store, message_id), "drained but never finalized" + assert INBOUND not in runner._log_halted + finally: + await runner.stop() + + +@pytest.mark.parametrize("claim_mode", CLAIM_MODES) +async def test_a_restart_is_refused_while_the_log_is_still_unwritable( + store: MessageStore, tmp_path: Path, claim_mode: str, monkeypatch: pytest.MonkeyPatch +) -> None: + # THE OTHER HALF OF THE ENFORCEMENT, and it was a MEASURED hole rather than a hypothetical: the + # halt fired correctly, and then `restart_inbound` + `start_outbound` re-armed the entire pipeline + # while the guard's own state still read {'file': 'unwritable', 'stdout': 'unwritable'}. The + # message went to PROCESSED with no application log behind it, in BOTH claim modes. Worse, it was + # unrecoverable-by-design: `_log_write_stopped` and the guard's per-sink `already_down` latch are + # both one-shot, so after that first restart NOTHING could ever fail-closed again in that process. + # + # A fail-closed control that any restart disarms is a control with an off switch. The recovery + # tests above pass because they REPAIR the log first; this one proves the repair is what earns the + # re-arm, rather than the restart command by itself. + outdir, logdir = tmp_path / "out", tmp_path / "logs" + outdir.mkdir() + logdir.mkdir() + runner = _e2e_runner(store, outdir, logdir, claim_mode) + await runner.start() + try: + _kill_every_sink(logdir, monkeypatch) + logging.getLogger("t").warning("a record this engine cannot write anywhere") + assert await _until(lambda: runner._log_write_stopped), "the halt never fired" + + # The operator restarts WITHOUT fixing anything. Deliberately no _revive_every_sink. + await runner.restart_inbound(INBOUND) + await runner.start_outbound(OUTBOUND) + + message_id = await store.enqueue_ingress(channel_id=INBOUND, raw=RAW) + await asyncio.sleep(1.0) # generous: the repaired path drains far inside this + + assert INBOUND in runner._log_halted # the re-arm was refused, not silently granted + assert INBOUND not in runner._sources # …and intake did not come back either + assert list(outdir.iterdir()) == [] + assert await store.outbox_for(message_id) == [] + assert (await store.get_message(message_id))["status"] == MessageStatus.RECEIVED.value + + # The refusal is not permanent β€” it is conditioned on the log, so the SAME restart works once + # the disk is fixed. Without this the test would also pass against an engine that simply never + # restarts anything, which is the wrong control for the right reason. + _revive_every_sink(logdir, monkeypatch) + await runner.restart_inbound(INBOUND) + await runner.start_outbound(OUTBOUND) + assert await _until(lambda: any(outdir.iterdir())), "the repaired engine never drained" + assert await _until_processed(store, message_id), "drained but never finalized" + finally: + await runner.stop() + + +def test_revalidate_reports_a_process_that_still_cannot_log(tmp_path: Path) -> None: + # The guard-level unit behind the refusal above. `unwritable` is set only by a failed write and + # nothing clears it, so a cached read cannot tell "fixed" from "still broken" β€” revalidate answers + # by WRITING. Both directions, because a revalidate that always said False would pass the refusal + # test for the wrong reason. + logdir = tmp_path / "logs" + logdir.mkdir() + guard = LogWriteGuard() + handler = _file_handler(logdir / "engine.log", guard) + _break_the_open_handle(handler) + _replace_directory_with_a_file(logdir) + handler.emit(_record("first write after the break")) + assert [s.state for s in guard.status()] == ["unwritable"] + + assert guard.revalidate() is False # still broken: the probe write cannot land + assert guard.can_log() is False + + logdir.unlink() + logdir.mkdir() + assert guard.revalidate() is True # repaired: the probe rolled to a fresh file and wrote + assert guard.can_log() is True + assert [s.state for s in guard.status()] == ["healthy"] + # The latch is genuinely cleared, so a LATER break pages again instead of being swallowed. + events: list[LogSinkEvent] = [] + guard.set_escalation(events.append) + _break_the_open_handle(handler) + _replace_directory_with_a_file(logdir) + handler.emit(_record("a second, independent break")) + assert [e.stage for e in events] == ["unwritable"] + assert events[0].stop_requested is True + + +# --- the two observability channels the ADR leans on, each pinned ------------ + + +def test_the_alert_type_is_operator_rule_targetable() -> None: + # ADR 0162 Β§5 claims an operator can route "the engine went deaf" APART from one stalled lane. + # That claim is only true if `log_write_failed` is in settings._ALERT_EVENT_TYPES β€” a name added + # to alert_sinks but omitted there is silently un-targetable (AlertRule rejects it), which is + # precisely the defect ALERT-12 records for lane_stuck and rcsi_off_degraded. + from messagefoundry.config.settings import AlertRule, AlertSeverity + from messagefoundry.pipeline.alert_sinks import AlertRuleSet + + rules = AlertRuleSet( + [AlertRule(event_type="log_write_failed", severity=AlertSeverity.CRITICAL)] + ) + assert rules.decide({"type": "log_write_failed", "connection": "file"}).severity == "critical" + # …and a different event still falls through to the default, so the rule is targeted, not global. + assert rules.decide({"type": "connection_stopped", "connection": "IB_X"}).severity == "warning" + + +def test_status_reports_per_sink_health_from_process_memory(tmp_path: Path) -> None: + # The THIRD channel, and the ADR's reason for having it: a log line about a broken log sink may + # never land and an engine with no notifier configured pages nobody, but /status answers from + # process memory. So it must report the break WITHOUT touching the filesystem it is reporting on. + from messagefoundry.api.app import _log_sink_health + + logdir = tmp_path / "logs" + logdir.mkdir() + configure_logging("INFO", log_file=LogFile(path=str(logdir / "engine.log"))) + assert {s.sink: s.state for s in _log_sink_health()} == {"stdout": "healthy", "file": "healthy"} + + _break_sink_and_replacement(_installed_file_sink(), logdir) + logging.getLogger("t").warning("a record this engine cannot write anywhere") + + reported = {s.sink: s for s in _log_sink_health()} + assert reported["file"].state == "unwritable" + assert reported["stdout"].state == "healthy" # the break is per-sink, not global + # Metadata only β€” a scrubbed reason and a timestamp, never a line of the log. + assert reported["file"].last_event and reported["file"].last_event_at + assert "a record this engine cannot write anywhere" not in (reported["file"].last_event or "") + + +def test_a_second_responder_taking_the_slot_is_announced( + capsys: pytest.CaptureFixture[str], +) -> None: + # The escalation seam holds ONE responder. A second RegistryRunner in the same process takes the + # slot and the first engine is silently unguarded from then on β€” a fail-closed control that + # disappears with every assertion in this file still green. One process runs one engine, so this + # is not made an error; it is made AUDIBLE, which is the difference between a known limit and a + # silent one. + guard = LogWriteGuard() + guard.set_escalation(lambda event: None) + capsys.readouterr() # discard anything from the first wiring + guard.set_escalation(lambda event: None) + + assert "no longer guarded" in capsys.readouterr().err + + +def test_re_wiring_the_same_responder_is_silent(capsys: pytest.CaptureFixture[str]) -> None: + # …and the negative control, because a warning that fires on the ordinary case gets ignored: + # re-installing the SAME callback (a restart re-subscribing) displaces nobody and says nothing. + def responder(event: LogSinkEvent) -> None: + return None + + guard = LogWriteGuard() + guard.set_escalation(responder) + capsys.readouterr() + guard.set_escalation(responder) + guard.set_escalation(None) + + assert capsys.readouterr().err == "" + + +@pytest.mark.parametrize("claim_mode", CLAIM_MODES) +async def test_a_reload_re_arms_exactly_the_inbounds_it_re_binds( + store: MessageStore, tmp_path: Path, claim_mode: str, monkeypatch: pytest.MonkeyPatch +) -> None: + # MEASURED, because the reload path was read two ways before it was run. reload() quiesces every + # source and then calls _start_inbound_unsafe for each inbound the new graph re-binds β€” which is + # where the re-arm lives β€” so a reload DOES resume the inbounds it re-binds, and leaves the ones + # it declines to bind (deployed=False / auto_start=False+not-previously-listening / DR-filtered) + # halted. Both halves matter: "a reload fixes it" and "a reload fixes nothing" are each half + # right, and shipping either sentence alone would send an operator the wrong way during an + # incident. + outdir, logdir = tmp_path / "out", tmp_path / "logs" + outdir.mkdir() + logdir.mkdir() + runner = _e2e_runner(store, outdir, logdir, claim_mode) + await runner.start() + try: + _kill_every_sink(logdir, monkeypatch) + logging.getLogger("t").warning("a record this engine cannot write anywhere") + assert await _until(lambda: runner._log_write_stopped), "the halt never fired" + message_id = await store.enqueue_ingress(channel_id=INBOUND, raw=RAW) + await asyncio.sleep(0.3) + assert await store.outbox_for(message_id) == [] # still halted + + _revive_every_sink(logdir, monkeypatch) # a reload re-arms only once the log works again + await runner.reload(_e2e_registry(outdir)) + + assert INBOUND not in runner._log_halted # re-bound, therefore re-armed + # …and it re-armed the STAGES, not just the flag: the row moves again. The OUTBOUND pause is + # operator-owned and a reload must NOT resume it (#115/#233), so the row reaches the outbound + # stage and waits there β€” the honest reach of a reload, and why the docs still say restart. + assert await _until_outbound_row(store, message_id), "the reload re-armed nothing" + assert list(outdir.iterdir()) == [] # …but delivery is still paused + await runner.start_outbound(OUTBOUND) + assert await _until(lambda: any(outdir.iterdir())), "never drained after reload + resume" + assert await _until_processed(store, message_id), "drained but never finalized" + finally: + await runner.stop() + + +@pytest.mark.parametrize("claim_mode", CLAIM_MODES) +async def test_a_runner_started_into_a_dead_log_comes_up_halted( + store: MessageStore, tmp_path: Path, claim_mode: str, monkeypatch: pytest.MonkeyPatch +) -> None: + # THE RE-ARM PATH THAT WAS NOT GATED, and it was found by execution rather than review. Every + # OTHER door back into processing asks `_log_recovery_ok` first β€” `restart_inbound`, + # `start_outbound`, a reload's `_start_inbound_unsafe`. `RegistryRunner.start` did not: it cleared + # `_log_write_stopped` and `_log_halted` unconditionally, on the reasoning that a fresh start is a + # fresh engine. + # + # MEASURED RED, in BOTH claim modes, on the rig below: with both sinks unwritable BEFORE the + # runner was built, a committed ingress row went to `PROCESSED` and was DELIVERED while + # `guard.can_log()` read False the whole time. That is the item's own sentence β€” processing what + # cannot be logged β€” reached through the one path the halt did not cover. It is not hypothetical + # plumbing: `Engine` starts a RegistryRunner on leadership acquisition and on the reload that + # first builds one, and neither asks about the log. + # + # The engine comes up HALTED rather than refusing to start, because /status, the alert state and + # the recovery paths are what an operator needs precisely here. + outdir, logdir = tmp_path / "out", tmp_path / "logs" + outdir.mkdir() + logdir.mkdir() + configure_logging("INFO", log_file=LogFile(path=str(logdir / "engine.log"))) + _kill_every_sink(logdir, monkeypatch) # the log dies BEFORE the runner exists + logging.getLogger("t").warning("a record this process cannot write anywhere") + guard = active_guard() + assert guard is not None and not guard.can_log(), "the rig never made the process unable to log" + + runner = RegistryRunner(_e2e_registry(outdir), store, poll_interval=0.02, claim_mode=claim_mode) + await runner.start() + try: + assert runner._log_write_stopped, "start cleared the halt against an unwritable log" + assert INBOUND in runner._log_halted + assert INBOUND not in runner._sources, "intake stayed up with the internal stages halted" + + message_id = await store.enqueue_ingress(channel_id=INBOUND, raw=RAW) + await asyncio.sleep(1.0) # generous: the healthy rig above delivers far inside this + assert list(outdir.iterdir()) == [] + assert await store.outbox_for(message_id) == [] + assert (await store.get_message(message_id))["status"] == MessageStatus.RECEIVED.value + + # …and the halt is CONDITIONED, not permanent β€” otherwise this test would also pass against a + # runner that simply never processes anything, which is the wrong control for the right reason. + _revive_every_sink(logdir, monkeypatch) + await runner.restart_inbound(INBOUND) + await runner.start_outbound(OUTBOUND) + assert await _until(lambda: any(outdir.iterdir())), "the repaired engine never drained" + assert await _until_processed(store, message_id), "drained but never finalized" + finally: + await runner.stop() + + +# --- the hair trigger on the DEFAULT sink, found by running the suite --------- + + +def test_a_swapped_stdout_stream_heals_at_stage_1_and_stops_nothing( + monkeypatch: pytest.MonkeyPatch, +) -> None: + # THE REGRESSION THIS FILE EXISTS TO PREVENT REPEATING, and it was found by the full suite rather + # than by review. The stdout handler holds the stream OBJECT it was built with. When a supervisor + # swaps the capture file β€” or, identically, when pytest tears its capture down β€” that object is + # closed and every later write raises "I/O operation on closed file", INCLUDING stage 1's own + # notice write. Stage 1 therefore failed by construction and every stdout write failure escalated + # to stage 2. Measured in the full suite: it halted a running load engine's seven connections and + # the load run sent ZERO messages. Re-resolving sys.stdout is the honest roll for a stream the + # engine did not open, and it is what "a re-attempt clears the transient" always claimed to do. + events: list[LogSinkEvent] = [] + guard = LogWriteGuard() + guard.set_escalation(events.append) + original, replacement = io.StringIO(), io.StringIO() + handler = GuardedStreamHandler(original, guard=guard, sink="stdout") + handler.setFormatter(logging.Formatter("%(message)s")) + handler.emit(_record("before the swap")) + + monkeypatch.setattr("sys.stdout", replacement) + original.close() # the object the handler still points at is now dead + handler.emit(_record("after the swap")) + + assert [e.stage for e in events] == ["rolled"] # healed β€” NOT a stop + assert guard.status()[0].state == "rolled" + written = replacement.getvalue() + assert "was rolled after a write failure" in written # the event is recorded on the live stream + assert "after the swap" in written # …and the record that failed is re-written, not dropped + handler.emit(_record("and it keeps working")) + assert "and it keeps working" in replacement.getvalue() + + +def test_one_dead_sink_beside_a_healthy_one_does_not_ask_for_a_stop(tmp_path: Path) -> None: + # "Can this process still log?" is the question the ruling asks, and it is NOT "did a sink + # break?". With the opt-in [logging].file configured there are two sinks; stopping every + # connection because ONE of them died β€” while the other is still accepting every record β€” is a + # control resting on a false premise. It is still recorded, still alerted, still on /status: + # visibility is unconditional, only the ENFORCEMENT is conditioned on the thing it is about. + events: list[LogSinkEvent] = [] + guard = LogWriteGuard() + guard.set_escalation(events.append) + guard.register("file") # healthy, never touched + log_dir = tmp_path / "logs" + log_dir.mkdir() + handler = GuardedStreamHandler(io.StringIO(), guard=guard, sink="stdout") + handler.setFormatter(logging.Formatter("%(message)s")) + handler.stream.close() + handler._roll = lambda: None # type: ignore[method-assign] # no live stdout to re-resolve to + handler.emit(_record("stdout is gone but the file sink is fine")) + + assert [e.stage for e in events] == ["unwritable"] + assert events[0].stop_requested is False # detected and alerted, but nothing is stopped + assert {s.sink: s.state for s in guard.status()} == {"file": "healthy", "stdout": "unwritable"} + + +def test_the_last_sink_dying_does_ask_for_a_stop(tmp_path: Path) -> None: + # …and the paired positive: once the OTHER sink is unwritable too, the process genuinely cannot + # log and the halt is asked for. Without this the test above would be indistinguishable from + # having disarmed the control. + events: list[LogSinkEvent] = [] + guard = LogWriteGuard() + guard.set_escalation(events.append) + log_dir = tmp_path / "logs" + log_dir.mkdir() + file_handler = _file_handler(log_dir / "app.log", guard) + stdout_handler = GuardedStreamHandler(io.StringIO(), guard=guard, sink="stdout") + stdout_handler.setFormatter(logging.Formatter("%(message)s")) + stdout_handler.stream.close() + stdout_handler._roll = lambda: None # type: ignore[method-assign] + stdout_handler.emit(_record("stdout first")) + assert events[-1].stop_requested is False + + _break_the_open_handle(file_handler) + _replace_directory_with_a_file(log_dir) + file_handler.emit(_record("and now the file too")) + + assert [e.stage for e in events] == ["unwritable", "unwritable"] + assert events[-1].stop_requested is True # nothing left that can log: HALT diff --git a/tests/test_phi_at_rest_inventory.py b/tests/test_phi_at_rest_inventory.py index c6ebe56d2..d72131fc4 100644 --- a/tests/test_phi_at_rest_inventory.py +++ b/tests/test_phi_at_rest_inventory.py @@ -160,6 +160,10 @@ ("retention", "wal_checkpoint_seconds"), ("retention", "vacuum_at"), ("backup", "config_only_on_server_db"), + # #122 / ADR 0162 β€” the opt-in engine-managed application-log sink the inventory's app-log row + # now names, and the fail-closed policy it names beside it. + ("logging", "file"), + ("logging", "on_write_failure"), ) diff --git a/tests/test_phi_logging_inventory.py b/tests/test_phi_logging_inventory.py index 5dff2ee23..7a0bc85d4 100644 --- a/tests/test_phi_logging_inventory.py +++ b/tests/test_phi_logging_inventory.py @@ -87,6 +87,12 @@ "two handler filters", "same two handler filters", "[ai].production", + # #122 / ADR 0162: the engine DOES install a file handler now, when the opt-in [logging].file is + # set. Both spellings the inventory used to carry are retired, so the absence claim cannot creep + # back as a copy-edit β€” a security document asserting an absence that has stopped being true is + # precisely what this scanner exists to catch. + "installs no file handler", + "installs **no file handler**", ) @@ -225,6 +231,10 @@ def test_default_on_wording_matches_the_shipped_defaults() -> None: "Β§7 says the off-box forward format defaults to JSON" ) assert logging_settings.forward_tls_verify is True, "Β§7 says TLS verification is on by default" + assert logging_settings.file is None, ( + "Β§7 calls the engine-managed [logging].file sink OPT-IN; a default-on file sink is a new " + "at-rest PHI surface and needs its own inventory row (#122, ADR 0162)" + ) assert alerts.security_notifications_required is True, ( "Β§7 calls the per-user security-event channel posture-mandatory" ) @@ -554,6 +564,15 @@ def test_every_diagnostics_field_is_named_in_the_inventory() -> None: #: which is how ``tray.log`` shipped undocumented. _ALLOWED_SINK_MODULES: dict[str, str] = { "messagefoundry/logging_setup.py": "streams 1 + 2 (stdout/stderr, the off-box syslog forwarder)", + # #122 / ADR 0162. This module defines the guarded handler CLASSES for stream 1 β€” + # GuardedStreamHandler (stdout) and GuardedFileHandler (the opt-in `[logging].file`, a + # RotatingFileHandler subclass) β€” which logging_setup constructs, filters and installs. No new + # DESTINATION: stream 1's row names both, and the same three PHI filters are installed on each. + # LISTED rather than excluded, because the class that opens and rolls the file genuinely lives + # here, so a future sink added beside it must still trip this gate. + "messagefoundry/logging_guard.py": ( + "stream 1 β€” the guarded handler classes for stdout and the opt-in `[logging].file`" + ), "messagefoundry/tray/__main__.py": ( "the tray's RotatingFileHandler β€” named in 'Not in this inventory, and why'" ),