“FuckThisBug”, o el Apolo y un trip sobrenatural al mundo del C++ y la Física Cuántica

Hoy, por fin, después de muchas horas de trabajo (semanas, posiblemente), de estar buscando a ciegas, disparando al aire, etc… por fin Mario encontró una manera de reproducir el problema que nos acosaba con el Apolo en una instalación.

Como casi todas las veces, los problemas, una vez identificados, son obvios y en muchas ocasiones hasta estúpidos. Yo estaba ya realmente desesperado por esto. Cuando uno es el responsable de que un proyecto tan importante para la empresa (y, a fin de cuentas, para uno mismo, pues esta empresa es mi futuro), pues como que sí da cosa no encontrar estas broncas. Y más cuando el defecto es en uno de tus “brain-childs”.

So… después de muchas horas, cientos de megas de loggeo, lectura, debug, mensajes que iban y venían, audios que se subían al FTP, y bajábamos aquí… corajes y frustraciones, Mario pudo reproducir el problema más o menos de manera constante debuggeando línea por línea las funciones en donde estaban estas broncas. Así le fallaba, más o menos, un 10% de las veces, en su máquina. A mi nunca me falló (ni aún haciendo lo mismo), supongo yo que porque las máquinas, el sistema operativo, memoria disponible, etc., son muy diferentes. Total, así pudimos identificar en parte cuál era la bronca, aunque, más importante aún, teníamos un caso para probar. Un TestCase.

Programar sin TestCases es prácticamente imposible. Uno no puede saber, a ciencia cierta, si el resultado o lo que uno está haciendo es correcto o no. Puedes terminar de “arreglar” la rutina, pero si no sabes cómo hacerle para tronarla, cómo puedes saber si tu arreglo efectivamente funciona o no? A mi me gusta decir que cuando el sistema compila es cuando empiezan los problemas :-). Mucha gente cree que porque el compilador ya terminó y no marcó ningún error entonces el programa ya está funcionando. Lamento decepcionarlos, pero eso está muy lejos de la realidad.

Entonces… se encontró por fin un TestCase que hacía tronar al sistema una de cada 10 veces.

Yo tenía ya una idea más o menos de porqué podría ser el problema. Después de semanas de darle vueltas al asunto, algo tiene que salir, no? Básicamente, los síntomas eran los siguientes: se tiene una función, un evento que sucede en una situación muy particular:  cuando un audio es liberado. Cuando el stram de ese audio se libera. En ese momento, el objeto que lleva el control directo o de bajo nivel notifica a los objetos que están registrados ante el para avisarles que X audio ya terminó. Por la manera como está esto construido, se tiene una lista (usando std::vector, y apuntadores a funciones. Una maravilla!!!), y el objeto manda llamar a cada uno de estos elementos de la lista. De aquí llegamos a la siguiente clase: TPlayerCartucho. Aquí hay un evento, EvAudioFinalizado, que analiza si el evento es o no para esta instancia, de no ser, lo ignora. Esto se hace comparando la dirección que le llega como parámetro al evento, con la que tiene almacenada como el TAudioPlayer al que está relacionado.

Entonces… el problema sucedía en esta función. Tronaba generalmente a la hora que esta función intentaba llamar a otra función miembro de esta misma clase, TPlayerCartucho.  Tronaba sin razón aparente. Esto es síntoma de que la instancia de TPlayerCartucho ya no es válida en ese momento, i.e., ya fue eliminada (delete).

En fin… revisando todo el código… y debuggeando todavía más… parecía como que podría darse el caso de que los eventos de notificación (el EvAudioFinalizado) no fuera eliminado de la lista. Qué problema podría presentar esto, se preguntan, si es que ese evento está amarrado con la dirección del TAudioPlayer al que van a manejar? Bueno… aquí viene un poco la idiosincrazia del manejo de memoria: de ser posible, los bloques de memoria se reusan. Esto evita fragmentación, que puede convertirse en un problema serio en un programa que tiene que correr 24x7x365. Es decir… cuando el sistema necesita generar de nuevo una instancia de un TAudioPlayer, es posible que le toque la misma dirección de memoria que le tocó a un TAudioPlayer anteriormente. Y, adivinen qué sucede en caso de que esa dirección sea la misma de una que ya existía, y cuyos eventos de notificación no fueron limpiados correctamente? Sí… un Access Violation en toda forma 🙂

A grandes rasgos, y con muchas más líneas de descripción de las que realmente son en esta pequeña pero importantísima parte del sistema, esto fue lo que sucedió.

La solución consiste básicamente en 2 partes:

1. Al destruir el TPlayerCartucho (en el destructor), mandamos eliminar los eventos de notificación. Esto YA se hacía, no crean que no, pero parece que en algunos casos no se manda llamar la rutina en donde sucedía (al finalizar precísamente uno de estos eventos).
2. “Firmamos” el TPlayerCartucho como válido/inválido. Y de ahí parte del título de este post: La firma, en mi momento de desesperación, es un char de 12 bytes, que dice “FuckThisBug” :-). Eso se pone, con ese texto, en el constructor del TPlayerCartucho. En el destructor se cambia por otros 12 bytes: “–IAmFree–“. Entonces, sencillo: antes de entrar y hacer cualquier cosa en los eventos de notificación, verificamos que el string esté como necesitamos (“FuckThisBug”), si no está así, paniqueamos en ese momento (y no dejamos que continúe el flujo del programa, que podría, si es que ese bloque de memoria no se ha usado para otra cosa, terminar en llamadas válidas a funciones, o, como en estos casos, terminar con un AV)

La solución real consistió en añadir 3 líneas de código al destructor. Después de eso no volvimos a saber de este bug (hasta el momento), y tengo la confianza de que así siga.

Y la física cuántica qué? Bueno, seguramente que esto no tiene mucho que ver con eso. Nuestros ordenadores todavía usan física común y corriente, a pesar de estar ya rayando en tamaños realmente pequeños. Pero en fin, todavía son 0 y 1 los que nos hacen o no la vida de cuadritos. Lo interesante viene aquí, en el sentido de que sin debuggear (asomarse) el proceso, no sucedía nada aquí! Una vez que abrimos la caja y vimos al gato (sí, recuerdan al gato de Shrödinger?), resulta que ya falla. Porqué? No sé. Hay algunas suposiciones: estamos afectando el timing de las diferentes tareas que interactúan aquí… o haciendo más lento el proceso, permitiendo de alguna manera que se colen a veces estas broncas. Pero bueno… respiro ya más tranquilo… “like a free man”… 🙂

En fin… that’s all para esta tarde de domingo… todavía tengo que actualizar esto en aquella instalación a las 10 (La Hora Nacional…), pero espero que ya quede de una vez por todo solucionado esto.

So… si leyeron hasta acá, jejejeje… gracias por la paciencia! Mañana espero subir más fotos de NY, del segundo batch, porque parece que sí quedaron algunas más que “merecen” ser vistas por el público en general.