diff --git a/PolyPilot/Components/Pages/Dashboard.razor b/PolyPilot/Components/Pages/Dashboard.razor index 27392189ea..7a4da087a1 100644 --- a/PolyPilot/Components/Pages/Dashboard.razor +++ b/PolyPilot/Components/Pages/Dashboard.razor @@ -820,6 +820,9 @@ completedSessions.Add(sessionName); streamingBySession.Remove(sessionName); activityBySession.Remove(sessionName); + // Refresh sessions list immediately — RefreshState may have been throttled + // when OnStateChanged fired just before OnSessionComplete + sessions = CopilotService.GetAllSessions().ToList(); ScheduleRender(); _ = Task.Delay(10000).ContinueWith(_ => { diff --git a/PolyPilot/Services/CopilotService.Events.cs b/PolyPilot/Services/CopilotService.Events.cs index c90d217a46..fe722674d4 100644 --- a/PolyPilot/Services/CopilotService.Events.cs +++ b/PolyPilot/Services/CopilotService.Events.cs @@ -199,12 +199,47 @@ private void HandleSessionEvent(SessionState state, SessionEvent evt) state.HasReceivedEventsSinceResume = true; Interlocked.Exchange(ref state.LastEventAtTicks, DateTime.UtcNow.Ticks); var sessionName = state.Info.Name; + var isCurrentState = _sessions.TryGetValue(sessionName, out var current) && ReferenceEquals(current, state); + + // Log critical lifecycle events and detect orphaned handlers + if (evt is SessionIdleEvent or AssistantTurnEndEvent or SessionErrorEvent) + { + Debug($"[EVT] '{sessionName}' received {evt.GetType().Name} " + + $"(IsProcessing={state.Info.IsProcessing}, isCurrentState={isCurrentState}, " + + $"thread={Environment.CurrentManagedThreadId})"); + } + + // Warn if receiving events on an orphaned (replaced) state object. + // We don't early-return here: both old and new SessionState share the same Info object + // (reconnect copies Info to newState), so CompleteResponse on the orphaned state still + // correctly clears IsProcessing on the live session's shared Info. + if (!isCurrentState) + { + Debug($"[EVT-WARN] '{sessionName}' event {evt.GetType().Name} delivered to ORPHANED state " + + $"(not in _sessions). This handler should have been detached."); + } + void Invoke(Action action) { if (_syncContext != null) - _syncContext.Post(_ => action(), null); + { + _syncContext.Post(_ => + { + try { action(); } + catch (Exception ex) + { + Debug($"[EVT-ERR] '{sessionName}' SyncContext.Post callback threw: {ex}"); + } + }, null); + } else - action(); + { + try { action(); } + catch (Exception ex) + { + Debug($"[EVT-ERR] '{sessionName}' inline callback threw: {ex}"); + } + } } switch (evt) @@ -324,7 +359,11 @@ void Invoke(Action action) break; case AssistantTurnEndEvent: - CompleteReasoningMessages(state, sessionName); + try { CompleteReasoningMessages(state, sessionName); } + catch (Exception ex) + { + Debug($"[EVT-ERR] '{sessionName}' CompleteReasoningMessages threw in TurnEnd: {ex}"); + } Invoke(() => { OnTurnEnd?.Invoke(sessionName); @@ -333,8 +372,18 @@ void Invoke(Action action) break; case SessionIdleEvent: - CompleteReasoningMessages(state, sessionName); - Invoke(() => CompleteResponse(state)); + try { CompleteReasoningMessages(state, sessionName); } + catch (Exception ex) + { + Debug($"[EVT-ERR] '{sessionName}' CompleteReasoningMessages threw before CompleteResponse: {ex}"); + } + Invoke(() => + { + Debug($"[IDLE] '{sessionName}' CompleteResponse dispatched " + + $"(syncCtx={(_syncContext != null ? "UI" : "inline")}, " + + $"IsProcessing={state.Info.IsProcessing}, thread={Environment.CurrentManagedThreadId})"); + CompleteResponse(state); + }); // Refresh git branch — agent may have switched branches state.Info.GitBranch = GetGitBranch(state.Info.WorkingDirectory); // Send notification when agent finishes @@ -556,7 +605,14 @@ private void FlushCurrentResponse(SessionState state) private void CompleteResponse(SessionState state) { - if (!state.Info.IsProcessing) return; // Already completed (e.g. timeout) + if (!state.Info.IsProcessing) + { + Debug($"[COMPLETE] '{state.Info.Name}' CompleteResponse skipped — IsProcessing already false"); + return; // Already completed (e.g. timeout) + } + + Debug($"[COMPLETE] '{state.Info.Name}' CompleteResponse executing " + + $"(responseLen={state.CurrentResponse.Length}, thread={Environment.CurrentManagedThreadId})"); CancelProcessingWatchdog(state); var response = state.CurrentResponse.ToString(); diff --git a/PolyPilot/Services/CopilotService.cs b/PolyPilot/Services/CopilotService.cs index 5fcf68250d..bd8a7e4d8c 100644 --- a/PolyPilot/Services/CopilotService.cs +++ b/PolyPilot/Services/CopilotService.cs @@ -19,6 +19,7 @@ public partial class CopilotService : IAsyncDisposable private readonly ConcurrentDictionary _closedSessionIds = new(); // Image paths queued alongside messages when session is busy (keyed by session name, list per queued message) private readonly ConcurrentDictionary>> _queuedImagePaths = new(); + private static readonly object _diagnosticLogLock = new(); private readonly IChatDatabase _chatDb; private readonly IServerManager _serverManager; private readonly IWsBridgeClient _bridgeClient; @@ -210,14 +211,51 @@ private void Debug(string message) LastDebugMessage = message; Console.WriteLine($"[DEBUG] {message}"); OnDebug?.Invoke(message); + + // Persist lifecycle diagnostics to file for post-mortem analysis (DEBUG builds only) +#if DEBUG + if (message.StartsWith("[EVT") || message.StartsWith("[IDLE") || + message.StartsWith("[COMPLETE") || message.StartsWith("[SEND") || + message.StartsWith("[RECONNECT") || message.StartsWith("[UI-ERR") || + message.Contains("watchdog")) + { + try + { + lock (_diagnosticLogLock) + { + var logPath = Path.Combine(PolyPilotBaseDir, "event-diagnostics.log"); + // Rotate at 10 MB to prevent unbounded growth + var fi = new FileInfo(logPath); + if (fi.Exists && fi.Length > 10 * 1024 * 1024) + try { File.Delete(logPath); } catch { } + File.AppendAllText(logPath, + $"{DateTime.UtcNow:yyyy-MM-dd HH:mm:ss.fff} {message}{Environment.NewLine}"); + } + } + catch { /* Don't let logging failures cascade */ } + } +#endif } private void InvokeOnUI(Action action) { if (_syncContext != null) - _syncContext.Post(_ => action(), null); + _syncContext.Post(_ => + { + try { action(); } + catch (Exception ex) + { + Debug($"[UI-ERR] InvokeOnUI callback threw: {ex}"); + } + }, null); else - action(); + { + try { action(); } + catch (Exception ex) + { + Debug($"[UI-ERR] InvokeOnUI inline callback threw: {ex}"); + } + } } public async Task InitializeAsync(CancellationToken cancellationToken = default) @@ -1398,6 +1436,7 @@ public async Task SendPromptAsync(string sessionName, string prompt, Lis throw new InvalidOperationException("Session is already processing a request."); state.Info.IsProcessing = true; + Debug($"[SEND] '{sessionName}' IsProcessing=true (thread={Environment.CurrentManagedThreadId})"); state.ResponseCompletion = new TaskCompletionSource(); state.CurrentResponse.Clear(); StartProcessingWatchdog(state, sessionName); @@ -1464,6 +1503,8 @@ public async Task SendPromptAsync(string sessionName, string prompt, Lis var newSession = await _client.ResumeSessionAsync(state.Info.SessionId, reconnectConfig, cancellationToken); // Cancel old watchdog BEFORE creating new state — they share Info/TCS CancelProcessingWatchdog(state); + Debug($"[RECONNECT] '{sessionName}' replacing state (old handler will be orphaned, " + + $"old session disposed, new session={newSession.SessionId})"); var newState = new SessionState { Session = newSession,