Stack overflow and Consistency check failed: FAILED: m_crawl.pFrame->IsTransitionToNativeFrame() in System.Runtime.Tests

[ViktorHofer]

Configuration: net6.0-Linux-Release-arm-CoreCLR_checked-(Ubuntu.1804.Arm32.Open)Ubuntu.1804.Armarch.Open@mcr.microsoft.com/dotnet-buildtools/prereqs:ubuntu-18.04-helix-arm32v7-bfcd90a-20200121150440

Console: https://helixre8s23ayyeko0k025g8.blob.core.windows.net/dotnet-runtime-refs-pull-57763-merge-f9442c68757543d495/System.Runtime.Tests/1/console.81cb9a1a.log?sv=2019-07-07&se=2021-09-08T23%3A47%3A52Z&sr=c&sp=rl&sig=O8X65xyK97R0N0ZIYbdqG%2Fw638FV2%2F7WZ3Ivju0NF5E%3D

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

Dump available

  Discovering: System.Runtime.Tests (method display = ClassAndMethod, method display options = None)
  Discovered:  System.Runtime.Tests (found 6216 of 6260 test cases)
  Starting:    System.Runtime.Tests (parallel test collections = on, max threads = 4)
    System.Tests.UIntPtrTests.GetHashCodeRespectAllBits [SKIP]
      Condition(s) not met: "Is64Bit"
    System.Tests.UIntPtrTests.Subtract [SKIP]
      Condition(s) not met: "Is64Bit"
    System.Tests.UIntPtrTests.TestCtor_VoidPointer_ToPointer [SKIP]
      Condition(s) not met: "Is64Bit"
    System.Tests.UIntPtrTests.Add [SKIP]
      Condition(s) not met: "Is64Bit"
    System.Tests.UIntPtrTests.TestSize [SKIP]
      Condition(s) not met: "Is64Bit"
    System.Tests.UIntPtrTests.Ctor_ULong [SKIP]
      Condition(s) not met: "Is64Bit"
    System.Tests.UIntPtrTests.TestImplicitCast [SKIP]
      Condition(s) not met: "Is64Bit"
    System.Tests.IntPtrTests.Size [SKIP]
      Condition(s) not met: "Is64Bit"
    System.Tests.IntPtrTests.Add [SKIP]
      Condition(s) not met: "Is64Bit"
    System.Tests.IntPtrTests.Subtract [SKIP]
      Condition(s) not met: "Is64Bit"
    System.Tests.IntPtrTests.ImplicitCast [SKIP]
      Condition(s) not met: "Is64Bit"
    System.Tests.IntPtrTests.GetHashCodeRespectAllBits [SKIP]
      Condition(s) not met: "Is64Bit"
    System.Tests.IntPtrTests.Ctor_VoidPointer_ToPointer [SKIP]
      Condition(s) not met: "Is64Bit"
    System.Tests.IntPtrTests.Ctor_Long [SKIP]
      Condition(s) not met: "Is64Bit"
    System.Tests.StringTests.IndexOf_SingleLetter(s: "Hello", target: '\0', startIndex: 0, count: 5, expected: -1) [SKIP]
      Target \0 is not supported in ICU
Stack overflow.

Assert failure(PID 58 [0x0000003a], Thread: 76 [0x004c]): Consistency check failed: FAILED: m_crawl.pFrame->IsTransitionToNativeFrame()
    File: /__w/1/s/src/coreclr/vm/stackwalk.cpp Line: 2269
    Image: /root/helix/work/correlation/dotnet

./RunTests.sh: line 162:    58 Aborted                 (core dumped) "$RUNTIME_PATH/dotnet" exec --runtimeconfig System.Runtime.Tests.runtimeconfig.json --depsfile System.Runtime.Tests.deps.json xunit.console.dll System.Runtime.Tests.dll -xml testResults.xml -nologo -nocolor -notrait category=IgnoreForCI -notrait category=OuterLoop -notrait category=failing $RSP_FILE
/root/helix/work/workitem
----- end Thu Aug 19 23:53:10 UTC 2021 ----- exit code 134 ----------------------------------------------------------
exit code 134 means SIGABRT Abort. Managed or native assert, or runtime check such as heap corruption, caused call to abort(). Core dumped.

@jkotas who would be the best person to look into this?

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.

[jkotas]

The assert is hit while trying to log stackoverflow stacktrace:

#9  0xf5b3248c in DbgAssertDialog (szFile=0xf5d0c855 "/__w/1/s/src/coreclr/vm/stackwalk.cpp", iLine=2269, szExpr=0x0)
    at /__w/1/s/src/coreclr/pal/inc/pal.h:3362
#10 0xf5b19c38 in CHECK::Trigger (this=0xe32fd240, reason=<optimized out>)
    at /__w/1/s/src/coreclr/utilcode/check.cpp:139
#11 0xf58faae6 in StackFrameIterator::NextRaw (this=0xe32fd438) at /__w/1/s/src/coreclr/vm/stackwalk.cpp:2269
#12 0xf58f93ae in StackFrameIterator::Next (this=0xe32fd438) at /__w/1/s/src/coreclr/vm/stackwalk.cpp:1559
#13 0xf58f8cce in Thread::StackWalkFramesEx (this=0x96a9078, pRD=0xe32fd730, pCallback=
    0xf5991539 <CallStackLogger::LogCallstackForLogCallback(CrawlFrame*, void*)>, pData=0xe32fdd10, flags=265,
    pStartFrame=0x0) at /__w/1/s/src/coreclr/vm/stackwalk.cpp:917
#14 0xf58f950e in Thread::StackWalkFrames (this=0x96a9078,
    pCallback=0xf5991539 <CallStackLogger::LogCallstackForLogCallback(CrawlFrame*, void*)>, pData=0xe32fdd10,
    flags=265, pStartFrame=0x0) at /__w/1/s/src/coreclr/vm/stackwalk.cpp:994
#15 0xf59913cc in LogCallstackForLogWorker (pThread=0x96a9078) at /__w/1/s/src/coreclr/vm/eepolicy.cpp:326
#16 0xf5991138 in LogStackOverflowStackTraceThread (arg=0x0) at /__w/1/s/src/coreclr/vm/eepolicy.cpp:606
#17 0xf5cb429c in CorUnix::CPalThread::ThreadEntry (pvParam=0xe58594d0)
    at /__w/1/s/src/coreclr/pal/src/thread/thread.cpp:1862
#18 0xf6213614 in start_thread (arg=0x149ee6a1) at pthread_create.c:463

[jkotas]

Unmanaged stacktrace of the thread that hit stack overflow:

(gdb) bt
#0  __libc_do_syscall () at ../sysdeps/unix/sysv/linux/arm/libc-do-syscall.S:46
#1  0xf6218072 in futex_wait_cancelable (private=<optimized out>, expected=0, futex_word=0x9752a04) at ../sysdeps/unix/sysv/linux/futex-internal.h:88
#2  __pthread_cond_wait_common (abstime=0x0, mutex=0x97529c0, cond=0x97529d8) at pthread_cond_wait.c:502
#3  __pthread_cond_wait (cond=0x97529d8, mutex=0x97529c0) at pthread_cond_wait.c:655
#4  0xf5ca2986 in CorUnix::CPalSynchronizationManager::ThreadNativeWait (ptnwdNativeWaitData=0x97529c0, dwTimeout=4294967295, ptwrWakeupReason=0xf4fa568c,
    pdwSignaledObject=0xf4fa5688) at /__w/1/s/src/coreclr/pal/src/synchmgr/synchmanager.cpp:478
#5  0xf5ca2162 in CorUnix::CPalSynchronizationManager::BlockThread (this=0x95e1380, pthrCurrent=0x97528a0, dwTimeout=4294967295, fAlertable=false, fIsSleep=<optimized out>,
    ptwrWakeupReason=0xf4fa56f8, pdwSignaledObject=0xf4fa56fc) at /__w/1/s/src/coreclr/pal/src/synchmgr/synchmanager.cpp:301
#6  0xf5ca97c6 in CorUnix::InternalWaitForMultipleObjectsEx (pThread=0x97528a0, nCount=<optimized out>, lpHandles=0xf4fa57c0, bWaitAll=<optimized out>,
    dwMilliseconds=4294967295, bAlertable=0, bPrioritize=0) at /__w/1/s/src/coreclr/pal/src/synchmgr/wait.cpp:637
#7  0xf5ca8e64 in WaitForSingleObject (hHandle=0x48c, dwMilliseconds=4294967295) at /__w/1/s/src/coreclr/pal/src/synchmgr/wait.cpp:80
#8  0xf5990796 in EEPolicy::HandleFatalStackOverflow (pExceptionInfo=0xf4fa5c3c, fSkipDebugger=0) at /__w/1/s/src/coreclr/vm/eepolicy.cpp:654
#9  0xf5a84126 in HandleHardwareException (ex=0xf4fa5c3c) at /__w/1/s/src/coreclr/vm/exceptionhandling.cpp:5221
#10 0xf5c5b62c in SEHProcessException (exception=0xf4fa5c3c) at /__w/1/s/src/coreclr/pal/src/exception/seh.cpp:267
#11 0xf5c5cdde in common_signal_handler (code=<optimized out>, siginfo=<optimized out>, sigcontext=0xe6cbed10, numParams=<optimized out>)
    at /__w/1/s/src/coreclr/pal/src/exception/signal.cpp:982
#12 0xf5c5cc18 in signal_handler_worker (code=1073741835, siginfo=0xe6cbec90, context=0xe6cbed10, returnPoint=0xe6cbea88)
    at /__w/1/s/src/coreclr/pal/src/exception/signal.cpp:507
#13 <signal handler called>
#14 0xe74bbe38 in ?? ()

Managed stacktrace (partially unwound):

Child SP       IP Call Site
F4FA5820 00000000 [FaultingExceptionFrame: f4fa5820]
E74BCBE8 e88307ba [DebuggerU2MCatchHandlerFrame: e74bcbe8]
E74BCCA4 e88307ba [HelperMethodFrame_PROTECTOBJ: e74bcca4] System.RuntimeMethodHandle.InvokeMethod(System.Object, System.Span`1<System.Object> ByRef, System.Signature, Boolean, Boolean)
E74BCD48 E88307BA System.Reflection.RuntimeMethodInfo.Invoke(System.Object, System.Reflection.BindingFlags, System.Reflection.Binder, System.Object[], System.Globalization.CultureInfo)
E74BCDA8 E87DCD0E System.Reflection.MethodBase.Invoke(System.Object, System.Object[])
E74BCDB8 E5BE05A0 Xunit.Sdk.TestInvoker`1[[System.__Canon, System.Private.CoreLib]].CallTestMethod(System.Object) [C:\Dev\xunit\xunit\src\xunit.execution\Sdk\Frameworks\Runners\TestInvoker.cs @ 150]
...

[jkotas]

The thread was executing System.Tests.TimeZoneInfoTests.GetAmbiguousTimeOffsets_Invalid() method.

The signal context has LR pointing into Xunit.Assert.RecordException(System.Func<System.Object>) right after return from the testCode delegate. PC is pointing at invalid instruction. I think we have somehow returned to invalid PC inside the testCode delegate and the stackoverflow is just a side-effect of executing bogus instructions. I am not able to tell how we ended up with the invalid PC.

[gbalykov]

I think I face the same issue on JIT/Regression/VS-ia64-JIT/V2.0-Beta2/b311420/b311420 clr test on armel. Reproduces on v5.0.0-preview.4.20251.6, v5.0.0-preview.7.20364.11, v5.0.0-rtm.20519.4, v6.0.0-preview.1.21102.12, 6.0-preview7, v6.0.0 and 7.0 (master). This test only crashes from time to time.

Error:

      Stack overflow.
      at NullableTest.And()
      at NullableTest.Run()
      at Test.Main()

With debug runtime assert fires:

Assert failure(PID 11324 [0x00002c3c], Thread: 11676 [0x2d9c]): Consistency check failed: FAILED: m_crawl.pFrame->IsTransitionToNativeFrame()
    File: /home/abuild/rpmbuild/BUILD/coreclr-6.0.0/src/coreclr/vm/stackwalk.cpp Line: 2269
    Image: /usr/share/dotnet/shared/Microsoft.NETCore.App/6.0.0/corerun

[mangod9]

@ViktorHofer is it ok to close this, and reopen if it still occurs?