From df7e73b3b16277e716e02d71b9d8ad1f2f4d48fe Mon Sep 17 00:00:00 2001 From: wshallwshall Date: Fri, 4 Sep 2026 17:49:09 -0500 Subject: [PATCH 1/4] feat(logging): fail-closed application-log write guard, ported onto main (BACKLOG #122) The owner ruled #122 in on 2026-08-11: "we never want to process stuff if the processing cannot be logged." That is CLAUDE.md section 1's count-and-log invariant applied to the application log. stdout, NSSM rotation, the RFC 5425 forwarder and #50's disk metering all make the log VISIBLE; none of them makes processing STOP when it cannot be written. This is the enforcement half. The work existed unlanded and unverified on `w3-log-write-failure`, whose history is unrelated to `main` (main's root is 72bfddfad, the branch's is 5fa6db9f), so it could never be merged or rebased. This commit re-applies it as a three-way patch onto current main and resolves the five conflicts main's movement created. What lands: - `messagefoundry/logging_guard.py`: `LogWriteGuard` plus the guarded sinks `GuardedStreamHandler` / `GuardedFileHandler`. Detection is a `logging.Handler.handleError` override, so one seam covers every sink and every OS failure mode with no polling. Two stages: `_roll` renames the broken file aside, opens a fresh one, writes the rollover notice and re-writes the failed record; only when that REPLACEMENT also refuses does `record_unwritable` escalate. Stage 1 is bounded by `_ROLL_FLAP_WINDOW_SECONDS` / `_MAX_ROLLS_PER_WINDOW`, because a sink needing rescue every few records is a failing log, not a transient. - `[logging].file` / `file_max_bytes` / `file_backup_count` / `on_write_failure` in `LoggingSettings`, with the validator refusing a `file` inside `log_dir` so the engine and NSSM can never rotate one file. - `RegistryRunner` wires itself to the guard and responds on the loop: `_on_log_sink_event` hands off thread-safely, and the halt stops all three tiers. `_resume_inbound_processing` and `start_outbound` gate every re-arm on `_log_recovery_ok`, which re-tests a dead sink BY WRITING to it, since `unwritable` is only ever set by a failed write and nothing clears it on its own. - A `log_write_failed` alert through the notifier and `SystemStatus.log_sinks` on `GET /status`, read from process memory so it still answers when the disk does not. Conflict resolutions worth naming: - The branch's hand-chosen `ENGINE_UI_SEAM: int = 19` is obsolete. BACKLOG #1220 replaced the hand-picked number with a digest computed by `scripts/webconsole_seam_snapshot.py`, so the seam is regenerated rather than bumped, and `SUPPORTED_ENGINE_SEAMS` follows it. - `_start_outbound` and `_start_outbound_unsafe` are `async` on main; the branch's sync call sites are awaited. - `docs/testing/master-test-plan/` was untracked under ADR 0160 D1, so the branch's edit there is dropped rather than re-created. `docs/adr/0162-*.md` is deliberately NOT in this commit. The ledger gate refuses it, correctly by its own rule: the claim names `C:/Users/Scott/Code/MessageFoundry-w3-log-write-failure`, which no longer exists, and the branch fallback names `w3-log-write-failure`, whose history is unrelated to main so no commit made there can reach this PR. Neither documented recovery is reachable from an isolated worktree, and allocating a fresh number is what burns a number, so the citations are plain `ADR 0162` with no dangling relative link. Co-Authored-By: Claude Opus 5 --- docs/CONFIGURATION.md | 12 +- docs/PHI.md | 6 +- docs/SERVICE.md | 47 + messagefoundry/__main__.py | 34 +- messagefoundry/api/_ui_seam.py | 11 +- messagefoundry/api/app.py | 25 + messagefoundry/api/models.py | 24 + messagefoundry/config/settings.py | 78 +- messagefoundry/logging_guard.py | 608 ++++++++++++ messagefoundry/logging_setup.py | 66 +- messagefoundry/pipeline/alert_sinks.py | 19 + messagefoundry/pipeline/alerts.py | 34 + messagefoundry/pipeline/wiring_runner.py | 287 +++++- messagefoundry_webconsole/__init__.py | 2 +- tests/golden/webconsole_seam.snapshot | 5 +- tests/test_log_write_guard.py | 1158 ++++++++++++++++++++++ tests/test_phi_at_rest_inventory.py | 4 + tests/test_phi_logging_inventory.py | 19 + 18 files changed, 2421 insertions(+), 18 deletions(-) create mode 100644 messagefoundry/logging_guard.py create mode 100644 tests/test_log_write_guard.py diff --git a/docs/CONFIGURATION.md b/docs/CONFIGURATION.md index 5a2b79129..beefe9cdf 100644 --- a/docs/CONFIGURATION.md +++ b/docs/CONFIGURATION.md @@ -33,7 +33,10 @@ > `[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 while naming their +> replacements (`file_max_bytes`, `file_backup_count`). ## Principle — two kinds of configuration @@ -674,7 +677,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 +692,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 | +| `file_backup_count` | int | `5` | how many `file.1` … `file.N` backups to keep (the legacy planned spelling `backups` is likewise refused, naming this key). 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..51342f6c1 100644 --- a/docs/SERVICE.md +++ b/docs/SERVICE.md @@ -390,6 +390,53 @@ 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..2609cf7a9 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,29 @@ 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.""" + 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 +1615,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 +2782,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..2bcc4c99a 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,228 @@ 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 _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) + 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) + 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) + + 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 +2736,15 @@ 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: + self._log_write_stopped = False # a restart re-arms the halt + self._log_halted.clear() # …and un-halts every inbound's internal stages + 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: @@ -2864,6 +3128,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. @@ -4921,6 +5195,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 +5534,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 +5617,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..b67db7c4c --- /dev/null +++ b/tests/test_log_write_guard.py @@ -0,0 +1,1158 @@ +# 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 messagefoundry.config.models import ConnectorType +from messagefoundry.config.settings import LoggingSettings, LogWriteFailurePolicy +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) + + +# --- 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() + + +# --- 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'" ), From af289664502b521aa91d6e8cdd65120460ff7103 Mon Sep 17 00:00:00 2001 From: wshallwshall Date: Fri, 4 Sep 2026 18:46:54 -0500 Subject: [PATCH 2/4] fix(logging): RegistryRunner.start was the one re-arm the #122 halt did not gate (BACKLOG #122) Found by execution, not by review. Every door back into processing asks `_log_recovery_ok` first -- `restart_inbound`, `start_outbound`, and a reload through `_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, both claim modes, before this commit: with both sinks made unwritable BEFORE the runner was built, a committed ingress row went to `PROCESSED` and was DELIVERED to the outbound file connector, while `LogWriteGuard.can_log()` read False throughout. That is the item's own sentence -- processing what cannot be logged -- reached through the one path the halt did not cover. It is reachable plumbing, not a test artefact. `Engine` starts a `RegistryRunner` on leadership acquisition and on the reload that first builds one, and neither asks about the log. Three parts, and the mutation test shows each is load-bearing: - `start` now gates the clear on `LogWriteGuard.revalidate`, which re-tests each DEAD sink by writing a real record to it. The ordinary case -- a guard `configure_logging` built moments ago, nothing dead -- has nothing to probe, answers True, and clears exactly as before. Mutating this back makes the new test fail in both claim modes. - `_start_pooled_dispatchers` replays an in-force halt onto the fresh INGRESS / ROUTED / RESPONSE dispatchers before step (3) seeds every lane READY -- the exact sibling of the `_outbound_paused` replay at (2.5), and it fails the same way when missing. Mutating it out makes only the POOLED arm fail: per_lane survives on its workers' loop-top gate, which pooled mode does not run. - `_unbind_for_log_failure` takes the listeners that already bound back down, so intake is never up with the internal stages halted -- the state `_start_inbound_unsafe`'s own refusal path already avoids. The engine comes up HALTED rather than refusing 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. It pages through the notifier for the reason the whole control does -- the thing that is broken is the log. `_reconcile_pooled_dispatchers` gets the same re-pause beside its existing outbound one, for the same belt-and-braces reason. Also, a second thing the port made stale. `_refuse_renamed_file_keys`'s docstring said `extra="ignore"` was why it had to run at `mode="before"`, which is still true of the MODEL but no longer describes what an operator meets: main's loader now refuses an unrecognized FILE key first. Measured across both layers: - file `[logging].max_bytes` -- refused by the loader, suggested onward as `file_max_bytes`; - file `[logging].backups` -- refused by the loader, naming no replacement (its nearest-name hint does not reach `file_backup_count`); - env `MEFOR_LOGGING_MAX_BYTES` and `MEFOR_LOGGING_BACKUPS` -- refused by this validator, each naming its replacement. So the validator is not redundant with the loader: env is the layer the file refusal deliberately does not cover, and these two spellings are the rare `MEFOR_*` names that fail loudly instead of silently. Pinned as a pair of tests so neither half of that sentence can go stale unnoticed, and `docs/CONFIGURATION.md` now says which layer does which. Co-Authored-By: Claude Opus 5 --- docs/CONFIGURATION.md | 12 +-- docs/SERVICE.md | 3 +- messagefoundry/config/settings.py | 16 +++- messagefoundry/pipeline/wiring_runner.py | 94 +++++++++++++++++++++++- tests/test_log_write_guard.py | 91 ++++++++++++++++++++++- 5 files changed, 205 insertions(+), 11 deletions(-) diff --git a/docs/CONFIGURATION.md b/docs/CONFIGURATION.md index beefe9cdf..510937857 100644 --- a/docs/CONFIGURATION.md +++ b/docs/CONFIGURATION.md @@ -34,9 +34,11 @@ > `[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].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 while naming their -> replacements (`file_max_bytes`, `file_backup_count`). +> #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 @@ -693,8 +695,8 @@ Only `baa_attested` is still a forward-compat placeholder (accepted-but-ignored) | `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` | 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 | -| `file_backup_count` | int | `5` | how many `file.1` … `file.N` backups to keep (the legacy planned spelling `backups` is likewise refused, naming this key). 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 | +| `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 diff --git a/docs/SERVICE.md b/docs/SERVICE.md index 51342f6c1..64a695733 100644 --- a/docs/SERVICE.md +++ b/docs/SERVICE.md @@ -404,8 +404,7 @@ one file is how a log gets shredded, and the loser of that race is the log you r 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: +**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 diff --git a/messagefoundry/config/settings.py b/messagefoundry/config/settings.py index 2609cf7a9..4c114cbed 100644 --- a/messagefoundry/config/settings.py +++ b/messagefoundry/config/settings.py @@ -1538,7 +1538,21 @@ def _refuse_renamed_file_keys(cls, data: Any) -> Any: 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.""" + 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"), diff --git a/messagefoundry/pipeline/wiring_runner.py b/messagefoundry/pipeline/wiring_runner.py index 2bcc4c99a..1636db12f 100644 --- a/messagefoundry/pipeline/wiring_runner.py +++ b/messagefoundry/pipeline/wiring_runner.py @@ -2583,6 +2583,47 @@ def _log_write_refused_restart(self, name: str) -> None: 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. @@ -2742,8 +2783,30 @@ async def start(self) -> None: # subscription is simply skipped — no engine behaviour depends on the guard existing. guard = active_log_guard() if guard is not None: - self._log_write_stopped = False # a restart re-arms the halt - self._log_halted.clear() # …and un-halts every inbound's internal stages + # 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). @@ -2832,6 +2895,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: @@ -3518,6 +3586,18 @@ 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. + for stage in (Stage.INGRESS, Stage.ROUTED, Stage.RESPONSE): + internal = self._dispatchers.get(stage) + if internal is None: + continue + for n in self._log_halted: + internal.pause_lane(n) # (3) start each (seed-all-READY + immediate sweep). reset_stale_inflight already ran (engine). for dispatcher in self._dispatchers.values(): await dispatcher.start() @@ -3677,6 +3757,16 @@ 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. + for stage in (Stage.INGRESS, Stage.ROUTED, Stage.RESPONSE): + internal = self._dispatchers.get(stage) + if internal is None: + continue + for n in self._log_halted: + internal.pause_lane(n) 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 diff --git a/tests/test_log_write_guard.py b/tests/test_log_write_guard.py index b67db7c4c..f6eaa4f72 100644 --- a/tests/test_log_write_guard.py +++ b/tests/test_log_write_guard.py @@ -32,9 +32,10 @@ from pathlib import Path import pytest +from pydantic import ValidationError from messagefoundry.config.models import ConnectorType -from messagefoundry.config.settings import LoggingSettings, LogWriteFailurePolicy +from messagefoundry.config.settings import LoggingSettings, LogWriteFailurePolicy, load_settings from messagefoundry.config.wiring import ( ConnectionSpec, InboundConnection, @@ -468,6 +469,42 @@ def test_settings_refuse_the_legacy_planned_rotation_key_names(tmp_path: Path) - 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 ------- @@ -1075,6 +1112,58 @@ async def test_a_reload_re_arms_exactly_the_inbounds_it_re_binds( 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 --------- From 36fabbd6b503a7b0b3035328a10b8ce77476e7ee Mon Sep 17 00:00:00 2001 From: wshallwshall Date: Fri, 4 Sep 2026 18:52:39 -0500 Subject: [PATCH 3/4] docs(backlog): close #122 -- the log-write halt is built and verified by execution (BACKLOG #122) Flips the banner to SHIPPED and records what was measured rather than what was claimed. Its own commit, and last, because every item's pull request edits this file by construction. Four things the row now states that it did not: - The partial halt was REAL. Mutating `_halt_inbound_processing` to a no-op put the committed ingress row on the outbound stage in both claim modes, while the healthy-log negative control still delivered. - A third hole of the same class was found here and was not on the branch: `RegistryRunner.start` was the one re-arm that never asked whether the log worked. - ADR 0162's file is not on `main`, and the number is NOT burned. The ledger gate refuses it correctly -- the claim's worktree is gone and its branch shares no root commit with `main`, so neither documented recovery is reachable and remedy 3 is not licensed. The subject is named rather than numbered, per CLAUDE.md section 5. - The anchor the row carried is stale. The branch tip is `46b3a4437`, not `d26d66a6`, and it carries eight commits rather than five. The prior banners are kept rather than rewritten -- the leading one supersedes them, which is how this file records history -- and the machine-read `Verdict` / `Closing-act` fields now say `build` / `code`, which is how it actually closed. Co-Authored-By: Claude Opus 5 --- docs/BACKLOG.md | 16 +++++++++++++--- 1 file changed, 13 insertions(+), 3 deletions(-) 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. From ad3914b55680685656d0da0c2ed21cd6c9a3b358 Mon Sep 17 00:00:00 2001 From: wshallwshall Date: Fri, 4 Sep 2026 19:12:18 -0500 Subject: [PATCH 4/4] refactor(logging): one definition of which lanes the #122 halt covers (BACKLOG #122) The /simplify pass on the previous commit. Three callers had grown the same six-line loop over `Stage.INGRESS` / `ROUTED` / `RESPONSE`, each pausing the dispatcher for a set of inbounds: the halt itself (`_halt_inbound_processing`), the fresh dispatchers at start (`_start_pooled_dispatchers` step 2.6), and the reload re-apply (`_reconcile_pooled_dispatchers`). Three copies of "which stages the halt covers" is a fact stated three times, and the failure mode is that a fourth stage is added to one of them. `_pause_internal_lanes` is now the single definition, and each call site keeps only its own reason for calling it. No behaviour change: the helper materialises its argument before iterating, as the halt already did, and every skip condition is unchanged. `_resume_inbound_processing`'s loop is deliberately NOT folded in -- it resumes rather than pauses, and reads the same stage tuple for the opposite reason. Co-Authored-By: Claude Opus 5 --- messagefoundry/pipeline/wiring_runner.py | 40 +++++++++++++----------- 1 file changed, 22 insertions(+), 18 deletions(-) diff --git a/messagefoundry/pipeline/wiring_runner.py b/messagefoundry/pipeline/wiring_runner.py index 1636db12f..b93db6663 100644 --- a/messagefoundry/pipeline/wiring_runner.py +++ b/messagefoundry/pipeline/wiring_runner.py @@ -2494,6 +2494,25 @@ async def _stop_all_for_log_failure(self, *, sink: str, reason: str) -> None: 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. @@ -2521,12 +2540,7 @@ def _halt_inbound_processing(self, names: Iterable[str]) -> None: """ halted = list(names) # materialised: registry.inbound is a live dict we iterate twice self._log_halted.update(halted) - 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) + 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. @@ -3592,12 +3606,7 @@ async def _start_pooled_dispatchers(self) -> None: # 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. - for stage in (Stage.INGRESS, Stage.ROUTED, Stage.RESPONSE): - internal = self._dispatchers.get(stage) - if internal is None: - continue - for n in self._log_halted: - internal.pause_lane(n) + 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() @@ -3761,12 +3770,7 @@ async def _reload_pooled_dispatchers(self, new_registry: Registry) -> None: # 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. - for stage in (Stage.INGRESS, Stage.ROUTED, Stage.RESPONSE): - internal = self._dispatchers.get(stage) - if internal is None: - continue - for n in self._log_halted: - internal.pause_lane(n) + 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