From 554a73070fc73575ccaaffb650c44c3e5bd2bcb0 Mon Sep 17 00:00:00 2001 From: maziggy Date: Mon, 25 May 2026 09:04:47 +0200 Subject: [PATCH] fix(maintenance): paused prints no longer accumulate runtime hours (#1521) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit PAUSE counted toward runtime_seconds equally with RUNNING, inflating hours-based maintenance thresholds (rod lube, belt check, nozzle clean) by however long overnight or extended pauses lasted. Maintenance items track mechanical wear, which is zero while paused, so the predicate now excludes PAUSE. Field-comment and docstring trail across main.py / models/printer.py / maintenance.py updated to match. Existing runtime_seconds values cannot be retroactively split — only future accumulation is fixed. Adds 3 regression tests pinning PAUSE non-accumulation, RUNNING accumulation, and the FINISH state's last_runtime_update clear (prevents idle-time back-bill when the printer next goes RUNNING). --- CHANGELOG.md | 1 + backend/app/api/routes/maintenance.py | 5 +- backend/app/main.py | 10 +- backend/app/models/printer.py | 4 +- .../tests/unit/test_runtime_tracking_pause.py | 155 ++++++++++++++++++ 5 files changed, 170 insertions(+), 5 deletions(-) create mode 100644 backend/tests/unit/test_runtime_tracking_pause.py diff --git a/CHANGELOG.md b/CHANGELOG.md index 56ce1a7e8..59d763b2c 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -28,6 +28,7 @@ All notable changes to Bambuddy will be documented in this file. - **Trivy DS-0026 (`Dockerfile.test` missing HEALTHCHECK): silenced via `HEALTHCHECK NONE`** — The test image runs `pytest` and exits; there is no long-running service to probe, so any HEALTHCHECK we added would be cargo-cult noise. `HEALTHCHECK NONE` is the documented Docker directive to explicitly opt out of any inherited healthcheck and is the way Trivy expects projects to signal "this image is not a service." Closes code-scanning alert #813. ### Fixed +- **Paused prints no longer inflate maintenance hours (#1521, reported by @TempleClause)** — The `track_printer_runtime` background task in `backend/app/main.py` counted both `RUNNING` and `PAUSE` states equally toward `runtime_seconds`, which feeds every hours-based maintenance interval (lubricate rods, clean nozzle, check belts, etc.). Maintenance items measure *mechanical wear*, and pause time involves no motion — so a print paused overnight stretched the maintenance clock forward by ~8 h without any actual wear, triggering "lubricate rods" warnings earlier than warranted. Reporter found this by code review (no support bundle), flagged it cleanly with the exact line in `main.py` and three ranked solution options. **Fix**: option 1 (exclude PAUSE entirely) — `state.state in ("RUNNING", "PAUSE")` → `state.state == "RUNNING"`. PAUSE now follows the same path as FINISH / IDLE / PREPARE: the elapsed-time accumulator skips it, and `last_runtime_update` is cleared so a later RUNNING transition starts fresh and doesn't back-bill the pause. No setting / toggle (reporter's option 3 was deliberately the throwaway — this is a wear-tracking semantic, not a user preference); no cap (option 2) — wear during pause is zero, not "reduced". Docstring and field-comment trail updated across `main.py`, `models/printer.py:23`, and the two `api/routes/maintenance.py` route docstrings that all previously described the field as covering "RUNNING and PAUSE states". **Out of scope**: retroactive backfill of existing `runtime_seconds` values — already-accumulated pause time cannot be split out, only future accumulation is fixed. Users with hours-based maintenance intervals already set will see slower accumulation going forward (the correct outcome), so a previously-near-due item may take longer to ring than under the old behaviour. **Tests**: 3 new in `test_runtime_tracking_pause.py` pinning the new contract — PAUSE does NOT accumulate and clears `last_runtime_update`; RUNNING still accumulates and updates the timestamp; a non-active state (FINISH) clears `last_runtime_update` to prevent back-billing the idle time when the printer next goes RUNNING. The tests drive the actual `track_printer_runtime()` coroutine through a single iteration via patched `asyncio.sleep` against an in-memory SQLite DB, so they catch any regression in the predicate at the call site (not just an extracted helper). Backend ruff clean; targeted 24-test rod/runtime subset all green. - **Quick Stats: user-cancelled prints now have their own bucket and no longer drag down the Success Rate gauge (#1390 follow-up, reported by @IndividualGhost1905)** — Reporter saw `Total prints: 20 / Success: 18 / Failed: 1` and asked where the 20th print went; the breakdown only showed Successful + Failed, so a cancelled run silently inflated the total without appearing anywhere. The earlier #1390 round had committed a test that *locked in* the bug — `it('uses total_prints as denominator so cancelled/stopped events count')` asserted the gauge should divide by `total_prints`, which lumped user/queue-cancelled jobs in with quality outcomes and conflated user intent with printer performance. **Cause**: `PrintLogEntry.status` has six values in production (`completed`, `failed`, `aborted`, `stopped`, `cancelled`, `skipped`) but the Quick Stats endpoint in `api/routes/archives.py` only counted two — `completed` → Successful, `status == "failed"` → Failed — and used a raw `count(*)` for Total Prints, so the other four statuses ended up in Total without surfacing in any breakdown row. `aborted` was particularly silent: classified as a failure elsewhere in the codebase (`failure_analysis.py`, `main.py:430,1729`) but not counted toward `failed_prints` in stats. **Fix**: three-bucket classification across the whole stats surface, matching how the rest of the codebase already groups these statuses. Quick Stats now returns `successful_prints` (completed), `failed_prints` (failed + aborted — printer-detected quality failures), and a new `cancelled_prints` (stopped + cancelled + skipped — user/queue interruptions). The SuccessRateWidget gauge divides by `successful + failed` only, so cancelling a roll because you changed your mind doesn't ding the printer's success rate — a Cancelled row in the breakdown surfaces the count so it doesn't silently vanish from Total Prints. The Failure Analysis service applies the same denominator change (`failure_rate = failed / (successful + failed)`) to both the headline rate and the per-week trend, so a week with no failures but several cancellations no longer reads as a misleading 0/N. **Schema change is additive-safe**: `ArchiveStats.cancelled_prints` defaults to `0` so any historical fixture validating against the model still parses; the frontend type also defaults the display to `0` when the field is missing. **i18n**: new `stats.cancelled` key with real translations across all 9 locales (de/es/fr/it/ja/pt-BR/zh-CN/zh-TW) per [[feedback_translate_dont_fallback]]; parity script clean at 4994 leaves per locale. **Tests**: existing `it('uses total_prints as denominator …')` test inverted to assert the new behaviour (40 completed / 20 failed / 35 cancelled → gauge shows 67%, Cancelled row reads 35), `cancelled_prints: 0` added to the shared mock so the unchanged-display assertion (140/150 → 93%) still holds since `140 / (140 + 10) = 93.33%` rounds identically. 33 StatsPage tests + 6 backend stats/failure tests green; frontend build + backend ruff clean. **Follow-up (cosmetic):** the new Cancelled row's Ban icon rendered in `text-bambu-gray` while the Successful and Failed icons used semantic `text-status-ok` / `text-status-error` tokens — reporter (@IndividualGhost1905) noted the asymmetry and asked for an orange to match what Archives + notification badges use for cancelled. Switched the Cancelled row to `text-status-warning` (amber-500, same token family as the other two rows), so all three icons are now semantic-token-driven and the new row matches the colour the user already associates with cancelled status elsewhere in the UI. - **Support bundle + bug-report submission now include the live diagnostic snapshot** — Three diagnostics (Connection Diagnostic per printer, Virtual Printer Setup Diagnostic per enabled VP, Log Health Scanner) have shipped on the System page and inline in the bug-report bubble since 6bc6a1d6 / e222a0ef / ed31b8f4, but the results were only ever shown to the *user* — never persisted into the downloadable support ZIP or the submitted GitHub issue. A report saying "looks broken in Bambuddy" arrived with no actionable signal beyond raw logs. **Fix**: new `services/diagnostic_snapshot.collect_diagnostic_snapshot` runs all three concurrently with an outer per-probe 15 s wall-clock cap (so a hung interface adds at most ~15 s to bundle generation regardless of fleet size — `asyncio.gather`, total ≈ max(per-cap) not sum). Fail-soft per probe: a crash inside one printer's check emits `{"printer_id": N, "error": "..."}` for that entry rather than nuking the whole snapshot — partial result beats a 500. Wired into `_collect_support_info()` so both flows (`POST /support/bundle` and `POST /bug-report/submit` via `support_info=...`) pick up the new `diagnostics` top-level key without their own changes. **Private-data sanitization** — the diagnostic schemas embed raw IPv4 in three places (`PrinterDiagnosticResult.ip_address`, network-mode check's `params.{printer_ip, host_ip}`, VP diagnostic's `params.bind_ip`), and the snapshot adds printer names. None of those should leak. The snapshot now runs a recursive sanitizer on the full result tree before returning: known DB-listed values (printer name, IP, serial, access code) get the same `[PRINTER]/[IP]/[SERIAL]/[ACCESS_CODE]` labels the log sanitizer already applies (via the shared `collect_sensitive_strings`), and an IPv4-regex fallback catches IPs the DB doesn't know about — most importantly the Bambuddy host IP returned by `_get_host_ip()` and any VP `bind_ip` the user picked at setup. Live-DB smoke test confirms zero raw IPv4 instances in the serialized snapshot output. **Progress indicators**: the bubble's "submitting" view and the System page's Download button now render a static four-line checklist showing what's running (printer connectivity → VP setup → log scan → submit/build ZIP) — communicates the longer wait honestly without faking server-side phase progress we can't actually track. **Tests**: 6 new in `test_diagnostic_snapshot.py` — empty-input shape stable, per-printer / per-VP result coverage, fail-soft on a single-probe crash, `timed_out` marker when a probe exceeds the per-probe cap (test patches the cap to 0.05 s), end-to-end IP sanitization across all five field shapes (top-level `ip_address`, `printer_ip`, `host_ip`, `bind_ip`, plus IPs embedded in log-health sample lines) with a final regex sweep over the JSON-serialized result asserting zero raw IPv4 escapes, concurrent execution proof (4 × 0.2 s probes complete in < 0.5 s, would be 0.8 s sequential). Existing 27 BugReportBubble + SystemInfoPage frontend tests still pass; 9-locale i18n parity check clean (4993 leaves per locale, 9 new keys added with real translations everywhere — no English fallback). Backend ruff clean. - **"Prefer Lowest Remaining Filament" now uses Bambuddy's inventory weight, not just the printer's RFID counter (#1508, reported by @kleinwareio)** — Reporter has an inventory spool cloned to slot 1 and the original (much further used) in slot 4 of the same P1S AMS, with the preference enabled, and the dispatch consistently picked slot 1 (the fresh clone) instead of slot 4 (the original they wanted to finish first). Root cause is the `prefer_lowest` sort in `_match_filaments_to_slots` (`print_scheduler.py`): the sort key reads `f.get("remain", -1)` straight out of `_build_loaded_filaments`, which sources it from MQTT AMS `tray.remain` — the printer firmware's own RFID-decremented value. Two problems with that signal: (a) it's only populated for Bambu RFID spools, so every non-RFID / 3rd-party / user-loaded tray reports `-1` and gets clamped to a sentinel — multiple non-RFID spools then tie in the sort and Python's stable sort collapses to AMS-slot insertion order, so slot 1 always wins; (b) even when set, it's the *printer's* counter, not Bambuddy's `label_weight - weight_used` (internal mode) or Spoolman's `remaining_weight` (Spoolman mode) — the two diverge any time the user re-spools, swaps cardboard, or runs a print outside Bambuddy. The reporter is on internal-inventory mode with non-RFID spools — both failure modes apply, hence slot 1 every time. **Fix**: when a slot is bound to a Bambuddy / Spoolman spool, that inventory record's remaining weight becomes the sort signal. New async helper `_build_inventory_remain_overrides(db, printer_id, loaded)` returns `{global_tray_id: remaining_grams}` for slots with an assignment — internal mode joins `SpoolAssignment` → `Spool` once per dispatch, Spoolman mode joins `SpoolmanSlotAssignment` then fetches each spool through the existing `_spoolman_remaining_grams` (shared with `filament_deficit.py`, parity rule per [[feedback_inventory_modes_parity]]). The new `_prefer_lowest_sort_key` consumes that map alongside the legacy MQTT field with a **two-tier** comparison: inventory-tracked spools always sort BEFORE MQTT-only spools, then ascending by remaining within each tier, then ascending by `ams_id * 4 + tray_id` as the deterministic slot tie-breaker. The tier flag dominates so we never compare grams (inventory) against percent (MQTT) — no unit-conversion contortions. MQTT-only behaviour is preserved exactly: `remain = -1` still maps to the 101 sentinel and slot order still decides on ties, so users who haven't bound any spools see no change. External / VT tray slots are skipped (tracked separately from AMS bindings). Lookup runs only when `prefer_lowest_filament` is enabled — no extra DB hit for users who don't use the preference. **Tests**: 6 new in `TestPreferLowestInventoryOverride` in `test_scheduler_ams_mapping.py` (inventory override beats MQTT remain — the literal reporter scenario with 950 g clone vs 50 g original; zero-grams still sorts first within its tier; inventory tier beats MQTT tier regardless of value; tied inventory grams break to lower slot; no-override falls through to MQTT — regression guard for un-tracked spools; legacy `remain = -1` still sentinel-sorts last when override map is None) + 7 new in `test_scheduler_inventory_remain.py` covering `_build_inventory_remain_overrides` directly (internal mode returns label_weight − weight_used per bound slot; external slots skipped; empty loaded short-circuits; over-consumed spool clamps to 0 g; unbound slots absent from map; Spoolman mode uses `_spoolman_remaining_grams` for parity; Spoolman unreachability silently omits that slot). 102 scheduler + inventory tests green; backend ruff clean. diff --git a/backend/app/api/routes/maintenance.py b/backend/app/api/routes/maintenance.py index d7d1af042..9c400b8aa 100644 --- a/backend/app/api/routes/maintenance.py +++ b/backend/app/api/routes/maintenance.py @@ -126,7 +126,8 @@ async def get_printer_total_hours(db: AsyncSession, printer_id: int) -> float: """Calculate total active hours for a printer from runtime counter plus offset. Uses the runtime_seconds counter which tracks actual machine active time - (RUNNING and PAUSE states), including calibration, heating, and printing. + (RUNNING state only — paused time is excluded since maintenance intervals + measure mechanical wear, not wall-clock active time, see #1521). """ # Get printer runtime and offset result = await db.execute( @@ -714,7 +715,7 @@ async def set_printer_hours( The offset is calculated as: offset = total_hours - runtime_hours Where runtime_hours comes from the runtime_seconds counter that tracks - actual machine active time (RUNNING/PAUSE states). + actual machine active time (RUNNING state only — paused time excluded, #1521). """ # Get printer result = await db.execute(select(Printer).where(Printer.id == printer_id)) diff --git a/backend/app/main.py b/backend/app/main.py index 4ee71179d..2b2fa35b0 100644 --- a/backend/app/main.py +++ b/backend/app/main.py @@ -4380,7 +4380,13 @@ RUNTIME_TRACKING_INTERVAL = 30 # Update every 30 seconds async def track_printer_runtime(): - """Background task to track printer active runtime (RUNNING/PAUSE states).""" + """Background task to track printer active runtime (RUNNING state only). + + PAUSE is intentionally excluded — the runtime counter feeds hours-based + maintenance intervals (rod lubrication, belt checks, nozzle cleaning) + which track mechanical wear. Pause time has no motion and no wear, so + counting it inflates maintenance warnings (#1521). + """ logger = logging.getLogger(__name__) # Wait for MQTT connections to establish on startup @@ -4418,7 +4424,7 @@ async def track_printer_runtime(): new_runtime = runtime_secs new_last_update = last_update - if state.state in ("RUNNING", "PAUSE"): + if state.state == "RUNNING": if last_update: lu = last_update if last_update.tzinfo else last_update.replace(tzinfo=timezone.utc) elapsed = (now - lu).total_seconds() diff --git a/backend/app/models/printer.py b/backend/app/models/printer.py index 72e17f0c7..442b58be3 100644 --- a/backend/app/models/printer.py +++ b/backend/app/models/printer.py @@ -20,7 +20,9 @@ class Printer(Base): is_active: Mapped[bool] = mapped_column(Boolean, default=True) auto_archive: Mapped[bool] = mapped_column(Boolean, default=True) print_hours_offset: Mapped[float] = mapped_column(Float, default=0.0) # Baseline hours to add - runtime_seconds: Mapped[int] = mapped_column(default=0) # Accumulated active runtime (RUNNING/PAUSE states) + runtime_seconds: Mapped[int] = mapped_column( + default=0 + ) # Accumulated active runtime (RUNNING state only — see #1521) last_runtime_update: Mapped[datetime | None] = mapped_column( DateTime, nullable=True ) # Last time runtime was updated diff --git a/backend/tests/unit/test_runtime_tracking_pause.py b/backend/tests/unit/test_runtime_tracking_pause.py new file mode 100644 index 000000000..3f338163e --- /dev/null +++ b/backend/tests/unit/test_runtime_tracking_pause.py @@ -0,0 +1,155 @@ +"""Regression tests for the runtime-tracking task (#1521). + +The ``runtime_seconds`` counter on each printer feeds hours-based maintenance +intervals (rod lubrication, belt checks, nozzle cleaning). It was accumulating +elapsed time whenever ``state.state`` was ``RUNNING`` *or* ``PAUSE``, which +meant a print paused for hours (e.g. overnight) inflated the maintenance +clock without any actual mechanical wear. Fix excludes PAUSE; these tests +pin the new contract. +""" + +from __future__ import annotations + +import asyncio +from datetime import datetime, timedelta, timezone +from types import SimpleNamespace +from unittest.mock import patch + +import pytest +from sqlalchemy import select +from sqlalchemy.ext.asyncio import AsyncSession, async_sessionmaker, create_async_engine + + +async def _build_db_with_printer(*, runtime_seconds: int, last_runtime_update: datetime | None): + """Spin up an in-memory DB with one active printer in the requested state.""" + import backend.app.models # noqa: F401 -- register all models on Base.metadata + from backend.app.core.database import Base + from backend.app.models.printer import Printer + + engine = create_async_engine("sqlite+aiosqlite:///:memory:", echo=False) + async with engine.begin() as conn: + await conn.run_sync(Base.metadata.create_all) + session_maker = async_sessionmaker(engine, class_=AsyncSession, expire_on_commit=False) + + async with session_maker() as db: + db.add( + Printer( + id=1, + name="P1", + serial_number="S1", + ip_address="1.1.1.1", + access_code="x", + is_active=True, + runtime_seconds=runtime_seconds, + last_runtime_update=last_runtime_update, + ) + ) + await db.commit() + return engine, session_maker + + +async def _run_one_iteration(session_maker, state_value: str): + """Run a single iteration of track_printer_runtime() against a mocked state. + + Patches ``asyncio.sleep`` to skip the startup wait and cancel after the + first loop tick. Patches ``printer_manager.get_status`` to return a fake + state with the requested ``.state`` value. Points the module-level + ``async_session`` at the test DB so the loop's queries hit it. + """ + from backend.app import main as app_main + + sleep_calls = {"count": 0} + real_sleep = asyncio.sleep + + async def fake_sleep(seconds, *args, **kwargs): + sleep_calls["count"] += 1 + # First sleep = the 15s startup wait. Second sleep = end-of-iteration + # tick; raise here so the loop exits cleanly via its CancelledError + # handler after exactly one work cycle. + if sleep_calls["count"] >= 2: + raise asyncio.CancelledError() + # Yield control to keep the event loop healthy without blocking. + await real_sleep(0) + + fake_state = SimpleNamespace(state=state_value, connected=True) + + # The loop's tail-of-iteration sleep is OUTSIDE its try/except, so the + # CancelledError raised from fake_sleep propagates out of the function + # rather than triggering the inner break — catch it at the test boundary. + with ( + patch.object(app_main, "async_session", session_maker), + patch.object(app_main.printer_manager, "get_status", return_value=fake_state), + patch.object(app_main.asyncio, "sleep", fake_sleep), + pytest.raises(asyncio.CancelledError), + ): + await app_main.track_printer_runtime() + + +@pytest.mark.asyncio +async def test_pause_state_does_not_accumulate_runtime(): + """PAUSE must NOT add to runtime_seconds — paused = no motion = no wear (#1521).""" + seeded_runtime = 1000 # 1000s already accumulated + seeded_last_update = datetime.now(timezone.utc) - timedelta(seconds=300) # 5min ago + engine, session_maker = await _build_db_with_printer( + runtime_seconds=seeded_runtime, last_runtime_update=seeded_last_update + ) + + await _run_one_iteration(session_maker, state_value="PAUSE") + + from backend.app.models.printer import Printer + + async with session_maker() as db: + row = (await db.execute(select(Printer).where(Printer.id == 1))).scalar_one() + # Runtime counter unchanged — the 5 minutes paused contributed nothing. + assert row.runtime_seconds == seeded_runtime + # last_runtime_update cleared on the non-running branch so the next + # transition to RUNNING starts fresh and doesn't back-bill paused time. + assert row.last_runtime_update is None + + await engine.dispose() + + +@pytest.mark.asyncio +async def test_running_state_still_accumulates_runtime(): + """RUNNING must continue to accumulate — the bug was scope, not the whole feature.""" + seeded_runtime = 1000 + seeded_last_update = datetime.now(timezone.utc) - timedelta(seconds=60) + engine, session_maker = await _build_db_with_printer( + runtime_seconds=seeded_runtime, last_runtime_update=seeded_last_update + ) + + await _run_one_iteration(session_maker, state_value="RUNNING") + + from backend.app.models.printer import Printer + + async with session_maker() as db: + row = (await db.execute(select(Printer).where(Printer.id == 1))).scalar_one() + # Wall-clock elapsed since seeded_last_update should now be added. + # Allow a generous lower bound (≥30s) — actual elapsed depends on + # how fast the test runs, but it MUST have grown past the seed. + assert row.runtime_seconds > seeded_runtime + assert row.runtime_seconds >= seeded_runtime + 30 + assert row.last_runtime_update is not None + + await engine.dispose() + + +@pytest.mark.asyncio +async def test_idle_state_clears_last_update_without_accumulating(): + """A non-active state (FINISH/IDLE/PREPARE/etc.) must clear last_runtime_update + so a later RUNNING transition doesn't retroactively back-bill all the idle time.""" + seeded_runtime = 1000 + seeded_last_update = datetime.now(timezone.utc) - timedelta(seconds=3600) # 1h ago + engine, session_maker = await _build_db_with_printer( + runtime_seconds=seeded_runtime, last_runtime_update=seeded_last_update + ) + + await _run_one_iteration(session_maker, state_value="FINISH") + + from backend.app.models.printer import Printer + + async with session_maker() as db: + row = (await db.execute(select(Printer).where(Printer.id == 1))).scalar_one() + assert row.runtime_seconds == seeded_runtime # no accumulation + assert row.last_runtime_update is None # cleared, prevents back-bill + await engine.dispose()