diff --git a/CHANGELOG.md b/CHANGELOG.md index 85f910e42..fd8f052e1 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -8,6 +8,7 @@ All notable changes to Bambuddy will be documented in this file. - **Orca Cloud profile sync now connects by approving a code instead of the copy-paste sign-in** — Connecting Bambuddy to Orca Cloud used to mean opening an OAuth sign-in in a new tab, watching it redirect to a `localhost` URL that fails to load, then copying that dead URL out of the address bar and pasting it back into Bambuddy. That dance existed only because Orca's auth backend (Supabase) accepts no redirect target other than `localhost`, and the deliberately-broken redirect page confused nearly everyone who reached it. OrcaSlicer has since shipped a first-class external-app pairing API (the OAuth 2.0 Device Authorization Grant, RFC 8628), so the flow is now: click **Connect**, approve a short code on your Orca Cloud settings page, and Bambuddy pairs itself — no redirect, no paste, no client secret, and it behaves identically from a LAN IP, `localhost`, or behind a reverse proxy. Bambuddy requests **read-only** access (it only lists and views your Orca Cloud profiles), keeps the pairing alive with the API's rotating refresh tokens (validated end-to-end against Orca's staging and production servers), and stores nothing beyond the issued token pair. The profile list and detail views are unchanged, so nothing downstream of the connect step looks different. The old paste-based sign-in and the email/password fallback are removed. Points at production Orca Cloud by default; `ORCA_CLOUD_API_BASE` overrides the endpoint for testing. ### Fixed +- **Reconnecting or restarting inflated Stats → Total Print Time by hundreds of hours on large farms (#2592, reporter @Jostxxl)** — On the reporter's farm a restart pushed Total Print Time from ~1,500h to 3,215h. When a printer reconnects, the connected edge runs `reconcile_stale_active_prints`, which closes out every archive still stuck in `status="printing"` (missed completions, disconnects, restarts) by synthesising an aborted `on_print_complete`. That wrote a `PrintLogEntry` whose duration was `completed_at - started_at` — but for a reconciled archive the real end time is unknown: the print stopped somewhere during the disconnect, and `completed_at` is only the reconnect moment. So each stale archive banked its entire multi-day gap as print time (one row was 51.9h), and a printer with several stale archives contributed hundreds of fabricated hours at once. Worse, the Stats total *recomputed* `completed_at - started_at` whenever the stored duration was falsy, so storing NULL wouldn't have helped. Reconciled completions now log an explicit `duration_seconds = 0` (honest "no measured runtime") and the two Stats time paths trust a stored 0 instead of recomputing from the stale timestamps — legacy rows that never recorded a duration still fall back as before. Reconciled aborts also get a truthful `failure_reason` ("Stale - reconciled after reconnect, end time unknown") instead of being mislabelled "User cancelled". Genuine long prints are untouched: nothing is capped, a still-running >24h print is never treated as stale, and a real >24h run keeps its full measured duration. Re-running reconciliation is already idempotent (the archive flips to `aborted`, so it isn't re-selected). Existing inflated rows from before this fix are not auto-corrected — they're indistinguishable from real cancellations in the database, and a blanket cap would clobber genuine long prints; the reporter repaired his own rows by hand. Covered by tests for the multi-day reconcile, multiple stale archives per printer, a retained >24h print, and the Stats total ignoring reconciled time while still counting real runtime. - **H2C prints intermittently recorded no filament and never deducted from inventory (#2582, reporter @gyrene2083)** — On an H2C (firmware `01.02.00.00`) filament usage sometimes wasn't deducted and the Print Log showed no filament for that print; the reporter confirmed the tell-tale detail — the failed print's archived `.3mf` didn't exist to download. Filament totals, the Print Log filament column, and the weight deduction all read the sliced 3MF's data, so when that file can't be pulled off the printer the print drops to the no-3MF fallback archive and every one of them comes up empty. The download itself was the failure: the H2C is the same H2 generation and the same firmware line as the P2S, whose FTPS data channel trips a vsFTPd + TLS 1.3 session-reuse bug on Python 3.13 (#1401) — and the X2D hit the sibling handshake variant (#1638). Both were fixed by capping that model's FTP control/data channel to TLS 1.2 via the per-model FTP profile registry, but the H2C had no entry and so ran on the Python-default TLS 1.3, leaving its 3MF downloads to fail the same way (intermittently, matching the "sometimes works, sometimes doesn't" report — the session-reuse race rather than a hard handshake failure). The H2C now gets the same `cap_tls_v1_2` profile as the P2S/X2D (with its `O1C`/`O1C2` SSDP codes mapped to it), so the sliced 3MF comes off the printer reliably and the slice data — filament total, Print Log filament, and the inventory deduction — is populated again. H2D is deliberately left on the default profile; it negotiates TLS 1.3 without this fault. - **An unresolved AMS mapping silently dispatched a P1S print to the empty external spool (#2589, reporter @Jostxxl)** — A queued P1S job with a regular AMS attached, two compatible PETG spools loaded, and nothing on the external spool holder started against the *external* feed and paused seconds later with a filament-runout HMS. The queue row was correct on its face — `use_ams=true` — but carried `ams_mapping=[-1]`, and Bambuddy turned that into a print with no AMS. Two faults combined. **A `-1` was read as "external spool."** The command builder's rule for "all slots are external, so drop `use_ams`" tested `t < 0 or t >= 254` — folding the *unresolved* sentinel (`-1`) in with a genuine external selection (`254`/`255`). An explicit external print serializes as `[254]`; an unresolved slot serializes as `[-1]`, and the two mean opposite things — one is "use the spool holder", the other is "we never worked out which tray." Only `>= 254` may now force `use_ams=False`; `-1` never does. **The unresolved mapping was trusted instead of recomputed.** The scheduler only computes a mapping when the row has *none*; a stored `[-1]` is non-empty, so it looked "already resolved" and was passed through verbatim — even though the backend had the live AMS trays and the plate's filament requirements right there and could have matched them. Dispatch now recomputes whenever the stored mapping is entirely unresolved, so a bogus `[-1]` self-heals against the trays actually loaded (and any pre-existing stuck row heals on the next scheduler pass); if nothing compatible is loaded it is cleared rather than sent, so the firmware reports a clear mapping error instead of quietly printing to an empty feed. **Where the `[-1]` came from.** The Print dialog builds the mapping from the selected printer's live status; if you submitted a single-printer job in the instant before that status query resolved, it matched against zero known trays and serialized every required slot as `-1`. The dialog now waits for the printer's AMS status before it will submit (showing a brief "Waiting for AMS status from …" notice), and the mapping hook returns *no* mapping rather than an all-`-1` one while the trays are unknown — so the scheduler resolves it at dispatch. A genuine no-match with trays present still serializes `-1` and surfaces the mismatch as before. **Tests.** Backend: the command builder keeps `use_ams=true` for `[-1]`/`[-1,-1]` and a padded `[-1,-1,5]`, still drops it for an explicit `[254]`; the scheduler recomputes a stored `[-1]`, leaves a resolved (or manually-overridden) mapping untouched, and clears an unresolvable one. An existing test that asserted the old `[-1] → use_ams=False` behaviour was corrected to the fixed contract. Frontend: the mapping hook returns `undefined` while status is loading, resolves to the AMS tray once it arrives (type-only match with strict colour off), and still emits `-1` for a real mismatch. Full backend suite and the PrintModal/mapping frontend suites green. - **Pushover Emergency priority (2) was rejected by the Pushover API (#2586)** — Setting a Pushover provider to priority 2 (Emergency) made every notification fail with Pushover's own error that `retry` and `expire` are required. Pushover *mandates* those two parameters for Emergency alerts — `retry` is how often it re-alerts (minimum 30 s) and `expire` is when it stops (maximum 10800 s / 3 h) — and Bambuddy never sent them, so the message was refused before it left the app. Priority 2 now works: two new optional fields (Emergency Retry / Expire) appear on the Pushover provider **only when priority is set to 2**, default to a sensible 60 s / 3600 s, are clamped to Pushover's legal 30–10800 s range, and are sent only at priority 2 (Pushover ignores them at other priorities). Emergency alerts now keep re-alerting until acknowledged, as intended. diff --git a/backend/app/api/routes/archives.py b/backend/app/api/routes/archives.py index 3973de140..5342fab8c 100644 --- a/backend/app/api/routes/archives.py +++ b/backend/app/api/routes/archives.py @@ -593,8 +593,12 @@ async def list_archives_slim( # print_time_seconds (slicer estimate) for non-completed # events would diverge from Quick Stats — so expose the # measured value here unconditionally. + # + # Trust an explicit 0 (reconciled aborts store it deliberately; + # their real end time is unknown) instead of recomputing the + # multi-day disconnect gap from the timestamps (#2592). r.duration_seconds - if r.duration_seconds and r.duration_seconds > 0 + if r.duration_seconds is not None else ( int((r.completed_at - r.started_at).total_seconds()) if r.started_at and r.completed_at and (r.completed_at - r.started_at).total_seconds() > 0 @@ -1071,7 +1075,12 @@ async def get_archive_stats( ) total_seconds = 0 for duration_seconds, started_at, completed_at in time_rows.all(): - if duration_seconds: + # Trust an explicitly stored duration, INCLUDING 0: a reconciled abort + # stores 0 on purpose because its real end time is unknown, and the + # started_at→completed_at fallback would otherwise bank the whole + # multi-day disconnect gap as print time (#2592). Only rows with a NULL + # duration (legacy entries that never recorded one) fall back. + if duration_seconds is not None: total_seconds += duration_seconds elif started_at and completed_at: elapsed = (completed_at - started_at).total_seconds() diff --git a/backend/app/main.py b/backend/app/main.py index 623629ad3..112822e7c 100644 --- a/backend/app/main.py +++ b/backend/app/main.py @@ -4718,6 +4718,13 @@ async def on_print_complete(printer_id: int, data: dict): if hms_errors: logger.info("[ARCHIVE] HMS errors at failure: %s", hms_errors) failure_reason = derive_failure_reason(status, hms_errors) + if data.get("_reconciled"): + # A reconciled completion closes out a stale archive at + # reconnect — it is not a user action, so don't mislabel it + # "User cancelled". The "Stale" prefix matches the existing + # stale-cleanup convention and records that the real end time + # is unknown, which is also why its logged duration is 0 (#2592). + failure_reason = "Stale - reconciled after reconnect, end time unknown" if failure_reason: logger.info("[ARCHIVE] failure_reason=%r (status=%s)", failure_reason, status) elif status == "failed" and hms_errors: @@ -4818,6 +4825,9 @@ async def on_print_complete(printer_id: int, data: dict): thumbnail_path=archive.thumbnail_path, created_by_id=archive.created_by_id, created_by_username=_print_user_info.get("username") if _print_user_info else None, + # Reconciled completions have an unknown real end time — + # log 0 duration instead of the whole disconnect gap (#2592). + reconciled=bool(data.get("_reconciled")), ) await db.commit() logger.info("[PRINT_LOG] Log entry written for archive %s", archive_id) diff --git a/backend/app/services/print_log.py b/backend/app/services/print_log.py index df79e7336..36f8dc8e6 100644 --- a/backend/app/services/print_log.py +++ b/backend/app/services/print_log.py @@ -33,11 +33,26 @@ async def write_log_entry( thumbnail_path: str | None = None, created_by_id: int | None = None, created_by_username: str | None = None, + reconciled: bool = False, ) -> PrintLogEntry: - """Write a print log entry.""" - duration = None - if started_at and completed_at: + """Write a print log entry. + + ``reconciled`` marks a synthetic completion written when a stale + ``status="printing"`` archive is closed out at reconnect. Its real end time + is unknown — the print stopped somewhere during the disconnect and + ``completed_at`` is only the reconnect moment — so ``completed_at - + started_at`` would bank the entire disconnect gap as print time, adding + hundreds of fictitious hours across a farm of stale rows (#2592). For those + entries we store an explicit ``0`` ("no measured runtime") rather than a + fabricated duration; the stats total trusts a stored 0 instead of + recomputing from the stale timestamps. + """ + if reconciled: + duration: int | None = 0 + elif started_at and completed_at: duration = int((completed_at - started_at).total_seconds()) + else: + duration = None entry = PrintLogEntry( archive_id=archive_id, diff --git a/backend/tests/integration/test_stats_reconciled_duration_2592.py b/backend/tests/integration/test_stats_reconciled_duration_2592.py new file mode 100644 index 000000000..37f78ae46 --- /dev/null +++ b/backend/tests/integration/test_stats_reconciled_duration_2592.py @@ -0,0 +1,66 @@ +"""Regression test for reconnect-reconciliation inflating Total Print Time (#2592). + +On a farm, a connected-edge reconcile closes out every stale ``status="printing"`` +archive as an aborted run whose duration was computed ``completed_at - started_at`` +— i.e. the whole multi-day disconnect gap — and the Stats endpoint's fallback +recomputed the same value even when the stored duration was 0/NULL. A single +reconnect could add hundreds of fictitious print hours (reporter @Jostxxl saw +Total Print Time jump from ~1,500h to 3,215h). + +The fix stores an explicit 0 for reconciled entries and makes the Stats total +trust that 0 instead of recomputing from the stale timestamps. This test drives +the ``/archives/stats`` endpoint with hand-crafted rows covering the reporter's +scenarios. +""" + +from __future__ import annotations + +from datetime import datetime, timedelta + +import pytest +from httpx import AsyncClient + +from backend.app.models.print_log import PrintLogEntry + + +@pytest.mark.asyncio +@pytest.mark.integration +async def test_stats_total_time_ignores_reconciled_but_keeps_real_runtime(async_client: AsyncClient, db_session): + base = datetime(2026, 7, 15, 10, 0, 0) + reconnect = base + timedelta(days=2, hours=4) # multi-day gap → ~52h each if recomputed + + rows = [ + # Two reconciled aborts for the same printer: duration logged as 0 on + # purpose (unknown real end time). Their timestamps span days, so the + # bug would have banked ~52h each (~104h total) via the fallback. + PrintLogEntry(printer_id=1, status="aborted", started_at=base, completed_at=reconnect, duration_seconds=0), + PrintLogEntry(printer_id=1, status="aborted", started_at=base, completed_at=reconnect, duration_seconds=0), + # A genuine >24h print — must be retained in full (no cap, no zeroing). + PrintLogEntry( + printer_id=1, + status="completed", + started_at=base, + completed_at=base + timedelta(hours=30), + duration_seconds=30 * 3600, + ), + # A legacy row that never stored a duration — must still fall back to + # its own (short, legitimate) 2h span. + PrintLogEntry( + printer_id=1, + status="completed", + started_at=base, + completed_at=base + timedelta(hours=2), + duration_seconds=None, + ), + ] + for r in rows: + db_session.add(r) + await db_session.commit() + + resp = await async_client.get("/api/v1/archives/stats") + assert resp.status_code == 200, resp.text + data = resp.json() + + # 30h (genuine) + 2h (legacy fallback) + 0 + 0 (reconciled) = 32.0h. + # Pre-fix the two reconciled rows would have added ~104h from their stamps. + assert data["total_print_time_hours"] == 32.0 diff --git a/backend/tests/unit/test_print_log.py b/backend/tests/unit/test_print_log.py index 58358dc7c..e65e12455 100644 --- a/backend/tests/unit/test_print_log.py +++ b/backend/tests/unit/test_print_log.py @@ -1,10 +1,12 @@ """Unit tests for print log service and schema.""" from datetime import datetime, timedelta +from unittest.mock import AsyncMock, MagicMock import pytest from backend.app.schemas.print_log import PrintLogEntrySchema, PrintLogResponse +from backend.app.services.print_log import write_log_entry class TestPrintLogEntrySchema: @@ -102,3 +104,44 @@ class TestWriteLogEntry: if started_at and completed: duration = int((completed - started_at).total_seconds()) assert duration is None + + +class TestWriteLogEntryReconciledDuration: + """write_log_entry duration handling for reconciled (synthetic) completions (#2592). + + A reconciled abort closes out a stale ``status="printing"`` archive at + reconnect; its real end time is unknown, so ``completed_at - started_at`` + would bank the whole disconnect gap as print time. Those entries must log + 0, while genuine prints (including >24h ones) keep their real duration. + """ + + @staticmethod + async def _write(**kwargs): + db = MagicMock() + db.flush = AsyncMock() + return await write_log_entry(db, **kwargs) + + @pytest.mark.asyncio + async def test_reconciled_logs_zero_despite_multiday_gap(self): + started = datetime(2026, 7, 15, 10, 0, 0) + completed = started + timedelta(days=2, hours=4) # the reconnect moment, not the real end + entry = await self._write(status="aborted", started_at=started, completed_at=completed, reconciled=True) + assert entry.duration_seconds == 0 + + @pytest.mark.asyncio + async def test_reconciled_logs_zero_even_without_timestamps(self): + entry = await self._write(status="aborted", reconciled=True) + assert entry.duration_seconds == 0 + + @pytest.mark.asyncio + async def test_genuine_long_print_retains_full_duration(self): + """A legitimate >24h print keeps its real duration — no cap, no zeroing.""" + started = datetime(2026, 7, 15, 10, 0, 0) + completed = started + timedelta(hours=30) + entry = await self._write(status="completed", started_at=started, completed_at=completed) + assert entry.duration_seconds == 30 * 3600 + + @pytest.mark.asyncio + async def test_non_reconciled_missing_times_is_none(self): + entry = await self._write(status="completed", started_at=datetime(2026, 7, 15, 10, 0, 0)) + assert entry.duration_seconds is None