From 26c6f6cb49e252ad571d044e8107554c80654d8b Mon Sep 17 00:00:00 2001 From: Scott Hall Date: Sat, 17 Oct 2026 13:10:39 -0500 Subject: [PATCH] Record a failed inbound TLS handshake on the HTTP intake listener, the API and MLLP under uvloop (BACKLOG #3302, #2613 item 3) Squash of four Builder commits; the pre-squash head 9a24c35fb8a6242a5a4cf5e74fdb993271b9ba65 is kept on branch b291/3302-pre-squash. Their messages follow, with one ASVS cell id removed. Record a failed inbound TLS handshake the event loop runs (BACKLOG #3302, #2613 item 3) Where the loop runs the TLS handshake (asyncio.start_server or loop.create_server with ssl=, uvloop, uvicorn), a failed one never reaches the application, and both loops log it at DEBUG only. So the HTTP intake listener and the API recorded none on any loop, and MLLP none on uvloop. New messagefoundry/tls_handshake_failures.py: - HandshakeFailures: the MLLP listener's counter and throttle (#2613), lifted out so all three surfaces share it. First failure at once, then one report per listener per 60 s with the count. - watch_loop_handshakes: sets the server context's sslobject_class to an SSLObject subclass whose do_handshake reports an ssl.SSLError other than SSLWantReadError/SSLSyscallError, then re-raises. Read in CPython 3.14 asyncio/sslproto.py and uvloop 0.23.0 sslproto.pyx: both build the object with ctx.wrap_bio and drive do_handshake, treating exactly that set as failure. No server or protocol class replaced. Wiring: MLLP installs the hook on the loop-run branch (uvloop) and keeps its own peer-bearing count where it upgrades itself; the HTTP listener emits tls_handshake_failed; the API logs a throttled WARNING, and serve logs the held count once uvicorn returns. Limits, recorded not forced: the hook knows no peer address, so these records name none; a handshake that only runs past its bound is not counted where the loop runs it. A wrong certificate, missing client certificate, downgrade or plaintext all raise and are counted. With [diagnostics].connection_events = false the MLLP and HTTP events are dropped as before (#3299); the in-process counters still count. The API line is a log line and does not depend on that switch. Proposed PR title: Record a failed inbound TLS handshake on the HTTP intake listener, the API and MLLP under uvloop (BACKLOG #3302, #2613 item 3) Proposed vault banner for #3302: CLOSING STEPS 1-3 BUILT (engine branch b291/3302-tls-handshake-record). A failed inbound TLS handshake is counted and recorded, throttled to one record per listener per minute, on the HTTP intake listener (tls_handshake_failed event), the API (WARNING line) and MLLP under uvloop (tls_handshake_failed event). Records the loop ran name no peer; a handshake past its bound is not counted there. Step 4, the vault re-read, is open vault record work. For #2613: open item 3 (the uvloop count) built on the same branch. The ledger was not edited. ----- Fix the handshake throttle's stale timer and the review's doc findings (BACKLOG #3302) code-review xhigh, round 1: - A report due now left an armed trailing timer in place. It could fire a second report inside the new window and lose its handle, so cancel() and flush() at stop() could not reach the next timer. _count now disarms it; the timer has its own callback. - The API line is logged by a plain emitter, at once, so a task that uvicorn's closing loop cancels can no longer lose it. - MLLP and HTTP stop() flush and cancel only while still stopping, so a stop() that resumes after a restart leaves the new run's failures be. - Docs: CONNECTIONS.md Table B said a failed MLLP handshake had no connection event; SECURITY.md said MLLP never runs its allow-list before a failed handshake, false on the stdlib loop (#1606); the changelog claimed every TLS listener (the DICOM SCP still logs at DEBUG only); the console filter comment named MLLP only. - The serve test restores the logger level it found. Proposed PR title: Record a failed inbound TLS handshake on the HTTP intake listener, the API and MLLP under uvloop (BACKLOG #3302, #2613 item 3) Proposed vault banner for #3302: CLOSING STEPS 1-3 BUILT (engine branch b291/3302-tls-handshake-record). A failed inbound TLS handshake is counted and recorded, throttled to one record per listener per minute, on the HTTP intake listener (tls_handshake_failed event), the API (WARNING line) and MLLP under uvloop (tls_handshake_failed event). Records the loop ran name no peer; a handshake past its bound is not counted there. Step 4, the vault re-read, is open vault record work. For #2613: open item 3 (the uvloop count) built on the same branch. The ledger was not edited. ----- Bound the recorder-fault log and tighten the handshake docs and tests (BACKLOG #3302) code-review xhigh, round 2 (the last): - A recorder that fails on every call logged a WARNING per failed handshake; now the first is a WARNING and later ones DEBUG. - The module's list of what the hook cannot see is now "at least" and names wrap_bio faults and wrap_socket contexts (the DICOM SCP). - The counters' docstrings say failures during stop() are not counted. - CONNECTIONS.md no longer says a uvloop handshake logs at DEBUG or frees a slot, and points at PHI.md row 7 instead of restating the throttle; SECURITY.md names build_api_ssl_context instead of a stale line anchor. - The timer test uses a 60 s window, and the API serve test polls the record's count instead of sleeping. Open notes are in the Builder's report for the PR body. Proposed PR title: Record a failed inbound TLS handshake on the HTTP intake listener, the API and MLLP under uvloop (BACKLOG #3302, #2613 item 3) Proposed vault banner for #3302: CLOSING STEPS 1-3 BUILT (engine branch b291/3302-tls-handshake-record). A failed inbound TLS handshake is counted and recorded, throttled to one record per listener per minute, on the HTTP intake listener (tls_handshake_failed event), the API (WARNING line) and MLLP under uvloop (tls_handshake_failed event). Records the loop ran name no peer; a handshake past its bound is not counted there. Step 4, the vault re-read, is open vault record work. For #2613: open item 3 (the uvloop count) built on the same branch. The ledger was not edited. ----- Stub the API context with a real SSLContext in the exposure tests (BACKLOG #3302) serve now watches the API context's handshakes, which sets its sslobject_class. The revocation-gate tests stubbed the context builder with a bare object(), so serve exited 1 there. They now get an empty server SSLContext; the gate, not context building, is still what they test. Found by the full suite on this branch. Proposed PR title: Record a failed inbound TLS handshake on the HTTP intake listener, the API and MLLP under uvloop (BACKLOG #3302, #2613 item 3) Proposed vault banner for #3302: CLOSING STEPS 1-3 BUILT (engine branch b291/3302-tls-handshake-record). A failed inbound TLS handshake is counted and recorded, throttled to one record per listener per minute, on the HTTP intake listener (tls_handshake_failed event), the API (WARNING line) and MLLP under uvloop (tls_handshake_failed event). Records the loop ran name no peer; a handshake past its bound is not counted there. Step 4, the vault re-read, is open vault record work. For #2613: open item 3 (the uvloop count) built on the same branch. The ledger was not edited. ----- --- changelog.d/3302.security.md | 10 + docs/CONNECTIONS.md | 2 +- docs/PHI.md | 2 +- docs/SECURITY.md | 4 +- messagefoundry/__main__.py | 8 +- messagefoundry/api/tls.py | 35 ++ messagefoundry/tls_handshake_failures.py | 248 ++++++++++ messagefoundry/transports/http_listener.py | 27 + messagefoundry/transports/mllp.py | 101 ++-- messagefoundry_webconsole/pages/monitoring.py | 4 +- scripts/security/crypto_inventory_check.py | 9 + tests/test_key_lifecycle_coverage.py | 3 + tests/test_listener_tls_exposure.py | 7 +- tests/test_mllp_tls.py | 10 +- tests/test_tls_handshake_failures.py | 463 ++++++++++++++++++ 15 files changed, 856 insertions(+), 77 deletions(-) create mode 100644 changelog.d/3302.security.md create mode 100644 messagefoundry/tls_handshake_failures.py create mode 100644 tests/test_tls_handshake_failures.py diff --git a/changelog.d/3302.security.md b/changelog.d/3302.security.md new file mode 100644 index 0000000000..44edd1d95b --- /dev/null +++ b/changelog.d/3302.security.md @@ -0,0 +1,10 @@ +- **A failed inbound TLS handshake now leaves a record on the HTTP intake listener, the API and + the MLLP listener, on any event loop.** The DICOM C-STORE SCP still logs one at DEBUG only. + The HTTP intake listener records one as a `tls_handshake_failed` connection event, as the MLLP + listener already did on the standard asyncio loop, and the MLLP listener now does so on uvloop + too, which the engine uses outside Windows. The API logs a WARNING line. Each record is the first + failure at once, then one per listener per minute carrying the count since the last, and names a + count, an exception class and OpenSSL's reason, never the peer's bytes or certificate. Where the + event loop runs the handshake the peer's address is not known, so those records name no peer, + and a handshake that only runs past its time bound is not counted there. + ([BACKLOG #3302](../docs/BACKLOG.md)) diff --git a/docs/CONNECTIONS.md b/docs/CONNECTIONS.md index f8e577880c..198a73096b 100644 --- a/docs/CONNECTIONS.md +++ b/docs/CONNECTIONS.md @@ -3929,7 +3929,7 @@ reading this page already applies to a file the scan never opened. | Service/hop | Timeout setting + default | Release procedure | Failure handling | Retry posture | |---|---|---|---|---| -| MLLP listener (inbound) | `receive_timeout` 60 s bounds an idle read (slow-loris) and `max_frame_seconds` 60 s bounds how long a frame may take to complete, on the clock the `receive_timeout` bullet under [Resource management & limits](#resource-management--limits-asvs-1312--1313--1326) describes, which is what reaches a peer that trickles bytes and is therefore never idle; the ACK **write** carries its own fixed 5 s bound, so a peer that takes the bytes and then stops reading cannot hold the connection either. That write bound is not operator-configurable — an ACK is engine-generated and receipt-sized, so there is no partner-sized body to size a budget against. With `tls = true`, a new connection has a fixed 10 s to finish its TLS handshake or the listener aborts it, and a connection the listener closes has a fixed 5 s for the TLS close exchange (on stop, the socket is closed as soon as its close notice is sent, except under uvloop, below). On the stdlib event loop (always on Windows), `source_ip_allowlist`, `max_connections` and `max_connections_per_host` apply **before** the handshake (BACKLOG #1606): the listener accepts plain TCP, refuses or admits the socket exactly as a plaintext listener does, and only then starts TLS. So a socket still in its handshake holds a real slot, and a peer outside the allowlist never gets a handshake. **Under uvloop the loop still runs the handshake, and all three apply only after it**, so there the handshake bound limits how long such a socket lives, not how many a peer can open. The engine runs on uvloop wherever it is installed, which the engine's own `uvloop` dependency does for CPython outside Windows. Neither TLS bound is operator-configurable: both are engine-fixed work with nothing partner-sized in them | the client handler's outer `finally` closes the writer, with a 5 s shutdown grace; stop also closes a socket still in its TLS handshake. Under uvloop, whose server offers no `close_clients()`, stop leaves such a socket to the 10 s bound and refuses it unread if it finishes the handshake after stop began, and stop can also wait up to the 5 s close-exchange bound for a peer that does not answer its close notice | a TLS handshake over its bound, or one that fails, is aborted with a DEBUG line only and no connection event, and gives its slot back; a decode/parse/validate failure NAKs synchronously and records `ERROR` before any ingress row; a frame over its deadline closes with a `frame_deadline` reason, having received nothing to drop; an ACK over its write bound drops the connection as a `peer_reset`; a fault inside the inbound handler, such as a store outage at the ingress commit, is answered with a fixed-text `AE` (`CE` in enhanced mode), then the connection closes and the event is `handler_error`; an inbound that sends no replies keeps the socket and sends nothing. That NAK has no message row, so the ACK capture stream does not hold it; the `handler_error` event is its record (BACKLOG #1619) | n/a — the sender retries | +| MLLP listener (inbound) | `receive_timeout` 60 s bounds an idle read (slow-loris) and `max_frame_seconds` 60 s bounds how long a frame may take to complete, on the clock the `receive_timeout` bullet under [Resource management & limits](#resource-management--limits-asvs-1312--1313--1326) describes, which is what reaches a peer that trickles bytes and is therefore never idle; the ACK **write** carries its own fixed 5 s bound, so a peer that takes the bytes and then stops reading cannot hold the connection either. That write bound is not operator-configurable — an ACK is engine-generated and receipt-sized, so there is no partner-sized body to size a budget against. With `tls = true`, a new connection has a fixed 10 s to finish its TLS handshake or the listener aborts it, and a connection the listener closes has a fixed 5 s for the TLS close exchange (on stop, the socket is closed as soon as its close notice is sent, except under uvloop, below). On the stdlib event loop (always on Windows), `source_ip_allowlist`, `max_connections` and `max_connections_per_host` apply **before** the handshake (BACKLOG #1606): the listener accepts plain TCP, refuses or admits the socket exactly as a plaintext listener does, and only then starts TLS. So a socket still in its handshake holds a real slot, and a peer outside the allowlist never gets a handshake. **Under uvloop the loop still runs the handshake, and all three apply only after it**, so there the handshake bound limits how long such a socket lives, not how many a peer can open. The engine runs on uvloop wherever it is installed, which the engine's own `uvloop` dependency does for CPython outside Windows. Neither TLS bound is operator-configurable: both are engine-fixed work with nothing partner-sized in them | the client handler's outer `finally` closes the writer, with a 5 s shutdown grace; stop also closes a socket still in its TLS handshake. Under uvloop, whose server offers no `close_clients()`, stop leaves such a socket to the 10 s bound and refuses it unread if it finishes the handshake after stop began, and stop can also wait up to the 5 s close-exchange bound for a peer that does not answer its close notice | a TLS handshake over its bound, or one that fails, is aborted; on the standard asyncio loop with a DEBUG line, giving its slot back, and under uvloop before any slot is taken. A failed one is recorded as a throttled `tls_handshake_failed` connection event on any loop (vault BACKLOG #2613, #3302; PHI.md section 7 row 7 says how). Under uvloop a handshake that only runs past its bound is not counted, and the event names no peer; a decode/parse/validate failure NAKs synchronously and records `ERROR` before any ingress row; a frame over its deadline closes with a `frame_deadline` reason, having received nothing to drop; an ACK over its write bound drops the connection as a `peer_reset`; a fault inside the inbound handler, such as a store outage at the ingress commit, is answered with a fixed-text `AE` (`CE` in enhanced mode), then the connection closes and the event is `handler_error`; an inbound that sends no replies keeps the socket and sends nothing. That NAK has no message row, so the ACK capture stream does not hold it; the `handler_error` event is its record (BACKLOG #1619) | n/a — the sender retries | | MLLP destination | `connect_timeout` 10 s, `timeout_seconds` 30 s (drain + ACK read) | the socket is closed per delivery, or reused and aged out via `idle_timeout_seconds` / `max_connection_age_seconds` when `persistent` | transient errors re-queue; a `NegativeAckError` (AR) dead-letters immediately | `RetryPolicy` — **default `retry_max_attempts` is 100, finite**; lower it, or set `None` to retry forever | | Raw TCP listener (inbound) | `receive_timeout` 60 s bounds an idle read (slow-loris) and `max_frame_seconds` 60 s bounds one frame on the same clock as MLLP's (vault BACKLOG #2606 and #2847), which is what reaches a peer that trickles bytes; the reply **write** carries its own fixed 5 s bound, so a peer that takes the bytes and then stops reading cannot hold the connection either. Not operator-configurable — a reply is engine-generated and receipt-sized, so there is no partner-sized body to size a budget against | as MLLP — handler `finally` closes the socket with a shutdown grace | parse failures record `ERROR` on the ingress path; a reply over its write bound drops the connection as a `peer_reset` | n/a | | X12 listener (inbound) | `receive_timeout` 60 s; `max_frame_seconds` 60 s bounds how long one interchange may take to complete, on the same clock as MLLP's (vault BACKLOG #2606); `max_interchange_bytes` bounds one ISA/IEA frame; the reply **write** carries its own fixed 5 s bound, so a peer that takes the bytes and then stops reading cannot hold the connection either. Not operator-configurable, for the same reason as the raw-TCP row | as MLLP — handler `finally` closes the socket with a shutdown grace | parse failures record `ERROR` on the ingress path; an allow-list refusal emits `peer_not_allowlisted` plus a WARNING log, and a capacity refusal emits `at_capacity`; a reply over its write bound drops the connection on a logged warning **and** the `peer_reset` its release path already carries. This listener emits the same seven kinds as the raw-TCP row above (BACKLOG #1665) | n/a | diff --git a/docs/PHI.md b/docs/PHI.md index aa9b1f985d..7c95bcbdaa 100644 --- a/docs/PHI.md +++ b/docs/PHI.md @@ -1810,7 +1810,7 @@ with materially different PHI profiles, so they get their own rows; stream 4 is | **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 ALLOW, non-enforcing WARN, **enforcing REFUSE (exit 2)** — there is no synthetic arm, and [ADR 0186](adr/0186-retire-the-synthetic-data-declaration-every-instance-carries-patient-data.md) left this cell with no per-hop way to accept the risk at all | the collector's, not the engine's | the identical four filters are installed on this handler. So the forwarded copy gets the same best-effort PHI redaction and credential scrub as stdout. A single-token identifier can survive it, as it can there. The copy also 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`, 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), and `reply_dropped`, a delivery whose 2xx reply body was over the byte bound and dropped (the status and the bound only, vault BACKLOG #3040) (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` / `reply_dropped` | 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`, `reply_dropped` 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; `reply_dropped` is the one row that answers "you ignored our reply", for the same reason) | -| **7. `connection_event` table — DEFAULT ON** (`[diagnostics].connection_events = true`) | transport/lifecycle events per connection: `established`, `closed` (reason `eof`, `idle_timeout` or `frame_deadline` — a fixed vocabulary chosen by the listener, never free text), `idle_timeout`, `at_capacity`, `peer_not_allowlisted`, `frame_oversize`, `framing_error`, `peer_reset`, the MLLP listener's `handler_error` (BACKLOG #1619 -- the inbound handler faulted on a frame the listener read cleanly, such as a store outage at the ingress commit; the reason is scrubbed at the source like every other), the MLLP listener's `tls_handshake_failed` (vault BACKLOG #2613 -- a TLS handshake on a listener that runs its own handshakes (the standard asyncio loop, not uvloop) failed; the first at once, then one per listener per minute carrying the count since the last, and the reason is a count and an exception class name, never the peer's bytes), the DATABASE poll source's `row_undecodable` (BACKLOG #1662 — a polled row the source cannot turn into a body; the reason is scrubbed at the source and names the exception type or the operator's own configured column, never a row value), the FILE poll source's quarantine kinds `file_oversize` / `file_decompress_failed` / `file_content_mismatch` / `file_scan_rejected` (BACKLOG #1621 — a drop moved to `.error`; the reason is a size, a content type or a scrubbed codec or scanner message, never the file name), 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, X12 and HTTP listeners emit these; the **DATABASE poll source** emits `row_undecodable` and nothing else (it dials out, so there is no lifecycle to report and its rows carry a **NULL peer column**); the **FILE poll source** emits only its four quarantine kinds, also with a NULL peer column; the **DICOM inbound C-STORE SCP** emits none — the runner injects the sink onto **every** source (`wiring_runner.py`, over the base-class `on_connection_event` field), so that connector *has* the wiring and simply never calls it — so this stream covers those four listeners plus those poll-source events and the runner's outbound-lane transitions — not literally every connection. A DICOM association's connects and refusals are therefore **absent** from this stream. The **`ISA`/`IEA`-framed X12 inbound** was equally absent until BACKLOG #1665 and is not any more: it emits the same seven kinds as the raw-TCP listener | 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. `reason` alone is gated on `messages:view_summary` and masked as `****` until the audited per-event `reveal=` act (BACKLOG #2443; the `connection_event.reason` row of §3's PL-2 block says how) | `[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, limit=200)` at the store (the bound §3's PL-2 block states) — 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 | +| **7. `connection_event` table — DEFAULT ON** (`[diagnostics].connection_events = true`) | transport/lifecycle events per connection: `established`, `closed` (reason `eof`, `idle_timeout` or `frame_deadline` — a fixed vocabulary chosen by the listener, never free text), `idle_timeout`, `at_capacity`, `peer_not_allowlisted`, `frame_oversize`, `framing_error`, `peer_reset`, the MLLP listener's `handler_error` (BACKLOG #1619 -- the inbound handler faulted on a frame the listener read cleanly, such as a store outage at the ingress commit; the reason is scrubbed at the source like every other), the MLLP and HTTP listeners' `tls_handshake_failed` (vault BACKLOG #2613 and #3302 -- an inbound TLS handshake failed, on any event loop; the first at once, then one per listener per minute carrying the count since the last. The reason is a count, an exception class name and OpenSSL's reason mnemonic, never the peer's bytes or certificate. The event names a peer only where the MLLP listener runs its own handshakes, which is the standard asyncio loop; where the loop runs them, which is uvloop and every HTTP listener, the peer is not known, and a handshake that only runs past its bound is not counted), the DATABASE poll source's `row_undecodable` (BACKLOG #1662 — a polled row the source cannot turn into a body; the reason is scrubbed at the source and names the exception type or the operator's own configured column, never a row value), the FILE poll source's quarantine kinds `file_oversize` / `file_decompress_failed` / `file_content_mismatch` / `file_scan_rejected` (BACKLOG #1621 — a drop moved to `.error`; the reason is a size, a content type or a scrubbed codec or scanner message, never the file name), 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, X12 and HTTP listeners emit these; the **DATABASE poll source** emits `row_undecodable` and nothing else (it dials out, so there is no lifecycle to report and its rows carry a **NULL peer column**); the **FILE poll source** emits only its four quarantine kinds, also with a NULL peer column; the **DICOM inbound C-STORE SCP** emits none — the runner injects the sink onto **every** source (`wiring_runner.py`, over the base-class `on_connection_event` field), so that connector *has* the wiring and simply never calls it — so this stream covers those four listeners plus those poll-source events and the runner's outbound-lane transitions — not literally every connection. A DICOM association's connects and refusals are therefore **absent** from this stream. The **`ISA`/`IEA`-framed X12 inbound** was equally absent until BACKLOG #1665 and is not any more: it emits the same seven kinds as the raw-TCP listener | 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. `reason` alone is gated on `messages:view_summary` and masked as `****` until the audited per-event `reveal=` act (BACKLOG #2443; the `connection_event.reason` row of §3's PL-2 block says how) | `[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, limit=200)` at the store (the bound §3's PL-2 block states) — 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`, `storage_threshold`, `cert_expiry`, `secret_rotation`, `initial_credential_expiring` (an UNCLAIMED admin-issued temporary password nearing the instant the login gate stops accepting it -- ASVS 6.4.5, BACKLOG #1141; keyed on `user:`, and the payload is the ISO deadline plus whole hours remaining, repeated in the reason column, never the password), `integrity_drift`, `update_available`, `backup_failed`, `store_privilege_warning` (the store privilege preflight found the store principal over-granted or could not read it -- BACKLOG #305; the payload is the finding, a count and the preflight's summary line, which names the login, the database and role names, never a password or message content), `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), `log_forward_failed` (the off-box log forwarder is absent, losing records or not sending -- BACKLOG #2612; keyed on `forwarder:`, with `@node:` or `@shard:` appended when several engine processes share the store, and the payload is that key, fixed reason words and a count, never a record, the collector's address or an error text; an unpinned cluster node's `node_id` holds this engine's own host name and process id, so the key carries them), `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), `approval_stale_requester` (a dual-control release refused because the requester no longer holds the authority the operation needs -- ASVS 8.3.2, BACKLOG #289; keyed on the approval id, and the payload is that id, the operation key and a closed-set reason slug, never the requester's name or the captured params), `approval_too_early` (a dual-control release refused because it arrived before `[approvals].min_dwell_seconds` -- ASVS 2.4.2, BACKLOG #287; keyed on `approval:`, and the payload is that key, the operation key and a fixed reason string, never the approver's or requester's name or the captured params), `audit_write_failed` (the approval gate could not write one of its audit rows -- vault BACKLOG #2255; keyed on `approval:`, or on `config_reload:inline` when an ungated config reload could not write its `config_reload_attempted` row -- vault BACKLOG #2254; the payload is that key and the lost row's audit action name, never the row's detail, a username or the captured params; the ERROR log line beside it holds the detail on some paths and only the exception on others), `ad_reconcile_aborted` (a directory reconciler pass left signed-in accounts unrevoked and needs an operator: the mass-revoke breaker tripped and nothing was revoked, or one or more probes were answered with an LDAP referral and those accounts were left unjudged while the rest of the pass was applied, BACKLOG #2538, or one or more probes raised a fault the engine could not read and those accounts were left unjudged the same way, BACKLOG #3100; the payload is a fixed source label, `directory-reconciler` for the breaker, `directory-reconciler-referral` for a referral and `directory-reconciler-probe-fault` for a probe fault so each is its own instance, the closed-set reason slug `mass_revoke_breaker`, `directory_referral` or `probe_fault`, the probed count and the latched operator explanation, never a username), `ad_reconcile_held` (the reconciler is holding accounts whose `userAccountControl` it cannot read, ADR 0195; the payload is the same fixed source label, a closed-set reason slug, the count of undetermined accounts and the latched operator explanation, never a username), `ad_session_revoked` (the reconciler revoked a directory principal's sessions; keyed on that operator account's username, with a `directory_absent`, `directory_disabled`, `directory_undetermined`, `roles_changed` or `scope_changed` reason), `approval_approver_provenance` (a dual-control release, or the resolution of an interrupted one, went ahead with an approver or resolver account created, re-passworded or TOTP-enrolled after the request -- BACKLOG #315, #2125; keyed on `approval:`, or `approval::resolve` for a resolution, and the payload is the operation key and the closed-set change slugs, never a username or the captured params), `administrator_granted` (the built-in Administrator role was granted by account creation, a role change, a directory group newly mapped to it -- BACKLOG #315 -- or a directory sign-in whose role sync newly gave the account the role -- vault BACKLOG #2610; keyed on `user:` or `ad-group:`, with the grant route and the granting administrator's username, or `` for a directory sign-in), `no_enabled_administrator` (a directory sign-in's role sync or the session reconciler took Administrator from its last enabled holder -- vault BACKLOG #3229; keyed on `user:`, and the payload is `via`, `ad-sync` or `ad-reconcile`, and a fixed reason sentence, never message content), `intake_paused` (the engine paused intake because the staged backlog went over `[inbound].max_staged_depth` or the SQLite volume fell below `[retention].min_free_disk_mb` -- BACKLOG #290; keyed on `intake:staged_depth` or `intake:disk_floor`, with `@node:` or `@shard:` appended when several engine processes share the store (BACKLOG #2272), and the payload is the reason, a count or a MiB figure, its limit and the store backend's name, never message content), `config_changed` (a start loaded a config whose fingerprint differs from the store's baseline -- vault BACKLOG #2597; keyed on `config:`, and the payload is the two digests, the node and engine shard labels, and the action, actor username and time of the row the older digest came from, never the config directory, a git commit or message content), `crl_reload_refused` (the CRL reload refused a replaced CRL file, so running TLS contexts keep the copy they hold -- vault BACKLOG #2904; keyed on `crl_reload:`, with `@node:` or `@shard:` appended when several engine processes share the store, and the payload is that key, the file's path, a short class token for the remedy, a count of contexts, the engine's own fixed remedy sentence and, when a start would refuse the file too, a `start_refuses` flag, never the refusal's reason, which quotes CRL issuer names and dates; that reason is in the application log, and in the `detail` of the CRL expiry alert once the held copy nears its `nextUpdate`), `remote_debug_refused` (the engine's remote-debugging guard refused scripts that another process injected into the engine process -- vault BACKLOG #2742; keyed on `remote_debug:refused`, with `@node:` or `@shard:` appended when several engine processes share the store, and the payload is that key, the count of scripts refused since the alert was last raised, the count since the process started and a fixed sentence built from the two, never a script's file name, which the injecting process chooses; that name is in the application log, in the guard's WARNING line), `sandbox_worker_refused` (a `[sandbox].mode = "subprocess"` worker was refused because the graph it loaded differs from the engine's, most often a config file edited on disk with no reload -- vault BACKLOG #2724; keyed on the inbound's name, raised once per refusal, and the payload is that name and a fixed sentence naming the cause and the remedy, never a message body or the refusal text, which names config names and digests and is in the application log), and the six security signals of the audit-stream rule layer -- vault BACKLOG #2613: `signin_failure_burst` (keyed on `signin:`, never the typed username), `access_denied_burst`, `body_view_burst` and `bulk_export` (each keyed on `account:`), `log_level_debug` (keyed on `logging:debug`) and `posture_loosened` (keyed on `posture:start`); the payload is a count and a fixed sentence holding a level name, switch names or a username, never a message body, a message id or an audit row's detail. The reachable **inverse** signals — `connection_restored`, `leadership_lost`, `dr_released`, `store_privilege_clean`, `intake_resumed`, `crl_reload_applied` (it resolves `crl_reload_refused` for the same file on the same engine process, once the reload's record no longer holds the refusal, and when the reload stops -- vault BACKLOG #2904), `ad_reconcile_breaker_cleared`, `ad_reconcile_hold_released` (the last two resolve `ad_reconcile_aborted`, under the breaker's or the referral's source but never the probe fault's, which has no inverse, and `ad_reconcile_held`; when they do, and where they never do, is stated once in [CONFIGURATION.md](CONFIGURATION.md#when-the-reconcilers-two-alerts-resolve-themselves) -- BACKLOG #2136) — are never rows here: `_record_state` routes an inverse through `_AUTO_RESOLVE` to `resolve_alert_instances_for`, never to `upsert_alert_instance`. (One more 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, and `reason` alone gated on `messages:view_summary` and masked as `****` until the audited per-alert `reveal=` act (BACKLOG #2443; the `alert_instance.reason` row of §3's PL-2 block says how); 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`: `safe_text(reason, limit=200)` (the bound §3's PL-2 block states) 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). | | **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` and `messages:view_summary`; 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, held to the 200-character bound §3's PL-2 block states, 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 | diff --git a/docs/SECURITY.md b/docs/SECURITY.md index 5515eb5115..0d5fb92fa3 100644 --- a/docs/SECURITY.md +++ b/docs/SECURITY.md @@ -3456,7 +3456,7 @@ slack. | Instance environment posture × claimed AI data scope | `[ai].derived_posture()` (from `[ai].environment` and `[security].production_instance`; an unresolved posture defaults to the **strictest** ceiling) re-resolved server-side through `resolve_effective_policy` on every `POST /ai/chat` | the effective mode is not `managed_endpoint`, or the request's `data_scope` exceeds the server-enforced ceiling (the engine-broker MVP enforces `code_only` regardless of what the caller claims) | **DENY** — **409** on the mode mismatch, **403** on scope excess; each audited `ai.assist` with PHI-safe metadata only | `mode = byo`, `data_scope = code_only` | `[ai].mode`, `[ai].data_scope`, `[ai].environment`, `[security].production_instance` | | Gated operation × requester-vs-approver identity × hold age | the pending-approval record: the operation name, the requesting identity, and the hold's creation time | `[approvals].enabled` **and** the operation is in `[approvals].operations` and has no approved unexpired release; the approver is the requester; the hold is older than `expiry_hours`; the hold is younger than `min_dwell_seconds` | **DENY** the immediate execution — **202** hold + `approval.requested` audit; the same **202** and id + `approval.request_repeated` audit for the same requester's repeat of an open hold; **403** on self-approval; **409** once expired or already decided; **409** + `approval.too_early` audit while younger than the floor (the hold stays pending); **409** + `approval.no_longer_gated` audit once dual control no longer gates the operation (the hold stays pending) | off; `['connection_purge','dead_letter_replay']`; 72 h; 2 s | `[approvals].enabled`, `operations`, `expiry_hours`, `min_dwell_seconds` | | mTLS client-certificate subject | the subject DN of the loaded CA certificate whose key directly signed the peer certificate, and the peer's qualified subject-RDN / SAN names | exact match of the name under the map entry for that verifying CA's DN (BACKLOG #2237), in a deny-by-default map (empty map = feature off). The same subject from another CA matches nothing. A client-sent intermediate, and two loaded CAs sharing one DN with different keys, name no issuer | **ALLOW** — resolve the mapped account **id** (BACKLOG #2238; never a username, which a rename can hand to another account) to its Identity (RBAC then authorizes); an unknown or disabled account grants none. A directory account is also asked about in the directory on every request and fails closed: anything short of a present, enabled account grants none, and the Identity keeps only the stored roles and channels its current groups still map to. One exception: when none of its groups is in the scope map, a scope an administrator set stays as stored (BACKLOG #2316) | `{}` = off | `[api].tls_client_cert_identities` (requires `tls_client_ca_file`) | -| Operator-listener peer client certificate | the TLS peer certificate presented at the API / `/ui` handshake | `[api].tls_client_ca_file` set (requires `tls_cert_file`) → `ssl.CERT_REQUIRED` plus strict RFC 5280 verify flags (`api/tls.py:47-50`); no client certificate, or one not issued by that CA | **DENY** — the TLS handshake fails, so the request never reaches the ASGI stack at all: no middleware runs, no route matches, no identity is resolved, and no 403 body is produced | unset = off (server-only TLS, no peer-certificate decision on the control plane) | `[api].tls_client_ca_file` | +| Operator-listener peer client certificate | the TLS peer certificate presented at the API / `/ui` handshake | `[api].tls_client_ca_file` set (requires `tls_cert_file`) → `ssl.CERT_REQUIRED` plus strict RFC 5280 verify flags (`build_api_ssl_context` in `api/tls.py`); no client certificate, or one not issued by that CA | **DENY** — the TLS handshake fails, so the request never reaches the ASGI stack at all: no middleware runs, no route matches, no identity is resolved, and no 403 body is produced. The failure is logged as a WARNING, the first at once and then one a minute carrying the count, naming no peer (vault BACKLOG #3302) | unset = off (server-only TLS, no peer-certificate decision on the control plane) | `[api].tls_client_ca_file` | | Declared token class of a federated assertion | the `typ` JOSE header, and the presence of an `events` claim, on a **signature-verified** JWS | `typ` present and — normalised `.strip().lower()` then `application/`-stripped — not `jwt`, so `at+jwt` (RFC 9068 access token), `logout+jwt` and `secevent+jwt` are refused while an **absent** `typ` is allowed (RFC 7519 §5.1 makes the header advisory); or the claim set carries `events`, i.e. an RFC 8417 security event token. Every such token is minted by the **same issuer under the same key**, so no signature or key rung distinguishes it | **DENY** the sign-in — `ClaimsError("wrong_token_type")` at the key-selection rung, `ClaimsError("unexpected_events_claim")` ahead of the nonce compare (a logout token carries no nonce, so a later check would misreport it as a browser-binding failure) | on | (no knob) | | Federated authentication-context claims (`amr` / `acr`) | the `amr` list / `acr` string of a **signature-verified** `id_token` | `oidc_require_mfa_claim` on **and** neither an `amr` value in `[auth].oidc_mfa_amr_values` (default `["mfa"]`) nor an `acr` in `oidc_required_acr_values` (default `[]`, so the `amr` arm alone decides) | **DENY** the sign-in — `ClaimsError("mfa_claim_missing")`. An IdP **assertion**, never a proof | on, `["mfa"]` / `[]` | `[auth].oidc_require_mfa_claim`, `oidc_mfa_amr_values`, `oidc_required_acr_values` | | Time since the IdP authentication event | the `auth_time` of a **signature-verified** `id_token`, requested by the `max_age` the engine sends on **every** authorization request (OIDC Core makes `auth_time` REQUIRED once `max_age` is sent) | `auth_time` absent or null; or older than `[auth].oidc_max_age_seconds` (no clock-skew grace on this side, so no session is minted already dead); or further in the future than the clock skew. A conforming IdP re-authenticates only when its own sign-in is older than `max_age`, so single sign-on is untouched for every user inside the window | **DENY** the sign-in — `ClaimsError("auth_time_missing")` / `("auth_time_stale")` (a future value is `issued_in_future`). An accepted sign-in is also capped: the session ends at `auth_time + oidc_max_age_seconds` if that is sooner than `id_token.exp` and the absolute cap. There is **no off switch**: `0` and any value outside the documented range ([CONFIGURATION.md](CONFIGURATION.md)) are refused at load, and omitting the key gives the default. An IdP that does not return `auth_time` refuses **every** federated sign-in. `auth_time` is IdP wall clock, so the bound is only as good as the IdP's clock | 43200 s (12 h) | `[auth].oidc_max_age_seconds` | @@ -3506,7 +3506,7 @@ listen source. The refusal action differs materially per listener, so each has i | **X12** | peer socket address | not in `source_ip_allowlist` | **DENY** — as MLLP (refuse, log, `peer_not_allowlisted` event); BACKLOG #1665 | | **HTTP** | peer socket address | not in `source_ip_allowlist` | **DENY** — a real `403 {"error":"forbidden"}` is written to the peer, then close; WARNING log + `peer_not_allowlisted` event | | **DICOM C-STORE SCP** | peer socket address at accept; `event.assoc.requestor.address` in the C-STORE backstop | not in `source_ip_allowlist` | **DENY** — the connection is closed at accept, before any TLS handshake or association; WARNING log naming the peer IP, at most one line per address per 60 s and at most 20 addresses per 60 s in all; **no connection event**. The backstop answers DIMSE status **`0x0124` (Not Authorized)** **before any durable commit** and logs each refusal with the calling AE; [DICOM.md](DICOM.md) section 3 says why a sender should not see it | -| **MLLP / HTTP / DICOM** — peer client certificate | the TLS peer certificate presented at handshake | `tls = true` **and** `tls_ca_file` set → `ssl.CERT_REQUIRED` plus strict RFC 5280 verify flags; no client certificate, or one not issued by that CA | **DENY** — the TLS handshake fails. On MLLP and HTTP the connection **never reaches the accept path**, so there is **no** connection event and no allow-list evaluation. The DICOM SCP accepts the connection first, checks its allow-list, and only then runs the handshake, so a peer outside the list is refused before any handshake; a failed handshake writes **no** connection event there either. `tls_ca_file` unset → server-only TLS and no peer-certificate decision. TCP and X12 have no inbound TLS at this release | +| **MLLP / HTTP / DICOM** — peer client certificate | the TLS peer certificate presented at handshake | `tls = true` **and** `tls_ca_file` set → `ssl.CERT_REQUIRED` plus strict RFC 5280 verify flags; no client certificate, or one not issued by that CA | **DENY** — the TLS handshake fails. On HTTP, and on MLLP where the event loop runs the handshake (uvloop), the connection **never reaches the accept path**, so there is no allow-list evaluation. On MLLP on the standard asyncio loop the allow-list and both connection caps run BEFORE the handshake (BACKLOG #1606). Either way the only connection event is a throttled `tls_handshake_failed`: the first failure at once, then one per listener per minute with the count (vault BACKLOG #2613, #3302). The DICOM SCP accepts the connection first, checks its allow-list, and only then runs the handshake, so a peer outside the list is refused before any handshake; a failed handshake writes **no** connection event there either. `tls_ca_file` unset → server-only TLS and no peer-certificate decision. TCP and X12 have no inbound TLS at this release | | **HTTP** — intake authentication (`intake_auth`, ADR 0154 D6) | the credential a peer presents: the `intake_api_key_header` header (default `x-api-key`) under `api_key`, `Authorization: Bearer` under `bearer`, or the verified client certificate's `CN:` / `SAN:` names under `mtls_subject` | `intake_auth` is not `none` and the key or token is missing or wrong, or the certificate's names are not in `intake_client_subjects`. **The default is `intake_auth = "none"`, which checks no credential: a default HTTP inbound admits any peer the rows above admit.** Under `api_key` / `bearer`, `GET`/`HEAD` probes are inside the check unless `intake_auth_health = "allow"`. Under `mtls_subject` the certificate is checked at accept, before the method is known, so no probe is exempt. A peer with no certificate from `tls_ca_file` never reaches this row: it fails the handshake in the peer-client-certificate row above | **DENY** — `401` for a missing or wrong key or token (read before any body byte), `400` for a credential header sent more than once, even with identical copies, and with `_` read as `-` in the header name, since the engine would keep the last copy while a front end may read the first (BACKLOG #2051; refused before any comparison, charged to the failed-attempt budget and audited `intake.auth_failed`), `403` for a verified certificate with an unlisted subject; nothing is committed. Audited `intake.auth_failed` / `intake.auth_subject_denied`, plus a connection event | | **HTTP** — intake failed-attempt budget (ADR 0154 D6) | the peer address, and the listener's failed-attempt count across all peers | the peer has spent `intake_auth_rate_limit` failed attempts in the window, or all peers together have spent `intake_auth_rate_limit_global` (defaults and the `0`/`None` off switch in [CONNECTIONS.md](CONNECTIONS.md)). A peer that authenticated inside the window is exempt from the global budget, so a flood cannot lock out a working partner. Counted in-process, so each engine shard keeps its own count | **THROTTLE** — `429` + `Retry-After: 60` before any credential is compared; audited `intake.auth_rate_limited`. A successful authentication never spends budget | | **HTTP** — peer-control start gate (ADR 0154 D7) | the listener's bind host × the presence of an **effective** peer control | non-loopback bind, `[security].enforcement = enforce` (the default), and **no** effective peer control: `intake_auth` is `none`, and `source_ip_allowlist` is unset or has an entry wider than a /8 (IPv4) or a /32 (IPv6), so `0.0.0.0/0` does not count. `tls` + `tls_ca_file` alone does not count either, because it binds no subject | **DENY at start** (`WiringError`); the connection degrades per ADR 0031 startup fault isolation. Loopback binds are exempt | diff --git a/messagefoundry/__main__.py b/messagefoundry/__main__.py index 804ffb067f..ea291863a1 100644 --- a/messagefoundry/__main__.py +++ b/messagefoundry/__main__.py @@ -4666,8 +4666,9 @@ def registry_filter(reg: Registry) -> Registry: # noqa: F811 (local shard-bound "ws": floored_ws, "timeout_graceful_shutdown": _UVICORN_DRAIN_SECONDS, # BACKLOG #3256; see the constant } - from messagefoundry.api.tls import build_api_ssl_context + from messagefoundry.api.tls import ApiHandshakeRecord, build_api_ssl_context + api_handshakes: ApiHandshakeRecord | None = None if _material is not None: _cert, _key = _material # _key is None when the operator embedded the private key in the cert PEM (tls_key_file is @@ -4688,6 +4689,8 @@ def registry_filter(reg: Registry) -> Registry: # noqa: F811 (local shard-bound print(f"error: {exc}", file=sys.stderr) return 2 run_kwargs["ssl_context_factory"] = lambda config, default_factory: ctx + # Vault BACKLOG #3302: the loop runs every API handshake, so a failed one left no record. + api_handshakes = ApiHandshakeRecord(ctx) # ADR 0083 activation: only when in-process mTLS (client CA) AND a cert-identity map are BOTH # configured, swap in the scope-populating HTTP protocol so a verified peer cert reaches # resolve_client_cert_identity. Gated on both so a mutual-auth-only bind (console mTLS, no map) @@ -4715,6 +4718,9 @@ def registry_filter(reg: Registry) -> Registry: # noqa: F811 (local shard-bound except Exception as exc: # last-resort: log an abnormal server exit PHI-redacted, then re-raise logging.getLogger(__name__).critical("server exited abnormally: %s", safe_exc(exc)) raise + finally: + if api_handshakes is not None: + api_handshakes.close() return 0 diff --git a/messagefoundry/api/tls.py b/messagefoundry/api/tls.py index 42e1503593..677194f2ee 100644 --- a/messagefoundry/api/tls.py +++ b/messagefoundry/api/tls.py @@ -37,6 +37,7 @@ ) from messagefoundry.keywrap import load_checked_cert_chain from messagefoundry.redaction import log_timestamp +from messagefoundry.tls_handshake_failures import HandshakeFailures, watch_loop_handshakes if TYPE_CHECKING: from messagefoundry.pki import SelfSignedFacts @@ -44,6 +45,7 @@ __all__ = [ "GENERATED_PAIR_REPLACED", + "ApiHandshakeRecord", "ApiTlsPlan", "ApiTlsSource", "GeneratedPairReplaced", @@ -124,6 +126,39 @@ def build_api_ssl_context(api: ApiSettings, *, enforcing: bool = True) -> ssl.SS return ctx +class ApiHandshakeRecord: + """A throttled WARNING line for each failed TLS handshake on the API (vault BACKLOG #3302). + + uvicorn hands the context to the loop, which runs every handshake and records a failed one at + DEBUG at most, so before #3302 nothing an operator reads showed a peer failing them again and + again. The API has no connection to carry an event, so the record is a log line: the first + failure at once, then one per minute carrying the count since the last. It names the count and + a cause, never the peer's bytes or certificate; the peer's address is not known where the hook + runs (see :mod:`messagefoundry.tls_handshake_failures`). Serve calls :meth:`close` once uvicorn + returns, so what the trailing line still held is logged rather than lost with the loop. + """ + + def __init__(self, ctx: ssl.SSLContext) -> None: + # A plain emitter, so a line is logged at once and never waits on a task that uvicorn's + # closing loop could cancel before it ran. + self.failures = HandshakeFailures(_log_api_handshake_failures) + watch_loop_handshakes(ctx, self._note) + + def _note(self, cause: str) -> None: + self.failures.note_soon(None, cause) + + def close(self) -> None: + """Disarm the trailing line and log what it still held. Needs no running loop.""" + self.failures.cancel() + held = self.failures.take_held() + if held is not None: + _log_api_handshake_failures(*held) + + +def _log_api_handshake_failures(_peer_host: str | None, reason: str) -> None: + log.warning("TLS handshake failed on the API listener: %s", reason) + + def _attach_issuer_index(ctx: ssl.SSLContext, cadata: str, cert_map: Mapping[str, object]) -> None: """Index the loaded client CAs on ``ctx`` for the mTLS shim, and say which map keys cannot match. diff --git a/messagefoundry/tls_handshake_failures.py b/messagefoundry/tls_handshake_failures.py new file mode 100644 index 0000000000..8ab0c874a3 --- /dev/null +++ b/messagefoundry/tls_handshake_failures.py @@ -0,0 +1,248 @@ +# SPDX-License-Identifier: AGPL-3.0-or-later +# Copyright (C) 2026 MessageFoundry Foundation, LLC and contributors +"""Count failed inbound TLS handshakes and report them, throttled (vault BACKLOG #2613, #3302). + +Two parts, shared by the MLLP listener, the HTTP intake listener and the API: + +* :class:`HandshakeFailures` is the counter and the throttle, one per listener. It was the MLLP + listener's own until #3302 lifted it here. The first failure is reported at once. Later ones + inside :data:`EVENT_SECONDS` are held, and one trailing report at the window's end says how many, + so a peer that fails handshakes as fast as it connects writes one row a minute, not one per try. +* :func:`watch_loop_handshakes` sees a failure the EVENT LOOP had, where no listener code runs. + +**Why the second part exists.** Where the loop runs the handshake, through +``asyncio.start_server(ssl=...)`` or ``loop.create_server(ssl=...)`` as uvicorn calls it, a failed +handshake never reaches the application: its protocol is built but never connected. The stdlib +loop logs the failure at DEBUG, and uvloop at DEBUG too (0.23.0 ``sslproto.pyx``, +``_fatal_error``), and the loop's exception handler is called only in debug mode. So the HTTP intake +listener and the API had no record on any loop, and the MLLP listener none on uvloop, which the +engine installs outside Windows. + +**The hook is the context's ``sslobject_class``.** Both loops build the TLS object for every +connection through ``SSLContext.wrap_bio`` (CPython 3.14 ``asyncio/sslproto.py``; uvloop 0.23.0 +``sslproto.pyx`` ``_start_handshake``), which instantiates ``sslobject_class``, and both drive it +with ``do_handshake()``. Both treat any ``ssl.SSLError`` from it as a failed handshake except +``SSLWantReadError`` and ``SSLSyscallError``, which they read as "call again". The subclass reports +exactly that set and re-raises unchanged, so the loop's own handling does not move. No server or +protocol class is replaced. + +**What it cannot see, at least, stated so it is not over-read.** + +* **The peer's address.** A TLS object holds two memory buffers and no socket, so these reports + name no peer. A trailing report for several failures names none anyway. +* **A handshake past its bound.** The loop aborts the transport and never calls ``do_handshake`` + again, so nothing raises. Where the MLLP listener runs its own handshakes, the stdlib loop, it + still counts that case itself. Elsewhere a peer that opens sockets and stays silent is not + counted. A wrong certificate, a missing client certificate, a protocol downgrade and plaintext on + a TLS port all raise, so all are counted. +* **A peer that hangs up mid-handshake.** Not counted, deliberately, as on MLLP since #2613: that is + what a load balancer's TCP health check does. +* **A failure outside ``do_handshake``**, such as one in ``wrap_bio`` itself, and any context driven + through ``wrap_socket`` rather than by an event loop, which is how the DICOM SCP runs its + handshakes. + +Stdlib only, so the API can import it without pulling in a transport. +""" + +from __future__ import annotations + +import asyncio +import logging +import re +import ssl +import time +from collections.abc import Callable, Coroutine +from typing import Any + +__all__ = [ + "EVENT_SECONDS", + "HandshakeFailures", + "handshake_cause", + "watch_loop_handshakes", +] + +logger = logging.getLogger(__name__) + +# Whether a fault in a recorder has been logged at WARNING yet. Later ones go to DEBUG, so a recorder +# that fails on every call cannot turn a handshake flood into the log flood the throttle prevents. +_recorder_fault_logged = False + +#: Seconds between two reports from one listener. Per listener, not per peer: the peer's address +#: is the caller's choice, so a per-peer window would let one host rotating addresses write a row +#: per address. +EVENT_SECONDS = 60.0 + +#: What both event loops treat as "call do_handshake again" rather than as a failed handshake. The +#: same tuple as CPython's ``asyncio.sslproto.SSLAgainErrors`` and uvloop's ``ssl_SSLAgainErrors``. +_AGAIN = (ssl.SSLWantReadError, ssl.SSLSyscallError) + +#: An OpenSSL reason mnemonic such as ``WRONG_VERSION_NUMBER``. Matched in full before it is kept, +#: so a cause can never carry anything a peer chose. +_REASON = re.compile(r"[A-Z0-9_]{1,64}") + + +def handshake_cause(exc: BaseException) -> str: + """The exception's class name, then OpenSSL's reason mnemonic when it has one. + + The mnemonic is what tells a downgrade (``UNSUPPORTED_PROTOCOL``) from a wrong certificate + (``TLSV1_ALERT_UNKNOWN_CA``) or plaintext on a TLS port (``HTTP_REQUEST``). It comes from + OpenSSL's fixed table, never from the peer's bytes, and is kept only if it looks like one. + """ + name = type(exc).__name__ + reason = getattr(exc, "reason", None) + if isinstance(reason, str) and _REASON.fullmatch(reason): + return f"{name} {reason}" + return name + + +class HandshakeFailures: + """One listener's failed-handshake counter and its throttled report. + + ``emit(peer_host, reason)`` sends one report: a coroutine function for a connection event, or a + plain function for a log line, which then runs at once rather than on a task a closing loop + could cancel. A report for one failure names its peer; a report for several names none, since + they may come from many peers. The reason is a count and a cause from :func:`handshake_cause`, + never the peer's bytes. + """ + + def __init__( + self, + emit: Callable[[str | None, str], Coroutine[Any, Any, None] | None], + *, + window: float = EVENT_SECONDS, + ) -> None: + self._emit = emit + self._window = window + #: Failed handshakes seen since this object was built. + self.count = 0 + # The count already reported, and when that report went. + self._reported = 0 + self._reported_at: float | None = None + # The latest failure's peer and cause, the trailing report's timer, and its tasks. + self._last: tuple[str | None, str] = (None, "") + self._timer: asyncio.TimerHandle | None = None + self._tasks: set[asyncio.Task[None]] = set() + + def _count(self, peer_host: str | None, cause: str) -> bool: + """Count one failure; True when a report is due now, else arm the trailing timer. + + A report due now also carries whatever a trailing timer held, so that timer is disarmed + here. Left armed, it could fire a second report inside the new window, since asyncio runs + a due I/O callback before a due timer in the same loop iteration.""" + self.count += 1 + self._last = (peer_host, cause) + now = time.monotonic() + last = self._reported_at + if last is None or now - last >= self._window: + self.cancel() + return True + if self._timer is None: + self._timer = asyncio.get_running_loop().call_later( + last + self._window - now, self._on_timer + ) + return False + + def take_held(self) -> tuple[str | None, str] | None: + """Mark the failures not yet reported as reported, and return the report for them. + + Synchronous, so a caller with no running loop left can still log what was held.""" + since = self.count - self._reported + if since <= 0: + return None + self._reported = self.count + self._reported_at = time.monotonic() + peer_host, cause = self._last + return ( + peer_host if since == 1 else None, + f"{since} failed handshake(s) since the last event; last cause {cause}", + ) + + async def note(self, peer_host: str | None, cause: str) -> None: + """Count one failure from a coroutine, reporting it before returning if a report is due.""" + if self._count(peer_host, cause): + await self.report() + + def note_soon(self, peer_host: str | None, cause: str) -> None: + """Count one failure from a plain callback on the loop, such as inside a handshake. The + report, if one is due, goes on a tracked task.""" + if self._count(peer_host, cause): + self._report_soon() + + def _on_timer(self) -> None: + """The trailing report's timer.""" + self._timer = None + self._report_soon() + + def _report_soon(self) -> None: + # Taken here, not in the task, so the window starts now: a second failure in the same loop + # turn is held for the trailing report, as under `note`, rather than reported twice. + held = self.take_held() + if held is None: + return + sent = self._emit(*held) + if sent is not None: + task = asyncio.get_running_loop().create_task(sent) + self._tasks.add(task) + task.add_done_callback(self._tasks.discard) + + async def report(self) -> None: + """Send one report for the failures not yet reported, if there are any.""" + held = self.take_held() + if held is not None: + sent = self._emit(*held) + if sent is not None: + await sent + + def cancel(self) -> None: + """Disarm the trailing timer. What it held stays held, for :meth:`flush` or :meth:`take_held`.""" + if self._timer is not None: + self._timer.cancel() + self._timer = None + + async def flush(self) -> None: + """At a listener's stop, once no handshake can add to the count: wait for any report in + flight, then send what the trailing timer still held. The emitters are fail-soft, so this + cannot fail a stop().""" + self.cancel() + if self._tasks: + await asyncio.gather(*self._tasks, return_exceptions=True) + await self.report() + + +def watch_loop_handshakes(ctx: ssl.SSLContext, on_failure: Callable[[str], None]) -> None: + """Call ``on_failure(cause)`` for each handshake on ``ctx`` that the event loop fails. + + ``ctx`` must be a server context this caller owns, since it is changed in place. A second call + replaces the first callback. ``on_failure`` runs inside the loop's handshake, so it must not + block; a fault in it is logged and never changes the handshake's outcome. + """ + ctx.sslobject_class = type( + "_WatchedSSLObject", (_WatchedSSLObject,), {"_on_failure": staticmethod(on_failure)} + ) + + +class _WatchedSSLObject(ssl.SSLObject): + """An ``SSLObject`` that reports a failed handshake before the loop sees it.""" + + _on_failure: Callable[[str], None] + + def do_handshake(self) -> None: + try: + super().do_handshake() + except _AGAIN: + raise + except ssl.SSLError as exc: + try: + self._on_failure(handshake_cause(exc)) + # A recording fault must never turn a failed handshake into a different error inside + # the loop's protocol, so it is logged and the handshake's own error goes on. + except Exception as fault: # noqa: BLE001 + _log_recorder_fault(fault) + raise + + +def _log_recorder_fault(fault: Exception) -> None: + global _recorder_fault_logged + level = logging.DEBUG if _recorder_fault_logged else logging.WARNING + _recorder_fault_logged = True + logger.log(level, "recording a failed TLS handshake failed: %s", type(fault).__name__) diff --git a/messagefoundry/transports/http_listener.py b/messagefoundry/transports/http_listener.py index d767c580e8..c615f3ef6e 100644 --- a/messagefoundry/transports/http_listener.py +++ b/messagefoundry/transports/http_listener.py @@ -49,6 +49,7 @@ from messagefoundry.config.models import ConnectorType, Source from messagefoundry.credential import client_cert_principal, constant_time_match_any from messagefoundry.redaction import safe_exc +from messagefoundry.tls_handshake_failures import HandshakeFailures, watch_loop_handshakes from messagefoundry.transports.admission import ListenerAdmission from messagefoundry.transports.base import ( InboundHandler, @@ -716,6 +717,12 @@ def __init__(self, config: Source) -> None: # Per-connection inbound TLS (present a server cert; opt-in mTLS via tls_ca_file), built once at # construction so a bad cert/key fails at build. None when tls is off → plaintext, byte-identical. self._ssl: ssl.SSLContext | None = _mllp_ssl_context(s, server=True, name=config.name or "") + # The loop runs this listener's handshakes on every loop, so a failed one never reaches + # `_on_client`. The context reports it, as a throttled `tls_handshake_failed` event like the + # MLLP listener's (vault BACKLOG #3302). The peer is not known there. + self._tls_failures = HandshakeFailures(self._emit_tls_failure) + if self._ssl is not None: + watch_loop_handshakes(self._ssl, self._note_tls_failure) # Intake authentication (ADR 0154 D6) — a PEER control: it authorises SUBMITTING a message on # this inbound, mints no identity and opens no session. Defaults to "none", which makes every # path below a no-op and every shipped configuration byte-identical. The env() refs are already @@ -830,9 +837,15 @@ async def stop(self) -> None: await asyncio.gather(*still_running, return_exceptions=True) self._clients.clear() self._client_tasks.clear() + # Report the handshake failures a trailing event still held (vault BACKLOG #3302). + # Not once a restart has begun, whose failures are its own to report. + if self._admission.stopping: + await self._tls_failures.flush() finally: # Even when this stop() is cancelled: a task cancelled past its grace never released. self._admission.reset() + if self._admission.stopping: + self._tls_failures.cancel() # Bound wait_closed() so a Windows ProactorEventLoop overlapped-op wedge can't hang teardown on # the suite's shared session loop (#55, mirrors MLLPSource.stop()). The listener is closed and # every client task is resolved, so a wait_closed() past the grace is an OS wedge — abandoning it @@ -844,6 +857,20 @@ async def stop(self) -> None: logger.warning("HTTP server.wait_closed() exceeded shutdown grace; abandoning") self._server = None + @property + def tls_handshake_failures(self) -> int: + """Failed TLS handshakes this listener has seen since it was built, outside its stop()s + (vault BACKLOG #3302).""" + return self._tls_failures.count + + def _note_tls_failure(self, cause: str) -> None: + # Not once stop() has begun, so no report outlives stop(). + if not self._admission.stopping: + self._tls_failures.note_soon(None, cause) + + async def _emit_tls_failure(self, peer_host: str | None, reason: str) -> None: + await self._emit_event("tls_handshake_failed", peer_host=peer_host, reason=reason) + async def _emit_event( self, kind: str, *, peer_host: str | None = None, reason: str | None = None ) -> None: diff --git a/messagefoundry/transports/mllp.py b/messagefoundry/transports/mllp.py index 24ab2138bf..179679693b 100644 --- a/messagefoundry/transports/mllp.py +++ b/messagefoundry/transports/mllp.py @@ -85,6 +85,12 @@ from messagefoundry.parsing.message import emit_raw_separators, reencode_with_separators from messagefoundry.parsing.peek import PEEK_READ_FAULTS, HL7PeekError, Peek, normalize from messagefoundry.redaction import clamp_untrusted, safe_exc +from messagefoundry.tls_handshake_failures import ( + EVENT_SECONDS, + HandshakeFailures, + handshake_cause, + watch_loop_handshakes, +) from messagefoundry.transports.admission import FrameClock, ListenerAdmission from messagefoundry.transports.base import ( DeliveryError, @@ -311,8 +317,8 @@ # #2613). Failed handshakes are logged at DEBUG only, so before #2613 nothing an operator reads # showed them. One event per window, carrying the count since the last one, records a flood without # letting a peer that fails handshakes as fast as it connects fill the connection_event table. -# Per listener, not per peer: the peer's address is the caller's choice. -_TLS_FAILURE_EVENT_SECONDS = 60.0 +# The shared value since #3302, whose `tls_handshake_failures` module says why it is per listener. +_TLS_FAILURE_EVENT_SECONDS = EVENT_SECONDS #: Characters of a negative acknowledgment's MSA-3 that reach the :class:`NegativeAckError` message #: (BACKLOG #1576). MSA-3 is *Text Message* — a human-readable reason for the rejection — and the @@ -1879,16 +1885,12 @@ def __init__(self, config: Source) -> None: # True while this listener runs TLS handshakes itself, after its own checks (BACKLOG #1606); # set at start() from the running loop, see `_upgrades_tls_itself`. self._upgrade_tls = False - #: Failed TLS handshakes this listener has seen, since it was built (vault BACKLOG #2613). - #: Counted only where the listener runs the handshake itself (`_upgrades_tls_itself`). - self.tls_handshake_failures = 0 - # The count already reported in a `tls_handshake_failed` event, and when that event went. - self._tls_failures_reported = 0 - self._tls_failure_event_at: float | None = None - # The latest failure's peer and cause, the trailing event's timer, and its task. - self._tls_last: tuple[str | None, str] = (None, "") - self._tls_flush: asyncio.TimerHandle | None = None - self._tls_flush_tasks: set[asyncio.Task[None]] = set() + # Failed TLS handshakes and their throttled `tls_handshake_failed` events (vault BACKLOG + # #2613), on every loop since #3302: `_start_tls` counts where this listener runs the + # handshake, and the context's hook (`_note_loop_tls_failure`) where the loop does. + self._tls_failures = HandshakeFailures( + self._emit_tls_failure, window=_TLS_FAILURE_EVENT_SECONDS + ) # The in-flight frame slots, `max_inflight_frames` of them; None when the bound is off. # Built at start() rather than here, so a slot a straggler from the previous run never # gave back cannot shrink the restarted listener's budget. Each holder releases the @@ -1931,7 +1933,9 @@ async def start( return # The loop runs the handshake, and `_on_client` sees the socket only after it. Both ends of # the TLS socket's life are bounded here instead: the handshake, and the close_notify - # exchange after writer.close(). Read at start() so a test can shorten them. + # exchange after writer.close(). Read at start() so a test can shorten them. A failed + # handshake never reaches `_on_client` either, so the context reports it (vault #3302). + watch_loop_handshakes(self._ssl, self._note_loop_tls_failure) self._server = await asyncio.start_server( self._on_client, self.host, @@ -2027,7 +2031,7 @@ async def _start_tls(self, reader: asyncio.StreamReader, writer: asyncio.StreamW # Windows Proactor reports that hang-up. A TLS error and the handshake bound count. hung_up = isinstance(exc, ConnectionResetError | BrokenPipeError) if not self._stopping and not hung_up: - await self._note_tls_failure(_peer_host(writer), type(exc).__name__) + await self._tls_failures.note(_peer_host(writer), handshake_cause(exc)) return False except AttributeError: if not _lost_its_transport(writer): @@ -2044,51 +2048,21 @@ async def _start_tls(self, reader: asyncio.StreamReader, writer: asyncio.StreamW reader._transport = writer.transport # type: ignore[attr-defined] # see the docstring return True - async def _note_tls_failure(self, peer_host: str | None, cause: str) -> None: - """Count one failed handshake, and emit a throttled ``tls_handshake_failed`` event (#2613). - - The first failure emits at once. Later ones inside :data:`_TLS_FAILURE_EVENT_SECONDS` are - held, and one trailing event at the window's end reports how many, so a burst is one row - with its size. stop() reports what is still held. An event for one failure names its peer; - an event for several names none, since they may come from many peers. ``cause`` is an - exception class name, never the peer's bytes. A handshake past its bound counts, as a - ``ConnectionAbortedError``.""" - self.tls_handshake_failures += 1 - self._tls_last = (peer_host, cause) - now = time.monotonic() - last = self._tls_failure_event_at - if last is None or now - last >= _TLS_FAILURE_EVENT_SECONDS: - await self._report_tls_failures() - elif self._tls_flush is None: - self._tls_flush = asyncio.get_running_loop().call_later( - last + _TLS_FAILURE_EVENT_SECONDS - now, self._flush_tls_failures - ) + @property + def tls_handshake_failures(self) -> int: + """Failed TLS handshakes this listener has seen since it was built, outside its stop()s + (vault BACKLOG #2613).""" + return self._tls_failures.count - def _cancel_tls_flush(self) -> None: - if self._tls_flush is not None: - self._tls_flush.cancel() - self._tls_flush = None - - def _flush_tls_failures(self) -> None: - """The trailing event's timer: report the held failures on a tracked task.""" - self._tls_flush = None - task = asyncio.get_running_loop().create_task(self._report_tls_failures()) - self._tls_flush_tasks.add(task) - task.add_done_callback(self._tls_flush_tasks.discard) - - async def _report_tls_failures(self) -> None: - """Emit one ``tls_handshake_failed`` for the failures not yet reported, if there are any.""" - since = self.tls_handshake_failures - self._tls_failures_reported - if since <= 0: - return - self._tls_failures_reported = self.tls_handshake_failures - self._tls_failure_event_at = time.monotonic() - peer_host, cause = self._tls_last - await self._emit_event( - "tls_handshake_failed", - peer_host=peer_host if since == 1 else None, - reason=f"{since} failed handshake(s) since the last event; last cause {cause}", - ) + def _note_loop_tls_failure(self, cause: str) -> None: + """A handshake the LOOP ran failed (vault BACKLOG #3302, #2613 item 3). The peer is not + known there. Ignored where this listener runs handshakes itself, which `_start_tls` already + counts, and once stop() has begun, so no report outlives stop().""" + if not self._upgrade_tls and not self._stopping: + self._tls_failures.note_soon(None, cause) + + async def _emit_tls_failure(self, peer_host: str | None, reason: str) -> None: + await self._emit_event("tls_handshake_failed", peer_host=peer_host, reason=reason) async def _handle_bounded(self, message: bytes) -> str | None: """Run the inbound handler inside one of this listener's in-flight slots, if the bound is on @@ -2178,13 +2152,14 @@ async def stop(self) -> None: self._client_tasks.clear() # Vault BACKLOG #2613: report the handshake failures a trailing event still held, once # no handshake can add to them. `_emit_event` is fail-soft, so this cannot fail stop(). - self._cancel_tls_flush() - if self._tls_flush_tasks: - await asyncio.gather(*self._tls_flush_tasks, return_exceptions=True) - await self._report_tls_failures() + # Not once a restart has begun (an abandoned stop() resuming late), whose failures are + # its own to report. + if self._stopping: + await self._tls_failures.flush() finally: # Again here, so a stop() cancelled above leaves no timer to fire after it. - self._cancel_tls_flush() + if self._stopping: + self._tls_failures.cancel() # Clear the per-host tables with them, in a `finally` so a stop() cancelled or failing # anywhere above still clears them (vault BACKLOG #2847), as the raw-TCP, X12 and HTTP # listeners already did. A client task the runner ABANDONS when a stop() overruns diff --git a/messagefoundry_webconsole/pages/monitoring.py b/messagefoundry_webconsole/pages/monitoring.py index 8c26b942c6..3e373e00db 100644 --- a/messagefoundry_webconsole/pages/monitoring.py +++ b/messagefoundry_webconsole/pages/monitoring.py @@ -355,8 +355,8 @@ def _alert_rules_section(config: AlertsConfig) -> list[Markup]: # BACKLOG #1619 -- the MLLP listener's inbound handler faulted on a frame it read cleanly (a # store outage at the ingress commit is the reachable case). Not a framing fault, so not that kind. "handler_error", - # vault BACKLOG #2613 -- a TLS handshake on an MLLP listener failed. Throttled to one per minute - # per listener; the reason carries the count since the last one. + # vault BACKLOG #2613 and #3302 -- a TLS handshake on an MLLP or HTTP listener failed. Throttled + # to one per minute per listener; the reason carries the count since the last one. "tls_handshake_failed", # BACKLOG #1662 — the DATABASE poll source, on a row it cannot turn into a body. The first # non-listener kind: a poll source has no peer, so its rows carry a NULL peer_host. diff --git a/scripts/security/crypto_inventory_check.py b/scripts/security/crypto_inventory_check.py index 546f2379cc..a42299c7fa 100644 --- a/scripts/security/crypto_inventory_check.py +++ b/scripts/security/crypto_inventory_check.py @@ -294,6 +294,10 @@ # BACKLOG #1352 / #1171: every private-key TLS load goes through keywrap.load_checked_cert_chain, # which checks the key's passphrase wrap and then calls load_cert_chain; ssl for that one call. "messagefoundry/keywrap.py": frozenset({"ssl"}), + # Vault BACKLOG #3302: subclasses ssl.SSLObject to OBSERVE a failed inbound handshake the event + # loop ran, and installs it as a server context's sslobject_class. It re-raises unchanged, and + # builds no context, loads no key and chooses no algorithm, so section 4 gains no row. + "messagefoundry/tls_handshake_failures.py": frozenset({"ssl"}), # ASVS 12.1.1: the startup TLS-floor probe. Client contexts ONLY, and deliberately weakened ones — # a withdrawn-version offer (minimum==maximum==TLSv1/1.1) at ALL:@SECLEVEL=0 with CERT_NONE, so the # ClientHello is actually sent and an untrusted internal CA cannot abort before the version is @@ -911,6 +915,11 @@ #: limits, and they are the most useful lines in this table: each is a first-party crypto decision #: that no call-pattern instrument can see. IMPORT_ONLY: dict[str, str] = { + "messagefoundry/tls_handshake_failures.py": ( + "subclasses ssl.SSLObject to observe a failed handshake and re-raise it, and sets a " + "server context's sslobject_class; the contexts it watches are built in transports/mllp.py " + "and api/tls.py, which are inventoried" + ), "messagefoundry/pipeline/dr.py": ( "names HopPosture, a value type, to hand the engine's posture to the cold-seed verify; " "that verify runs in pipeline/dr_backup.py, which is inventoried" diff --git a/tests/test_key_lifecycle_coverage.py b/tests/test_key_lifecycle_coverage.py index cad24c0417..aaaa44669b 100644 --- a/tests/test_key_lifecycle_coverage.py +++ b/tests/test_key_lifecycle_coverage.py @@ -243,6 +243,9 @@ "time, and that credential is governed by the rotation schedule", "messagefoundry/integrity.py": _KEYLESS, "messagefoundry/redaction.py": _KEYLESS, + "messagefoundry/tls_handshake_failures.py": "observes a failed inbound handshake on a server " + "context another module builds and re-raises it (vault BACKLOG #3302); it loads, mints and " + "holds no key", "messagefoundry/parsing/xml/signature.py": _VERIFY_ONLY, "messagefoundry/parsing/xml/_deps.py": _VERIFY_ONLY, "messagefoundry/pipeline/cert_expiry.py": "reads PUBLIC certificate facts to alarm on expiry; " diff --git a/tests/test_listener_tls_exposure.py b/tests/test_listener_tls_exposure.py index 3bef1d8727..29c5cb7be7 100644 --- a/tests/test_listener_tls_exposure.py +++ b/tests/test_listener_tls_exposure.py @@ -14,6 +14,7 @@ from __future__ import annotations import logging +import ssl from pathlib import Path import pytest @@ -79,9 +80,11 @@ def _mock_start(monkeypatch: pytest.MonkeyPatch) -> None: monkeypatch.setattr("messagefoundry.api.create_managed_app", lambda **kw: object()) monkeypatch.setattr("uvicorn.run", lambda *a, **k: None) # The in-process-TLS start path builds an SSLContext from the cert PEM before uvicorn.run; stub it - # so the tests need no on-disk cert (the GATE, not context-building, is under test). + # so the tests need no on-disk cert (the GATE, not context-building, is under test). A real, empty + # server context rather than a bare object: serve watches its handshakes (vault BACKLOG #3302). monkeypatch.setattr( - "messagefoundry.api.tls.build_api_ssl_context", lambda api, *, enforcing=True: object() + "messagefoundry.api.tls.build_api_ssl_context", + lambda api, *, enforcing=True: ssl.SSLContext(ssl.PROTOCOL_TLS_SERVER), ) diff --git a/tests/test_mllp_tls.py b/tests/test_mllp_tls.py index 8b7c47bc4c..872fdc424f 100644 --- a/tests/test_mllp_tls.py +++ b/tests/test_mllp_tls.py @@ -1129,9 +1129,9 @@ async def test_failed_handshakes_are_counted_and_their_events_throttled( source, _cert_path = _tls_source(tmp_path) events = _Events() source.on_connection_event = events - await source._note_tls_failure("10.0.0.9", "SSLError") - await source._note_tls_failure("10.0.0.8", "SSLError") - await source._note_tls_failure("10.0.0.7", "ConnectionAbortedError") + await source._tls_failures.note("10.0.0.9", "SSLError") + await source._tls_failures.note("10.0.0.8", "SSLError") + await source._tls_failures.note("10.0.0.7", "ConnectionAbortedError") # The control: three failures inside one window are one event so far, and the count is exact. assert source.tls_handshake_failures == 3 assert events.seen == [ @@ -1161,13 +1161,13 @@ async def test_stop_reports_the_handshake_failures_still_held( await source.start(_ack) try: for _ in range(4): - await source._note_tls_failure("10.0.0.9", "SSLError") + await source._tls_failures.note("10.0.0.9", "SSLError") assert len(events.seen) == 1 finally: await asyncio.wait_for(source.stop(), timeout=10.0) held = events.seen[1][2] assert held is not None and held.startswith("3 failed handshake(s)") - assert source._tls_flush is None + assert source._tls_failures._timer is None async def test_a_peer_dropping_as_its_handshake_completes_is_closed_quietly( diff --git a/tests/test_tls_handshake_failures.py b/tests/test_tls_handshake_failures.py new file mode 100644 index 0000000000..5697c45e9a --- /dev/null +++ b/tests/test_tls_handshake_failures.py @@ -0,0 +1,463 @@ +# SPDX-License-Identifier: AGPL-3.0-or-later +# Copyright (C) 2026 MessageFoundry Foundation, LLC and contributors +"""A failed inbound TLS handshake the EVENT LOOP ran leaves a record (vault BACKLOG #3302). + +Before #3302 the HTTP intake listener and the API recorded none on any loop, and the MLLP listener +none on uvloop, where the loop runs its handshakes. Each surface below fails a real handshake and +reads the record, and each has a control that completes one and reads none. The MLLP case runs on +uvloop where it is installed (CI's Linux legs) and, everywhere, on the stdlib loop forced onto the +same loop-run path uvloop takes. +""" + +from __future__ import annotations + +import asyncio +import contextlib +import logging +import socket +import ssl +import sys +from pathlib import Path +from typing import Any + +import pytest + +from messagefoundry.api.tls import ApiHandshakeRecord +from messagefoundry.config.models import ConnectorType, Destination, Source +from messagefoundry.tls_handshake_failures import ( + HandshakeFailures, + handshake_cause, + watch_loop_handshakes, +) +from messagefoundry.transports import mllp as mllp_module +from messagefoundry.transports.http_listener import HttpSource +from messagefoundry.transports.mllp import MLLPDestination +from tests.test_mllp_tls import ADT, _ack, _cert, _close_raw, _Events, _tls_source, _until + +_PLAINTEXT = b"GET / HTTP/1.1\r\nHost: x\r\n\r\n" + + +def _server_ctx(tmp_path: Path) -> tuple[ssl.SSLContext, str]: + cert, key = _cert(tmp_path) + ctx = ssl.SSLContext(ssl.PROTOCOL_TLS_SERVER) + ctx.load_cert_chain(cert, key) + return ctx, cert + + +def _pinned_client(cert: str) -> ssl.SSLContext: + ctx = ssl.create_default_context(cafile=cert) + ctx.minimum_version = ssl.TLSVersion.TLSv1_2 + return ctx + + +def _refuse_the_certificate(port: int) -> bool: + """A client that does not trust the listener's certificate, so it sends an alert the SERVER + then fails its handshake on: the wrong-certificate case the row names. Blocking, run in a + thread: asyncio's own client drops the socket without sending the alert, which the server + reads as a hang-up. True when the client refused, as it must.""" + ctx = ssl.create_default_context() + with socket.create_connection(("127.0.0.1", port), timeout=5.0) as raw: + try: + with ctx.wrap_socket(raw, server_hostname="127.0.0.1"): + return False + except ssl.SSLCertVerificationError: + return True + + +async def _plaintext_peer(port: int) -> None: + """Send plaintext to a TLS port, then wait for the listener to drop the socket.""" + reader, writer = await asyncio.open_connection("127.0.0.1", port) + try: + writer.write(_PLAINTEXT) + await writer.drain() + with contextlib.suppress(ConnectionError, TimeoutError): + await asyncio.wait_for(reader.read(1024), timeout=5.0) + finally: + await _close_raw(writer) + + +async def _tls_peer(port: int, ctx: ssl.SSLContext) -> bool: + """Open a TLS connection with ``ctx``; True when the handshake completed.""" + try: + _reader, writer = await asyncio.wait_for( + asyncio.open_connection("127.0.0.1", port, ssl=ctx, server_hostname="127.0.0.1"), + timeout=5.0, + ) + except (ssl.SSLError, ConnectionError): + return False + await _close_raw(writer) + return True + + +# --- the hook and the throttle, without a socket --------------------------------------------- + + +def _handshake_in_memory(server: ssl.SSLObject, client: ssl.SSLObject, pipes: Any) -> None: + """Drive both ends of a handshake over memory BIOs until both finish.""" + c_in, c_out, s_in, s_out = pipes + done = {"client": False, "server": False} + for _ in range(20): + for side, obj in (("client", client), ("server", server)): + if done[side]: + continue + try: + obj.do_handshake() + done[side] = True + except ssl.SSLWantReadError: + pass + s_in.write(c_out.read()) + c_in.write(s_out.read()) + if all(done.values()): + return + pytest.fail("the in-memory handshake did not finish") + + +def test_the_hook_reports_a_failed_handshake_and_not_a_completed_one(tmp_path: Path) -> None: + server_ctx, cert = _server_ctx(tmp_path) + seen: list[str] = [] + watch_loop_handshakes(server_ctx, seen.append) + + # The control: a completed handshake raises SSLWantReadError on the way, which both loops read + # as "call again", and reports nothing. + pipes = (ssl.MemoryBIO(), ssl.MemoryBIO(), ssl.MemoryBIO(), ssl.MemoryBIO()) + c_in, c_out, s_in, s_out = pipes + server = server_ctx.wrap_bio(s_in, s_out, server_side=True) + client = _pinned_client(cert).wrap_bio(c_in, c_out, server_hostname="127.0.0.1") + _handshake_in_memory(server, client, pipes) + assert seen == [] + + # Plaintext where a ClientHello belongs fails, and is reported with a cause, not the bytes. + s_in, s_out = ssl.MemoryBIO(), ssl.MemoryBIO() + s_in.write(_PLAINTEXT) + server = server_ctx.wrap_bio(s_in, s_out, server_side=True) + with pytest.raises(ssl.SSLError): + server.do_handshake() + assert len(seen) == 1 + assert seen[0].startswith("SSLError") + assert "GET" not in seen[0] + + +def test_a_fault_in_the_recorder_does_not_change_the_handshake_error( + tmp_path: Path, caplog: pytest.LogCaptureFixture, monkeypatch: pytest.MonkeyPatch +) -> None: + """The first fault is a WARNING and later ones DEBUG, so a recorder failing on every call + cannot turn a handshake flood into a log flood.""" + import messagefoundry.tls_handshake_failures as thf + + monkeypatch.setattr(thf, "_recorder_fault_logged", False) + server_ctx, _cert_path = _server_ctx(tmp_path) + + def broken(_cause: str) -> None: + raise RuntimeError("recorder fault") + + watch_loop_handshakes(server_ctx, broken) + with caplog.at_level(logging.DEBUG, logger="messagefoundry.tls_handshake_failures"): + for _ in range(3): + s_in, s_out = ssl.MemoryBIO(), ssl.MemoryBIO() + s_in.write(_PLAINTEXT) + server = server_ctx.wrap_bio(s_in, s_out, server_side=True) + with pytest.raises(ssl.SSLError): # the handshake's own error, not the recorder's + server.do_handshake() + faults = [ + r.levelno + for r in caplog.records + if r.getMessage() == "recording a failed TLS handshake failed: RuntimeError" + ] + assert faults == [logging.WARNING, logging.DEBUG, logging.DEBUG] + + +def test_the_cause_keeps_only_an_openssl_mnemonic() -> None: + err = ssl.SSLError(1, "boom") + err.reason = "WRONG_VERSION_NUMBER" + assert handshake_cause(err) == "SSLError WRONG_VERSION_NUMBER" + err.reason = "not a mnemonic: peer bytes" + assert handshake_cause(err) == "SSLError" + assert handshake_cause(ConnectionAbortedError("bound")) == "ConnectionAbortedError" + + +async def test_note_soon_throttles_as_note_does() -> None: + """``note_soon`` runs inside the loop's handshake, so it cannot await. The first failure is + still reported at once and its window starts then, so a second in the same loop turn is held + for the trailing report rather than reported twice.""" + sent: list[tuple[str | None, str]] = [] + + async def emit(peer_host: str | None, reason: str) -> None: + sent.append((peer_host, reason)) + + failures = HandshakeFailures(emit) + failures.note_soon("10.0.0.1", "SSLError") + failures.note_soon("10.0.0.2", "SSLError") + failures.note_soon("10.0.0.3", "SSLError") + await _until(lambda: bool(sent), "no report was sent") + await asyncio.sleep(0.05) + assert sent == [("10.0.0.1", "1 failed handshake(s) since the last event; last cause SSLError")] + assert failures.count == 3 + assert failures._timer is not None # the trailing report is armed + await failures.flush() + assert sent[-1] == (None, "2 failed handshake(s) since the last event; last cause SSLError") + assert failures._timer is None + await failures.flush() + assert len(sent) == 2 # nothing more was held, so nothing more is sent + + +async def test_a_report_due_now_disarms_the_trailing_timer() -> None: + """A failure that arrives once the window has passed, before the trailing timer has fired (an + I/O callback runs before a due timer in one loop iteration), reports everything held. The old + timer must not fire a second report inside the new window, and cancel() must reach the next.""" + sent: list[tuple[str | None, str]] = [] + + async def emit(peer_host: str | None, reason: str) -> None: + sent.append((peer_host, reason)) + + # A window far longer than the test, so no step of it can fall outside one by being slow. + failures = HandshakeFailures(emit, window=60.0) + failures.note_soon(None, "SSLError") + failures.note_soon(None, "SSLError") # held: arms the trailing timer + stale = failures._timer + assert stale is not None + assert failures._reported_at is not None + failures._reported_at -= 61.0 # the window has passed, and the timer has not run yet + failures.note_soon(None, "SSLError") + assert stale.cancelled() + await _until(lambda: len(sent) == 2, "the due report was not sent") + assert sent[1] == (None, "2 failed handshake(s) since the last event; last cause SSLError") + failures.note_soon(None, "SSLError") # inside the new window: a new timer + fresh = failures._timer + assert fresh is not None and fresh is not stale + failures.cancel() + assert fresh.cancelled() and failures._timer is None + assert len(sent) == 2 + + +# --- the HTTP intake listener ----------------------------------------------------------------- + + +def _http_tls_source(tmp_path: Path) -> tuple[HttpSource, str]: + cert, key = _cert(tmp_path) + source = HttpSource( + Source( + type=ConnectorType.HTTP, + settings={ + "host": "127.0.0.1", + "port": 0, + "tls": True, + "tls_cert_file": cert, + "tls_key_file": key, + }, + ) + ) + return source, cert + + +async def _no_reply(_raw: bytes) -> str | None: + return None + + +async def test_the_http_listener_records_a_failed_handshake(tmp_path: Path) -> None: + source, cert = _http_tls_source(tmp_path) + events = _Events() + source.on_connection_event = events + await source.start(_no_reply) + try: + # The control: a completed handshake is no failure. + assert await _tls_peer(source.sockport, _pinned_client(cert)) + await asyncio.sleep(0.1) + assert "tls_handshake_failed" not in events.kinds() + assert source.tls_handshake_failures == 0 + + await _plaintext_peer(source.sockport) + await _until(lambda: "tls_handshake_failed" in events.kinds(), "no failure event") + failed = [e for e in events.seen if e[0] == "tls_handshake_failed"] + assert len(failed) == 1 + (_kind, peer, reason) = failed[0] + assert peer is None # the loop's TLS object knows no peer + assert reason is not None and reason.startswith("1 failed handshake(s)") + assert "GET" not in reason # a cause, never the peer's bytes + assert source.tls_handshake_failures == 1 + + # A client that refuses the listener's certificate fails the SERVER's handshake too. Inside + # the window it is held, and stop() reports it. + assert await asyncio.to_thread(_refuse_the_certificate, source.sockport) + await _until(lambda: source.tls_handshake_failures == 2, "the second failure not counted") + assert len([k for k in events.kinds() if k == "tls_handshake_failed"]) == 1 + finally: + await asyncio.wait_for(source.stop(), timeout=10.0) + failed = [e for e in events.seen if e[0] == "tls_handshake_failed"] + assert len(failed) == 2 + assert failed[1][2] is not None and failed[1][2].startswith("1 failed handshake(s)") + + +# --- the MLLP listener where the loop runs the handshake -------------------------------------- + + +async def _mllp_loop_run_scenario(tmp_path: Path) -> None: + source, cert = _tls_source(tmp_path) + events = _Events() + source.on_connection_event = events + await source.start(_ack) + try: + assert source._upgrade_tls is False # the loop runs the handshake here + # The control: a real TLS sender gets a message through and no failure is recorded. + dest = MLLPDestination( + Destination( + name="out", + type=ConnectorType.MLLP, + settings={ + "host": "127.0.0.1", + "port": source.sockport, + "timeout_seconds": 5, + "tls": True, + "tls_ca_file": cert, + "tls_check_hostname": True, + }, + ) + ) + try: + await dest.send(ADT) + finally: + await dest.aclose() + assert "tls_handshake_failed" not in events.kinds() + assert source.tls_handshake_failures == 0 + + await _plaintext_peer(source.sockport) + await _until(lambda: "tls_handshake_failed" in events.kinds(), "no failure event") + assert source.tls_handshake_failures == 1 + (_kind, peer, reason) = next(e for e in events.seen if e[0] == "tls_handshake_failed") + assert peer is None # the loop's TLS object knows no peer + assert reason is not None and reason.startswith("1 failed handshake(s)") + assert "MSH" not in reason and "GET" not in reason + finally: + await asyncio.wait_for(source.stop(), timeout=10.0) + + +async def test_mllp_records_a_failed_loop_run_handshake_on_the_stdlib_loop( + tmp_path: Path, monkeypatch: pytest.MonkeyPatch +) -> None: + """The path uvloop takes, forced on the stdlib loop so it runs on every platform.""" + monkeypatch.setattr(mllp_module, "_upgrades_tls_itself", lambda _loop: False) + await _mllp_loop_run_scenario(tmp_path) + + +@pytest.mark.skipif(sys.platform == "win32", reason="uvloop does not run on Windows") +def test_mllp_records_a_failed_handshake_on_uvloop(tmp_path: Path) -> None: + """Vault BACKLOG #2613 item 3: the real loop, not a stand-in. It skips where uvloop is not + installed.""" + uvloop = pytest.importorskip("uvloop") + asyncio.run(_mllp_loop_run_scenario(tmp_path), loop_factory=uvloop.new_event_loop) + + +def test_a_listener_running_its_own_handshake_does_not_count_twice(tmp_path: Path) -> None: + """On the stdlib loop the MLLP listener upgrades each socket itself and counts a failure in + `_start_tls`, with the peer. The context hook must stay out of that count.""" + source, _cert_path = _tls_source(tmp_path) + source._upgrade_tls = True + source._note_loop_tls_failure("SSLError") + assert source.tls_handshake_failures == 0 + + +# --- the API ------------------------------------------------------------------------------------ + + +def _api_records(caplog_records: list[logging.LogRecord]) -> list[str]: + return [ + r.getMessage() + for r in caplog_records + if r.name == "messagefoundry.api.tls" + and r.levelno == logging.WARNING + and r.getMessage().startswith("TLS handshake failed on the API listener") + ] + + +class _Collect(logging.Handler): + def __init__(self) -> None: + super().__init__(logging.WARNING) + self.records: list[logging.LogRecord] = [] + + def emit(self, record: logging.LogRecord) -> None: + self.records.append(record) + + +@pytest.mark.usefixtures("bounded_warn_only_retention", "verified_log_forwarding") +def test_serve_records_a_failed_api_handshake( + tmp_path: Path, monkeypatch: pytest.MonkeyPatch +) -> None: + """The context serve hands uvicorn, served the way uvicorn serves it (``loop.create_server`` + with ``ssl=``). The first failure is a WARNING at once; a second inside the window is held and + logged when uvicorn returns.""" + import messagefoundry.api.tls as api_tls + from messagefoundry.__main__ import main + from messagefoundry.api_tls_source import GENERATED_CERT_NAME + from messagefoundry.store.crypto import generate_key + from tests.test_api_tls import _SYNTHETIC_LOOPBACK_TOML, SAMPLES_CONFIG + + collect = _Collect() + tls_log = logging.getLogger("messagefoundry.api.tls") + during: dict[str, Any] = {} + records: list[ApiHandshakeRecord] = [] + + class _Seen(ApiHandshakeRecord): + def __init__(self, ctx: ssl.SSLContext) -> None: + super().__init__(ctx) + records.append(self) + + monkeypatch.setattr(api_tls, "ApiHandshakeRecord", _Seen) + + async def scenario(ctx: ssl.SSLContext) -> None: + loop = asyncio.get_running_loop() + server = await loop.create_server(asyncio.Protocol, "127.0.0.1", 0, ssl=ctx) + port = server.sockets[0].getsockname()[1] + try: + pinned = _pinned_client(str(tmp_path / GENERATED_CERT_NAME)) + during["control_ok"] = await _tls_peer(port, pinned) + await asyncio.sleep(0.1) + during["after_control"] = _api_records(collect.records) + await _plaintext_peer(port) + await _until(lambda: bool(_api_records(collect.records)), "no WARNING line") + during["after_failure"] = _api_records(collect.records) + assert await asyncio.to_thread(_refuse_the_certificate, port) + await _until(lambda: records[0].failures.count == 2, "the refusal was not counted") + during["held"] = _api_records(collect.records) + finally: + server.close() + await server.wait_closed() + + level_before = tls_log.level + + def fake_run(*_args: Any, **kwargs: Any) -> None: + tls_log.addHandler(collect) + tls_log.setLevel(logging.WARNING) + asyncio.run(scenario(kwargs["ssl_context_factory"](None, None))) + + monkeypatch.chdir(tmp_path) + monkeypatch.setenv("MEFOR_STORE_ENCRYPTION_KEY", generate_key()) + monkeypatch.setattr("uvicorn.run", fake_run) + (tmp_path / "messagefoundry.toml").write_text(_SYNTHETIC_LOOPBACK_TOML, encoding="utf-8") + try: + assert main(["serve", "--config", str(SAMPLES_CONFIG), "--env", "dev"]) == 0 + after_close = _api_records(collect.records) + finally: + tls_log.removeHandler(collect) + tls_log.setLevel(level_before) + + assert during["control_ok"] is True + assert during["after_control"] == [] # the control: a completed handshake logs nothing + assert len(during["after_failure"]) == 1 + line = during["after_failure"][0] + assert line.startswith("TLS handshake failed on the API listener: 1 failed handshake(s)") + assert "GET" not in line + assert during["held"] == during["after_failure"] # the second is held inside the window + assert len(after_close) == 2 # and logged once uvicorn returned + assert after_close[1].startswith("TLS handshake failed on the API listener: 1 failed") + + +def test_the_api_record_logs_nothing_at_close_when_nothing_is_held(tmp_path: Path) -> None: + ctx, _cert_path = _server_ctx(tmp_path) + record = ApiHandshakeRecord(ctx) + collect = _Collect() + tls_log = logging.getLogger("messagefoundry.api.tls") + tls_log.addHandler(collect) + try: + record.close() + finally: + tls_log.removeHandler(collect) + assert _api_records(collect.records) == []