Skip to content

Commit a037b3a

Browse files
committed
fix(tests): stop transport flush thread between tests so it doesn't race respx
PR #60 landed the cancellable-sleep fix in Transport._flush_loop and expected CI wall-clock to drop to 3-5 minutes. The first green run on PR #60 (PR #60 run #1) actually took 9m 47s — the test step dominated by a retry storm: Request failed (attempt 5/11), retrying in 8.46s: ConnectError Request failed (attempt 6/11), retrying in 9.16s: ConnectError ... Circuit breaker OPEN. Batch of 10 events will be re-queued. Root cause: `tests/conftest.py:reset_runtime` teardown nulled the runtime reference WITHOUT calling `runtime.shutdown()`. The transport flush thread therefore kept running across tests, the buffer drained through httpx with no respx context active, and the xdist workers spent the next 9 minutes retry-sending the buffer against the real (unreachable in CI) backend. `_retry_with_backoff (max_retries=10, max_delay=10s)` is 65s of pure sleep per failed batch, and with 4 xdist workers and many buffered batches this multiplied into 9m 47s — i.e. a CI-noise fix that hid a deeper lifecycle bug. Pre-fix CI was already paying this cost (5s shutdown-sleep × 200+ tests ≈ 17 min of teardown per Python leg); the retry storm was always there but masked by the dominant 5s cost. PR #60's 5s fix exposed it. Fix: add `flush: bool = True` to both `Transport.stop()` and `NullRunRuntime.shutdown()`. When False, the transport thread is cancelled WITHOUT a final `_do_flush()` / `_persist_to_wal()`. `tests/conftest.py:reset_runtime` teardown now calls `inst.shutdown(flush=False)` before nilling the reference. This makes the conftest teardown a true no-op for the buffer — the test that wrote the events is responsible for asserting on what it cared about. The production default (`flush=True`) is preserved, so the `nullrun.shutdown()` audit contract ("drain in-flight events") is unchanged. Pins: * `tests/test_transport.py::test_stop_flush_false_skips_final_flush ` — buffers an event, calls `stop(flush=False)` with no respx active, asserts the call returns in <1s AND the buffer is left untouched. Pre-fix this would have hung for 65s+ on the first retry. * `tests/test_init_contract.py::TestShutdownFlushKwarg:: test_runtime_shutdown_flush_false_skips_final_flush` — same contract at the `NullRunRuntime` level: `shutdown(flush=False )` propagates the `flush=False` flag to `Transport.stop()`. Public API additions: * `Transport.stop(timeout=10.0, flush: bool = True)` — `flush =False` is the new flag. * `NullRunRuntime.shutdown(flush: bool = True)` — propagates. * `nullrun.shutdown(timeout=2.0, flush: bool = True)` — passes `flush` through to the runtime. No on-wire or production behaviour change. CI step is expected to drop from ~9m 47s (PR #60 run #1) to ~30-60s on the next run.
1 parent 99bc197 commit a037b3a

6 files changed

Lines changed: 172 additions & 11 deletions

File tree

src/nullrun/__init__.py

Lines changed: 9 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -41,7 +41,7 @@ def my_agent(query):
4141
from nullrun.runtime import track_event, track_llm, track_tool
4242

4343

44-
def shutdown(timeout: float = 2.0) -> None:
44+
def shutdown(timeout: float = 2.0, flush: bool = True) -> None:
4545
"""Gracefully shut down the NullRun runtime.
4646
4747
Sends a clean WebSocket close frame, drains in-flight events, and
@@ -62,6 +62,13 @@ def shutdown(timeout: float = 2.0) -> None:
6262
``NullRunRuntime.shutdown `` already caps WS join at
6363
0.5s and the WS close at 2.0s — this parameter is
6464
reserved for future expansion and is currently unused.
65+
flush: when True (default) the transport drains any
66+
buffered events to the backend on the way out. Pass
67+
False to cancel the flush thread without a final
68+
network call — used by the test conftest to teardown
69+
between tests without racing the respx context exit
70+
(see ``NullRunRuntime.shutdown(flush=False)`` for the
71+
full rationale).
6572
6673
Example::
6774
@@ -75,7 +82,7 @@ def shutdown(timeout: float = 2.0) -> None:
7582
runtime = NullRunRuntime._instance # type: ignore[attr-defined]
7683
if runtime is None:
7784
return
78-
runtime.shutdown()
85+
runtime.shutdown(flush=flush)
7986

8087

8188
def status():

src/nullrun/runtime.py

Lines changed: 15 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -1822,8 +1822,20 @@ def _auth_headers(self) -> dict[str, str]:
18221822
headers[HEADER_PROTOCOL] = _protocol_header_value()
18231823
return headers
18241824

1825-
def shutdown(self) -> None:
1826-
"""Shutdown runtime gracefully."""
1825+
def shutdown(self, flush: bool = True) -> None:
1826+
"""Shutdown runtime gracefully.
1827+
1828+
Args:
1829+
flush: when True (default) the transport drains any
1830+
buffered events to the backend on the way out — the
1831+
production "send everything you have before we go"
1832+
contract. When False, the transport thread is
1833+
cancelled without a final ``_do_flush()``. Used by
1834+
the test conftest to teardown between tests without
1835+
racing the respx context exit
1836+
(see ``Transport.stop(flush=False)`` for the full
1837+
rationale; observed 9m 47s CI noise on PR #60).
1838+
"""
18271839
# Stop the HTTP poller (legacy path) if it was started.
18281840
self._poll_running = False
18291841
if self._poll_thread and self._poll_thread.is_alive():
@@ -1847,7 +1859,7 @@ def shutdown(self) -> None:
18471859
self._ws_thread.join(timeout=0.5)
18481860

18491861
if self._transport:
1850-
self._transport.stop()
1862+
self._transport.stop(flush=flush)
18511863
NullRunRuntime._instance = None
18521864
logger.info("NullRun Runtime shutdown")
18531865

src/nullrun/transport.py

Lines changed: 22 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -807,8 +807,25 @@ def __exit__(self, exc_type, exc_val, exc_tb) -> None:
807807
except Exception as e: # noqa: BLE001 — best-effort on context exit
808808
logger.debug(f"Transport.__exit__: stop() raised: {e}")
809809

810-
def stop(self, timeout: float = 10.0) -> None:
811-
"""Stop background flush thread and flush remaining events."""
810+
def stop(self, timeout: float = 10.0, flush: bool = True) -> None:
811+
"""Stop background flush thread and flush remaining events.
812+
813+
Args:
814+
timeout: max seconds to wait for the flush thread to exit.
815+
flush: when True (default) the final ``_do_flush()`` and
816+
``_persist_to_wal()`` run after the thread joins — the
817+
production "drain on the way out" contract. When
818+
False, the thread is cancelled but the buffer is left
819+
alone. The test conftest uses ``flush=False`` to
820+
teardown between tests without a final httpx call —
821+
in tests the respx context has already exited by the
822+
time the conftest's teardown runs, so a final
823+
``_do_flush()`` would race respx and trigger a
824+
``ConnectError`` retry storm
825+
(observed: 9m 47s of "Request failed (attempt N/11),
826+
retrying in 10s" on PR #60, dominating the
827+
otherwise-fast xdist wall clock).
828+
"""
812829
self._running = False
813830
self._stopped = True # Mark as stopped to prevent double flush
814831
# Wake the flush thread out of its cancellable sleep so join()
@@ -820,8 +837,9 @@ def stop(self, timeout: float = 10.0) -> None:
820837
self._stop_event.set()
821838
if self._flush_thread:
822839
self._flush_thread.join(timeout=timeout)
823-
self._do_flush() # Final flush
824-
self._persist_to_wal() # WAL any remaining events
840+
if flush:
841+
self._do_flush() # Final flush
842+
self._persist_to_wal() # WAL any remaining events
825843
self._client.close()
826844
# Detach the weakref finalizer — stop is the canonical
827845
# "I am done" path. After this point the finalizer will

tests/conftest.py

Lines changed: 18 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -42,8 +42,24 @@ def reset_runtime():
4242

4343
yield
4444

45-
# Just clear references, don't call shutdown which may try HTTP calls
46-
# after respx mock context has already exited
45+
# Stop any running transport flush thread BEFORE we drop the
46+
# reference. Without this the thread keeps running across tests,
47+
# the buffer drains through httpx with no respx context active,
48+
# and the worker logs a ``ConnectError`` retry storm for the rest
49+
# of the xdist session — observed 9m 47s of "Request failed
50+
# (attempt N/11), retrying in 10s" on PR #60, which dwarfed the
51+
# actual test time. ``flush=False`` skips the final ``_do_flush``
52+
# / ``_persist_to_wal`` so the teardown is a true no-op even when
53+
# the buffer still has events; the test that wrote them is
54+
# responsible for asserting on what it cared about. Best-effort:
55+
# the runtime may be in any state at teardown, and we don't want
56+
# a flaky shutdown to mask the real test failure that just ran.
57+
inst = NullRunRuntime._instance
58+
if inst is not None:
59+
try:
60+
inst.shutdown(flush=False)
61+
except Exception:
62+
pass
4763
NullRunRuntime._instance = None
4864
_dec._runtime = None
4965
_act._action_handler = None

tests/test_init_contract.py

Lines changed: 55 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -16,6 +16,7 @@
1616
from __future__ import annotations
1717

1818
import threading
19+
import time
1920

2021
import pytest
2122

@@ -316,3 +317,57 @@ def test_init_logs_debug_when_probe_raises(
316317
rt.shutdown()
317318
finally:
318319
_caps_mod.probe_capabilities = original_probe
320+
321+
322+
class TestShutdownFlushKwarg:
323+
"""Regression pin for the PR #60 follow-up: ``shutdown(flush=...)``
324+
must propagate to ``Transport.stop(flush=...)`` so the test
325+
conftest can teardown between tests without racing the respx
326+
context exit. Pre-this-pin, the conftest's teardown just nulled
327+
the runtime reference; the transport flush thread kept running
328+
with a non-empty buffer, the next ``_do_flush`` raced respx and
329+
hit the real network, and CI logged 9m 47s of
330+
"Request failed (attempt N/11), retrying in 10s" — dominating
331+
the otherwise-fast xdist wall clock.
332+
"""
333+
334+
def test_runtime_shutdown_flush_false_skips_final_flush(self, mock_api):
335+
"""``runtime.shutdown(flush=False)`` cancels the transport
336+
thread WITHOUT triggering a final ``_do_flush()``.
337+
338+
We use ``_test_mode=True`` so init skips auth, then buffer
339+
an event directly into the transport (bypassing
340+
``track()``'s auth path), then call ``shutdown(flush=False
341+
)`` AFTER the respx context has exited. The whole call must
342+
return in well under 1s; a regression to
343+
``shutdown(flush=...)`` not propagating would push the
344+
assertion past the 5s connect timeout × retry budget.
345+
"""
346+
# _test_mode skips auth but still starts the transport thread.
347+
rt = NullRunRuntime(
348+
api_key="test-key-12345678",
349+
_test_mode=True,
350+
polling=False,
351+
)
352+
# Buffer an event so a final _do_flush() would have
353+
# something to attempt to send. mock_api is a function-
354+
# scoped fixture; we drop the reference so the respx
355+
# context exits before we call shutdown.
356+
rt._transport._buffer.append({"event_id": "x", "event": "test"})
357+
358+
started = time.monotonic()
359+
rt.shutdown(flush=False)
360+
elapsed = time.monotonic() - started
361+
362+
assert elapsed < 1.0, (
363+
f"shutdown(flush=False) took {elapsed:.2f}s; expected "
364+
f"<1s. The flush=False kwarg did not propagate to "
365+
f"Transport.stop() — the conftest teardown regression "
366+
f"is back."
367+
)
368+
# And the buffer is left alone — the test that wrote it
369+
# is responsible for asserting on what it cared about.
370+
assert len(rt._transport._buffer) == 1, (
371+
f"shutdown(flush=False) should leave the buffer alone; "
372+
f"expected 1 event, got {len(rt._transport._buffer)}."
373+
)

tests/test_transport.py

Lines changed: 53 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -111,6 +111,59 @@ def test_stop_interrupts_flush_sleep(self):
111111
f"cancellable-wait fix regressed."
112112
)
113113

114+
def test_stop_flush_false_skips_final_flush(self):
115+
"""``stop(flush=False)`` cancels the thread WITHOUT a final
116+
``_do_flush()`` so the conftest can teardown between tests
117+
without racing the respx context exit.
118+
119+
Regression pin for the second CI-noise fix (PR #60 follow-up):
120+
the conftest previously nulled the runtime reference without
121+
calling ``shutdown()`` so the transport flush thread kept
122+
running with a non-empty buffer; on the next ``_do_flush``
123+
(after respx exited) httpx hit the real network, got
124+
``ConnectError``, retried 11 times with up-to-10s backoff,
125+
and dominated the xdist wall clock (9m 47s of
126+
"Request failed (attempt N/11), retrying in 10s").
127+
128+
The contract being pinned here: with ``flush=False``,
129+
``_do_flush`` is NOT called from ``stop()`` even when the
130+
buffer is non-empty. The teardown is a true no-op apart
131+
from the thread join.
132+
"""
133+
from nullrun.transport import FlushConfig
134+
135+
t = Transport(
136+
api_url="https://api.test.nullrun.io",
137+
api_key="test-key-12345678",
138+
config=FlushConfig(flush_interval=30.0),
139+
)
140+
t.start()
141+
# Buffer an event so a final _do_flush() would have something
142+
# to attempt to send (and therefore would race respx).
143+
t._buffer.append({"event_id": "x", "event": "test"})
144+
# No respx mock active here — if stop() tries to flush, httpx
145+
# will block for the 5s connect timeout per attempt and
146+
# multiply by the retry budget. The whole point of
147+
# ``flush=False`` is to skip that path entirely.
148+
started = time.monotonic()
149+
t.stop(flush=False)
150+
elapsed = time.monotonic() - started
151+
# Generous bound: thread join is the only blocking step. A
152+
# regression to "stop() always flushes" would push this
153+
# past 60s on the first failure.
154+
assert elapsed < 1.0, (
155+
f"stop(flush=False) took {elapsed:.2f}s; expected < 1s. "
156+
f"The final _do_flush() ran despite flush=False — the "
157+
f"conftest teardown is back to racing respx and the "
158+
f"CI retry-storm regression is open again."
159+
)
160+
# And the buffer is left alone — the conftest contract is
161+
# "we don't care, the test that wrote it is responsible".
162+
assert len(t._buffer) == 1, (
163+
f"stop(flush=False) should leave the buffer untouched; "
164+
f"expected 1 event, got {len(t._buffer)}."
165+
)
166+
114167
def test_ssl_verification_enabled(self, transport):
115168
# httpx 0.28+ doesn't expose verify as a direct attribute
116169
# SSL verification is enabled by default (verify=True)

0 commit comments

Comments
 (0)