Загадка внезапно умирающего процесса Oracle: как мини-дамп помог найти причину

Привет, Хабр! Меня зовут Павел, я ведущий архитектор в «Инфосистемы Джет», и это мой дебют на этой площадке.

Кому он будет полезен:

• Администраторам Oracle Database (особенно под Windows)

• Системным администраторам, сталкивающимся с загадочными падениями процессов

• Разработчикам, интересующимся низкоуровневой отладкой (WinDbg, IDA, Ghidra)

• Всем, кто любит детективные истории из мира IT

Предисловие. Загадка без логов

Несколько лет назад к нам обратился заказчик с о-о-очень странной проблемой: процесс Oracle Database на их Windows Server периодически умирал совершенно внезапно. Под «внезапно» понимается, что процесс убивался без каких-либо сообщений в логах. Просто был процесс — и вот его уже нет. Единственный след — автоматически создаваемый Windows mini damp около 1,2 Мб.

Заказчик бился над проблемой долго и отчаянно: меняли серверное железо, операционную систему, виртуализацию. Бесполезно. Особенно раздражало, что на абсолютно идентичной конфигурации с похожими данными проблема не воспроизводилась. Вендорская поддержка Oracle к этому моменту уже закончилась. Когда мы предложили «просто глянуть, вдруг что-то получится», энтузиазма с их стороны было ноль. И их можно понять: все предыдущие попытки анализа мини-дампов и логов заходили в тупик. «Поверьте, коллеги, мы просто потеряем время: и наше, и ваше» — примерно так звучал их главный аргумент. Но мы решили попробовать.

Предупреждение: Я не профессиональный Windows-разработчик. Часть вещей изучал по ходу дела. Возможно, в рассуждениях есть неточности — буду благодарен за комментарии экспертов. Тем не менее нам удалось найти причину и решить проблему. Делимся историей успеха.

Mini dump: первые улики

Итак, в наличии был только mini dump, который создавался автоматически Windows. Что есть в дампе:

• Информация о падении (исключении)

• Загруженные модули

• Стек вызовов на момент падения

• Информация о тредах

В общем, немного.

Открываем дамп в WinDbg и первым делом смотрим на исключение:

0:139> .exr -1 ExceptionAddress: 0000000142c02f4f (oracle+0x0000000002c02f4f)     ExceptionCode: c0000409 (Security check failure or stack buffer overrun)   ExceptionFlags: 00000001 NumberParameters: 0

Код исключения c0000409 — ошибка проверки безопасности или затертый стек. Причина падения понятна, осталось понять где и почему.

Далее смотрим стек:

0:139> k  # Child-SP             RetAddr         Call Site 00 00000001`29b884d8 000007fe`fcb61430 ntdll!NtWaitForMultipleObjects+0xa 01 00000001`29b884e0 00000000`76d316e3 KERNELBASE!WaitForMultipleObjectsEx+0xe8 02 00000001`29b885e0 00000000`76dab8b5 kernel32!WaitForMultipleObjectsExImplementation+0xb3 03 00000001`29b88670 00000000`76daba37 kernel32!WerpReportFaultInternal+0x215 04 00000001`29b88710 00000000`76daba8f kernel32!WerpReportFault+0x77 05 00000001`29b88740 00000000`76dabcac kernel32!BasepReportFault+0x1f 06 00000001`29b88770 00000001`46d3e91c kernel32!UnhandledExceptionFilter+0x1fc 07 00000001`29b88850 00000001`48c8e4f8 oracle+0x6d3e91c 08 00000001`29b88858 1a481a57`00000006 oracle+0x8c8e4f8 09 00000001`29b88860 00000001`00000000 0x1a481a57`00000006 0a 00000001`29b88868 0000a00a`00000001 0x00000001`00000000 0b 00000001`29b88870 00000001`49368410 0x0000a00a`00000001 0c 00000001`29b88878 00000001`29b88898 oracle+0x9368410 0d 00000001`29b88880 00000001`29b88890 0x00000001`29b88898 0e 00000001`29b88888 00000000`00000000 0x00000001`29b88890

Фреймы 00-06 — это обработка фатальной ошибки ядром Windows (ntdll, KERNELBASE, kernel32).

Фреймы 07-0e — стек пользовательского кода Oracle. Информации из мини-дампа катастрофически мало для понимания, где и почему в коде Oracle произошел сбой, приведший к повреждению стека.

Вывод: нужен полноценный дамп памяти процесса, чтобы увидеть состояние всего стека, глобальных переменных и памяти в момент падения.

Добыча «тяжелой артиллерии»: полный dump

Чтобы Windows создавала полные дампы при падении Oracle, настраиваем Windows Error Reporting (WER):

1. Создать в реестре ключ HKEY_LOCAL_MACHINE\SOFTWARE\Microsoft\Windows\Windows Error Reporting\LocalDumps

2. Добавить в него DumpType REG_DWORD со значением 2

3. После падения собрать дамп (%LOCALAPPDATA%\CrashDumps или C:\Windows\System32\config\systemprofile\AppData\Local\CrashDumps)

4. Дождаться следующего падения

Полученный файл — 144 Гб. Внутри всё — код, данные, стеки, загруженные модули и символы.

Загружаем этот монстр в WinDbg и снова смотрим стек:

0:049> k 8  # Child-SP             RetAddr         Call Site 00 00000000`52c484d8 000007fe`fd4a1430 ntdll!NtWaitForMultipleObjects+0xa 01 00000000`52c484e0 00000000`773816e3 KERNELBASE!WaitForMultipleObjectsEx+0xe8 02 00000000`52c485e0 00000000`773fb8b5 kernel32!WaitForMultipleObjectsExImplementation+0xb3 03 00000000`52c48670 00000000`773fba37 kernel32!WerpReportFaultInternal+0x215 04 00000000`52c48710 00000000`773fba8f kernel32!WerpReportFault+0x77 05 00000000`52c48740 00000000`773fbcac kernel32!BasepReportFault+0x1f 06 00000000`52c48770 00000001`46d3e91c kernel32!UnhandledExceptionFilter+0x1fc 07 00000000`52c48850 00000001`42c02f4f oracle!JVM_FindClassFromClassLoader+0x30ec9a

В этом случае падение произошло по адресу 00000001`42c02f4f, отладчик пытается угадать, что падение было в функции JVM_FindClassFromClassLoader со смещением 0x30ec9a. Возможно, это JVM (спойлер: нет).

Смотрим машинный код по адресу возврата 00000001`42c02f4f.

0:049> u 00000001`42c02f3d oracle+0x2c02f3d: 00000001`42c02f3d e856bb7603    call    oracle!qxiqrpt+0x2f746e (00000001`4636ea98) 00000001`42c02f42 488b8c24281b0000 mov  rcx,qword ptr [rsp+1B28h] 00000001`42c02f4a e85178ff04    call    oracle!jatxnPush+0x194c8 (00000001`47bfa7a0) 00000001`42c02f4f 89d8          mov     eax,ebx 00000001`42c02f51 4881c4401b0000  add   rsp,1B40h 00000001`42c02f58 5b            pop     rbx 00000001`42c02f59 5e            pop     rsi 00000001`42c02f5a 5f            pop     rdi

Видим возврат в 00000001`42c02f4f после вызова call oracle!jatxnPush+0x194c8 (00000001`47bfa7a0) Уж не там ли всё порушилось? Время расчехлить артиллерию.

Инструменты следствия: IDA и Ghidra

Анализировать машинный код из дампа с помощью отладчика — такое себе занятие (можно, но неэффективно). Поэтому берем оригинальные модули и используем профессиональные инструменты:

• IDA Free: индустриальный стандарт, мощный и быстрый;

• Ghidra: бесплатный инструмент от NSA.

! Полный анализ файлов занял около трех часов каждого инструмента.

Важное отступление: адреса в дампе (например, 00000001`42c02f4f) не совпадают с адресами в оригинальном .exe файле на диске. Это, в частности, из-за ASLR (Address Space Layout Randomization). Оба инструмента позволяют указать базовый адрес загрузки модуля (который берется из дампа), чтобы корректно сопоставить адреса инструкций.

Загружаем файл exe в IDA и указываем базовый адрес. Переходим по адресу падения (0000000142C02F4F):

.text:0000000142C02F0D loc_142C02F0D:                           ; CODE XREF: sub_142C020AC+806??j .text:0000000142C02F0D                  mov     [rsp+36B8h+var_3698], 0 .text:0000000142C02F16                  mov     eax, 2F0B8h .text:0000000142C02F1B                  mov     rcx, [r12+rax] .text:0000000142C02F1F                  mov     esi, 2F488h .text:0000000142C02F24                  movsxd  rdi, edx .text:0000000142C02F27                  mov     rdx, [r12+rsi] .text:0000000142C02F2B                  lea     r8, aKwqmscanscinde_0 ; "kwqmScanScIndexSeg: invalid indextype" .text:0000000142C02F32                  mov     r9d, 1 .text:0000000142C02F38                  mov     [rsp+36B8h+var_3690], rdi .text:0000000142C02F3D                  call    kgeasnmierr .text:0000000142C02F42 .text:0000000142C02F42 loc_142C02F42:                           ; CODE XREF: sub_142C020AC+7FE??j .text:0000000142C02F42                                          ; sub_142C020AC+E5F??j .text:0000000142C02F42                  mov     rcx, [rsp+6952] ; StackCookie .text:0000000142C02F4A                  call    __security_check_cookie .text:0000000142C02F4F                  mov     eax, ebx

Ключевые находки IDA

Итак, теперь мы видим, что после вызова kgeasnmierr, по адресу 0000000142C02F4A вызывается __security_check_cookie. Что это за функция? Это часть рантайма MSVC, который борется с порушенным стеком с помощью печенек. А именно — перед вызовом пользовательской функции (в данном случае вызов kgeasnmierr по адресу 0000000142C02F3D) в стек пишется волшебное значение («печенька»). После вызова функции проверяется, что печенька на месте. Если в процессе работы функции стек был перезаписан, то __security_check_cookie аварийно завершает работу с исключением Security check failure or stack buffer overrun. Как раз наш случай.

Осталось понять, по какой причине порушился стек в kgeasnmierr.

Ghidra в помощь (анализ С)

Ghidra позволяет посмотреть код в псевдо-С. Смотрим код, который вызывает kgeasnmierr.

Видно, что какая-то функция позвала kgeasnmierr с сообщением об ошибке “kwqmScanScIndexSeg: invalid indextype”. Судя по другим сообщениям, содержащим kwqmScanScIndexSeg, можно предположить, что функция, которая вызвала kgeasnmierr, а затем и __security_check_cookie, так и называется — kwqmScanScIndexSeg.

Итак, что нам дал анализ инструментами:

1. Функция (kwqmScanScIndexSeg), содержащая точку падения, готовит сообщение об ошибке "kwqmScanScIndexSeg: invalid indextype".

2. Она вызывает функцию kgeasnmierr (предположительно, логирующую или обрабатывающую ошибки).

3. Внутри kgeasnmierr происходит переполнение стека (Stack Buffer Overrun), разрушающее стековый фрейм вызывающей функции.

4. При возврате из kgeasnmierr, __security_check_cookie обнаруживает повреждение «печеньки» и генерирует исключение c0000409.

5. Система ловит необработанное исключение, создает дамп и убивает процесс.

Разгадка: Сломанная «печенька» и редкая ошибка.

Поиск строки "kwqmScanScIndexSeg: invalid indextype" в Google дал ошеломляющий результат — всего два (!) совпадения. Оба были на специализированных форумах и косвенно указывали на связь с компонентом Oracle Advanced Queuing (AQ) и проблемами с индексами, специфичными для AQ.

Остался главный вопрос: что такое kwqmScanScIndexSeg и при чем тут invalid indextype?

Итак, подозрение на Advanced Queue. Предварительный диагноз:

1. kwqmScanScIndexSeg получает на вход какие-то неверные данные (неверный тип индекса) и

2. Вызывает kgeasnmierr для сообщения об ошибке “kwqmScanScIndexSeg: invalid indextype” и

3. kgeasnmierr рушит стек

4. __security_check_cookie обнаруживает порушенный стек и

5. Зовет not so gracefull shutdown: kernel32!UnhandledExceptionFilter

6. Который генерирует дамп и аварийно завершает процесс

Решение и выводы

Рекомендация заказчику была простой: удалить и перестроить все индексы, связанные с очередями Oracle Advanced Queuing (AQ).

Результат: после применения этой рекомендации загадочные падения процесса Oracle полностью прекратились.

Выводы

1. Дампы — это важно: даже мини-дамп может указать направление (код исключения). Полный дамп — бесценен.

2. WinDbg — мощь: базовый анализ исключения и стека — первый шаг.

3. Ключ: без IDA/Ghidra понять, что именно сломалось внутри бинарника Oracle, было бы почти невозможно. Умение работать с ASLR критично.

4. Поиск — друг: даже два результата могут дать решающую подсказку.

5. Stack Cookies работают: механизм защиты стека MSVC выполнил свою задачу — обнаружил повреждение и предотвратил потенциально опасное продолжение работы.

Это был отличный пример того, как методичный анализ, даже без вендорской поддержки и при минимуме исходных данных, может привести к решению самой сложной проблемы. Удачи в отладке!