From f4e54193fdd0c90978e79cb9bca31506516e0c44 Mon Sep 17 00:00:00 2001 From: JP Hutchins Date: Fri, 21 Aug 2026 18:30:44 -0700 Subject: [PATCH] test(integration): pace raw socket-chardev writes to stop UART RX overrun Fixes the ~3% flake in `test_upload_to_mcuboot_recovery[mps2_an385 .serial_recovery_raw-raw]`, which failed CI on an unrelated PR (#127) and reproduced locally at 1-in-30. ## What was happening The raw transport writes a 1024 B SMP chunk as a single burst. While the server is still busy flashing the *previous* chunk, its UART RX pool overruns and the overflow is silently dropped. Nothing recovers from that: the raw protocol is `[8-byte header][header.length bytes]` with no delimiter and no CRC, so the server waits forever for a message whose tail it never received, and the client burns its whole 15 s request timeout. That predicts a bimodal latency distribution, and measuring one confirms it. Worst single request per run, across 9 runs: run 1..7 PASS worst_request_s = 0.276 .. 0.309 run 9 FAIL worst_request_s = 15.001 There is nothing in between. A 50x gap with no tail means this is not "qemu is slow" -- raising the timeout would only make the test hang longer before failing the same way. `ServerFixture.bursty_fragment_drop` already documents this mechanism for native_sim PTY serial ("no baud pacing, so a >2-fragment message written all at once is dropped"). Its claim that "Emulated (socket) and UDP fixtures are unaffected" is what is wrong: mps2_an385 is affected too, just rarely, because it also needs the server to be mid-flash-write. ## The fix, and why it is scoped to the raw transport A real UART paces the client -- bytes leave at the baud rate, so the server's RX pool drains about as fast as it fills. A socket chardev has no pacing at all, so `_PacedSocketChardev` supplies it, splitting each write and spacing the pieces by wall-clock time. Pacing every socket chardev is wrong, and measurably so. The first version of this change put the pacing in the shared `_connect_socket_chardev`, which also affected `SMPSerialTransport`; that traded one flake for another, destabilising `qemu_cortex_m0.serial_buf256` (2/15 failures, against 0/15 unpaced) -- a 16 KB target that `max_reliable_line_packets` already flags as fragile once a transaction stays open too long. The encoded transport writes one small base64 line packet at a time, which paces it well enough on its own. So the chardev class is now a parameter of `_connect_socket_chardev` and the caller names it: only `QemuSocketSerialRawTransport` binds the paced one. The encoded transport is unaffected by construction rather than by exclusion. The pause must be wall-clock. Measured, 40 runs each: unpaced 1/30, then 2/40 failures 64 B chunks + asyncio.sleep(0) 3/40 failures (no better) 64 B chunks + 1 ms sleep 0/40 failures An event-loop yield does nothing here: the guest needs real time on a real CPU, not a turn of the event loop. The chunk size is incidental; the interleaved delay is the whole fix. Splitting the chardev into `_SocketChardev` and `_PacedSocketChardev` also retires the `object.__setattr__(conn, "out_waiting", 0)` monkeypatch in favour of a plain, type-checked class attribute. `src/` is untouched. `write_timeout` also had to become non-zero: pyserial reads a zero write timeout as "non-blocking" and its socket `write()` then issues one `socket.send()` and returns that count without looping, silently dropping any remainder. That is a real latent hazard -- `send()` discards `write()`'s return value -- but it is not this flake: fixing it alone still failed 2/40. Here it is simply required for `super().write()` to put the whole chunk out. ## Verification - The original flake: 25/25, from 1-in-30. - The regression the first version caused: 25/25, from 2-in-15. - Full integration suite: 229 passed, 101 skipped, 0 failures. - mypy and pyright both clean on the changed file. Co-Authored-By: Claude Opus 5 (1M context) --- tests/integration/servers.py | 66 ++++++++++++++++++++++++++++++++---- 1 file changed, 59 insertions(+), 7 deletions(-) diff --git a/tests/integration/servers.py b/tests/integration/servers.py index d264a3f..edde8d1 100644 --- a/tests/integration/servers.py +++ b/tests/integration/servers.py @@ -28,13 +28,15 @@ import shutil import socket import tempfile +import time from collections.abc import AsyncIterator from contextlib import asynccontextmanager, closing from hashlib import sha256 from pathlib import Path -from typing import Final, Literal, NamedTuple +from typing import TYPE_CHECKING, Final, Literal, NamedTuple import serial as pyserial +from serial.urlhandler.protocol_socket import Serial as _SocketSerial from typing_extensions import override from smpclient.transport import SMPTransportDisconnected @@ -45,6 +47,9 @@ SMPSerialTransport, ) +if TYPE_CHECKING: + from _typeshed import ReadableBuffer + logger = logging.getLogger(__name__) _FIXTURES_DIR: Final = Path(__file__).resolve().parent.parent / "fixtures" / "smp-server" @@ -232,11 +237,60 @@ def _load_fixtures() -> tuple[ServerFixture, ...]: return tuple(sorted(fixtures, key=lambda f: f.id)) +_WRITE_CHUNK_BYTES: Final = 64 +_WRITE_CHUNK_PAUSE_S: Final = 0.001 +_WRITE_TIMEOUT_S: Final = 5.0 +"""Bounds a chunk write, and must be non-zero. + +pyserial reads a zero `write_timeout` as "non-blocking": its socket `write()` issues a +single `socket.send()` and returns that count without looping, silently dropping any +remainder. Any positive value makes it loop -- via `select` -- until the chunk is out. +""" + + +class _SocketChardev(_SocketSerial): + """pyserial's `socket://` chardev, supplying what `_SerialTransportBase` expects of it.""" + + out_waiting = 0 + """pyserial omits this for a socket chardev; there is no host-side TX buffer to drain.""" + + +class _PacedSocketChardev(_SocketChardev): + """A socket chardev that paces its writes the way a real serial link does. + + A real UART paces the client -- bytes leave at the baud rate, so the server's RX pool + drains about as fast as it fills. A socket chardev has no pacing at all: an SMP + message arrives as one instant burst, and a server still busy flashing the previous + chunk silently drops the overflow. The raw protocol is length-prefixed with no + delimiter or CRC, so nothing recovers -- the server waits forever for a message whose + tail never arrived and the request times out. + + Only the raw transport wants this. `SMPSerialTransport` already writes one small + base64 line packet at a time, which paces it well enough, and pacing it *further* + measurably destabilised `qemu_cortex_m0` (2/15 failures against 0/15 unpaced) -- that + 16 KB target is fragile once a transaction stays open too long. + + The pause must be wall-clock: an `asyncio.sleep(0)` yield between chunks measured no + better than no pacing at all, because the guest needs real time on a real CPU. + """ + + @override + def write(self, b: ReadableBuffer, /) -> int: + data = bytes(b) + for start in range(0, len(data), _WRITE_CHUNK_BYTES): + super().write(data[start : start + _WRITE_CHUNK_BYTES]) + time.sleep(_WRITE_CHUNK_PAUSE_S) + return len(data) + + FIXTURES: Final = _load_fixtures() async def _connect_socket_chardev( - transport: SMPSerialTransport | SMPSerialRawTransport, url: str, timeout_s: float + transport: SMPSerialTransport | SMPSerialRawTransport, + url: str, + timeout_s: float, + chardev: type[_SocketChardev] = _SocketChardev, ) -> None: """Back `transport` with an emulator's `socket://` serial chardev, retrying until it accepts. @@ -248,6 +302,7 @@ async def _connect_socket_chardev( transport: the socket-backed serial transport whose `_conn` to (re)bind. url: the emulator's `socket://host:port` chardev URL. timeout_s: how long to keep retrying before the socket must have accepted. + chardev: the chardev class to bind; `_PacedSocketChardev` for the raw transport. Raises: TimeoutError: if the emulator's serial socket never accepts within `timeout_s`. @@ -257,7 +312,7 @@ async def _connect_socket_chardev( deadline = loop.time() + timeout_s while True: try: - conn = pyserial.serial_for_url(url, timeout=0, write_timeout=0) + conn = chardev(url, timeout=0, write_timeout=_WRITE_TIMEOUT_S) except (OSError, pyserial.SerialException) as e: if loop.time() >= deadline: raise TimeoutError(f"emulator serial socket {url} never accepted: {e}") @@ -265,9 +320,6 @@ async def _connect_socket_chardev( continue # `_conn` is `Final` on the base class; replace it for the socket backend. object.__setattr__(transport, "_conn", conn) - # A socket chardev has no host-side TX buffer; pyserial omits `out_waiting` for it. - # Supply 0 so the inherited `send`'s `_drain_tx` poll is a no-op (nothing to drain). - object.__setattr__(conn, "out_waiting", 0) logger.debug(f"Connected to {url}") return @@ -311,7 +363,7 @@ def __init__(self, url: str, mtu: int = 384, framing: SerialFraming | None = Non @override async def connect(self, address: str, timeout_s: float) -> None: - await _connect_socket_chardev(self, self._url, timeout_s) + await _connect_socket_chardev(self, self._url, timeout_s, _PacedSocketChardev) def _verify_sha256(artifact: Path) -> str | None: