Browse Source

Don't log a printer callback cancelled at shutdown as an error (#3243)

Stopping the event loop cancels the printer callbacks still pending.
_schedule_async's done-callback then called result(), which raises
concurrent.futures.CancelledError. Unlike asyncio's, that one is an
Exception, so it was logged as "Exception in scheduled callback" with
a traceback. Two support packages show it as the last line before a
restart.

Return early on a cancelled future, as core/tasks.py already does. A
callback that raised is still logged as an error.
maziggy 1 day ago
parent
commit
3e646febd6

+ 1 - 0
CHANGELOG.md

@@ -138,6 +138,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
+- **Shutting Bambuddy down logged an error with a traceback when nothing was wrong (#3243, reported by @Thomansky)** — Stopping Bambuddy cancels the printer updates still waiting to be handled, and each cancelled one was logged as `ERROR ... Exception in scheduled callback` with a traceback, as the last line before the restart. In a log or a support bundle it looked like a crash. A cancelled update now ends quietly; one that actually fails is still logged as an error.
 - **H2D, H2D Pro and H2C with several AMS on one extruder marked the wrong tray as loaded on every filament change (#3242, reported by @Thomansky)** — These printers report the loading tray as a slot number (0-3) without saying which AMS it is in, and the report that says which AMS is read a moment later. In that gap Bambuddy assumed AMS 0: during a print feeding from AMS 2 slot 1, AMS 0 slot 1 showed as loaded for about a second, and that tray went into the list of tray changes that splits a print's filament between spools. Support packages show this on every filament change.
   - **Now:** while a print runs, the slot is matched against the trays the print uses, taken from the printer's own mapping. If that doesn't settle it, as in a multi-colour print with the same slot in two AMS, the tray already loaded stays marked until the printer says which one is feeding.
   - **Usage:** no case was found where a spool was actually charged for the wrong tray, because the wrong tray was always replaced within the same layer. It no longer gets into the list at all.

+ 5 - 0
backend/app/services/printer_manager.py

@@ -706,6 +706,11 @@ class PrinterManager:
             future = asyncio.run_coroutine_threadsafe(coro, self._loop)
 
             def handle_exception(f):
+                # Stopping the loop cancels callbacks still pending. That is
+                # shutdown, not a failure (#3243), and concurrent.futures'
+                # CancelledError is an Exception, so it would be logged below.
+                if f.cancelled():
+                    return
                 try:
                     # This will re-raise any exception from the coroutine
                     f.result()

+ 71 - 0
backend/tests/unit/services/test_printer_manager.py

@@ -152,6 +152,77 @@ class TestPrinterManager:
         manager._schedule_async(coro)
         coro.close()
 
+    @staticmethod
+    def _run_with_loop_thread(manager, coro_fn, cancel: bool):
+        """Schedule on a real loop in a thread, the way the MQTT thread does.
+
+        With ``cancel``, cancel the task once it runs, as stopping the loop
+        does at shutdown. Returns the future ``_schedule_async`` created,
+        settled, with its done-callback already run.
+        """
+        import asyncio
+        import concurrent.futures
+        import threading
+
+        loop = asyncio.new_event_loop()
+        thread = threading.Thread(target=loop.run_forever, daemon=True)
+        thread.start()
+        futures = []
+        real = asyncio.run_coroutine_threadsafe
+
+        def record(coro, target_loop):
+            future = real(coro, target_loop)
+            futures.append(future)
+            return future
+
+        started = threading.Event()
+
+        async def wrapped():
+            started.set()
+            return await coro_fn()
+
+        try:
+            manager._loop = loop
+            with patch("asyncio.run_coroutine_threadsafe", side_effect=record):
+                manager._schedule_async(wrapped())
+            assert len(futures) == 1
+            if cancel:
+                assert started.wait(timeout=5)
+                loop.call_soon_threadsafe(lambda: [t.cancel() for t in asyncio.all_tasks(loop)])
+            concurrent.futures.wait(futures, timeout=5)
+        finally:
+            # Callbacks run on the loop thread; joining it means they have run.
+            loop.call_soon_threadsafe(loop.stop)
+            thread.join(timeout=5)
+            loop.close()
+        return futures[0]
+
+    def test_schedule_async_cancelled_callback_is_not_an_error(self, manager, caplog):
+        """#3243: shutdown cancels pending callbacks; that must not log an ERROR."""
+        import asyncio
+        import logging
+
+        async def slow():
+            await asyncio.sleep(10)
+
+        with caplog.at_level(logging.DEBUG, logger="backend.app.services.printer_manager"):
+            future = self._run_with_loop_thread(manager, slow, cancel=True)
+
+        assert future.cancelled()
+        assert "Exception in scheduled callback" not in caplog.text
+
+    def test_schedule_async_failing_callback_is_still_logged(self, manager, caplog):
+        import logging
+
+        async def boom():
+            raise RuntimeError("callback failed")
+
+        with caplog.at_level(logging.ERROR, logger="backend.app.services.printer_manager"):
+            future = self._run_with_loop_thread(manager, boom, cancel=False)
+
+        assert isinstance(future.exception(), RuntimeError)
+        assert "Exception in scheduled callback: callback failed" in caplog.text
+
     def test_schedule_async_with_stopped_loop(self, manager):
         """Verify nothing happens when loop is not running."""
         mock_loop = MagicMock()