Runtime: Unsubscribe from Console.CancelKeyPress hangs after Task.Delay was cancelled

[Maxim-Kornilov]

This will happen only if all of these conditions are met:
1) use Task.Delay
2) token source was cancelled inside ConsoleCancelEventHandler;
3) token source was cancelled with CancellationTokenSource.Cancel method;
4) method marked as async and Task.Delay is awaited.

Bug is not reproduced if any of these conditions is violated:

• Condition №1 is violated: Use any other task instead of Task.Delay
  AsyncTaskCancel.cs
• Condition №2 is violated: Cancel outside ConsoleCancelEventHandler
  AsyncDelayCancelOutsideHandler.cs
  But it hangs inside ConsoleCancelEventHandler if I add GetAwaiter().GetResult() to Task.Run(() => tokenSource.Cancel())
• Condition №3 is violated: Cancel using CancelAfter
  AsyncDelayCancelAfter.cs
• Condition №4 is violated: Use GetAwaiter().GetResult() for Task.Delay
  SyncDelay.cs

This bug is reproduced even if I use dotnet publish -c release -r win10-x86.

Simple test case or GitHub repo with all test cases

private static async Task SimpleTestCase()
{
    var tokenSource = new CancellationTokenSource();
    ConsoleCancelEventHandler cancelled = (s, e) =>
    {
        // Conditions dotnet/corefx#2 and dotnet/corefx#3
        tokenSource.Cancel();
        e.Cancel = true;
    };
    Console.CancelKeyPress += cancelled;

    try
    {
        Console.WriteLine("Press Ctrl+C to continue");
        // Conditions dotnet/corefx#1 and dotnet/corefx#4
        await Task.Delay(TimeSpan.FromHours(1.0), tokenSource.Token);  
    }
    catch (OperationCanceledException)
    {
        Console.WriteLine("Cancelled");
    }

    Console.CancelKeyPress -= cancelled;
}

dotnet info

Программы командной строки .NET (2.0.2)

Product Information:
 Version:            2.0.2
 Commit SHA-1 hash:  a04b4bf512

Runtime Environment:
 OS Name:     Windows
 OS Version:  10.0.16299
 OS Platform: Windows
 RID:         win10-x64
 Base Path:   C:\Program Files\dotnet\sdk\2.0.2\

Microsoft .NET Core Shared Framework Host

  Version  : 2.0.0
  Build    : e8b8861ac7faf042c87a5c2f9f2d04c98b69f28d

I know that Task.Delay is part of coreclr and Console.CancelKeyPress is part of corefx. I dont't know what causes the issue, but I file it here because the Console.CancelKeyPress is the one that not working as expexted.

[kevingosse]

The continuation is inlined when calling tokenSource.Cancel(). Therefore, we end up calling Console.CancelKeyPress -= cancelled; inside of the callstack of the Console.CancelKeyPress event, which causes the process to hang (some kind of deadlock in the native part I suppose).

A simpler repro, without tasks:

```C#
static void Main(string[] args)
{
ConsoleCancelEventHandler cancelled = null;

cancelled = (s, e) =>
{
    Console.CancelKeyPress -= cancelled;
    Environment.FailFast(string.Empty); // Will never be reached
};
Console.CancelKeyPress += cancelled;
Console.WriteLine("Press Ctrl+C to continue");

Thread.Sleep(1000000);

}
```

[kevingosse]

Digging one step further, after capturing a dump with the above repro code (captured on a .NET Framework process, but I think the issue is the same as .NET Core).

The CancelKeyPress callback is stuck on the callstack:

 # RetAddr           : Args to Child                                                           : Call Site
00 00007ffb`a9edbe9b : 00000215`00000000 00000000`00000000 00007ffb`945d9628 00000000`00000000 : ntdll!NtWaitForAlertByThreadId+0x14
01 00007ffb`a9edbd01 : 00007ffb`a69783e0 0000003c`947fee90 00007ffb`a69783e8 00007ffb`36785a00 : ntdll!RtlpWaitOnAddressWithTimeout+0x43
02 00007ffb`a9eb4571 : 0000003c`947ff300 00007ffb`a69783e0 00000215`fffffffa 00007ffb`36785a78 : ntdll!RtlpWaitOnCriticalSection+0x1a1
03 00007ffb`a9eb4490 : 00000215`96a8086c 0000003c`947ff000 00000000`00000000 00000000`00000000 : ntdll!RtlpEnterCriticalSectionContended+0xd1
04 00007ffb`a67ca33c : 00007ffb`95ef7f0e 0000003c`947fede8 0000003c`947fee18 00000215`96ad8ff0 : ntdll!RtlEnterCriticalSection+0x40
05 00007ffb`94b9870e : 00000215`96ad9018 00000000`00000000 00000215`94d1ed70 00000000`00000001 : KERNELBASE!SetConsoleCtrlHandler+0x1c
06 00007ffb`94ea511f : 00000215`96ad3390 00000215`96ad9018 0000003c`947ff0a0 00000215`96ad2ed8 : mscorlib_ni+0xc5870e
07 00007ffb`94c964da : 00000215`96ad9018 00000000`00000000 00000000`00000000 00000000`00000000 : mscorlib_ni+0xf6511f
08 00007ffb`368905f2 : 0000003c`947ff120 00000000`00000001 0000003c`947ff3b0 00000215`96ad8ff0 : mscorlib_ni+0xd564da
09 00007ffb`94c96273 : 00000215`96ad2ec0 00000000`00000000 00000215`96ada3e0 00000000`00000000 : 0x00007ffb`368905f2
0a 00007ffb`94434740 : 00000215`96ad7fe8 00000215`94d1ed70 0000003c`947fee08 0000003c`947fef50 : mscorlib_ni+0xd56273
0b 00007ffb`944345d4 : 00000215`96ad90b8 00000215`96ad9018 00000215`96ad8ff0 00000000`00000001 : mscorlib_ni+0x4f4740
0c 00007ffb`9443f120 : 0000003c`947ff428 0000003c`947ff428 0000003c`947ff300 00000000`00000001 : mscorlib_ni+0x4f45d4
0d 00007ffb`9443f73e : 00000215`96ad8ff0 00000000`000004eb 00000000`00000000 00000000`00000000 : mscorlib_ni+0x4ff120
0e 00007ffb`95ea5a03 : 00007ffb`95ea5f31 00000000`00000000 0000003c`947ff538 00000000`0000013a : mscorlib_ni+0x4ff73e
0f 00007ffb`95ea589d : 0000d79e`67e3d1e7 00007ffb`95ea64ad 0000003c`947ff678 00000000`00000007 : clr!CallDescrWorkerInternal+0x83
10 00007ffb`95ea5fa5 : 00000000`00000000 00000000`00000000 0000003c`947ff708 0000003c`947ff538 : clr!CallDescrWorkerWithHandler+0x4e
11 00007ffb`95eab6f9 : 0000003c`947ffa10 0000003c`947ff9c0 0000003c`947ffa10 0000003c`947ff770 : clr!MethodDescCallSite::CallTargetWorker+0xf8
12 00007ffb`95ea6751 : 0000003c`947ff598 00000000`00000230 00000215`94c00300 00007ffb`a8daf020 : clr!QueueUserWorkItemManagedCallback+0x2a
13 00007ffb`95ea66cc : 0000003c`947ff770 00007ffb`9e3044a8 0000003c`947ff718 ffffffff`ffffffff : clr!ManagedThreadBase_DispatchInner+0x39
14 00007ffb`95ea660a : 00007ffb`96877000 00007ffb`96657114 00007ffb`a8daf020 00007ffb`95f20adf : clr!ManagedThreadBase_DispatchMiddle+0x6c
15 00007ffb`95ea678b : ffffffff`ffffffff 00000215`94d1ed70 00000000`00000000 00000000`00000001 : clr!ManagedThreadBase_DispatchOuter+0x75
16 00007ffb`95eab660 : 00000215`94d2f6d0 00007ffb`960018c0 00000000`00000000 00000000`00000000 : clr!ManagedThreadBase_FullTransitionWithAD+0x2f
17 00007ffb`95ea7648 : 00000001`00010008 0000003c`947ffa08 0000003c`947ffa10 00000000`00000001 : clr!ManagedPerAppDomainTPCount::DispatchWorkItem+0xa0
18 00007ffb`95ea7525 : 00000001`00010008 00000000`00000001 00000215`94d1ed70 00000000`00000001 : clr!ThreadpoolMgr::ExecuteWorkRequest+0x64
19 00007ffb`9606222f : 00000000`00000000 00000000`00000000 00000000`00000001 00000000`00000409 : clr!ThreadpoolMgr::WorkerThreadStart+0xf5
1a 00007ffb`a8af2774 : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`00000000 : clr!Thread::intermediateThreadProc+0x86
1b 00007ffb`a9f10d51 : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`00000000 : kernel32!BaseThreadInitThunk+0x14
1c 00000000`00000000 : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`00000000 : ntdll!RtlUserThreadStart+0x21

If we investigate the critical section the thread is waiting on:

Critical section   = 0x00007ffba69783e0 (KERNELBASE!ConsoleStateLock+0x0)
DebugInfo          = 0x0000021594d32360
LOCKED
LockCount          = 0x1
WaiterWoken        = No
OwningThread       = 0x0000000000090f90
RecursionCount     = 0x1
LockSemaphore      = 0xFFFFFFFF
SpinCount          = 0x00000000020007d0

The owning thread turns out to be:

 # Child-SP          RetAddr           Call Site
00 0000003c`943fefa8 00007ffb`a67adcb0 ntdll!NtWaitForMultipleObjects+0x14
01 0000003c`943fefb0 00007ffb`96060e4e KERNELBASE!WaitForMultipleObjectsEx+0xf0
02 0000003c`943ff2b0 00007ffb`96060cdc clr!WaitForMultipleObjectsEx_SO_TOLERANT+0x62
03 0000003c`943ff310 00007ffb`96060ad5 clr!Thread::DoAppropriateWaitWorker+0x1e4
04 0000003c`943ff410 00007ffb`96000005 clr!Thread::DoAppropriateWait+0x7d
05 0000003c`943ff490 00007ffb`9444923b clr!WaitHandleNative::CorWaitOneNative+0x165
06 0000003c`943ff6c0 00007ffb`9444920e mscorlib_ni+0x50923b
07 0000003c`943ff6f0 00007ffb`94c961d3 mscorlib_ni+0x50920e
08 0000003c`943ff730 00007ffb`94c26228 mscorlib_ni+0xd561d3
09 0000003c`943ff770 00007ffb`95ea220e mscorlib_ni+0xce6228
0a 0000003c`943ff7c0 00007ffb`a676717d clr!UMThunkStub+0x6e
0b 0000003c`943ff850 00007ffb`a8af2774 KERNELBASE!CtrlRoutine+0x9d
0c 0000003c`943ff940 00007ffb`a9f10d51 kernel32!BaseThreadInitThunk+0x14
0d 0000003c`943ff970 00000000`00000000 ntdll!RtlUserThreadStart+0x21

Putting it together:

• When Ctrl+C is pressed, a thread is spawned inside of the process, and executes KERNELBASE!CtrlRoutine . That method acquires a critical section, then calls ControlCHandlerRegistrar.BreakEvent which in turns executes Console.HandleBreakEvent.
• Console.HandleBreakEvent launches a task to execute the user event callback, then waits on it: https://github.com/dotnet/corefx/blob/fc225bd023e4e692d18442b02454cada7c252368/src/System.Console/src/System/Console.cs#L730-L751
• In the task, the user code tries to unhook the ctrl+c event, which triggers a call to KERNELBASE!SetConsoleCtrlHandler
• That method tries to acquire the critical section owned by KERNELBASE!CtrlRoutine -> deadlock

I'm not sure what can be done to handle this situation. According to comments in the code, the event callback is executed in another task because the stack is too small (https://github.com/dotnet/corefx/blob/fc225bd023e4e692d18442b02454cada7c252368/src/System.Console/src/System/Console.cs#L719-L721). And we have to wait on the task because we need to know whether the user sets e.Cancel to true. The only possible fix I see would be to detect the reentrant case in the Console.CancelKeyPress setter and execute _registrar.Unregister() in a task. But it could have subtle impacts if some people are expecting the unregister logic to be executed synchronously.

[stephentoub]

Thanks for the great debugging, @Maxim-Kornilov.

[chrisnas]

Thanks for the great debugging, @Maxim-Kornilov.

Thanks Kevin ;^)

[stephentoub]

Ah, sorry, yes, thanks @kevingosse.

[AceHack]

Do you recommend unsubscribing from this event in a console app? Any problems if I don't unsubscribe?

[stephentoub]

Do you recommend unsubscribing from this event in a console app? Any problems if I don't unsubscribe?

You mean whether it's ok to let the console app terminate without unsubscribing as cleanup? That's fine.

[AceHack]

@stephentoub yep, that's exactly my question, I'm very OCD about unsubscribing from events, so it just felt wrong not to unsubscribe. I did a Task.Run and unsubscribed inside to get around this issue, guess I don't need that. Thanks for the quick response.