Bytes & Chips

Hemos ido asumiendo con el tiempo que aspectos como la seguridad y las pruebas deben de tenerse en cuenta durante todo el ciclo de vida del proyecto, desde sus orígenes hasta su finalización. Que no son requisitos no funcionales deseables o secundarios, si no que son prioritarios como parte de la estructura fundamental del aplicativo (hace no tanto eran funcionalidades o mecanismos que se diseñaban e implementaban a la finalización del proyecto como un añadido, si se hacían). Sin embargo la traza de aplicación, aún habiendo hecho méritos, no ha recibido en muchos casos la misma consideración ;-P.

En esta entrada no creo que os descubra nada nuevo a los que tengáis experiencia en el desarrollo. La idea es hacer un ejercicio de síntesis y revisión para resumir lo que, en mi opinión, son las mejores o las buenas prácticas del log de aplicación. Por supuesto, las aportaciones, observaciones, matizaciones y críticas son bienvenidas; os invito a que os unáis a este ejercicio.

El log o traza de aplicación es el procesado y almacenamiento de información relativa a la ejecución de una aplicación. Contiene datos de entidades, cambios de estado y componentes software involucradas en dicha ejecución. Su principal funcionalidad es facilitar el seguimiento o análisis de la ejecución de la aplicación:

• Analizar el comportamiento de la aplicación durante la fase de desarrollo y depuración (pruebas de caja blanca)
• Analizar los bugs o errores de ejecución detectados, sus causas y consecuencias
• Servir de registro de auditoría cuando la información contenida y el modo en que se ha procesado cumpla los criterios requeridos
• Medir el rendimiento o carga de los sistemas o aplicaciones
• Revertir el estado del aplicativo siguiendo en orden inverso el log

Aunque depende de las circunstancias en las que nos encontremos, el segundo de los usos suele ser el más relevante. Un buen log desarrollado correctamente en el código y mantenido o configurado en explotación es una garantía de respuesta rápida para análisis de errores; que incluso podrían hacerse sin necesidad de parar el aplicativo, reconfigurarlo o aplicarle ningún cambio.

La traza de aplicación suele formarse por un conjunto de eventos que se almacenan secuencialmente, por lo general en el orden en que suceden, de manera persistente o recuperable. Se pueden almacenar en ficheros, en BBDD, en componentes distribuidos a tal efecto… Se pueden habilitar mecanismos de rotación o historificación de estos logs, se pueden utilizar por monitores para lanzar alertas, se pueden integrar y fusionar para hacer análisis más exhaustivos… Lo relevante es que la información registrada y la forma en que se gestiona sea útil.

Existen numerosas soluciones y propuestas software, tanto libres como propietarias, más o menos estandarizadas, más sencillas o más completas, de mil tipos y formas. Lo importante es buscar aquella se ajusta a nuestras necesidades y entornos, para olvidarnos de la implementación del mecanismo por completo; y ceñirnos a los dos aspectos más importantes:

• El contenido de cada registro o evento, principal preocupación del desarrollador
• El modo en que se procesa, persiste y gestiona, principal preocupación de la explotación del sistema o aplicativo

El coste de implementación del logging se encuentra en el ir, mientras se desarrolla, dejando traza en los diferentes puntos del código. Esta actividad debe hacerse durante el desarrollo, siguiendo patrones, criterios y procedimientos preestablecidos. De esta manera los desarrolladores tendrán criterios comunes y la traza será coherente entre las diferentes partes del código.

La traza y la documentación del código pueden tener puntos en común en cuanto a su filosofía, objetivos y modo de aplicación, pero existe una diferencia importante entre ambos: mientras la documentación del código se adentra en el por qué se hace algo de esa manera, la traza debe cubrir el qué se hace. Por poner un ejemplo, en un bucle la documentación del código debería indicar por qué los límites o condiciones de salida son tales y la traza registrar durante la ejecución en qué punto se cumplió dicha condición de salida.

La información registrada en la traza debe ser relevante y completa. Se pueden considerar los siguientes aspectos a la hora de decidir qué información incluir:

• Qué:
  • Qué evento o acción ha ocurrido.
  • Qué entidades han estado involucradas.
  • Si hay un cambio de estado, ¿cuál era el anterior? ¿cuál es el nuevo estado?.
• Dónde:
  • En qué punto del código ha ocurrido: componente, clase, fichero de código, método o bloque de ejecución, línea de código… Cuanto más detallada sea esta información mejor para localizar el lugar del posible error o por donde ha pasado la ejecución, por un lado; pero más puede afectar el logging al rendimiento (se podría requerir información de debug) y a la concrección de la información de la traza, por otro.
• Cuándo:
  • Registrando el momento temporal, bien absoluto o bien relativo al comienzo de ejecución o cualquier otro evento.
  • Generando una traza secuencial o causal, en la que los eventos que ocurren antes en el tiempo o que ocasionan otros, aparezcan antes.
• En qué contexto:
  • Registrando estados o variables: propios de la ejecución (parámetros), de personalización o específicos de usuario, referentes a la sesión o transacción en ejecución…
  • Indicando hebras, transacciones o peticiones relacionadas cuando estemos en entornos concurrentes.

Para que la información de la traza sea más detallada en momento de análisis y más manejable durante la explotación de la misma, se establecen niveles de filtrado. De tal manera que solo se muestra o almacenan aquellos eventos con un nivel mayor o igual al del nivel de traza establecido. Las librerías de logging permiten filtrar los eventos por otros criterios como son la clase o contexto del evento, también.

Los niveles más comunes son DEBUG, INFO, WARNING y ERROR. La clasificación de los diferentes eventos en cada nivel es parte del ejercicio de análisis, y deben orientarse a que la traza sea legible y útil en los diferentes contextos del aplicativo, desde el desarrollo hasta la explotación.

Este puede ser un ejemplo de semántica de niveles de logging:

• DEBUG, para información de muy bajo nivel solo útil para el debug de la aplicación, tanto en el desarrollo como en el análisis de incidencias
  • Llamadas a funciones y procedimientos y otros componentes, con parámetros y respuestas
  • Flujos de ejecución
  • Desarrollo de algoritmos y procedimientos que permitan identificar y seguir su ejecución en desarrollo
• INFO, información de más alto nivel que permita hacer un seguimiento de la ejecución normal
  • Paradas y arranques de servicios y sistemas
  • Parámetros críticos o relevantes de configuración
  • Comienzo y fin de transacciones y operaciones completas
  • Cambios de estado de operaciones
• WARN, información de situaciones, que aún sin ser de error, si son anómalas o no previstas, aunque el aplicativo tiene alternativas para solventarlas
  • Parámetros no definidos, y cuyo valor se toma por defecto
  • Situaciones anómalas, pero que son resueltas por el aplicativo, dejando la operación en un estado correcto
  • Funcionalidades no primordiales o imprescindibles, que no pueden resolverse, pero que dejan la operación en un estado correcto
• ERROR, información de situaciones que son de error y que impiden la ejecución correcta de una operación o transacción, pero sin afectar a otras operaciones o transacciones (error aislado o contenido)
  • No se pudo realizar una operación o transacción, pero no afecta a otras
  • Peticiones o consultas erróneas (almacenando los parámetros de entrada)
  • Funcionalidades generales del aplicativo, que aún afectando al funcionamiento general del aplicativo, no se consideran primordiales o imprescindibles
• FATAL, información de situaciones de error que afectan al funcionamiento general del aplicativo (errores no aislados o contenidos en alcance)
  • Parámetros no definidos o configuraciones erróneas
  • Falta de conexión o comunicación con otros componentes
  • Errores de ejecución que pueden afectar a operaciones o transacciones independientes, o que afectan al funcionamiento general de la aplicación

Tanto el contenido y forma de cada evento de log, como la semántica de los niveles son parte del diseño del aplicativo. Estos criterios deben definirse y ser comunicados al equipo de desarrollo para que se apliquen de manera homogénea y coherente en todo el desarrollo. Si estos criterios son consensuados con el equipo se puede sacar mucho provecho de la experiencia de los desarrolladores.

Otras recomendaciones a tener en cuenta son:

• Registrar los eventos de manera atómica, que toda la información referente a un evento se almacene en un registro o línea.
• Orientar el formato de la información mostrada a poder ser usado de manera informatizada o automática con herramientas específicas.
• En lo referente a excepciones:
  • Mostrar siempre la traza completa de la excepción con su mensaje y todo el stacktrace.
  • Si la excepción es capturada, tratada y luego lanzada de nuevo (bien la misma u otra) no dejar traza de la excepción hasta que se capture y se trate en última instancia. De esta manera cada excepción solo se mostrará una vez. Si no lo hacemos así y registramos cada captura y relanzamiento aparacerá en la traza varias veces y no sabremos si es la misma o son varias. (Antipatrón catch-log-throw).
  • Hacer uso de la propiedad de excepción causante o interna cuando capturemos y relancemos la excepción. En Java es el método getCause(), en .NET la propiedad InnerException.

• Hacer uso de mecanismos de MDC/NDC (información de contexto) para entornos de múltiples hebras o ámbitos de transacción. Esta información nos puede permitir filtrar o concretar la información de log  en contexto de negocio específicos como pueden ser clientes, usuarios, productos…
• Implementar el método toString() de todas las clases de negocio o POJOs para facilitar su traceado.
• Hay que tener en cuenta las diferencias y zonas horarias a la hora de trabajar con logs de varias máquinas o componentes.
• El logging no puede tener efectos laterales, no puede modificar el estado de ningún parámetro, variable o procedimiento. Solo muestra información. Debe ser ligero, el propio logging no puede requerir de procesamientos largos o costosos.
• Las llamadas a métodos, componentes y componentes distribuidos externos, deberían registrarse tras la llamada incluyendo los parámetros de entrada y la respuesta, así como clase/componente y método, a nivel de DEBUG. Y a nivel de ERROR y FATAL cuando ocurra un error en la llamada (si fuese una excepción se debe tracear parámetros de entrada y excepción)

Un saludo,

Juan Francisco Adame Lorite