diff --git a/backend/app/main.py b/backend/app/main.py index 195b93cf1..1d333996e 100644 --- a/backend/app/main.py +++ b/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 diff --git a/backend/app/services/bambu_mqtt.py b/backend/app/services/bambu_mqtt.py index 74b44c5b1..151075d43 100644 --- a/backend/app/services/bambu_mqtt.py +++ b/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( diff --git a/backend/app/services/printer_manager.py b/backend/app/services/printer_manager.py index e570fb791..cbc315743 100644 --- a/backend/app/services/printer_manager.py +++ b/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.""" diff --git a/backend/tests/unit/services/test_bambu_mqtt.py b/backend/tests/unit/services/test_bambu_mqtt.py index 049566bcb..4aef18545 100644 --- a/backend/tests/unit/services/test_bambu_mqtt.py +++ b/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"