fix(notifications): print-complete duration uses actual elapsed, not slicer estimate (#1198)

Pre-fix, _background_notifications in main.py:3434 built archive_data
  with print_time_seconds (the slicer's pre-print estimate parsed from
  the 3MF at archive creation), and notification_service.py:909 formatted
  that field straight into the {{duration}} template variable. A print
  cancelled 2 minutes into a 3-hour estimate notified "duration: 3h".

  Compute actual_time_seconds from started_at/completed_at in main.py and
  add it to archive_data. notification_service.py prefers it, falls back
  to print_time_seconds when the actual can't be derived.

  Also add "cancelled" to the list of statuses that get completed_at set
  in update_archive_status — pre-fix only completed/failed/aborted got a
  timestamp, so queue-UI cancellations had no actual elapsed to compute
  from. Audited every completed_at consumer; none depend on NULL to mean
  "cancelled" (status field already carries that signal), and the
  statistics-totals aggregation gets more accurate too as a side effect.

  3 new regression tests in TestNotificationVariableFallbacks pin the
  {{duration}} variable contract (actual wins over estimate; estimate
  falls in when actual is missing; "Unknown" when both absent).

backend/app/main.py

@@ -3169,7 +3169,9 @@ async def on_print_complete(printer_id: int, data: dict):
             await service.update_archive_status(
                 archive_id,
                 status=status,
-                completed_at=datetime.now(timezone.utc) if status in ("completed", "failed", "aborted") else None,
+                completed_at=(
+                    datetime.now(timezone.utc) if status in ("completed", "failed", "aborted", "cancelled") else None
+                ),
                 failure_reason=failure_reason,
             )
             logger.info(
@@ -3431,8 +3433,19 @@ async def on_print_complete(printer_id: int, data: dict):
                     archive_result = await db.execute(select(PrintArchive).where(PrintArchive.id == archive_id))
                     archive = archive_result.scalar_one_or_none()
                     if archive:
+                        # Actual elapsed time from started_at/completed_at when both are
+                        # populated (every terminal status sets completed_at after #1198).
+                        # 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:
+                            elapsed = (archive.completed_at - archive.started_at).total_seconds()
+                            if elapsed > 0:
+                                actual_time_seconds = int(elapsed)
+
                         archive_data = {
                             "print_time_seconds": archive.print_time_seconds,
+                            "actual_time_seconds": actual_time_seconds,
                             "actual_filament_grams": archive.filament_used_grams,
                             "failure_reason": archive.failure_reason,
                             "created_by_id": archive.created_by_id,

backend/app/services/notification_service.py

@@ -906,8 +906,12 @@ class NotificationService:
         }
 
         if archive_data:
-            if archive_data.get("print_time_seconds"):
-                variables["duration"] = self._format_duration(archive_data["print_time_seconds"])
+            # {{duration}} on completion / failure / stopped events is the *actual*
+            # elapsed time (#1198). Slicer-estimated print_time_seconds is only used
+            # as a last-resort fallback when timestamps weren't recorded.
+            duration_seconds = archive_data.get("actual_time_seconds") or archive_data.get("print_time_seconds")
+            if duration_seconds:
+                variables["duration"] = self._format_duration(duration_seconds)
             if archive_data.get("actual_filament_grams"):
                 variables["filament_grams"] = f"{archive_data['actual_filament_grams']:.1f}"
             if status == "failed" and archive_data.get("failure_reason"):

backend/tests/unit/services/test_notification_service.py

@@ -1024,6 +1024,120 @@ class TestNotificationVariableFallbacks:
             if captured_variables.get("duration"):
                 assert captured_variables["duration"] != "Unknown"
 
+    @pytest.mark.asyncio
+    async def test_duration_prefers_actual_time_seconds_over_slicer_estimate(self, service):
+        """#1198: completion notification duration must reflect *actual* elapsed
+        time from started_at/completed_at, not the slicer's pre-print estimate.
+
+        Pre-fix the duration variable read from `print_time_seconds` (slicer
+        estimate parsed from the 3MF at archive creation), so a print cancelled
+        2 minutes into a 3-hour estimate would notify "duration: 3h"."""
+        mock_db = AsyncMock()
+        mock_provider = MagicMock()
+        mock_provider.id = 1
+
+        captured_variables: dict = {}
+
+        async def capture_build(db, event_type, variables):
+            captured_variables.update(variables)
+            return ("Test", "Test")
+
+        with (
+            patch.object(service, "_get_providers_for_event", new_callable=AsyncMock) as mock_get,
+            patch.object(service, "_send_to_providers", new_callable=AsyncMock),
+            patch.object(service, "_build_message_from_template", side_effect=capture_build),
+        ):
+            mock_get.return_value = [mock_provider]
+
+            await service.on_print_complete(
+                printer_id=1,
+                printer_name="Test",
+                status="cancelled",
+                data={"subtask_name": "test_print"},
+                db=mock_db,
+                archive_data={
+                    "print_time_seconds": 10800,  # 3h slicer estimate
+                    "actual_time_seconds": 120,  # 2m actual elapsed
+                },
+            )
+
+        # 2 minutes — not 3 hours — even though the slicer estimate is in the dict.
+        assert "2m" in captured_variables["duration"]
+        assert "3h" not in captured_variables["duration"]
+
+    @pytest.mark.asyncio
+    async def test_duration_falls_back_to_slicer_estimate_when_actual_time_missing(self, service):
+        """#1198: when actual_time_seconds is absent (e.g. timestamps weren't
+        recorded for some reason), the duration variable falls back to
+        print_time_seconds rather than rendering 'Unknown'. Preserves
+        backwards-compat for any code path that didn't compute actual elapsed."""
+        mock_db = AsyncMock()
+        mock_provider = MagicMock()
+        mock_provider.id = 1
+
+        captured_variables: dict = {}
+
+        async def capture_build(db, event_type, variables):
+            captured_variables.update(variables)
+            return ("Test", "Test")
+
+        with (
+            patch.object(service, "_get_providers_for_event", new_callable=AsyncMock) as mock_get,
+            patch.object(service, "_send_to_providers", new_callable=AsyncMock),
+            patch.object(service, "_build_message_from_template", side_effect=capture_build),
+        ):
+            mock_get.return_value = [mock_provider]
+
+            await service.on_print_complete(
+                printer_id=1,
+                printer_name="Test",
+                status="completed",
+                data={"subtask_name": "test_print"},
+                db=mock_db,
+                archive_data={
+                    "print_time_seconds": 3600,  # 1h slicer estimate, no actual
+                    "actual_time_seconds": None,
+                },
+            )
+
+        assert captured_variables["duration"] != "Unknown"
+        assert "1h" in captured_variables["duration"]
+
+    @pytest.mark.asyncio
+    async def test_duration_unknown_when_both_time_fields_missing(self, service):
+        """#1198: with neither actual nor estimated time available the duration
+        variable surfaces the existing 'Unknown' fallback."""
+        mock_db = AsyncMock()
+        mock_provider = MagicMock()
+        mock_provider.id = 1
+
+        captured_variables: dict = {}
+
+        async def capture_build(db, event_type, variables):
+            captured_variables.update(variables)
+            return ("Test", "Test")
+
+        with (
+            patch.object(service, "_get_providers_for_event", new_callable=AsyncMock) as mock_get,
+            patch.object(service, "_send_to_providers", new_callable=AsyncMock),
+            patch.object(service, "_build_message_from_template", side_effect=capture_build),
+        ):
+            mock_get.return_value = [mock_provider]
+
+            await service.on_print_complete(
+                printer_id=1,
+                printer_name="Test",
+                status="completed",
+                data={"subtask_name": "test_print"},
+                db=mock_db,
+                archive_data={
+                    "print_time_seconds": None,
+                    "actual_time_seconds": None,
+                },
+            )
+
+        assert captured_variables["duration"] == "Unknown"
+
     @pytest.mark.asyncio
     async def test_print_complete_with_finish_photo_url(self, service):
         """Verify finish_photo_url is passed through from archive_data."""