Browse Source

Notify a flickering HMS fault once, not on every return (#3226)

Track a last-seen time per fault instead of one set per printer, with a
10-minute window. Faults seen before the print resumes, starts or
finishes are forgotten as soon as they are gone, so a fixed runout that
recurs is still reported.
maziggy 1 day ago
parent
commit
902f09a7fe
3 changed files with 162 additions and 26 deletions
  1. 1 0
      CHANGELOG.md
  2. 52 24
      backend/app/main.py
  3. 109 2
      backend/tests/unit/services/test_hms_severity_2728.py

+ 1 - 0
CHANGELOG.md

@@ -267,6 +267,7 @@ All notable changes to Bambuddy will be documented in this file.
 - **Drying an AMS no longer sends an hourly "temperature high" alert for the whole cycle (#1802)** — The AMS temperature alert compares against the same threshold that colours the printer card, which defaults to 35 C, while drying deliberately runs at 45 C for PLA, 65 C for PETG and up to 85 C on an AMS-HT. The alert repeats once an hour for as long as the condition holds, so a twelve-hour dry sent twelve notifications about a temperature you asked for, and then kept sending them while the unit cooled back down. The alert is now held back for the length of a cycle and through the cool-down that follows it, using the drying state the firmware already reports rather than anything you have to configure. Suppression lifts as soon as the unit reads back at or below your threshold, so a 65 C cycle in a cold basement and a 45 C one in a warm room each get exactly the cool-down they need instead of a fixed guess. Two things are deliberately left alone: the humidity alert, which is the one you want during drying because the number falling is the point, and a unit reporting `HeatOutOfControl`, where an AMS that has lost thermal control is precisely when the alert should still reach you. Because a cycle plus its cool-down can outlast a restart, the suppression is stored rather than held in memory. No new setting — the alert simply stops firing for heat you asked for. Wiki updated. Covered by backend tests.
 - **Drying an AMS no longer sends an hourly "temperature high" alert for the whole cycle (#1802)** — The AMS temperature alert compares against the same threshold that colours the printer card, which defaults to 35 C, while drying deliberately runs at 45 C for PLA, 65 C for PETG and up to 85 C on an AMS-HT. The alert repeats once an hour for as long as the condition holds, so a twelve-hour dry sent twelve notifications about a temperature you asked for, and then kept sending them while the unit cooled back down. The alert is now held back for the length of a cycle and through the cool-down that follows it, using the drying state the firmware already reports rather than anything you have to configure. Suppression lifts as soon as the unit reads back at or below your threshold, so a 65 C cycle in a cold basement and a 45 C one in a warm room each get exactly the cool-down they need instead of a fixed guess. Two things are deliberately left alone: the humidity alert, which is the one you want during drying because the number falling is the point, and a unit reporting `HeatOutOfControl`, where an AMS that has lost thermal control is precisely when the alert should still reach you. Because a cycle plus its cool-down can outlast a restart, the suppression is stored rather than held in memory. No new setting — the alert simply stops firing for heat you asked for. Wiki updated. Covered by backend tests.
 - **Closing the bug-report panel no longer throws the capture away and leaves the logs running (#2847)** — Step 2 of the report flow asks you to reproduce the problem, and the panel sits over the part of the app you have to reach to do it. Closing it was the obvious move and it was the wrong one twice over. Reopening put you back on an empty step 1 — while the server was still logging at DEBUG, with nothing left in the flow that could stop it, because only **Stop & Submit** ever did. Leave it closed instead and the five-minute cap eventually fired behind your back: logging stopped and the report was filed with no window open and no confirmation that it had happened. Which of the two you got depended only on whether you reopened the panel inside five minutes. A capture is now a thing that outlives the panel. Closing keeps it running and says so — the bug button turns amber for as long as a capture is going, and clicking it returns you to step 2 with your description, your screenshot and the elapsed timer where you left them. If the cap does fire while the panel is closed, the panel reopens so the submission happens in front of you rather than behind you. The timer is measured against the capture's start time rather than counted in ticks, so a background tab, where browsers throttle timers hard, no longer stretches five minutes into something else. A capture also survives a page reload, which matters because reloading is a perfectly ordinary step in reproducing a bug: the report picks it back up where it was. One that outlived the cap while nobody was watching is not resumed and not filed — a description written an hour ago is not a report you are still expecting — but the log level is put back, which is the part that previously stayed wrong indefinitely. Translated in all locales; wiki updated. Covered by frontend tests.
 - **Closing the bug-report panel no longer throws the capture away and leaves the logs running (#2847)** — Step 2 of the report flow asks you to reproduce the problem, and the panel sits over the part of the app you have to reach to do it. Closing it was the obvious move and it was the wrong one twice over. Reopening put you back on an empty step 1 — while the server was still logging at DEBUG, with nothing left in the flow that could stop it, because only **Stop & Submit** ever did. Leave it closed instead and the five-minute cap eventually fired behind your back: logging stopped and the report was filed with no window open and no confirmation that it had happened. Which of the two you got depended only on whether you reopened the panel inside five minutes. A capture is now a thing that outlives the panel. Closing keeps it running and says so — the bug button turns amber for as long as a capture is going, and clicking it returns you to step 2 with your description, your screenshot and the elapsed timer where you left them. If the cap does fire while the panel is closed, the panel reopens so the submission happens in front of you rather than behind you. The timer is measured against the capture's start time rather than counted in ticks, so a background tab, where browsers throttle timers hard, no longer stretches five minutes into something else. A capture also survives a page reload, which matters because reloading is a perfectly ordinary step in reproducing a bug: the report picks it back up where it was. One that outlived the cap while nobody was watching is not resumed and not filed — a description written an hour ago is not a report you are still expecting — but the log level is put back, which is the part that previously stayed wrong indefinitely. Translated in all locales; wiki updated. Covered by frontend tests.
 - **The File Manager's card menu no longer loses its top entry (#2846)** — In grid view a file card's action menu was drawn inside the card, and the card clipped anything its children painted outside it. A card is as tall as its square thumbnail plus whatever metadata the file has, so an STL — which has none beyond a name and a size — produced the shortest card in the library, about 270px against a seven-entry menu that needs closer to 310px. The difference was one row, and the row it took was the top one: **Slice**, since **Print** is only offered for a file that is already sliced. A 3MF carries a target model and a print count, two more rows, and its card was tall enough, which is why the button appeared there and looked like a file-type rule rather than a layout accident. Nothing about STL was special; the shortest card simply lost the first item, whichever it happened to be. The menu now opens against the viewport, the way the archive card's menu already did, so no card can crop it, and the card no longer clips its own children. List view was never affected — it has no menu, only inline buttons. Covered by a frontend test.
 - **The File Manager's card menu no longer loses its top entry (#2846)** — In grid view a file card's action menu was drawn inside the card, and the card clipped anything its children painted outside it. A card is as tall as its square thumbnail plus whatever metadata the file has, so an STL — which has none beyond a name and a size — produced the shortest card in the library, about 270px against a seven-entry menu that needs closer to 310px. The difference was one row, and the row it took was the top one: **Slice**, since **Print** is only offered for a file that is already sliced. A 3MF carries a target model and a print count, two more rows, and its card was tall enough, which is why the button appeared there and looked like a file-type rule rather than a layout accident. Nothing about STL was special; the shortest card simply lost the first item, whichever it happened to be. The menu now opens against the viewport, the way the archive card's menu already did, so no card can crop it, and the card no longer clips its own children. List view was never affected — it has no menu, only inline buttons. Covered by a frontend test.
+- **A printer fault that kept coming and going was notified every time it came back (#3226, reported by @sgiffhorn)** — Bambuddy remembered which faults it had already notified as one list per printer, replaced on every status update, so a fault was forgotten the moment one update arrived without it. A 30-second grace period was meant to cover that, but only applied when the printer reported no faults at all, which never happens while it holds a notice such as the lubrication reminder. An H2D whose nozzle camera lens fault switched on and off beside two lubrication notices sent the same notification 9 times in 22 minutes. Each fault is now remembered on its own and notified again only after it has been gone for 10 minutes. So that a fault you fixed is still reported if it happens again soon, a fault seen before the print is resumed, started or finished is forgotten as soon as it is gone, without the wait; a filament runout fixed before resuming is notified again if it recurs a few minutes later. Covered by unit tests.
 
 
 ### Security
 ### Security
 - **Bumped `PyJWT` to 2.15.1 and `urllib3` to 2.8.0** — PyJWT 2.14 and 2.15 fix thirteen advisories, most of them algorithm confusion when one `decode()` call accepts both an HMAC and an asymmetric algorithm, and JWKS fetching through `PyJWKClient`. Bambuddy's session tokens accept only HS256, and SSO fetches the identity provider's key set itself before handing it to PyJWT, so neither path was open to these. The fixes for deeply nested or malformed tokens, and for JWK Sets with one bad key (which now skip that key instead of failing the whole set), do reach the SSO sign-in. urllib3 2.8.0 fixes three advisories in response streaming and HTTPS-proxy TLS; Bambuddy doesn't use urllib3 itself, it arrives through other packages. `virtualenv`, which only the development tools pull in, is pinned to 21.7.13 or later so `pip-audit` stays clean.
 - **Bumped `PyJWT` to 2.15.1 and `urllib3` to 2.8.0** — PyJWT 2.14 and 2.15 fix thirteen advisories, most of them algorithm confusion when one `decode()` call accepts both an HMAC and an asymmetric algorithm, and JWKS fetching through `PyJWKClient`. Bambuddy's session tokens accept only HS256, and SSO fetches the identity provider's key set itself before handing it to PyJWT, so neither path was open to these. The fixes for deeply nested or malformed tokens, and for JWK Sets with one bad key (which now skip that key instead of failing the whole set), do reach the SSO sign-in. urllib3 2.8.0 fixes three advisories in response streaming and HTTPS-proxy TLS; Bambuddy doesn't use urllib3 itself, it arrives through other packages. `virtualenv`, which only the development tools pull in, is pinned to 21.7.13 or later so `pip-audit` stays clean.

+ 52 - 24
backend/app/main.py

@@ -478,13 +478,18 @@ _kill_switch_setting_cache: tuple[bool, float] | None = None
 # provider notification when the immediate attempt failed.
 # provider notification when the immediate attempt failed.
 _kill_switch_notification_tasks: dict[int, asyncio.Task[bool]] = {}
 _kill_switch_notification_tasks: dict[int, asyncio.Task[bool]] = {}
 
 
-# Track HMS errors that have been notified: {printer_id: set of error codes}
-# This prevents sending duplicate notifications for the same error
-_notified_hms_errors: dict[int, set[str]] = {}
-# Track when HMS errors were last seen: {printer_id: timestamp}
-# Used to debounce clearing — prevents flapping errors from re-triggering notifications
-_hms_last_seen: dict[int, float] = {}
-_HMS_CLEAR_GRACE_SECONDS = 30.0
+# HMS faults already notified, with when each was last seen:
+# {printer_id: {fault key: timestamp}}. Tracked per fault, not per printer: a
+# fault that flickers beside a held notice was forgotten on every gap and
+# notified on every return (#3226). The window is long because the measured
+# gaps reach 64 s.
+_notified_hms_errors: dict[int, dict[str, float]] = {}
+_HMS_CLEAR_GRACE_SECONDS = 600.0
+# The print state each printer was last seen in, and the faults recorded before
+# it last changed, which are forgotten as soon as they are gone (see
+# _take_new_hms_faults).
+_hms_print_state: dict[int, str] = {}
+_hms_forget_when_gone: dict[int, set[str]] = {}
 
 
 # Track timelapse file baselines at print start: {printer_id: set of video filenames}
 # Track timelapse file baselines at print start: {printer_id: set of video filenames}
 # Used for snapshot-diff detection at print completion
 # Used for snapshot-diff detection at print completion
@@ -1494,18 +1499,46 @@ def _hms_errors_to_notify(errors: list, new_error_codes: set[str]) -> list:
     return [e for e in errors if _hms_notify_key(e) in new_error_codes and _hms_fault_counts(e)]
     return [e for e in errors if _hms_notify_key(e) in new_error_codes and _hms_fault_counts(e)]
 
 
 
 
-def _take_new_hms_faults(printer_id: int, errors: list) -> list:
+def _take_new_hms_faults(printer_id: int, errors: list, print_state: str | None = None) -> list:
     """The faults on this printer not notified yet, and record them as notified.
     """The faults on this printer not notified yet, and record them as notified.
 
 
     Tracking is updated before anything is sent, so concurrent status callbacks
     Tracking is updated before anything is sent, so concurrent status callbacks
-    cannot notify the same fault twice. The set is replaced, not extended: a
-    fault that clears and later returns is notified again, and the grace period
-    in the caller keeps a fault that flickers off for a moment from doing that.
+    cannot notify the same fault twice. A notified fault is forgotten once it
+    has been gone for ``_HMS_CLEAR_GRACE_SECONDS``, so one that flickers off
+    and on is notified once (#3226), while one that clears and comes back much
+    later is notified again.
+
+    When ``print_state`` changes (a print resumed, started or finished), every
+    fault recorded so far is forgotten the first time it is gone, without the
+    wait: a runout fixed before resuming must be notified if it happens again a
+    few minutes later, while the printer sits paused. Not only the faults gone
+    at the change itself, because the update that flips the state can still
+    carry the old fault (a ``print_error`` entry stays until a payload brings
+    ``hms``).
     """
     """
+    now = time.time()
     current = {_hms_notify_key(e) for e in errors}
     current = {_hms_notify_key(e) for e in errors}
-    new = current - _notified_hms_errors.get(printer_id, set())
-    _notified_hms_errors[printer_id] = current
-    _hms_last_seen[printer_id] = time.time()
+    seen = _notified_hms_errors.setdefault(printer_id, {})
+    forget_when_gone = _hms_forget_when_gone.setdefault(printer_id, set())
+
+    if print_state is not None:
+        print_state = print_state.upper()
+        if _hms_print_state.get(printer_id, print_state) != print_state:
+            forget_when_gone.update(seen)
+        _hms_print_state[printer_id] = print_state
+
+    for key, last_seen in list(seen.items()):
+        if key not in current and (key in forget_when_gone or now - last_seen >= _HMS_CLEAR_GRACE_SECONDS):
+            del seen[key]
+            forget_when_gone.discard(key)
+
+    new = current - seen.keys()
+    for key in current:
+        seen[key] = now
+    if not seen:
+        _notified_hms_errors.pop(printer_id, None)
+    if not forget_when_gone:
+        _hms_forget_when_gone.pop(printer_id, None)
     return _hms_errors_to_notify(errors, new)
     return _hms_errors_to_notify(errors, new)
 
 
 
 
@@ -1928,7 +1961,7 @@ async def on_printer_status_change(printer_id: int, state: PrinterState):
     # Check for new HMS errors and send notifications
     # Check for new HMS errors and send notifications
     current_hms_errors = getattr(state, "hms_errors", []) or []
     current_hms_errors = getattr(state, "hms_errors", []) or []
     if current_hms_errors:
     if current_hms_errors:
-        new_errors = _take_new_hms_faults(printer_id, current_hms_errors)
+        new_errors = _take_new_hms_faults(printer_id, current_hms_errors, state.state)
 
 
         if new_errors:
         if new_errors:
             try:
             try:
@@ -2010,15 +2043,10 @@ async def on_printer_status_change(printer_id: int, state: PrinterState):
                 logging.getLogger(__name__).warning(f"HMS error notification failed: {e}")
                 logging.getLogger(__name__).warning(f"HMS error notification failed: {e}")
 
 
     else:
     else:
-        # No HMS errors — only clear tracking after a grace period to prevent
-        # flapping errors (brief hms:[] gaps) from re-triggering notifications.
-        # Some HMS codes (e.g. chamber temp regulation during PETG prints) toggle
-        # on/off every few seconds as conditions fluctuate around thresholds.
-        if printer_id in _notified_hms_errors:
-            last_seen = _hms_last_seen.get(printer_id, 0)
-            if time.time() - last_seen >= _HMS_CLEAR_GRACE_SECONDS:
-                _notified_hms_errors.pop(printer_id, None)
-                _hms_last_seen.pop(printer_id, None)
+        # No HMS errors: nothing to send, but faults gone long enough (or gone
+        # across a print state change) are forgotten. Some codes, e.g. chamber
+        # temperature regulation during PETG prints, toggle every few seconds.
+        _take_new_hms_faults(printer_id, [], state.state)
 
 
     await ws_manager.send_printer_status(
     await ws_manager.send_printer_status(
         printer_id,
         printer_id,

+ 109 - 2
backend/tests/unit/services/test_hms_severity_2728.py

@@ -157,10 +157,12 @@ class TestNotificationDeduplication:
     @pytest.fixture(autouse=True)
     @pytest.fixture(autouse=True)
     def _clean(self):
     def _clean(self):
         main_module._notified_hms_errors.pop(self.PRINTER, None)
         main_module._notified_hms_errors.pop(self.PRINTER, None)
-        main_module._hms_last_seen.pop(self.PRINTER, None)
+        main_module._hms_print_state.pop(self.PRINTER, None)
+        main_module._hms_forget_when_gone.pop(self.PRINTER, None)
         yield
         yield
         main_module._notified_hms_errors.pop(self.PRINTER, None)
         main_module._notified_hms_errors.pop(self.PRINTER, None)
-        main_module._hms_last_seen.pop(self.PRINTER, None)
+        main_module._hms_print_state.pop(self.PRINTER, None)
+        main_module._hms_forget_when_gone.pop(self.PRINTER, None)
 
 
     def test_two_faults_on_one_part_are_both_notified(self):
     def test_two_faults_on_one_part_are_both_notified(self):
         """#1840's H2C held both of these at once; they share attr 05000600."""
         """#1840's H2C held both of these at once; they share attr 05000600."""
@@ -192,3 +194,108 @@ class TestNotificationDeduplication:
         a = SimpleNamespace(full_code="", attr=0x05000600, code="0x20005", severity=2)
         a = SimpleNamespace(full_code="", attr=0x05000600, code="0x20005", severity=2)
         b = SimpleNamespace(full_code="", attr=0x05000600, code="0x20006", severity=2)
         b = SimpleNamespace(full_code="", attr=0x05000600, code="0x20006", severity=2)
         assert _hms_notify_key(a) != _hms_notify_key(b)
         assert _hms_notify_key(a) != _hms_notify_key(b)
+
+
+class TestFlickeringFaults:
+    """#3226: an H2D held two lubrication notices for the whole print while the
+    nozzle-camera-lens fault came and went (on 20-29 s, off 25-64 s). The
+    notified set was replaced on every update, so each return was notified."""
+
+    PRINTER = 9002
+    RODS = "0501040000030002"
+    LENS = "0C00010000020017"
+
+    @pytest.fixture(autouse=True)
+    def _clean(self):
+        main_module._notified_hms_errors.pop(self.PRINTER, None)
+        main_module._hms_print_state.pop(self.PRINTER, None)
+        main_module._hms_forget_when_gone.pop(self.PRINTER, None)
+        yield
+        main_module._notified_hms_errors.pop(self.PRINTER, None)
+        main_module._hms_print_state.pop(self.PRINTER, None)
+        main_module._hms_forget_when_gone.pop(self.PRINTER, None)
+
+    @pytest.fixture
+    def clock(self, monkeypatch):
+        now = [1_000_000.0]
+        monkeypatch.setattr(main_module.time, "time", lambda: now[0])
+        return now
+
+    def test_a_fault_flickering_beside_a_held_notice_is_notified_once(self, clock):
+        rods, lens = _fault(self.RODS, 3), _fault(self.LENS)
+        assert _take_new_hms_faults(self.PRINTER, [rods, lens], "RUNNING") == [lens]
+        for _ in range(9):
+            clock[0] += 64
+            assert _take_new_hms_faults(self.PRINTER, [rods], "RUNNING") == []
+            clock[0] += 29
+            assert _take_new_hms_faults(self.PRINTER, [rods, lens], "RUNNING") == []
+
+    def test_a_fault_gone_for_the_whole_window_is_notified_again(self, clock):
+        lens = _fault(self.LENS)
+        assert _take_new_hms_faults(self.PRINTER, [lens], "RUNNING") == [lens]
+        clock[0] += 1
+        assert _take_new_hms_faults(self.PRINTER, [], "RUNNING") == []
+        clock[0] += main_module._HMS_CLEAR_GRACE_SECONDS
+        assert _take_new_hms_faults(self.PRINTER, [], "RUNNING") == []
+        assert self.PRINTER not in main_module._notified_hms_errors
+        assert _take_new_hms_faults(self.PRINTER, [lens], "RUNNING") == [lens]
+
+    def test_a_fault_fixed_before_resuming_is_notified_when_it_returns(self, clock):
+        """A runout pauses the print; the user fixes it and resumes. The same
+        fault minutes later must not go unnoticed while the printer sits paused."""
+        runout = _fault("0700200000020001")
+        assert _take_new_hms_faults(self.PRINTER, [runout], "PAUSE") == [runout]
+        clock[0] += 60
+        assert _take_new_hms_faults(self.PRINTER, [], "RUNNING") == []
+        clock[0] += 120
+        assert _take_new_hms_faults(self.PRINTER, [runout], "PAUSE") == [runout]
+
+    def test_a_state_change_keeps_a_fault_that_is_still_there(self, clock):
+        lens = _fault(self.LENS)
+        assert _take_new_hms_faults(self.PRINTER, [lens], "RUNNING") == [lens]
+        clock[0] += 5
+        assert _take_new_hms_faults(self.PRINTER, [lens], "FINISH") == []
+
+    def test_the_first_state_seen_is_not_a_change(self, clock):
+        lens = _fault(self.LENS)
+        assert _take_new_hms_faults(self.PRINTER, [lens]) == [lens]
+        clock[0] += 5
+        assert _take_new_hms_faults(self.PRINTER, [], "RUNNING") == []
+        assert _take_new_hms_faults(self.PRINTER, [lens], "RUNNING") == []
+
+    def test_a_fault_still_reported_at_the_resume_is_forgotten_once_gone(self, clock):
+        """The update that flips PAUSE to RUNNING can still carry the fault; it
+        goes on the next one. A recurrence minutes later must still notify."""
+        runout = _fault("0700200000020001")
+        assert _take_new_hms_faults(self.PRINTER, [runout], "PAUSE") == [runout]
+        clock[0] += 60
+        assert _take_new_hms_faults(self.PRINTER, [runout], "RUNNING") == []
+        clock[0] += 2
+        assert _take_new_hms_faults(self.PRINTER, [], "RUNNING") == []
+        clock[0] += 120
+        assert _take_new_hms_faults(self.PRINTER, [runout], "PAUSE") == [runout]
+
+    def test_a_state_change_costs_a_flickering_fault_at_most_one_more_notification(self, clock):
+        rods, lens = _fault(self.RODS, 3), _fault(self.LENS)
+        assert _take_new_hms_faults(self.PRINTER, [rods, lens], "RUNNING") == [lens]
+        clock[0] += 5
+        assert _take_new_hms_faults(self.PRINTER, [rods, lens], "FINISH") == []
+        clock[0] += 30
+        assert _take_new_hms_faults(self.PRINTER, [rods], "FINISH") == []
+        clock[0] += 30
+        assert _take_new_hms_faults(self.PRINTER, [rods, lens], "FINISH") == [lens]
+        for _ in range(5):
+            clock[0] += 60
+            assert _take_new_hms_faults(self.PRINTER, [rods], "FINISH") == []
+            clock[0] += 30
+            assert _take_new_hms_faults(self.PRINTER, [rods, lens], "FINISH") == []
+
+    def test_tracking_is_dropped_once_everything_is_forgotten(self, clock):
+        lens = _fault(self.LENS)
+        _take_new_hms_faults(self.PRINTER, [lens], "RUNNING")
+        clock[0] += 1
+        _take_new_hms_faults(self.PRINTER, [lens], "FINISH")
+        clock[0] += 1
+        _take_new_hms_faults(self.PRINTER, [], "FINISH")
+        assert self.PRINTER not in main_module._notified_hms_errors
+        assert self.PRINTER not in main_module._hms_forget_when_gone