Un breve cuento de terror

Te han llamado en medio de la noche y no precisamente esa chica que acosas sino alguien de tu empresa, igual de asustado que ella pero más desesperado, con la voz entrecortada y en medio del llanto, pidiendo tu ayuda para revisar porque ese proceso nocturno que sólo puede ejecutarse en ese momento, no se está ejecutando? Seguramente sí y como es tu deber, ingresas al servidor afectado en busca de pistas, confiado en encontrar la causa en el log de la aplicación, solucionarlo en un par de minutos y poder así seguir con tu descanso. El plan va bien hasta que te encuentras con una o varias de estas situaciones:

  1. El log no existe
  2. El log existe pero… está en blanco
  3. El log no está en blanco pero… sólo contiene mensajes del tipo «Proceso ejecutado con éxito», sin un rastro de error
  4. El log tiene mensajes de error como «Ha ocurrido un error», hasta ahí, sin más detalle
  5. Tienes suerte y el log tiene «detalles» del error: «Ha ocurrido un error ERR00258» (Sí IIS, estoy hablando de ti!)

Hay otras variaciones de estas situaciones pero en cualquier caso el resultado es el mismo: no hay información suficiente que te ayude a diagnosticar la causa rápidamente, restablecer el servicio y descansar el resto de la noche y en lugar de ello, te cubres con la cobija para llorar más fuertemente que quien te llamó.

Un registro de eventos, bitácora o más comúnmente conocido como log, es una herramienta que bien utilizada, te brindará la información amplia y suficiente para actuar con seguridad cuando un componente falle y te dará información para determinar mejoras incluso si ese componente de software nunca llegase a fallar (…caso realmente hipotético)

A continuación veremos algunos tips de uso del log para evitar que te ahogues en llanto cuando ocurra ese momento «shit happens» y puedas tener la información adecuada a la mano.

Usa un Logger

Los administradores de servidores suelen desechar lo que imprime un servidor o contenedor de aplicaciones para evitar que su disco se llene de logs, por ejemplo, desviando la salida estándar hacia /dev/null. Esto causará que cualquier instrucción que imprima un texto en pantalla como System.out.println en Java, simplemente se pierda.

Otra razón más común es que el servidor se inicie sin un comando que envíe las instrucciones que imprime hacia un archivo, algo como servidor.sh start > archivo.log. En varios sistemas operativos el operador «>» (o «>>») causa que lo que imprima una aplicación en pantalla, se guarde en un archivo. Nadie te puede garantizar que así se inicie el servidor que contiene a tu aplicación

Para evitar un log en blanco, utiliza un logger, uno real como Log4J o Logback y no esa librería utilitaria de funciones estándar que construyó hace años alguien en tu empresa.

Utilizarlo es sencillo y no muy diferente a usar System.out.println:

public class HelloLogger {

private static Logger log = LoggerFactory.getLogger(HelloLogger.class);

  public static void main(String[] args) {
    log.info("Hello Logger!");
  }
}

Si quieres saber más sobre como configurar y usar un logger, visita la documentación de Logback o Log4J o deja un comentario si quieres que trate este tema en detalle.

Registra la información relevante

Te has encontrado (o has escrito…) mensajes del tipo «entró al método», «salió», «Si llegó aquí»? No lo niegues, tienes la culpa escrita en la cara.

Un log es útil si la información que allí se registra ayuda a diagnosticar el problema y para ello una librería de logging es realmente útil pues sólo utilizando configuración puedes registrar por ejemplo, el lugar exacto del mensaje… sin escribir código adicional!

Si ejecutas el fragmento de código anterior obtendrás un resultado similar al siguiente:

10:32:10.461 [main] INFO com.sinbugs.tips.logging.HelloLogger - Hello Logger!

El texto escrito por el logger contiene lo siguiente, en su orden:

  • Hora exacta hasta el milisegundo
  • Método en el cual se imprimió el texto
  • Nivel de importancia o prioridad del texto (INFO)
  • Paquete y clase en la que se encuentra el método
  • El mensaje que se quiere mostrar

Con un poco de configuración es posible agregar por ejemplo, el número de la línea de código que imprimió el mensaje, el archivo JAR que contiene a la clase e información de contexto (id de la petición o transacción, id de usuario, etc.). Intenta hacer lo mismo con System.out.println sin cambiar el código y entenderás porque es mil veces mejor usar un logger.

Utiliza adecuadamente los niveles de log

Todas las librerías de logging utilizan niveles de log o prioridades. El nombre puede cambiar según la librería pero el concepto es el mismo: una etiqueta que identifica a cada mensaje como perteneciente a una categoría, usualmente asociada al detalle e importancia del mensaje. Los niveles cambian entre frameworks o librerías siendo los más comunes los siguientes:

  • ERROR: Generalmente para excepciones o situaciones en las que el flujo de la aplicación se ve interrumpido
  • WARN: Advertencias, situaciones anormales que no interrumpen a la aplicación pero que podrían traer consecuencias más adelante
  • INFO: Para información general por ejemplo, cuando inicia o finaliza una transacción
  • DEBUG: Para información detallada, por ejemplo, el paso a paso de lo que está haciendo un proceso
  • TRACE: Para información muy detallada por ejemplo, valores de variables

Por ejemplo, una configuración de logback como la siguiente, habilita en la línea 10, los mensajes INFO y superiores (WARN y ERROR):

<?xml version="1.0" encoding="UTF-8"?>
<configuration>

	<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
		<encoder>
			<pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n</pattern>
		</encoder>
	</appender>

	<root level="info">
		<appender-ref ref="STDOUT" />
	</root>
</configuration>

Los niveles de log también son muy útiles para inspeccionar, filtrar o hacer búsquedas en logs utilizando herramientas como Stackify, DataDog, Lilith u otras.

No silenciar las excepciones

Es muy común encontrar código como el siguiente en aplicaciones de la vida real (incluso en grandes multinacionales):

try{
  ...
}catch(Exception e){
  e.printStackTrace();
}

En principio parece correcto pero… recuerdas el problema con utilizar la instrucción System.out.println? Es el mismo caso aquí: la traza de la excepción que es vital en un diagnóstico, simplemente se perderá porque printStackTrace utiliza la salida de error estándar, que generalmente también es la pantalla, para imprimir el mensaje. Al no utilizar un logger tampoco tienes el detalle de paquete, clase, método, etc, del contexto donde se generó la excepción.

Una mejor manera de hacerlo es reemplazar la instrucción printStackTrace por algo como log.error("Error en el proceso de negocio ABC", e), suponiendo que sabes que hacer con la excepción, de otro modo es mejor no atrapar la excepción o relanzarla para que las capas superiores la traten, excepto si la excepción se produce en un controlador web, en cuyo caso se debe registrar en el log y mostrar un mensaje apropiado al usuario.

Hasta aquí esta primera parte de consejos sobre como sacar el máximo provecho a tu log. Espera próximamente la segunda parte.