Depuração de corrupção de memória: Quem escreveu "2" na minha pilha?

Há várias semanas, recebemos um relatório de bug de um cliente que dizia que seu jogo estava travando quando usava o backend de script IL2CPP. O controle de qualidade verificou o bug e o atribuiu a mim para correção. O projeto era bem grande (embora longe dos maiores); levou 40 minutos para ser construído em minha máquina. As instruções no relatório de bug diziam: "Jogue o jogo por 5 a 10 minutos até ele travar". Com certeza, depois de seguir as instruções, observei uma falha. Abri o WinDbg e estava pronto para fazer isso. Infelizmente, o rastreamento da pilha era falso:

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'

Claramente, o senhor tentou executar um endereço de memória inválido. Embora o stacktrace tenha sido corrompido, eu esperava que apenas uma parte de toda a pilha tivesse sido corrompida e que eu pudesse reconstruí-la se observasse o conteúdo da memória além do registro do ponteiro da pilha. Com certeza, isso me deu uma ideia de onde procurar em seguida:

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

Aqui está uma reconstrução aproximada do stacktrace:

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

Muito bem, agora eu sabia qual thread estava falhando: era a thread de sondagem de soquete em tempo de execução do IL2CPP. Sua responsabilidade é informar aos outros threads quando seus soquetes estão prontos para enviar ou receber dados. Funciona assim: há uma fila FIFO na qual as solicitações de pesquisa de soquete são colocadas por outros threads, o thread de pesquisa de soquete retira essas solicitações da fila uma a uma, chama a função select() e, quando select() retorna um resultado, coloca em fila um retorno de chamada que estava na solicitação original para o pool de threads.

Portanto, alguém está corrompendo gravemente a pilha. Para restringir a pesquisa, decidi colocar "sentinelas de pilha" na maioria das estruturas de pilha desse tópico. Veja como meu sentinela de pilha foi definido:

Quando for construído, ele preencherá o buffer com "0xDD". Ao ser destruído, ele verificaria se esses valores não foram alterados. Isso funcionou incrivelmente bem: o jogo não estava mais travando! Em vez disso, ele estava afirmando:

Alguém estava tocando as partes íntimas da minha sentinela - e definitivamente não era um amigo. Executei isso mais algumas vezes e o resultado foi o mesmo: todas as vezes, o valor "2" foi gravado primeiro no buffer. Olhando para a visualização da memória, percebi que o que eu via era familiar:

Esses são exatamente os mesmos valores que vimos no primeiro rastreamento de pilha corrompido. Percebi que o que quer que tenha causado o travamento anterior também foi responsável por corromper o sentinela da pilha. No início, pensei que se tratava de algum tipo de estouro de buffer e que alguém estava escrevendo fora dos limites da variável local. Então, comecei a colocar essas sentinelas de pilha de forma muito mais agressiva: antes de quase todas as chamadas de função que o thread fazia. No entanto, as corrupções pareciam ocorrer em momentos aleatórios, e não consegui descobrir o que as estava causando usando esse método.

Eu sabia que a memória estava sempre sendo corrompida quando uma das minhas sentinelas estava no escopo. De alguma forma, eu precisava pegar em flagrante a coisa que o corrompe. Pensei em fazer com que a memória da sentinela da pilha fosse lida somente durante o período de vida da sentinela da pilha: Eu chamaria VirtualProtect() no construtor para marcar as páginas como somente leitura e o chamaria novamente no destruidor para torná-las graváveis:

Para minha surpresa, ele ainda estava sendo corrompido! E a mensagem no registro de depuração foi:

A memória foi corrompida em 0xd046ffeea8. Ele era somente leitura quando foi corrompido.
O CrashingGame.exe acionou um ponto de interrupção.

Isso foi um sinal de alerta para mim. Alguém estava corrompendo a memória enquanto ela era somente leitura ou logo antes de eu configurá-la para somente leitura. Como não obtive nenhuma violação de acesso, presumi que fosse a última, então alterei o código para verificar se o conteúdo da memória foi alterado logo após definir meus valores mágicos:

Minha teoria foi confirmada:

A memória foi corrompida em 0x79b3bfea78.
O CrashingGame.exe acionou um ponto de interrupção.

Nesse momento, eu estava pensando: "Bem, deve ser outro fio corrompendo minha pilha. DEVE ser. Certo? RIGHT?”. A única maneira que eu sabia como proceder para investigar isso era usar pontos de interrupção de dados (memória) para capturar o infrator. Infelizmente, no x86, o senhor pode observar apenas quatro locais de memória por vez, o que significa que posso monitorar 32 bytes no máximo, enquanto a área que estava sendo corrompida era de 16 KB. De alguma forma, eu precisava descobrir onde definir os pontos de interrupção. Comecei a observar padrões de corrupção. No início, parecia que eles eram aleatórios, mas isso era apenas uma ilusão devido à natureza do ASLR: toda vez que eu reiniciava o jogo, ele colocava a pilha em um endereço de memória aleatório, de modo que o local da corrupção era naturalmente diferente. No entanto, quando percebi isso, parei de reiniciar o jogo sempre que a memória se corrompia e continuei a execução. Isso me levou a descobrir que o endereço de memória corrompido era sempre constante em uma determinada sessão de depuração. Em outras palavras, uma vez corrompido uma vez, ele sempre será corrompido exatamente no mesmo endereço de memória, desde que eu não encerre o programa:

A memória foi corrompida em 0x90445febd8.
O CrashingGame.exe acionou um ponto de interrupção.
A memória foi corrompida em 0x90445febd8.
O CrashingGame.exe acionou um ponto de interrupção.

Defini um ponto de interrupção de dados nesse endereço de memória e observei que ele continuava quebrando sempre que eu o definia como um valor mágico de 0xDD. Imaginei que isso fosse demorar um pouco, mas o Visual Studio realmente me permite definir uma condição nesse ponto de interrupção: interromper somente se o valor desse endereço de memória for 2:

Um minuto depois, esse ponto de parada finalmente foi atingido. Cheguei a esse ponto depois de três dias de depuração. Esse seria o meu triunfo. "Finalmente consegui derrubar o senhor!", proclamei. Ou, pelo menos, foi o que pensei de forma otimista:

Observei o depurador com descrença enquanto minha mente se enchia de mais perguntas do que respostas: "O quê? Como isso é possível? Será que estou ficando louco?". Decidi dar uma olhada na desmontagem:

Com certeza, ele estava modificando esse local de memória. Mas o senhor estava escrevendo 0xDD nele, não 0x02! Depois de observar a janela de memória, toda a região já estava corrompida:

Quando eu estava prestes a bater a cabeça na parede, liguei para meu colega de trabalho e pedi que ele verificasse se eu havia deixado passar algo óbvio. Analisamos juntos o código de depuração e não encontramos nada que pudesse, mesmo que remotamente, causar essa estranheza. Em seguida, dei um passo atrás e tentei imaginar o que poderia estar causando a interrupção do depurador, pensando que o código definiu o valor como "2". Pensei na seguinte cadeia hipotética de eventos:

1. mov byte ptr [rax], 0DDh modifica o local da memória, a CPU interrompe a execução para permitir que o depurador inspecione o estado do programa
2. A memória é corrompida por algo
3. O depurador inspeciona o endereço de memória, encontra "2" dentro dele e acha que foi isso que mudou.

Então... o que pode alterar o conteúdo da memória enquanto o programa está congelado por um depurador? Até onde sei, isso é possível em dois cenários: ou é outro processo que está fazendo isso ou é o kernel do sistema operacional. Para investigar qualquer uma dessas situações, um depurador convencional não funcionará. Entre na área de depuração do kernel.

Surpreendentemente, a configuração da depuração do kernel é extremamente fácil no Windows. O senhor precisará de duas máquinas: a que será executada pelo depurador e a que será depurada pelo senhor. Abra o prompt de comando elevado na máquina em que você fará a depuração e digite o seguinte:

Host IP é o endereço IP da máquina que tem o depurador em execução. Ele usará a porta especificada para a conexão do depurador. Ele pode estar entre 49152 e 65535. Depois de pressionar Enter no segundo comando, ele informará uma chave secreta (truncada na imagem) que funciona como uma senha quando o usuário conecta o depurador. Após concluir essas etapas, reinicie o sistema.

No outro computador, abra o WinDbg, clique em File -> Kernel Debug e digite a porta e a chave.

Se tudo correr bem, o senhor poderá interromper a execução pressionando Debug -> Break. Se isso funcionar, o computador "debugado" congelará. Digite "g" para continuar a execução.

Iniciei o jogo e esperei que ele quebrasse uma vez para descobrir o endereço em que a memória é corrompida:

A memória foi corrompida em 0x49d05fedd8.
O CrashingGame.exe acionou um ponto de interrupção.

Muito bem, agora que eu sabia o endereço onde definir um ponto de interrupção de dados, tive que configurar meu depurador do kernel para realmente defini-lo:

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 }"

Depois de algum tempo, o ponto de interrupção foi realmente atingido...

 # 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]

Muito bem, o que está acontecendo aqui? A sentinela está alegremente definindo seus valores mágicos, então há uma interrupção de hardware, que chama alguma rotina de conclusão, e isso escreve "2" na minha pilha. Wow. Por algum motivo, o kernel do Windows está corrompendo minha memória. Mas por quê?

A princípio, pensei que o senhor deveria estar chamando alguma API do Windows e passando argumentos inválidos. Então, examinei novamente todo o código da thread de polling do soquete e descobri que a única chamada de sistema que estávamos fazendo era a função select(). Fui ao MSDN e passei uma hora relendo os documentos sobre select() e verificando novamente se estávamos fazendo tudo corretamente. Pelo que pude perceber, não havia muito que pudesse ser feito de errado com ele, e definitivamente não havia um lugar nos documentos onde se dizia "se o senhor passar esse parâmetro, escreveremos 2 na sua pilha". Parecia que estávamos fazendo tudo certo.

Depois de ficar sem o que tentar, decidi entrar na função select() com um depurador, passar por sua desmontagem e descobrir como ela funciona. Levei algumas horas, mas consegui fazer isso. Parece que a função select() é um invólucro para a WSPSelect(), que é mais ou menos assim:

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
...
*/

A parte importante aqui é a chamada para NtDeviceIoControlFile(), o fato de que ele passa sua variável local statusBlock como um parâmetro de saída e, finalmente, o fato de que ele espera que o evento seja sinalizado usando uma espera alertável. Até aí tudo bem: ele chama uma função do kernel, que retorna STATUS_PENDING se não puder concluir a solicitação imediatamente. Nesse caso, WSPSelect() aguarda até que o evento seja definido. Quando NtDeviceIoControlFile() é concluído, ele grava o resultado na variável statusBlock e, em seguida, define o evento. A espera é concluída e, em seguida, WSPSelect() retorna.

A estrutura IO_STATUS_BLOCK tem a seguinte aparência:

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

Em 64 bits, essa estrutura tem 16 bytes de comprimento. Chamou minha atenção o fato de que essa estrutura parece corresponder ao meu padrão de corrupção de memória: os primeiros 4 bytes são corrompidos (NTSTATUS tem 4 bytes de comprimento), depois 4 bytes são ignorados (preenchimento/espaço para PVOID) e, finalmente, mais 8 são corrompidos. Se isso fosse realmente o que estava sendo gravado na minha memória, então os primeiros quatro bytes conteriam o status do resultado. Os primeiros 4 bytes de corrupção eram sempre 0x00000102. E esse é o código de erro para... STATUS_TIMEOUT! Essa seria uma boa teoria, se o WSPSelect() não esperasse a conclusão do NtDeviceIOControlFile(). Mas foi o que aconteceu.

Depois de descobrir como a função select() funcionava, decidi analisar o quadro geral de como o thread de polling do soquete funcionava. E, então, fui atingido como uma tonelada de tijolos.

Quando outro thread envia um soquete para ser processado pelo thread de sondagem de soquete, o thread de sondagem de soquete chama select() nessa função. Como select() é uma chamada de bloqueio, quando outro soquete é colocado na fila de threads de sondagem de soquete, ele precisa interromper de alguma forma select() para que o novo soquete seja processado o mais rápido possível. Como funciona a função select() da interrupção? Aparentemente, usamos o QueueUserAPC() para executar um procedimento assíncrono enquanto o select() estava bloqueado... e lançamos uma exceção por causa disso! Isso desenrolou a pilha, fez com que executássemos mais alguns códigos e, em algum momento no futuro, o kernel concluiria o trabalho e gravaria o resultado na variável local statusBlock (que não existia mais naquele momento). Se o senhor acertasse um endereço de retorno na pilha, teríamos um crash.

A correção foi bem simples: em vez de usar QueueUserAPC(), agora criamos um soquete de loopback para o qual enviamos um byte sempre que precisamos interromper select(). Esse caminho tem sido usado em plataformas POSIX há bastante tempo e agora também é usado no Windows. A correção para esse bug foi lançada no Unity 5.3.4p1.

Esse é um daqueles bugs que deixam o senhor acordado à noite. Levei 5 dias para solucioná-lo e, provavelmente, é um dos bugs mais difíceis que já tive de analisar e corrigir. Lição aprendida, pessoal: não lancem exceções de procedimentos assíncronos se estiverem dentro de uma chamada de sistema!