Depuración de la corrupción de memoria: ¡¿Quién escribió '2' en mi pila?!

Hace varias semanas recibimos un informe de error de un cliente que decía que su juego se bloqueaba al utilizar el backend de scripting IL2CPP. QA verificó el fallo y me lo asignó para que lo arreglara. El proyecto era bastante grande (aunque lejos de los más grandes); tardó 40 minutos en construirse en mi máquina. Las instrucciones del informe de errores decían: "Juegue al juego durante 5-10 minutos hasta que se bloquee". Efectivamente, tras seguir las instrucciones, observé un fallo. Encendí WinDbg dispuesto a clavarlo. Desgraciadamente, el rastro de pila 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, intentó ejecutar una dirección de memoria no válida. Aunque el stacktrace se había corrompido, esperaba que sólo se hubiera corrompido una parte de toda la pila y que debería ser capaz de reconstruirla si miro el contenido de la memoria más allá del registro del puntero de la pila. Sin duda, eso me dio una idea de dónde buscar a continuación:

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

He aquí un rastro de pila reconstruido a grandes rasgos:

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

Muy bien, ahora ya sabía qué hilo estaba fallando: era el hilo de sondeo del socket en tiempo de ejecución IL2CPP. Su responsabilidad es indicar a otros hilos cuándo sus sockets están listos para enviar o recibir datos. Funciona así: hay una cola FIFO en la que otros subprocesos colocan las solicitudes de sondeo de socket, el subproceso de sondeo de socket luego dequeues estas solicitudes una por una, llama a la función select() y cuando select() devuelve un resultado, pone en cola una devolución de llamada que estaba en la solicitud original al grupo de subprocesos.

Así que alguien está corrompiendo gravemente la pila. Para acotar la búsqueda, decidí poner "centinelas de pila" en la mayoría de los marcos de pila de ese hilo. Así es como se definió mi centinela de pila:

Cuando se construya, llenará el búfer con "0xDD". Cuando se destruya, se comprobará si esos valores no han cambiado. Esto funcionó increíblemente bien: ¡el juego ya no se bloqueaba! En su lugar, se afirmaba:

Alguien había estado tocando las partes privadas de mi centinela - y definitivamente no era un amigo. Ejecuté esto un par de veces más, y el resultado fue el mismo: cada vez se escribió primero un valor de "2" en el búfer. Al observar la vista de la memoria, me di cuenta de que lo que veía me resultaba familiar:

Estos son exactamente los mismos valores que hemos visto en la primera traza de pila corrupta. Me di cuenta de que lo que causó el fallo anteriormente también fue responsable de corromper la pila centinela. Al principio, pensé que se trataba de algún tipo de desbordamiento del búfer y que alguien estaba escribiendo fuera de los límites de sus variables locales. Así que empecé a colocar estos centinelas de pila de forma mucho más agresiva: antes de casi cada llamada a función que hacía el hilo. Sin embargo, las corrupciones parecían producirse en momentos aleatorios, y no fui capaz de encontrar la causa utilizando este método.

Sabía que la memoria siempre se corrompía mientras uno de mis centinelas estaba en el ámbito. De alguna manera necesitaba atrapar con las manos en la masa a la cosa que lo corrompe. He pensado hacer que la memoria del centinela de pila sea de sólo lectura mientras dure la vida del centinela de pila: Yo llamaría a VirtualProtect() en el constructor para marcar las páginas como de sólo lectura, y lo llamaría de nuevo en el destructor para hacerlas escribibles:

Para mi sorpresa, ¡se seguía corrompiendo! Y el mensaje en el registro de depuración era:

La memoria se corrompió en 0xd046ffeea8. Era de sólo lectura cuando se corrompió.
CrashingGame.exe ha activado un punto de interrupción.

Esto fue una señal de alarma para mí. Alguien había estado corrompiendo la memoria mientras ésta era de sólo lectura, o justo antes de que la pusiera en sólo lectura. Como no obtuve violaciones de acceso, supuse que era esto último, así que cambié el código para comprobar si el contenido de la memoria cambiaba justo después de establecer mis valores mágicos:

Mi teoría se verificó:

La memoria se corrompió en 0x79b3bfea78.
CrashingGame.exe ha activado un punto de interrupción.

En este punto estaba pensando: "Bueno, debe ser otro hilo que corrompe mi pila. Tiene que serlo. ¿Verdad? ¿CORRECTO?". La única forma que conocía de proceder para investigar esto era utilizar puntos de interrupción de datos (memoria) para atrapar al infractor. Por desgracia, en x86 sólo se pueden vigilar cuatro posiciones de memoria a la vez, lo que significa que puedo vigilar 32 bytes como máximo, mientras que el área que se había estado corrompiendo era de 16 KB. De alguna manera tenía que averiguar dónde fijar los puntos de ruptura. Empecé a observar patrones de corrupción. Al principio, parecía que eran aleatorios, pero eso no era más que una ilusión debido a la naturaleza de ASLR: cada vez que reiniciaba el juego, colocaba la pila en una dirección de memoria aleatoria, por lo que el lugar de la corrupción difería de forma natural. Sin embargo, cuando me di cuenta de esto, dejé de reiniciar el juego cada vez que la memoria se corrompía y simplemente continué la ejecución. Esto me llevó a descubrir que la dirección de memoria corrupta era siempre constante para una sesión de depuración determinada. En otras palabras, una vez que se haya corrompido una vez, siempre se corromperá exactamente en la misma dirección de memoria mientras no termine el programa:

La memoria se corrompió en 0x90445febd8.
CrashingGame.exe ha activado un punto de interrupción.
La memoria se corrompió en 0x90445febd8.
CrashingGame.exe ha activado un punto de interrupción.

Establecí un punto de interrupción de datos en esa dirección de memoria y observé cómo se seguía rompiendo cada vez que la fijaba en el valor mágico de 0xDD. Me imaginaba que esto iba a llevar un tiempo, pero Visual Studio me permite establecer una condición en ese punto de ruptura: que sólo se rompa si el valor de esa dirección de memoria es 2:

Un minuto después, este punto de ruptura finalmente llegó. Llegué a este punto después de 3 días depurando esta cosa. Este iba a ser mi triunfo. "¡Por fin te he inmovilizado!", proclamé. O eso pensaba con tanto optimismo:

Observé el depurador con incredulidad mientras mi mente se llenaba de más preguntas que respuestas: "¿Qué? ¿Cómo es posible? ¿Me estoy volviendo loco?". Decidí mirar el desmontaje:

Efectivamente, estaba modificando esa posición de memoria. Pero le estaba escribiendo 0xDD, ¡no 0x02! Después de mirar la ventana de memoria, toda la región estaba ya corrompida:

Cuando estaba a punto de darme cabezazos contra la pared, llamé a mi compañero de trabajo y le pedí que mirara si se me había escapado algo obvio. Revisamos juntos el código de depuración y no pudimos encontrar nada que pudiera causar ni remotamente tal rareza. Entonces di un paso atrás y traté de imaginar qué podría estar causando que el depurador se rompiera pensando que el código establecía el valor en "2". Se me ocurrió la siguiente cadena hipotética de acontecimientos:

1. mov byte ptr [rax], 0DDh modifica la posición de memoria, la CPU interrumpe la ejecución para permitir que el depurador inspeccione el estado del programa
2. La memoria se corrompe por algo
3. El depurador inspecciona la dirección de memoria, encuentra "2" dentro y piensa que eso es lo que ha cambiado.

Entonces... ¿qué puede cambiar el contenido de la memoria mientras el programa está congelado por un depurador? Hasta donde yo sé, eso es posible en 2 escenarios: o es otro proceso el que lo hace, o es el núcleo del sistema operativo. Para investigar cualquiera de ellos, un depurador convencional no funcionará. Entre en la tierra de la depuración del kernel.

Sorprendentemente, configurar la depuración del núcleo es extremadamente fácil en Windows. Necesitará 2 máquinas: en la que se ejecutará el depurador y en la que depurará. Abra el símbolo del sistema elevado en la máquina que va a depurar y escriba esto:

La IP del host es la dirección IP de la máquina que tiene el depurador en ejecución. Utilizará el puerto especificado para la conexión del depurador. Puede estar entre 49152 y 65535. Tras pulsar intro en el segundo comando, le indicará una clave secreta (truncada en la imagen) que actúa como contraseña cuando conecta el depurador. Tras completar estos pasos, reinicie.

En el otro ordenador, abra WinDbg, haga clic en Archivo -> Depuración del núcleo e introduzca el puerto y la clave.

Si todo va bien, podrá interrumpir la ejecución pulsando Depurar -> Interrumpir. Si eso funciona, el ordenador "debugee" se congelará. Introduzca "g" para continuar la ejecución.

Arranqué el juego y esperé a que se rompiera una vez para poder averiguar la dirección en la que se corrompe la memoria:

La memoria se corrompió en 0x49d05fedd8.
CrashingGame.exe ha activado un punto de interrupción.

Muy bien, ahora que sabía la dirección donde fijar un punto de interrupción de datos, tenía que configurar mi depurador del núcleo para fijarlo realmente:

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

Después de algún tiempo, el punto de ruptura...

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

Muy bien, ¡¿qué está pasando aquí?! El centinela está felizmente estableciendo sus valores mágicos, luego hay una interrupción de hardware, que luego llama a alguna rutina de finalización, y que escribe "2" en mi pila. Vaya. Bien, por alguna razón el núcleo de Windows está corrompiendo mi memoria. Pero, ¿por qué?

Al principio, pensé que esto tenía que ser nosotros llamando a alguna API de Windows y pasándole argumentos no válidos. Así que volví a revisar todo el código del hilo de sondeo del socket y descubrí que la única llamada al sistema que hemos estado llamando allí era a la función select(). Fui a MSDN y me pasé una hora releyendo la documentación sobre select() y volviendo a comprobar si lo estábamos haciendo todo correctamente. Por lo que pude ver, no había realmente mucho que se pudiera hacer mal con él, y definitivamente no había un lugar en los documentos donde dijera "si le pasa este parámetro, escribiremos 2 en su pila". Parecía que lo estábamos haciendo todo bien.

Después de quedarme sin cosas que probar, decidí entrar en la función select() con un depurador, recorrer su desensamblaje y averiguar cómo funciona. Me llevó varias horas, pero lo conseguí. Parece que la función select( ) es una envoltura de la WSPSelect(), que a grandes rasgos tiene este aspecto:

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

Lo importante aquí es la llamada a NtDeviceIoControlFile(), el hecho de que pase su variable local statusBlock como parámetro out y, por último, el hecho de que espere a que se señale el evento mediante una espera alertable. Hasta aquí todo bien: llama a una función del núcleo, que devuelve STATUS_PENDING si no puede completar la solicitud inmediatamente. En ese caso, WSPSelect() espera hasta que se active el evento. Una vez que NtDeviceIoControlFile() ha terminado, escribe el resultado en la variable statusBlock y, a continuación, activa el evento. La espera se completa y entonces vuelve WSPSelect().

La estructura IO_STATUS_BLOCK tiene el siguiente aspecto:

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

En 64 bits, esa estructura tiene una longitud de 16 bytes. Me llamó la atención que esta estructura parece coincidir con mi patrón de corrupción de memoria: los primeros 4 bytes se corrompen (NTSTATUS tiene 4 bytes de longitud), luego se saltan 4 bytes (relleno/espacio para PVOID) y finalmente se corrompen 8 más. Si eso era efectivamente lo que se estaba escribiendo en mi memoria, entonces los cuatro primeros bytes contendrían el estado del resultado. Los 4 primeros bytes de corrupción eran siempre 0x00000102. Y resulta que ese es el código de error de... ¡STATUS_TIMEOUT! Esa sería una teoría sólida, si sólo WSPSelect() no esperara a que NtDeviceIOControlFile() finalizara. Pero así fue.

Después de averiguar cómo funcionaba la función select(), decidí ver el panorama general del funcionamiento del hilo de sondeo de sockets. Y entonces me golpeó como una tonelada de ladrillos.

Cuando otro hilo empuja un socket para que sea procesado por el hilo de sondeo de sockets, el hilo de sondeo de sockets llama a select() en esa función. Dado que select() es una llamada de bloqueo, cuando otro socket es empujado a la cola del hilo de sondeo de sockets tiene que interrumpir de alguna manera a select() para que el nuevo socket sea procesado lo antes posible. ¿Cómo se interrumpe la función select()? Al parecer, utilizamos QueueUserAPC() para ejecutar un procedimiento asíncrono mientras select() estaba bloqueado... ¡y lanzamos una excepción por ello! Eso desenrollaba la pila, nos hacía ejecutar algo más de código y, en algún momento futuro, el núcleo completaba el trabajo y escribía el resultado en la variable local statusBlock (que ya no existía en ese momento). Si por casualidad diera con una dirección de retorno en la pila, nos estrellaríamos.

El arreglo fue bastante sencillo: en lugar de utilizar QueueUserAPC(), ahora creamos un socket de bucle de retorno al que enviamos un byte cada vez que necesitamos interrumpir select(). Esta ruta se ha utilizado en plataformas POSIX durante bastante tiempo, y ahora también se utiliza en Windows. La corrección de este error se incluyó en Unity 5.3.4p1.

Este es uno de esos fallos que no le dejan dormir. Tardé 5 días en resolverlo, y es probablemente uno de los fallos más difíciles que he tenido que investigar y solucionar. Lección aprendida, amigos: ¡no lancen excepciones fuera de procedimientos asíncronos si están dentro de una llamada al sistema!