diff --git a/CHANGELOG.md b/CHANGELOG.md index ce3070813..c29811efa 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -4,6 +4,9 @@ All notable changes to Bambuddy will be documented in this file. ## [0.2.4b2] - Unreleased +### Fixed +- **AMS slot configuration intermittently fails to reach the printer after several configs in a row** ([#1164](https://github.com/maziggy/bambuddy/issues/1164), reported by @RosdasHH) — Configuring AMS slots a handful of times (the reporter saw it almost every 6th change) would silently stop reaching the printer; ~1 minute later the filament colours on the printer would briefly jump between slots, then settle. Root cause was the zombie-session watchdog at `bambu_mqtt.py:861` introduced for [#887](https://github.com/maziggy/bambuddy/issues/887). When an `ams_filament_setting` response took >10 s (normal under load — concurrent K-profile fetches, busy printer, network jitter) the watchdog incremented an `_ams_cmd_unanswered` counter and zeroed `_last_ams_cmd_time` so it wouldn't re-trigger on the next status push. The bug: the response handler that reset the counter was guarded by `and self._last_ams_cmd_time > 0` — so when the late response *did* arrive (after the watchdog had already zeroed the timer), the counter stayed armed at 1. The next slow response on any `ams_filament_setting` command — possibly minutes or hours later, on an entirely unrelated config attempt — would take the counter to 2 and trigger `force_reconnect_stale_session()`. The user-visible symptoms match exactly: configs stop landing (because MQTT reconnects mid-publish, dropping the in-flight command and surfacing as `Cannot set AMS filament setting: not connected` if the user retries during the ~1 min reconnect window), then the queued state finally lands when the reconnect completes (the "filament colours jumping around" the reporter described). Fix is to drop the `_last_ams_cmd_time > 0` guard: any `ams_filament_setting` response — late or not — proves the channel is alive, so the counter must reset. Watchdog still trips on a real zombie session (no responses at all for two consecutive >10 s windows). Regression test in `test_bambu_mqtt.py::TestZombieSessionDetection::test_late_response_after_watchdog_clears_counter_issue_1164` simulates the exact sequence (watchdog fires → late response arrives → second slow response on a fresh command) and asserts the counter resets to 0 on the late response and the second command doesn't tip the threshold to 2. Other 10 zombie-detection tests still pass unchanged. + ## [0.2.4b1] - 2026-04-29 ### Added diff --git a/backend/app/services/bambu_mqtt.py b/backend/app/services/bambu_mqtt.py index c5c08c567..e01078a04 100644 --- a/backend/app/services/bambu_mqtt.py +++ b/backend/app/services/bambu_mqtt.py @@ -857,8 +857,20 @@ class BambuMQTTClient: and print_data.get("sequence_id") == self._dev_mode_probe_seq ): self._handle_dev_mode_probe_response(print_data) - # Track user-initiated ams_filament_setting responses (#887 zombie detection) - elif cmd == "ams_filament_setting" and self._last_ams_cmd_time > 0: + # Track user-initiated ams_filament_setting responses (#887 + # zombie detection). Reset both the timer AND the unanswered + # counter on ANY response — the response proves the channel is + # alive, so the counter must not stay armed even when the + # watchdog already zeroed `_last_ams_cmd_time` on a previous + # tick. The original `and self._last_ams_cmd_time > 0` guard + # caused #1164: one sluggish response (>10s) would set the + # counter to 1 and zero the timer; the late response arrived + # but was ignored by this branch (timer is 0); the counter + # stayed at 1 indefinitely; the very next slow response — + # possibly hours later, on a totally unrelated command — would + # take it to 2 and force-reconnect, surfacing as "filament + # config doesn't reach the printer ~6 changes in". + elif cmd == "ams_filament_setting": self._last_ams_cmd_time = 0.0 self._ams_cmd_unanswered = 0 if "command" in print_data and print_data.get("command") == "extrusion_cali_get": diff --git a/backend/tests/unit/services/test_bambu_mqtt.py b/backend/tests/unit/services/test_bambu_mqtt.py index be749e86e..df60b7f9b 100644 --- a/backend/tests/unit/services/test_bambu_mqtt.py +++ b/backend/tests/unit/services/test_bambu_mqtt.py @@ -4140,6 +4140,54 @@ class TestZombieSessionDetection: assert mqtt_client._ams_cmd_unanswered == 1 assert mqtt_client.state.connected is True # no reconnect + def test_late_response_after_watchdog_clears_counter_issue_1164(self, mqtt_client): + """Regression for #1164: a late ams_filament_setting response — one + that arrives AFTER the watchdog has already zeroed + `_last_ams_cmd_time` and incremented the unanswered counter — must + still reset the counter. Without this, a single sluggish response + leaves the counter armed at 1 indefinitely; the next slow response + on a totally unrelated command (possibly minutes or hours later) + takes it to 2 and force-reconnects, surfacing as 'AMS slot config + doesn't reach the printer ~6 changes in'.""" + import time + + # First command publishes, then doesn't get a response for >10s. + # Watchdog fires: counter=1, _last_ams_cmd_time zeroed. + mqtt_client._last_ams_cmd_time = time.monotonic() - 11.0 + mqtt_client._update_state({"gcode_state": "IDLE"}) + assert mqtt_client._ams_cmd_unanswered == 1 + assert mqtt_client._last_ams_cmd_time == 0.0 # watchdog cleared it + + # Late response arrives — the `_process_message` path used to require + # `_last_ams_cmd_time > 0` before resetting the counter, so this would + # have silently been ignored. + mqtt_client._process_message( + { + "print": { + "command": "ams_filament_setting", + "sequence_id": "0", + "result": "success", + "reason": "success", + } + } + ) + + # Counter MUST be reset — the response proves the channel is alive. + assert mqtt_client._ams_cmd_unanswered == 0, ( + "Late ams_filament_setting response must reset the unanswered " + "counter even when the watchdog already zeroed _last_ams_cmd_time. " + "If this assertion fails the #1164 regression is back: a single " + "sluggish response will leave the counter armed and cause a " + "spurious force_reconnect on the next slow response." + ) + + # Now even if a future command times out, the counter starts fresh + # and a single timeout doesn't trip the 2x reconnect threshold. + mqtt_client._last_ams_cmd_time = time.monotonic() - 11.0 + mqtt_client._update_state({"gcode_state": "IDLE"}) + assert mqtt_client._ams_cmd_unanswered == 1 + assert mqtt_client.state.connected is True # no force reconnect + def test_on_connect_resets_tracking(self, mqtt_client): """_on_connect resets zombie tracking fields.""" import time