diff --git a/docs/BACKLOG.md b/docs/BACKLOG.md index f8ef769..6c5b1fb 100644 --- a/docs/BACKLOG.md +++ b/docs/BACKLOG.md @@ -8596,3 +8596,57 @@ The `startswith(MARKER_PREFIX)` half stays in every case. **Meets #344 instance 2 at the 1222.** That item (found independently and concurrently) traces the far end of this same chain: a contended head raises 1222, the store swallows it as a normal EMPTY, and the dispatcher goes to phase IDLE with no timer armed — **a test-rig gap, not an engine defect**, since production's periodic sweep re-readies such a lane and the ADR 0070 tests disable that sweep deliberately. Nothing here contradicts that and this item's severity is **not** escalated on it. What this adds is a **duration profile**: #344 assumes momentary producer contention, whereas a connection poisoned by *this* defect holds its `queue` X locks for as long as it sits unclaimed in the pool's free deque, so the 1222 can repeat across successive sweep ticks instead of clearing on the next. Cited by ledger number, not SHA — that branch is unpushed and may be rebased. **Source:** secondary lead from a PR #138 CI diagnosis, 2026-08-02; confirmed by live reproduction rather than by the reasoning in the lead, two of whose premises proved false. + +## 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.** + +## 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. + +## 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. diff --git a/messagefoundry/logging_setup.py b/messagefoundry/logging_setup.py index ec8e466..5fb3c09 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: diff --git a/tests/test_logging.py b/tests/test_logging.py index 1d5d8a9..02da819 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