Bug 2444

Причины этой ошибки могут быть настолько разнообразны, что вряд ли возможно составить общий алгоритм решения. Общий ключ к решению -- получить бэктрейс точки, наиболее близкой к проблемному месту.

Итак, в программе были запущены как минимум два потока и на экране появилось бесконечное сообщение:

err:ntdll:RtlpWaitForCriticalSection section 0x110570 "?" wait timed out in
thread 003d, blocked by 0039, retrying (60 sec)

Что мы можем из этого узнать?
1. Адрес критической секции 0x110570
2. Открыл ее поток с идентификатором 0x39, вызовом RtlEnterCriticalSection(0x110570)
3. Завершения ее ожидает поток 0x3d, который вызвал RtlpWaitForCriticalSection(0x110570), которая выводит эту ошибку каждые 60 сек.

В теории, поток 0x39 должен инициировать выполнение RtlLeaveForCriticalSection(0x110570), для того, чтобы крутящаяся в бесконечном цикле RtlpWaitForCriticalSection(0x110570) в потоке 0x3d, завершилась.
(почему я пишу "инициировать"? Потому, что RtlLeaveCriticalSection(0x110570) теоретически может запускаться и не в том же самом потоке, где произошло ранее RtlEnterCriticalSection(0x110570) (но скорее всего в том жк самом)).

В процессе выполнения программы, мест с открытиями или закрытиями разных критических секций достаточно много. И мы должны выделить условие, по которому мы будем наблюдать за "нашей" критической секцией (нам не надо наблюдать за открытием/закрытием посторонних критических секций, это засоряет лог)

Нам нужно отследить:
1) успешное выполнение RtlLeaveCriticalSection(0x110570)
2) вход в функцию RtlEnterCriticalSection(0x110570)
3) выход из функции RtlEnterCriticalSection(0x110570)
Зачем пункт 3? Дело в том, что вход в критическую секцию возможен только в том случае, если она закрыта, поэтому внутри RtlEnterCriticalSection(0x110570) располагается RtlpWaitForCriticalSection(0x110570), чтобы дождаться её закрытия. И вполне возможно, что именно из-за этого RtlEnterCriticalSection(0x110570) не отработает полностью, а повиснет на бесконечном цикле в RtlpWaitForCriticalSection(0x110570), который мы наблюдаем.

нужно изменять функции RtlLeaveCriticalSection(crit) и RtlEnterCriticalSection(crit):
для RtlEnterCriticalSection:

 NTSTATUS WINAPI RtlEnterCriticalSection( RTL_CRITICAL_SECTION *crit )
 {
+    static int cEnter = 0;
+    if(crit == 0x110570)
+        MESSAGE("thread %x: call RtlEnterCriticalSection(%x) #%i\n", GetCurrentThreadId(), crit, cEnter);
+
     if (crit->SpinCount)
     {
         ULONG count;

-        if (RtlTryEnterCriticalSection( crit )) return STATUS_SUCCESS;
+        if (RtlTryEnterCriticalSection( crit )){
+            if(crit == 0x110570)
+                MESSAGE("thread %x: ret RtlEnterCriticalSection(%x) #%i\n -> STATUS_SUCCESS\n", GetCurrentThreadId(), crit, cEnter++);
+            return STATUS_SUCCESS;
+        }
         for (count = crit->SpinCount; count > 0; count--)
         {
             if (crit->LockCount > 0) break;  /* more than one waiter, don't bother spinning */
@@ -546,6 +555,8 @@ NTSTATUS WINAPI RtlEnterCriticalSection( RTL_CRITICAL_SECTION *crit )
         if (crit->OwningThread == ULongToHandle(GetCurrentThreadId()))
         {
             crit->RecursionCount++;
+            if(crit == 0x110570)
+                MESSAGE("thread %x: ret RtlEnterCriticalSection(%x) #%i -> STATUS_SUCCESS\n", GetCurrentThreadId(), crit, cEnter++);
             return STATUS_SUCCESS;
         }

@@ -555,6 +566,8 @@ NTSTATUS WINAPI RtlEnterCriticalSection( RTL_CRITICAL_SECTION *crit )
 done:
     crit->OwningThread   = ULongToHandle(GetCurrentThreadId());
     crit->RecursionCount = 1;
+    if(crit == 0x110570)
+        MESSAGE("thread %x: ret RtlEnterCriticalSection(%x) #%i -> STATUS_SUCCESS\n", GetCurrentThreadId(), crit, cEnter++);
     return STATUS_SUCCESS;
 }

для RtlLeaveCriticalSection:
 NTSTATUS WINAPI RtlLeaveCriticalSection( RTL_CRITICAL_SECTION *crit )
 {
+    static int cLeave = 0;
+    if(crit == 0x110570)
+        MESSAGE("thread %x: RtlLeaveCriticalSection(%x) #%i", GetCurrentThreadId(), crit, cLeave ++);
+
     if (--crit->RecursionCount) interlocked_dec( &crit->LockCount );
     else
     {

Компилируем и воспроизводим багу.
вероятно в логе мы увидим что-то вроде такого:

...
thread 39: call RtlEnterCriticalSection(110570) #56
thread 39: ret RtlEnterCriticalSection(110570) #56 -> STATUS_SUCCESS
...
thread 39: RtlLeaveCriticalSection(110570) #56
...
thread 39: call RtlEnterCriticalSection(110570) #57
thread 39: ret RtlEnterCriticalSection(110570) #57 -> STATUS_SUCCESS
...
thread 39: call RtlEnterCriticalSection(110570) #58
thread 39: ret RtlEnterCriticalSection(110570) #58 -> STATUS_SUCCESS
err:ntdll:RtlpWaitForCriticalSection section 0x110570 "?" wait timed out in
thread 003d, blocked by 0039, retrying (60 sec)
err:ntdll:RtlpWaitForCriticalSection section 0x110570 "?" wait timed out in
thread 003d, blocked by 0039, retrying (60 sec)
...

Что мы отсюда можем распознать:
1. Последняя успешно открытая и закрытая критическая секция с адресом 0x110570 имеет номер 56
2. Не закрываемая критическая секция с этим же адресом, имеет номер 57. После её открытия происходит баг, который мы ищем (в результате чего критическая секция не закрывается)
3. Программа 58-ой раз хочет открыть критическую секцию, но у неё не получается, поскольку на 57-ом разе критическая секция закрыта не была.

Следовательно нам нужно упасть с бэктрейсом в месте 57-ого открытия критической секции.
Патчим RtlEnterCriticalSection во второй раз:
 NTSTATUS WINAPI RtlEnterCriticalSection( RTL_CRITICAL_SECTION *crit )
 {
+    static int cEnter = 0;
+    if(crit == 0x110570) {
+        MESSAGE("thread %x: call RtlEnterCriticalSection(%x) #%i\n", GetCurrentThreadId(), crit, cEnter);
+        if(cEnter == 57){
+           int *p = 0;
+
+           RtlLeaveCriticalSection(crit);
+           *p = 5; /* call debugger */
+        }
+    }
+
     if (crit->SpinCount)
     {
         ULONG count;


Закрывание критической секции перед падением является обязательным, т. к. в противном случае winedbg может не отобразить бэктрейс.
Как следствие закрытия критической секции в нужном месте, бага может (скорее всего) не воспроизвестись (но это не значит, что она решена),
однако отладчик всё равно должен выдать бэктрейс для открывшего критическую секцию треда.

Если отладчик не запускается, то это значит, что получаемое в результате записи по нулевому адресу исключение перхватывают установленные программой глобальные или локальные обработчики исключений. В первом случае проблема решается в простом удалении строчки top_filter = filter; из функции SetUnhandledExceptionFilter в dlls/kernel32/except.c . Если же отключение глобального обработчика все равно не приводит к вызову отладчика, то это случай, когда исключение перехватывается локальным обработчиком, и это надо решать при помощи патча из баги http://bugs.etersoft.ru/show_bug.cgi?id=2521

> это предупреждение на вылет программы,
> тогда хоть будем видеть backtrace.

Если делать падение с бэктрейсом на момент первого вывода сообщения о блокировки, то мы получим бэктрейс совершенно другого потока, где проблемы нет.