fix(tests): a hardcoded ephemeral port could TCP self-connect, and the syslog startup connect was unbounded (BACKLOG #349, #350; files #351)

[wshallwshall]

Three findings from investigating a single CI red, landed as its own PR rather than folded into the PR it fired on — it is a shared-test defect, and coupling them would misattribute it.

BACKLOG #349 — two logging tests could self-connect (fixed)

Both tests asserted "collector is down" 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 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. When the allocator hands it the destination port, TCP simultaneous open (RFC 793) connects the socket to itself: connect() returns success with nothing listening anywhere, and installed is True.

Reproduced on the real syscall path (select() writability + SO_ERROR == 0 + non-0.0.0.0 local address, avoiding the getpeername()-on-pending-connect false positive): the socket established with 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 now comes from 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.

⚠️ 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 was fixed too. 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.

The "bind, read the port, close it, reuse it" fix was rejected — it returns a port from the ephemeral range by construction, the exact enabling precondition, and was demonstrated self-connectable on its own output. This repo had already retired that antipattern (tests/test_load_runner.py documents the TOCTOU race verbatim).

BACKLOG #350 — the syslog startup connect was unbounded (fixed)

_TimeoutSysLogHandler captured timeout= but never forwarded it to super().__init__, so self.timeout stayed None. Stdlib runs if self.timeout: sock.settimeout(self.timeout) before sock.connect(sa) — the only thing bounding the startup connect. The subclass's own settimeout runs after super().createSocket() returns, so it bounds later sends and reconnects but never the initial connect. _FORWARD_TCP_TIMEOUT = 5.0 existed precisely to stop a stalled collector blocking the event loop; the startup connect ran under the OS default instead, contradicting the class's own docstring.

Routed through kwargs because timeout is also SysLogHandler's 4th positional parameter — the explicit form is a double-bind that mypy strict rejects.

BACKLOG #351 — a failover test's 0.35s margin (filed, deliberately not fixed)

Filed only. On the same commit the SQL Server 2022 leg passed while 2025 failed, so the cause is latency vs margin rather than the delay predicate. But that does not exonerate the change it fired on (ADR 0159 adds work at the exact _acquire path the test round-trips through), and distinguishing "marginal test tipped by added latency" from "real regression" needs that change's author. Widening the margin now would turn a visible question into a silent one.

Scope correction

The red was previously labelled repo-wide. It is not: one branch, one run, one job — ever, across two exhaustive scans with verified positive controls. Genuinely repo-wide reds here show 129 / 69 / 27 occurrences. It also never blocked the PR it appeared on — git diff origin/main <that head> -- tests/test_logging.py messagefoundry/logging_setup.py is empty. Re-running the one job was the entire remedy.

The mechanism is confirmed sufficient, not confirmed observed — the failing job carries zero port telemetry, and a transient listener from any runner process yields an identical observable. Not chased further, because the fix is identical under both surviving hypotheses.

Verification

• ruff format --check / ruff check — clean
• mypy strict — no errors in changed files; total at the pre-existing 21-error baseline (pynetdicom stubs)
• pytest — 119 passing across every module importing logging_setup
• Negative control: with createSocket patched to succeed, installed=True (reproducing the CI failure); patched to raise, installed=False — the assertion discriminates
• Gate falsified against its own subject: a deliberately doubled banner made backlog_status_check.py fail naming #349, so its green means it can see these items

🤖 Generated with Claude Code