1. Timelapse Race Condition Fix (bambu_mqtt.py)

Problem: xcam data was parsed BEFORE _was_running was set to True, so timelapse detection failed when both arrived in the same message.

  Fix: Added timelapse detection at two critical points:

  # Lines 1375-1381: When entering RUNNING state
  if self.state.state == "RUNNING" and current_file:
      if not self._was_running:
          if self.state.timelapse:
              self._timelapse_during_print = True
              logger.info(f"[{self.serial_number}] Timelapse detected when entering RUNNING state")

  # Lines 1391-1399: When print start detected
  if self.state.timelapse:
      self._timelapse_during_print = True
      logger.info(f"[{self.serial_number}] Timelapse detected at print start")

  2. Callback Error Handling (main.py + printer_manager.py)

  Problem: The on_print_complete callback was hanging silently - no logs after "Found archive".

  Fixes:
  - Added try/except wrapper around "Update archive status" section (line 749-767)
  - Added [CALLBACK] log messages at start and end of callback
  - Added exception handler to _schedule_async in printer_manager.py to log any exceptions from async callbacks

  3. New Integration Tests (test_bambu_mqtt.py)

  Added TestRealisticMessageFlow class with 5 new tests that simulate real MQTT message sequences:

  1. test_timelapse_detected_at_print_start_in_same_message - The critical race condition test
  2. test_timelapse_not_detected_when_disabled
  3. test_timelapse_detected_when_enabled_after_print_start
  4. test_print_complete_includes_timelapse_flag_full_flow - Full lifecycle test
  5. test_print_failed_includes_timelapse_flag

  These tests process messages through _process_message() with proper {"print": {...}} wrapping, matching real MQTT flow.

  Files Modified:

  - backend/app/services/bambu_mqtt.py - Timelapse race condition fix
  - backend/app/main.py - Error handling + logging for on_print_complete
  - backend/app/services/printer_manager.py - Exception capture in _schedule_async
  - backend/tests/unit/services/test_bambu_mqtt.py - New integration tests

  Next Steps

  You should restart the application to apply these changes. The next print will show:
  - [CALLBACK] on_print_complete started for printer X
  - [ARCHIVE] Updating archive X status...
  - [ENERGY], [PHOTO], [AUTO-OFF] logs (if those features trigger)
  - [CALLBACK] on_print_complete finished for printer X, archive X

backend/app/main.py

@@ -641,7 +641,12 @@ async def on_print_complete(printer_id: int, data: dict):
     import logging
     logger = logging.getLogger(__name__)
 
-    await ws_manager.send_print_complete(printer_id, data)
+    logger.info(f"[CALLBACK] on_print_complete started for printer {printer_id}")
+
+    try:
+        await ws_manager.send_print_complete(printer_id, data)
+    except Exception as e:
+        logger.warning(f"[CALLBACK] WebSocket send_print_complete failed: {e}")
 
     filename = data.get("filename", "")
     subtask_name = data.get("subtask_name", "")
@@ -745,19 +750,26 @@ async def on_print_complete(printer_id: int, data: dict):
         return
 
     # Update archive status
-    async with async_session() as db:
-        service = ArchiveService(db)
-        status = data.get("status", "completed")
-        await service.update_archive_status(
-            archive_id,
-            status=status,
-            completed_at=datetime.now() if status in ("completed", "failed", "aborted") else None,
-        )
+    logger.info(f"[ARCHIVE] Updating archive {archive_id} status...")
+    try:
+        async with async_session() as db:
+            service = ArchiveService(db)
+            status = data.get("status", "completed")
+            await service.update_archive_status(
+                archive_id,
+                status=status,
+                completed_at=datetime.now() if status in ("completed", "failed", "aborted") else None,
+            )
+            logger.info(f"[ARCHIVE] Archive {archive_id} status updated to {status}")
 
-        await ws_manager.send_archive_updated({
-            "id": archive_id,
-            "status": status,
-        })
+            await ws_manager.send_archive_updated({
+                "id": archive_id,
+                "status": status,
+            })
+            logger.info(f"[ARCHIVE] WebSocket notification sent for archive {archive_id}")
+    except Exception as e:
+        logger.error(f"[ARCHIVE] Failed to update archive {archive_id} status: {e}", exc_info=True)
+        # Continue with other operations even if archive update fails
 
     # Report filament usage to Spoolman if print completed successfully
     if data.get("status") == "completed":
@@ -1094,6 +1106,8 @@ async def on_print_complete(printer_id: int, data: dict):
         import logging
         logging.getLogger(__name__).warning(f"Queue item update failed: {e}")
 
+    logger.info(f"[CALLBACK] on_print_complete finished for printer {printer_id}, archive {archive_id}")
+
 
 # AMS sensor history recording
 _ams_history_task: asyncio.Task | None = None

backend/app/services/bambu_mqtt.py

@@ -1375,6 +1375,10 @@ class BambuMQTTClient:
         if self.state.state == "RUNNING" and current_file:
             if not self._was_running:
                 logger.info(f"[{self.serial_number}] Now tracking RUNNING state for {current_file}")
+                # Check if timelapse was enabled in the same message (xcam parsed before this)
+                if self.state.timelapse:
+                    self._timelapse_during_print = True
+                    logger.info(f"[{self.serial_number}] Timelapse detected when entering RUNNING state")
             self._was_running = True
             self._completion_triggered = False
 
@@ -1384,8 +1388,15 @@ class BambuMQTTClient:
             # Reset completion tracking for new print
             self._was_running = True
             self._completion_triggered = False
-            # Reset timelapse tracking - will be set to True if timelapse is detected during print
-            self._timelapse_during_print = False
+            # Initialize timelapse tracking based on current state
+            # NOTE: xcam data is parsed BEFORE this code runs in _process_message,
+            # so self.state.timelapse may already be set from this message.
+            # We preserve that value instead of blindly resetting to False.
+            if self.state.timelapse:
+                self._timelapse_during_print = True
+                logger.info(f"[{self.serial_number}] Timelapse detected at print start")
+            else:
+                self._timelapse_during_print = False
 
         if (is_new_print or is_file_change) and self.on_print_start:
             logger.info(

backend/app/services/printer_manager.py

@@ -42,9 +42,25 @@ class PrinterManager:
         self._on_ams_change = callback
 
     def _schedule_async(self, coro):
-        """Schedule an async coroutine from a sync context."""
+        """Schedule an async coroutine from a sync context.
+
+        Captures exceptions from the coroutine and logs them to prevent
+        silent failures in callbacks.
+        """
         if self._loop and self._loop.is_running():
-            asyncio.run_coroutine_threadsafe(coro, self._loop)
+            future = asyncio.run_coroutine_threadsafe(coro, self._loop)
+
+            def handle_exception(f):
+                try:
+                    # This will re-raise any exception from the coroutine
+                    f.result()
+                except Exception as e:
+                    import logging
+                    logging.getLogger(__name__).error(
+                        f"Exception in scheduled callback: {e}", exc_info=True
+                    )
+
+            future.add_done_callback(handle_exception)
 
     async def connect_printer(self, printer: Printer) -> bool:
         """Connect to a printer."""

backend/tests/unit/services/test_bambu_mqtt.py

@@ -191,3 +191,221 @@ class TestPrintCompletionWithTimelapse:
         mqtt_client._timelapse_during_print = False
 
         assert mqtt_client._timelapse_during_print is False
+
+
+class TestRealisticMessageFlow:
+    """Tests that simulate realistic MQTT message sequences.
+
+    These tests process messages through _process_message to test the full flow,
+    including the order of xcam parsing vs state detection.
+    """
+
+    @pytest.fixture
+    def mqtt_client(self):
+        """Create a BambuMQTTClient instance for testing."""
+        from backend.app.services.bambu_mqtt import BambuMQTTClient
+
+        client = BambuMQTTClient(
+            ip_address="192.168.1.100",
+            serial_number="TEST123",
+            access_code="12345678",
+        )
+        return client
+
+    def test_timelapse_detected_at_print_start_in_same_message(self, mqtt_client):
+        """Test that timelapse is detected when xcam and state come in same message.
+
+        This is the critical race condition test - xcam data is parsed BEFORE
+        state detection, so the timelapse flag must be set AFTER _was_running is True.
+        """
+        # Callbacks to track events
+        start_callback_data = {}
+
+        def on_start(data):
+            start_callback_data.update(data)
+
+        mqtt_client.on_print_start = on_start
+
+        # Initial state - idle
+        mqtt_client._was_running = False
+        mqtt_client._timelapse_during_print = False
+        mqtt_client._previous_gcode_state = None
+
+        # Simulate first message when print starts - contains both xcam and gcode_state
+        # This is the realistic scenario from the printer
+        # NOTE: Real MQTT messages wrap print data inside a "print" key
+        payload = {
+            "print": {
+                "gcode_state": "RUNNING",
+                "gcode_file": "/data/Metadata/test_print.gcode",
+                "subtask_name": "Test_Print",
+                "xcam": {
+                    "timelapse": "enable",  # Timelapse is enabled in this print
+                    "printing_monitor": True,
+                },
+                "mc_percent": 0,
+                "mc_remaining_time": 3600,
+            }
+        }
+
+        # Process the message (this is what happens in real MQTT flow)
+        mqtt_client._process_message(payload)
+
+        # Verify timelapse was detected even though xcam is parsed before state
+        assert mqtt_client._was_running is True, "_was_running should be True after RUNNING state"
+        assert mqtt_client.state.timelapse is True, "state.timelapse should be True"
+        assert mqtt_client._timelapse_during_print is True, (
+            "timelapse_during_print should be True when timelapse is in the same message as RUNNING state"
+        )
+
+    def test_timelapse_not_detected_when_disabled(self, mqtt_client):
+        """Test that timelapse is NOT detected when disabled in xcam data."""
+        mqtt_client.on_print_start = lambda data: None
+
+        # Initial state - idle
+        mqtt_client._was_running = False
+        mqtt_client._timelapse_during_print = False
+        mqtt_client._previous_gcode_state = None
+
+        # Print starts without timelapse
+        payload = {
+            "print": {
+                "gcode_state": "RUNNING",
+                "gcode_file": "/data/Metadata/test_print.gcode",
+                "subtask_name": "Test_Print",
+                "xcam": {
+                    "timelapse": "disable",  # Timelapse is disabled
+                    "printing_monitor": True,
+                },
+            }
+        }
+
+        mqtt_client._process_message(payload)
+
+        assert mqtt_client._was_running is True
+        assert mqtt_client.state.timelapse is False
+        assert mqtt_client._timelapse_during_print is False
+
+    def test_timelapse_detected_when_enabled_after_print_start(self, mqtt_client):
+        """Test timelapse detected when enabled in a message after print starts."""
+        mqtt_client.on_print_start = lambda data: None
+
+        # First message - print starts without timelapse info
+        payload_start = {
+            "print": {
+                "gcode_state": "RUNNING",
+                "gcode_file": "/data/Metadata/test_print.gcode",
+                "subtask_name": "Test_Print",
+            }
+        }
+        mqtt_client._process_message(payload_start)
+
+        assert mqtt_client._was_running is True
+        assert mqtt_client._timelapse_during_print is False  # Not detected yet
+
+        # Second message - xcam data arrives with timelapse enabled
+        payload_xcam = {
+            "print": {
+                "gcode_state": "RUNNING",
+                "gcode_file": "/data/Metadata/test_print.gcode",
+                "subtask_name": "Test_Print",
+                "xcam": {
+                    "timelapse": "enable",
+                },
+            }
+        }
+        mqtt_client._process_message(payload_xcam)
+
+        # Now timelapse should be detected because _was_running is already True
+        assert mqtt_client._timelapse_during_print is True
+
+    def test_print_complete_includes_timelapse_flag_full_flow(self, mqtt_client):
+        """Test full print lifecycle with timelapse - from start to completion."""
+        start_data = {}
+        complete_data = {}
+
+        def on_start(data):
+            start_data.update(data)
+
+        def on_complete(data):
+            complete_data.update(data)
+
+        mqtt_client.on_print_start = on_start
+        mqtt_client.on_print_complete = on_complete
+
+        # 1. Print starts with timelapse
+        mqtt_client._process_message({
+            "print": {
+                "gcode_state": "RUNNING",
+                "gcode_file": "/data/Metadata/test.gcode",
+                "subtask_name": "Test",
+                "xcam": {"timelapse": "enable"},
+            }
+        })
+
+        assert mqtt_client._timelapse_during_print is True
+        assert "subtask_name" in start_data
+
+        # 2. Print continues (multiple messages)
+        for _ in range(3):
+            mqtt_client._process_message({
+                "print": {
+                    "gcode_state": "RUNNING",
+                    "gcode_file": "/data/Metadata/test.gcode",
+                    "subtask_name": "Test",
+                    "mc_percent": 50,
+                }
+            })
+
+        # Timelapse flag should still be True
+        assert mqtt_client._timelapse_during_print is True
+
+        # 3. Print completes
+        mqtt_client._process_message({
+            "print": {
+                "gcode_state": "FINISH",
+                "gcode_file": "/data/Metadata/test.gcode",
+                "subtask_name": "Test",
+            }
+        })
+
+        # Verify completion callback received timelapse flag
+        assert "timelapse_was_active" in complete_data
+        assert complete_data["timelapse_was_active"] is True
+        assert complete_data["status"] == "completed"
+
+        # Flags should be reset after completion
+        assert mqtt_client._timelapse_during_print is False
+        assert mqtt_client._was_running is False
+
+    def test_print_failed_includes_timelapse_flag(self, mqtt_client):
+        """Test that failed print also includes timelapse flag."""
+        complete_data = {}
+
+        def on_complete(data):
+            complete_data.update(data)
+
+        mqtt_client.on_print_start = lambda data: None
+        mqtt_client.on_print_complete = on_complete
+
+        # Start with timelapse
+        mqtt_client._process_message({
+            "print": {
+                "gcode_state": "RUNNING",
+                "gcode_file": "/data/Metadata/test.gcode",
+                "subtask_name": "Test",
+                "xcam": {"timelapse": "enable"},
+            }
+        })
+
+        # Print fails
+        mqtt_client._process_message({
+            "print": {
+                "gcode_state": "FAILED",
+                "gcode_file": "/data/Metadata/test.gcode",
+                "subtask_name": "Test",
+            }
+        })
+
+        assert complete_data["timelapse_was_active"] is True
+        assert complete_data["status"] == "failed"