Generar archivos de log con Zend Framework

Logo de Zend Framework

Nota: En el desarrollo del artículo se asume que el lector posee conocimientos de PHP y Zend_Framework.

Muchas veces me he encontrado con las siguiente situación:

Hay un error en un caso de uso particular. Sólo conocemos el caso de uso, lo que debería hacer, y lo que actualmente está haciendo, que no difiere mucho en lo que debería hacer, pero que cambia notablemente el resultado del caso.

Luego de analizar dos o tres veces el camino que realiza ese caso por la lógica de negocio, cada vez más minuciosamente que la anterior, no encuentro nada que sea ilógico, es decir, a priori, debería funcionar bien, como se describe en la poscondición del caso de uso.

Hasta el momento, uno no sabe si es algún error de tipeo en los nombres de las variables, en la conexión con la base de datos, en la codificación de caracteres, en los tipos de variables… en fin, no sé bien en qué se basa el error.

Una de las cosas típicas que uno comienza a hacer, es “mostrar en pantalla” (es decir, usar echo, print_r, die, ensuciando el HTML a mostrar o rompiendo el formato de los datos de un JSON, por ejemplo) para ver qué está pasando en el medio, y a medida que vamos viendo bien o mal los contenidos de las variables, vamos acotando el margen de búsqueda del error.

El problema surge cuando éstas cosas están en producción, o por alguna otra razón necesitamos que la salida no sea modificada mientras depuramos el código.

Algunos un poco más experimentados, al encontrarse en ésta instancia, comienzan a volcar los datos de la depuración sobre algún archivo utilizando error_log() de PHP. Generalmente, cuando se está apurado y el sistema no estaba preparado para generar archivos de registros para depuración, el archivo sirve para encontrar el error, pero es tan caótico, sin descripciones de lo que se está mostrando, que cuando se finaliza el proceso de depuración luego de corregir el error, se quitan las líneas que generaban el archivo porque se conoce que no va a ser útil para una segunda vez, y para evitar sobrecargar el sistema generando constantemente un archivo de registros que es utilizado sólo una vez.

Si al encontrarnos en ésta situación el proyecto utiliza Zend Framework, hay buenas noticias. Zend Framework cuenta con la clase Zend_Log, que fue diseñada precisamente para generar registros transparentemente sobre cualquier salida que se le configure (entre ellas, archivos de texto plano).

Ésta clase tiene un alto nivel de abstracción y es muy dinámica (característica común en los componentes de Zend Framework, según mi opinión personal), por lo que el hecho de utilizarla puede llevar al desarrollador a diseñar y desarrollar a niveles de complejidad bastante altos. Pero en éste caso, sólo voy a explicar cómo utilizarla de forma básica pero muy útil para resolver problemas cuando no se puede modificar la salida estándar de PHP, pero se necesita mantener el trabajo realizado por si se requiere nuevamente que el sistema genere un registro de lo que sucede. Para ello, me voy a basar en un caso práctico que tuve que resolver, y decidí hacerlo con Zend_Log.

Para empezar, si la única salida que se utilizará para el registro es un archivo, o un pequeño conjunto de archivos, algo muy conveniente es crear una subclase de Zend_Log que se encargue de configurar los accesos a los archivos deseados en el momento de ser instanciada, y evitar su configuración cada vez que es requerida en los distintos métodos.

En mi caso en particular, decidí que con sólo un archivo me alcanzaba, al menos por el momento, para ese caso. Por lo que creé la siguiente subclase:

/**
*
* Instanciar siempre con getInstance.
* Loguea sobre application.log
* Configurable desde config.ini, variables log.*
*
* @author El /\/egro (Emilio Daniel Colombo)
*
*/
class Oh_Zend_Log extends Zend_Log
{
/**
*
* Singleton.
*
* @var Oh_Zend_Log
*/
private static $_instance = null;
/**
*
* Get Singleton.
*
* @return Oh_Zend_Log
*/
public static function getInstance() {
// Si no estaba instanciado, lo instancia y lo configura.
if (self::$_instance === null) {
self::$_instance = new self();

// Establece el archivo sobre el cual escribir.
$oConfig = Zend_Registry::get('config');
$oWriter = new Zend_Log_Writer_Stream(ROOT_DIR . $oConfig->log->application->file);
self::$_instance->addWriter($oWriter);

// Establece el filtro de tipos de logs.
$oFilter = new Zend_Log_Filter_Priority((int) $oConfig->log->application->priority);
self::$_instance->addFilter($oFilter);

// Indica a nivel de debug que se instanció el logger.
self::$_instance->info('Instanciación del logger');
}

// Devuelve la instancia.
return self::$_instance;
}

public function __destruct() {
$this->info('Destrucción del logger mediante ' . __METHOD__);
parent::__destruct();
}
}

Nota: A partir de aquí, a ésta subclase y a sus instancias las llamaré logger.

En ésta subclase en particular, se pueden notar tres cosas de relevancia:

  • Posee un pseudo-singleton. Estrictamente hablando, no es un singleton, pero como fue desarrollado con apuro, no lo creí necesario y para simplificar un poco el código (en Zend_Log el constructor es público, asi que no lo puedo redefinir como privado, por lo que para que sea realmente un singleton, hay que escribir algunas líneas más de código), me alcanzaba con tener una instancia única de clase a la que pudiera acceder en cualquier momento.
  • Si se crea la primer instancia de la clase mediante getInstance(), se autoconfigura la salida para que sea texto plano sobre un archivo especificado, y se crea una línea en el registro para indicar que se instanció el logger.
  • El destructor del logger registra su propia muerte en la salida configurada.

Para comenzar a enteder cómo funciona el logger para luego utilizarlo o crear uno que se ajuste a las distintas necesidades individuales, voy a explicar lo que realiza getInstance() para configurar los parámetros necesarios del logger, que como se puede apreciar, no tiene muchas líneas, y verán que tampoco tiene mucha complejidad.

Cuando se invoca al método getInstance() de la subclase para generar la primer instancia, al detectar que todavía no está generada la instancia, genera y almacena en la variable de clase una instancia de sí misma, que hereda todas las propiedades y los comportamientos de Zend_Log.

Luego, configura qué archivo debe ser el de salida:

// Establece el archivo sobre el cual escribir.
$oConfig = Zend_Registry::get('config');
$oWriter = new Zend_Log_Writer_Stream(ROOT_DIR . $oConfig->log->application->file);
self::$_instance->addWriter($oWriter);

Aquí probablemente se noten algunas cosas que no están claras, porque son del contexto del sistema sobre el que utilicé la clase. Se puede ver que utilicé otra herramienta muy útil de Zend Framework, el Zend_Registry, para almacenar variables de configuración que, a su vez, al iniciarse el sistema se obtienen desde un archivo de configuración. Otro elemento no especificado es la constante ROOT_DIR que también es definida al iniciarse el sistema, con la ruta raíz del proyecto.

Dejando éstos detalles específicos del proyecto al margen, lo importante es que al instanciar el Zend_Log_Writer_Stream se le debe enviar como parámetro el nombre del archivo sobre el cuál se desea que el logger escriba los registros. Una vez  creado este Zend_Log_Writer_Stream que se encargará de manipular el archivo, se le indica al logger que utilice éste writer stream para pasarle las líneas que deben escribirse.

Con ésto, ya estaría creada la instancia del logger, y configurado el lugar donde se volcará la información de depuración.

Falta un detalle que no es menor, que resultará de suma utilidad cada vez que se comience o se termine de depurar algún error con ayuda del archivo:

// Establece el filtro de tipos de logs.
$oFilter = new Zend_Log_Filter_Priority((int) $oConfig−>log−>application−>priority);
self::$_instance−>addFilter($oFilter);

Zend_Log permite añadir filtros sobre lo que se escribirá u omitirá en la salida. Es decir, ésto es lo que permitirá evitar el borrado de las líneas donde se realiza la escritura sobre el archivo de registros cuando se finalice la depuración para evitar que el archivo crezca descontroladamente, o para que el proceso de escritura no afecte el rendimiento del sistema. A continuación veremos que permite controlar de forma bastante granular la cantidad de información que debe escribirse en la salida.

El Zend_Log_Filter_Priority indicará un nivel de prioridad de filtrado de los registros a escribir. El constructor toma como parámetro un entero que especifica esa prioridad. Éstos enteros están también representados por constantes propias de la clase Zend_Log, que pueden verse en la parte superior de la definición de dicha clase:

class Zend_Log
{
const EMERG = 0; // Emergency: system is unusable // Emergencia: el sistema no puede utilizarse
const ALERT = 1; // Alert: action must be taken immediately // Alerta: debe tomarse una acción inmediatamente
const CRIT = 2; // Critical: critical conditions // Crítico: condiciones críticas
const ERR = 3; // Error: error conditions // Error: condiciones de error
const WARN = 4; // Warning: warning conditions // Advertencia: condiciones de advertencia
const NOTICE = 5; // Notice: normal but significant condition // Atención: condición normal pero significante
const INFO = 6; // Informational: informational messages // Informativo: mensajes informativos
const DEBUG = 7; // Debug: debug messages // Depuración: mensajes de depuración
(...)

 

(Me tomé la libertad de traducir al español el significado de los distintos niveles. No es una traducción oficial, y no es necesariamente correcta).

Como se puede ver, Zend_Log predefine ocho niveles de prioridad sobre los mensajes. La clase permite añadir niveles de prioridad, y está explicado en la documentación oficial de la misma. Generalmente, para el cas que se describe en éste artículo, no se necesitan más niveles de prioridad.

Nuevamente, en la definición de la subclase, se hace utilidad de variables de configuración con Zend_Registry. Pero simplemente lo que hay que especificarle por parámetro al constructor del Zend_Log_Filter_Priority es el nivel de prioridad por el que se debe filtrar, ya sea especificándolo como un número entero entre 0 y 7, o como una constante (como Zend_Log::DEBUG, Zend_Log::INFO, etc).

Una vez creado el filtro por nivel de prioridad, se le indica a la instancia que debe utilizar ese filtro, añadiendoselo con addFilter(). A partir de allí, sólo se enviarán al writer (o los writers; se puede añadir más de uno para un mismo Zend_Log) los registros que tengan prioridad igual o mayor a la especificada por el filtro.

Con ésto, cuando se desee depurar, se cambia la prioridad del filtro a Zend_Log::DEBUG (o simplemente 7), y cuando se deja de depurar, es conveniente cambiar la prioridad a, por ejemplo Zend_Log::ERR (o simplemente 3) para que sólo se registre información cuando ocurre algún error que tenga gran efecto sobre el sistema o su comportamiento, y así poder revisar el archivo de registros con cierta periodicidad para detectar si el sistema está fallando y en dónde.

Para poder continuar, el archivo al que apunta el writer debe estar creado. Es importante revisar que esté exactamente en la ubicación que especificamos, y que tenga los permisos necesarios para que el sistema pueda escribir en el mismo. Por ejemplo, en un sistema Linux habrá que asignarle los permisos de lectura y escritura a los usuarios y grupos necesarios. Para probar, al principio, lo más simple es dar permisos de lectura y escritura a todos los usuarios para el archivo en cuestión.

Ahora viene la parte divertida.

Una vez creada e incluída la clase del logger en el proyecto, sólo quedarían dos cosas por hacer: detectar por qué lugares de la lógica de negocio pasa el caso de uso que falla, y agregar algunas salidas en puntos clave que permitan saber qué se está haciendo, y qué estado tienen las variables más relevantes en esos puntos y después de ser modificadas.

Para escribir en el archivo, simplemente debe obtenerse la instancia de la clase (que si no existe, ella misma se encargará de instanciarse), y especificamos el mensaje, indicando también la prioridad del mismo.

La instanciación es simplemente así:

$oLogger = Oh_Zend_Log::getInstance();

 

La especificación del mensaje y de la prioridad para realizar la escritura se puede realizar de dos formas, dadas por Zend_Log:

Mediante el método genérico, enviando como parámetros el mensaje (en éste caso, un string) y la prioridad:

$oLogger−>log('Ésto es un mensaje', Zend_Log::INFO);
$oLogger−>log('Ésto es un mensaje con detalles adicionales', Zend_Log::DEBUG);

 

O mediante los pseudo-métodos específicos para cada prioridad:

$oLogger−>info('Ésto es un mensaje');
$oLogger−>debug('Ésto es un mensaje con detalles adicionales');

Ambos ejemplos escriben lo mismo en el registro. Zend_Log detecta cuando se invoca a un

 método que tiene el nombre de la constante de alguna de las prioridades, y genera la salida con esa prioridad.

Por defecto, Zend_Log escribe sobre el archivo con un formato donde se especifica la fecha y hora, la prioridad, el mensaje, y un retorno de carro al final de cada registro. Ésto puede ser configurado, y está especificado en la documentación oficial.

Hasta aquí, no pareciera muy distinto a escribir en un archivo con el error_log() de PHP, como dije antes. Pero si se organiza bien, puede ser bastante más útil.

Una forma mejorada de utilizarlo (que es como lo implementé yo en un caso donde me costó detectar el error) sería la siguiente:

Al comienzo de los métodos más importantes de alto nivel (es decir, métodos que realizan tareas bastante completas invocando a otros métodos menores; por ejemplo, un método que se encarga de realizar la registración completa de un usuario en la base de datos en base a los datos del formulario sin validar), crear un registro en el archivo que indique que se está por crear el usuario, en base a los datos pasados por parámetros, y dándole la prioridad de informativo. Por ejemplo:

$oLogger−>info("Creando usuario en el método: " . __METHOD__ . " con los datos: " . print_r($datosDelFormulario, true));

 

Donde $datosDelFormulario son los parámetros que le llegan al método en un array.

También al finalizar los métodos importantes de alto nivel, mostrar el resultado. Siguiendo el mismo ejemplo, al final del método que realiza la registración del usuario:

$oLogger−>info("Usuario creado exitosamente, en el método: " . __METHOD__ . " devolviendo: $variableQueVaARetornarse";

 

Donde $variableQueVaARetornarse es la variable que luego será puesta en el return de la función.

Antes de lanzar excepciones (al menos sobre las que se sospecha que se pueden estar lanzando, de las funciones que se están depurando), especificando la particularidad de la situación. Por ejemplo, antes de lanzar una excepción al no poder crearse un usuario:

$oLogger−>notice("Lanzando excepción desde " . __METHOD__ . " − No se puede crear el usuario con email $email porque ya existe en el sistema.");

 

Notar que en éste caso, es conveniente subir la prioridad del registro. En muchas excepciones, la prioridad va a ser más que simplemente informativa.

Zend_Log también permite pasar un Zend_Exception en vez de un mensaje. Lo detecta automáticamente como excepción, y lo envía a la salida con un formato legible para un desarrollador.

Antes de las estructuras de control de flujo críticas, complejas, o que se sospecha que estén fallando, indicando qué camino está tomando en el caso de un if, por ejemplo, o cuántas iteraciones está realizando un for y sobre qué valores va iterando.

Al recuperar datos de una base de datos, para saber si se está conectando correctamente y los datos están en el formato correcto.

Utilizar las prioridades de los mensajes correctamente. Por ejemplo:

  • Si se están registrando los datos que recorre una iteración, es información muy específica, por lo que debería ser con prioridad de debug.
  • Si se está informando sobre la acción que está por realizar un método y si terminó exitosamente, será con prioridad informativa.
  • Si es una excepción o error que es común que pase y ya está perfectamente diseñado el control de dicha excepción, como el email repetido en un nuevo usuario, será con prioridad notice.
  • Si se lanzó una excepción que está controlada, pero que no es común que suceda y se reinició cierto proceso para el usuario, será una advertencia.
  • Si se cortó el flujo de ejecución por algún error que todavía no está del todo contemplado, será con prioridad de error.
  • Si se detecta que se perdieron datos necesarios de la base de datos, será con prioridad crítica.
  • Si se detecta que se llenó el espacio del disco y no se pueden seguir guardando datos hasta que se libere, será con prioridad de alerta.
  • Si se detecta que la base de datos se cayó o perdió todos los datos y no se puede seguir utilizando el sistema, será con prioridad de emergencia.

Una vez que se entiende el funcionamiento básico de Zend_Log, luego es cuestión de creatividad y planificación para lograr un archivo con registros que permitan entender qué cosas está haciendo y por qué lugares está pasando el flujo de ejecución y por cuáles no.

Durante el proceso de depuración, la utilización de ésta herramienta radica simplemente en ejecutar el caso del que se conoce la precondición y la poscondición en particular sobre la que el sistema falla, analizar la salida que se vuelca sobre el archivo, detectar dónde es que las variables dejan de tener correspondencia con lo que deberían contener, acotar el rango del error agregando líneas que muestren más registros con información más detallada de lo que sucede, hasta que se encuentra el método minimal que falla, y se corrige el error. Luego, se aumenta la prioridad de registros que el filtro permite escribir, y se deja preparado para cuando se necesite realizar el mismo método.

De todas formas, es muy recomendable que no se abuse de la utilización del logger, incluso con la correcta utilización de los filtros, ya que si se utiliza sobre grandes iteraciones, por ejemplo, por más que la mayoría de la salida quede filtrada por prioridad, se están utilizando ciclos de reloj en realizar esas verificaciones, y para acceder a propiedades de diversos objetos, y para cambiar de contexto entre varios métodos anidados. Y es bien sabido que por más que sean pocos ciclos, en una gran iteración esos ciclos se pueden transformar fácilmente en segundos.

Con ésto doy concluída mi introducción a la herramienta de Zend_Log acompañada con una guía sobre cómo utilizarla como ayuda para resolver algunos problemas, con la esperanza de que a alguien más le sirva para resolver algunos errores en códigos muy entreverados que les complica el pensamiento a veces innecesariamente.

Ésta es la primer versión del artículo, y probablemente tenga que realizarle algunos ajustes, asi que incito al lector a dejar cualquier tipo de comentarios, incluyendo sugerencias sobre cómo podría mejorarse el artículo para estar más completo o más entendible.

Referencias externas:

Deja un comentario

Tu dirección de correo electrónico no será publicada. Los campos necesarios están marcados *

*

Puedes usar las siguientes etiquetas y atributos HTML: <a href="" title=""> <abbr title=""> <acronym title=""> <b> <blockquote cite=""> <cite> <code> <del datetime=""> <em> <i> <q cite=""> <strike> <strong>

© VB-MUNDO – Visual Basic y mucho más
CyberChimps