diff --git a/backend/app/main.py b/backend/app/main.py index 25a222a70..9a8bc3e79 100644 --- a/backend/app/main.py +++ b/backend/app/main.py @@ -129,6 +129,7 @@ from backend.app.services.spoolman_tracking import ( ) from backend.app.services.tasmota import tasmota_service from backend.app.utils.ams_drying import is_drying_active, temperature_alarm_suppressed +from backend.app.utils.print_jobs import is_internal_printer_job # ============================================================================= @@ -3043,12 +3044,21 @@ async def on_print_start(printer_id: int, data: dict): logger.info("[CALLBACK] Print start detected - filename: %s, subtask: %s", filename, subtask_name) - # Skip calibration prints — internal printer files should not be archived - # Bambu calibration gcode lives under /usr/ (e.g. /usr/etc/print/auto_cali_for_user.gcode) - if filename and filename.startswith("/usr/"): - logger.info("[CALLBACK] Skipping archive — internal printer file detected: %s", filename) - if not notification_sent: - await _send_print_start_notification(printer_id, data, logger=logger) + # Skip the printer's own jobs — a calibration run is not a user's print. + # See is_internal_printer_job for what counts and why both fields are + # tested; the pressure-advance line reports as a subtask name with no + # /usr/ path, which the old prefix-only test here missed entirely. + # + # No notification either. The event describes the printer calibrating + # itself, so "Print started" is as wrong as the archive was, and the + # matching completion is suppressed in on_print_complete for the same + # reason. + if is_internal_printer_job(filename, subtask_name): + logger.info( + "[CALLBACK] Skipping archive — internal printer job detected: filename=%s, subtask=%s", + filename, + subtask_name, + ) return if not filename and not subtask_name: @@ -5875,6 +5885,23 @@ async def on_print_complete(printer_id: int, data: dict): log_timing("Filament usage tracking") if not archive_id: + # The printer's own calibration run has no archive by design, so this + # arrives here every time one finishes. Returning before the no-archive + # notification is not just noise control: that path attributes an + # unmatched completion to any queue item this printer finished in the + # last five minutes, which for a calibration that runs alongside a real + # print means emailing its owner that their print is done, twice and + # early. Everything above this point has already run — the plate-clear + # gate, the queue reconciliation, the SD-card cleanup — so only the + # notification is skipped. + if is_internal_printer_job(filename, subtask_name): + logger.info( + "[CALLBACK] Internal printer job completed, no notification: filename=%s, subtask=%s", + filename, + subtask_name, + ) + return + logger.warning("Could not find archive for print complete: filename=%s, subtask=%s", filename, subtask_name) # Still send print-complete/failed/stopped notifications even without an archive. diff --git a/backend/app/utils/print_jobs.py b/backend/app/utils/print_jobs.py new file mode 100644 index 000000000..1f378f9df --- /dev/null +++ b/backend/app/utils/print_jobs.py @@ -0,0 +1,72 @@ +"""Telling the printer's own internal jobs apart from a user's print. + +Bambu firmware runs jobs on its own behalf -- bed levelling, vibration +compensation, the pressure-advance line it lays down before a print when flow +dynamics calibration is on -- and reports them over MQTT through exactly the +same print-start and print-complete events a real print uses. Nothing about the +event says "this one is mine": Bambuddy has to recognise the job by name. + +Getting that wrong is not free. An unrecognised calibration run has no 3MF +anywhere on the printer, so the archive path sweeps FTP for a file that cannot +exist -- six candidate names across five directories, with retries -- and then +writes a no-3MF archive named after the calibration, on a printer that is in +the middle of calibrating. + +Kept as a leaf module with no imports of its own so both the print-start and +print-complete callbacks can share one answer. +""" + +# Job names the printer runs for itself. Matched exactly (after normalising), +# not by prefix or substring: "auto" and "calib" are ordinary words in a user's +# own filenames, and a rule loose enough to catch an unnamed future calibration +# would silently swallow somebody's print. +# +# ``auto_cali_for_user`` is the bed-levelling / vibration run, normally reported +# with a ``/usr/etc/print/`` path that the rule below catches on its own; it is +# listed anyway because the path is not guaranteed and a name-only report of it +# would otherwise slip through. +# +# ``auto_pa_line_calib_mode`` is the pressure-advance (K profile) line. This one +# is reported as a *subtask name* with no ``/usr/`` path at all, which is why +# the path rule alone was never enough. +INTERNAL_JOB_NAMES = frozenset( + { + "auto_cali_for_user", + "auto_pa_line_calib_mode", + } +) + +# Longest first: ``.gcode.3mf`` has to be stripped whole, or ``.3mf`` would +# match first and leave a trailing ``.gcode`` behind. +_PRINT_SUFFIXES = (".gcode.3mf", ".gcode", ".3mf") + + +def _normalize_job_name(value: str) -> str: + """Reduce a reported name to something comparable against the set above. + + Drops any directory part, one print-file suffix, and case. The printer is + not consistent about which of these it includes -- the same calibration + reports as a bare name in ``subtask_name`` and, when it appears at all, as + a full path in ``gcode_file``. + """ + name = value.rsplit("/", 1)[-1].rsplit("\\", 1)[-1].strip().casefold() + for suffix in _PRINT_SUFFIXES: + if name.endswith(suffix): + return name[: -len(suffix)] + return name + + +def is_internal_printer_job(filename: str | None, subtask_name: str | None = None) -> bool: + """True when this print event belongs to the printer, not to a user. + + Both fields are tested because neither is reliably populated: the + pressure-advance line arrives as a subtask name with no filename, while the + levelling run arrives as a ``/usr/etc/print/...`` path. A job is internal if + *either* field says so. + """ + if filename and filename.startswith("/usr/"): + # Bambu keeps its own calibration gcode on the read-only system + # partition. Nothing a user can print ever lives there, so the whole + # prefix is safe to treat as internal without naming each file. + return True + return any(_normalize_job_name(value) in INTERNAL_JOB_NAMES for value in (filename, subtask_name) if value) diff --git a/backend/tests/unit/test_archive_filtering.py b/backend/tests/unit/test_archive_filtering.py index b15f5195d..7789f7cc9 100644 --- a/backend/tests/unit/test_archive_filtering.py +++ b/backend/tests/unit/test_archive_filtering.py @@ -59,13 +59,16 @@ class TestCalibrationPrintFiltering: }, ) - # Notification should still be sent - mock_notif_send.assert_called_once() + # And no notification. The event describes the printer + # calibrating itself, so "Print started: auto_cali_for_user" is + # as wrong as the archive would have been. This assertion used + # to demand the opposite. + mock_notif_send.assert_not_called() # Verify the skip was logged info_messages = [r.message for r in capture_logs.records if r.levelno >= 20] - skip_msgs = [m for m in info_messages if "internal printer file" in str(m)] - assert skip_msgs, "Should log that internal printer file was skipped" + skip_msgs = [m for m in info_messages if "internal printer job" in str(m)] + assert skip_msgs, "Should log that an internal printer job was skipped" @pytest.mark.asyncio async def test_usr_prefix_various_paths(self, capture_logs): @@ -108,7 +111,7 @@ class TestCalibrationPrintFiltering: await on_print_start(1, {"filename": path, "subtask_name": "test"}) - skip_msgs = [r for r in capture_logs.records if "internal printer file" in str(r.message)] + skip_msgs = [r for r in capture_logs.records if "internal printer job" in str(r.message)] assert skip_msgs, f"Path {path} should be skipped" capture_logs.clear() diff --git a/backend/tests/unit/test_internal_printer_jobs.py b/backend/tests/unit/test_internal_printer_jobs.py new file mode 100644 index 000000000..04271c25e --- /dev/null +++ b/backend/tests/unit/test_internal_printer_jobs.py @@ -0,0 +1,212 @@ +"""The printer's own calibration runs leave no archive and send no notification. + +Auto pressure-advance calibration -- the K-profile line the printer lays down +before a print when flow dynamics calibration is on -- reports over MQTT through +the same print-start event a real print uses, as the subtask name +``auto_pa_line_calib_mode`` with no ``/usr/`` path attached. The only guard +Bambuddy had tested ``filename.startswith("/usr/")``, so the calibration sailed +past it, found no 3MF anywhere on the printer (there is none to find), and left +a no-3MF archive named after itself in the user's history. + +The same name is already known to the completion guard: #2829's capture of +queue item 649 has ``auto_pa_line_calib_mode`` arriving as the subtask name of a +completion that had to be refused against a running job. +""" + +from unittest.mock import AsyncMock, MagicMock, patch + +import pytest + +from backend.app.utils.print_jobs import is_internal_printer_job + + +class TestTheCalibrationIsRecognised: + def test_the_pressure_advance_line_by_subtask_name(self): + """How it actually arrives: a bare subtask name, no filename at all.""" + assert is_internal_printer_job("", "auto_pa_line_calib_mode") + + def test_the_pressure_advance_line_by_filename(self): + """Both fields are tested, because which one carries it is not fixed.""" + assert is_internal_printer_job("auto_pa_line_calib_mode", None) + + def test_the_levelling_run_by_its_system_path(self): + assert is_internal_printer_job("/usr/etc/print/auto_cali_for_user.gcode", "auto_cali_for_user") + + def test_the_levelling_run_by_name_alone(self): + """The /usr/ path is not guaranteed, so the name is listed too.""" + assert is_internal_printer_job(None, "auto_cali_for_user") + + @pytest.mark.parametrize( + "reported", + [ + "auto_pa_line_calib_mode", + "auto_pa_line_calib_mode.gcode", + "auto_pa_line_calib_mode.3mf", + "auto_pa_line_calib_mode.gcode.3mf", + "AUTO_PA_LINE_CALIB_MODE", + "/data/auto_pa_line_calib_mode.gcode.3mf", + ], + ) + def test_however_the_name_is_dressed_up(self, reported): + """Path, suffix and case all vary between the fields and firmwares.""" + assert is_internal_printer_job(reported, None) + + def test_anything_under_usr_counts(self): + """Nothing a user can print lives on the read-only system partition.""" + assert is_internal_printer_job("/usr/bin/firmware_test.gcode", "test") + + +class TestItLeavesRealPrintsAlone: + """The failure that matters: swallowing somebody's actual print.""" + + def test_an_ordinary_print(self): + assert not is_internal_printer_job("Benchy.gcode.3mf", "Benchy") + + def test_nothing_reported_at_all(self): + assert not is_internal_printer_job(None, None) + assert not is_internal_printer_job("", "") + + @pytest.mark.parametrize( + "reported", + [ + "auto_pa_line_calib_mode_v2.3mf", + "my_auto_pa_line_calib_mode.3mf", + "auto_cali_for_user_test.gcode.3mf", + ], + ) + def test_a_users_file_that_merely_contains_the_name(self, reported): + """Exact match after normalising, so no prefix or substring rule can + eat a file somebody deliberately named after the calibration.""" + assert not is_internal_printer_job(reported, None) + + def test_a_calibration_cube(self): + """The obvious false positive for any rule built on the word 'calib'.""" + assert not is_internal_printer_job("Calibration_Cube.gcode.3mf", "Calibration Cube") + + +def _mocked_print_start(): + """Patch set for driving on_print_start without a printer or database.""" + return ( + patch("backend.app.main.async_session"), + patch("backend.app.main.notification_service"), + patch("backend.app.main.smart_plug_manager"), + patch("backend.app.main.ws_manager"), + patch("backend.app.main.printer_manager"), + patch("backend.app.main.mqtt_relay"), + ) + + +class TestPrintStartSkipsTheCalibration: + @pytest.mark.asyncio + async def test_no_archive_and_no_notification(self, capture_logs): + sess, notif, plug, ws, pm, relay = _mocked_print_start() + with sess as mock_session_maker, notif as mock_notif, plug as mock_plug, ws as mock_ws, pm as mock_pm, relay: + mock_notif.on_print_start = AsyncMock() + mock_plug.on_print_start = AsyncMock() + mock_ws.send_print_start = AsyncMock() + mock_pm.get_printer = MagicMock(return_value=MagicMock(name="Test", serial_number="TEST123")) + + mock_printer = MagicMock() + mock_printer.auto_archive = True + mock_printer.id = 1 + + mock_session = AsyncMock() + mock_session.__aenter__ = AsyncMock(return_value=mock_session) + mock_session.__aexit__ = AsyncMock() + mock_session.execute = AsyncMock( + return_value=MagicMock(scalar_one_or_none=MagicMock(return_value=mock_printer)) + ) + mock_session_maker.return_value = mock_session + + with patch("backend.app.main._send_print_start_notification", new_callable=AsyncMock) as mock_notify: + from backend.app.main import on_print_start + + # No filename: exactly what the printer reports for this run, + # and the reason the old /usr/ prefix test never fired. + await on_print_start(1, {"filename": "", "subtask_name": "auto_pa_line_calib_mode"}) + + mock_notify.assert_not_called() + + skipped = [r for r in capture_logs.records if "internal printer job" in str(r.message)] + assert skipped, "Should log that the calibration run was skipped" + + +class TestPrintCompleteStaysQuiet: + @pytest.mark.asyncio + async def test_no_orphan_notification_when_the_calibration_finishes(self): + """With no archive to close, the completion would otherwise fall into + the no-archive notification path -- which attributes an unmatched + completion to any queue item this printer finished in the last five + minutes. For a calibration running alongside a real print that means + telling its owner their print is done, early and twice. + """ + with ( + patch("backend.app.main.async_session") as mock_session_maker, + patch("backend.app.main.ws_manager") as mock_ws, + patch("backend.app.main.printer_manager") as mock_pm, + patch("backend.app.main.mqtt_relay") as mock_relay, + patch("backend.app.main.spawn_background_task") as mock_spawn, + patch("backend.app.main.clear_3mf_cache"), + ): + mock_ws.send_print_complete = AsyncMock() + mock_relay.on_print_complete = AsyncMock() + mock_pm.get_printer = MagicMock(return_value=MagicMock(name="Test", serial_number="TEST123")) + mock_pm.get_current_print_user = MagicMock(return_value=None) + mock_pm.clear_current_print_user = MagicMock() + mock_pm.set_awaiting_plate_clear = MagicMock() + + mock_session = AsyncMock() + mock_session.__aenter__ = AsyncMock(return_value=mock_session) + mock_session.__aexit__ = AsyncMock() + mock_session.execute = AsyncMock( + return_value=MagicMock(scalar_one_or_none=MagicMock(return_value=None), scalars=MagicMock()) + ) + mock_session_maker.return_value = mock_session + + from backend.app.main import on_print_complete + + await on_print_complete( + 1, + {"filename": "", "subtask_name": "auto_pa_line_calib_mode", "status": "completed"}, + ) + + spawned = [c for c in mock_spawn.call_args_list if "notify-no-archive" in str(c)] + assert not spawned, "No completion notification should be spawned for a calibration run" + + @pytest.mark.asyncio + async def test_a_real_orphan_print_still_notifies(self): + """The no-archive path exists for prints started outside Bambuddy. The + guard must not take those down with it. + """ + with ( + patch("backend.app.main.async_session") as mock_session_maker, + patch("backend.app.main.ws_manager") as mock_ws, + patch("backend.app.main.printer_manager") as mock_pm, + patch("backend.app.main.mqtt_relay") as mock_relay, + patch("backend.app.main.spawn_background_task") as mock_spawn, + patch("backend.app.main.clear_3mf_cache"), + ): + mock_ws.send_print_complete = AsyncMock() + mock_relay.on_print_complete = AsyncMock() + mock_pm.get_printer = MagicMock(return_value=MagicMock(name="Test", serial_number="TEST123")) + mock_pm.get_current_print_user = MagicMock(return_value=None) + mock_pm.clear_current_print_user = MagicMock() + mock_pm.set_awaiting_plate_clear = MagicMock() + + mock_session = AsyncMock() + mock_session.__aenter__ = AsyncMock(return_value=mock_session) + mock_session.__aexit__ = AsyncMock() + mock_session.execute = AsyncMock( + return_value=MagicMock(scalar_one_or_none=MagicMock(return_value=None), scalars=MagicMock()) + ) + mock_session_maker.return_value = mock_session + + from backend.app.main import on_print_complete + + await on_print_complete( + 1, + {"filename": "", "subtask_name": "Benchy", "status": "completed"}, + ) + + spawned = [c for c in mock_spawn.call_args_list if "notify-no-archive" in str(c)] + assert spawned, "An unmatched real print must still notify"