fix(logging): a stream closed at shutdown is one INFO line, not an ERROR traceback

Uvicorn cancels requests still open when the 5 s graceful-shutdown cap is
reached (an MJPEG camera stream never ends by itself) and logged each one as
"Exception in ASGI application" with a CancelledError traceback, plus a
"Cancel N running task(s)" ERROR line. Both are INFO now; every other error
and cancellation keeps its level and traceback.

CHANGELOG.md

@@ -164,6 +164,7 @@ All notable changes to Bambuddy will be documented in this file.
 - **The frontend build no longer warns about `path` and `crypto` being externalized for the STEP previewer (#2976)** — `occt-import-js`, the Emscripten build behind STEP previews, requires both modules, but only inside its `ENVIRONMENT_IS_NODE` branches; in the browser it loads its `.wasm` from the URL the preview worker passes and draws randomness from `crypto.getRandomValues`. Vite still externalized both and printed two warnings on every build. `vite.config.ts` now drops exactly those two warnings for that one package through `build.rolldownOptions.onLog`, so an externalization anywhere else, or of any other module, still shows.
 
 ### Fixed
+- **A restart with a camera view open no longer logs errors** — A camera stream never ends by itself, so a restart closes it after 5 seconds. Each stream closed that way was logged as an ERROR with a full traceback ("Exception in ASGI application ... timeout graceful shutdown exceeded"), which looked like a crash in the log and in support bundles. It is now one INFO line per stream, and the "Cancel N running task(s)" line before them is INFO too; real errors are logged as before.
 - **Archive export includes the whole end day, and an invalid print speed is refused** — `GET /api/v1/archives/export?date_to=2026-10-15` read the date as midnight and left out everything printed that day; a date on its own now ends with that day, as in every other date filter, and a date and time with a UTC offset is converted to UTC. The Archives page was not affected, because it never sends dates. `POST /api/v1/printers/{id}/print-speed` with a mode other than 1-4 answered 500 "Failed to set print speed"; it now answers 422.
 - **AMS drying now applies to "Any <model>" queue jobs** — With **Wait for drying to complete** on, a job for "Any X1C" could still start on an X1C whose AMS was drying, and its drying was never stopped for the print; queue auto-drying also never dried anything for such a job. Now a model job passes over a drying printer for another of the model, and waits only while every one of them is drying. The printer it lands on stops drying like it would for a job pinned to it, and a scheduled model job has queue auto-drying dry every printer it could run on.
 - **Every way of adding a queue job now works like the print dialog** — Jobs added from File Manager's **Add to queue**, the webhook, a virtual printer, a pipeline run or an order's **Dispatch remaining** sent no "Job added" notification and no MQTT `queue/job_added` event; now every path sends them. Several jobs added at once are one notification per printer, such as "3 jobs (bracket, hinge, lid)", and MQTT gets one event per job. File Manager, the webhook and pipeline runs ignored the default print options (timelapse, bed levelling and the rest) and now use them. The copies an order dispatches lost their cost centre, so they were billed to none and never checked against its budget; they now keep it, and with billing on, dispatching is refused when you may not print with that cost centre or its budget cannot cover every copy. A `scheduled_time` sent to the API or webhook with a UTC offset, such as `10:00+02:00`, was stored as 10:00 UTC and the job started two hours late; the offset is now converted.

backend/app/core/logging_filters.py

@@ -267,6 +267,42 @@ class WriteRequestsOnlyFilter(logging.Filter):
         return any(token in message for token in self._WRITE_VERB_TOKENS)
 
 
+class ShutdownCancelledRequestFilter(logging.Filter):
+    """One INFO line for a request uvicorn cancels at the end of a shutdown.
+
+    The service caps the graceful shutdown (``--timeout-graceful-shutdown``)
+    because an MJPEG camera stream never ends by itself. When the cap is
+    reached uvicorn logs "Cancel N running task(s)" and then, for each
+    cancelled request, "Exception in ASGI application" with the full
+    ``CancelledError`` traceback, both at ERROR. That happens on every restart
+    with a camera view open and is not an error. Only that cancellation is
+    rewritten, recognised by uvicorn's own cancel message; any other failure,
+    and any other cancellation, keeps its level and traceback.
+
+    Attach to ``logging.getLogger("uvicorn.error")`` before any filter that
+    renders the traceback.
+    """
+
+    _CANCEL_MESSAGE = "timeout graceful shutdown exceeded"
+
+    def filter(self, record: logging.LogRecord) -> bool:  # noqa: A003 — stdlib API name
+        exc = record.exc_info[1] if record.exc_info else None
+        if isinstance(exc, asyncio.CancelledError) and self._CANCEL_MESSAGE in str(exc):
+            record.msg = "Request closed at shutdown, still open after the grace period (a camera stream, for example)"
+            record.args = None
+            record.exc_info = None
+            record.exc_text = None
+            self._as_info(record)
+        elif exc is None and isinstance(record.msg, str) and record.msg.endswith(self._CANCEL_MESSAGE):
+            self._as_info(record)
+        return True
+
+    @staticmethod
+    def _as_info(record: logging.LogRecord) -> None:
+        record.levelno = logging.INFO
+        record.levelname = logging.getLevelName(logging.INFO)
+
+
 class CancelledPoolNoiseFilter(logging.Filter):
     """Drop SQLAlchemy connection-pool log records driven by request cancellation.
 

backend/app/main.py

@@ -344,7 +344,8 @@ root_logger.addHandler(console_handler)
 def _attach_file_handler_to_uvicorn(handler: logging.Handler) -> None:
     """Send uvicorn's own loggers to bambuddy.log as well.
 
-    Both ship with propagate=False, so the root handler never sees them.
+    Neither reaches the root handler: uvicorn.access has propagate=False, and
+    uvicorn.error propagates only to "uvicorn", which has propagate=False.
     uvicorn.access is the record of which endpoint changed server state;
     uvicorn.error is where an unhandled route error is logged with its
     traceback ("Exception in ASGI application").
@@ -399,8 +400,14 @@ if app_settings.log_to_file:
 
 # Query-string tokens out of uvicorn's request and WebSocket lines, on every
 # handler (console included), whether or not file logging is on.
-from backend.app.core.logging_filters import QueryTokenRedactFilter  # noqa: E402
+from backend.app.core.logging_filters import (  # noqa: E402
+    QueryTokenRedactFilter,
+    ShutdownCancelledRequestFilter,
+)
 
+# First, so the traceback of a stream cancelled at shutdown is dropped before
+# the filters below render it.
+logging.getLogger("uvicorn.error").addFilter(ShutdownCancelledRequestFilter())
 for _uvicorn_logger in ("uvicorn.access", "uvicorn.error"):
     logging.getLogger(_uvicorn_logger).addFilter(QueryTokenRedactFilter())
     logging.getLogger(_uvicorn_logger).addFilter(_refused_header_filter)

backend/tests/unit/test_shutdown_cancel_log_filter.py

@@ -0,0 +1,93 @@
+"""A stream still open at shutdown is closed with a line, not a traceback.
+
+The service caps uvicorn's graceful shutdown at 5 s (test_launcher_shutdown_config):
+an MJPEG camera stream never ends by itself, so uvicorn cancels it. Each cancelled
+request was then logged at ERROR with a full traceback ("Exception in ASGI
+application ... CancelledError: Task cancelled, timeout graceful shutdown
+exceeded"), on every restart with a camera view open. Expected, harmless, and
+alarming in a support bundle. It is now one INFO line, and uvicorn's own
+"Cancel N running task(s)" line is INFO too. A real error at any time, and any
+other cancellation, keeps its level and traceback.
+"""
+
+import asyncio
+import logging
+
+import pytest
+
+from backend.app.core.logging_filters import ShutdownCancelledRequestFilter
+
+SHUTDOWN_CANCEL = "Task cancelled, timeout graceful shutdown exceeded"
+
+
+def _record(msg, args=None, exc=None, level=logging.ERROR):
+    exc_info = (type(exc), exc, None) if exc is not None else None
+    return logging.LogRecord("uvicorn.error", level, "", 0, msg, args, exc_info)
+
+
+@pytest.fixture
+def f():
+    return ShutdownCancelledRequestFilter()
+
+
+def test_a_request_cancelled_at_shutdown_is_one_info_line(f):
+    record = _record("Exception in ASGI application\n", exc=asyncio.CancelledError(SHUTDOWN_CANCEL))
+
+    assert f.filter(record) is True
+    assert (record.levelno, record.levelname) == (logging.INFO, "INFO")
+    assert record.exc_info is None and record.exc_text is None
+    assert "closed at shutdown" in record.getMessage()
+
+
+def test_uvicorns_count_of_cancelled_tasks_is_info(f):
+    record = _record("Cancel %s running task(s), timeout graceful shutdown exceeded", (2,))
+
+    f.filter(record)
+
+    assert record.levelno == logging.INFO
+    assert record.getMessage() == "Cancel 2 running task(s), timeout graceful shutdown exceeded"
+
+
+@pytest.mark.parametrize(
+    "exc",
+    [RuntimeError("boom"), asyncio.CancelledError(), asyncio.CancelledError("client went away")],
+)
+def test_other_failures_keep_their_traceback(f, exc):
+    record = _record("Exception in ASGI application\n", exc=exc)
+
+    f.filter(record)
+
+    assert record.levelno == logging.ERROR
+    assert record.exc_info is not None
+
+
+def test_it_is_on_uvicorns_logger_ahead_of_the_traceback_filters():
+    """Attached by main; first, so no other filter renders the traceback."""
+    from backend.app import main  # noqa: F401 - installs the filters
+
+    filters = logging.getLogger("uvicorn.error").filters
+    assert isinstance(filters[0], ShutdownCancelledRequestFilter)
+
+
+def test_what_the_log_file_gets():
+    """Through the real logger: a line, no traceback."""
+    import io
+
+    from backend.app import main  # noqa: F401 - installs the filters
+
+    stream = io.StringIO()
+    handler = logging.StreamHandler(stream)
+    handler.setFormatter(logging.Formatter("%(levelname)s %(message)s"))
+    logger = logging.getLogger("uvicorn.error")
+    logger.addHandler(handler)
+    try:
+        try:
+            raise asyncio.CancelledError(SHUTDOWN_CANCEL)
+        except asyncio.CancelledError as exc:
+            logger.error("Exception in ASGI application\n", exc_info=exc)
+    finally:
+        logger.removeHandler(handler)
+
+    written = stream.getvalue()
+    assert written.startswith("INFO Request closed at shutdown")
+    assert "Traceback" not in written