Procházet zdrojové kódy

fix(notifications): a print without an archive is no longer attributed to the previous queue job

maziggy před 1 týdnem
rodič
revize
8c0826f69d

+ 0 - 16
.basedpyright/baseline.json

@@ -4057,22 +4057,6 @@
                     "lineCount": 1
                 }
             },
-            {
-                "code": "reportAttributeAccessIssue",
-                "range": {
-                    "startColumn": 57,
-                    "endColumn": 75,
-                    "lineCount": 1
-                }
-            },
-            {
-                "code": "reportAttributeAccessIssue",
-                "range": {
-                    "startColumn": 85,
-                    "endColumn": 103,
-                    "lineCount": 1
-                }
-            },
             {
                 "code": "reportAttributeAccessIssue",
                 "range": {

+ 2 - 0
CHANGELOG.md

@@ -161,6 +161,8 @@ 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 print started outside Bambuddy could be reported to the owner of the previous queue job** — On a printer with **Auto-archive completed prints** switched off (in the printer's settings), a print Bambuddy didn't start (for example one started on the printer itself) has no archive. When it finished, failed or was stopped, the notification looked for any queue job this printer had finished in the last five minutes and treated the print as that job: its owner got the "your print is done" email for a print that wasn't theirs. It now uses only the queue job the print itself belongs to, so such a print isn't sent to anyone's personal email.
+  - **A queue job whose archive couldn't be found** at the end, when it finishes or fails, is still reported to its owner, and its duration (`{duration}`) is how long it actually ran instead of "Unknown". A job stopped from the queue page in that situation no longer sends its owner the "stopped" email.
 - **Smart plug power alerts were never sent** — A plug's **Power Alerts** (alert if the power is above or below a value) never reached any notification provider, and each time one was due, that request for the plug's status on the printer card failed. They also were only checked while someone had a printer page open.
   - **Now checked in the background,** about once a minute, whether or not Bambuddy is open.
   - **One alert per crossing:** you're told when the power leaves the range, and again only after it was back inside it, so a printer idling below a low value is reported once rather than every five minutes. The low value only counts while the plug reports itself switched on, so turning a printer off raises no alert (a plug that can't report its switch state gets no low alerts). Alerts go out as the **Printer Error** event ("Printer Error: Power High" / "Power Low"). Wiki updated.

+ 24 - 25
backend/app/main.py

@@ -163,7 +163,7 @@ from backend.app.utils.ams_drying import is_drying_active, temperature_alarm_sup
 from backend.app.utils.ams_humidity import ams_humidity_percent
 from backend.app.utils.filament_types import printer_filament_type
 from backend.app.utils.fts_routing import extruder_for_inlet
-from backend.app.utils.local_time import utcnow_naive
+from backend.app.utils.local_time import to_naive_utc, utcnow_naive
 from backend.app.utils.print_jobs import is_internal_printer_job
 
 
@@ -7809,11 +7809,8 @@ async def on_print_complete(printer_id: int, data: dict):
     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
+        # notification keeps a calibration from being announced as a finished
+        # print. 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):
@@ -7839,33 +7836,35 @@ async def on_print_complete(printer_id: int, data: dict):
                     printer_obj = result.scalar_one_or_none()
                     p_name = printer_obj.name if printer_obj else f"Printer {printer_id}"
 
-                    # Try to find the most-recent queue item for this printer so we can
-                    # recover created_by_id and estimated print time.
-                    # NOTE: By the time this task runs the queue item status has already
-                    # been updated to a terminal state (completed/failed/cancelled), so
-                    # we look for recently-completed items (within the last 5 minutes).
+                    # Only the queue item this completion itself closed (the
+                    # reconciliation above, which checks the run belongs to it).
+                    # A print started outside Bambuddy closed none, and must not
+                    # borrow an earlier job's owner, email or times.
                     no_archive_data: dict | None = None
                     try:
-                        cutoff = datetime.now(timezone.utc) - timedelta(minutes=5)
-                        q_result = await db.execute(
-                            select(PrintQueueItem)
-                            .where(PrintQueueItem.printer_id == printer_id)
-                            .where(PrintQueueItem.status.in_(["completed", "failed", "cancelled"]))
-                            .where(PrintQueueItem.completed_at >= cutoff)
-                            .order_by(PrintQueueItem.completed_at.desc())
-                            .limit(1)
-                        )
-                        queue_item = q_result.scalar_one_or_none()
+                        queue_item = await db.get(PrintQueueItem, queue_item_id) if queue_item_id else None
                         if queue_item:
                             no_archive_data = {"created_by_id": queue_item.created_by_id}
-                            # Pull estimated time from library file when available
-                            if queue_item.library_file_id:
+                            # How long it really ran, as the archive path reports it (#1198).
+                            started = to_naive_utc(queue_item.started_at)
+                            ended = to_naive_utc(queue_item.completed_at)
+                            if started and ended and (ended - started).total_seconds() > 0:
+                                no_archive_data["actual_time_seconds"] = int((ended - started).total_seconds())
+                            # Estimated time: the queue item caches it from its
+                            # archive or library file; otherwise read the library
+                            # file's metadata (LibraryFile has no column for it).
+                            if queue_item.print_time_seconds:
+                                no_archive_data["print_time_seconds"] = queue_item.print_time_seconds
+                            elif queue_item.library_file_id:
                                 lib_result = await db.execute(
                                     select(LibraryFile).where(LibraryFile.id == queue_item.library_file_id)
                                 )
                                 lib_file = lib_result.scalar_one_or_none()
-                                if lib_file and lib_file.print_time_seconds:
-                                    no_archive_data["print_time_seconds"] = lib_file.print_time_seconds
+                                estimate = (
+                                    (lib_file.file_metadata or {}).get("print_time_seconds") if lib_file else None
+                                )
+                                if estimate:
+                                    no_archive_data["print_time_seconds"] = estimate
                     except Exception as lookup_err:
                         logger.debug(
                             "[NOTIFY-BG] Could not look up queue item for no-archive notification: %s", lookup_err

+ 147 - 0
backend/tests/unit/test_notify_no_archive_duration.py

@@ -0,0 +1,147 @@
+"""A completion with no archive is notified about its own queue job, or none.
+
+When a completion matches no archive, the notification used to borrow the
+queue item this printer had finished in the last five minutes. For a print
+started outside Bambuddy that was some earlier, unrelated job: its owner got
+the "your print is done" email, and the notification took that job's data. It
+now uses only the queue item the completion itself closed (the one
+_completion_belongs_to_queue_item accepted), with that job's real duration.
+"""
+
+from datetime import datetime, timedelta, timezone
+from unittest.mock import AsyncMock, MagicMock, patch
+
+import pytest
+from sqlalchemy.ext.asyncio import AsyncSession, async_sessionmaker
+
+from backend.app.models.library import LibraryFile
+from backend.app.models.print_queue import PrintQueueItem
+from backend.app.models.user import User
+
+
+async def _complete_without_archive(test_engine, printer_id: int, status: str = "completed"):
+    """Run on_print_complete for a print no archive matches.
+
+    Returns (archive_data the notification got, user-email mock). The queue
+    reconciliation and the spawned notification run against the test database;
+    the archive lookup sees an empty session, so the no-archive path is taken.
+    """
+    from backend.app.main import on_print_complete
+
+    real_db = async_sessionmaker(test_engine, class_=AsyncSession, expire_on_commit=False)
+    empty_session = AsyncMock()
+    empty_session.__aenter__ = AsyncMock(return_value=empty_session)
+    empty_session.__aexit__ = AsyncMock()
+    empty_session.execute = AsyncMock(
+        return_value=MagicMock(scalar_one_or_none=MagicMock(return_value=None), scalars=MagicMock())
+    )
+    with (
+        patch("backend.app.main.async_session", MagicMock(return_value=empty_session)),
+        patch("backend.app.core.database.async_session", real_db),
+        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()
+
+        await on_print_complete(printer_id, {"filename": "", "subtask_name": "Benchy", "status": status})
+
+    spawned = [c for c in mock_spawn.call_args_list if c.kwargs.get("name") == "notify-no-archive"]
+    assert len(spawned) == 1, mock_spawn.call_args_list
+    for other in mock_spawn.call_args_list:
+        if other is not spawned[0] and hasattr(other.args[0], "close"):
+            other.args[0].close()
+
+    with (
+        patch("backend.app.main.async_session", real_db),
+        patch("backend.app.main.notification_service.on_print_complete", new_callable=AsyncMock) as sent,
+        patch("backend.app.main._dispatch_user_print_email", new_callable=AsyncMock) as email,
+    ):
+        await spawned[0].args[0]
+    sent.assert_awaited_once()
+    return sent.await_args.kwargs["archive_data"], email
+
+
+async def _user(db_session) -> int:
+    user = User(username="owner", password_hash="x", role="user", is_active=True)
+    db_session.add(user)
+    await db_session.commit()
+    return user.id
+
+
+async def _library_file(db_session, metadata: dict | None) -> int:
+    lib = LibraryFile(
+        filename="benchy.3mf", file_path="library/benchy.3mf", file_type="3mf", file_size=1, file_metadata=metadata
+    )
+    db_session.add(lib)
+    await db_session.commit()
+    return lib.id
+
+
+async def _queue_item(db_session, printer_id: int, **fields) -> None:
+    db_session.add(PrintQueueItem(printer_id=printer_id, **fields))
+    await db_session.commit()
+
+
+class TestAPrintFromOutsideBambuddy:
+    @pytest.mark.asyncio
+    async def test_is_not_attributed_to_the_job_finished_before_it(self, test_engine, db_session, printer_factory):
+        printer = await printer_factory()
+        owner = await _user(db_session)
+        lib_id = await _library_file(db_session, {"print_time_seconds": 5400})
+        await _queue_item(
+            db_session,
+            printer.id,
+            status="completed",
+            created_by_id=owner,
+            library_file_id=lib_id,
+            print_time_seconds=5400,
+            completed_at=datetime.now(timezone.utc) - timedelta(minutes=2),
+        )
+
+        archive_data, email = await _complete_without_archive(test_engine, printer.id)
+
+        assert not (archive_data or {}).get("created_by_id")
+        assert "print_time_seconds" not in (archive_data or {})
+        email.assert_not_awaited()
+
+
+class TestAQueueJobWhoseArchiveWasNotFound:
+    @pytest.mark.asyncio
+    async def test_is_notified_with_its_owner_and_real_duration(self, test_engine, db_session, printer_factory):
+        printer = await printer_factory()
+        owner = await _user(db_session)
+        lib_id = await _library_file(db_session, {"print_time_seconds": 5400})
+        await _queue_item(
+            db_session,
+            printer.id,
+            status="printing",
+            created_by_id=owner,
+            library_file_id=lib_id,
+            started_at=datetime.now(timezone.utc) - timedelta(minutes=30),
+        )
+
+        archive_data, email = await _complete_without_archive(test_engine, printer.id, status="failed")
+
+        assert archive_data["created_by_id"] == owner
+        assert archive_data["print_time_seconds"] == 5400
+        assert archive_data["actual_time_seconds"] == pytest.approx(1800, abs=60)
+        email.assert_awaited_once()
+
+    @pytest.mark.asyncio
+    async def test_the_queue_items_cached_estimate_comes_first(self, test_engine, db_session, printer_factory):
+        printer = await printer_factory()
+        lib_id = await _library_file(db_session, {"print_time_seconds": 5400})
+        await _queue_item(db_session, printer.id, status="printing", library_file_id=lib_id, print_time_seconds=4200)
+
+        archive_data, _ = await _complete_without_archive(test_engine, printer.id)
+
+        assert archive_data["print_time_seconds"] == 4200
+        assert "actual_time_seconds" not in archive_data  # no start time recorded