fix(camera): honor ?fps=N URL parameter on /camera/<id>

CameraPage hard-coded fps=15 in the stream URL and never read the
  URL query string, so /camera/1?fps=5 and similar diagnostic URLs
  were silent no-ops. Sibling StreamOverlayPage already honored ?fps=;
  this brings CameraPage to parity.

  - Read fps via useSearchParams, default 15, clamp 1-30, fallback to
    15 on non-numeric input (mirrors StreamOverlayPage's parser)
  - Thread the parsed value into the stream URL builder
  - 5 new tests in CameraPage.test.tsx pinning default, honored value,
    clamp-above-30, clamp-below-1, and non-numeric fallback

  Surfaced while triaging #1131 (H2D camera freeze). Independent of
  the underlying freeze investigation; restores the diagnostic knob
  the issue thread was relying on.
This commit is contained in:
maziggy
2026-04-27 07:13:33 +02:00
parent 527f8ea471
commit 0334f64e37
5 changed files with 182 additions and 131 deletions
+1
View File
@@ -32,6 +32,7 @@ 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
- **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.
- **Reprint-from-archive failed with `0500_4003` SD R/W errors after a stuck dispatch, fixable only by restarting the container** ([#1136](https://github.com/maziggy/bambuddy/issues/1136)) — Reported by @smandon: reprinting from archives sometimes fails immediately with MicroSD R/W exception errors, with the printer's MQTT push referencing a 3MF file from a *different unrelated* archive (`WARIO_Wall_decor_-_NO_AMS.3mf` while the user was actually trying to print `Cable_Organiser_Cable_Clip.3mf`). Once it starts happening, every subsequent reprint hits the same error until the container is restarted. Root cause traced from his support package log to paho-mqtt's client-side QoS 1 queue: when the printer's command channel goes half-broken (telemetry still flowing, publishes silently dropped — same #887/#936 pattern), Bambuddy's 15s dispatch deadline expires (`background_dispatch.py:993`) and calls `force_reconnect_stale_session()`. That function was force-closing the underlying socket so paho's auto-reconnect would kick in — but the same `mqtt.Client` instance, same `client_id`, and **same in-process QoS 1 queue** stayed alive across the reconnect. Any unacked publish from the broken session — typically the just-sent `project_file` for the new archive — got replayed verbatim on the new connection. And because the in-process queue accumulates across multiple stuck dispatches within one Python process, by the second or third stuck reprint there were several stale `project_file`/`resume`/`stop`/`clean_print_error` commands queued up and replaying together. The printer received the flood, tried to load whichever stale path the firmware latched onto last, found a file that no longer existed on its SD card → `0500_4003`. Container restart was the only thing that fixed it because it was the only thing that wiped paho's in-process queue. Replaced the socket-close with a context-aware reconnect: `force_reconnect_stale_session()` and `check_staleness()` now go through a routing helper `_reset_client_for_reconnect()` that picks the right teardown strategy based on caller context. **Async-context callers** (the dispatch deadline path — `background_dispatch.py:993` — which is the actual #1136 trigger, plus FastAPI route handlers via `check_staleness`) get the **hard-reset path**: `client.disconnect()` (broker sees DISCONNECT and drops the session immediately, since `clean_session=True`), `client.loop_stop()` (kills the paho network thread, taking its QoS 1 queue with it), nulls out `self._client`, and calls `self.connect()` to construct a fresh `mqtt.Client` with an incremented `client_id`. New connection starts genuinely empty, no replay possible. **Paho-network-thread callers** (the developer-mode probe and `ams_filament_setting` zombie detection inside `_update_state`, lines ~2604 and ~2623) keep the **socket-close fallback** — calling `loop_stop()` from inside the network thread would self-join and deadlock, so the safe pattern there remains "close the socket and let paho's own loop detect it and auto-reconnect on the same client". Theoretical queue replay is still possible on those paths but #1136 specifically traced through the dispatch path, and the legacy socket-close has been battle-tested for the zombie paths since #887. Routing decision is made via `asyncio.get_running_loop()` — paho's callback thread has no loop, every legitimate hard-reset caller does. 7 regression tests across two new test classes: `TestForceReconnectRouting` (3 tests pinning the sync-context → socket-close fallback, async-context → hard-reset path with mock-stubbed `connect()`, and the state-disconnected broadcast firing once on either path) and `TestHardResetClientDirect` (3 tests pinning the helper directly: old client receives `disconnect()` + `loop_stop()`, `_client` reference cleared, failing `disconnect()` doesn't propagate so the await chain in `background_dispatch.py` doesn't break). Existing `TestZombieSessionDetection::test_two_timeouts_force_reconnect` and `TestDeveloperModeProbeTimeout::test_second_timeout_forces_reconnect` updated to assert the socket-close path (matching their paho-thread context), preserving the legacy contract. All 2179 backend unit tests pass. Thanks to @smandon for the precise reproduction logs that made this diagnosable from a single support package.
- **`logs/bambuddy.log` was silently dropping records from named child loggers** — When the trace-ID column was added to the log format (`%(trace_id)s`), the `TraceIDFilter` was attached to the root logger. Per Python's logging semantics, a filter on a `Logger` only fires for records that *originate* at that logger — records propagated up from child loggers (every `backend.app.*` module — most of the application) never trigger it. Result: child-logger records arrived at the file handler with no `trace_id` attribute, the formatter raised `KeyError: 'trace_id'`, and `Handler.handleError` printed to stderr and dropped the record. `bambuddy.log` ended up with INFO/DEBUG records appearing only "partially" — exactly the records emitted directly through `logging.info(...)` (root logger) or `uvicorn.access` (which had its own explicit filter attachment) made it; everything else was discarded. Moved `_trace_id_filter` from `root_logger.addFilter()` to `console_handler.addFilter()` + `file_handler.addFilter()` — handler-level filters fire for every record the handler receives, regardless of which logger emitted it. The filter's own docstring already said "Attach to the file handler (or any handler whose format string references `%(trace_id)s`)" — the implementation was just wrong. New regression test in `test_trace.py::TestFilterMustBeAttachedToHandlerNotLogger` pins the contract: a child logger emits a record, propagation reaches the handler-level filter, the formatter sees a populated `trace_id` field, and the line is written. Existing 23 trace tests keep passing unchanged. Restart-shutdown recursion in journalctl was also a side effect — every shutdown log line was raising the formatter `ValueError`, which got caught and logged… raising again, forever, until the lifespan exit unwound; the new placement breaks the cycle since records now format cleanly.
@@ -32,7 +32,7 @@ const mockPrinter = {
};
// Custom render for CameraPage which needs specific route params
function renderCameraPage(printerId: number) {
function renderCameraPage(printerId: number, search = '') {
const queryClient = new QueryClient({
defaultOptions: {
queries: { retry: false, gcTime: 0 },
@@ -43,7 +43,7 @@ function renderCameraPage(printerId: number) {
return rtlRender(
<QueryClientProvider client={queryClient}>
<I18nextProvider i18n={i18n}>
<MemoryRouter initialEntries={[`/cameras/${printerId}`]}>
<MemoryRouter initialEntries={[`/cameras/${printerId}${search}`]}>
<ThemeProvider>
<AuthProvider>
<ToastProvider>
@@ -177,6 +177,53 @@ describe('CameraPage', () => {
});
});
describe('fps URL parameter (#1131)', () => {
it('defaults to fps=15 when no query parameter is provided', async () => {
renderCameraPage(1);
await waitFor(() => {
const src = (document.querySelector('img') as HTMLImageElement | null)?.getAttribute('src') || '';
expect(src).toContain('fps=15');
});
});
it('honors fps query parameter from URL', async () => {
renderCameraPage(1, '?fps=5');
await waitFor(() => {
const src = (document.querySelector('img') as HTMLImageElement | null)?.getAttribute('src') || '';
expect(src).toContain('fps=5');
});
});
it('clamps fps above 30 to 30', async () => {
renderCameraPage(1, '?fps=60');
await waitFor(() => {
const src = (document.querySelector('img') as HTMLImageElement | null)?.getAttribute('src') || '';
expect(src).toContain('fps=30');
});
});
it('clamps fps below 1 to 1', async () => {
renderCameraPage(1, '?fps=0');
await waitFor(() => {
const src = (document.querySelector('img') as HTMLImageElement | null)?.getAttribute('src') || '';
expect(src).toContain('fps=1');
});
});
it('falls back to 15 for non-numeric fps', async () => {
renderCameraPage(1, '?fps=invalid');
await waitFor(() => {
const src = (document.querySelector('img') as HTMLImageElement | null)?.getAttribute('src') || '';
expect(src).toContain('fps=15');
});
});
});
describe('invalid printer', () => {
it('shows invalid printer message for ID 0', async () => {
renderCameraPage(0);
+5 -2
View File
@@ -1,5 +1,5 @@
import { useState, useEffect, useRef, useCallback } from 'react';
import { useParams } from 'react-router-dom';
import { useParams, useSearchParams } from 'react-router-dom';
import { useQuery, useMutation, useQueryClient } from '@tanstack/react-query';
import { useTranslation } from 'react-i18next';
import { RefreshCw, AlertTriangle, Camera, Maximize, Minimize, WifiOff, ZoomIn, ZoomOut } from 'lucide-react';
@@ -22,6 +22,9 @@ export function CameraPage() {
const { hasPermission, authEnabled, user } = useAuth();
const { printerId } = useParams<{ printerId: string }>();
const id = parseInt(printerId || '0', 10);
const [searchParams] = useSearchParams();
const fpsParam = parseInt(searchParams.get('fps') || '15', 10);
const fps = Math.min(Math.max(isNaN(fpsParam) ? 15 : fpsParam, 1), 30);
// Subscribe to the stream-token query so this page re-renders once the token
// arrives. useStreamTokenSync (mounted in App) already owns the fetch; this
@@ -599,7 +602,7 @@ export function CameraPage() {
const currentUrl = transitioning || waitingForStreamToken
? ''
: streamMode === 'stream'
? appendToken(`/api/v1/printers/${id}/camera/stream?fps=15&t=${imageKey}`)
? appendToken(`/api/v1/printers/${id}/camera/stream?fps=${fps}&t=${imageKey}`)
: appendToken(`/api/v1/printers/${id}/camera/snapshot?t=${imageKey}`);
const isDisabled = streamLoading || transitioning || isReconnecting;
File diff suppressed because one or more lines are too long
+1 -1
View File
@@ -26,7 +26,7 @@
<!-- Splash screens for iOS -->
<link rel="apple-touch-startup-image" href="/img/android-chrome-512x512.png" />
<script type="module" crossorigin src="/assets/index-DJk_kz74.js"></script>
<script type="module" crossorigin src="/assets/index-DCOWEBQL.js"></script>
<link rel="stylesheet" crossorigin href="/assets/index-telVPl_h.css">
</head>
<body>