JetHabr вчера в 10:12

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

Средний

7 мин

1.6K

Блог компании Инфосистемы ДжетOracle * Windows *

Кейс

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

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

Администраторам 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):

Создать в реестре ключ HKEY_LOCAL_MACHINE\SOFTWARE\Microsoft\Windows\Windows Error Reporting\LocalDumps
Добавить в него DumpType REG_DWORD со значением 2
После падения собрать дамп (%LOCALAPPDATA%\CrashDumps или C:\Windows\System32\config\systemprofile\AppData\Local\CrashDumps)
Дождаться следующего падения

Полученный файл — 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.

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

Функция (kwqmScanScIndexSeg), содержащая точку падения, готовит сообщение об ошибке "kwqmScanScIndexSeg: invalid indextype".
Она вызывает функцию kgeasnmierr (предположительно, логирующую или обрабатывающую ошибки).
Внутри kgeasnmierr происходит переполнение стека (Stack Buffer Overrun), разрушающее стековый фрейм вызывающей функции.
При возврате из kgeasnmierr, __security_check_cookie обнаруживает повреждение «печеньки» и генерирует исключение c0000409.
Система ловит необработанное исключение, создает дамп и убивает процесс.

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

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

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

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

kwqmScanScIndexSeg получает на вход какие-то неверные данные (неверный тип индекса) и
Вызывает kgeasnmierr для сообщения об ошибке “kwqmScanScIndexSeg: invalid indextype” и
kgeasnmierr рушит стек
__security_check_cookie обнаруживает порушенный стек и
Зовет not so gracefull shutdown: kernel32!UnhandledExceptionFilter
Который генерирует дамп и аварийно завершает процесс

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

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

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

Выводы

Дампы — это важно: даже мини-дамп может указать направление (код исключения). Полный дамп — бесценен.
WinDbg — мощь: базовый анализ исключения и стека — первый шаг.
Ключ: без IDA/Ghidra понять, что именно сломалось внутри бинарника Oracle, было бы почти невозможно. Умение работать с ASLR критично.
Поиск — друг: даже два результата могут дать решающую подсказку.
Stack Cookies работают: механизм защиты стека MSVC выполнил свою задачу — обнаружил повреждение и предотвратил потенциально опасное продолжение работы.

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

Хабы: