Assert in TlsObjectDestructor

[christianscheuer]

I'm hitting an assert in [PalRedhawkUnix.cpp line 420]:(

corert/src/Native/Runtime/unix/PalRedhawkUnix.cpp

Line 420 in 65846c0

ASSERT(data == pthread_getspecific(g_threadKey));

)

// Destructor of the thread local object represented by the g_threadKey,
// called when a thread is shut down
void TlsObjectDestructor(void* data)
{
    ASSERT(data == pthread_getspecific(g_threadKey));

    RuntimeThreadShutdown(data);
}

Stacktraces:

  2712 Thread_1001544   DispatchQueue_1: com.apple.main-thread  (serial)
    + 2712 start  (in libdyld.dylib) + 1  [0x7fff9472b5c9]
    +   2712 main  (in demoapp) + 258  [0x100014242]
    +     2712 __managed__Main  (in demoapp) + 87  [0x100128893]
    +       2712 src_DemoApp_Program__Main  (in demoapp) + 106  [0x10013006e]
    +         2712 src_Mac_CoreFoundation_CFRunLoop__CFRunLoopRun  (in demoapp) + 33  [0x10013083d]
    +           2712 CFRunLoopRun  (in CoreFoundation) + 97  [0x7fff8e62c671]
    +             2712 CFRunLoopRunSpecific  (in CoreFoundation) + 296  [0x7fff8e574bd8]
    +               2712 __CFRunLoopRun  (in CoreFoundation) + 1371  [0x7fff8e57537b]
    +                 2712 __CFRunLoopServiceMachPort  (in CoreFoundation) + 212  [0x7fff8e575eb4]
    +                   2712 mach_msg  (in libsystem_kernel.dylib) + 55  [0x7fff987bd64f]
    +                     2712 mach_msg_trap  (in libsystem_kernel.dylib) + 10  [0x7fff987be4de]
    5424 Thread_<multiple>   DispatchQueue_10: com.apple.root.default-qos  (serial)
    + 5424 start_wqthread  (in libsystem_pthread.dylib) + 13  [0x7fff919f03dd]
    +   5424 _pthread_wqthread  (in libsystem_pthread.dylib) + 729  [0x7fff919f2a9d]
    +     5424 _dispatch_worker_thread3  (in libdispatch.dylib) + 91  [0x7fff8c24ea1c]
    +       5424 _dispatch_root_queue_drain  (in libdispatch.dylib) + 935  [0x7fff8c24edc7]
    +         5424 _dispatch_client_callout  (in libdispatch.dylib) + 8  [0x7fff8c24be73]
    +           5424 src_Mac_CoreFoundation_DispatchQueue__static_dispatcher_to_managed  (in demoapp) + 137  [0x100176ad1]
    +             2712 src_DemoApp_CommunicationService__ConsoleReader  (in demoapp) + 16  [0x10014cfc0]
    +               2712 System_Console_System_IO_SyncTextReader__ReadLine  (in demoapp) + 61  [0x100201705]
    +                 2712 System_Console_System_IO_StdInReader__ReadLine_0  (in demoapp) + 122  [0x10024107a]
    +                   2712 System_Console_System_IO_StdInReader__ReadKey  (in demoapp) + 256  [0x10027c31c]
    +                     2712 System_Console_Interop_Sys__ReadStdin  (in demoapp) + 66  [0x10029c4e2]
    +                       2712 read  (in libsystem_kernel.dylib) + 10  [0x7fff987c4682]
    2712 Thread_1001575   DispatchQueue_2: com.apple.libdispatch-manager  (serial)
    + 2712 _dispatch_mgr_thread  (in libdispatch.dylib) + 52  [0x7fff8c25026e]
    +   2712 kevent64  (in libsystem_kernel.dylib) + 10  [0x7fff987c4232]
    2712 Thread_1001576
    + 2712 start_wqthread  (in libsystem_pthread.dylib) + 13  [0x7fff919f03dd]
    +   2712 _pthread_wqthread  (in libsystem_pthread.dylib) + 879  [0x7fff919f2b33]
    +     2712 _pthread_exit  (in libsystem_pthread.dylib) + 117  [0x7fff919f2460]
    +       2712 _pthread_tsd_cleanup  (in libsystem_pthread.dylib) + 86  [0x7fff919f2739]
    +         2712 TlsObjectDestructor(void*)  (in demoapp) + 76  [0x10010b80c]
    +           2712 Assert(char const*, char const*, unsigned int, char const*)  (in demoapp) + 19  [0x100016163]
    2712 Thread_1001579
    + 2712 start_wqthread  (in libsystem_pthread.dylib) + 13  [0x7fff919f03dd]
    +   2712 __workq_kernreturn  (in libsystem_kernel.dylib) + 10  [0x7fff987c394a]
    2712 Thread_1001580
    + 2712 thread_start  (in libsystem_pthread.dylib) + 13  [0x7fff919f03ed]
    +   2712 _pthread_start  (in libsystem_pthread.dylib) + 176  [0x7fff919f2fd7]
    +     2712 _pthread_body  (in libsystem_pthread.dylib) + 131  [0x7fff919f305a]
    +       2712 FinalizerStart(void*)  (in demoapp) + 170  [0x10001d15a]
    +         2712 ProcessFinalizers  (in demoapp) + 52  [0x1001294f0]
    +           2712 RhpWaitForFinalizerRequest  (in demoapp) + 45  [0x100018d2d]
    +             2712 PalWaitForSingleObjectEx(void*, unsigned int, unsigned int)  (in demoapp) + 33  [0x10001e3a1]
    +               2712 WaitForSingleObjectEx  (in demoapp) + 105  [0x10010cd29]
    +                 2712 UnixEvent::Wait(unsigned int)  (in demoapp) + 207  [0x10010e38f]
    +                   2712 __psynch_cvwait  (in libsystem_kernel.dylib) + 10  [0x7fff987c3136]
    2712 Thread_1001585
    + 2712 thread_start  (in libsystem_pthread.dylib) + 13  [0x7fff919f03ed]
    +   2712 _pthread_start  (in libsystem_pthread.dylib) + 176  [0x7fff919f2fd7]
    +     2712 _pthread_body  (in libsystem_pthread.dylib) + 131  [0x7fff919f305a]
    +       2712 read  (in libsystem_kernel.dylib) + 10  [0x7fff987c4682]
    2712 Thread_1001748
      2712 start_wqthread  (in libsystem_pthread.dylib) + 13  [0x7fff919f03dd]
        2712 __workq_kernreturn  (in libsystem_kernel.dylib) + 10  [0x7fff987c394a]

[janvorli]

Hmm, it actually looks like the assert is wrong. When I was writing this code, I have not noticed the text I have marked with bold in the documentation below:
An optional destructor function may be associated with each key value. At thread exit, if a key value has a non-NULL destructor pointer, and the thread has a non-NULL value associated with that key, the value of the key is set to NULL, and then the function pointed to is called with the previously associated value as its sole argument.

Can you please remove that assert?

[janvorli]

I meant, try to remove it and see if things work.

[christianscheuer]

Thanks, @janvorli. Removing the assert makes it hit a new assert.

thread #9: tid = 0x102c50, 0x00000001000161c3 demoapp`Assert(expr="pCurThread->IsInitialized()", file="/projects/corert/src/Native/Runtime/Full/../threadstore.inl", line_num=20, message=0x0000000000000000) + 19 at rhassert.cpp:25, stop reason = EXC_BAD_INSTRUCTION (code=EXC_I386_INVOP, subcode=0x0)
  * frame #0: 0x00000001000161c3 demoapp`Assert(expr="pCurThread->IsInitialized()", file="/projects/corert/src/Native/Runtime/Full/../threadstore.inl", line_num=20, message=0x0000000000000000) + 19 at rhassert.cpp:25
    frame #1: 0x00000001000348ce demoapp`ThreadStore::GetCurrentThread() + 62 at threadstore.inl:20
    frame #2: 0x000000010003c979 demoapp`RuntimeThreadShutdown(thread=0x0000000101520920) + 25 at startup.cpp:272
    frame #3: 0x000000010010b835 demoapp`TlsObjectDestructor(data=0x0000000101520920) + 21 at PalRedhawkUnix.cpp:422
    frame #4: 0x00007fff919f2739 libsystem_pthread.dylib`_pthread_tsd_cleanup + 86
    frame #5: 0x00007fff919f2460 libsystem_pthread.dylib`_pthread_exit + 117
    frame #6: 0x00007fff919f2b33 libsystem_pthread.dylib`_pthread_wqthread + 879
    frame #7: 0x00007fff919f03dd libsystem_pthread.dylib`start_wqthread + 13

[janvorli]

@christianscheuer could you please check if the pCurThread at frame 1 is equal to the thread parameter at frame 2?
If it is, then please set breakpoint at PalAttachThread, run the app and when you hit the breakpoint, continue if it is not the secondary thread that's causing the issue.
Once you hit it on the secondary thread, please write down the thread address and then step through the code until you reach pAttachingThread->m_ThreadStateFlags = Thread::TSF_Attached; in ThreadStore::AttachCurrentThread. Once you reach it, just let it continue and when you hit the error, see if the thread parameter at frame 2 is equal to the thread address you have written down.

[janvorli]

@christianscheuer alternatively, if you'd be willing to share your testing app source, it might help me to reason about the possible issue or build and debug it localy.

[christianscheuer]

@janvorli They don't seem to be the same.

frame 1:
(Thread *) pCurThread = 0x000000011cd00160

frame 2:
thread = 0x00000001012161b0

I would love to be able to share the code, but what I'm running is a complete closed source app at this point. I'll do a little more digging to see if I can isolate the issue.

[christianscheuer]

The thread in question seems to be a worker thread started by a call to
dispatch_get_global_queue (OSX's Grand Central Dispatch). The worker thread has probably previously executed managed code. By the time this assert happens, it is probably because GCD is shutting down the thread.

[janvorli]

@christianscheuer could you please print the contents of the actual Thread variable pointed to by the pointers at frame 2 and 1? It is very strange that they are different.
The value at frame 2 was originally set in ThreadStore::AttachCurrentThread to the value obtained from RawGetCurrentThread(), which returns an address of a thread local variable tls_CurrentThread.
The value at frame 1 comes from ThreadStore::GetCurrentThread, which also gets it as an address of tls_CurrentThread. So I really don't understand how these two can differ unless OSX calls the TlsObjectDestructor on a different thread, which would be strange.

[christianscheuer]

Stacktrace:

thread #3: tid = 0x12723d, 0x0000000100016303 demoapp`Assert(expr="pCurThread->IsInitialized()", file="/projects/corert/src/Native/Runtime/Full/../threadstore.inl", line_num=20, message=0x0000000000000000) + 19 at rhassert.cpp:25, stop reason = EXC_BAD_INSTRUCTION (code=EXC_I386_INVOP, subcode=0x0)
    frame #0: 0x0000000100016303 demoapp`Assert(expr="pCurThread->IsInitialized()", file="/projects/corert/src/Native/Runtime/Full/../threadstore.inl", line_num=20, message=0x0000000000000000) + 19 at rhassert.cpp:25
    frame #1: 0x0000000100034a0e demoapp`ThreadStore::GetCurrentThread() + 62 at threadstore.inl:20
  * frame #2: 0x000000010003cab9 demoapp`RuntimeThreadShutdown(thread=0x0000000101417250) + 25 at startup.cpp:272
    frame #3: 0x000000010010b975 demoapp`TlsObjectDestructor(data=0x0000000101417250) + 21 at PalRedhawkUnix.cpp:422
    frame #4: 0x00007fff919f2739 libsystem_pthread.dylib`_pthread_tsd_cleanup + 86
    frame #5: 0x00007fff919f2460 libsystem_pthread.dylib`_pthread_exit + 117
    frame #6: 0x00007fff919f2b33 libsystem_pthread.dylib`_pthread_wqthread + 879
    frame #7: 0x00007fff919f03dd libsystem_pthread.dylib`start_wqthread + 13



Value of *pCurThread in frame 1:

(Thread) $0 = {
  ThreadBuffer = {
    m_rgbAllocContextBuffer = {
      [0] = '\0'
      [1] = '\0'
      [2] = '\0'
      [3] = '\0'
      [4] = '\0'
      [5] = '\0'
      [6] = '\0'
      [7] = '\0'
      [8] = '\0'
      [9] = '\0'
      [10] = '\0'
      [11] = '\0'
      [12] = '\0'
      [13] = '\0'
      [14] = '\0'
      [15] = '\0'
      [16] = '\0'
      [17] = '\0'
      [18] = '\0'
      [19] = '\0'
      [20] = '\0'
      [21] = '\0'
      [22] = '\0'
      [23] = '\0'
      [24] = '\0'
      [25] = '\0'
      [26] = '\0'
      [27] = '\0'
      [28] = '\0'
      [29] = '\0'
      [30] = '\0'
      [31] = '\0'
      [32] = '\0'
      [33] = '\0'
      [34] = '\0'
      [35] = '\0'
      [36] = '\0'
      [37] = '\0'
      [38] = '\0'
      [39] = '\0'
      [40] = '\0'
      [41] = '\0'
      [42] = '\0'
      [43] = '\0'
      [44] = '\0'
      [45] = '\0'
      [46] = '\0'
      [47] = '\0'
      [48] = '\0'
      [49] = '\0'
      [50] = '\0'
      [51] = '\0'
      [52] = '\0'
      [53] = '\0'
      [54] = '\0'
      [55] = '\0'
    }
    m_ThreadStateFlags = 0
    m_pTransitionFrame = 0xffffffffffffffff
    m_pHackPInvokeTunnel = 0xffffffffffffffff
    m_pCachedTransitionFrame = 0x0000000000000000
    m_pNext = 0x0000000000000000
    m_hPalThread = 0xffffffffffffffff
    m_ppvHijackedReturnAddressLocation = 0x0000000000000000
    m_pvHijackedReturnAddress = 0x0000000000000000
    m_pExInfoStackHead = 0x0000000000000000
    m_pStackLow = 0x0000000000000000
    m_pStackHigh = 0x0000000000000000
    m_pTEB = 0x0000000000000000
    m_uPalThreadIdForLogging = 0
    m_threadId = {
      m_id = 0x0000000000000000
      m_isValid = false
    }
    m_pThreadStressLog = 0x0000000000000000
    m_uRand = 0
    m_numDynamicTypesTlsCells = 0
    m_pDynamicTypesTlsCells = 0x0000000000000000
    m_pThreadLocalModuleStatics = 0x0000000000000000
    m_numThreadLocalModuleStatics = 0
  }
}




Value of *(Thread*)thread in frame 2:

(Thread) $1 = {
  ThreadBuffer = {
    m_rgbAllocContextBuffer = {
      [0] = '\0'
      [1] = '\0'
      [2] = '\0'
      [3] = '\0'
      [4] = '\0'
      [5] = '\0'
      [6] = '\0'
      [7] = '\0'
      [8] = '\0'
      [9] = '\0'
      [10] = '\0'
      [11] = '\0'
      [12] = '\0'
      [13] = '\0'
      [14] = '\0'
      [15] = '\0'
      [16] = '\x10'
      [17] = '\0'
      [18] = '\0'
      [19] = '\0'
      [20] = '\0'
      [21] = '\0'
      [22] = '\0'
      [23] = '\0'
      [24] = '\0'
      [25] = '\0'
      [26] = '\0'
      [27] = '\0'
      [28] = '\0'
      [29] = '\0'
      [30] = '\0'
      [31] = '\0'
      [32] = '\0'
      [33] = '\0'
      [34] = '\0'
      [35] = '\0'
      [36] = '\0'
      [37] = '\0'
      [38] = '\0'
      [39] = '\0'
      [40] = '\0'
      [41] = '\0'
      [42] = '\0'
      [43] = '\0'
      [44] = '\0'
      [45] = '\0'
      [46] = '\0'
      [47] = '\0'
      [48] = '\0'
      [49] = '\0'
      [50] = '\0'
      [51] = '\0'
      [52] = '\0'
      [53] = '\0'
      [54] = '\0'
      [55] = '\0'
    }
    m_ThreadStateFlags = 1
    m_pTransitionFrame = 0xffffffffffffffff
    m_pHackPInvokeTunnel = 0x0000000101580a90
    m_pCachedTransitionFrame = 0x0000000000000000
    m_pNext = 0x000000010171ca70
    m_hPalThread = 0x0000000101406330
    m_ppvHijackedReturnAddressLocation = 0x0000000000000000
    m_pvHijackedReturnAddress = 0x0000000000000000
    m_pExInfoStackHead = 0x0000000000000000
    m_pStackLow = 0x0000000101501000
    m_pStackHigh = 0x0000000101581000
    m_pTEB = 0x0000000000000000
    m_uPalThreadIdForLogging = 1208893
    m_threadId = {
      m_id = 0x0000000101581000
      m_isValid = true
    }
    m_pThreadStressLog = 0x0000000000000000
    m_uRand = 0
    m_numDynamicTypesTlsCells = 0
    m_pDynamicTypesTlsCells = 0x0000000000000000
    m_pThreadLocalModuleStatics = 0x000000010140b550
    m_numThreadLocalModuleStatics = 1
  }

}

[janvorli]

So the value at frame 1 is not valid, looks like it is freshly initialized, while the one at frame 2 is likely correct. My quick guess is that when the OSX runtime calls the TlsObjectDestructor, it has already removed the tls_CurrentThread from the TLS and somehow attempt to access it on the thread again creates a fresh copy of it.

It seems we will need to modify the thread shutdown code so that it doesn't check if the thread passed in the TlsObjectDestructor matches the tls_CurrentThread, pass it further to the ThreadStore::DetachCurrentThread instead of getting it from tls_CurrentThread in the DetachCurrentThread and also change the PalDetachThread for Unix to be dummy, since we cannot read the pthread_getspecific at that point.

[christianscheuer]

Fixed in #2531