Test suite stabilization: root-cause the 502 flake, zero resource leaks, -33% runtime, timing observability #112

Merged

adrian.tkacz merged 8 commits from fix/test-suite-stabilization into develop 2026-09-22 20:17:13 +00:00

Conversation 2 Commits 8 Files changed 16 +346 -62

kilo commented 2026-09-22 18:35:20 +00:00

Member

Copy link

Closes #111.

Root causes found (with evidence)

1. The intermittent 502 backend_failure in PackagedWorkerPathTests — a real product lifecycle bug.
default_connect_factory left socket.create_connection's 10 s timeout active for the whole worker session. With the server-advertised 15 s heartbeat cadence, read-silence gaps longer than 10 s are routine, so the worker's read loop hit the socket timeout, treated the healthy session as lost, and tore it down (server logs the session close; worker reconnects with backoff and re-probes). A dispatch landing in that flap window found no authenticated session for the resource → AdapterPermanentError → 502. Reproduced under CPU saturation:

• one batch: 502 with SR-DIAG session close: connection error server-side and a silent worker (adapter never failed — proving the server-side flap);
• standalone 20/20 passed (dispatch always beat the 10 s mark locally).

Fix: the established session socket gets SESSION_IO_TIMEOUT_SECONDS = 60 (protocol-sane ceiling, far above the heartbeat cadence); request_stop() now also closes the active transport so a blocked read unwinds deterministically. Validated: 40/40 packaged-test passes under full 12-core saturation (previously failing ~1 in 8–10 runs).

2. Second, independent flake in the same test (~1/64 runs): pairing codes beginning with -.
secrets.token_urlsafe codes can start with -; argparse then treats the code as a flag (--code: expected one argument). Reproduced once under load. Fixed at issuance (leading - redrawn, unit-pinned) and the test passes --code=<code>. This also fixes the same defect for real administrators pairing real devices.

3. ResourceWarnings (70 in the baseline full-gate log). Product: probe_codex_version and CodexSession left child stdout/stderr pipe handles unclosed (warnings firing inside worker_codex_adapter.py), stderr drainer unjoined. Tests: stop_worker_process never drained/closed the worker's pipes, in-process CodexWorker never closed captured TLS transports, unclosed http.client connections in test_gateway_server, one open(...).read(). All ownership made deterministic (verified via PYTHONTRACEMALLOC attribution + -W always::ResourceWarning per-file runs).

4. Timing pathology. The flap imposed a ~10 s constant on ~20 composed-worker E2E tests (baseline profile: 15–26 s each). Two further timeout-waiting tests fixed: RemoteBridgeTests cleanup order (server_close before shutdown spun the serve thread; join(5) always burned its ceiling) and the startup-banner test consuming a 20 s subprocess timeout to read a banner that is flushed at startup.

Results

	before	after
make check (wall)	746.4 s	511 s (test phase 721.5 s → 416.0 s, −42%)
full-gate ResourceWarnings	70	0
flaky test (20×)	flaky (CI run #31 failure)	20/20 PASS
Codex E2E file (5×)	—	5/5 PASS, 0 warnings each
orphan subprocesses/threads after teardown	flap-driven churn	0 (census unchanged across all stages)
loaded validation (12-core saturation, 40×)	~1 fail / 8–10	40/40 PASS
slowest test in the suite	26.3 s	7.6 s

Timing observability: SR_TEST_TIMING=1 make test (and CI's check step) prints the fifteen slowest tests and total test wall time via the new ~70-line tools/test_runner.py — no new dependencies, no new make targets, no extra CI statuses.

Scope discipline

One gate (make check) unchanged; no make acceptance, no make release-check, no pytest, no retries, no timeout-bumping as a fix, no coverage removed (1895 tests before, 1896 after — one new unit test). No provider/routing behavior changed beyond the lifecycle bug the 502 proved.

Validation

• make check exit 0 (1896 tests, 416.0 s) with 0 ResourceWarnings
• make package-check exit 0; make guardrails exit 0 (40 tests); git diff --check clean
• basedpyright: 0 errors, 0 warnings, 0 notes
• Forgejo CI: run #1902 success on this PR head
• Independent review (GLM-5.3-Flash, thinking=MAX): APPROVE — verdict and finding-by-finding disposition in the review comment

Closes #111. ## Root causes found (with evidence) **1. The intermittent `502 backend_failure` in `PackagedWorkerPathTests` — a real product lifecycle bug.** `default_connect_factory` left `socket.create_connection`'s 10 s timeout active for the whole worker session. With the server-advertised 15 s heartbeat cadence, read-silence gaps longer than 10 s are routine, so the worker's read loop hit the socket timeout, treated the healthy session as lost, and tore it down (server logs the session close; worker reconnects with backoff and re-probes). A dispatch landing in that flap window found no authenticated session for the resource → `AdapterPermanentError` → 502. Reproduced under CPU saturation: - one batch: 502 with `SR-DIAG session close: connection error` server-side and a **silent** worker (adapter never failed — proving the server-side flap); - standalone 20/20 passed (dispatch always beat the 10 s mark locally). Fix: the established session socket gets `SESSION_IO_TIMEOUT_SECONDS = 60` (protocol-sane ceiling, far above the heartbeat cadence); `request_stop()` now also closes the active transport so a blocked read unwinds deterministically. Validated: **40/40 packaged-test passes under full 12-core saturation** (previously failing ~1 in 8–10 runs). **2. Second, independent flake in the same test (~1/64 runs): pairing codes beginning with `-`.** `secrets.token_urlsafe` codes can start with `-`; argparse then treats the code as a flag (`--code: expected one argument`). Reproduced once under load. Fixed at issuance (leading `-` redrawn, unit-pinned) and the test passes `--code=<code>`. This also fixes the same defect for real administrators pairing real devices. **3. ResourceWarnings (70 in the baseline full-gate log).** Product: `probe_codex_version` and `CodexSession` left child stdout/stderr pipe handles unclosed (warnings firing inside `worker_codex_adapter.py`), stderr drainer unjoined. Tests: `stop_worker_process` never drained/closed the worker's pipes, in-process `CodexWorker` never closed captured TLS transports, unclosed `http.client` connections in `test_gateway_server`, one `open(...).read()`. All ownership made deterministic (verified via `PYTHONTRACEMALLOC` attribution + `-W always::ResourceWarning` per-file runs). **4. Timing pathology.** The flap imposed a ~10 s constant on ~20 composed-worker E2E tests (baseline profile: 15–26 s each). Two further timeout-waiting tests fixed: `RemoteBridgeTests` cleanup order (server_close before shutdown spun the serve thread; join(5) always burned its ceiling) and the startup-banner test consuming a 20 s subprocess timeout to read a banner that is flushed at startup. ## Results | | before | after | |---|---|---| | `make check` (wall) | 746.4 s | 511 s (test phase 721.5 s → **416.0 s, −42%**) | | full-gate ResourceWarnings | 70 | **0** | | flaky test (20×) | flaky (CI run #31 failure) | **20/20 PASS** | | Codex E2E file (5×) | — | **5/5 PASS, 0 warnings each** | | orphan subprocesses/threads after teardown | flap-driven churn | **0** (census unchanged across all stages) | | loaded validation (12-core saturation, 40×) | ~1 fail / 8–10 | **40/40 PASS** | | slowest test in the suite | 26.3 s | **7.6 s** | Timing observability: `SR_TEST_TIMING=1 make test` (and CI's check step) prints the fifteen slowest tests and total test wall time via the new ~70-line `tools/test_runner.py` — no new dependencies, no new make targets, no extra CI statuses. ## Scope discipline One gate (`make check`) unchanged; no `make acceptance`, no `make release-check`, no pytest, no retries, no timeout-bumping as a fix, no coverage removed (1895 tests before, 1896 after — one new unit test). No provider/routing behavior changed beyond the lifecycle bug the 502 proved. ## Validation - `make check` exit 0 (1896 tests, 416.0 s) with 0 ResourceWarnings - `make package-check` exit 0; `make guardrails` exit 0 (40 tests); `git diff --check` clean - basedpyright: 0 errors, 0 warnings, 0 notes - Forgejo CI: run [#1902](https://forgejo.creatidy.com/BioMedical-IT/scarcity-router/actions/runs/35) success on this PR head - Independent review (GLM-5.3-Flash, thinking=MAX): **APPROVE** — verdict and finding-by-finding disposition in [the review comment](https://forgejo.creatidy.com/BioMedical-IT/scarcity-router/pulls/112#issuecomment-11114)

kilo added 5 commits 2026-09-22 18:35:20 +00:00

fix(worker): stop reusing the connect timeout as the session I/O ceiling (issue #111) ... 73535dce8a

default_connect_factory left create_connection's 10 s timeout active for
the whole session. With the server-advertised 15 s heartbeat cadence,
idle gaps longer than 10 s are ROUTINE, so the worker read loop treated
healthy sessions as lost, tore down the TLS connection, reconnected with
backoff and re-probed — continuously. Under load, a dispatch landing in
that flap window saw the resource's session gone and failed with
AdapterPermanentError, surfacing as the intermittent 502 backend_failure
in PackagedWorkerPathTests (Forgejo run #31); a sibling drop mid-execution
resolves as ambiguous_execution_state (500).

The established socket now gets SESSION_IO_TIMEOUT_SECONDS (60 s) — far
above the heartbeat cadence, still a bounded ceiling for a dead peer.
request_stop() additionally closes the active session transport so a
read parked in recv unwinds deterministically instead of waiting on a
timeout.

fix(codex): account for every descriptor and thread in the adapter lifecycle (issue #111) ... cd3a031cb9

probe_codex_version left the child's stdout and stderr pipe handles open
after reaping, and CodexSession left its stderr drainer unjoined with the
stderr handle never closed (the reader owned only stdout). Every version
probe and every app-server session leaked up to two pipe fds that were
reclaimed only by GC — the source of the unclosed-BufferedReader
ResourceWarnings sprinkled through the suite log and of transient fd
growth under repeated probing.

Shutdown now owns its activities: the session joins the stderr drainer
and closes both pipe handles after the bounded terminate/kill/reap, and
the version probe closes both handles once it has read the version.

fix(workers): issue CLI-safe pairing codes (never begin with '-') (issue #111) ... cb0299327c

token_urlsafe codes can begin with '-' (1 in 64). Such a code passed on
the command line is read by argparse as a flag
('argument --code: expected one argument'), breaking the documented
pair invocation for the administrator pasting the code — reproduced as a
1-in-64 flake in the packaged-worker acceptance test. A leading '-' is
now redrawn at issuance; mid-code '-' stays legal.

test(m10): deterministic subprocess, socket and file ownership in the harnesses (issue #111) ... df4fe3c6cc

- stop_worker_process fully owns the worker subprocess: bounded
  terminate/kill/reap, then drain and close both pipes (idempotent),
  returning the captured output; the packaged test surfaces the worker's
  own stderr tail when the dispatch assertion fails, so the closed
  worker-side reason is visible instead of parked in an unread pipe.
- in-process CodexWorker.close closes every captured transport and raw
  socket explicitly; test factories mirror the production session I/O
  ceiling instead of leaving the 10 s connect timeout active.
- ServerHarness tracks and closes its HTTP client connections;
  AdapterCallImportGuard reads the module source with a with-block.
  Together with the product fixes this takes the suite to zero
  project-owned ResourceWarnings (verified with -W always and
  PYTHONTRACEMALLOC attribution).

test: SR_TEST_TIMING=1 slowest-tests observability for make test and CI (issue #111) ... bfd55dcb9a

make test now runs through tools/test_runner.py — plain unittest
discovery, unchanged by default; SR_TEST_TIMING=1 appends the fifteen
slowest tests and the total test wall time. CI sets the variable on the
existing check step, so the job log answers 'which tests are slow?'
without new tooling, extra statuses or workflow layers.

adrian.tkacz added 1 commit 2026-09-22 19:09:11 +00:00

test: replace timeout-waiting synchronization in the two slowest suite tests (issue #111) ... 42cceb2347

- RemoteBridgeTests._serve registered cleanups in an order that LIFO-ran
  server_close() BEFORE shutdown(): the serve loop was left spinning on a
  closed socket and thread.join(5) consumed its full timeout on every
  RemoteBridge test (5 s each; 20 s for the four-subTest contract test).
  Cleanups now run shutdown -> join -> server_close.
- test_startup_banner_reports_version spawned the real server and waited
  for a 20 s subprocess timeout to collect its banner. The banner is
  flushed at startup, so the test now reads until it appears (20 s kept
  as a safety ceiling), then terminates the child and drains/closes both
  pipes explicitly.

Together with the session-flap fix this removes every wait whose full
duration was consumed without producing evidence; measured on this host:
RemoteBridge cluster ~60 s -> ~4 s, banner 20.6 s -> ~1.5 s. The runner
also accepts optional test names, matching the unittest CLI ergonomics
for focused runs.

adrian.tkacz added 1 commit 2026-09-22 19:10:22 +00:00

test: annotate the banner subprocess as Popen[str] for the typecheck gate (issue #111) e2a360da8c

adrian.tkacz added 1 commit 2026-09-22 19:23:27 +00:00

test: remediation from the independent review of the stabilization branch (issue #111) ... 1620ce1b6e

- ScriptedWorker.next_execute's direct-read path now honors its timeout:
  each raw read is bounded to the remaining wait budget via the new
  SocketTransport.set_timeout, so a silence observation raises
  TimeoutError at the deadline (~2 s) instead of at the 10 s connection
  ceiling (scenario_12 measured 15.8 s -> ~6 s).
- Deterministic unit test pins the CLI-safe pairing-code grammar: a
  leading-'-' draw is redrawn at issuance (previously exercised only via
  the 1-in-64 e2e path).
- The banner test's stream read carries an explicit str annotation for
  the typecheck gate.

kilo commented 2026-09-22 19:31:39 +00:00

Author

Member

Copy link

Independent review verdict — APPROVE

Reviewer: fresh GLM-5.3-Flash (thinking=MAX), one pass, adversarial mandate of 13 points (issue #111 / PR #112). Reviewed commit bfd55dc; findings 1+2 below were fixed later on the branch (42cceb2) and findings 3+4 in the remediation commit 1620ce1.

Key confirmations (all with file:line evidence in the review record):

• 502 root cause independently reproduced and confirmed: the reviewer ran their own experiment — create_connection(timeout=10) leaves the 10 s timeout on the established socket, and a parked recv across a >10 s quiet gap raises TimeoutError at exactly 10.0 s; traced the full chain _read_loop → reconnect backoff → session_for_resource raising worker_offline → _begin → AdapterPermanentError → coordinator backend_failure/502. Cadence math verified: 15 s heartbeat gap > 10 s ceiling. Verdict: "HONEST" fix — the 60 s ceiling is a new protocol-sane bound (above the server's 45 s liveness kill), not the old timeout reused; no retries, no swallowed 502, assertion strengthened with worker-stderr evidence.
• Pairing-code flake confirmed: P(leading '-') = 1/64 for token_urlsafe; argparse misparses it. Fixed at issuance.
• Pipe/socket/thread ownership: "every descriptor owned" across probe, session, fixture and harness paths.
• Runtime justified: ~486 s for 1895 tests is genuine integration work (composed servers, real TLS, subprocess fake app-servers, scripted mid-turn pauses); reviewer identified only ~56 s of removable wait — which the two remediation commits then removed; final gate: 1896 tests in 416.0 s, 0 ResourceWarnings, slowest test 7.58 s.
• Coverage preserved (no test deleted/mocked), no release-readiness regression (37/37 worker-client+identity tests re-run by reviewer), no complexity (no make acceptance/release-check, no pytest, no dependencies).

DEFER findings and their disposition:

1. _serve() cleanup-order bug (5 s × every RemoteBridge test) — fixed in 42cceb2 (after the reviewed commit).
2. Startup-banner 20 s timeout wait — fixed in 42cceb2.
3. next_execute direct path ignoring its timeout — fixed in 1620ce1 (new SocketTransport.set_timeout; scenario_12 15.8 s → 7.6 s).
4. Pairing-code redraw lacked a deterministic unit test — added in 1620ce1 (mocked token_urlsafe).
5. request_stop closing a transport during the microscopic connect→register window unwinds via the 60 s ceiling — bounded, accepted, no action.

Gate on the final commit (1620ce1): make check exit 0 (1896 tests, 416.0 s), 0 ResourceWarnings, basedpyright 0/0/0, package-check exit 0, guardrails exit 0, git diff --check clean, orphan census unchanged (0 new).

## Independent review verdict — APPROVE Reviewer: fresh GLM-5.3-Flash (thinking=MAX), one pass, adversarial mandate of 13 points (issue #111 / PR #112). Reviewed commit bfd55dc; findings 1+2 below were fixed later on the branch (42cceb2) and findings 3+4 in the remediation commit 1620ce1. **Key confirmations (all with file:line evidence in the review record):** - **502 root cause independently reproduced and confirmed**: the reviewer ran their own experiment — `create_connection(timeout=10)` leaves the 10 s timeout on the established socket, and a parked recv across a >10 s quiet gap raises `TimeoutError` at exactly 10.0 s; traced the full chain `_read_loop` → reconnect backoff → `session_for_resource` raising `worker_offline` → `_begin` → `AdapterPermanentError` → coordinator `backend_failure`/502. Cadence math verified: 15 s heartbeat gap > 10 s ceiling. Verdict: "HONEST" fix — the 60 s ceiling is a new protocol-sane bound (above the server's 45 s liveness kill), not the old timeout reused; no retries, no swallowed 502, assertion strengthened with worker-stderr evidence. - **Pairing-code flake confirmed**: P(leading '-') = 1/64 for token_urlsafe; argparse misparses it. Fixed at issuance. - **Pipe/socket/thread ownership**: "every descriptor owned" across probe, session, fixture and harness paths. - **Runtime justified**: ~486 s for 1895 tests is genuine integration work (composed servers, real TLS, subprocess fake app-servers, scripted mid-turn pauses); reviewer identified only ~56 s of removable wait — which the two remediation commits then removed; **final gate: 1896 tests in 416.0 s, 0 ResourceWarnings, slowest test 7.58 s**. - **Coverage preserved** (no test deleted/mocked), **no release-readiness regression** (37/37 worker-client+identity tests re-run by reviewer), **no complexity** (no make acceptance/release-check, no pytest, no dependencies). **DEFER findings and their disposition:** 1. `_serve()` cleanup-order bug (5 s × every RemoteBridge test) — **fixed in 42cceb2** (after the reviewed commit). 2. Startup-banner 20 s timeout wait — **fixed in 42cceb2**. 3. `next_execute` direct path ignoring its timeout — **fixed in 1620ce1** (new `SocketTransport.set_timeout`; scenario_12 15.8 s → 7.6 s). 4. Pairing-code redraw lacked a deterministic unit test — **added in 1620ce1** (mocked `token_urlsafe`). 5. `request_stop` closing a transport during the microscopic connect→register window unwinds via the 60 s ceiling — bounded, accepted, no action. Gate on the final commit (1620ce1): `make check` exit 0 (1896 tests, 416.0 s), 0 ResourceWarnings, basedpyright 0/0/0, package-check exit 0, guardrails exit 0, `git diff --check` clean, orphan census unchanged (0 new).

adrian.tkacz approved these changes 2026-09-22 20:17:03 +00:00

adrian.tkacz merged commit 20db0433ed into develop 2026-09-22 20:17:13 +00:00

adrian.tkacz referenced this pull request from a commit 2026-09-22 20:17:13 +00:00

Merge pull request 'Test suite stabilization: root-cause the 502 flake, zero resource leaks, -33% runtime, timing observability' (#112) from fix/test-suite-stabilization into develop

adrian.tkacz deleted branch fix/test-suite-stabilization 2026-09-22 20:17:13 +00:00

Sign in to join this conversation.

Reviewers

No reviewers

adrian.tkacz

Labels

Clear labels   

accessibility

Barrier affecting people with disabilities

  

bug

Something isn't working

  

documentation

Improvements or additions to documentation

  

duplicate

This issue or pull request already exists

  

enhancement

New feature or request

  

good first issue

Good for newcomers

  

help wanted

Extra attention is needed

  

invalid

This doesn't seem right

  

P1

Owner-declared highest explicit implementation priority (loop ordering rank)

  

P2

Required product and integration work

  

P3

Deferred or producer-dependent work

  

question

Further information is requested

  

wontfix

This will not be worked on

No labels

accessibility

bug

documentation

duplicate

enhancement

good first issue

help wanted

invalid

P1

P2

P3

question

wontfix

Milestone

Clear milestone

No items

No milestone

Projects

Clear projects

No items

No project

Assignees

Clear assignees

No assignees

2 participants

Notifications

Subscribe

Due date

The due date is invalid or out of range. Please use the format "yyyy-mm-dd".

No due date set.

Dependencies

No dependencies set.

Reference

Creatidy/scarcity-router!112

No description provided.