search

open-telemetry / opentelemetry-dotnet-instrumentation

OpenTelemetry .NET Automatic Instrumentation
https://opentelemetry.io
Apache License 2.0
368 stars 91 forks source link

CI sometimes hanging on Windows (net462?) #1362

Closed pjanotti closed 2 years ago

pjanotti commented 2 years ago

Some CI runs on Windows seems to be deadlocking on IntegrationTests.AspNetTests.SubmitMetrics:

  Error: The active test run was aborted. Reason: Test host process crashed
  15:29:52 [ERR] The active test run was aborted. Reason: Test host process crashed
  15:29:52 [DBG] Data collector 'Blame' message: The specified inactivity time of 3 minutes has elapsed. Collecting hang dumps from testhost and its child processes.
  15:29:52 [DBG] Data collector 'Blame' message: Dumping 4824 - testhost.net462.
  15:29:52 [DBG] Results File: D:\a\opentelemetry-dotnet-instrumentation\opentelemetry-dotnet-instrumentation\build_data\results\IntegrationTests\runneradmin_fv-az448-3_2022-10-03_15_22_24.trx
  15:29:52 [DBG] 
  Error: The active Test Run was aborted because the host process exited unexpectedly. Please inspect the call stack above, if available, to get more information about where the exception originated from.
  15:29:52 [ERR] The active Test Run was aborted because the host process exited unexpectedly. Please inspect the call stack above, if available, to get more information about where the exception originated from.
  Error: The test running when the crash occurred: 
  15:29:52 [ERR] The test running when the crash occurred: 
  Error: IntegrationTests.AspNetTests.SubmitMetrics
  15:29:52 [ERR] IntegrationTests.AspNetTests.SubmitMetrics
  15:29:52 [ERR] 
  Error: This test may, or may not be the source of the crash.
  15:29:52 [ERR] This test may, or may not be the source of the crash.
  15:29:52 [DBG] 
  15:29:52 [DBG] Attachments:
  15:29:52 [DBG]   D:\a\opentelemetry-dotnet-instrumentation\opentelemetry-dotnet-instrumentation\build_data\results\IntegrationTests\85c407ec-7dbc-4d21-9825-81ae737ccefc\Sequence_3b2b7ab21538437aa5daf91d019727fb.xml
  15:29:52 [DBG]   D:\a\opentelemetry-dotnet-instrumentation\opentelemetry-dotnet-instrumentation\build_data\results\IntegrationTests\85c407ec-7dbc-4d21-9825-81ae737ccefc\testhost.net462_4824_20221003T152910_hangdump.dmp
  15:29:52 [DBG] Passed!  - Failed:     0, Passed:    17, Skipped:     0, Total:    17, Duration: 3 m 42 s - IntegrationTests.dll (net462)
rajkumar-rangaraj commented 2 years ago

Looked at the dumps from this test run, here are two stacks which involved in an issue.

0:020> kL
 # Child-SP          RetAddr               Call Site
00 00000053`4987e3e8 00007ffe`fc4935e1     ntdll!ZwWaitForSingleObject+0x14
01 00000053`4987e3f0 00007ffe`fc4935b2     httpapi!HttpApiSynchronousDeviceControl+0x1711
02 (Inline Function) --------`--------     httpapi!HttpApiDeviceControl+0x1812
03 00000053`4987e470 00007ffe`9fa60d6c     httpapi!HttpReceiveHttpRequest+0x1852
04 00000053`4987e4e0 00007ffe`9fa60750     xunit_runner_utility_net452_18d00dc0000!DomainBoundILStubClass.IL_STUB_PInvoke(System.Runtime.InteropServices.CriticalHandle, UInt64, UInt32, HTTP_REQUEST*, UInt32, UInt32*, System.Threading.NativeOverlapped*)+0xac
05 00000053`4987e5b0 00007ffe`9fa60034     System!System.Net.HttpListener.GetContext+0x120
06 00000053`4987e670 00007ffe`fae4e9a8     IntegrationTests_18c98570000!IntegrationTests.Helpers.TestHttpListener.HandleHttpRequests+0x24
07 00000053`4987e6b0 00007ffe`fae4e895     mscorlib_ni!System.Threading.ExecutionContext.RunInternal+0x108
08 00000053`4987e780 00007ffe`fae4e865     mscorlib_ni!System.Threading.ExecutionContext.Run+0x15
09 00000053`4987e7b0 00007ffe`fae731f5     mscorlib_ni!System.Threading.ExecutionContext.Run+0x55
0a 00000053`4987e800 00007ffe`fe260e73     mscorlib_ni!System.Threading.ThreadHelper.ThreadStart+0x55
0b 00000053`4987e840 00007ffe`fe12961b     clr!CallDescrWorkerInternal+0x83
0c 00000053`4987e880 00007ffe`fe178b5a     clr!CallDescrWorkerWithHandler+0x47
0d 00000053`4987e8c0 00007ffe`fe471889     clr!MethodDescCallSite::CallTargetWorker+0xfa
0e 00000053`4987e9c0 00007ffe`fe14230b     clr!ThreadNative::KickOffThread_Worker+0x218d09
0f 00000053`4987ec10 00007ffe`fe14222f     clr!ManagedThreadBase_DispatchInner+0x33
10 00000053`4987ec50 00007ffe`fe1420fb     clr!ManagedThreadBase_DispatchMiddle+0x83
11 00000053`4987ed40 00007ffe`fe259695     clr!ManagedThreadBase_DispatchOuter+0x87
12 00000053`4987edd0 00007ffe`fe4ab2e8     clr!ManagedThreadBase_DispatchInCorrectAD+0x15
13 00000053`4987ee00 00007ffe`fe3ee2b7     clr!Thread::DoADCallBack+0x3a4
14 00000053`4987ef90 00007ffe`fe14222f     clr!ManagedThreadBase_DispatchInner+0x2abfdf
15 00000053`4987efd0 00007ffe`fe1420fb     clr!ManagedThreadBase_DispatchMiddle+0x83
16 00000053`4987f0c0 00007ffe`fe14206f     clr!ManagedThreadBase_DispatchOuter+0x87
17 00000053`4987f150 00007ffe`fe259a11     clr!ManagedThreadBase_FullTransitionWithAD+0x2f
18 (Inline Function) --------`--------     clr!ManagedThreadBase::KickOff+0x20
19 00000053`4987f1b0 00007ffe`fe2454ea     clr!ThreadNative::KickOffThread+0xe1
1a 00000053`4987f270 00007fff`0a4c4ed0     clr!Thread::intermediateThreadProc+0x8a
1b 00000053`4987ff30 00007fff`0bf5e39b     kernel32!BaseThreadInitThunk+0x10
1c 00000053`4987ff60 00000000`00000000     ntdll!RtlUserThreadStart+0x2b

Managed stack

0:020> !CLRStack
OS Thread Id: 0xb9c (20)
        Child SP               IP Call Site
000000534987e528 00007fff0bf7f7f4 [InlinedCallFrame: 000000534987e528] System.Net.UnsafeNclNativeMethods+HttpApi.HttpReceiveHttpRequest(System.Runtime.InteropServices.CriticalHandle, UInt64, UInt32, HTTP_REQUEST*, UInt32, UInt32*, System.Threading.NativeOverlapped*)
000000534987e528 00007ffe9fa60d6c [InlinedCallFrame: 000000534987e528] System.Net.UnsafeNclNativeMethods+HttpApi.HttpReceiveHttpRequest(System.Runtime.InteropServices.CriticalHandle, UInt64, UInt32, HTTP_REQUEST*, UInt32, UInt32*, System.Threading.NativeOverlapped*)
000000534987e4e0 00007ffe9fa60d6c DomainBoundILStubClass.IL_STUB_PInvoke(System.Runtime.InteropServices.CriticalHandle, UInt64, UInt32, HTTP_REQUEST*, UInt32, UInt32*, System.Threading.NativeOverlapped*)
000000534987e5b0 00007ffe9fa60750 System.Net.HttpListener.GetContext()
000000534987e670 00007ffe9fa60034 IntegrationTests.Helpers.TestHttpListener.HandleHttpRequests()
000000534987e6b0 00007ffefae4e9a8 System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object, Boolean)
000000534987e780 00007ffefae4e895 System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object, Boolean)
000000534987e7b0 00007ffefae4e865 System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object)
000000534987e800 00007ffefae731f5 System.Threading.ThreadHelper.ThreadStart()
000000534987ea20 00007ffefe260e73 [GCFrame: 000000534987ea20] 
000000534987ed88 00007ffefe260e73 [DebuggerU2MCatchHandlerFrame: 000000534987ed88] 
000000534987ef08 00007ffefe260e73 [ContextTransitionFrame: 000000534987ef08] 
000000534987f108 00007ffefe260e73 [DebuggerU2MCatchHandlerFrame: 000000534987f108] 

0:021> kL
 # Child-SP          RetAddr               Call Site
00 00000053`4703c198 00007fff`0959377c     ntdll!ZwWaitForMultipleObjects+0x14
01 00000053`4703c1a0 00007ffe`fe191636     KERNELBASE!WaitForMultipleObjectsEx+0xec
02 00000053`4703c490 00007ffe`fe19102a     clr!WaitForMultipleObjectsEx_SO_TOLERANT+0x62
03 (Inline Function) --------`--------     clr!Thread::DoAppropriateAptStateWait+0x40
04 00000053`4703c4f0 00007ffe`fe190e01     clr!Thread::DoAppropriateWaitWorker+0x206
05 00000053`4703c5e0 00007ffe`fe103157     clr!Thread::DoAppropriateWait+0x7d
06 00000053`4703c660 00007ffe`fe256174     clr!CLREventBase::WaitEx+0xab
07 (Inline Function) --------`--------     clr!CLREventBase::Wait+0x21
08 (Inline Function) --------`--------     clr!Thread::Wait+0x21
09 00000053`4703c6d0 00007ffe`fe25613d     clr!Thread::Block+0x2c
0a 00000053`4703c700 00007ffe`fe255f38     clr!SyncBlock::Wait+0x1e9
0b (Inline Function) --------`--------     clr!ObjHeader::Wait+0x29
0c (Inline Function) --------`--------     clr!Object::Wait+0x29
0d 00000053`4703c830 00007ffe`faeb0294     clr!ObjectNative::WaitTimeout+0xd8
0e 00000053`4703c9b0 00007ffe`fae78009     mscorlib_ni!System.Threading.ManualResetEventSlim.Wait+0x364
0f 00000053`4703ca40 00007ffe`fb724831     mscorlib_ni!System.Threading.Tasks.Task.SpinThenBlockingWait+0xe9
10 00000053`4703cab0 00007ffe`fae77e49     mscorlib_ni!System.Threading.Tasks.Task.InternalWait+0x1b1
11 00000053`4703cb80 00007ffe`fb724630     mscorlib_ni!System.Threading.Tasks.Task.Wait+0x39
12 00000053`4703cbb0 00007ffe`9fff9182     mscorlib_ni!System.Threading.Tasks.Task.Wait+0x40
13 00000053`4703cbe0 00007ffe`9fe28f3e     IntegrationTests_18c98570000!IntegrationTests.Helpers.Models.Container.Dispose+0x52
14 00000053`4703cc20 00007ffe`9fe28e5b     IntegrationTests_18c98570000!IntegrationTests.AspNetTests.<SubmitMetrics>d__2.MoveNext+0x68e
15 00000053`4703cc70 00007ffe`fae4e9a8     IntegrationTests_18c98570000!IntegrationTests.AspNetTests.<SubmitMetrics>d__2.MoveNext+0x5ab
16 00000053`4703cd20 00007ffe`fae4e895     mscorlib_ni!System.Threading.ExecutionContext.RunInternal+0x108
17 00000053`4703cdf0 00007ffe`faeacc8f     mscorlib_ni!System.Threading.ExecutionContext.Run+0x15
18 00000053`4703ce20 00007ffe`faeb1ad3     mscorlib_ni!System.Runtime.CompilerServices.AsyncMethodBuilderCore.MoveNextRunner.Run+0x6f
19 00000053`4703ce70 00007ffe`fae2b900     mscorlib_ni!System.Threading.Tasks.AwaitTaskContinuation.RunOrScheduleAction+0x63
1a 00000053`4703cec0 00007ffe`fae31788     mscorlib_ni!System.Threading.Tasks.Task.FinishContinuations+0x400
1b 00000053`4703cf50 00007ffe`faeabfb3     mscorlib_ni!System.Threading.Tasks.Task<System.__Canon>.TrySetResult+0x68
1c 00000053`4703cf90 00007ffe`9fa7f667     mscorlib_ni!System.Runtime.CompilerServices.AsyncTaskMethodBuilder<System.Net.Http.HttpResponseMessage>.SetResult+0xa3
1d 00000053`4703cfe0 00007ffe`fae4e9a8     System_Net_Http_18d01590000!System.Net.Http.HttpClient.<FinishSendAsyncBuffered>d__58.MoveNext+0x387
1e 00000053`4703d0b0 00007ffe`fae4e895     mscorlib_ni!System.Threading.ExecutionContext.RunInternal+0x108
1f 00000053`4703d180 00007ffe`faeacc8f     mscorlib_ni!System.Threading.ExecutionContext.Run+0x15
20 00000053`4703d1b0 00007ffe`faeb1ad3     mscorlib_ni!System.Runtime.CompilerServices.AsyncMethodBuilderCore.MoveNextRunner.Run+0x6f
21 00000053`4703d200 00007ffe`fae2b900     mscorlib_ni!System.Threading.Tasks.AwaitTaskContinuation.RunOrScheduleAction+0x63
22 00000053`4703d250 00007ffe`faeb0a55     mscorlib_ni!System.Threading.Tasks.Task.FinishContinuations+0x400
23 00000053`4703d2e0 00007ffe`faeab794     mscorlib_ni!System.Threading.Tasks.Task`1.TrySetResult+0x7f335
24 00000053`4703d310 00007ffe`faeab7d4     mscorlib_ni+0x5ab794
25 00000053`4703d350 00007ffe`9fb82ffd     mscorlib_ni!System.Runtime.CompilerServices.AsyncTaskMethodBuilder<System.Threading.Tasks.VoidTaskResult>.SetResult+0x24
26 00000053`4703d380 00007ffe`fae4e9a8     System_Net_Http_18d01590000!System.Net.Http.HttpContent.<LoadIntoBufferAsyncCore>d__49.MoveNext+0x17d
27 00000053`4703d400 00007ffe`fae4e895     mscorlib_ni!System.Threading.ExecutionContext.RunInternal+0x108
28 00000053`4703d4d0 00007ffe`faeacc8f     mscorlib_ni!System.Threading.ExecutionContext.Run+0x15
29 00000053`4703d500 00007ffe`faeb1ad3     mscorlib_ni!System.Runtime.CompilerServices.AsyncMethodBuilderCore.MoveNextRunner.Run+0x6f
2a 00000053`4703d550 00007ffe`fae2b900     mscorlib_ni!System.Threading.Tasks.AwaitTaskContinuation.RunOrScheduleAction+0x63
2b 00000053`4703d5a0 00007ffe`fae77614     mscorlib_ni!System.Threading.Tasks.Task.FinishContinuations+0x400
2c 00000053`4703d630 00007ffe`fae78ae7     mscorlib_ni!System.Threading.Tasks.Task.Finish+0x34
2d 00000053`4703d690 00007ffe`fae77b91     mscorlib_ni!System.Threading.Tasks.Task.ExecuteWithThreadLocal+0x257
2e 00000053`4703d740 00007ffe`faeaea52     mscorlib_ni!System.Threading.Tasks.Task.ExecuteEntry+0xa1
2f 00000053`4703d780 00007ffe`faeae926     mscorlib_ni!System.Threading.Tasks.ThreadPoolTaskScheduler.TryExecuteTaskInline+0x32
30 00000053`4703d7d0 00007ffe`faeae5c6     mscorlib_ni!System.Threading.Tasks.TaskScheduler.TryRunInline+0x1a6
31 00000053`4703d870 00007ffe`fae2b5fe     mscorlib_ni!System.Threading.Tasks.TaskContinuation.InlineIfPossibleOrElseQueue+0x76
32 00000053`4703d900 00007ffe`faeb0a55     mscorlib_ni!System.Threading.Tasks.Task.FinishContinuations+0xfe
33 00000053`4703d990 00007ffe`faeab794     mscorlib_ni!System.Threading.Tasks.Task`1.TrySetResult+0x7f335
34 00000053`4703d9c0 00007ffe`faeab7d4     mscorlib_ni+0x5ab794
35 00000053`4703da00 00007ffe`fb881503     mscorlib_ni!System.Runtime.CompilerServices.AsyncTaskMethodBuilder<System.Threading.Tasks.VoidTaskResult>.SetResult+0x24
36 00000053`4703da30 00007ffe`fae4e9a8     mscorlib_ni!System.IO.Stream.<CopyToAsyncInternal>d__27.MoveNext+0x343
37 00000053`4703dae0 00007ffe`fae4e895     mscorlib_ni!System.Threading.ExecutionContext.RunInternal+0x108
38 00000053`4703dbb0 00007ffe`faeacc8f     mscorlib_ni!System.Threading.ExecutionContext.Run+0x15
39 00000053`4703dbe0 00007ffe`faeb1ad3     mscorlib_ni!System.Runtime.CompilerServices.AsyncMethodBuilderCore.MoveNextRunner.Run+0x6f
3a 00000053`4703dc30 00007ffe`fae2b900     mscorlib_ni!System.Threading.Tasks.AwaitTaskContinuation.RunOrScheduleAction+0x63
3b 00000053`4703dc80 00007ffe`faeb25cd     mscorlib_ni!System.Threading.Tasks.Task.FinishContinuations+0x400
3c 00000053`4703dd10 00007ffe`fb8b92c5     mscorlib_ni!System.Threading.Tasks.Task`1.TrySetResult+0x80ead
3d 00000053`4703dd50 00007ffe`fb8b93e3     mscorlib_ni!System.Threading.Tasks.TaskFactory<int>.FromAsyncTrimPromise<System.IO.Stream>.Complete+0x35
3e 00000053`4703dd90 00007ffe`9fa8f20f     mscorlib_ni!System.Threading.Tasks.TaskFactory<int>.FromAsyncTrimPromise<System.IO.Stream>.CompleteFromAsyncResult+0x93
3f 00000053`4703ddf0 00007ffe`fae4e9a8     System!System.Net.LazyAsyncResult.Complete+0x8f
40 00000053`4703de40 00007ffe`fae4e895     mscorlib_ni!System.Threading.ExecutionContext.RunInternal+0x108
41 00000053`4703df10 00007ffe`fae4e865     mscorlib_ni!System.Threading.ExecutionContext.Run+0x15
42 00000053`4703df40 00007ffe`9fa8f159     mscorlib_ni!System.Threading.ExecutionContext.Run+0x55
43 00000053`4703df90 00007ffe`9fa8eff6     System!System.Net.ContextAwareResult.Complete+0xc9
44 00000053`4703dfe0 00007ffe`9fa8e705     System!System.Net.LazyAsyncResult.ProtectedInvokeCallback+0xc6
45 00000053`4703e020 00007ffe`faeadae4     System!System.Net.Sockets.BaseOverlappedAsyncResult.CompletionPortCallback+0x125
46 00000053`4703e090 00007ffe`fe260e73     mscorlib_ni!System.Threading._IOCompletionCallback.PerformIOCompletionCallback+0x84
47 00000053`4703e0f0 00007ffe`fe12961b     clr!CallDescrWorkerInternal+0x83
48 00000053`4703e130 00007ffe`fe129420     clr!CallDescrWorkerWithHandler+0x47
49 00000053`4703e170 00007ffe`fe4e0d15     clr!DispatchCallSimple+0x60
4a 00000053`4703e200 00007ffe`fe14230b     clr!BindIoCompletionCallBack_Worker+0x105
4b 00000053`4703e2b0 00007ffe`fe14222f     clr!ManagedThreadBase_DispatchInner+0x33
4c 00000053`4703e2f0 00007ffe`fe1420fb     clr!ManagedThreadBase_DispatchMiddle+0x83
4d 00000053`4703e3e0 00007ffe`fe259695     clr!ManagedThreadBase_DispatchOuter+0x87
4e 00000053`4703e470 00007ffe`fe4ab2e8     clr!ManagedThreadBase_DispatchInCorrectAD+0x15
4f 00000053`4703e4a0 00007ffe`fe3ee2b7     clr!Thread::DoADCallBack+0x3a4
50 00000053`4703e630 00007ffe`fe14222f     clr!ManagedThreadBase_DispatchInner+0x2abfdf
51 00000053`4703e670 00007ffe`fe1420fb     clr!ManagedThreadBase_DispatchMiddle+0x83
52 00000053`4703e760 00007ffe`fe14206f     clr!ManagedThreadBase_DispatchOuter+0x87
53 00000053`4703e7f0 00007ffe`fe4e0e79     clr!ManagedThreadBase_FullTransitionWithAD+0x2f
54 (Inline Function) --------`--------     clr!ManagedThreadBase::ThreadPool+0x18
55 00000053`4703e850 00007ffe`fe4e0d99     clr!BindIoCompletionCallbackStubEx+0xb1
56 00000053`4703e8d0 00007ffe`fe476833     clr!BindIoCompletionCallbackStub+0x9
57 00000053`4703e900 00007ffe`fe2454ea     clr!ThreadpoolMgr::CompletionPortThreadStart+0x633
58 00000053`4703e9a0 00007fff`0a4c4ed0     clr!Thread::intermediateThreadProc+0x8a
59 00000053`4703f7e0 00007fff`0bf5e39b     kernel32!BaseThreadInitThunk+0x10
5a 00000053`4703f810 00000000`00000000     ntdll!RtlUserThreadStart+0x2b

Managed Stack

0:021> !ClrStack
OS Thread Id: 0x1cd0 (21)
        Child SP               IP Call Site
000000534703c750 00007fff0bf802c4 [GCFrame: 000000534703c750] 
000000534703c898 00007fff0bf802c4 [HelperMethodFrame_1OBJ: 000000534703c898] System.Threading.Monitor.ObjWait(Boolean, Int32, System.Object)
000000534703c9b0 00007ffefaeb0294 System.Threading.ManualResetEventSlim.Wait(Int32, System.Threading.CancellationToken)
000000534703ca40 00007ffefae78009 System.Threading.Tasks.Task.SpinThenBlockingWait(Int32, System.Threading.CancellationToken)
000000534703cab0 00007ffefb724831 System.Threading.Tasks.Task.InternalWait(Int32, System.Threading.CancellationToken)
000000534703cb80 00007ffefae77e49 System.Threading.Tasks.Task.Wait(Int32, System.Threading.CancellationToken)
000000534703cbb0 00007ffefb724630 System.Threading.Tasks.Task.Wait(System.TimeSpan)
000000534703cbe0 00007ffe9fff9182 IntegrationTests.Helpers.Models.Container.Dispose()
000000534703cc20 00007ffe9fe28f3e IntegrationTests.AspNetTests+d__2.MoveNext()
000000534703cc70 00007ffe9fe28e5b IntegrationTests.AspNetTests+d__2.MoveNext()
000000534703cd20 00007ffefae4e9a8 System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object, Boolean)
000000534703cdf0 00007ffefae4e895 System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object, Boolean)
000000534703ce20 00007ffefaeacc8f System.Runtime.CompilerServices.AsyncMethodBuilderCore+MoveNextRunner.Run()
000000534703ce70 00007ffefaeb1ad3 System.Threading.Tasks.AwaitTaskContinuation.RunOrScheduleAction(System.Action, Boolean, System.Threading.Tasks.Task ByRef)
000000534703cec0 00007ffefae2b900 System.Threading.Tasks.Task.FinishContinuations()
000000534703cf50 00007ffefae31788 System.Threading.Tasks.Task`1[[System.__Canon, mscorlib]].TrySetResult(System.__Canon)
000000534703cf90 00007ffefaeabfb3 System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1[[System.__Canon, mscorlib]].SetResult(System.__Canon)
000000534703cfe0 00007ffe9fa7f667 System.Net.Http.HttpClient+d__58.MoveNext()
000000534703d0b0 00007ffefae4e9a8 System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object, Boolean)
000000534703d180 00007ffefae4e895 System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object, Boolean)
000000534703d1b0 00007ffefaeacc8f System.Runtime.CompilerServices.AsyncMethodBuilderCore+MoveNextRunner.Run()
000000534703d200 00007ffefaeb1ad3 System.Threading.Tasks.AwaitTaskContinuation.RunOrScheduleAction(System.Action, Boolean, System.Threading.Tasks.Task ByRef)
000000534703d250 00007ffefae2b900 System.Threading.Tasks.Task.FinishContinuations()
000000534703d2e0 00007ffefaeb0a55 System.Threading.Tasks.Task`1[[System.Threading.Tasks.VoidTaskResult, mscorlib]].TrySetResult(System.Threading.Tasks.VoidTaskResult)
000000534703d310 00007ffefaeab794 System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1[[System.Threading.Tasks.VoidTaskResult, mscorlib]].SetResult(System.Threading.Tasks.VoidTaskResult)
000000534703d350 00007ffefaeab7d4 System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1[[System.Threading.Tasks.VoidTaskResult, mscorlib]].SetResult(System.Threading.Tasks.Task`1)
000000534703d380 00007ffe9fb82ffd System.Net.Http.HttpContent+d__49.MoveNext()
000000534703d400 00007ffefae4e9a8 System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object, Boolean)
000000534703d4d0 00007ffefae4e895 System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object, Boolean)
000000534703d500 00007ffefaeacc8f System.Runtime.CompilerServices.AsyncMethodBuilderCore+MoveNextRunner.Run()
000000534703d550 00007ffefaeb1ad3 System.Threading.Tasks.AwaitTaskContinuation.RunOrScheduleAction(System.Action, Boolean, System.Threading.Tasks.Task ByRef)
000000534703d5a0 00007ffefae2b900 System.Threading.Tasks.Task.FinishContinuations()
000000534703d630 00007ffefae77614 System.Threading.Tasks.Task.Finish(Boolean)
000000534703d690 00007ffefae78ae7 System.Threading.Tasks.Task.ExecuteWithThreadLocal(System.Threading.Tasks.Task ByRef)
000000534703d740 00007ffefae77b91 System.Threading.Tasks.Task.ExecuteEntry(Boolean)
000000534703d780 00007ffefaeaea52 System.Threading.Tasks.ThreadPoolTaskScheduler.TryExecuteTaskInline(System.Threading.Tasks.Task, Boolean)
000000534703d7d0 00007ffefaeae926 System.Threading.Tasks.TaskScheduler.TryRunInline(System.Threading.Tasks.Task, Boolean)
000000534703d870 00007ffefaeae5c6 System.Threading.Tasks.TaskContinuation.InlineIfPossibleOrElseQueue(System.Threading.Tasks.Task, Boolean)
000000534703d900 00007ffefae2b5fe System.Threading.Tasks.Task.FinishContinuations()
000000534703d990 00007ffefaeb0a55 System.Threading.Tasks.Task`1[[System.Threading.Tasks.VoidTaskResult, mscorlib]].TrySetResult(System.Threading.Tasks.VoidTaskResult)
000000534703d9c0 00007ffefaeab794 System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1[[System.Threading.Tasks.VoidTaskResult, mscorlib]].SetResult(System.Threading.Tasks.VoidTaskResult)
000000534703da00 00007ffefaeab7d4 System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1[[System.Threading.Tasks.VoidTaskResult, mscorlib]].SetResult(System.Threading.Tasks.Task`1)
000000534703da30 00007ffefb881503 System.IO.Stream+d__27.MoveNext()
000000534703dae0 00007ffefae4e9a8 System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object, Boolean)
000000534703dbb0 00007ffefae4e895 System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object, Boolean)
000000534703dbe0 00007ffefaeacc8f System.Runtime.CompilerServices.AsyncMethodBuilderCore+MoveNextRunner.Run()
000000534703dc30 00007ffefaeb1ad3 System.Threading.Tasks.AwaitTaskContinuation.RunOrScheduleAction(System.Action, Boolean, System.Threading.Tasks.Task ByRef)
000000534703dc80 00007ffefae2b900 System.Threading.Tasks.Task.FinishContinuations()
000000534703dd10 00007ffefaeb25cd System.Threading.Tasks.Task`1[[System.Int32, mscorlib]].TrySetResult(Int32)
000000534703dd50 00007ffefb8b92c5 System.Threading.Tasks.TaskFactory`1+FromAsyncTrimPromise`1[[System.Int32, mscorlib],[System.__Canon, mscorlib]].Complete(System.__Canon, System.Func`3, System.IAsyncResult, Boolean)
000000534703dd90 00007ffefb8b93e3 System.Threading.Tasks.TaskFactory`1+FromAsyncTrimPromise`1[[System.Int32, mscorlib],[System.__Canon, mscorlib]].CompleteFromAsyncResult(System.IAsyncResult)
000000534703ddf0 00007ffe9fa8f20f System.Net.LazyAsyncResult.Complete(IntPtr)
000000534703de40 00007ffefae4e9a8 System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object, Boolean)
000000534703df10 00007ffefae4e895 System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object, Boolean)
000000534703df40 00007ffefae4e865 System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object)
000000534703df90 00007ffe9fa8f159 System.Net.ContextAwareResult.Complete(IntPtr)
000000534703dfe0 00007ffe9fa8eff6 System.Net.LazyAsyncResult.ProtectedInvokeCallback(System.Object, IntPtr)
000000534703e020 00007ffe9fa8e705 System.Net.Sockets.BaseOverlappedAsyncResult.CompletionPortCallback(UInt32, UInt32, System.Threading.NativeOverlapped*)
000000534703e090 00007ffefaeadae4 System.Threading._IOCompletionCallback.PerformIOCompletionCallback(UInt32, UInt32, System.Threading.NativeOverlapped*)
000000534703e230 00007ffefe260e73 [GCFrame: 000000534703e230] 
000000534703e428 00007ffefe260e73 [DebuggerU2MCatchHandlerFrame: 000000534703e428] 
000000534703e5a8 00007ffefe260e73 [ContextTransitionFrame: 000000534703e5a8] 
000000534703e7a8 00007ffefe260e73 [DebuggerU2MCatchHandlerFrame: 000000534703e7a8]

On thread 21, I see a successful HTML string, which mean Output.WriteLine(content); got executed successfully.

        using var container = await StartContainerAsync(testSettings, webPort);

        var client = new HttpClient();
        var response = await client.GetAsync($"http://localhost:{webPort}");
        var content = await response.Content.ReadAsStringAsync();
        Output.WriteLine("Sample response:");
        Output.WriteLine(content);

       collector.AssertExpectations();

There are no traces in the dumps to understand what happened to collector.AssertExpectations(). We might need to figure it out with available information.

Test public async Task SubmitMetrics() is async which makes it difficult to debug. Maybe we need to change this as sync test to find an issue.

pellared commented 2 years ago

I think that it hangs here: https://github.com/open-telemetry/opentelemetry-dotnet-instrumentation/blob/20194d16b965cd90ef9587c3c2f968e02b8f2d24/test/IntegrationTests/Helpers/Models/Container.cs#L36

I guess that it is some problem that stopping the container takes too long (it should be killed after 15 sec). It might be a bug in Testcontainers. Someone would have to take a closer look.

Kielek commented 2 years ago

Main is green last 13 days. Closing.