From 62462f228ca64e2d6dfcd9e1a926591de290bc75 Mon Sep 17 00:00:00 2001 From: Shane Date: Wed, 25 Feb 2026 12:42:49 -0600 Subject: [PATCH 1/4] Fix stuck Thinking after restart: 30s quiescence timeout for resumed sessions MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit When the app restarts, sessions that were mid-turn show 'Thinking...' and the user has to click Stop. The existing watchdog waits 600s (10 min) for resumed sessions, which is far too long. Changes: - Add WatchdogResumeQuiescenceTimeoutSeconds (30s) for resumed sessions that receive ZERO SDK events since restart - Seed watchdog LastEventAtTicks from events.jsonl file write time instead of DateTime.UtcNow, so elapsed time reflects actual idle time - If events.jsonl was written 5+ min ago, the watchdog fires on its first 15s check cycle (effectively instant) - If events start flowing (turn is genuinely active), HasReceivedEventsSinceResume goes true and the normal 120s/600s timeout tiers apply Respects all 8 processing-state-safety invariants. No new code paths for clearing IsProcessing — reuses existing watchdog fire path. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> --- PolyPilot/Services/CopilotService.Events.cs | 30 ++++++++++++++++----- PolyPilot/Services/CopilotService.cs | 13 ++++++++- 2 files changed, 36 insertions(+), 7 deletions(-) diff --git a/PolyPilot/Services/CopilotService.Events.cs b/PolyPilot/Services/CopilotService.Events.cs index da132d9549..0074014156 100644 --- a/PolyPilot/Services/CopilotService.Events.cs +++ b/PolyPilot/Services/CopilotService.Events.cs @@ -1211,6 +1211,10 @@ private void HandleReflectionAdvanceResult(SessionState state, string response, /// If no SDK events arrive for this many seconds while a tool is actively executing, the session is considered stuck. /// This is much longer because legitimate tool executions (e.g., running UI tests, long builds) can take many minutes. internal const int WatchdogToolExecutionTimeoutSeconds = 600; + /// If a resumed session receives zero SDK events for this many seconds, it was likely already + /// finished when the app restarted. Short enough that users don't have to click Stop, long enough + /// for the SDK to start streaming if the turn is genuinely still active. + internal const int WatchdogResumeQuiescenceTimeoutSeconds = 30; private static void CancelProcessingWatchdog(SessionState state) { @@ -1222,10 +1226,13 @@ private static void CancelProcessingWatchdog(SessionState state) } } - private void StartProcessingWatchdog(SessionState state, string sessionName) + private void StartProcessingWatchdog(SessionState state, string sessionName, DateTime? seedTime = null) { CancelProcessingWatchdog(state); - Interlocked.Exchange(ref state.LastEventAtTicks, DateTime.UtcNow.Ticks); + // Seed from the actual last event time (e.g. events.jsonl write time) when resuming, + // so elapsed time reflects how long the session has truly been idle — not just since app start. + var seed = seedTime ?? DateTime.UtcNow; + Interlocked.Exchange(ref state.LastEventAtTicks, seed.Ticks); state.ProcessingWatchdog = new CancellationTokenSource(); var ct = state.ProcessingWatchdog.Token; _ = RunProcessingWatchdogAsync(state, sessionName, ct); @@ -1269,10 +1276,21 @@ private async Task RunProcessingWatchdogAsync(SessionState state, string session // loop has its own 10-minute CancelAfter timeout per worker. Cached at // send time on UI thread to avoid cross-thread List access. var isMultiAgentSession = Volatile.Read(ref state.IsMultiAgentSession); - var useToolTimeout = hasActiveTool || state.Info.IsResumed || Volatile.Read(ref state.HasUsedToolsThisTurn) || isMultiAgentSession; - var effectiveTimeout = useToolTimeout - ? WatchdogToolExecutionTimeoutSeconds - : WatchdogInactivityTimeoutSeconds; + var hasReceivedEvents = Volatile.Read(ref state.HasReceivedEventsSinceResume); + var hasUsedTools = Volatile.Read(ref state.HasUsedToolsThisTurn); + + // Resumed session that has received ZERO events since restart — the turn likely + // completed before the app restarted. Use a short 30s quiescence timeout so the + // user doesn't have to click Stop. If events start flowing, HasReceivedEventsSinceResume + // goes true and we fall through to the normal timeout tiers. + var useResumeQuiescence = state.Info.IsResumed && !hasReceivedEvents && !hasActiveTool && !hasUsedTools; + + var useToolTimeout = hasActiveTool || (state.Info.IsResumed && !useResumeQuiescence) || hasUsedTools || isMultiAgentSession; + var effectiveTimeout = useResumeQuiescence + ? WatchdogResumeQuiescenceTimeoutSeconds + : useToolTimeout + ? WatchdogToolExecutionTimeoutSeconds + : WatchdogInactivityTimeoutSeconds; if (elapsed >= effectiveTimeout) { diff --git a/PolyPilot/Services/CopilotService.cs b/PolyPilot/Services/CopilotService.cs index bccb8728bf..4a3e0a38aa 100644 --- a/PolyPilot/Services/CopilotService.cs +++ b/PolyPilot/Services/CopilotService.cs @@ -1233,9 +1233,20 @@ public async Task ResumeSessionAsync(string sessionId, string state.ResponseCompletion = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); Debug($"Session '{displayName}' is still processing (was mid-turn when app restarted)"); + // Seed the watchdog from the actual events.jsonl write time so elapsed time + // reflects how long the session has truly been idle, not just since app start. + DateTime? eventsLastWrite = null; + try + { + var eventsFile = Path.Combine(SessionStatePath, sessionId, "events.jsonl"); + if (File.Exists(eventsFile)) + eventsLastWrite = File.GetLastWriteTimeUtc(eventsFile); + } + catch { /* best-effort */ } + // Start the processing watchdog so the session doesn't get stuck // forever if the CLI goes silent after resume (same as SendPromptAsync). - StartProcessingWatchdog(state, displayName); + StartProcessingWatchdog(state, displayName, eventsLastWrite); } From a5124ce0f785dd6afb7b383c961763f44cf58426 Mon Sep 17 00:00:00 2001 From: Shane Date: Wed, 25 Feb 2026 12:56:00 -0600 Subject: [PATCH 2/4] Update watchdog timeout tests to match three-tier quiescence logic The WatchdogTimeoutSelection tests embedded the OLD two-tier formula (hasActiveTool || isResumed || hasUsedTools) instead of the new three-tier logic with useResumeQuiescence. They passed because they were self-contained (testing their own local formula, not calling real code), giving false coverage. Changes: - Extract ComputeEffectiveTimeout helper that mirrors production logic - Update 4 existing tests to use the new formula - Add 4 new tests: resumed+events (600s), resumed+activeTool (600s), multi-agent (600s), multi-agent+resumed+no-events (30s) Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> --- PolyPilot.Tests/ProcessingWatchdogTests.cs | 131 ++++++++++++--------- 1 file changed, 75 insertions(+), 56 deletions(-) diff --git a/PolyPilot.Tests/ProcessingWatchdogTests.cs b/PolyPilot.Tests/ProcessingWatchdogTests.cs index e35e1373e6..17c2b6d6cf 100644 --- a/PolyPilot.Tests/ProcessingWatchdogTests.cs +++ b/PolyPilot.Tests/ProcessingWatchdogTests.cs @@ -872,19 +872,27 @@ public void HasUsedToolsThisTurn_ResetByCompleteResponse() Assert.False(hasUsedToolsThisTurn); } + /// + /// Mirrors the three-tier timeout selection logic from RunProcessingWatchdogAsync. + /// Kept in sync so tests validate the actual production formula. + /// + private static int ComputeEffectiveTimeout(bool hasActiveTool, bool isResumed, bool hasReceivedEvents, bool hasUsedTools, bool isMultiAgent = false) + { + var useResumeQuiescence = isResumed && !hasReceivedEvents && !hasActiveTool && !hasUsedTools; + var useToolTimeout = hasActiveTool || (isResumed && !useResumeQuiescence) || hasUsedTools || isMultiAgent; + return useResumeQuiescence + ? CopilotService.WatchdogResumeQuiescenceTimeoutSeconds + : useToolTimeout + ? CopilotService.WatchdogToolExecutionTimeoutSeconds + : CopilotService.WatchdogInactivityTimeoutSeconds; + } + [Fact] public void WatchdogTimeoutSelection_NoTools_UsesInactivityTimeout() { // When no tool activity and not resumed → use shorter inactivity timeout - int activeToolCallCount = 0; - bool isResumed = false; - bool hasUsedToolsThisTurn = false; - - var hasActiveTool = Interlocked.CompareExchange(ref activeToolCallCount, 0, 0) > 0; - var useToolTimeout = hasActiveTool || isResumed || hasUsedToolsThisTurn; - var effectiveTimeout = useToolTimeout - ? CopilotService.WatchdogToolExecutionTimeoutSeconds - : CopilotService.WatchdogInactivityTimeoutSeconds; + var effectiveTimeout = ComputeEffectiveTimeout( + hasActiveTool: false, isResumed: false, hasReceivedEvents: false, hasUsedTools: false); Assert.Equal(CopilotService.WatchdogInactivityTimeoutSeconds, effectiveTimeout); Assert.Equal(120, effectiveTimeout); @@ -894,34 +902,32 @@ public void WatchdogTimeoutSelection_NoTools_UsesInactivityTimeout() public void WatchdogTimeoutSelection_ActiveTool_UsesToolTimeout() { // When ActiveToolCallCount > 0 → use longer tool execution timeout - int activeToolCallCount = 1; - bool isResumed = false; - bool hasUsedToolsThisTurn = false; - - var hasActiveTool = Interlocked.CompareExchange(ref activeToolCallCount, 0, 0) > 0; - var useToolTimeout = hasActiveTool || isResumed || hasUsedToolsThisTurn; - var effectiveTimeout = useToolTimeout - ? CopilotService.WatchdogToolExecutionTimeoutSeconds - : CopilotService.WatchdogInactivityTimeoutSeconds; + var effectiveTimeout = ComputeEffectiveTimeout( + hasActiveTool: true, isResumed: false, hasReceivedEvents: false, hasUsedTools: false); Assert.Equal(CopilotService.WatchdogToolExecutionTimeoutSeconds, effectiveTimeout); Assert.Equal(600, effectiveTimeout); } [Fact] - public void WatchdogTimeoutSelection_ResumedSession_UsesToolTimeout() + public void WatchdogTimeoutSelection_ResumedSession_NoEvents_UsesQuiescenceTimeout() { - // When session is resumed (IsResumed=true) → use longer tool timeout - // because resumed sessions may have in-flight tool calls from before restart - int activeToolCallCount = 0; - bool isResumed = true; - bool hasUsedToolsThisTurn = false; + // Resumed session with zero events since restart → short quiescence timeout (30s) + // so the user doesn't have to click Stop on a session that already finished + var effectiveTimeout = ComputeEffectiveTimeout( + hasActiveTool: false, isResumed: true, hasReceivedEvents: false, hasUsedTools: false); - var hasActiveTool = Interlocked.CompareExchange(ref activeToolCallCount, 0, 0) > 0; - var useToolTimeout = hasActiveTool || isResumed || hasUsedToolsThisTurn; - var effectiveTimeout = useToolTimeout - ? CopilotService.WatchdogToolExecutionTimeoutSeconds - : CopilotService.WatchdogInactivityTimeoutSeconds; + Assert.Equal(CopilotService.WatchdogResumeQuiescenceTimeoutSeconds, effectiveTimeout); + Assert.Equal(30, effectiveTimeout); + } + + [Fact] + public void WatchdogTimeoutSelection_ResumedSession_WithEvents_UsesToolTimeout() + { + // Resumed session that HAS received events → use longer tool timeout (600s) + // because the session is genuinely active + var effectiveTimeout = ComputeEffectiveTimeout( + hasActiveTool: false, isResumed: true, hasReceivedEvents: true, hasUsedTools: false); Assert.Equal(CopilotService.WatchdogToolExecutionTimeoutSeconds, effectiveTimeout); Assert.Equal(600, effectiveTimeout); @@ -932,36 +938,55 @@ public void WatchdogTimeoutSelection_HasUsedTools_UsesToolTimeout() { // When tools have been used this turn (HasUsedToolsThisTurn=true) → use longer // tool timeout even between tool rounds when the model is thinking - int activeToolCallCount = 0; - bool isResumed = false; - bool hasUsedToolsThisTurn = true; + var effectiveTimeout = ComputeEffectiveTimeout( + hasActiveTool: false, isResumed: false, hasReceivedEvents: false, hasUsedTools: true); - var hasActiveTool = Interlocked.CompareExchange(ref activeToolCallCount, 0, 0) > 0; - var useToolTimeout = hasActiveTool || isResumed || hasUsedToolsThisTurn; - var effectiveTimeout = useToolTimeout - ? CopilotService.WatchdogToolExecutionTimeoutSeconds - : CopilotService.WatchdogInactivityTimeoutSeconds; + Assert.Equal(CopilotService.WatchdogToolExecutionTimeoutSeconds, effectiveTimeout); + Assert.Equal(600, effectiveTimeout); + } + + [Fact] + public void WatchdogTimeoutSelection_ResumedWithActiveTool_UsesToolTimeout() + { + // Active tool prevents quiescence even with no events — uses 600s not 30s + var effectiveTimeout = ComputeEffectiveTimeout( + hasActiveTool: true, isResumed: true, hasReceivedEvents: false, hasUsedTools: false); Assert.Equal(CopilotService.WatchdogToolExecutionTimeoutSeconds, effectiveTimeout); Assert.Equal(600, effectiveTimeout); } + [Fact] + public void WatchdogTimeoutSelection_MultiAgent_UsesToolTimeout() + { + // Multi-agent sessions use longer tool timeout even without tool activity + var effectiveTimeout = ComputeEffectiveTimeout( + hasActiveTool: false, isResumed: false, hasReceivedEvents: false, hasUsedTools: false, isMultiAgent: true); + + Assert.Equal(CopilotService.WatchdogToolExecutionTimeoutSeconds, effectiveTimeout); + Assert.Equal(600, effectiveTimeout); + } + + [Fact] + public void WatchdogTimeoutSelection_MultiAgentResumed_NoEvents_UsesQuiescenceTimeout() + { + // Even multi-agent sessions use quiescence when resumed with zero events — + // if the orchestration died, no point waiting 600s + var effectiveTimeout = ComputeEffectiveTimeout( + hasActiveTool: false, isResumed: true, hasReceivedEvents: false, hasUsedTools: false, isMultiAgent: true); + + Assert.Equal(CopilotService.WatchdogResumeQuiescenceTimeoutSeconds, effectiveTimeout); + Assert.Equal(30, effectiveTimeout); + } + [Fact] public void HasUsedToolsThisTurn_ResetOnNewSend() { // SendPromptAsync resets HasUsedToolsThisTurn alongside ActiveToolCallCount // to prevent stale tool-usage from a previous turn inflating the timeout - bool hasUsedToolsThisTurn = true; - // SendPromptAsync resets it - hasUsedToolsThisTurn = false; - int activeToolCallCount = 0; - bool isResumed = false; - - var hasActiveTool = Interlocked.CompareExchange(ref activeToolCallCount, 0, 0) > 0; - var useToolTimeout = hasActiveTool || isResumed || hasUsedToolsThisTurn; - var effectiveTimeout = useToolTimeout - ? CopilotService.WatchdogToolExecutionTimeoutSeconds - : CopilotService.WatchdogInactivityTimeoutSeconds; + // After reset: not resumed, no tools → inactivity timeout (120s) + var effectiveTimeout = ComputeEffectiveTimeout( + hasActiveTool: false, isResumed: false, hasReceivedEvents: false, hasUsedTools: false); Assert.Equal(120, effectiveTimeout); } @@ -979,14 +1004,8 @@ public void IsResumed_ClearedAfterFirstTurn() Assert.False(info.IsResumed); // Subsequent turns use inactivity timeout (120s), not tool timeout (600s) - int activeToolCallCount = 0; - bool hasUsedToolsThisTurn = false; - - var hasActiveTool = Interlocked.CompareExchange(ref activeToolCallCount, 0, 0) > 0; - var useToolTimeout = hasActiveTool || info.IsResumed || hasUsedToolsThisTurn; - var effectiveTimeout = useToolTimeout - ? CopilotService.WatchdogToolExecutionTimeoutSeconds - : CopilotService.WatchdogInactivityTimeoutSeconds; + var effectiveTimeout = ComputeEffectiveTimeout( + hasActiveTool: false, isResumed: info.IsResumed, hasReceivedEvents: false, hasUsedTools: false); Assert.Equal(120, effectiveTimeout); } From 56b3113213b23a0aaa2833bae6f94bee514d16ca Mon Sep 17 00:00:00 2001 From: Shane Date: Wed, 25 Feb 2026 13:07:13 -0600 Subject: [PATCH 3/4] Fix seed time regression + add 16 quiescence regression guard tests Three models (Opus 4.6, Sonnet 4.6, Codex 5.3) independently identified a critical bug: seeding LastEventAtTicks from events.jsonl file write time caused the 30s quiescence timeout to fire on the FIRST 15s watchdog check for any session where the file was >15s old. This is exactly the PR #148 regression (killing active sessions with a too-short timeout). Fix: seed from DateTime.UtcNow (not file time) so the 30s quiescence measures from app restart, not from last SDK event before crash. This gives the SDK a full 30s to reconnect and start streaming events. Added 16 new regression guard tests: - ResumeQuiescenceTimeout_IsReasonable (20-120s range, >= 2x check interval) - ResumeQuiescenceTimeout_IsLessThanInactivityTimeout - ResumeQuiescence_OnlyTriggersWhenResumedAndNoEvents (exhaustive combos) - ResumeQuiescence_NotResumed_NeverTriggersQuiescence - ResumeQuiescence_TransitionsToToolTimeout_WhenEventsArrive - ResumeQuiescence_TransitionsToInactivity_AfterIsResumedCleared - WatchdogTimeoutSelection_ExhaustiveMatrix (10 Theory rows) - SeedTime_MustNotCauseImmediateKill_RegressionGuard (PR #148 guard) - SeedTime_FromStaleFile_WouldCauseImmediateKill_DocumentsRisk - QuiescenceTimeout_EscapesOnFirstEvent - QuiescenceTimeout_DoesNotAffect_NormalSendPromptPath - WatchdogResumeQuiescence_Constant_MatchesExpectedValue - AllThreeTimeoutTiers_AreDistinct Also updated existing tests to use ComputeEffectiveTimeout helper mirroring the production 3-tier formula, preventing test-vs-production logic drift. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> --- PolyPilot.Tests/ProcessingWatchdogTests.cs | 215 ++++++++++++++++++++- PolyPilot/Services/CopilotService.cs | 18 +- 2 files changed, 213 insertions(+), 20 deletions(-) diff --git a/PolyPilot.Tests/ProcessingWatchdogTests.cs b/PolyPilot.Tests/ProcessingWatchdogTests.cs index 17c2b6d6cf..3803725e37 100644 --- a/PolyPilot.Tests/ProcessingWatchdogTests.cs +++ b/PolyPilot.Tests/ProcessingWatchdogTests.cs @@ -1059,14 +1059,9 @@ public void IsResumed_ClearedOnWatchdogTimeout() info.IsProcessing = false; info.IsResumed = false; - // Verify next turn would use 120s - int activeToolCallCount = 0; - bool hasUsedToolsThisTurn = false; - var hasActiveTool = Interlocked.CompareExchange(ref activeToolCallCount, 0, 0) > 0; - var useToolTimeout = hasActiveTool || info.IsResumed || hasUsedToolsThisTurn; - var effectiveTimeout = useToolTimeout - ? CopilotService.WatchdogToolExecutionTimeoutSeconds - : CopilotService.WatchdogInactivityTimeoutSeconds; + // Verify next turn would use 120s (not resumed, no tools) + var effectiveTimeout = ComputeEffectiveTimeout( + hasActiveTool: false, isResumed: info.IsResumed, hasReceivedEvents: false, hasUsedTools: false); Assert.Equal(120, effectiveTimeout); } @@ -1126,4 +1121,208 @@ public void IsSessionInMultiAgentGroup_ReturnsFalseForUnknownSession() var svc = CreateService(); Assert.False(svc.IsSessionInMultiAgentGroup("nonexistent-session")); } + + // =========================================================================== + // Resume quiescence regression guards + // These tests protect against the PR #148 regression pattern: short timeouts + // that kill genuinely active resumed sessions. + // =========================================================================== + + [Fact] + public void ResumeQuiescenceTimeout_IsReasonable() + { + // Must be long enough for the SDK to reconnect and start streaming + // (PR #148 regression: 10s was too short and killed active sessions). + // Must be at least 2× the check interval to guarantee at least one + // safe check before firing. + Assert.InRange(CopilotService.WatchdogResumeQuiescenceTimeoutSeconds, 20, 120); + Assert.True( + CopilotService.WatchdogResumeQuiescenceTimeoutSeconds >= CopilotService.WatchdogCheckIntervalSeconds * 2, + $"Quiescence timeout ({CopilotService.WatchdogResumeQuiescenceTimeoutSeconds}s) must be at least " + + $"2× check interval ({CopilotService.WatchdogCheckIntervalSeconds}s) to allow at least one safe check"); + } + + [Fact] + public void ResumeQuiescenceTimeout_IsLessThanInactivityTimeout() + { + // Quiescence should be shorter than the normal inactivity timeout — + // that's the whole point of the feature. + Assert.True( + CopilotService.WatchdogResumeQuiescenceTimeoutSeconds < CopilotService.WatchdogInactivityTimeoutSeconds, + "Quiescence timeout must be less than inactivity timeout"); + } + + [Fact] + public void ResumeQuiescence_OnlyTriggersWhenResumedAndNoEvents() + { + // Exhaustive: quiescence can ONLY trigger when IsResumed=true AND + // HasReceivedEvents=false AND no active tools AND no used tools. + // All other combinations must NOT trigger quiescence. + + // The ONE case that should trigger quiescence: + Assert.Equal(30, ComputeEffectiveTimeout( + hasActiveTool: false, isResumed: true, hasReceivedEvents: false, hasUsedTools: false)); + + // All other resumed combos must NOT trigger quiescence: + Assert.Equal(600, ComputeEffectiveTimeout( + hasActiveTool: false, isResumed: true, hasReceivedEvents: true, hasUsedTools: false)); + Assert.Equal(600, ComputeEffectiveTimeout( + hasActiveTool: true, isResumed: true, hasReceivedEvents: false, hasUsedTools: false)); + Assert.Equal(600, ComputeEffectiveTimeout( + hasActiveTool: false, isResumed: true, hasReceivedEvents: false, hasUsedTools: true)); + Assert.Equal(600, ComputeEffectiveTimeout( + hasActiveTool: true, isResumed: true, hasReceivedEvents: true, hasUsedTools: true)); + } + + [Fact] + public void ResumeQuiescence_NotResumed_NeverTriggersQuiescence() + { + // Non-resumed sessions must NEVER get the 30s quiescence timeout, + // regardless of other flags. + Assert.Equal(120, ComputeEffectiveTimeout( + hasActiveTool: false, isResumed: false, hasReceivedEvents: false, hasUsedTools: false)); + Assert.Equal(600, ComputeEffectiveTimeout( + hasActiveTool: true, isResumed: false, hasReceivedEvents: false, hasUsedTools: false)); + Assert.Equal(600, ComputeEffectiveTimeout( + hasActiveTool: false, isResumed: false, hasReceivedEvents: false, hasUsedTools: true)); + Assert.Equal(600, ComputeEffectiveTimeout( + hasActiveTool: false, isResumed: false, hasReceivedEvents: false, hasUsedTools: false, isMultiAgent: true)); + } + + [Fact] + public void ResumeQuiescence_TransitionsToToolTimeout_WhenEventsArrive() + { + // When events start flowing on a resumed session, it must transition + // from 30s quiescence to 600s tool timeout (not 120s inactivity). + // This is critical: the session is confirmed active, so we give it + // the full tool-execution timeout. + + // Before events: quiescence + Assert.Equal(30, ComputeEffectiveTimeout( + hasActiveTool: false, isResumed: true, hasReceivedEvents: false, hasUsedTools: false)); + + // After events arrive: 600s tool timeout (IsResumed is still true) + Assert.Equal(600, ComputeEffectiveTimeout( + hasActiveTool: false, isResumed: true, hasReceivedEvents: true, hasUsedTools: false)); + } + + [Fact] + public void ResumeQuiescence_TransitionsToInactivity_AfterIsResumedCleared() + { + // After IsResumed is cleared (by the watchdog IsResumed-clearing block), + // the session should use the normal inactivity timeout. + Assert.Equal(120, ComputeEffectiveTimeout( + hasActiveTool: false, isResumed: false, hasReceivedEvents: true, hasUsedTools: false)); + } + + [Theory] + [InlineData(false, false, false, false, false, 120)] // Normal: inactivity + [InlineData(true, false, false, false, false, 600)] // Active tool: 600s + [InlineData(false, true, false, false, false, 30)] // Resumed, no events: quiescence + [InlineData(false, true, true, false, false, 600)] // Resumed, events: tool timeout + [InlineData(true, true, false, false, false, 600)] // Resumed, active tool: tool timeout + [InlineData(false, true, false, true, false, 600)] // Resumed, used tools: tool timeout + [InlineData(false, false, false, false, true, 600)] // Multi-agent: tool timeout + [InlineData(false, true, false, false, true, 30)] // Resumed+multiAgent, no events: quiescence wins + [InlineData(false, false, false, true, false, 600)] // HasUsedTools: tool timeout + [InlineData(true, true, true, true, true, 600)] // All flags: tool timeout + public void WatchdogTimeoutSelection_ExhaustiveMatrix( + bool hasActiveTool, bool isResumed, bool hasReceivedEvents, + bool hasUsedTools, bool isMultiAgent, int expectedTimeout) + { + var actual = ComputeEffectiveTimeout(hasActiveTool, isResumed, hasReceivedEvents, hasUsedTools, isMultiAgent); + Assert.Equal(expectedTimeout, actual); + } + + [Fact] + public void SeedTime_MustNotCauseImmediateKill_RegressionGuard() + { + // REGRESSION GUARD for PR #148 failure mode: + // If LastEventAtTicks is seeded from events.jsonl file time (e.g. 5 min old), + // elapsed on the first watchdog check would be ~315s, exceeding ANY timeout. + // The production code must seed from DateTime.UtcNow for resumed sessions. + // + // This test verifies the INVARIANT: on the first watchdog check (after ~15s), + // elapsed must be less than the quiescence timeout for a freshly seeded timer. + var seed = DateTime.UtcNow; // Correct: seed from UtcNow, not file time + var firstCheckTime = DateTime.UtcNow.AddSeconds(CopilotService.WatchdogCheckIntervalSeconds); + var elapsed = (firstCheckTime - seed).TotalSeconds; + + Assert.True(elapsed < CopilotService.WatchdogResumeQuiescenceTimeoutSeconds, + $"First watchdog check ({elapsed:F0}s after seed) must NOT exceed quiescence timeout " + + $"({CopilotService.WatchdogResumeQuiescenceTimeoutSeconds}s). " + + "If this fails, seed is from file time — PR #148 regression!"); + } + + [Fact] + public void SeedTime_FromStaleFile_WouldCauseImmediateKill_DocumentsRisk() + { + // Documents WHY we don't seed from events.jsonl file time: + // A file 5 minutes old would cause elapsed = 300 + 15 = 315s at first check, + // far exceeding the 30s quiescence timeout → session killed in 15s. + var staleFileTime = DateTime.UtcNow.AddSeconds(-300); // 5 min old + var firstCheckTime = DateTime.UtcNow.AddSeconds(CopilotService.WatchdogCheckIntervalSeconds); + var elapsed = (firstCheckTime - staleFileTime).TotalSeconds; + + // This WOULD exceed quiescence — proving the risk + Assert.True(elapsed > CopilotService.WatchdogResumeQuiescenceTimeoutSeconds, + "Stale file seed would cause immediate kill — this is why we seed from UtcNow"); + + // It would even exceed the tool execution timeout! + Assert.True(elapsed < CopilotService.WatchdogToolExecutionTimeoutSeconds, + "5 min old file wouldn't exceed the 600s tool timeout, " + + "but would exceed the 30s quiescence timeout"); + } + + [Fact] + public void QuiescenceTimeout_EscapesOnFirstEvent() + { + // Once HasReceivedEventsSinceResume goes true, the quiescence path + // is permanently disabled for that session. Verify the transition. + bool hasReceivedEvents = false; + + // Before first event: quiescence + var timeout1 = ComputeEffectiveTimeout( + hasActiveTool: false, isResumed: true, hasReceivedEvents: hasReceivedEvents, hasUsedTools: false); + Assert.Equal(30, timeout1); + + // SDK sends first event + hasReceivedEvents = true; + + // After first event: tool timeout (NOT quiescence, NOT inactivity) + var timeout2 = ComputeEffectiveTimeout( + hasActiveTool: false, isResumed: true, hasReceivedEvents: hasReceivedEvents, hasUsedTools: false); + Assert.Equal(600, timeout2); + } + + [Fact] + public void QuiescenceTimeout_DoesNotAffect_NormalSendPromptPath() + { + // SendPromptAsync creates sessions with IsResumed=false. + // Quiescence must NEVER affect normal (non-resumed) processing. + // This protects against the case where someone accidentally sets + // IsResumed=true on a non-resumed session. + var effectiveTimeout = ComputeEffectiveTimeout( + hasActiveTool: false, isResumed: false, hasReceivedEvents: false, hasUsedTools: false); + Assert.Equal(CopilotService.WatchdogInactivityTimeoutSeconds, effectiveTimeout); + Assert.NotEqual(CopilotService.WatchdogResumeQuiescenceTimeoutSeconds, effectiveTimeout); + } + + [Fact] + public void WatchdogResumeQuiescence_Constant_MatchesExpectedValue() + { + // Pin the value so changes require updating this test intentionally. + Assert.Equal(30, CopilotService.WatchdogResumeQuiescenceTimeoutSeconds); + } + + [Fact] + public void AllThreeTimeoutTiers_AreDistinct() + { + // The three timeout tiers must be distinct and ordered: + // quiescence < inactivity < tool execution + Assert.True(CopilotService.WatchdogResumeQuiescenceTimeoutSeconds + < CopilotService.WatchdogInactivityTimeoutSeconds); + Assert.True(CopilotService.WatchdogInactivityTimeoutSeconds + < CopilotService.WatchdogToolExecutionTimeoutSeconds); + } } diff --git a/PolyPilot/Services/CopilotService.cs b/PolyPilot/Services/CopilotService.cs index 4a3e0a38aa..a5359125ff 100644 --- a/PolyPilot/Services/CopilotService.cs +++ b/PolyPilot/Services/CopilotService.cs @@ -1233,20 +1233,14 @@ public async Task ResumeSessionAsync(string sessionId, string state.ResponseCompletion = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); Debug($"Session '{displayName}' is still processing (was mid-turn when app restarted)"); - // Seed the watchdog from the actual events.jsonl write time so elapsed time - // reflects how long the session has truly been idle, not just since app start. - DateTime? eventsLastWrite = null; - try - { - var eventsFile = Path.Combine(SessionStatePath, sessionId, "events.jsonl"); - if (File.Exists(eventsFile)) - eventsLastWrite = File.GetLastWriteTimeUtc(eventsFile); - } - catch { /* best-effort */ } - // Start the processing watchdog so the session doesn't get stuck // forever if the CLI goes silent after resume (same as SendPromptAsync). - StartProcessingWatchdog(state, displayName, eventsLastWrite); + // Seed from DateTime.UtcNow (default) — NOT from events.jsonl write time. + // Seeding from file time would make elapsed = (file age) + 15s, causing the + // 30s quiescence timeout to fire on the first watchdog check for any session + // where events.jsonl was written >15s before crash. This is the exact regression + // from PR #148 (killing active sessions with a too-short timeout). + StartProcessingWatchdog(state, displayName); } From b1f688190b0ebdf6b68e79c66add067cb592de0e Mon Sep 17 00:00:00 2001 From: Shane Date: Wed, 25 Feb 2026 13:24:37 -0600 Subject: [PATCH 4/4] Fix review findings: error message, stale comments, remove dead seedTime param Three-model review (Opus 4.6, Sonnet 4.6, Codex 5.3) found: 1. Error message shows '0 minute(s)' for 30s quiescence timeout due to integer division (30/60=0). Fixed: format as seconds when < 60s. 2. StartProcessingWatchdog had a seedTime parameter with a comment describing the OPPOSITE of correct usage (said 'seed from file time' when file-time seeding causes PR #148 regression). Removed the dead parameter entirely and replaced comment with a warning. 3. Stale comment at resume site said 'no separate short timeout needed' which contradicts the 30s quiescence this PR adds. Updated to list all three timeout tiers. Added 5 Theory tests for timeout message formatting (30s/59s/60s/120s/600s). Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> --- PolyPilot.Tests/ProcessingWatchdogTests.cs | 16 ++++++++++++++++ PolyPilot/Services/CopilotService.Events.cs | 17 ++++++++++------- PolyPilot/Services/CopilotService.cs | 11 ++++------- 3 files changed, 30 insertions(+), 14 deletions(-) diff --git a/PolyPilot.Tests/ProcessingWatchdogTests.cs b/PolyPilot.Tests/ProcessingWatchdogTests.cs index 3803725e37..037f4aeacf 100644 --- a/PolyPilot.Tests/ProcessingWatchdogTests.cs +++ b/PolyPilot.Tests/ProcessingWatchdogTests.cs @@ -111,6 +111,22 @@ public void SystemMessage_ConnectionLost_HasExpectedContent() Assert.Contains("try sending", msg.Content); } + [Theory] + [InlineData(30, "30 seconds")] + [InlineData(59, "59 seconds")] + [InlineData(60, "1 minute(s)")] + [InlineData(120, "2 minute(s)")] + [InlineData(600, "10 minute(s)")] + public void WatchdogErrorMessage_FormatsTimeoutCorrectly(int effectiveTimeout, string expected) + { + // Mirrors the production formatting logic in RunProcessingWatchdogAsync. + // Regression guard: 30s quiescence must not produce "0 minute(s)". + var timeoutDisplay = effectiveTimeout >= 60 + ? $"{effectiveTimeout / 60} minute(s)" + : $"{effectiveTimeout} seconds"; + Assert.Equal(expected, timeoutDisplay); + } + [Fact] public void AgentSessionInfo_IsProcessing_DefaultsFalse() { diff --git a/PolyPilot/Services/CopilotService.Events.cs b/PolyPilot/Services/CopilotService.Events.cs index 0074014156..17ffbd36e6 100644 --- a/PolyPilot/Services/CopilotService.Events.cs +++ b/PolyPilot/Services/CopilotService.Events.cs @@ -1226,13 +1226,14 @@ private static void CancelProcessingWatchdog(SessionState state) } } - private void StartProcessingWatchdog(SessionState state, string sessionName, DateTime? seedTime = null) + private void StartProcessingWatchdog(SessionState state, string sessionName) { CancelProcessingWatchdog(state); - // Seed from the actual last event time (e.g. events.jsonl write time) when resuming, - // so elapsed time reflects how long the session has truly been idle — not just since app start. - var seed = seedTime ?? DateTime.UtcNow; - Interlocked.Exchange(ref state.LastEventAtTicks, seed.Ticks); + // Always seed from DateTime.UtcNow. Do NOT pass events.jsonl file time here — + // that would make elapsed = (file age) + check interval, causing the 30s quiescence + // timeout to fire on the first watchdog check for any file > ~15s old. + // This is the exact regression pattern from PR #148 (short timeout killing active sessions). + Interlocked.Exchange(ref state.LastEventAtTicks, DateTime.UtcNow.Ticks); state.ProcessingWatchdog = new CancellationTokenSource(); var ct = state.ProcessingWatchdog.Token; _ = RunProcessingWatchdogAsync(state, sessionName, ct); @@ -1294,7 +1295,9 @@ private async Task RunProcessingWatchdogAsync(SessionState state, string session if (elapsed >= effectiveTimeout) { - var timeoutMinutes = effectiveTimeout / 60; + var timeoutDisplay = effectiveTimeout >= 60 + ? $"{effectiveTimeout / 60} minute(s)" + : $"{effectiveTimeout} seconds"; Debug($"Session '{sessionName}' watchdog: no events for {elapsed:F0}s " + $"(timeout={effectiveTimeout}s, hasActiveTool={hasActiveTool}, isResumed={state.Info.IsResumed}, hasUsedTools={state.HasUsedToolsThisTurn}, multiAgent={isMultiAgentSession}), clearing stuck processing state"); // Capture generation before posting — same guard pattern as CompleteResponse. @@ -1327,7 +1330,7 @@ private async Task RunProcessingWatchdogAsync(SessionState state, string session state.Info.History.Add(ChatMessage.SystemMessage( "⚠️ Session appears stuck — no response received. You can try sending your message again.")); state.ResponseCompletion?.TrySetResult(""); - OnError?.Invoke(sessionName, $"Session appears stuck — no events received for over {timeoutMinutes} minute(s)."); + OnError?.Invoke(sessionName, $"Session appears stuck — no events received for over {timeoutDisplay}."); OnStateChanged?.Invoke(); }); break; diff --git a/PolyPilot/Services/CopilotService.cs b/PolyPilot/Services/CopilotService.cs index a5359125ff..b726cd1009 100644 --- a/PolyPilot/Services/CopilotService.cs +++ b/PolyPilot/Services/CopilotService.cs @@ -1226,8 +1226,8 @@ public async Task ResumeSessionAsync(string sessionId, string copilotSession.On(evt => HandleSessionEvent(state, evt)); // If still processing, set up ResponseCompletion so events flow properly. - // The processing watchdog (120s inactivity / 600s tool timeout) handles - // stuck sessions — no separate short timeout needed. + // The processing watchdog (30s resume quiescence / 120s inactivity / 600s tool timeout) + // handles stuck sessions — see RunProcessingWatchdogAsync for the three-tier logic. if (isStillProcessing) { state.ResponseCompletion = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); @@ -1235,11 +1235,8 @@ public async Task ResumeSessionAsync(string sessionId, string // Start the processing watchdog so the session doesn't get stuck // forever if the CLI goes silent after resume (same as SendPromptAsync). - // Seed from DateTime.UtcNow (default) — NOT from events.jsonl write time. - // Seeding from file time would make elapsed = (file age) + 15s, causing the - // 30s quiescence timeout to fire on the first watchdog check for any session - // where events.jsonl was written >15s before crash. This is the exact regression - // from PR #148 (killing active sessions with a too-short timeout). + // Seeds from DateTime.UtcNow — NOT events.jsonl write time. + // See StartProcessingWatchdog comment for why file-time seeding is dangerous. StartProcessingWatchdog(state, displayName);