diff --git a/features/steps/tdd_mcp_client_timer_cancel_race_steps.py b/features/steps/tdd_mcp_client_timer_cancel_race_steps.py new file mode 100644 index 000000000..11bba652e --- /dev/null +++ b/features/steps/tdd_mcp_client_timer_cancel_race_steps.py @@ -0,0 +1,323 @@ +"""Step definitions for features/tdd_mcp_client_timer_cancel_race.feature. + +TDD issue-capture scenario for #10516: McpClient idle/health timer can fire +after cancellation due to race condition in _schedule_idle_timer(). + +_schedule_idle_timer() stores the Timer in self._idle_timer inside the lock +but calls timer.start() OUTSIDE the lock. This creates a race window where +shutdown() can call _cancel_idle_timer() (which cancels the Timer and nulls +the reference) while the original thread has not yet called timer.start(). + +The race: timer.start() is called AFTER cancel() was called on the same Timer. +Python 3.x Timer.cancel() sets _was_cancelled=True but does not prevent a +subsequent start() from being accepted. The timer does NOT fire in this case +(due to the cancelled flag). However, if the timing is such that cancel() is +called BEFORE start(), the timer will fire — which is the bug. + +The @tdd_expected_fail tag inverts the test result so CI passes while the +bug is unfixed. When the bug is fixed (by moving timer.start() inside the +lock), the @tdd_expected_fail tag must be removed. + +See: https://git.cleverthis.com/cleveragents/cleveragents-core/issues/10516 +""" + +from __future__ import annotations + +import threading +import time + +from behave import given, then, when +from behave.runner import Context + +from cleveragents.mcp.adapter import MCPServerConfig +from cleveragents.mcp.client import McpClient, McpClientConfig +from features.mocks.mock_mcp_transport import MockMCPTransport + + +def _mock_tool(name: str, desc: str = "", schema: dict | None = None) -> dict: + return { + "name": name, + "description": desc or f"Mock tool {name}", + "inputSchema": schema or {}, + } + + +class _ShutdownOnCancelTimer: + """Timer probe that marks shutdown while scheduler cancellation is active.""" + + def __init__(self, client: McpClient) -> None: + self._client = client + self.cancel_called = False + + def cancel(self) -> None: + self.cancel_called = True + with self._client._lock: + self._client._shutting_down = True + + +# ── Given ───────────────────────────────────────────────────────── + + +@given("an McpClient with a very short idle timeout (0.05s)") +def step_mcp_client_short_idle(context: Context) -> None: + """Create an McpClient configured with a 50ms idle timeout. + + Health checks are disabled to avoid interference from that timer. + """ + server_config = MCPServerConfig( + name="test-timer-race", + transport="stdio", + command="echo", + ) + context.timer_race_config = McpClientConfig( + server=server_config, + lazy_start=False, + idle_timeout_seconds=0.05, # 50 ms — fires quickly for testing + health_check_interval_seconds=0, # Disable health checks + ) + context.timer_race_transport = MockMCPTransport( + tools=[_mock_tool("test_tool")], + ) + context.timer_race_client = McpClient( + config=context.timer_race_config, + transport=context.timer_race_transport, + ) + context.timer_race_callback_fired = False + context.timer_race_callback_lock = threading.Lock() + + +@given("a mock transport with one tool") +def step_mock_transport_one_tool(context: Context) -> None: + """Ensure the transport has at least one tool for discovery.""" + # Already configured in the previous step; this step is here for + # readability and alignment with the feature file's given clause. + pass + + +@given("a shared flag to detect if the idle callback fired after shutdown") +def step_shared_callback_flag(context: Context) -> None: + """Initialize the shared flag used to detect late timer callbacks.""" + context.timer_race_callback_fired = False + context.timer_race_callback_lock = threading.Lock() + + +@given("an McpClient with active idle and health timers") +def step_mcp_client_active_timers(context: Context) -> None: + """Create a client whose timer schedulers would normally install timers.""" + server_config = MCPServerConfig( + name="test-timer-shutdown-guard", + transport="stdio", + command="echo", + ) + context.timer_race_config = McpClientConfig( + server=server_config, + lazy_start=False, + idle_timeout_seconds=60.0, + health_check_interval_seconds=60.0, + ) + context.timer_race_transport = MockMCPTransport( + tools=[_mock_tool("test_tool")], + ) + context.timer_race_client = McpClient( + config=context.timer_race_config, + transport=context.timer_race_transport, + ) + + +@given("the timer race client is marked as shutting down") +def step_mark_timer_race_client_shutting_down(context: Context) -> None: + """Simulate the shutdown window before timer scheduling is attempted.""" + context.timer_race_client._shutting_down = True + + +@given("cancellation of existing timers begins shutdown") +def step_existing_timer_cancellation_begins_shutdown(context: Context) -> None: + """Install cancel probes that flip shutdown after the scheduler's first guard.""" + client = context.timer_race_client + context.timer_race_idle_cancel_probe = _ShutdownOnCancelTimer(client) + context.timer_race_health_cancel_probe = _ShutdownOnCancelTimer(client) + with client._lock: + client._idle_timer = context.timer_race_idle_cancel_probe + client._health_timer = context.timer_race_health_cancel_probe + client._shutting_down = False + + +# ── When ────────────────────────────────────────────────────────── + + +@when("I start the client") +def step_start_client(context: Context) -> None: + """Start the McpClient, which triggers idle timer scheduling.""" + context.timer_race_client.start() + + +@when("I trigger the idle timer race by forcing a reschedule during shutdown") +def step_trigger_timer_race(context: Context) -> None: + """Trigger the timer-cancel race and detect if it causes a late fire. + + This step uses a simple concurrent approach: + 1. Start the client (which schedules an idle timer). + 2. Wait a tiny bit so the timer is definitely scheduled. + 3. Launch two threads: one that repeatedly schedules the idle timer, + and one that calls shutdown. + 4. Wait for threads to complete and for any late timer fires. + 5. Check if _check_idle was called after shutdown. + + We avoid complex barriers and instead use simple timing-based + coordination. The race window is hit through sheer concurrency + combined with the 50ms idle timeout. + """ + client = context.timer_race_client + callback_lock = context.timer_race_callback_lock + + # ── Patch _check_idle to detect late fires ────────────────────── + original_check_idle = client._check_idle + + def patched_check_idle() -> None: + is_shutting = client._shutting_down + state = client.state + with callback_lock: + if is_shutting or state in ("stopping", "stopped"): + context.timer_race_callback_fired = True + original_check_idle() + + client._check_idle = patched_check_idle + + try: + # Wait for initial timer to be scheduled + original_sleep = getattr(time, "_original_sleep", time.sleep) + original_sleep(0.1) + + for _iteration in range(5): + # Reset flag for this iteration + with callback_lock: + context.timer_race_callback_fired = False + + # Ensure client is in running state + if client.state not in ("running",): + from contextlib import suppress as _suppress + + client._started = False + client._shutting_down = False + client._state = "idle" + with _suppress(Exception): + client._adapter.connect() + client._adapter.discover_tools() + client._started = True + client._state = "running" + client._last_activity = time.monotonic() + + # Launch concurrent schedule + shutdown threads + from contextlib import suppress + + def schedule_repeatedly() -> None: + for _j in range(50): + if client.state not in ("running",): + break + with suppress(Exception): + client._schedule_idle_timer() + # Very small sleep to allow other threads to run + time.sleep(0.001) + + def shutdown_repeatedly() -> None: + from contextlib import suppress + + for _j in range(50): + if client.state not in ("running",): + break + with suppress(Exception): + client.shutdown() + # Re-start for next iteration + client._started = False + client._shutting_down = False + client._state = "idle" + with suppress(Exception): + client._adapter.connect() + client._adapter.discover_tools() + client._started = True + client._state = "running" + client._last_activity = time.monotonic() + time.sleep(0.001) + + t1 = threading.Thread(target=schedule_repeatedly, daemon=True) + t2 = threading.Thread(target=shutdown_repeatedly, daemon=True) + + t1.start() + t2.start() + + t1.join(timeout=5) + t2.join(timeout=5) + + # Small wait to let any late fires manifest + original_sleep(0.1) + + if context.timer_race_callback_fired: + # Race detected — stop early + break + + finally: + # Restore original _check_idle + client._check_idle = original_check_idle + + +@when("I wait long enough for any late timer fires (0.3s)") +def step_wait_for_late_fires(context: Context) -> None: + """Wait 300ms to allow any timer callbacks that might race to fire.""" + original_sleep = getattr(time, "_original_sleep", time.sleep) + original_sleep(0.3) + + +@when("I ask the client to schedule idle and health timers") +def step_schedule_idle_and_health_timers(context: Context) -> None: + """Invoke both scheduler guards while shutdown is in progress.""" + client = context.timer_race_client + client._schedule_idle_timer() + if hasattr(context, "timer_race_health_cancel_probe"): + with client._lock: + client._shutting_down = False + client._schedule_health_check() + + +# ── Then ────────────────────────────────────────────────────────── + + +@then("the idle timer callback should not have fired after shutdown") +def step_idle_callback_not_fired_after_shutdown(context: Context) -> None: + """Assert that _check_idle() did NOT fire after shutdown was called. + + With the bug present (timer.start() called outside the lock in + _schedule_idle_timer()), the race can cause the timer to fire even + though shutdown() was called and _cancel_idle_timer() was invoked. + + This assertion FAILS while the bug exists (expected for + @tdd_expected_fail), and will PASS once the bug is fixed by moving + timer.start() inside the lock or otherwise preventing the race. + """ + assert not context.timer_race_callback_fired, ( + "The idle timer callback (_check_idle) fired after shutdown() was " + "called. This confirms the race condition in _schedule_idle_timer() " + "where timer.start() is called outside the lock, allowing a " + "timer to fire even after shutdown() has called _cancel_idle_timer(). " + "The fix should move timer.start() inside the lock or use a " + "different synchronisation scheme to prevent the race. " + f"Errors (if any): {getattr(context, 'timer_race_errors', [])}" + ) + + +@then("no idle or health timer should be scheduled") +def step_no_idle_or_health_timer_scheduled(context: Context) -> None: + """Assert shutdown guards returned before installing timers.""" + client = context.timer_race_client + assert client._idle_timer is None, "Idle timer was scheduled during shutdown" + assert client._health_timer is None, "Health timer was scheduled during shutdown" + + +@then("cancellation should have been observed for both timers") +def step_cancellation_observed_for_both_timers(context: Context) -> None: + """Assert both scheduler paths reached the cancellation probe.""" + assert context.timer_race_idle_cancel_probe.cancel_called, ( + "Idle timer cancellation probe was not reached" + ) + assert context.timer_race_health_cancel_probe.cancel_called, ( + "Health timer cancellation probe was not reached" + ) diff --git a/features/tdd_mcp_client_timer_cancel_race.feature b/features/tdd_mcp_client_timer_cancel_race.feature new file mode 100644 index 000000000..09e7dc997 --- /dev/null +++ b/features/tdd_mcp_client_timer_cancel_race.feature @@ -0,0 +1,91 @@ +# This test captures bug issue #10516 — McpClient idle/health timer can fire +# after cancellation due to a race condition in _schedule_idle_timer() and +# _schedule_health_check(). +# +# Both scheduling methods follow this pattern: +# with self._lock: +# timer = threading.Timer(...) +# self._X_timer = timer +# timer.start() ← OUTSIDE the lock — race window! +# +# Race scenario: +# 1. Thread A: creates timer, stores in self._X_timer, releases lock +# 2. Thread B: calls shutdown() → _cancel_X_timer() acquires lock, +# calls timer.cancel(), sets self._X_timer = None, releases lock +# 3. Thread A: calls timer.start() — if this happens AFTER step 2's +# cancel, the Timer.cancel() internal flag is already set and the +# callback will NOT fire (Python 3.x behaviour). +# +# However, there is a variant of this race that CAN cause the callback +# to fire after shutdown: +# - If Thread B's cancel() is interrupted (e.g. by a signal or GIL +# preemption) AFTER cancel() is called but BEFORE the lock is +# re-acquired to set self._X_timer = None +# - Thread A can see the non-None self._X_timer (still not None) +# and call timer.start() on a timer that was already cancelled. +# - In Python 3.x Timer.cancel() sets _was_cancelled=True but does NOT +# prevent a subsequent start() from being called. +# +# The @tdd_expected_fail tag inverts the test result: the underlying +# assertion fails (proving the bug exists) but CI reports the scenario +# as passed. When the bug is fixed, the @tdd_expected_fail tag must be +# removed. +# +# See: https://git.cleverthis.com/cleveragents/cleveragents-core/issues/10516 + +@tdd_issue @tdd_issue_10516 +Feature: TDD Issue #10516 — McpClient timer can fire after cancellation race + The idle timer and health-check timer in McpClient can fire after + shutdown() has been called because timer.start() is called outside + the lock in _schedule_idle_timer() and _schedule_health_check(). + + This means there is a race window where: + - Thread A is in _schedule_idle_timer(), has stored the Timer in + self._idle_timer and released the lock, but has not yet called + timer.start() + - Thread B calls shutdown(), which calls _cancel_idle_timer(), which + acquires the lock, calls timer.cancel(), but may not yet have set + self._idle_timer = None when Thread A calls timer.start() + - If the timer is started AFTER cancel() was called but before + self._idle_timer was nulled, the Timer's internal cancelled flag + is set but start() was still invoked — in Python 3.x this means + the callback does NOT fire. + - HOWEVER: in the variant race where Thread B is descheduled AFTER + calling cancel() but BEFORE nulling self._idle_timer, Thread A can + re-enter _schedule_idle_timer() from within _check_idle (during the + reschedule path) and overwrite self._idle_timer with a new Timer + that has not been cancelled. This new timer then starts and can + fire AFTER shutdown() has set _shutting_down=True. + + The test proves the race by: + 1. Starting a client with a very short idle timeout + 2. Forcing the idle timer to fire by waiting + 3. While _check_idle is in the reschedule path (inside _lock, setting + self._idle_timer to a new Timer but before timer.start() is called), + another thread calls shutdown() + 4. shutdown() calls _cancel_idle_timer() which cancels the in-flight + Timer and sets self._idle_timer = None + 5. The original thread's timer.start() was already called before + shutdown's cancel, so the timer fires even though _shutting_down=True + + Scenario: Idle timer must not fire after shutdown is called + Given an McpClient with a very short idle timeout (0.05s) + And a mock transport with one tool + And a shared flag to detect if the idle callback fired after shutdown + When I start the client + And I trigger the idle timer race by forcing a reschedule during shutdown + And I wait long enough for any late timer fires (0.3s) + Then the idle timer callback should not have fired after shutdown + + Scenario: Timer schedulers skip work during shutdown + Given an McpClient with active idle and health timers + And the timer race client is marked as shutting down + When I ask the client to schedule idle and health timers + Then no idle or health timer should be scheduled + + Scenario: Timer schedulers recheck shutdown after cancellation + Given an McpClient with active idle and health timers + And cancellation of existing timers begins shutdown + When I ask the client to schedule idle and health timers + Then cancellation should have been observed for both timers + And no idle or health timer should be scheduled diff --git a/src/cleveragents/mcp/client.py b/src/cleveragents/mcp/client.py index cf3b503af..c83146e08 100644 --- a/src/cleveragents/mcp/client.py +++ b/src/cleveragents/mcp/client.py @@ -327,17 +327,21 @@ class McpClient: def _schedule_idle_timer(self) -> None: """Schedule the idle auto-stop timer.""" - self._cancel_idle_timer() - timeout = self._config.idle_timeout_seconds - if timeout <= 0: - return - with self._lock: + if self._shutting_down: + return + if self._idle_timer is not None: + self._idle_timer.cancel() + self._idle_timer = None + if self._shutting_down: + return + timeout = self._config.idle_timeout_seconds + if timeout <= 0: + return timer = threading.Timer(timeout, self._check_idle) timer.daemon = True self._idle_timer = timer - - timer.start() + timer.start() def _cancel_idle_timer(self) -> None: """Cancel any pending idle timer.""" @@ -372,17 +376,21 @@ class McpClient: def _schedule_health_check(self) -> None: """Schedule the next health-check timer.""" - self._cancel_health_check() - interval = self._config.health_check_interval_seconds - if interval <= 0: - return - with self._lock: + if self._shutting_down: + return + if self._health_timer is not None: + self._health_timer.cancel() + self._health_timer = None + if self._shutting_down: + return + interval = self._config.health_check_interval_seconds + if interval <= 0: + return timer = threading.Timer(interval, self._perform_health_check) timer.daemon = True self._health_timer = timer - - timer.start() + timer.start() def _cancel_health_check(self) -> None: """Cancel any pending health-check timer."""