System.Private.Uri.Functional.Tests crash in CI

[jkotas]

Hit by #63935 (comment)

https://dev.azure.com/dnceng/public/_build/results?buildId=1558792&view=ms.vss-test-web.build-test-results-tab&runId=43920258&paneView=dotnet-dnceng.dnceng-build-release-tasks.helix-test-information-tab&resultId=186001

I couldn't figure out the best area label to add to this issue. If you have write-permissions please help me learn by adding exactly one area label.

[janvorli]

The crash happened due to the timeout of the thread suspension:

* thread #1, name = 'dotnet', stop reason = signal SIGABRT
  * frame #0: 0x00007ff72070bfb7 libc.so.6`__GI_raise(sig=<unavailable>) at raise.c:51
    frame #1: 0x00007ff72070d921 libc.so.6`__GI_abort at abort.c:79
    frame #2: 0x00007ff7205d3c3b libcoreclr.so`::PROCAbort(signal=<unavailable>) at process.cpp:3455:5
    frame #3: 0x00007ff720567bac libcoreclr.so`sigtrap_handler(int, siginfo_t*, void*) [inlined] invoke_previous_action(action=<unavailable>, code=<unavailable>, siginfo=<unavailable>, context=<unavailable>, signalRestarts=<unavailable>) at signal.cpp:414:13
    frame #4: 0x00007ff720567ba4 libcoreclr.so`sigtrap_handler(code=<unavailable>, siginfo=<unavailable>, context=<unavailable>) at signal.cpp:664:5
    frame #5: 0x00007ff721613980 libpthread.so.0`__restore_rt
    frame #6: 0x00007ff7205df8f1 libcoreclr.so`DBG_DebugBreak at debugbreak.S:9
    frame #7: 0x00007ff720565467 libcoreclr.so`::DebugBreak() at debug.cpp:406:9
    frame #8: 0x00007ff72028f909 libcoreclr.so`ThreadSuspend::SuspendRuntime(reason=<unavailable>) at threadsuspend.cpp:3576:17
    frame #9: 0x00007ff72029212e libcoreclr.so`ThreadSuspend::SuspendEE(reason=SUSPEND_OTHER) at threadsuspend.cpp:5707:5
    frame #10: 0x00007ff71ff61822 libcoreclr.so`CallCountingManager::StopAndDeleteAllCallCountingStubs() at callcounting.cpp:961:5
    frame #11: 0x00007ff7200cc688 libcoreclr.so`TieredCompilationManager::DoBackgroundWork(this=0x000056086c22c5c0, workDurationTicksRef=0x00007ff71c412bf0, minWorkDurationTicks=2000000, maxWorkDurationTicks=50000000) at tieredcompilation.cpp:861:13
    frame #12: 0x00007ff7200cb028 libcoreclr.so`TieredCompilationManager::BackgroundWorkerStart(this=0x000056086c22c5c0) at tieredcompilation.cpp:483:14
    frame #13: 0x00007ff7200cae73 libcoreclr.so`TieredCompilationManager::BackgroundWorkerBootstrapper1((null)=<unavailable>) at tieredcompilation.cpp:431:52
    frame #14: 0x00007ff7200c51fe libcoreclr.so`ManagedThreadBase_DispatchOuter(ManagedThreadCallState*) [inlined] ManagedThreadBase_DispatchInner(pCallState=<unavailable>) at threads.cpp:7317:5
    frame #15: 0x00007ff7200c51f7 libcoreclr.so`ManagedThreadBase_DispatchOuter(ManagedThreadCallState*) at threads.cpp:7361:9
    frame #16: 0x00007ff7200c50f1 libcoreclr.so`ManagedThreadBase_DispatchOuter(ManagedThreadCallState*) [inlined] ManagedThreadBase_DispatchOuter(this=<unavailable>, pParam=<unavailable>)::$_6::operator()(ManagedThreadBase_DispatchOuter(ManagedThreadCallState*)::TryArgs*) const::'lambda'(Param*)::operator()(Param*) const at threads.cpp:7519:13
    frame #17: 0x00007ff7200c50ed libcoreclr.so`ManagedThreadBase_DispatchOuter(ManagedThreadCallState*) at threads.cpp:7521:9
    frame #18: 0x00007ff7200c5073 libcoreclr.so`ManagedThreadBase_DispatchOuter(pCallState=<unavailable>) at threads.cpp:7545:5
    frame #19: 0x00007ff7200c59cd libcoreclr.so`ManagedThreadBase::KickOff(void (*)(void*), void*) [inlined] ManagedThreadBase_FullTransition(pTarget=<unavailable>, args=<unavailable>, filterType=ManagedThread)(void*), void*, UnhandledExceptionLocation) at threads.cpp:7565:5
    frame #20: 0x00007ff7200c59b5 libcoreclr.so`ManagedThreadBase::KickOff(pTarget=<unavailable>, args=<unavailable>)(void*), void*) at threads.cpp:7600:5
    frame #21: 0x00007ff7200cadd0 libcoreclr.so`TieredCompilationManager::BackgroundWorkerBootstrapper0(args=0x000056086c25a690) at tieredcompilation.cpp:412:5
    frame #22: 0x00007ff7205db722 libcoreclr.so`CorUnix::CPalThread::ThreadEntry(pvParam=0x000056086c25ef20) at thread.cpp:1829:16
    frame #23: 0x00007ff7216086db libpthread.so.0`start_thread(arg=0x00007ff71c413700) at pthread_create.c:463
    frame #24: 0x00007ff7207ee71f libc.so.6`__clone at clone.S:95

It seems that the shutdown might have taken extended time. I can see that the thread that was shutting down (thread 0x5250, number 6 in the debugger list) was in cooperative GC mode. So the suspension had to wait for it.

(lldb) p *(Thread*)0x00056086C245540
(Thread) $1 = {
  m_stackLocalAllocator = nullptr
  m_State = (m_val = 131618)
  m_fPreemptiveGCDisabled = (m_val = 1)

[janvorli]

And we actually switch the thread to the cooperative mode intentionally (you can see that the EEShutdownHelper was called from the line 1668):

runtime/src/coreclr/vm/ceemain.cpp

Lines 1665 to 1673 in 83b52cd

	if (GetThreadNULLOk())
	{
	GCX_COOP();
	EEShutDownHelper(fIsDllUnloading);
	}
	else
	{
	EEShutDownHelper(fIsDllUnloading);
	}

Here is the stack trace of the thread that's shutting down for more clarity:

* thread #6, stop reason = signal 0
  * frame #0: 0x00007ff71c84e630 libclrjit.so`inject_activation_handler(code=34, siginfo=0x00007ffe20182370, context=0x00007ffe20182240) at signal.cpp:786
    frame #1: 0x00007ff721613980 libpthread.so.0`__restore_rt
    frame #2: 0x00007ff7207dee17 libc.so.6`unlink at syscall-template.S:78
    frame #3: 0x00007ff72042af09 libcoreclr.so`ds_ipc_close(ipc=0x000056086c214700, is_shutdown=<unavailable>, callback=(libcoreclr.so`server_error_callbackse(char const*, unsigned int) at ds-server.c:88))(char const*, unsigned int)) at ds-ipc-pal-socket.c:1304:19
    frame #4: 0x00007ff720534725 libcoreclr.so`ds_ipc_stream_factory_shutdown(void (*)(char const*, unsigned int)) [inlined] ds_port_close(port=0x000056086c10, is_shutdown=true, callback=(libcoreclr.so`server_error_callback_close(char const*, unsigned int) at ds-server.c:88))(char const*, unsigned int)) at ds-i:617:3
    frame #5: 0x00007ff7205346ed libcoreclr.so`ds_ipc_stream_factory_shutdown(callback=(libcoreclr.so`server_error_callback_close(char const*, unsigned int)ds-server.c:88))(char const*, unsigned int)) at ds-ipc.c:514:3
    frame #6: 0x00007ff720534609 libcoreclr.so`ds_server_shutdown() at ds-server.c:247:3
    frame #7: 0x00007ff7205499cd libcoreclr.so`EEShutDownHelper(int) [inlined] DiagnosticServerAdapter::Shutdown() at diagnosticserveradapter.h:21:10
    frame #8: 0x00007ff7205499c8 libcoreclr.so`EEShutDownHelper(fIsDllUnloading=NO) at ceemain.cpp:1200:9
    frame #9: 0x00007ff72054a747 libcoreclr.so`EEShutDown(fIsDllUnloading=NO) at ceemain.cpp:1668:9
    frame #10: 0x00007ff71ffa5da6 libcoreclr.so`CorHost2::UnloadAppDomain2(this=<unavailable>, dwDomainId=<unavailable>, fWaitUntilDone=<unavailable>, pLatcxitCode=0x00007ffe201832b0) at corhost.cpp:902:13
    frame #11: 0x00007ff71ff36e12 libcoreclr.so`::coreclr_shutdown_2(hostHandle=<unavailable>, domainId=<unavailable>, latchedExitCode=<unavailable>) at unierface.cpp:357:24
    frame #12: 0x00007ff72198b5df libhostpolicy.so`___lldb_unnamed_symbol452 + 111
    frame #13: 0x00007ff72199975a libhostpolicy.so`___lldb_unnamed_symbol531 + 1386
    frame #14: 0x00007ff721999bc1 libhostpolicy.so`___lldb_unnamed_symbol532 + 49
    frame #15: 0x00007ff72199a5ec libhostpolicy.so`corehost_main + 172
    frame #16: 0x00007ff7219f4a34 libhostfxr.so`___lldb_unnamed_symbol457 + 1812
    frame #17: 0x00007ff7219f3139 libhostfxr.so`___lldb_unnamed_symbol455 + 665
    frame #18: 0x00007ff7219ee5eb libhostfxr.so`hostfxr_main_startupinfo + 171
    frame #19: 0x000056086ac3d65a dotnet`___lldb_unnamed_symbol464 + 938
    frame #20: 0x000056086ac3dad0 dotnet`___lldb_unnamed_symbol465 + 144
    frame #21: 0x00007ff7206eebf7 libc.so.6`__libc_start_main(main=(dotnet`___lldb_unnamed_symbol465), argc=18, argv=0x00007ffe20183868, init=<unavailable>,i=<unavailable>, rtld_fini=<unavailable>, stack_end=0x00007ffe20183858) at libc-start.c:310
    frame #22: 0x000056086ac32029 dotnet`___lldb_unnamed_symbol339 + 41

[janvorli]

@jkotas do you know why we run the EEShutdownHelper in GC cooperative mode when the current thread exists?

[jkotas]

No idea. It sounds like ds_server_shutdown at least should be running in preemptive mode.

[janvorli]

I have thought the same.

[janvorli]

cc: @dotnet/dotnet-diag