Runtime: Heap corruption in System.Net.HttpListener tests

[jkotas]

Hit in https://github.com/dotnet/runtime/pull/31991 on Libraries Test Run release coreclr Windows_NT x86 Release:

Stacktrace of the crash from https://helix.dot.net/api/2019-06-17/jobs/55fc485f-ed44-4531-8009-fb6441da25d1/workitems/System.Net.HttpListener.Tests/files/dotnet.exe.1880.dmp :

0c 0739f48c 775efad1 ntdll!RtlpReportHeapFailure+0x21 [d:\w7rtm\minkernel\ntos\rtl\heaplog.c @ 159] 
0d 0739f4c0 7759d97c ntdll!RtlpLogHeapFailure+0xa1 [d:\w7rtm\minkernel\ntos\rtl\heaplog.c @ 679] 
0e 0739f4f0 76434fde ntdll!RtlFreeHeap+0x64 [d:\w7rtm\minkernel\ntos\rtl\heap.c @ 1887] 
0f 0739f538 71e3b3bc KERNELBASE!GlobalFree+0x27 [d:\w7rtm\minkernel\kernelbase\gmem.c @ 153] 
10 0739f580 71f6b3ea Interop+Kernel32.LocalFree(IntPtr)+0x28
11 0739f58c 04d23508 System_Private_CoreLib!System.Runtime.InteropServices.Marshal.FreeHGlobal(IntPtr)+0x1a
12 0739f59c 056af618 System_Net_HttpListener!System.Net.RequestContextBase.Dispose(Boolean)+0x28
13 0739f5ac 056af5aa System_Net_HttpListener!System.Net.AsyncRequestContext.Dispose(Boolean)+0x50
14 0739f5b8 056af578 System_Net_HttpListener!System.Net.RequestContextBase.Dispose()+0x1a
15 0739f5c4 044ace49 System_Net_HttpListener!System.Net.RequestContextBase.Close()+0x10
16 0739f5d4 044acd32 System_Net_HttpListener!System.Net.HttpListenerRequest.Close()+0x41
17 0739f61c 05bed744 System_Net_HttpListener!System.Net.HttpListenerContext.Close()+0xaa
18 0739f64c 056a3416 System_Net_HttpListener!System.Net.HttpListenerResponse.NonBlockingCloseCallback(System.IAsyncResult)+0x9c
19 0739f6a0 056a328a System_Net_HttpListener!System.Net.LazyAsyncResult.Complete(IntPtr)+0x16e
1a 0739f6e0 05bed68e System_Net_HttpListener!System.Net.LazyAsyncResult.ProtectedInvokeCallback(System.Object, IntPtr)+0x11a
1b 0739f710 05bed351 System_Net_HttpListener!System.Net.HttpResponseStreamAsyncResult.IOCompleted(System.Net.HttpResponseStreamAsyncResult, UInt32, UInt32)+0x1ae
1c 0739f738 71f0fdfa System_Net_HttpListener!System.Net.HttpResponseStreamAsyncResult.Callback(UInt32, UInt32, System.Threading.NativeOverlapped*)+0x111
1d 0739f750 71f10553 System_Private_CoreLib!System.Threading.ThreadPoolBoundHandleOverlapped.CompletionCallback(UInt32, UInt32, System.Threading.NativeOverlapped*)+0x3a
1e 0739f76c 72460a6f System_Private_CoreLib!System.Threading._IOCompletionCallback.PerformIOCompletionCallback(UInt32, UInt32, System.Threading.NativeOverlapped*)+0x37

[ManickaP]

Does this error from helix mean that the dump has been already deleted?

<Error>
  <Code>AuthenticationFailed</Code>
  <Message>
    Server failed to authenticate the request. Make sure the value of Authorization header is formed correctly including the signature. RequestId:5f0a05a2-501e-0098-064a-e7633d000000 Time:2020-02-19T17:33:04.2223625Z
  </Message>
  <AuthenticationErrorDetail>
    Signed expiry time [Wed, 19 Feb 2020 09:10:28 GMT] must be after signed start time [Wed, 19 Feb 2020 17:33:04 GMT]
  </AuthenticationErrorDetail>
</Error>

BTW, I'm signed into helix.

[ManickaP]

Notes: might be related to https://github.com/dotnet/runtime/issues/30284 and fix for this issue: https://github.com/dotnet/runtime/issues/25497

[ManickaP]

The dump I've available has a heap corruption in a different place, but might be caused by the same problem. I don't know if there's something more I could get from the dump or if any of this info is anyhow helpful.
I've also tried to run the HttpListener test under WinDbg with PageHeap on and wasn't able to reproduce the issue.

Details:

> !heap -s
SEGMENT HEAP ERROR: failed to initialize the extention
**************************************************************
*                                                            *
*                  HEAP ERROR DETECTED                       *
*                                                            *
**************************************************************

Details:

Heap address:  0000000000470000
Error address: 000000001b622e60
Error type:    HEAP_FAILURE_FREELISTS_CORRUPTION
Details:       The heap detected a corrupt free list. These are
               usually the result of a use-after-free error.
Follow-up:     Enable pageheap.

Stack trace:
Stack trace at 0x00000000779c7cd8
    0000000077973871: ntdll!RtlpAllocateHeap+0xa11
    00000000778c7b9c: ntdll!RtlAllocateHeap+0x16c
    000007fee6864c4f: coreclr!operator new[]+0x27
    000007fee6924ffa: coreclr!ThreadStatics::AllocateAndInitTLM+0x3a
    000007fee6924d98: coreclr!JIT_GetGCThreadStaticBase_Helper+0x1a4
    000007fee6924be1: coreclr!JIT_GetSharedGCThreadStaticBase+0xb1
    000007fee64046e0: System_Private_CoreLib!System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object)$##60020BD+0x20
    000007fee63fb15c: System_Private_CoreLib!System.Threading.ThreadHelper.ThreadStart(System.Object)$##6001EEF+0x3c
    000007fee6982cd3: coreclr!CallDescrWorkerInternal+0x83
    000007fee68b3979: coreclr!MethodDescCallSite::CallTargetWorker+0x259
    000007fee696c64a: coreclr!ThreadNative::KickOffThread_Worker+0xea
    000007fee68b1683: coreclr!ManagedThreadBase_DispatchMiddle+0x8f
    000007fee68b155e: coreclr!ManagedThreadBase_DispatchOuter+0xaa
    000007fee6954c55: coreclr!ThreadNative::KickOffThread+0x1f5
    000000007769556d: kernel32!BaseThreadInitThunk+0xd
    00000000778f372d: ntdll!RtlUserThreadStart+0x1d

LFH Key                   : 0x0000002028e66bd0
Termination on corruption : ENABLED
          Heap     Flags   Reserv  Commit  Virt   Free  List   UCR  Virt  Lock  Fast 
                            (k)     (k)    (k)     (k) length      blocks cont. heap 
-------------------------------------------------------------------------------------
Virtual block: 0000000001de0000 - 0000000001de0000 (size 0000000000000000)
0000000000470000 00000002    8192   6164   8192     40   113     4    1      2   LFH
0000000000010000 00008000      64      8     64      5     1     1    0      0      
0000000000020000 00008000      64     64     64     61     1     1    0      0      
00000000006b0000 00001002    1088    168   1088      1     2     2    0      0   LFH
0000000001fd0000 00001002     512     12    512      3     1     1    0      0      
0000000002230000 00041002     512      8    512      3     1     1    0      0      
0000000002210000 00001002    1088    172   1088      4     3     2    0      0   LFH
0000000000630000 00041002     512      8    512      3     1     1    0      0      
000000001b9d0000 00041002     512      8    512      3     1     1    0      0      
000000001aa90000 00001002     512    164    512      2     4     1    0      0   LFH
000000001b920000 00001002     512      8    512      2     2     1    0      0      
000000001b250000 00011002     512      8    512      3     2     1    0      0      
000000001bb20000 00001002     512      8    512      3     2     1    0      0      
000000001cad0000 00001002      64      8     64      3     1     1    0      0      
000000001c610000 00001002      64      8     64      3     1     1    0      0      
-------------------------------------------------------------------------------------

> k
# Child-SP          RetAddr           Call Site
00 00000000`1d16dea8 00000000`7795e3d2 ntdll!ZwWaitForSingleObject+0xa
01 00000000`1d16deb0 00000000`7795e9f5 ntdll!RtlReportExceptionEx+0x1d2
02 00000000`1d16dfa0 00000000`7795ea5a ntdll!RtlReportException+0xb5
03 00000000`1d16e020 00000000`7795f296 ntdll!RtlpTerminateFailureFilter+0x1a
04 00000000`1d16e050 00000000`778f7258 ntdll!RtlReportCriticalFailure+0x96
05 00000000`1d16e080 00000000`7790be9d ntdll!_C_specific_handler+0x8c
06 00000000`1d16e0f0 00000000`778e040a ntdll!RtlpExecuteHandlerForException+0xd
07 00000000`1d16e120 00000000`778e3c0f ntdll!RtlDispatchException+0x45a
08 00000000`1d16e800 00000000`7795f262 ntdll!RtlRaiseException+0x22f
09 00000000`1d16f1b0 00000000`7795f836 ntdll!RtlReportCriticalFailure+0x62
0a 00000000`1d16f280 00000000`77960452 ntdll!RtlpReportHeapFailure+0x26
0b 00000000`1d16f2b0 00000000`77962564 ntdll!RtlpHeapHandleError+0x12
0c 00000000`1d16f2e0 00000000`77973871 ntdll!RtlpLogHeapFailure+0xa4
0d 00000000`1d16f310 00000000`778c7b9c ntdll!RtlpAllocateHeap+0xa11
0e 00000000`1d16f4f0 000007fe`e6864c4f ntdll!RtlAllocateHeap+0x16c
0f (Inline Function) --------`-------- coreclr!EEHeapAlloc+0xe [F:\workspace\_work\1\s\src\coreclr\src\vm\hosting.cpp @ 221] 
10 (Inline Function) --------`-------- coreclr!EEHeapAllocInProcessHeap+0x21 [F:\workspace\_work\1\s\src\coreclr\src\vm\hosting.cpp @ 248] 
11 (Inline Function) --------`-------- coreclr!ClrAllocInProcessHeap+0x21 [F:\workspace\_work\1\s\src\coreclr\src\inc\clrhost.h @ 199] 
12 00000000`1d16f600 000007fe`e6924ffa coreclr!operator new[]+0x27 [F:\workspace\_work\1\s\src\coreclr\src\utilcode\clrhost_nodependencies.cpp @ 375] 
13 (Inline Function) --------`-------- coreclr!ThreadStatics::AllocateTLM+0xd [F:\workspace\_work\1\s\src\coreclr\src\vm\threadstatics.cpp @ 710] 
14 00000000`1d16f630 000007fe`e6924d98 coreclr!ThreadStatics::AllocateAndInitTLM+0x3a [F:\workspace\_work\1\s\src\coreclr\src\vm\threadstatics.cpp @ 650] 
15 (Inline Function) --------`-------- coreclr!ThreadStatics::GetTLM+0x10e [F:\workspace\_work\1\s\src\coreclr\src\vm\threadstatics.cpp @ 682] 
16 (Inline Function) --------`-------- coreclr!ThreadStatics::GetTLM+0x119 [F:\workspace\_work\1\s\src\coreclr\src\vm\threadstatics.cpp @ 691] 
17 00000000`1d16f670 000007fe`e6924be1 coreclr!JIT_GetGCThreadStaticBase_Helper+0x1a4 [F:\workspace\_work\1\s\src\coreclr\src\vm\jithelpers.cpp @ 1754] 
18 00000000`1d16f7d0 000007fe`e64046e0 coreclr!JIT_GetSharedGCThreadStaticBase+0xb1 [F:\workspace\_work\1\s\src\coreclr\src\vm\jithelpers.cpp @ 1836] 
19 00000000`1d16f810 000007fe`e63fb15c System_Private_CoreLib!System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object)$##60020BD+0x20
1a 00000000`1d16f880 000007fe`e6982cd3 System_Private_CoreLib!System.Threading.ThreadHelper.ThreadStart(System.Object)$##6001EEF+0x3c
1b 00000000`1d16f8c0 000007fe`e68b3979 coreclr!CallDescrWorkerInternal+0x83 [F:\workspace\_work\1\s\src\coreclr\src\vm\amd64\CallDescrWorkerAMD64.asm @ 101] 
1c 00000000`1d16f900 000007fe`e696c64a coreclr!MethodDescCallSite::CallTargetWorker+0x259 [F:\workspace\_work\1\s\src\coreclr\src\vm\callhelpers.cpp @ 554] 
1d 00000000`1d16fa40 000007fe`e68b1683 coreclr!ThreadNative::KickOffThread_Worker+0xea [F:\workspace\_work\1\s\src\coreclr\src\vm\comsynchronizable.cpp @ 248] 
1e (Inline Function) --------`-------- coreclr!ManagedThreadBase_DispatchInner+0xd [F:\workspace\_work\1\s\src\coreclr\src\vm\threads.cpp @ 7357] 
1f 00000000`1d16fba0 000007fe`e68b155e coreclr!ManagedThreadBase_DispatchMiddle+0x8f [F:\workspace\_work\1\s\src\coreclr\src\vm\threads.cpp @ 7401] 
20 00000000`1d16fcb0 000007fe`e6954c55 coreclr!ManagedThreadBase_DispatchOuter+0xaa [F:\workspace\_work\1\s\src\coreclr\src\vm\threads.cpp @ 7562] 
21 (Inline Function) --------`-------- coreclr!ManagedThreadBase_FullTransition+0x37 [F:\workspace\_work\1\s\src\coreclr\src\vm\threads.cpp @ 7609] 
22 (Inline Function) --------`-------- coreclr!ManagedThreadBase::KickOff+0x37 [F:\workspace\_work\1\s\src\coreclr\src\vm\threads.cpp @ 7644] 
23 00000000`1d16fd50 00000000`7769556d coreclr!ThreadNative::KickOffThread+0x1f5 [F:\workspace\_work\1\s\src\coreclr\src\vm\comsynchronizable.cpp @ 363] 
24 00000000`1d16fe70 00000000`778f372d kernel32!BaseThreadInitThunk+0xd
25 00000000`1d16fea0 00000000`00000000 ntdll!RtlUserThreadStart+0x1d



md5-c91435491c0f17e323f33954958ee38a



> !heap -i 000000001b622e60
SEGMENT HEAP ERROR: failed to initialize the extention
Detailed information for block entry 000000001b622e60
Assumed heap       : 0x000000001c610000 (Use !heap -i NewHeapHandle to change)
Header content     : 0x1B61EC50 0x00000000
Owning segment     : 0x000000001c610000 (offset 0)
Block flags        : 0x60 (free user_flag )
Total block size   : 0xec50 units (0xec500 bytes)
Previous block size: 0x9644 units (0x96440 bytes)
Block CRC          : ERROR - current 1b, expected dd
List corrupted: (Blink->Flink = 0000000000000000) != (Block = 000000001b622e70)
Free list entry    : CORRUPTED
Previous block     : 0x000000001b58ca20
Next block         : 0x000000001b70f360



md5-c91435491c0f17e323f33954958ee38a



> !heap -x 000000001b622e60
SEGMENT HEAP ERROR: failed to initialize the extention
List corrupted: (Flink->Blink = 000000001b64a170) != (Block = 000000001b622e60)
HEAP 0000000000470000 (Seg 000000001b450000) At 000000001b622e50 Error: block list entry corrupted

List corrupted: (Blink->Flink = 000000001b64a170) != (Block = 000000001b653180)
HEAP 0000000000470000 (Seg 000000001b450000) At 000000001b653170 Error: block list entry corrupted

Entry             User              Heap              Segment               Size  PrevSize  Unused    Flags
-------------------------------------------------------------------------------------------------------------
000000001b622e50  000000001b622e60  0000000000470000  000000001b450000       b60       4e0         0  free 

[jkotas]

The dump I've available

Was it Windows 7 like the one at the top, or newer Windows version?

[ManickaP]

The Helix Queue is: windows.7.amd64.open, also there were no other crashes in this build (according to Kusto) and it was on master.
Details: https://helix.dot.net/api/2019-06-17/jobs/9fdff4d5-5f76-43c1-bef7-ab86188e7a53/details

[jkotas]

Have you tried with page heap on Windows 7? It may be Windows7 specific bug.

[ManickaP]

I haven't, though I will, good idea 👍

[ManickaP]

I was able to successfully reproduce the issue on Win7 VM with PageHeap. I was able to isolate the offending test and reproduce the same exception stack:

Unhandled exception. System.Runtime.InteropServices.COMException (0x80000003): One or more arguments are invalid (0x80000003)
   at System.Runtime.InteropServices.Marshal.ThrowExceptionForHR(Int32 errorCode) in D:\Projects\runtime.cleaner\src\libraries\System.Private.CoreLib\src\System\Runtime\InteropServices\Marshal.cs:line 606
   at System.Runtime.InteropServices.Marshal.FreeHGlobal(IntPtr hglobal) in D:\Projects\runtime.cleaner\src\coreclr\src\System.Private.CoreLib\src\System\Runtime\InteropServices\Marshal.CoreCLR.cs:line 281
   at System.Net.RequestContextBase.Dispose(Boolean disposing) in D:\Projects\runtime.cleaner\src\libraries\System.Net.HttpListener\src\System\Net\Windows\RequestContextBase.cs:line 54
   at System.Net.AsyncRequestContext.Dispose(Boolean disposing) in D:\Projects\runtime.cleaner\src\libraries\System.Net.HttpListener\src\System\Net\Windows\AsyncRequestContext.cs:line 97
   at System.Net.RequestContextBase.Dispose() in D:\Projects\runtime.cleaner\src\libraries\System.Net.HttpListener\src\System\Net\Windows\RequestContextBase.cs:line 46
   at System.Net.RequestContextBase.Close() in D:\Projects\runtime.cleaner\src\libraries\System.Net.HttpListener\src\System\Net\Windows\RequestContextBase.cs:line 40
   at System.Net.HttpListenerRequest.Close() in D:\Projects\runtime.cleaner\src\libraries\System.Net.HttpListener\src\System\Net\Windows\HttpListenerRequest.Windows.cs:line 333
   at System.Net.HttpListenerContext.Close() in D:\Projects\runtime.cleaner\src\libraries\System.Net.HttpListener\src\System\Net\Windows\HttpListenerContext.Windows.cs:line 88
   at System.Net.HttpListenerResponse.Dispose() in D:\Projects\runtime.cleaner\src\libraries\System.Net.HttpListener\src\System\Net\Windows\HttpListenerResponse.Windows.cs:line 185
   at System.Net.HttpListenerResponse.System.IDisposable.Dispose() in D:\Projects\runtime.cleaner\src\libraries\System.Net.HttpListener\src\System\Net\HttpListenerResponse.cs:line 297
   at System.Net.HttpListenerResponse.Close() in D:\Projects\runtime.cleaner\src\libraries\System.Net.HttpListener\src\System\Net\Windows\HttpListenerResponse.Windows.cs:line 124
   at System.Net.HttpListenerContext.Close() in D:\Projects\runtime.cleaner\src\libraries\System.Net.HttpListener\src\System\Net\Windows\HttpListenerContext.Windows.cs:line 82
   at System.Net.HttpListenerResponse.NonBlockingCloseCallback(IAsyncResult asyncResult) in D:\Projects\runtime.cleaner\src\libraries\System.Net.HttpListener\src\System\Net\Windows\HttpListenerResponse.Windows.cs:line 210
   at System.Net.LazyAsyncResult.Complete(IntPtr userToken) in D:\Projects\runtime.cleaner\src\libraries\Common\src\System\Net\LazyAsyncResult.cs:line 396
   at System.Net.LazyAsyncResult.ProtectedInvokeCallback(Object result, IntPtr userToken) in D:\Projects\runtime.cleaner\src\libraries\Common\src\System\Net\LazyAsyncResult.cs:line 350
   at System.Net.LazyAsyncResult.InvokeCallback(Object result) in D:\Projects\runtime.cleaner\src\libraries\Common\src\System\Net\LazyAsyncResult.cs:line 357
   at System.Net.HttpResponseStreamAsyncResult.IOCompleted(HttpResponseStreamAsyncResult asyncResult, UInt32 errorCode, UInt32 numBytes) in D:\Projects\runtime.cleaner\src\libraries\System.Net.HttpListener\src\System\Net\Windows\HttpResponseStreamAsyncResult.cs:line 221
   at System.Net.HttpResponseStreamAsyncResult.Callback(UInt32 errorCode, UInt32 numBytes, NativeOverlapped* nativeOverlapped) in D:\Projects\runtime.cleaner\src\libraries\System.Net.HttpListener\src\System\Net\Windows\HttpResponseStreamAsyncResult.cs:line 230
   at System.Threading.ThreadPoolBoundHandleOverlapped.CompletionCallback(UInt32 errorCode, UInt32 numBytes, NativeOverlapped* nativeOverlapped) in D:\Projects\runtime.cleaner\src\coreclr\src\System.Private.CoreLib\src\System\Threading\ClrThreadPoolBoundHandleOverlapped.cs:line 49
   at System.Threading._IOCompletionCallback.PerformIOCompletionCallback(UInt32errorCode, UInt32 numBytes, NativeOverlapped* pNativeOverlapped) in D:\Projects\runtime.cleaner\src\coreclr\src\System.Private.CoreLib\src\System\Threading\Overlapped.cs:line 63

The same repro doesn't fail on my Win 10 machine (running the test in a loop for many hours).

[ManickaP]

The failing test is HttpListenerResponseTests.CloseResponseEntity_ChunkedSentHeaders_DoesNotModifyContentLength, it fails only for willBlock == false:
```c#
using (HttpListenerResponse response = await GetResponse())
{
response.SendChunked = true;
response.OutputStream.Write(SimpleMessage, 0, SimpleMessage.Length);

response.Close(new byte[] { (byte)'a' }, willBlock);
Assert.Equal(-1, response.ContentLength64);

string clientResponse = GetClientResponse(136);
Assert.EndsWith("\r\n5\r\nHello\r\n1\r\na\r\n0\r\n\r\n", clientResponse);

}
```

The fail is caused by a race condition between Dispose at the end of the using block calling HttpListenerContext.Close() and NonBlockingCloseCallback (passed to _responseStream.BeginWrite in case of non-blocking HttpListenerResponse.Close(byte[])) calling the same method from thread-pool thread. This HttpListenerRequest.Close() method calls underneath _memoryBlob.Close() which ends up in calling the Marshal.FreeHGlobal. I don't actually understand how this can work on Win 10, the different timing of the NonBlockingCloseCallback invocation is the only thing I can think of.

Anyway, I was able to fix this by ensuring that only one thread can dispose/free the memoryBlob (via Interlocked.Exchange) and the repro as well as the original test have been running successfully for over an hour. I'll put up a PR soon.