fix(#1113): silence Windows asyncio Proactor cleanup-RST noise

bambuddy.log on Windows fills with

    Exception in callback _ProactorBasePipeTransport._call_connection_lost()
    ConnectionResetError: [WinError 10054] An existing connection was
    forcibly closed by the remote host

  every time a printer / MQTT broker / camera RSTs a TCP socket instead
  of FINing it. The application-layer reconnect (paho-mqtt, httpx)
  handles the actual disconnect fine; the traceback is asyncio
  bookkeeping. Reported by @cadtoolbox who runs 9 printers including 5
  offline X1Es, so the log filled multiple times per minute.

  New backend/app/core/asyncio_handlers.py installs a custom
  loop.set_exception_handler on Windows that pattern-matches three
  signals together (platform == win32, exception is
  ConnectionResetError, asyncio message contains
  _call_connection_lost) and demotes the entry to DEBUG. Genuine
  ConnectionResetErrors raised inside application coroutines have a
  different message string and still surface; BrokenPipeError /
  ConnectionAbortedError on the same cleanup path also still surface.

  Wired from lifespan startup before any task can spawn that might
  trip it. Linux / macOS use the Selector loop, so install is an
  explicit no-op there with a False return.

  9 unit tests in test_asyncio_handlers.py covering signature match,
  rejection of unrelated resets, platform gate, suppress vs.
  pass-through to default handler.
This commit is contained in:
maziggy
2026-04-27 16:14:31 +02:00
parent 02eb5f57dc
commit 56800589ff
4 changed files with 208 additions and 0 deletions
+2
View File
@@ -35,6 +35,8 @@ All notable changes to Bambuddy will be documented in this file.
- **Per-request trace ID column on every log line, plumbed through HTTP access log + application logs + response headers** — Builds on the new uvicorn-access-log-into-bambuddy.log change below: the access line tells you *who* called an endpoint, but until now there was no way to tie that line to the application records emitted on the server side while handling that request. A new FastAPI middleware (`trace_id_middleware` in `main.py`, sourced from `backend.app.core.trace`) stamps each request with a fresh 8-char hex ID (or honours a sane inbound `X-Trace-Id` header for cross-system correlation), stores it in a `ContextVar` so any code in the request's call stack can read it, echoes it on the response as `X-Trace-Id`, and a new `TraceIDFilter` injects it into every `LogRecord` so the format string `[%(trace_id)s]` resolves to the right ID for the right request. ContextVars (rather than `request.state`) are the right plumbing here because asyncio copies the current context into every `asyncio.create_task`, so background work spawned from inside a request inherits the trace ID without explicit threading; the logging filter has no access to the FastAPI request object regardless. Records emitted outside any request scope (startup, MQTT callbacks, scheduler) get a stable `-` placeholder so the column stays visually aligned and missing values are obvious in `grep`. Inbound `X-Trace-Id` is hard-validated against a strict whitelist (`[A-Za-z0-9_-]+`, max 64 chars) before being honoured — a hostile or buggy caller cannot smuggle log-injection payloads (newlines, control chars, megabyte blobs) into `bambuddy.log` via the trace-ID column; values that fail the gate silently trigger a freshly minted server-side ID rather than failing the request. Middleware is decorated AFTER `auth_middleware` on purpose: Starlette stacks `@app.middleware` decorators LIFO so the last-decorated runs first inbound, making trace stamp the OUTERMOST layer — auth log lines and every record emitted on the way down to and back from the route handler all carry the same ID. Output now looks like `2026-04-26 09:51:39,152 INFO [uvicorn.access] [a4f3b1e7] 192.168.1.42:54812 - "POST /api/v1/printers/1/print/stop HTTP/1.1" 200` paired with the route handler's `2026-04-26 09:51:39,158 INFO [bambu_mqtt] [a4f3b1e7] [SERIAL] Sent stop print command` — one `grep a4f3b1e7` away from the full causality chain. 30 new tests across `tests/unit/test_trace.py` (placeholder when no request scope, filter copies ContextVar value onto records, ID propagates into spawned tasks via asyncio context copy, concurrent requests don't leak IDs into each other, generator produces unique hex IDs, hostile payloads rejected by validator, max-length boundary, dash/underscore variants accepted) plus `tests/integration/test_trace_middleware.py` (X-Trace-Id header echoed on response, body and header IDs match, each request gets a unique ID, generator format stays short hex, safe inbound IDs honoured, hostile inbound IDs replaced, overlong inbound IDs replaced, ContextVar reset cleanly after request).
### Fixed
- **Windows install: `bambuddy.log` filling with `WinError 10054 — _ProactorBasePipeTransport._call_connection_lost` tracebacks** ([#1113](https://github.com/maziggy/bambuddy/issues/1113), reported by @cadtoolbox) — Cosmetic-but-noisy. When a printer / MQTT broker / camera RSTs a TCP socket instead of FINing it (offline X1Es in @cadtoolbox's setup, network gear that drops idle TCP, the printer firmware's own watchdog), Windows asyncio's Proactor cleanup path tries `socket.shutdown(SHUT_RDWR)` on the already-dead socket and hits `WinError 10054`. Application-layer reconnect logic (paho-mqtt, httpx) handles the actual disconnect fine — paho retries, MQTT comes back, telemetry resumes — so the traceback is pure asyncio bookkeeping noise, but it fired multiple times per minute on @cadtoolbox's 9-printer setup with 5 offline X1Es and was the first thing in the sanitized log. Adds a custom `loop.set_exception_handler` (new `backend/app/core/asyncio_handlers.py`) installed on Windows only that pattern-matches the specific `_call_connection_lost` cleanup-RST signature (three signals together: `sys.platform == "win32"`, the exception is `ConnectionResetError`, and the asyncio message string contains `_call_connection_lost`) and downgrades it to DEBUG. Real `ConnectionResetError`s raised inside application coroutines (different message string) and other Proactor cleanup errors (`BrokenPipeError`, `ConnectionAbortedError` — same callback site, distinct signal worth keeping visible) all pass through to `loop.default_exception_handler` unchanged. Linux / macOS use the Selector event loop and never hit this codepath, so `install_proactor_reset_filter()` is an explicit no-op there with a `False` return — verified by `test_install_is_no_op_on_non_windows`. 9 unit tests in `test_asyncio_handlers.py` cover: discriminator matches the exact reported signature, rejects unrelated `ConnectionResetError`s, rejects `BrokenPipeError` even on the same callback site, rejects when no exception object is present, install is platform-gated, install wires the handler onto the loop, suppression doesn't reach the default handler, and unrelated exceptions still hit the default handler. Wired from `lifespan` startup before any task can spawn that might trip it.
- **Auto-Print G-code Injection: start snippet landed before printer startup, and `{placeholder}` substitution was silently broken** ([#422](https://github.com/maziggy/bambuddy/issues/422) follow-up) — Two compounding bugs surfaced by @pleite (Swapmod) and @DevScarabyte (multi-height test prints) on the initial #422 ship: **(1)** Start snippets were prepended to the entire `plate_X.gcode` content, which placed them *before* the printer's bed-heat / homing / nozzle-prime sequence — so a Swapmod start snippet that assumed nozzle-at-temp ran on a cold printer. The injection now anchors at `; MACHINE_START_GCODE_END` (the marker sitting at the bottom of every Bambu/Orca slicer's `MACHINE_START_GCODE` block, after `M109` wait-for-temp), matching where a slicer-side custom-start-gcode would land. Files without the marker (older slicer versions) keep the prepend behaviour as a fallback with a warning log. **(2)** Slicer-style placeholders like `G1 Z{max_layer_z} F600` were written verbatim to the output gcode — the printer firmware then parsed `Z{max_layer_z}` as `Z1` and crashed the head into the print on a 60mm-tall model (a real safety issue: prints damaged, top glass + AMS pushed up off the printer when the model was taller than the hard-coded park height). Added a header parser that reads the 3MF's `; HEADER_BLOCK_START..END` block (lowercased keys, `[units]` suffix stripped, spaces → underscores) and a Prusa-style `{name}` substitution pass that runs over both start and end snippets before injection. Supported placeholders: `{max_layer_z}` / `{max_print_height}` (top-layer Z), `{total_layer_number}` / `{total_layers}`, `{total_filament_weight}`, `{total_filament_length}`, plus any other normalised header key from the source file. Unknown placeholders are left in the snippet verbatim with a warning log — a typo never silently expands to an empty string and the firmware never receives a malformed `Z` parameter. 16 new regression tests in `test_gcode_injection.py` covering: start snippet anchored to the marker (printer startup runs first, snippet sits between `M109 S220` and the marker, file head untouched), missing-marker fallback path, end snippet still appended at EOF, `{max_layer_z}` resolved through the alias map, direct-key substitution from the normalised header, unknown-placeholder pass-through, and direct unit tests for each new helper (`_parse_3mf_gcode_header`, `_substitute_placeholders`, `_inject_start_at_marker`). Wiki page documents the supported placeholder list with a safety warning specifically calling out `{max_layer_z}` for park moves.
- **Camera page ignored `?fps=N` URL parameter** ([#1131](https://github.com/maziggy/bambuddy/issues/1131) diagnostic) — `CameraPage.tsx` hard-coded `fps=15` in the stream URL and never read the URL query string, so `/camera/1?fps=5` (and similar diagnostic suggestions for the freeze report) were silent no-ops. The sibling `StreamOverlayPage` already honoured `?fps=` correctly; the bug was that `CameraPage` was the gap. Now reads `searchParams.get('fps')` via `useSearchParams`, parses it, falls back to 15 on missing/non-numeric, clamps to the backend's 1–30 range, and threads the resulting value into the stream URL. Backend `generate_rtsp_mjpeg_stream` already accepted the parameter and re-clamps per-model (chamber-image A1/P1 capped at 5, RTSP capped at 30). 5 new regression tests in `CameraPage.test.tsx::fps URL parameter (#1131)` cover default-15, honoured value, clamp-above-30, clamp-below-1, and non-numeric fallback — same matrix `StreamOverlayPage.test.tsx` already pins. Independent of the underlying freeze investigation in #1131; surfaced while triaging that report.
+73
View File
@@ -0,0 +1,73 @@
"""Asyncio event-loop exception handlers used at app startup.
Currently houses a single Windows-specific filter for the noisy
``_ProactorBasePipeTransport._call_connection_lost`` ``WinError 10054``
that fires every time a printer / MQTT broker / camera RSTs a TCP socket
instead of closing it cleanly. See ``install_proactor_reset_filter`` for
the why and the failure mode it suppresses.
"""
from __future__ import annotations
import asyncio
import logging
import sys
from typing import Any
logger = logging.getLogger(__name__)
def _is_proactor_connection_reset(context: dict[str, Any]) -> bool:
"""True if `context` describes the Windows Proactor cleanup-RST noise.
asyncio's default exception handler is invoked in two distinct cases
we care about — generic uncaught task exceptions, and the specific
`_call_connection_lost` cleanup path — and we only want to suppress
the latter. Match on three signals together so a real
`ConnectionResetError` raised inside an application task still
surfaces normally:
1. The exception is `ConnectionResetError` (or a subclass).
2. asyncio's own message string mentions `_call_connection_lost`
(the Proactor-cleanup callback is the only place Python emits
this exact phrase).
3. We're actually on Windows, where the Proactor is in use.
"""
if sys.platform != "win32":
return False
exc = context.get("exception")
if not isinstance(exc, ConnectionResetError):
return False
message = context.get("message", "")
return "_call_connection_lost" in message
def _proactor_reset_filter(loop: asyncio.AbstractEventLoop, context: dict[str, Any]) -> None:
"""Custom event-loop exception handler.
Handles the Proactor-cleanup `ConnectionResetError` by logging it at
DEBUG instead of ERROR, and delegates everything else to asyncio's
default handler so unrelated bugs are still visible.
"""
if _is_proactor_connection_reset(context):
logger.debug(
"asyncio Proactor: peer reset socket during cleanup (WinError 10054); "
"ignored — application-layer reconnect handles the disconnect"
)
return
loop.default_exception_handler(context)
def install_proactor_reset_filter(loop: asyncio.AbstractEventLoop | None = None) -> bool:
"""Install the filter on `loop` (or the running loop if omitted).
Returns True when the filter was installed (Windows only), False on
every other platform — so callers can branch on the return value if
they want to log the install / skip.
"""
if sys.platform != "win32":
return False
if loop is None:
loop = asyncio.get_running_loop()
loop.set_exception_handler(_proactor_reset_filter)
return True
+6
View File
@@ -4160,6 +4160,12 @@ def stop_auth_cleanup() -> None:
@asynccontextmanager
async def lifespan(app: FastAPI):
# Startup
# Install Windows-only asyncio Proactor cleanup-RST filter (#1113) before
# anything else can spawn tasks that might trip it.
from backend.app.core.asyncio_handlers import install_proactor_reset_filter
install_proactor_reset_filter()
await init_db()
# Register an app-scoped httpx client for Bambu Cloud services so
+127
View File
@@ -0,0 +1,127 @@
"""Tests for the Windows asyncio Proactor cleanup-RST filter (#1113)."""
from __future__ import annotations
import asyncio
from unittest.mock import patch
import pytest
from backend.app.core.asyncio_handlers import (
_is_proactor_connection_reset,
_proactor_reset_filter,
install_proactor_reset_filter,
)
# `_is_proactor_connection_reset` short-circuits on non-Windows; pretend we're
# on Windows for the discrimination tests so they exercise the actual logic.
@pytest.fixture
def fake_windows():
with patch("backend.app.core.asyncio_handlers.sys.platform", "win32"):
yield
class TestIsProactorConnectionReset:
"""The discriminator that decides whether a context is the noise we silence."""
def test_matches_proactor_cleanup_reset(self, fake_windows):
ctx = {
"exception": ConnectionResetError(10054, "An existing connection was forcibly closed"),
"message": "Exception in callback _ProactorBasePipeTransport._call_connection_lost()",
}
assert _is_proactor_connection_reset(ctx) is True
def test_rejects_when_not_on_windows(self):
# No `fake_windows` fixture — sys.platform reflects the real OS.
ctx = {
"exception": ConnectionResetError(10054, "irrelevant"),
"message": "Exception in callback _ProactorBasePipeTransport._call_connection_lost()",
}
# The whole point of the filter is to be a Windows-only no-op.
with patch("backend.app.core.asyncio_handlers.sys.platform", "linux"):
assert _is_proactor_connection_reset(ctx) is False
def test_rejects_unrelated_connection_reset(self, fake_windows):
"""A real `ConnectionResetError` raised inside an app coroutine —
not from the Proactor cleanup path — must NOT be suppressed.
Otherwise we'd hide genuine connectivity bugs."""
ctx = {
"exception": ConnectionResetError(),
"message": "Task exception was never retrieved",
}
assert _is_proactor_connection_reset(ctx) is False
def test_rejects_other_exception_types(self, fake_windows):
"""Other OSErrors (BrokenPipeError, ConnectionAbortedError) might
share the cleanup path but they're a different signal worth
keeping visible — we only silence the specific 10054 family."""
ctx = {
"exception": BrokenPipeError(),
"message": "Exception in callback _ProactorBasePipeTransport._call_connection_lost()",
}
assert _is_proactor_connection_reset(ctx) is False
def test_rejects_when_no_exception(self, fake_windows):
"""asyncio sometimes invokes the handler with no exception object
(e.g. resource warnings) — those shouldn't blanket-match."""
ctx = {"message": "_call_connection_lost was slow"}
assert _is_proactor_connection_reset(ctx) is False
class TestProactorResetFilter:
"""The handler glue itself — does it suppress the right ones and
pass everything else through to the default handler?"""
@pytest.mark.asyncio
async def test_suppresses_proactor_reset(self, fake_windows):
loop = asyncio.get_running_loop()
with patch.object(loop, "default_exception_handler") as default:
_proactor_reset_filter(
loop,
{
"exception": ConnectionResetError(10054, "forcibly closed"),
"message": "Exception in callback _ProactorBasePipeTransport._call_connection_lost()",
},
)
# Suppression = default handler is never reached.
default.assert_not_called()
@pytest.mark.asyncio
async def test_passes_unrelated_through_to_default(self, fake_windows):
"""A different uncaught exception must go through asyncio's normal
path so it surfaces in logs and tests as an actual problem."""
loop = asyncio.get_running_loop()
ctx = {
"exception": ValueError("real bug"),
"message": "Task exception was never retrieved",
}
with patch.object(loop, "default_exception_handler") as default:
_proactor_reset_filter(loop, ctx)
default.assert_called_once_with(ctx)
class TestInstallation:
"""Wiring: install_proactor_reset_filter only runs on Windows."""
@pytest.mark.asyncio
async def test_install_is_no_op_on_non_windows(self):
"""Linux/macOS use the Selector loop, which doesn't hit this code
path — the install must be inert so the Linux production path
keeps the default exception handler untouched."""
loop = asyncio.get_running_loop()
with (
patch("backend.app.core.asyncio_handlers.sys.platform", "linux"),
patch.object(loop, "set_exception_handler") as setter,
):
installed = install_proactor_reset_filter(loop)
assert installed is False
setter.assert_not_called()
@pytest.mark.asyncio
async def test_install_attaches_handler_on_windows(self, fake_windows):
loop = asyncio.get_running_loop()
with patch.object(loop, "set_exception_handler") as setter:
installed = install_proactor_reset_filter(loop)
assert installed is True
setter.assert_called_once_with(_proactor_reset_filter)