Engine & platform

Отладка повреждений памяти: Кто написал "2" в моей стопке?!

TAUTVYDAS ŽILYS / UNITY TECHNOLOGIESContributor

Apr 25, 2016|16 Мин

Отладка повреждений памяти: Кто написал "2" в моей стопке?!

Эта веб-страница была переведена с помощью машинного перевода для вашего удобства. Мы не можем гарантировать точность или надежность переведенного контента. Если у вас есть вопросы о точности переведенного контента, обращайтесь к официальной английской версии веб-страницы.

Нажмите здесь.

Привет, меня зовут Таутвидас, и я разработчик программного обеспечения в Unity, работающий в команде Windows. Я хотел бы поделиться историей отладки неуловимой ошибки повреждения памяти.

Несколько недель назад мы получили сообщение об ошибке от клиента, в котором говорилось, что его игра аварийно завершается при использовании бэкенда сценариев IL2CPP. Отдел контроля качества проверил ошибку и передал ее мне для исправления. Проект получился довольно большим (хотя и далеко не самым большим); на моей машине его сборка заняла 40 минут. В инструкции к сообщению об ошибке сказано: "Играйте в игру в течение 5-10 минут, пока не произойдет сбой". Конечно, после выполнения инструкций я наблюдал сбой. Я запустил WinDbg, готовый прибить его. К сожалению, трассировка стека была ложной:

0:049> k
# Child-SP           RetAddr           Call Site
00 00000022`e25feb10 00000000`00000010 0x00007ffa`00000102

0:050> u 0x00007ffa`00000102 L10
00007ffa`00000102 ??         ???
                          ^ Memory access error in 'u 0x00007ffa`00000102 l10'

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

0:049> dps @rsp L200
...............
00000022`e25febd8  00007ffa`b1fdc65c ucrtbased!heap_alloc_dbg+0x1c [d:\th\minkernel\crts\ucrt\src\appcrt\heap\debug_heap.cpp @ 447]
00000022`e25febe0  00000000`00000004
00000022`e25febe8  00000022`00000001
00000022`e25febf0  00000022`00000000
00000022`e25febf8  00000000`00000000
00000022`e25fec00  00000022`e25fec30
00000022`e25fec08  00007ffa`99b3d3ab UnityPlayer!std::_Vector_alloc<std::_Vec_base_types<il2cpp::os::PollRequest,std::allocator<il2cpp::os::PollRequest> > >::_Get_data+0x2b [ c:\program files (x86)\microsoft visual studio 14.0\vc\include\vector @ 642]
00000022`e25fec10  00000022`e25ff458
00000022`e25fec18  cccccccc`cccccccc
00000022`e25fec20  cccccccc`cccccccc
00000022`e25fec28  00007ffa`b1fdf54c ucrtbased!_calloc_dbg+0x6c [d:\th\minkernel\crts\ucrt\src\appcrt\heap\debug_heap.cpp @ 511]
00000022`e25fec30  00000000`00000010
00000022`e25fec38  00007ffa`00000001
...............
00000022`e25fec58  00000000`00000010
00000022`e25fec60  00000022`e25feca0
00000022`e25fec68  00007ffa`b1fdb69e ucrtbased!calloc+0x2e [d:\th\minkernel\crts\ucrt\src\appcrt\heap\calloc.cpp @ 25]
00000022`e25fec70  00000000`00000001
00000022`e25fec78  00000000`00000010
00000022`e25fec80  cccccccc`00000001
00000022`e25fec88  00000000`00000000
00000022`e25fec90  00000022`00000000
00000022`e25fec98  cccccccc`cccccccc
00000022`e25feca0  00000022`e25ff3f0
00000022`e25feca8  00007ffa`99b3b646 UnityPlayer!il2cpp::os::SocketImpl::Poll+0x66 [ c:\users\tautvydas\builds\bin2\il2cppoutputproject\il2cpp\libil2cpp\os\win32\socketimpl.cpp @ 1429]
00000022`e25fecb0  00000000`00000001
00000022`e25fecb8  00000000`00000010
...............
00000022`e25ff3f0  00000022`e25ff420
00000022`e25ff3f8  00007ffa`99c1caf4 UnityPlayer!il2cpp::os::Socket::Poll+0x44 [ c:\users\tautvydas\builds\bin2\il2cppoutputproject\il2cpp\libil2cpp\os\socket.cpp @ 324]
00000022`e25ff400  00000022`e25ff458
00000022`e25ff408  cccccccc`ffffffff
00000022`e25ff410  00000022`e25ff5b4
00000022`e25ff418  00000022`e25ff594
00000022`e25ff420  00000022`e25ff7e0
00000022`e25ff428  00007ffa`99b585f8 UnityPlayer!il2cpp::vm::SocketPollingThread::RunLoop+0x268 [ c:\users\tautvydas\builds\bin2\il2cppoutputproject\il2cpp\libil2cpp\vm\threadpool.cpp @ 452]
00000022`e25ff430  00000022`e25ff458
00000022`e25ff438  00000000`ffffffff
...............
00000022`e25ff7d8  00000022`e25ff6b8
00000022`e25ff7e0  00000022`e25ff870
00000022`e25ff7e8  00007ffa`99b58d2c UnityPlayer!il2cpp::vm::SocketPollingThreadEntryPoint+0xec [ c:\users\tautvydas\builds\bin2\il2cppoutputproject\il2cpp\libil2cpp\vm\threadpool.cpp @ 524]
00000022`e25ff7f0  00007ffa`9da83610 UnityPlayer!il2cpp::vm::g_SocketPollingThread
00000022`e25ff7f8  00007ffa`99b57700 UnityPlayer!il2cpp::vm::FreeThreadHandle [ c:\users\tautvydas\builds\bin2\il2cppoutputproject\il2cpp\libil2cpp\vm\threadpool.cpp @ 488]
00000022`e25ff800  00000000`0000106c
00000022`e25ff808  cccccccc`cccccccc
00000022`e25ff810  00007ffa`9da83610 UnityPlayer!il2cpp::vm::g_SocketPollingThread
00000022`e25ff818  000001c4`1705f5c0
00000022`e25ff820  cccccccc`0000106c
...............
00000022`e25ff860  00005eaa`e9a6af86
00000022`e25ff868  cccccccc`cccccccc
00000022`e25ff870  00000022`e25ff8d0
00000022`e25ff878  00007ffa`99c63b52 UnityPlayer!il2cpp::os::Thread::RunWrapper+0xd2 [ c:\users\tautvydas\builds\bin2\il2cppoutputproject\il2cpp\libil2cpp\os\thread.cpp @ 106]
00000022`e25ff880  00007ffa`9da83610 UnityPlayer!il2cpp::vm::g_SocketPollingThread
00000022`e25ff888  00000000`00000018
00000022`e25ff890  cccccccc`cccccccc
...............
00000022`e25ff8a8  000001c4`15508c90
00000022`e25ff8b0  cccccccc`00000002
00000022`e25ff8b8  00007ffa`99b58c40 UnityPlayer!il2cpp::vm::SocketPollingThreadEntryPoint [ c:\users\tautvydas\builds\bin2\il2cppoutputproject\il2cpp\libil2cpp\vm\threadpool.cpp @ 494]
00000022`e25ff8c0  00007ffa`9da83610 UnityPlayer!il2cpp::vm::g_SocketPollingThread
00000022`e25ff8c8  000001c4`155a5890
00000022`e25ff8d0  00000022`e25ff920
00000022`e25ff8d8  00007ffa`99c19a14 UnityPlayer!il2cpp::os::ThreadStartWrapper+0x54 [ c:\users\tautvydas\builds\bin2\il2cppoutputproject\il2cpp\libil2cpp\os\win32\threadimpl.cpp @ 31]
00000022`e25ff8e0  000001c4`155a5890
...............
00000022`e25ff900  cccccccc`cccccccc
00000022`e25ff908  00007ffa`99c63a80 UnityPlayer!il2cpp::os::Thread::RunWrapper [ c:\users\tautvydas\builds\bin2\il2cppoutputproject\il2cpp\libil2cpp\os\thread.cpp @ 80]
00000022`e25ff910  000001c4`155a5890
...............
00000022`e25ff940  000001c4`1e0801b0
00000022`e25ff948  00007ffa`e6858102 KERNEL32!BaseThreadInitThunk+0x22
00000022`e25ff950  000001c4`1e0801b0
00000022`e25ff958  00000000`00000000
00000022`e25ff960  00000000`00000000
00000022`e25ff968  00000000`00000000
00000022`e25ff970  00007ffa`99c199c0 UnityPlayer!il2cpp::os::ThreadStartWrapper [ c:\users\tautvydas\builds\bin2\il2cppoutputproject\il2cpp\libil2cpp\os\win32\threadimpl.cpp @ 26]
00000022`e25ff978  00007ffa`e926c5b4 ntdll!RtlUserThreadStart+0x34
00000022`e25ff980  00007ffa`e68580e0 KERNEL32!BaseThreadInitThunk

Вот примерная реконструкция стектрейса:

00000022`e25febd8  00007ffa`b1fdc65c ucrtbased!heap_alloc_dbg+0x1c [...\appcrt\heap\debug_heap.cpp @ 447]
00000022`e25fec28  00007ffa`b1fdf54c ucrtbased!_calloc_dbg+0x6c [...\appcrt\heap\debug_heap.cpp @ 511]
00000022`e25fec68 00007ffa`b1fdb69e  ucrtbased!calloc+0x2e [...\appcrt\heap\calloc.cpp @ 25]
00000022`e25feca8  00007ffa`99b3b646 UnityPlayer!il2cpp::os::SocketImpl::Poll+0x66 [...\libil2cpp\os\win32\socketimpl.cpp @ 1429]
00000022`e25ff3f8  00007ffa`99c1caf4 UnityPlayer!il2cpp::os::Socket::Poll+0x44 [...\libil2cpp\os\socket.cpp @ 324]
00000022`e25ff428  00007ffa`99b585f8 UnityPlayer!il2cpp::vm::SocketPollingThread::RunLoop+0x268 [...\libil2cpp\vm\threadpool.cpp @ 452]
00000022`e25ff7e8  00007ffa`99b58d2c UnityPlayer!il2cpp::vm::SocketPollingThreadEntryPoint+0xec [...\libil2cpp\vm\threadpool.cpp @ 524]
00000022`e25ff878  00007ffa`99c63b52 UnityPlayer!il2cpp::os::Thread::RunWrapper+0xd2 [...\libil2cpp\os\thread.cpp @ 106]
00000022`e25ff8d8  00007ffa`99c19a14 UnityPlayer!il2cpp::os::ThreadStartWrapper+0x54 [...\libil2cpp\os\win32\threadimpl.cpp @ 31]
00000022`e25ff948  00007ffa`e6858102 KERNEL32!BaseThreadInitThunk+0x22
00000022`e25ff978  00007ffa`e926c5b4 ntdll!RtlUserThreadStart+0x34

Хорошо, теперь я знал, какой поток дает сбой: это был поток опроса сокетов во время выполнения IL2CPP. В его обязанности входит сообщать другим потокам, когда их сокеты готовы к отправке или приему данных. Это происходит следующим образом: существует FIFO-очередь, в которую запросы на опрос сокетов помещаются другими потоками, затем поток опроса сокетов снимает эти запросы один за другим, вызывает функцию select(), и когда select() возвращает результат, он ставит в очередь обратный вызов, который был в исходном запросе, в пул потоков.

Значит, кто-то сильно испортил стек. Чтобы сузить поиск, я решил поместить "stack sentinels" на большинство стековых рам в этой теме. Вот как был определен мой стековый дозорный:

Когда он будет создан, он заполнит буфер значением "0xDD". При уничтожении он проверит, не изменились ли эти значения. Это сработало невероятно хорошо: игра больше не падала! Вместо этого он утверждал:

Кто-то трогал интимные места моего часового - и это точно был не друг. Я проделал это еще несколько раз, и результат был тот же: каждый раз первым в буфер записывалось значение "2". Взглянув на вид памяти, я заметил, что то, что я видел, было мне знакомо:

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

Я знал, что память всегда повреждается, когда один из моих часовых находится в зоне видимости. Мне как-то нужно было поймать с поличным ту тварь, которая его развращает. Я решил сделать память дозорного стека только для чтения на время жизни дозорного стека: Я бы вызвал VirtualProtect() в конструкторе, чтобы пометить страницы только для чтения, и снова вызвал бы ее в деструкторе, чтобы сделать их доступными для записи:

К моему удивлению, он все еще был поврежден! И сообщение в журнале отладки было таким:

Память была повреждена по адресу 0xd046ffeea8. Когда он был поврежден, он был доступен для чтения.
CrashingGame.exe создал точку останова.

Для меня это был тревожный сигнал. Кто-то испортил память либо в тот момент, когда она была доступна только для чтения, либо непосредственно перед тем, как я перевел ее в режим "только для чтения". Поскольку я не получил никаких нарушений доступа, я предположил, что дело в последнем, поэтому я изменил код, чтобы проверить, изменилось ли содержимое памяти сразу после установки моих магических значений:

Моя теория подтвердилась:

Память была повреждена по адресу 0x79b3bfea78.
CrashingGame.exe создал точку останова.

В этот момент я задумался: "Что ж, должно быть, это еще один поток, испортивший мою стопку. Это ДОЛЖНО быть так. Верно? ПРАВДА?". Единственный способ, который я знал, как продолжить расследование, - это использовать точки останова данных (памяти), чтобы поймать нарушителя. К сожалению, на x86 Вы можете следить только за четырьмя участками памяти одновременно, что означает, что я могу следить максимум за 32 байтами, в то время как область, которая была повреждена, составляла 16 КБ. Мне как-то нужно было понять, где установить точки останова. Я начал замечать закономерности коррупции. Сначала казалось, что они случайны, но это была лишь иллюзия из-за природы ASLR: каждый раз, когда я перезапускал игру, она помещала стек по случайному адресу памяти, так что место повреждения естественным образом отличалось. Однако, когда я понял это, я перестал перезапускать игру каждый раз, когда память становилась поврежденной, и просто продолжил выполнение. В результате я обнаружил, что адрес поврежденной памяти всегда был постоянным для данной сессии отладки. Другими словами, если программа была повреждена один раз, она всегда будет повреждаться по одному и тому же адресу памяти, пока я не завершу программу:

Память была повреждена по адресу 0x90445febd8.
CrashingGame.exe создал точку останова.
Память была повреждена по адресу 0x90445febd8.
CrashingGame.exe создал точку останова.

Я установил точку останова данных на этом адресе памяти и наблюдал, как он продолжает ломаться всякий раз, когда я устанавливаю его на магическое значение 0xDD. Я полагал, что это займет много времени, но Visual Studio действительно позволяет мне установить условие для этой точки останова: прерывать только в том случае, если значение этого адреса памяти равно 2:

Через минуту эта точка останова наконец-то сработала. Я пришел к этому моменту после 3 дней отладки этой штуки. Это должен был быть мой триумф. "Наконец-то я прижал Вас к стенке!", - провозгласил я. Или я так оптимистично думал:

Я смотрел на отладчик с недоверием, поскольку в моей голове было больше вопросов, чем ответов: "Что? Как это вообще возможно? Я схожу с ума?". Я решил посмотреть на разборку:

Конечно, он изменял эту область памяти. Но он записывал на него 0xDD, а не 0x02! После просмотра окна памяти вся область уже была повреждена:

Когда я уже готов был биться головой о стену, я позвонил своему коллеге и попросил его посмотреть, не пропустил ли я что-то очевидное. Мы вместе просмотрели отладочный код и не нашли ничего, что могло бы хотя бы отдаленно вызвать такие странности. Затем я сделал шаг назад и попытался представить себе, что могло заставить отладчик сломаться, думая, что код установил значение "2". Я придумал следующую гипотетическую цепочку событий:

1. mov byte ptr [rax], 0DDh изменяет ячейку памяти, CPU прерывает выполнение, чтобы позволить отладчику проверить состояние программы
2. Память испорчена чем-то
3. Отладчик проверяет адрес памяти, находит внутри него "2" и думает, что именно это и изменилось.

Итак... что может изменить содержимое памяти, пока программа заморожена отладчиком? Насколько я знаю, это возможно в двух сценариях: либо это делает другой процесс, либо ядро ОС. Чтобы исследовать любой из них, обычный отладчик не подойдет. Войдите в страну отладки ядра.

Удивительно, но настройка отладки ядра очень проста в Windows. Вам понадобятся 2 машины: та, на которой будет работать отладчик, и та, на которой Вы будете отлаживать. Откройте расширенную командную строку на машине, на которой Вы собираетесь проводить отладку, и введите следующее:

Host IP - это IP-адрес машины, на которой запущен отладчик. Он будет использовать указанный порт для подключения отладчика. Он может находиться в любом диапазоне от 49152 до 65535. После нажатия клавиши Enter во второй команде, она сообщит Вам секретный ключ (на рисунке он усечен), который служит паролем при подключении отладчика. После выполнения этих действий перезагрузитесь.

На другом компьютере откройте WinDbg, нажмите Файл -> Отладка ядра и введите порт и ключ.

Если все идет хорошо, Вы сможете прервать выполнение, нажав Debug -> Break. Если это сработает, компьютер "дебютанта" зависнет. Введите "g", чтобы продолжить выполнение.

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

Память была повреждена по адресу 0x49d05fedd8.
CrashingGame.exe создал точку останова.

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

kd> !process 0 0
PROCESS ffffe00167228080
    SessionId: 1  Cid: 26b8    Peb: 49cceca000  ParentCid: 03d8
    DirBase: 1ae5e3000  ObjectTable: ffffc00186220d80  HandleCount: 
    Image: CrashingGame.exe

kd> .process /i ffffe00167228080
You need to continue execution (press 'g' ) for the context
to be switched. When the debugger breaks in again, you will be in
the new process context.
kd> g
Break instruction exception - code 80000003 (first chance)
nt!DbgBreakPointWithStatus:
fffff801`7534beb0 cc              int     3
kd> .process
Implicit process is now ffffe001`66e9e080
kd> .reload /f
kd> ba w 1 0x00000049D05FEDD8 ".if (@@c++(*(char*)0x00000049D05FEDD8 == 2)) { k } .else { gc }"

Через некоторое время точка останова действительно сработала...

 # Child-SP          RetAddr           Call Site
00 ffffd000`23c1e980 fffff801`7527dc64 nt!IopCompleteRequest+0xef
01 ffffd000`23c1ea70 fffff801`75349953 nt!KiDeliverApc+0x134
02 ffffd000`23c1eb00 00007ffd`7e08b4bd nt!KiApcInterrupt+0xc3
03 00000049`d05fad50 cccccccc`cccccccc UnityPlayer!StackSentinel::StackSentinel+0x4d [...\libil2cpp\utils\memory.cpp @ 21]

Хорошо, так что же здесь происходит?! Дозорный радостно устанавливает свои магические значения, затем происходит аппаратное прерывание, которое затем вызывает какую-то процедуру завершения, и это записывает "2" в мой стек. Вау. Так, по какой-то причине ядро Windows повреждает мою память. Но почему?

Сначала я подумал, что это мы вызываем какой-то Windows API и передаем ему неверные аргументы. Поэтому я снова просмотрел весь код потока опроса сокетов и обнаружил, что единственным системным вызовом, который мы там вызывали, была функция select(). Я зашел в MSDN и провел час, перечитывая документацию по select() и перепроверяя, все ли мы делаем правильно. Насколько я могу судить, с ним не так уж много можно сделать неправильно, и в документации определенно не было места, где бы говорилось: "Если Вы передадите ему этот параметр, мы запишем 2 в Ваш стек". Казалось, что мы все делаем правильно.

Исчерпав все возможности, я решил зайти в функцию select() с помощью отладчика, разобрать ее на части и понять, как она работает. Это заняло у меня несколько часов, но я справился. Похоже, что функция select() является оберткой для функции WSPSelect(), которая выглядит примерно так:

auto completionEvent = TlsGetValue(MSAFD_SockTlsSlot);

/* setting up some state
…
*/

IO_STATUS_BLOCK statusBlock;
auto result = NtDeviceIoControlFile(networkDeviceHandle, completionEvent, nullptr, nullptr, &statusBlock, 0x12024,
    buffer, bufferLength, buffer, bufferLength);

if (result == STATUS_PENDING)
    WaitForSingleObjectEx(completionEvent, INFINITE, TRUE);

/* convert result and return it
...
*/

Здесь важен вызов функции NtDeviceIoControlFile(), тот факт, что она передает локальную переменную statusBlock в качестве параметра out, и, наконец, тот факт, что она ожидает сигнала о событии с помощью alertable wait. Пока все хорошо: она вызывает функцию ядра, которая возвращает STATUS_PENDING, если не может завершить запрос немедленно. В этом случае WSPSelect() ждет, пока событие не будет установлено. Как только NtDeviceIoControlFile() завершает работу, она записывает результат в переменную statusBlock, а затем устанавливает событие. Ожидание завершается, а затем WSPSelect() возвращается.

Структура IO_STATUS_BLOCK выглядит следующим образом:

typedef struct _IO_STATUS_BLOCK
{
    union
    {
        NTSTATUS Status;
        PVOID    Pointer;
    };
    ULONG_PTR Information;
} IO_STATUS_BLOCK, *PIO_STATUS_BLOCK;

В 64-битной версии эта структура имеет длину 16 байт. Мое внимание привлекло то, что эта структура, похоже, соответствует моей схеме повреждения памяти: первые 4 байта повреждаются (NTSTATUS имеет длину 4 байта), затем 4 байта пропускаются (padding/space для PVOID) и, наконец, еще 8 повреждаются. Если бы это действительно было то, что записывалось в мою память, то первые четыре байта содержали бы статус результата. Первые 4 поврежденных байта всегда были 0x00000102. И это код ошибки для... STATUS_TIMEOUT! Это была бы здравая теория, если бы только WSPSelect() не ждал завершения работы NtDeviceIOControlFile(). Но это произошло.

Разобравшись с тем, как работает функция select(), я решил посмотреть на общую картину того, как работает поток опроса сокетов. И тут на меня обрушилась тонна кирпичей.

Когда другой поток передает сокет для обработки потоком опроса сокетов, поток опроса сокетов вызывает select() для этой функции. Поскольку select() - это блокирующий вызов, когда в очередь потока опроса сокетов попадает другой сокет, он должен каким-то образом прервать select(), чтобы новый сокет был обработан как можно скорее. Как выполняется функция прерывания select()? Очевидно, мы использовали QueueUserAPC() для выполнения асинхронной процедуры, в то время как select() был заблокирован... и из-за этого выкинули исключение! Это разворачивало стек, заставляло нас выполнить еще немного кода, а затем в какой-то момент в будущем ядро завершало работу и записывало результат в локальную переменную statusBlock (которая на тот момент уже не существовала). Если он случайно попадет на возвращаемый адрес в стеке, мы потерпим крах.

Исправление было довольно простым: вместо использования QueueUserAPC() мы теперь создаем петлевой сокет, на который отправляем байт каждый раз, когда нам нужно прервать select(). Этот путь уже давно используется на POSIX-платформах, а теперь он используется и в Windows. Исправление этой ошибки появилось в Unity 5.3.4p1.

Это один из тех жучков, которые не дают Вам спать по ночам. На решение этой проблемы у меня ушло 5 дней, и это, пожалуй, одна из самых сложных ошибок, которые мне когда-либо приходилось исследовать и исправлять. Урок усвоен, друзья: не выбрасывайте исключения из асинхронных процедур, если Вы находитесь внутри системного вызова!