From 4258a58c1243975162014e5ad9b478513ecc2d97 Mon Sep 17 00:00:00 2001 From: jeomon Date: Sat, 29 Aug 2026 07:18:33 +0530 Subject: [PATCH] fix: back off when the watchdog rebuild is triggered by degradation The rebuild loop reset backoff to 1s on any clean return from _event_loop, and a rebuild requested by FAIL_THRESHOLD consecutive COMErrors returns exactly that way. So a UIA stack that degrades immediately on every rebuild was retried once a second forever: a fresh COM client built and torn down per second, and one "WatchDog event pipeline degraded" warning per second. The exponential backoff only ever applied to the exception path. Reset backoff only after a run that survived HEALTHY_RUN_SECONDS, so an intermittent glitch after hours of healthy operation still retries promptly, while a persistently broken environment escalates to the 30s cap. Verified against the old code: twelve consecutive immediate degradations produced twelve 1.0s waits, where they now escalate 1, 2, 4, 8 ... 30. This is the log flood in #332 and the client churn behind it. It does not address the terminal E_UNEXPECTED crash, which is a native access violation no Python except can catch and needs the watchdog out of process. Refs #332 --- src/windows_mcp/watchdog/service.py | 17 +++- tests/test_watchdog_backoff.py | 140 ++++++++++++++++++++++++++++ 2 files changed, 156 insertions(+), 1 deletion(-) create mode 100644 tests/test_watchdog_backoff.py diff --git a/src/windows_mcp/watchdog/service.py b/src/windows_mcp/watchdog/service.py index b44295ab..dc24ae6b 100755 --- a/src/windows_mcp/watchdog/service.py +++ b/src/windows_mcp/watchdog/service.py @@ -9,6 +9,7 @@ import comtypes.client import comtypes import logging +import time from .event_handlers import ( FocusChangedEventHandler, @@ -26,6 +27,12 @@ FAIL_THRESHOLD = 5 MAX_BACKOFF_SECONDS = 30.0 +# How long a run must survive before its exit is treated as a one-off rather +# than a symptom of a still-broken environment. Below this, the backoff keeps +# growing, so a UIA stack that degrades immediately on every rebuild is retried +# ever more slowly instead of churning COM clients at 1 Hz forever. +HEALTHY_RUN_SECONDS = 60.0 + class WatchDog: def __init__(self): @@ -127,6 +134,7 @@ def _run(self): backoff = 1.0 while self.is_running.is_set(): comtypes.CoInitialize() + started = time.monotonic() try: self.uia = self._create_uia() self._needs_rebuild.clear() @@ -134,13 +142,20 @@ def _run(self): self._structure_fail_count = 0 self._property_fail_count = 0 self._event_loop() - backoff = 1.0 # clean exit (stopped or rebuild requested) except Exception as e: logger.warning(f"WatchDog degraded, rebuilding UIA client: {e}") finally: self._teardown_handlers() comtypes.CoUninitialize() + # Only a run that lasted earns a reset. A rebuild requested seconds + # after starting means the environment is still broken, and + # resetting here would retry at 1 Hz indefinitely -- rebuilding the + # COM client and logging a warning every second, in exactly the + # degraded state this backoff exists to damp. + if time.monotonic() - started >= HEALTHY_RUN_SECONDS: + backoff = 1.0 + if self.is_running.is_set(): self.is_running.wait(backoff) backoff = min(backoff * 2, MAX_BACKOFF_SECONDS) diff --git a/tests/test_watchdog_backoff.py b/tests/test_watchdog_backoff.py new file mode 100644 index 00000000..21897c00 --- /dev/null +++ b/tests/test_watchdog_backoff.py @@ -0,0 +1,140 @@ +"""Regression tests for issue #332 — backoff must apply to degraded rebuilds. + +The watchdog rebuilds its UIA client when the focus pipeline goes stale, which +`_event_loop` signals by returning with `_needs_rebuild` set. That return was +treated as a clean exit and reset the backoff to 1 second, so an environment +that degrades immediately on every rebuild was retried once a second forever — +churning COM clients and emitting a warning per second, which is the log flood +in the report. Backoff now only resets after a run that actually lasted. +""" + +import time +import types + +import pytest + +from windows_mcp.watchdog import service as watchdog_service +from windows_mcp.watchdog.service import MAX_BACKOFF_SECONDS, WatchDog + + +@pytest.fixture +def watchdog(monkeypatch): + """A WatchDog with every COM touchpoint stubbed out.""" + # __init__ grabs the UIA singleton, which would build COM. + monkeypatch.setattr( + watchdog_service._AutomationClient, + "instance", + classmethod(lambda cls: types.SimpleNamespace(UIAutomationCore=object())), + ) + monkeypatch.setattr(watchdog_service.comtypes, "CoInitialize", lambda: None) + monkeypatch.setattr(watchdog_service.comtypes, "CoUninitialize", lambda: None) + + watchdog = WatchDog() + monkeypatch.setattr(watchdog, "_create_uia", lambda: object()) + monkeypatch.setattr(watchdog, "_teardown_handlers", lambda: None) + return watchdog + + +def run_capturing_waits(watchdog, monkeypatch, event_loop): + """Drive _run synchronously, recording what it would have slept.""" + waits = [] + monkeypatch.setattr(watchdog, "_event_loop", event_loop) + monkeypatch.setattr( + watchdog.is_running, "wait", lambda timeout: waits.append(timeout) or False + ) + watchdog.is_running.set() + watchdog._run() + return waits + + +class TestDegradedRebuildBacksOff: + def test_immediate_degradation_escalates(self, watchdog, monkeypatch): + """The reported failure mode: rebuild requested as soon as each run starts.""" + runs = {"n": 0} + + def event_loop(): + runs["n"] += 1 + watchdog._needs_rebuild.set() # what FAIL_THRESHOLD COMErrors do + if runs["n"] >= 5: + watchdog.is_running.clear() + + waits = run_capturing_waits(watchdog, monkeypatch, event_loop) + + assert waits == [1.0, 2.0, 4.0, 8.0], "a degraded rebuild must not reset backoff" + + def test_backoff_is_capped(self, watchdog, monkeypatch): + runs = {"n": 0} + + def event_loop(): + runs["n"] += 1 + watchdog._needs_rebuild.set() + if runs["n"] >= 12: + watchdog.is_running.clear() + + waits = run_capturing_waits(watchdog, monkeypatch, event_loop) + + assert max(waits) == MAX_BACKOFF_SECONDS + assert waits[-1] == MAX_BACKOFF_SECONDS + + def test_exception_path_still_backs_off(self, watchdog, monkeypatch): + runs = {"n": 0} + + def event_loop(): + runs["n"] += 1 + if runs["n"] >= 4: + watchdog.is_running.clear() + raise OSError("pump exploded") + + waits = run_capturing_waits(watchdog, monkeypatch, event_loop) + + assert waits == [1.0, 2.0, 4.0] + + +class TestHealthyRunResetsBackoff: + def test_a_run_that_lasted_resets_the_backoff(self, watchdog, monkeypatch): + """An intermittent glitch after a long healthy run should retry promptly.""" + monkeypatch.setattr(watchdog_service, "HEALTHY_RUN_SECONDS", 0.05) + runs = {"n": 0} + + def event_loop(): + runs["n"] += 1 + if runs["n"] == 2: + time.sleep(0.06) # this run survived long enough to count + watchdog._needs_rebuild.set() + if runs["n"] >= 3: + watchdog.is_running.clear() + + waits = run_capturing_waits(watchdog, monkeypatch, event_loop) + + assert waits == [1.0, 1.0], "a long run should return the retry delay to 1s" + + def test_stopping_does_not_wait(self, watchdog, monkeypatch): + def event_loop(): + watchdog.is_running.clear() + + waits = run_capturing_waits(watchdog, monkeypatch, event_loop) + + assert waits == [] + + +class TestClientIsRebuiltEachCycle: + def test_every_cycle_gets_a_fresh_client_and_clean_counters(self, watchdog, monkeypatch): + """#334's contract: never reuse a client that just reported failure.""" + clients = [] + monkeypatch.setattr(watchdog, "_create_uia", lambda: clients.append(object()) or clients[-1]) + runs = {"n": 0} + seen_counts = [] + + def event_loop(): + runs["n"] += 1 + seen_counts.append(watchdog._focus_fail_count) + watchdog._focus_fail_count = 99 # simulate failures during the run + watchdog._needs_rebuild.set() + if runs["n"] >= 3: + watchdog.is_running.clear() + + run_capturing_waits(watchdog, monkeypatch, event_loop) + + assert len(clients) == 3, "each cycle must build its own client" + assert len(set(map(id, clients))) == 3 + assert seen_counts == [0, 0, 0], "failure counters must reset per cycle"