One of my colleagues in enterprise product support runs a weekly debug talk consisting of a walkthrough of a debug session. Usually, the debug session comes to a conclusion, but one week, the debug session was unsatisfyingly inconclusive. We knew that something bad was happening, but we couldn’t figure out why.<\/p>\n
This problem gnawed at me, so I continued debugging it after the meeting was over. Here is the story.<\/p>\n
In the original problem, we observed a failure because a critical section failed to prevent two threads from entering the same block of code. You had one job.<\/i><\/p>\n The The handle of the TraceLogging provider to register. The handle must not already be registered.<\/span><\/p><\/blockquote>\n The crash was occurring because two threads were trying to register the handler.<\/p>\n Sidebar<\/b>: Most of the crash dumps did not show two threads actively in the critical section, so all we saw was one thread getting upset about the double registration, and no sign of the other thread. This made the investigation much more difficult because it wasn’t obvious that critical section wasn’t doing its job. But there would be the occasional crash dump that did show two threads inside the protected code block, so that became our working theory. Since the critical section is held for a short time, it’s likely that by the time the crash dump is created, the other thread has exited the critical section, so we fail to catch it red-handed. End sidebar<\/b>.<\/p>\n It’s apparent that this code wants to lazy-initialize the critical section. Here’s the code that does it:<\/p>\n This code uses an To try to understand better how we got into this state, I looked at the Sidebar<\/b>: The complaint about typedef void (CALLBACK *TRACELOGGINGCALLBACK)\r\n (TraceLoggingHProvider, PVOID);\r\n\r\nVOID\r\nDoWithTraceLoggingHandle(TRACELOGGINGCALLBACK Callback, PVOID Context)\r\n{\r\n InitializeCriticalSectionOnDemand();\r\n EnterCriticalSection(&g_critsec);<\/span>\r\n HRESULT hr = TraceLoggingRegister(g_myProvider);\r\n if (SUCCEEDED(hr))\r\n {\r\n (*Callback)(g_myProvider, Context);\r\n TraceLoggingUnregister(g_myProvider);\r\n }\r\n LeaveCriticalSection(&g_critsec);<\/span>\r\n}\r\n<\/pre>\nTraceLoggingRegister<\/code> documentation says about its parameter:<\/p>\nRTL_RUN_ONCE g_initCriticalSectionOnce = RTL_RUN_ONCE_INIT;\r\nCRITICAL_SECTION g_critsec;\r\n\r\nULONG\r\nCALLBACK\r\nInitializeCriticalSectionOnce(\r\n _In_ PRTL_RUN_ONCE InitOnce,\r\n _In_opt_ PVOID Parameter,\r\n _Inout_opt_ PVOID *lpContext\r\n)\r\n{\r\n UNREFERENCED_PARAMETER(InitOnce);\r\n UNREFERENCED_PARAMETER(Parameter);\r\n UNREFERENCED_PARAMETER(lpContext);\r\n\r\n InitializeCriticalSection(&g_critsec);\r\n return STATUS_SUCCESS;\r\n}\r\n\r\nVOID\r\nInitializeCriticalSectionOnDemand(VOID)\r\n{\r\n RtlRunOnceExecuteOnce(&g_initCriticalSectionOnce,\r\n InitializeCriticalSectionOnce, NULL, NULL);\r\n}\r\n<\/pre>\nRTL_RTL_INIT_Rtl\u00adRun\u00adOnce\u00adExecute\u00adOnce<\/code> is the DDK version of the Win32 Init\u00adOnce\u00adExecute\u00adOnce<\/code> function.<\/p>\ng_critsec<\/code> and the g_init\u00adCritical\u00adSection\u00adOnce<\/code>.<\/p>\n0:008> !critsec somedll!g_critsec\r\n\r\nDebugInfo for CritSec at 00007ffd928fa050 could not be read\r\nProbably NOT an initialized critical section.\r\n\r\nCritSec somedll!g_critsect+0+0 at 00007ffd928fa050\r\nLockCount NOT LOCKED\r\nRecursionCount 0\r\nOwningThread 0\r\n*** Locked\r\n<\/pre>\n
Debug\u00adInfo<\/code> is well-meaning but doesn’t quite understand the full story of that field. If we dump the CRITICAL_0:008> dt somedll!g_critsec\r\n +0x000 DebugInfo : 0xffffffff`ffffffff<\/span> _RTL_CRITICAL_SECTION_DEBUG\r\n +0x008 LockCount : 0n-1\r\n +0x00c RecursionCount : 0n0\r\n +0x010 OwningThread : (null)\r\n +0x018 LockSemaphore : (null) \r\n +0x020 SpinCount : 0x20007d0\r\n<\/pre>\n