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()