Skip to content

Commit 57c96dd

Browse files
committed
fix(dotnet): recover from dropped session idle events
1 parent 50f8456 commit 57c96dd

4 files changed

Lines changed: 464 additions & 10 deletions

File tree

dotnet/src/Session.cs

Lines changed: 127 additions & 10 deletions
Original file line numberDiff line numberDiff line change
@@ -81,13 +81,18 @@ private sealed record EventSubscription(Type EventType, Action<SessionEvent> Han
8181
private IReadOnlyList<OpenCanvasInstance> _openCanvases = Array.Empty<OpenCanvasInstance>();
8282

8383
private int _isDisposed;
84+
private long _eventEnqueueVersion;
85+
86+
private abstract record EventDispatchItem;
87+
private sealed record EventItem(SessionEvent Event) : EventDispatchItem;
88+
private sealed record EventBarrier(TaskCompletionSource<bool> Completion) : EventDispatchItem;
8489

8590
/// <summary>
8691
/// Channel that serializes event dispatch. <see cref="DispatchEvent"/> enqueues;
8792
/// a single background consumer (<see cref="ProcessEventsAsync"/>) dequeues and
8893
/// invokes handlers one at a time, preserving arrival order.
8994
/// </summary>
90-
private readonly Channel<SessionEvent> _eventChannel = Channel.CreateUnbounded<SessionEvent>(
95+
private readonly Channel<EventDispatchItem> _eventChannel = Channel.CreateUnbounded<EventDispatchItem>(
9196
new() { SingleReader = true });
9297

9398
/// <summary>
@@ -336,7 +341,8 @@ public async Task<string> SendAsync(MessageOptions options, CancellationToken ca
336341

337342
var totalTimestamp = Stopwatch.GetTimestamp();
338343
var effectiveTimeout = timeout ?? TimeSpan.FromSeconds(60);
339-
var tcs = new TaskCompletionSource<AssistantMessageEvent?>(TaskCreationOptions.RunContinuationsAsynchronously);
344+
var tcs = new TaskCompletionSource<(AssistantMessageEvent? Message, string CompletedBy)>(TaskCreationOptions.RunContinuationsAsynchronously);
345+
var completionCandidate = new TaskCompletionSource<bool>(TaskCreationOptions.RunContinuationsAsynchronously);
340346
AssistantMessageEvent? lastAssistantMessage = null;
341347
var firstAssistantMessageLogged = false;
342348

@@ -346,6 +352,7 @@ void Handler(SessionEvent evt)
346352
{
347353
case AssistantMessageEvent assistantMessage:
348354
lastAssistantMessage = assistantMessage;
355+
completionCandidate.TrySetResult(true);
349356
if (!firstAssistantMessageLogged)
350357
{
351358
firstAssistantMessageLogged = true;
@@ -356,12 +363,16 @@ void Handler(SessionEvent evt)
356363
}
357364
break;
358365

366+
case AssistantTurnEndEvent:
367+
completionCandidate.TrySetResult(true);
368+
break;
369+
359370
case SessionIdleEvent:
360371
LoggingHelpers.LogTiming(_logger, LogLevel.Debug, null,
361372
"CopilotSession.SendAndWaitAsync idle received. Elapsed={Elapsed}, SessionId={SessionId}",
362373
totalTimestamp,
363374
SessionId);
364-
tcs.TrySetResult(lastAssistantMessage);
375+
tcs.TrySetResult((lastAssistantMessage, "idle"));
365376
break;
366377

367378
case SessionErrorEvent errorEvent:
@@ -371,6 +382,77 @@ void Handler(SessionEvent evt)
371382
}
372383
}
373384

385+
async Task MonitorRuntimeCompletionAsync(CancellationToken waitCancellationToken)
386+
{
387+
try
388+
{
389+
var candidateOrCompletion = await Task.WhenAny(completionCandidate.Task, tcs.Task).ConfigureAwait(false);
390+
if (candidateOrCompletion != completionCandidate.Task)
391+
{
392+
return;
393+
}
394+
395+
// In the normal path session.idle follows the assistant events in the
396+
// same notification burst. Give it a brief chance to arrive so the
397+
// fallback adds no RPC traffic to healthy turns.
398+
var graceDelay = Task.Delay(TimeSpan.FromMilliseconds(250), waitCancellationToken);
399+
if (await Task.WhenAny(graceDelay, tcs.Task).ConfigureAwait(false) != graceDelay)
400+
{
401+
return;
402+
}
403+
404+
while (!tcs.Task.IsCompleted)
405+
{
406+
// The runtime owns the authoritative view of background tasks and
407+
// follow-up turns. This RPC returns only after those have settled.
408+
await Rpc.Tasks.WaitForPendingAsync(waitCancellationToken).ConfigureAwait(false);
409+
410+
var activity = await Rpc.Metadata.ActivityAsync(waitCancellationToken).ConfigureAwait(false);
411+
if (!activity.HasActiveWork)
412+
{
413+
// RPC responses and session.event notifications share one ordered
414+
// connection, but user handlers run on a separate FIFO channel.
415+
// Flush that channel before confirming the runtime is still idle.
416+
await FlushEventDispatchAsync(waitCancellationToken).ConfigureAwait(false);
417+
activity = await Rpc.Metadata.ActivityAsync(waitCancellationToken).ConfigureAwait(false);
418+
if (!activity.HasActiveWork)
419+
{
420+
var stableEventVersion = Volatile.Read(ref _eventEnqueueVersion);
421+
await FlushEventDispatchAsync(waitCancellationToken).ConfigureAwait(false);
422+
if (stableEventVersion != Volatile.Read(ref _eventEnqueueVersion))
423+
{
424+
continue;
425+
}
426+
427+
activity = await Rpc.Metadata.ActivityAsync(waitCancellationToken).ConfigureAwait(false);
428+
if (!activity.HasActiveWork
429+
&& stableEventVersion == Volatile.Read(ref _eventEnqueueVersion))
430+
{
431+
tcs.TrySetResult((lastAssistantMessage, "activity"));
432+
return;
433+
}
434+
}
435+
}
436+
437+
await Task.Delay(TimeSpan.FromMilliseconds(100), waitCancellationToken).ConfigureAwait(false);
438+
}
439+
}
440+
catch (RemoteRpcException ex) when (ex.ErrorCode == RemoteRpcException.MethodNotFoundErrorCode)
441+
{
442+
// Older runtimes may not expose activity/task-drain RPCs. Preserve the
443+
// existing event-only behavior and let session.idle or the timeout win.
444+
LogRuntimeCompletionFallbackUnavailable(ex, SessionId);
445+
}
446+
catch (OperationCanceledException) when (waitCancellationToken.IsCancellationRequested)
447+
{
448+
// The timeout/caller-cancellation registration completes tcs.
449+
}
450+
catch (Exception ex) when (ex is RemoteRpcException or IOException or ObjectDisposedException or JsonException)
451+
{
452+
tcs.TrySetException(ex);
453+
}
454+
}
455+
374456
using var subscription = On<SessionEvent>(Handler);
375457

376458
await SendAsync(options, cancellationToken);
@@ -385,16 +467,17 @@ void Handler(SessionEvent evt)
385467
else
386468
tcs.TrySetException(new TimeoutException($"SendAndWaitAsync timed out after {effectiveTimeout}"));
387469
});
470+
var runtimeCompletionTask = MonitorRuntimeCompletionAsync(cts.Token);
388471
try
389472
{
390-
var result = await tcs.Task;
473+
var completion = await tcs.Task;
391474
LoggingHelpers.LogTiming(_logger, LogLevel.Debug, null,
392475
"CopilotSession.SendAndWaitAsync complete. Elapsed={Elapsed}, SessionId={SessionId}, CompletedBy={CompletedBy}, AssistantMessageReceived={AssistantMessageReceived}",
393476
totalTimestamp,
394477
SessionId,
395-
"idle",
396-
result is not null);
397-
return result;
478+
completion.CompletedBy,
479+
completion.Message is not null);
480+
return completion.Message;
398481
}
399482
catch (Exception ex) when (ex is TimeoutException)
400483
{
@@ -414,6 +497,11 @@ void Handler(SessionEvent evt)
414497
"error");
415498
throw;
416499
}
500+
finally
501+
{
502+
cts.Cancel();
503+
await runtimeCompletionTask.ConfigureAwait(false);
504+
}
417505
}
418506

419507
/// <summary>
@@ -485,8 +573,27 @@ internal void DispatchEvent(SessionEvent sessionEvent)
485573
// never completes (multi-client permission scenario).
486574
_ = HandleBroadcastEventAsync(sessionEvent);
487575

488-
// Queue the event for serial processing by user handlers.
489-
_eventChannel.Writer.TryWrite(sessionEvent);
576+
// Queue the event for serial processing by user handlers. Increment first so
577+
// a completion monitor can detect an event even if this thread is preempted
578+
// before the channel write.
579+
Interlocked.Increment(ref _eventEnqueueVersion);
580+
_eventChannel.Writer.TryWrite(new EventItem(sessionEvent));
581+
}
582+
583+
/// <summary>
584+
/// Waits until every event already queued for this session has been delivered to
585+
/// user handlers. Events arriving after the barrier remain queued behind it.
586+
/// </summary>
587+
private async Task FlushEventDispatchAsync(CancellationToken cancellationToken)
588+
{
589+
var completion = new TaskCompletionSource<bool>(TaskCreationOptions.RunContinuationsAsynchronously);
590+
var queued = _eventChannel.Writer.TryWrite(new EventBarrier(completion));
591+
ObjectDisposedException.ThrowIf(!queued, this);
592+
593+
using var registration = cancellationToken.Register(
594+
static state => ((TaskCompletionSource<bool>)state!).TrySetCanceled(),
595+
completion);
596+
await completion.Task.ConfigureAwait(false);
490597
}
491598

492599
/// <summary>
@@ -495,8 +602,15 @@ internal void DispatchEvent(SessionEvent sessionEvent)
495602
/// </summary>
496603
private async Task ProcessEventsAsync()
497604
{
498-
await foreach (var sessionEvent in _eventChannel.Reader.ReadAllAsync())
605+
await foreach (var item in _eventChannel.Reader.ReadAllAsync())
499606
{
607+
if (item is EventBarrier barrier)
608+
{
609+
barrier.Completion.TrySetResult(true);
610+
continue;
611+
}
612+
613+
var sessionEvent = ((EventItem)item).Event;
500614
var dispatchTimestamp = Stopwatch.GetTimestamp();
501615
var eventType = sessionEvent.GetType();
502616
foreach (var subscription in _eventHandlers)
@@ -1935,6 +2049,9 @@ await InvokeRpcAsync<object>(
19352049
[LoggerMessage(Level = LogLevel.Error, Message = "Unhandled exception in session event handler")]
19362050
private partial void LogEventHandlerError(Exception exception);
19372051

2052+
[LoggerMessage(Level = LogLevel.Debug, Message = "Runtime completion fallback unavailable. SessionId={sessionId}")]
2053+
private partial void LogRuntimeCompletionFallbackUnavailable(Exception exception, string sessionId);
2054+
19382055
[LoggerMessage(Level = LogLevel.Debug, Message = "Failed to fetch tool metadata for {toolName}")]
19392056
private partial void LogToolMetadataFetchFailed(Exception exception, string toolName);
19402057

Lines changed: 84 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,84 @@
1+
/*---------------------------------------------------------------------------------------------
2+
* Copyright (c) Microsoft Corporation. All rights reserved.
3+
*--------------------------------------------------------------------------------------------*/
4+
5+
using System.Collections;
6+
using System.Reflection;
7+
using Xunit;
8+
using Xunit.Abstractions;
9+
10+
namespace GitHub.Copilot.Test.E2E;
11+
12+
/// <summary>
13+
/// Verifies that .NET completion remains reliable when the runtime's ephemeral
14+
/// <c>session.idle</c> notification does not reach the SendAndWait handler.
15+
/// </summary>
16+
public class SendAndWaitReliabilityE2ETests(E2ETestFixture fixture, ITestOutputHelper output)
17+
: E2ETestBase(fixture, "send_and_wait_reliability", output)
18+
{
19+
[Fact]
20+
public async Task Should_Complete_When_Live_SessionIdle_Is_Dropped()
21+
{
22+
await using var session = await CreateSessionAsync();
23+
var userMessageDispatched = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously);
24+
var releaseUserMessage = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously);
25+
var idleObserved = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously);
26+
27+
using var userSubscription = session.On<UserMessageEvent>(_ =>
28+
{
29+
userMessageDispatched.TrySetResult();
30+
releaseUserMessage.Task.GetAwaiter().GetResult();
31+
});
32+
using var idleSubscription = session.On<SessionIdleEvent>(_ => idleObserved.TrySetResult());
33+
34+
var completionTask = session.SendAndWaitAsync(
35+
new MessageOptions { Prompt = "What is 5+5? Reply with just the number." },
36+
timeout: TimeSpan.FromSeconds(30));
37+
38+
try
39+
{
40+
await userMessageDispatched.Task.WaitAsync(TimeSpan.FromSeconds(10));
41+
SuppressIdleForSendAndWaitHandler(session);
42+
}
43+
finally
44+
{
45+
releaseUserMessage.TrySetResult();
46+
}
47+
48+
var response = await completionTask;
49+
await idleObserved.Task.WaitAsync(TimeSpan.FromSeconds(10));
50+
51+
Assert.NotNull(response);
52+
Assert.Contains("10", response.Data.Content);
53+
}
54+
55+
private static void SuppressIdleForSendAndWaitHandler(CopilotSession session)
56+
{
57+
var handlersField = typeof(CopilotSession).GetField(
58+
"_eventHandlers",
59+
BindingFlags.Instance | BindingFlags.NonPublic)
60+
?? throw new InvalidOperationException("CopilotSession._eventHandlers was not found.");
61+
var handlers = (IEnumerable)(handlersField.GetValue(session)
62+
?? throw new InvalidOperationException("CopilotSession._eventHandlers was null."));
63+
64+
var sendAndWaitSubscription = handlers.Cast<object>().Last(subscription =>
65+
{
66+
var eventType = subscription.GetType().GetProperty("EventType")?.GetValue(subscription);
67+
return Equals(eventType, typeof(SessionEvent));
68+
});
69+
var handlerField = sendAndWaitSubscription.GetType().GetField(
70+
"<Handler>k__BackingField",
71+
BindingFlags.Instance | BindingFlags.NonPublic)
72+
?? throw new InvalidOperationException("EventSubscription.Handler backing field was not found.");
73+
var original = (Action<SessionEvent>)(handlerField.GetValue(sendAndWaitSubscription)
74+
?? throw new InvalidOperationException("SendAndWait event handler was null."));
75+
76+
handlerField.SetValue(sendAndWaitSubscription, (Action<SessionEvent>)(evt =>
77+
{
78+
if (evt is not SessionIdleEvent)
79+
{
80+
original(evt);
81+
}
82+
}));
83+
}
84+
}

0 commit comments

Comments
 (0)