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"
+    )

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

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."""