Quellcode durchsuchen

fix(notifications): the daily digest goes out during quiet hours and a failed one keeps its events for the next (dropped after two days); a deleted queued archive no longer leaves its creator to be named on a later print; a print closed at reconnect reports no actual duration; the template editor knows the print outcome confirmation and names every event

maziggy vor 2 Tagen
Ursprung
Commit
dad7fea37b

+ 4 - 0
CHANGELOG.md

@@ -164,6 +164,10 @@ 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
+- **Notifications: the daily digest could be lost** — When the digest could not be sent (a network error, say), its events were deleted anyway. A digest time inside the provider's quiet hours was skipped, logged as sent, and its events deleted too. The digest now goes out at its time even during quiet hours, and a failed send keeps the events for the next day's digest (events more than two days old are dropped, so a provider that keeps failing does not pile them up). Lines from an earlier day show their date.
+- **Notifications: a later print could be attributed to the user of an earlier queued one** — When a queued print's archive was deleted while it was being sent to the printer, the record of who queued it was left behind, and an unrelated later print of the same name on that printer named and emailed that user.
+- **Notifications: "Print Stopped" after a printer came back online showed the time it was offline as the print's duration** — A print that ended while the printer was offline is closed when it reconnects; its real end time is unknown, so the notification now shows the sliced estimate instead of, say, 14 hours.
+- **Notification templates: the print outcome confirmation had no variables or preview in the editor** — The editor now lists its variables (including the confirmation link) and previews it, and seven other events (AMS humidity and temperature, bed cooled, the sensor alerts, auto-drying suspended, missing spool assignment) have their names.
 - **Configure Slot: a manual K value that could not be sent was reported as applied** — With no K-profile picked, a typed K value goes to the printer on its own command; when that send failed, the slot still read as configured. A warning now says the filament was set but the K value was not sent.
 - **A stray Stop on an idle printer could relabel a later failed print as cancelled** — Stop on a printer with no print loaded still marked it as stopped by the user. If the next print was first seen mid-way (after Bambuddy reconnected), that print's real failure was then reported as the user's cancel. The mark is now only set while a print is loaded (or the printer's state is unknown).
 - **Skip Objects and the printer connection diagnostic held a database connection through their printer I/O** — For a print started outside Bambuddy, the object list pulls the file over FTP, which on a printer mid-print can take a while; the diagnostic probes the printer and waits up to 10 seconds for a report. The connection is now released first.

+ 8 - 0
backend/app/api/routes/notification_templates.py

@@ -37,6 +37,14 @@ EVENT_NAMES = {
     "ai_failure_detection": "AI Failure Detection",
     "plate_not_empty": "Plate Not Empty",
     "plate_clear_required": "Plate Clear Required",
+    "print_confirm_request": "Print Outcome Confirmation",
+    "print_missing_spool_assignment": "Missing Spool Assignment",
+    "bed_cooled": "Bed Cooled",
+    "ams_humidity_high": "AMS Humidity High",
+    "ams_temperature_high": "AMS Temperature High",
+    "ams_drying_suspended": "Auto-Drying Suspended",
+    "ha_sensor_alert": "Printer Sensor Alert",
+    "location_ha_sensor_alert": "Storage Location Sensor Alert",
     "filament_low": "Filament Low",
     "maintenance_due": "Maintenance Due",
     "first_layer_complete": "First Layer Complete",

+ 23 - 9
backend/app/main.py

@@ -4741,6 +4741,11 @@ async def on_print_start(printer_id: int, data: dict):
         expected_keys = _expected_print_keys(printer_id, filename, subtask_name)
 
         expected_archive_id = None
+        # Who queued it, taken with the entries it was registered beside: left
+        # behind once those are gone (the archive deleted mid-dispatch, or the
+        # start notification already sent), the expiry never saw it, and an
+        # unrelated later print of that name was attributed to that user (EP-2).
+        fallback_creator = None
         for key in expected_keys:
             expected_archive_id = _expected_prints.pop(key, None)
             _expected_print_registered_at.pop(key, None)
@@ -4749,6 +4754,9 @@ async def on_print_start(printer_id: int, data: dict):
                 for other_key in expected_keys:
                     _expected_prints.pop(other_key, None)
                     _expected_print_registered_at.pop(other_key, None)
+                    creator = _expected_print_creators.pop(other_key, None)
+                    if fallback_creator is None:
+                        fallback_creator = creator
                 break
 
         if expected_archive_id:
@@ -4987,13 +4995,7 @@ async def on_print_start(printer_id: int, data: dict):
                 if not notification_sent:
                     # Use archive's created_by_id; fall back to the creator registered via
                     # register_expected_print (handles library-file-based queue items where
-                    # the freshly-created archive has no created_by_id yet).
-                    # Pop ALL matching keys so no stale entries remain in the dict.
-                    fallback_creator = None
-                    for key in expected_keys:
-                        popped = _expected_print_creators.pop(key, None)
-                        if fallback_creator is None:
-                            fallback_creator = popped
+                    # the freshly-created archive has no created_by_id yet), taken above.
                     archive_data = {
                         "print_time_seconds": archive.print_time_seconds,
                         "created_by_id": archive.created_by_id or fallback_creator,
@@ -8542,7 +8544,15 @@ async def _close_out_print(printer_id: int, data: dict):
                             # 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:
+                            # Not for a completion reconciled at reconnect: it
+                            # ended at an unknown time while the printer was
+                            # offline, and "now" is the reconnect (DB-C9).
+                            if (
+                                not data.get("_reconciled")
+                                and 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
@@ -9276,7 +9286,11 @@ async def _close_out_print(printer_id: int, data: dict):
                         # Falls back to None so the notification path can decide whether to
                         # render the slicer estimate as a last resort.
                         actual_time_seconds = None
-                        if archive.started_at and archive.completed_at:
+                        # Unknown for a completion reconciled at reconnect: the
+                        # print ended while the printer was offline and
+                        # completed_at is the reconnect, so the gap would read
+                        # as the duration -- 14 h for a night offline (DB-C9).
+                        if archive.started_at and archive.completed_at and not data.get("_reconciled"):
                             elapsed = (archive.completed_at - archive.started_at).total_seconds()
                             if elapsed > 0:
                                 actual_time_seconds = int(elapsed)

+ 25 - 0
backend/app/schemas/notification_template.py

@@ -32,6 +32,19 @@ class EventType(StrEnum):
 
 # Available variables for each event type
 EVENT_VARIABLES: dict[str, list[str]] = {
+    # Post-print outcome request (#1898): good/reject are the one-tap links,
+    # confirm_url opens the archive's confirmation dialog.
+    "print_confirm_request": [
+        "printer",
+        "filename",
+        "confirm_url",
+        "good_url",
+        "reject_url",
+        "archive_id",
+        "finish_photo_url",
+        "timestamp",
+        "app_name",
+    ],
     "print_start": ["printer", "filename", "estimated_time", "eta", "timestamp", "app_name"],
     "print_complete": [
         "printer",
@@ -142,6 +155,7 @@ EVENT_VARIABLES: dict[str, list[str]] = {
 # Events whose real notification can carry a camera snapshot — mirrors which
 # NotificationService.on_* methods accept image_data.
 PHOTO_CAPABLE_EVENTS: set[str] = {
+    "print_confirm_request",
     "print_start",
     "print_complete",
     "print_failed",
@@ -244,6 +258,17 @@ SAMPLE_DATA: dict[str, dict[str, str]] = {
         "timestamp": "2024-01-15 15:10",
         "app_name": "Bambuddy",
     },
+    "print_confirm_request": {
+        "printer": "Bambu X1C",
+        "filename": "Benchy",
+        "confirm_url": "http://bambuddy.local:8000/archives?confirm=42",
+        "good_url": "http://bambuddy.local:8000/api/v1/archives/confirm/sample-token/good",
+        "reject_url": "http://bambuddy.local:8000/api/v1/archives/confirm/sample-token/reject",
+        "archive_id": "42",
+        "finish_photo_url": "/api/v1/archives/42/photos/finish_20240115_143500_abc12345.jpg",
+        "timestamp": "2024-01-15 14:35",
+        "app_name": "Bambuddy",
+    },
     "plate_not_empty": {
         "printer": "Bambu X1C",
         "difference_percent": "12.4",

+ 34 - 8
backend/app/services/notification_service.py

@@ -33,6 +33,10 @@ from backend.app.utils.notification_photos import save_notification_photo
 
 logger = logging.getLogger(__name__)
 
+# How long a digest event is kept for: through one failed daily digest, so it
+# goes out with the next one, then dropped (FO-C4).
+DIGEST_RETRY_HOURS = 48
+
 # Honest User-Agent — matches the convention used by every other outbound
 # httpx client in the codebase (bambu_cloud, makerworld, firmware_check,
 # inventory). Previously this client leaked python-httpx/<version>, which
@@ -1377,14 +1381,16 @@ class NotificationService:
         variables: dict | None = None,
         photo_cache: dict | None = None,
         printer_id: int | None = None,
+        bypass_quiet_hours: bool = False,
     ) -> tuple[bool, str]:
         """Send notification to a specific provider.
 
         *photo_cache* lets the providers of one send share a single persisted
-        photo URL (see _get_or_build_photo_url).
+        photo URL (see _get_or_build_photo_url). *bypass_quiet_hours* is for
+        the daily digest, which goes out at the time chosen for it.
         """
         # Check quiet hours
-        if self._is_in_quiet_hours(provider):
+        if not bypass_quiet_hours and self._is_in_quiet_hours(provider):
             logger.info("Skipping notification to %s - quiet hours active", provider.name)
             return True, "Skipped - quiet hours"
 
@@ -3043,7 +3049,19 @@ class NotificationService:
             )
             queue_entries = list(result.scalars().all())
 
+            # Events kept after a failed digest get the next one, not every
+            # one after it: a provider whose digest always fails (revoked
+            # credentials, a busy day too long for Pushover) would otherwise
+            # grow its queue without end. Before FO-C4 a failed day was
+            # simply deleted.
+            cutoff = datetime.utcnow() - timedelta(hours=DIGEST_RETRY_HOURS)
+            expired = [e for e in queue_entries if e.created_at is not None and e.created_at < cutoff]
+            for entry in expired:
+                await db.delete(entry)
+            queue_entries = [e for e in queue_entries if e not in expired]
+
             if not queue_entries:
+                await db.commit()
                 logger.debug("No queued notifications for provider %s", provider.name)
                 return
 
@@ -3063,15 +3081,21 @@ class NotificationService:
                 event_label = event_type.replace("_", " ").title()
                 body_parts.append(f"== {event_label} ({len(entries)}) ==")
                 for entry in entries:
-                    time_str = entry.created_at.strftime("%H:%M")
+                    # From an earlier day (late yesterday, or kept from a
+                    # failed digest): say which day.
+                    if entry.created_at.date() != datetime.utcnow().date():
+                        time_str = entry.created_at.strftime("%m-%d %H:%M")
+                    else:
+                        time_str = entry.created_at.strftime("%H:%M")
                     printer_info = f"[{entry.printer_name}] " if entry.printer_name else ""
                     body_parts.append(f"  {time_str} {printer_info}{entry.title}")
                 body_parts.append("")
 
             body = "\n".join(body_parts)
 
-            # Send the digest
-            success, error = await self._send_to_provider(provider, title, body, db)
+            # Send the digest. At its own time even inside quiet hours: skipped
+            # there, it was logged as sent and its events deleted (FO-C4).
+            success, error = await self._send_to_provider(provider, title, body, db, bypass_quiet_hours=True)
 
             # Log the digest
             await self._log_notification(
@@ -3084,9 +3108,11 @@ class NotificationService:
                 error_message=error if not success else None,
             )
 
-            # Clear the queue
-            for entry in queue_entries:
-                await db.delete(entry)
+            # Clear the queue once it went out; a failed send keeps the events
+            # for the next digest instead of losing them (FO-C4).
+            if success:
+                for entry in queue_entries:
+                    await db.delete(entry)
             await db.commit()
 
             if success:

+ 117 - 0
backend/tests/integration/test_daily_digest_delivery.py

@@ -0,0 +1,117 @@
+"""The daily digest is not lost (FO-C4).
+
+The queued events were deleted whatever the send's outcome, so a failed send
+lost the day's digest. A digest time inside the provider's quiet hours was
+"skipped", logged as sent, and its events deleted too. It now goes out at its
+time even in quiet hours -- that time was chosen for it, as plate-not-empty
+alerts also ignore them -- and a failed send keeps the events for the next.
+"""
+
+import json
+from unittest.mock import AsyncMock, patch
+
+import pytest
+from sqlalchemy import select
+from sqlalchemy.ext.asyncio import AsyncSession, async_sessionmaker
+
+from backend.app.models.notification import NotificationDigestQueue, NotificationProvider
+from backend.app.services.notification_service import notification_service
+
+pytestmark = [pytest.mark.asyncio, pytest.mark.integration]
+
+
+async def _provider_with_queue(db_session) -> int:
+    provider = NotificationProvider(
+        name="phone",
+        provider_type="ntfy",
+        enabled=True,
+        config=json.dumps({"server": "https://ntfy.example", "topic": "t"}),
+        daily_digest_enabled=True,
+        daily_digest_time="07:00",
+    )
+    db_session.add(provider)
+    await db_session.flush()
+    for title in ("Print Completed", "Print Failed"):
+        db_session.add(
+            NotificationDigestQueue(provider_id=provider.id, event_type="print_complete", title=title, message=title)
+        )
+    await db_session.commit()
+    return provider.id
+
+
+async def _send_digest(
+    test_engine, provider_id: int, send_result: tuple[bool, str], *, quiet_now: bool = False
+) -> AsyncMock:
+    maker = async_sessionmaker(test_engine, class_=AsyncSession, expire_on_commit=False)
+    send = AsyncMock(return_value=send_result)
+    with (
+        patch("backend.app.core.database.async_session", maker),
+        patch.object(notification_service, "_send_ntfy", send),
+        patch.object(notification_service, "_is_in_quiet_hours", return_value=quiet_now),
+    ):
+        await notification_service.send_digest(provider_id)
+    return send
+
+
+async def _queued(db_session, provider_id: int) -> int:
+    db_session.expire_all()
+    rows = await db_session.scalars(
+        select(NotificationDigestQueue).where(NotificationDigestQueue.provider_id == provider_id)
+    )
+    return len(rows.all())
+
+
+async def test_a_failed_send_keeps_the_events_for_the_next_digest(test_engine, db_session):
+    provider_id = await _provider_with_queue(db_session)
+
+    send = await _send_digest(test_engine, provider_id, (False, "connection refused"))
+
+    send.assert_awaited_once()
+    assert await _queued(db_session, provider_id) == 2
+
+
+async def test_a_digest_inside_quiet_hours_is_still_sent(test_engine, db_session):
+    provider_id = await _provider_with_queue(db_session)
+
+    send = await _send_digest(test_engine, provider_id, (True, ""), quiet_now=True)
+
+    send.assert_awaited_once()
+    assert await _queued(db_session, provider_id) == 0
+
+
+async def test_a_sent_digest_clears_its_events(test_engine, db_session):
+    provider_id = await _provider_with_queue(db_session)
+
+    await _send_digest(test_engine, provider_id, (True, ""))
+
+    assert await _queued(db_session, provider_id) == 0
+
+
+async def test_events_kept_after_a_failure_are_retried_once_not_forever(test_engine, db_session):
+    """A digest that always fails -- revoked credentials, or a busy day too
+    long for Pushover's 1024 characters -- must not grow its queue without end:
+    kept events get the next digest, and are dropped after that."""
+    from datetime import datetime, timedelta
+
+    provider_id = await _provider_with_queue(db_session)
+    for hours_ago, title in ((50, "Three days ago"), (26, "Yesterday")):
+        db_session.add(
+            NotificationDigestQueue(
+                provider_id=provider_id,
+                event_type="print_complete",
+                title=title,
+                message=title,
+                created_at=datetime.utcnow() - timedelta(hours=hours_ago),
+            )
+        )
+    await db_session.commit()
+
+    send = await _send_digest(test_engine, provider_id, (False, "message too long"))
+
+    body = send.await_args.args[2]
+    assert "Yesterday" in body
+    assert "Three days ago" not in body
+    # Yesterday's line says which day it was from.
+    yesterday = (datetime.utcnow() - timedelta(hours=26)).strftime("%m-%d")
+    assert f"{yesterday} " in body
+    assert await _queued(db_session, provider_id) == 3

+ 43 - 0
backend/tests/integration/test_notification_template_editor_events.py

@@ -0,0 +1,43 @@
+"""Every notification event can be edited with its variables and a preview (CE-7).
+
+The print outcome confirmation (#1898) had no entry in the editor's variable
+list, sample data or names: the editor listed no variables for it and the
+preview left {printer}, {filename} and {confirm_url} empty. Seven other
+events had no display name.
+"""
+
+import pytest
+from httpx import AsyncClient
+
+from backend.app.api.routes.notification_templates import EVENT_NAMES
+from backend.app.models.notification_template import DEFAULT_TEMPLATES
+from backend.app.schemas.notification_template import EVENT_VARIABLES, SAMPLE_DATA
+
+pytestmark = [pytest.mark.asyncio, pytest.mark.integration]
+
+SEEDED = sorted({t["event_type"] for t in DEFAULT_TEMPLATES})
+
+
+@pytest.mark.parametrize("event_type", SEEDED)
+async def test_each_seeded_event_has_variables_samples_and_a_name(event_type):
+    assert event_type in EVENT_VARIABLES
+    assert set(EVENT_VARIABLES[event_type]) <= set(SAMPLE_DATA[event_type])
+    assert event_type in EVENT_NAMES
+
+
+async def test_the_confirmation_request_previews_its_link(async_client: AsyncClient):
+    template = next(t for t in DEFAULT_TEMPLATES if t["event_type"] == "print_confirm_request")
+
+    response = await async_client.post(
+        "/api/v1/notification-templates/preview",
+        json={
+            "event_type": "print_confirm_request",
+            "title_template": template["title_template"],
+            "body_template": template["body_template"],
+        },
+    )
+
+    assert response.status_code == 200
+    body = response.json()["body"]
+    assert SAMPLE_DATA["print_confirm_request"]["printer"] in body
+    assert SAMPLE_DATA["print_confirm_request"]["confirm_url"] in body

+ 11 - 1
backend/tests/integration/test_print_complete_end_to_end.py

@@ -87,7 +87,7 @@ async def queued_print(db_session, printer_factory):
     return {"printer": printer.id, "user": user.id, "center": center.id, "archive": archive.id, "item": item.id}
 
 
-async def _complete(test_engine, printer_id: int, status: str, name: str = "part", extra: dict | None = None) -> None:
+async def _complete(test_engine, printer_id: int, status: str, name: str = "part", extra: dict | None = None):
     maker = async_sessionmaker(test_engine, class_=AsyncSession, expire_on_commit=False)
     tasks_before = set(asyncio.all_tasks())
     with (
@@ -123,6 +123,7 @@ async def _complete(test_engine, printer_id: int, status: str, name: str = "part
             _done, pending = await asyncio.wait(spawned, timeout=10)
             # Left running, they would carry on into the next test unpatched
             assert not pending, f"background work still running: {pending}"
+    return notif
 
 
 async def _rows(db_session, archive_id: int, item_id: int):
@@ -154,6 +155,15 @@ async def test_a_completed_print(test_engine, db_session, queued_print):
     assert abs(charge.amount) == pytest.approx(5.0)
 
 
+async def test_a_completion_reconciled_at_reconnect_has_no_actual_duration(test_engine, db_session, queued_print):
+    """DB-C9: the printer was offline and the print ended at some unknown time;
+    the reconnect closes it now, so now minus its start is not its duration."""
+    notif = await _complete(test_engine, queued_print["printer"], "aborted", extra={"_reconciled": True})
+
+    archive_data = notif.on_print_complete.await_args.kwargs["archive_data"]
+    assert archive_data["actual_time_seconds"] is None
+
+
 async def test_a_failed_print(test_engine, db_session, queued_print):
     await _complete(test_engine, queued_print["printer"], "failed")
 

+ 36 - 0
backend/tests/unit/test_expected_print_creator_cleared.py

@@ -0,0 +1,36 @@
+"""A matched expected print takes its creator record with it (EP-2).
+
+A queued print registers who started it under every name variant. The start
+handler removed that record only when the print's archive was still there
+and no start notification had gone out; the 2-hour expiry sweeps by the
+expected-print entries, which the match had already removed. A leftover
+record then named -- and emailed -- that user for an unrelated later print
+of the same name on that printer.
+"""
+
+import pytest
+
+from backend.app import main
+from backend.tests.unit import test_plate_check_chamber_light as harness
+
+pytestmark = pytest.mark.asyncio
+
+# The harness's own autouse fixtures (dict clearing, light count) are not
+# collected here, so take them explicitly.
+_clear_dicts = harness._clear_dicts
+_light_count = harness._light_count
+
+
+async def test_a_print_whose_archive_is_gone_leaves_no_creator(_clear_dicts, _light_count):
+    # The harness's session finds no archive: it was deleted mid-dispatch.
+    main.register_expected_print(1, "Benchy.3mf", 999, created_by_id=7)
+    assert main._expected_print_creators
+
+    await harness._run_print_start([], check_plate_empty=harness._objects_on_plate())
+
+    # The match took the expected print, and no creator record outlives the
+    # entries the expiry sweeps by (a name variant the match did not try
+    # keeps both, and the sweep takes them together).
+    assert 999 not in {main._expected_prints.get(k) for k in [(1, "Benchy.3mf"), (1, "Benchy")]}
+    orphaned = set(main._expected_print_creators) - set(main._expected_print_registered_at)
+    assert not orphaned

+ 22 - 2
backend/tests/unit/test_notify_no_archive_duration.py

@@ -19,7 +19,7 @@ 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"):
+async def _complete_without_archive(test_engine, printer_id: int, status: str = "completed", **extra):
     """Run on_print_complete for a print no archive matches.
 
     Returns (archive_data the notification got, user-email mock). The queue
@@ -51,7 +51,7 @@ async def _complete_without_archive(test_engine, printer_id: int, status: str =
         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})
+        await on_print_complete(printer_id, {"filename": "", "subtask_name": "Benchy", "status": status, **extra})
 
     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
@@ -145,3 +145,23 @@ class TestAQueueJobWhoseArchiveWasNotFound:
 
         assert archive_data["print_time_seconds"] == 4200
         assert "actual_time_seconds" not in archive_data  # no start time recorded
+
+
+class TestACompletionReconciledAtReconnect:
+    @pytest.mark.asyncio
+    async def test_has_no_actual_duration(self, test_engine, db_session, printer_factory):
+        """DB-C9: the printer was offline, the print ended at some unknown time,
+        and the reconnect closes the job now -- the gap is not how long it ran."""
+        printer = await printer_factory()
+        await _queue_item(
+            db_session,
+            printer.id,
+            status="printing",
+            print_time_seconds=4200,
+            started_at=datetime.now(timezone.utc) - timedelta(hours=14),
+        )
+
+        archive_data, _ = await _complete_without_archive(test_engine, printer.id, status="aborted", _reconciled=True)
+
+        assert archive_data["print_time_seconds"] == 4200
+        assert "actual_time_seconds" not in archive_data