From 9e725012cab74f8879090af27001dcbb3849d029 Mon Sep 17 00:00:00 2001 From: wshallwshall Date: Sun, 2 Aug 2026 14:46:47 -0500 Subject: [PATCH 1/3] fix(tests): two logging tests could self-connect to their own hardcoded port (BACKLOG #349) Both tests asserted a down collector by connecting to a hardcoded high port on the premise "port N is unbound -> connect raises OSError". That premise is unsound on Windows for any port in the dynamic range: SysLogHandler.createSocket issues a BLIND connect (it never bind()s), so the kernel draws the socket's own SOURCE port from that same range. When the allocator hands it the DESTINATION port, TCP simultaneous open connects the socket to itself, connect() succeeds with nothing listening, and `installed` is True. Reproduced on the real syscall path: local == peer, SO_ERROR 0. The contract under test is "an OSError raised while BUILDING the handler is tolerated", not "port N is closed", so the refusal is now injected at the syscall seam. The real _build_syslog_handler, the real tcp/tls/udp dispatch and the real except-OSError warn path are all still exercised; the test is deterministic instead of merely improbable. Patch createSocket, NOT socket.create_connection: SysLogHandler uses getaddrinfo + socket.socket() + sock.connect() and never touches create_connection, so that patch would intercept nothing and leave the flake shipping. The TLS sibling gets the same treatment. It was never safe, only lucky -- after a self-connect it reads back its own ClientHello and dies with ssl.SSLError, an OSError subclass, so its assertions passed by accident. --- docs/BACKLOG.md | 24 ++++++++++++++++++++++++ tests/test_logging.py | 41 ++++++++++++++++++++++++++++++++++++----- 2 files changed, 60 insertions(+), 5 deletions(-) diff --git a/docs/BACKLOG.md b/docs/BACKLOG.md index 0ec8bf72..b876a802 100644 --- a/docs/BACKLOG.md +++ b/docs/BACKLOG.md @@ -8567,3 +8567,27 @@ The `startswith(MARKER_PREFIX)` half stays in every case. **ADR 0158 — the taxonomy, and where this item sits in it.** Cited by **rule**, not just by number, because the rule is what transfers: *"An equality check satisfiable by coincidence is not an equality check."* That is this defect exactly. By the ADR's own one-line test for **Class 2** — *a control that cannot observe or act on its own failure*: **if this control were broken, what would tell me?** If the encryption were replaced tomorrow with a weak encoding, `"DOE" not in raw` would still go green. The answer is the control, which is the defect. *(Deliberately unlinked: the ADR is on PR #145's branch and not yet on `main`, so a relative link would render broken. Guessing its filename from its title is the same failure mode this item is about — it was guessed, checked, and was wrong.)* **Follow-up, deliberately not done here:** file this against ADR 0158 **once 0158 is on `main`**. Padding a document at merge time with instances its author did not choose is its own defect, and the ADR's instances are attributed by convention. **Source:** PR #142 (BACKLOG #323 layer 3, SMTP TLS), 2026-08-02 — observed on that PR's CI and deliberately **not** fixed there, because it is unrelated to the SMTP change and widening the PR would have obscured it. **Provenance is itemised, not aggregated** — "produced by N sessions" is a confidence claim, and an unsourced one of exactly that shape is what this item is about. **Rates:** derived here exactly, reproduced independently by the #142 session at N=144, recomputed analytically by #344's owner; the 200k-trial simulation came with the originating report. **Sibling audit:** derived twice from different scopes and reconciled. **Instrument-first framing, the ≥6 rule, the leave-the-rest-alone scoping:** from the #142 session's review. **The "infinitely fast machine" discriminator:** from #344's owner. **The demand to falsify the banner gate before trusting its green:** from the #346 session. No claim here rests on a count of who agreed. **Verification of this filing's own instruments:** every probability recomputed by two methods that agree (`Fraction` and `-expm1(N*log1p(-x))`), the audit counts re-derived from the working tree rather than quoted, and `backlog_status_check.py` **falsified against this item** — a deliberately doubled banner made it fail at `BACKLOG.md:8429` naming #347, so its green is evidence that it can see this item rather than evidence it skipped it. + +## 349. Two logging tests connect to a hardcoded ephemeral-range port and can self-connect + +> ✅ **Status CLOSED (filed + fixed 2026-08-02).** `test_configure_logging_tolerates_unreachable_tcp_collector` connected to `127.0.0.1:65500` on the stated premise *"Port 65500 is unbound → connect raises OSError."* **That premise is unsound on Windows for any port in 49152-65535.** `SysLogHandler.createSocket` issues a **blind** connect — it never calls `bind()` — so the kernel draws the socket's own **source** port from the same dynamic range (measured `netsh int ipv4 show dynamicport tcp`: start 49152, number 16384). When the allocator hands that socket the **destination** port, the SYN matches itself, TCP simultaneous open (RFC 793) establishes the socket **to itself**, `connect()` returns success with nothing listening anywhere, and `installed` is `True`. Fixed by injecting the refusal at the syscall seam instead of over the network. + +**Cluster:** Testing & CI. **Priority:** P2. **Verdict:** built. **Severity:** medium (a red that reads as the PR's own defect), low (likelihood: ~1/16384 per connect). + +**Reproduced on the real syscall path**, not inferred: non-blocking connects to an unbound loopback port, qualified by `select()` writability **plus** `SO_ERROR == 0` **plus** a non-`0.0.0.0` local address — deliberately avoiding the `getpeername()`-on-pending-connect false positive. Source ports marched 58357 → 58396 and on the attempt that drew the destination port the socket **established with `local == peer == ('127.0.0.1', 58396)`**, `SO_ERROR 0`. An explicit `bind(65500)` + `connect(65500)` succeeds identically: **the allocator does not skip the destination port.** + +**`installed is True` strictly entails a successful connect** — verified from CPython 3.14.6 source and re-demonstrated locally. `logging_setup.py` sets `forwarder_installed = True` only in the `else:` of `try: _build_syslog_handler(...) except OSError`. In stdlib `handlers.py` the **inet** branch ends `if err is not None: raise err`; the *"not regarded as an error if the other end isn't listening"* swallow applies **only** to the `isinstance(address, str)` AF_UNIX branch. Local negative control: with `createSocket` patched to succeed, `installed=True` (the observed CI failure); patched to raise, `installed=False`. + +**⛔ The obvious fix is wrong.** "Bind a socket, read the assigned port, close it, use that" returns a port **from the ephemeral range by construction** — precisely the enabling precondition — and was demonstrated self-connectable on its own output. It appears to pass only because Windows allocates forward-sequentially with the cursor one step past the returned port: undocumented behaviour on a **system-wide** cursor shared with every other process. **This repo had already retired that antipattern** — [`tests/test_load_runner.py`](../tests/test_load_runner.py) documents the TOCTOU race verbatim. A live instance still ships at `tests/test_connection_api.py:61-67` (`_dead_port`) and was **not** fixed here. + +**The fix, and the trap in it.** The contract under test is *"an `OSError` raised while **building** the handler is tolerated"* — **not** *"port X is closed."* Both tests now `monkeypatch.setattr(_TimeoutSysLogHandler | _TlsSysLogHandler, "createSocket", …)` to raise `ConnectionRefusedError`, matching an idiom already used in the same file. The real `_build_syslog_handler`, the real tcp/tls/udp dispatch and the real `except OSError` warn path are all still exercised. ⭐ **Patch `createSocket`, NOT `socket.create_connection`** — `SysLogHandler` uses `getaddrinfo` + `socket.socket()` + `sock.connect()` and never touches `create_connection`, so that patch intercepts nothing and ships a still-flaky test. Two independent analyses got this wrong. + +**The TLS sibling (port 65501) was fixed too, and was never safe — only lucky.** After a self-connect the client reads back its own ClientHello and dies with `ssl.SSLError`, an `OSError` subclass, so its assertions still passed. Self-healing by accident is not a property to rely on. + +**⛔ NOT repo-wide, and the "repo-wide" label was itself the costly error.** This test has failed on **one branch, one run, one job — ever**, established by two exhaustive scans (131 and 154 failed-job logs, the latter covering all 66 failed runs, the earlier attempts of all 15 re-run runs, and the 7 failed test jobs inside 208 cancelled runs) with **verified positive controls** — the same pipeline extracted 554 other `FAILED tests/...` lines, so the zeros are true negatives. For scale, genuinely repo-wide reds here show **129 / 69 / 27** occurrences. **It did not block PR #150:** `git diff origin/main <#150 head> -- tests/test_logging.py messagefoundry/logging_setup.py` is **empty** — the test and code at the failing commit are byte-identical to `main`, and #150's diff is `scorecard.py` + its test. Re-running that one job was the entire remedy. + +**⚠️ Mechanism CONFIRMED as sufficient, NOT as observed.** Nobody saw it happen in the failing job: the log carries **zero port telemetry** and no captured stdout, and a transient ephemeral listener held by any unrelated runner process produces an identical observable. All socket measurement was taken on a Windows 11 26200 host that is measurably non-stock (a refused loopback connect takes ~2.0s vs ~1ms to a live listener, indicating a filter driver) — **the windows-2022 runner's own dynamic range and port exclusions were never measured**, and if 65500 is excluded there the mechanism is impossible on the only OS where it has ever fired. The observed rate also underpredicts by ~15x. Not chased further: **the fix is identical under both surviving hypotheses.** + +**Related:** #350 (found in the same module during this work), #351 (same defect class — an environmental assumption asserted as fact), #347 and ADR 0158 (an assertion that passes for a reason unrelated to the property it tests). + +**Source:** the windows-2022 leg of an unrelated PR's CI run, 2026-08-02. A prior handoff attributed it to "the OS handing 65500 to any process opening an outbound socket during a 21-minute **parallel** run" — **refuted twice over**: a port held as another socket's ESTABLISHED **source** port is measurably *not* connectable (that conflates *in use* with *in LISTEN*), and there is no `pytest-xdist` (`addopts` is `--timeout=60 --timeout-method=thread`), so pytest runs **serially** and there is no parallelism for a race to occur in. Its dynamic-range premise survives and is what enables the real mechanism: **the right fact for the wrong reason.** diff --git a/tests/test_logging.py b/tests/test_logging.py index 1d5d8a96..02da8193 100644 --- a/tests/test_logging.py +++ b/tests/test_logging.py @@ -396,12 +396,31 @@ def test_configure_logging_forwarder_text_format_uses_plain_formatter() -> None: def test_configure_logging_tolerates_unreachable_tcp_collector( + monkeypatch: pytest.MonkeyPatch, capsys: pytest.CaptureFixture[str], ) -> None: # A down TCP collector must not crash startup: configure_logging warns and runs without it, so the - # engine's availability never hinges on the SIEM. Port 65500 is unbound → connect raises OSError. + # engine's availability never hinges on the SIEM. + # + # The refusal is injected at the syscall seam instead of by connecting to a "known-closed" port, + # because no port is reliably closed here (BACKLOG #349). SysLogHandler.createSocket issues a BLIND + # connect — it never bind()s — so the kernel draws its SOURCE port from the dynamic range that any + # hardcoded high port also sits in. When the allocator hands the socket the destination port, TCP + # simultaneous open connects it to ITSELF: connect() returns success with nothing listening anywhere + # and `installed` is True. That fired once on windows-2022 and read as the PR's own defect. + # The contract under test is "an OSError while BUILDING the handler is tolerated" — not "port X is + # closed" — so removing the network makes it deterministic instead of merely improbable. + from messagefoundry.logging_setup import _TimeoutSysLogHandler + + def _refuse(self: Any) -> None: + raise ConnectionRefusedError("collector down") + + # Patch createSocket, NOT socket.create_connection: SysLogHandler uses getaddrinfo + socket() + + # sock.connect() and never touches create_connection, so that patch would intercept nothing and + # leave the flake shipping. The port below is inert — nothing connects. + monkeypatch.setattr(_TimeoutSysLogHandler, "createSocket", _refuse) installed = configure_logging( - "INFO", forward=SyslogForward(host="127.0.0.1", port=65500, protocol="tcp") + "INFO", forward=SyslogForward(host="127.0.0.1", port=514, protocol="tcp") ) assert installed is False # the forwarder was NOT installed… assert len(logging.getLogger().handlers) == 1 # …only stdout remains @@ -593,13 +612,25 @@ def test_build_syslog_handler_selects_tls_and_wires_context( def test_configure_logging_tolerates_unreachable_tls_collector( + monkeypatch: pytest.MonkeyPatch, capsys: pytest.CaptureFixture[str], ) -> None: - # A down TLS collector must be best-effort exactly like TCP: the connect to an unbound port raises - # OSError before any handshake, configure_logging warns and runs without the forwarder. + # A down TLS collector must be best-effort exactly like TCP: an OSError raised before/at the + # handshake leaves configure_logging warning and running without the forwarder. + # + # Same seam, same reason as the TCP sibling (BACKLOG #349): the old hardcoded 65501 was in the + # dynamic range and self-connectable. This one merely *looked* safe — after a self-connect the + # client reads back its own ClientHello and dies with ssl.SSLError, an OSError subclass, so the + # assertions still passed. It was self-healing by accident, which is not a property to rely on. + from messagefoundry.logging_setup import _TlsSysLogHandler + + def _refuse(self: Any) -> None: + raise ConnectionRefusedError("collector down") + + monkeypatch.setattr(_TlsSysLogHandler, "createSocket", _refuse) installed = configure_logging( "INFO", - forward=SyslogForward(host="127.0.0.1", port=65501, protocol="tls", tls_verify=False), + forward=SyslogForward(host="127.0.0.1", port=6514, protocol="tls", tls_verify=False), ) assert installed is False assert len(logging.getLogger().handlers) == 1 # only stdout remains From 34d8278a85575e81a0fb9388e268d1f6446fbaea Mon Sep 17 00:00:00 2001 From: wshallwshall Date: Sun, 2 Aug 2026 14:47:17 -0500 Subject: [PATCH 2/3] fix(logging): the syslog startup connect was unbounded (BACKLOG #350) _TimeoutSysLogHandler captured `timeout=` into self._sock_timeout and then called super().__init__(*args, **kwargs) WITHOUT it, so self.timeout stayed None. In stdlib handlers.py the inet branch runs `if self.timeout: sock.settimeout(self.timeout)` BEFORE sock.connect(sa) -- that is the only thing bounding the STARTUP connect. This class's own settimeout runs in createSocket AFTER super().createSocket() has already returned, so it could bound later sends and reconnects but never the initial connect. _FORWARD_TCP_TIMEOUT = 5.0 exists precisely so a stalled collector cannot block the calling thread (the asyncio event loop), yet the one connect made during engine startup ran under the OS default instead -- contradicting this class's own docstring and _build_syslog_handler's. A collector host that silently DROPS SYNs rather than refusing them would stall engine start. logging.handlers.SysLogHandler.__init__ has accepted `timeout=` all along; it was simply never passed. Routed through kwargs rather than passed explicitly because `timeout` is also SysLogHandler's 4th POSITIONAL parameter, making super().__init__(*args, timeout=...) a possible double-bind that mypy strict rejects. Every construction site here is keyword-only, so this is equivalent at runtime. Found while fixing #349; unrelated to it beyond sharing the module. --- docs/BACKLOG.md | 16 ++++++++++++++++ messagefoundry/logging_setup.py | 12 ++++++++++++ 2 files changed, 28 insertions(+) diff --git a/docs/BACKLOG.md b/docs/BACKLOG.md index b876a802..53e4bfac 100644 --- a/docs/BACKLOG.md +++ b/docs/BACKLOG.md @@ -8591,3 +8591,19 @@ The `startswith(MARKER_PREFIX)` half stays in every case. **Related:** #350 (found in the same module during this work), #351 (same defect class — an environmental assumption asserted as fact), #347 and ADR 0158 (an assertion that passes for a reason unrelated to the property it tests). **Source:** the windows-2022 leg of an unrelated PR's CI run, 2026-08-02. A prior handoff attributed it to "the OS handing 65500 to any process opening an outbound socket during a 21-minute **parallel** run" — **refuted twice over**: a port held as another socket's ESTABLISHED **source** port is measurably *not* connectable (that conflates *in use* with *in LISTEN*), and there is no `pytest-xdist` (`addopts` is `--timeout=60 --timeout-method=thread`), so pytest runs **serially** and there is no parallelism for a race to occur in. Its dynamic-range premise survives and is what enables the real mechanism: **the right fact for the wrong reason.** + +## 350. _TimeoutSysLogHandler never forwards timeout to the stdlib ctor, leaving the startup connect unbounded + +> ✅ **Status CLOSED (filed + fixed 2026-08-02).** `_TimeoutSysLogHandler.__init__` captured `timeout=` into `self._sock_timeout` and called `super().__init__(*args, **kwargs)` **without it**, so `self.timeout` stayed `None`. In stdlib `handlers.py` the inet branch runs `if self.timeout: sock.settimeout(self.timeout)` **before** `sock.connect(sa)` — that is the only thing bounding the **startup** connect. The subclass's own `settimeout` runs in `createSocket` *after* `super().createSocket()` has already returned, so it can bound later sends and reconnects but never the initial connect. + +**Cluster:** Observability & Ops. **Priority:** P3. **Verdict:** built. **Severity:** low (needs a collector host that DROPS rather than refuses), low (likelihood). + +**Why it matters.** `_FORWARD_TCP_TIMEOUT = 5.0` existed precisely so a stalled collector could not block the calling thread — the asyncio event loop — yet the one connect made during engine startup ran under the OS default instead. This contradicted the class's own docstring (*"pins a socket timeout on its socket … so a runtime send to a stalled TCP collector can't block the calling thread indefinitely"*) and `_build_syslog_handler`'s. A collector host that silently **drops** SYNs rather than refusing them would stall engine start; under pytest it would hang to the 60s watchdog. + +**Confirmed by source, not by symptom.** `logging.handlers.SysLogHandler.__init__` in CPython 3.14.6 is `(self, address=('localhost', 514), facility=1, socktype=None, timeout=None)` — the parameter has been accepted all along and was simply never passed. + +**Implementation note.** The timeout is routed through `kwargs` rather than passed explicitly: `timeout` is also `SysLogHandler`'s **4th positional** parameter, so `super().__init__(*args, timeout=…)` is a possible double-bind that **mypy strict rejects outright** (caught by the checker, not by review). Every construction site is keyword-only, so this is equivalent at runtime. + +**Related:** #349 (same module; this was found while fixing that). + +**Source:** adversarial review of #349, 2026-08-02 — an incidental finding, not the thing being looked for. diff --git a/messagefoundry/logging_setup.py b/messagefoundry/logging_setup.py index ec8e466d..5fb3c095 100644 --- a/messagefoundry/logging_setup.py +++ b/messagefoundry/logging_setup.py @@ -235,6 +235,18 @@ class _TimeoutSysLogHandler(logging.handlers.SysLogHandler): def __init__(self, *args: Any, timeout: float | None = None, **kwargs: Any) -> None: self._sock_timeout = timeout + # Forward the timeout to the stdlib ctor as well (BACKLOG #350). SysLogHandler.createSocket + # applies `self.timeout` via settimeout() *before* sock.connect(), so this is the only thing + # that bounds the STARTUP connect; our own settimeout in createSocket runs after connect has + # already returned and can bound nothing but later sends/reconnects. Without this the startup + # connect fell back to the OS default — on a collector host that DROPS rather than refuses, + # that stalls engine start, contradicting this class's own "can't block the calling thread" + # contract and _build_syslog_handler's docstring. + # Routed through kwargs rather than passed explicitly: `timeout` is also SysLogHandler's 4th + # POSITIONAL parameter, so `super().__init__(*args, timeout=...)` is a possible double-bind + # that mypy rejects outright. Every construction site here is keyword-only, so this is + # equivalent at runtime and honest to the checker. + kwargs["timeout"] = timeout super().__init__(*args, **kwargs) # SysLogHandler.__init__ calls createSocket() (3.11+) def createSocket(self) -> None: From e298222f148c553ed3ebc4417dc0356f11441afb Mon Sep 17 00:00:00 2001 From: wshallwshall Date: Sun, 2 Aug 2026 14:47:43 -0500 Subject: [PATCH 3/3] =?UTF-8?q?backlog:=20file=20#351=20=E2=80=94=20a=20fa?= =?UTF-8?q?ilover=20test=20asserting=20on=20a=200.35s=20wall-clock=20margi?= =?UTF-8?q?n?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit tests/test_cluster_failover_sqlserver.py::test_preferred_delay0_wins_expired_lease_race_over_delayed_node sleeps _TTL + 0.15 so the lease is expired by ~0.15s, then requires a node carrying a 0.5s acquire handicap to be rejected. Correctness therefore rests on under 0.35s of wall clock elapsing across a real SQL Server round-trip on a shared CI runner. Filed, deliberately NOT fixed. On the SAME commit the 2022 leg passed while 2025 failed, and a broken delay predicate would fail on both since that logic is backend-version independent -- so the cause is latency versus margin, not the predicate. But that does NOT exonerate the change it fired on: BACKLOG #348 / ADR 0159 adds work at the _acquire chokepoint, the exact connection path this test round-trips through, so it may be the trigger without being wrong. Distinguishing "marginal test tipped by added latency" from "real regression" needs that change's author. Widening the margin now would convert a visible question into a silent one. Same defect class as #349: an environmental assumption asserted as fact. --- docs/BACKLOG.md | 14 ++++++++++++++ 1 file changed, 14 insertions(+) diff --git a/docs/BACKLOG.md b/docs/BACKLOG.md index 53e4bfac..1f97c915 100644 --- a/docs/BACKLOG.md +++ b/docs/BACKLOG.md @@ -8607,3 +8607,17 @@ The `startswith(MARKER_PREFIX)` half stays in every case. **Related:** #349 (same module; this was found while fixing that). **Source:** adversarial review of #349, 2026-08-02 — an incidental finding, not the thing being looked for. + +## 351. SQL Server failover test asserts on a 0.35s wall-clock margin across a real DB round-trip + +> 🚧 **Status OPEN (filed 2026-08-02).** `tests/test_cluster_failover_sqlserver.py::test_preferred_delay0_wins_expired_lease_race_over_delayed_node` sleeps `_TTL + 0.15` so the lease is expired by ~0.15s, then requires a node carrying a **0.5s** acquire handicap to be rejected. Correctness therefore rests on **less than 0.35s of wall clock** elapsing between the sleep and `dr._maintain_leadership()` — across a real SQL Server round-trip, on a shared CI runner. Observed failing as `assert dr.is_leader() is False → assert True is False`. + +**Cluster:** Testing & CI. **Priority:** P3. **Verdict:** triage — **do not "fix" by widening the margin until the question below is answered.** **Severity:** medium (a red that reads as the PR's own defect), unknown (likelihood: one observation). + +**The discriminating evidence.** On the **same commit**, the `sql server (store + connector) 2022` leg PASSED while `2025` FAILED. A genuinely broken delay predicate would fail on both — that logic is backend-version independent. The job log also states `Command failed with exit 1 (not a native crash) — not retrying`, so this is **not** the pyodbc 3.14 segfault and its retry mitigation is not involved. Across the last 12 runs it was the **only** sql-server-leg failure, and a sibling PR on the same `main` passed both legs — so it is **not** repo-wide either. + +**⚠️ What this does NOT establish.** It does not exonerate the PR it fired on. That PR (BACKLOG #348 / ADR 0159) adds work at the `_acquire` chokepoint — **the exact connection path this test round-trips through** — so it may be the *trigger* without being *wrong*: it spent latency the test had no headroom for. **Distinguishing "marginal test tipped by added latency" from "real regression in the delay predicate" needs that change's author**, and is why this is filed rather than patched. Widening the margin before answering it would convert a visible question into a silent one. + +**Related:** #349 (same defect class: an environmental assumption asserted as fact), #347, ADR 0158. + +**Source:** CI on an unrelated PR, 2026-08-02, observed while driving the merge queue.