Mi granito de java: Log4j

martes, 26 de julio de 2011

Log4j

La experiencia indica que el logging forma parte importante del desarrollo de una aplicación. Sobretodo porque nos permite conocer el estado de los objetos en un momento determinado.

Log4j es un framework de Java que se utiliza como herramienta de logging. Muchas veces utilizamos el limitado pero efectivo System.out.printl() para realizar salidas por consola o hacer seguimiento de un error. Si bien a veces con esto alcanza, la realidad es que su alcance es limitado. Hay diversas situaciones en las cuales encuestaríamos algo más completo. Se me ocurre, por ejemplo:
  • Quiero guardar un archivo con las salidas de la consola.
  • Quiero ver los mensajes con un formato determinado.
  • ¿Que pasa en los casos donde ocurre un error en producción que no se replica en desarrollo? Llenamos de log nuestro código para poder seguirlo! Y cuando lo encontramos, tenemos que volver a sacar todas las líneas que hemos puesto por las distintas clases! Sin contar la cantidad de veces que debo realizar el deploy en producción. Por otro lado, si lleno el código de log, se llena la consola sin sentido, pero sería bueno guardar esas líneas de log por las dudas...entonces ¿No sería bueno tener diversos niveles de log y que se ejecuten las lineas de log que yo quiero con solo modificar el nivel en un archivo de configuración? Estos y otros problemas los puede arreglar Log4j.

    Características de Log4j.

    Es simple de usar y entender. Fue hecho en Java; es open source y fue desarrollada en Java por la Apache Software Foundation que permite a los desarrolladores de software elegir la salida y el nivel de granularidad de los mensajes o “logs” (logging) en tiempo de ejecución y no en tiempo de compilación como es comúnmente realizado. Como si fuera poco, es más rápdio que realizar un System.out.print() y le ocupa al sistema menor cantidad de recursos.
    La configuración de salida y granularidad de los mensajes es realizada mediante un archivo de configuración externo. Adenás de Java, Log4J ha sido implementado en otros lenguajes como: C, C++, C#, Perl, Python, Ruby y Eiffel.
    La página oficial de Log4J es http://logging.apache.org/log4j/ y desde allí debemos bajar los jars necesarios para trabajar en nuestro programa.



    Configuración y uso.

    Podriamos dividir en dos partes a Log4j. La primer parte consiste en configurarlo. Esto se hace una sola vez y nunca más. En el 99% de los casos no lo tendremos que hacer nosotros, pero es bueno saber como se configura por si alguna vez caemos dentro de ese 1%. La configuración por lo general reside en un archivo de propiedades llamado log4j.properties. Pero debemos tener en cuenta que se puede hacer mediante un achivo xml o programáticamente. Esta última opción no es recomendable ya que se debe tocar código y compilar de nuevo cada vez que se quiere cambiar el nivel del logging.
    La segunda parte consiste en saber usarlo. Es la parte más sencilla y con sólo aprender 2 o 3 tips y ya estamos listos.
    Primero veremos como se configura y al final de este post veremos como se usa. Si sólo necesitan usarlo pueden ir directamente al final donde se muestran unos ejemplos de uso.

    Niveles de prioridad.

    Log4j tiene tres components principales para configurar: loggers, appenders y layouts (que los veremos más adelante). Estos tres funcionan juntos para loggear de acuerdo al tipo de mensaje y formato. Cuando escribamos un mensaje para que vaya al log debemos especificar su nivel de prioridad. Por defecto Log4J tiene 6 niveles de prioridad para los mensajes (trace, debug, info, warn, error, fatal). Además existen otros dos niveles extras (all y off).
    Niveles de prioridad (De mayor -poco detalle- a menor -mucho detalle-):
    • FATAL: se utiliza para mensajes críticos del sistema, generalmente después de guardar el mensaje el programa abortará.
    • ERROR: se utiliza en mensajes de error de la aplicación que se desea guardar, estos eventos afectan al programa pero lo dejan seguir funcionando, como por ejemplo que algún parámetro de configuración no es correcto y se carga el parámetro por defecto.
    • WARN: se utiliza para mensajes de alerta sobre eventos que se desea mantener constancia, pero que no afectan al correcto funcionamiento del programa.
    • INFO: se utiliza para mensajes informativos sobre el avance de la aplicación. Estimo que deb ser el más utilizado de todos los niveles.
    • DEBUG: se utiliza para escribir mensajes de depuración. Este nivel no debe estar activado cuando la aplicación se encuentre en producción.
    • TRACE: se utiliza para mostrar mensajes con un mayor nivel de detalle que debug.
    Extras:
    • ALL: este es el nivel de máximo detalle, habilita todos los logs (en general equivale a TRACE).
    • OFF: este es el nivel de mínimo detalle, deshabilita todos los logs.
    Por lo general, INFO y DEBUG son los utilizados.

    Appenders.

    En Log4J los mensajes son enviados a una (o varias) salida de destino, lo que se denomina un appender. Existen varios appenders y también podemos crear propios. Típicamente la salida de los mensajes es redirigida a un fichero de texto .log (FileAppender, RollingFileAppender), a un servidor remoto donde almacenar registros (SocketAppender), a una dirección de correo electrónico (SMTPAppender), e incluso en una base de datos (JDBCAppender). Casi nunca es utilizado en un entorno de producción la salida a la consola (ConsoleAppender) ya que perdería gran parte de la utilidad de Log4J.

     No se precupen si no entienden la configuración, de a poco vamos a ver cada punto.

    *Fe de erratas: donde dice No mostrará mensajes por debajo del nivel INFO debería decir No mostrará mensajes por debajo del nivel DEBUG

    Los appenders se configuran en el archivo externo.Los appenders que vienen con Log4J se encuentran en el paquete org.apache.log4j. Estos son:

    ConsoleAppender

    Este appender despliega el log en la consola; tiene las siguientes opciones:

    • Threshold=WARN: Este parámetro establece que el appender no despliega ningún mensaje con prioridad menor a la especificada aquí.
    • ImmediateFlush=true: El valor por defecto es true, esto quiere decir que los mensajes de log no son almacenados en un buffer, sino que son enviados directamente al destino.
    • Target=System.err: El valor por defecto es System.out. Establece la salida del sistema a ser utilizada.

    FileAppender

    Este appender redirecciona los mensajes de logs hacia un archivo.

    • Threshold=WARN: Este parámetro establece que el appender no despliega ningún mensaje con prioridad menor a la especificada aquí.
    • ImmediateFlush=true: El valor por defecto es true, esto quiere decir que los mensajes de log no son almacenadosen un buffer, sino que son enviados directamente al destino.
    • File=mylog.txt: Nombre del archivo donde se almacenará el log. Se puede utilizar el nombre de algún property (${nombre_de_la_propiedad}) para especificar el nombre o la ubicación del archivo.
    • Append=false: El valor por defecto es true, para que los nuevos mensajes de logs se adicionen al archivo existente.
    • Si se especifica false, cuando se inicie la aplicación el archivo de log se sobreescribirá. 


      RollingFileAppender

      Este appender redirecciona los mensajes de logs hacia un archivo y permite definir politicas de rotación para que el archivo no crezca indefinidamente.

      • Threshold=WARN: Este parámetro establece que el appender no despliega ningún mensaje con prioridad menor a la especificada aquí.
      • ImmediateFlush=true: El valor por defecto es true, esto quiere decir que los mensajes de log no son almacenados en un buffer, sino que son enviados directamente al destino.
      • File=mylog.txt: Nombre del archivo donde se almacenará el log. Se puede utilizar el nombre de algún property (${nombre_de_la_propiedad}) para especificar el nombre o la ubicación del archivo.
      • Append=false: El valor por defecto es true, para que los nuevos mensajes de logs se adicionen al archivo existente. Si se especifica false, cuando se inicie la aplicación el archivo de log se sobreescribirá.
      • MaxFileSize=100KB: Los sufijos pueden ser KB, MB o GB. Rota el archivo de log cuando alcanza el tamaño especificado.
      • MaxBackupIndex=2: Mantiene un máximo de 2 (por ejemplo) archivos de respaldo. Borra los archivos anteriores.Si se especifica 0 no se mantiene respaldos.

      DailyRollingFileAppender

      Este appender redirecciona los mensajes de logs hacia un archivo y permite definir politicas de rotación basados en fechas.

      • Threshold=WARN: Este parámetro establece que el appender no despliega ningún mensaje con prioridad menor a la especificada aquí.
      • ImmediateFlush=true: El valor por defecto es true, esto quiere decir que los mensajes de log no son almacenados en un buffer, sino que son enviados directamente al destino.
      • File=mylog.txt: Nombre del archivo donde se almacenará el log. Se puede utilizar el nombre de algún property (${nombre_del_property}) para especificar el nombre o la ubicación del archivo.
      • Append=false: El valor por defecto es true, para que los nuevos mensajes de logs se adicionen al archivo existente.Si se especifica false, cuando se inicie la aplicación el archivo de log se sobreescribirá.
      • DatePattern='.'yyyy-ww: Rota el archivo cada semana Se puede especificar que la frecuencia de rotación sea mensual, semanal, diaria, 2 veces al día, cada hora o cada minuto. Este valor no solo especifica la frecuencia de rotación sino el sufijo del archivo de respaldo. Algunos ejemplos de frecuencia de rotación son:

      1. '.'yyyy-MM: Rota el archivo el primero de cada mes
      2. '.'yyyy-ww: Rota el archivo al inicio de cada semana
      3. '.'yyyy-MM-dd: Rota el archivo a la media noche todos los días
      4. '.'yyyy-MM-dd-a: Rota el archivo a la media noche y al media día, todos los días
      5. '.'yyyy-MM-dd-HH: Rota el archivo al inicio de cada hora
      6. '.'yyyy-MM-dd-HH-mm: Rota el archivo al inicio de cada minuto

      SocketAppender

      Redirecciona los mensajes de logs hacia un servidor remoto de log.

      El mensaje de log se almacenará en el servidor remoto sin sufrir alteraciones en los datos (como fecha, tiempo desde que se inicio la aplicación, NDC), exactamente como si hubiese sido guardado localmente.

      El SocketAppender no utiliza Layout. Únicamente serializa el objeto LoggingEvent para enviarlo.
      Utiliza TCP/IP, consecuentemente si el servidor es accesible el mensaje eventualemente arribará al servidor. Si el servidor remoto está abajo, la petición de log será simplemente rota. Cuando el servidor vuelva a estar disponible la transmisión se reasume transparentemente.Esta reconexión transparente es realizada por un connector thread que periodicamente revisa si existe conexión con el servidor.

      Los eventos de logging son automaticamente almacenados en memoria por la implementación nativa de TCP/IP. Esto quiere decir que si la conexión hacia el servidor de logs es lenta y la conexión con los clientes es rápida, los clientes no se ven afectados por la lentitud de la red.

      El SocketAppender tiene las siguientes propiedades:
      • Threshold=WARN: Este parámetro establece que el appender no despliega ningún mensaje con prioridad menor a la especificada aquí.
      • ImmediateFlush=true: El valor por defecto es true, esto quiere decir que los mensajes de log no son almacenados en un buffer, sino que son enviados directamente al destino.
      • port=6548: Especifica el puerto por el que se va a comunicar al servidor de logs.
      • remoteHost=192.168.10.225: Especifica la máquina donde se encuentra el servidor de logs.
      • reconnectionDelay=300: El valor por defecto es de 30000 milisegundos, que corresponden a 30 segundos. Es un valor entero que corresponde al número de milisegundos que va a esperar para volver a intentar conectarse con el servidor cuando se ha perdido comunicación con este.

      SMTPAppender

      Envia un mail con los mensajes de logs, típicamente se utiliza para los niveles ERROR y FATAL.

      El número de eventos de log enviados en el mail depende del valor de BufferSize. El SMTPAppender mantiene únicamente el último BifferSize en un buffer cíclico.
      • Threshold=WARN: Este parámetro establece que el appender no despliega ningún mensaje con prioridad menor a la especificada aquí.
      • ImmediateFlush=true: El valor por defecto es true, esto quiere decir que los mensajes de log no son almacenados en un buffer, sino que son enviados directamente al destino.
      • To=direccion1@dominio.com: Especifica la dirección de correo a donde se enviará el mail.
      • From=direccion2@dominio.com: Especifica la dirección de correo desde donde se envia el mail.
      • SMTPHost=mail.dominio.com: Especifica el servidor de SMTP que se va a utilizar para enviar el mail.
      • Subject=Mensajes de Logs: Especifica el asunto del mail.
      • LocationInfo=true: El valor por defecto es false. Envía información acerca de la ubicación donde se generó el evento de log.
      • BufferSize=20: El valor por defecto es 512. Representa el número máximo de eventos de logs que serán recolectados antes de enviar el mail.

      JDBCAppender

      Este appender redirecciona los mensajes de log hacia una base de datos.

      • Threshold=WARN: Este parámetro establece que el appender no despliega ningún mensaje con prioridad menor a la especificada aquí.
      • ImmediateFlush=true: El valor por defecto es true, esto quiere decir que los mensajes de log no son almacenados en un buffer, sino que son enviados directamente al destino.
      • Driver=mm.mysql.Driver: Define el driver a ser utilizado, asegurese de tener la clase en el CLASSPATH.
      • URL=jdbc:mysql://localhost/LOG4JDemo: Es la cadena de conexión que se utilizará.
      • ser=default: El usuario de la base de datos.
      • password=default: La clave para poder ingresar a la base de datos.
      • sql=INSERT INTO TABLA (Message) VALUES ('%d - %c - %p - %m'): La instrucción SQL que se utiliza para grabar el mensaje en la base de datos. Si se desea se puede guardar cada valor en columnas separadas,por ejemplo: INSERT INTO JDBCTEST (Date, Logger, Priority, Message) VALUES ('%d', '%c', '%p', '%m').

      Otros appeders:
      SyslogAppender: redirecciona los mensajes de logs sistemas operativos Unix.

      NTEventLogAppender: redirecciona los mensajes de logs hacia los logs del sistema de NT.

      JMSAppender: serializa los eventos y los transmite como un mensaje JMS tipo ObjectMessage.


      Layouts

      Es el responsable de dar un formato de presentación a los mensajes. Permite presentar el mensaje con el formato necesario para almacenarlo simplemente en un archivo de texto .log (SimpleLayout y PatternLayout), en una tabla HTML (HTMLLayout), o en un archivo XML (XMLLayout).
      Además podemos añadir información extra al mensaje, como la fecha en que se generó, la clase que lo generó, el nivel que posee, etc. Inclusive se pueden crear layouts propios. Basta con heredar de la clase org.apache.log4j.Layout.
      Los layouts que vienen con el PI son: DateLayout, HTMLLayout, PatternLayout, SimpleLayout, XMLLayout.
      SimpleLayout, como lo indica su nombre, es algo simple: nivel de prioridad, un "-" y el mensaje en cuestión. Por ejemplo: INFO - Hola Mundo!
       El más utilizado es PatternLayout ya que permite darnos la libertad de utilizar la creatividad para crear el formato de los mensajes. Para ello, debemos aprender algunos patrones:
      •     %m: muestra el mensaje.
      •     %p: muestra el nivel de prioridad.
      •     %r: muestra los milisegundos desde que comenzo la aplicación hasta el evento que se logueó.
      •     %t: muestra el nombre del thread que loguel el evento.
      •     %x: muestra el NDC  del thread que loguel el evento.
      •     %n: deja un renglón, con lo cual nos olvidamos de "\n" o "\r\n".
      •     %c: categoría del evento que figura en la configuración.
      •     %%: muestra un signo de porcentaje.
      •     %d: muestra la fecha del vento, que se le puede dar un formato determinado, por ejemplo %d{HH:mm:ss,SSS} o %d{dd MMM yyyy HH:mm:ss,SSS}.
      •     %C: muestra el nombre de la clase que logueo el evento.
      •     %M: muestra el método de la clase que logueo el evento.
      •     %L: muestra el número de línea donde se logueo el evento.
      Obviamente utilizar la fecha (el  %d) hace el logueo más pesado.

      Opcionalmete, se puede especificar los márgenes de cada uno:
      •     Se utiliza el signo menos (-), seguido de un entero para el margen izquierdo.
      •     Se utiliza un entero para el margen derecho.
      •     Se utiliza un punto (.) con un entero para el ancho mínimo.
      Ejemplos:
        %20p: espacios que tenrá a la derecha el nivel de prioridad.
        %-20p: espacios que tenrá a la izquierda el nivel de prioridad.



      Configuración del entorno.

      El entorno log4j es completamente configurable programaticamente. Sin embargo, es mucho más flexible configurar log4j usando archivos de configuración . Estos archivos pueden estar escritos en XML o en Java properties (formato key=value).

      Veamos un ejemplo, con un archivo properties donde se colocan dos appenders: uno para realizar una salida por consola y otro para que guarde un archivo. Por otro lado, cada appender tiene un nivel de prioridad distinto.

      log4j.rootCategory= miArchivo, miConsola
      # Indica alias para las salidas de log, podemos tener varias

      log4j.appender.miArchivo=org.apache.log4j.FileAppender
      # Appender miArchivo (lugar donde se envian los mensajes) es un archivo

      log4j.appender.miArchivo.Threshold=INFO
      # No mostrará mensajes por debajo del nivel INFO

      log4j.appender.miArchivo.ImmediateFlush=true
      #  Se vuelca el mensaje inmediatamente en el appender

      log4j.appender.miArchivo.file=C:/Users/Admin/Documents/Java/logFile.log
      #  Archivo (appender)

      log4j.appender.miArchivo.layout=org.apache.log4j.PatternLayout
      #  Tipo de diseño de los mensajes

      log4j.appender.miArchivo.layout.ConversionPattern=%d %-5p %C.%M(%L)===> %m%n
      # Diseño 

      log4j.appender.miArchivo.append=false
      # No añade, borra el contenido anterior

      log4j.appender.miConsola=org.apache.log4j.ConsoleAppender
      # Appender de miConsola

      log4j.appender.miConsola.Threshold=DEBUG
      # No mostrará mensajes por debajo del nivel INFO

      log4j.appender.miConsola.layout=org.apache.log4j.PatternLayout
      # miConsola utiliza PatternLayout

      log4j.appender.miConsola.layout.ConversionPattern=%-4r [%t] %-5p %c %x - %m%n
      # Diseño

      Como se puede observar en el ejemplo, usarlo es muy sencillo, basta con decirle a Log4j que nuestra clase quiere guardar log mediante la sentencia Logger.getLogger(Clase.class) y listo. Con eso es suficiente para utilizarlo. Si prestan atención cuando se loguea un mensaje, se coloca el nivel de prioridad.
      Veremos como quedó el archivo que grabó el log con un nivel de prioridad distinto al de la consola:

      13 comentarios:

      Anónimo dijo...

      No conocia este blog, aunque deberia...de ahora en adeltante lo he de visitar mas amenudo....felicitaciones!!

      Max dijo...

      Muchas gracias!

      Eder Fontalvo Melendez dijo...

      Muy bien Blog, he estado viendo blog de logging en Java, pero solo conseguía del 2009 hacia atrás.

      shianim dijo...

      Hola tengo la siguiente duda:

      Se puede hacer que el archivo de log salga de la sigiente manera:

      logFile_fecha_y_hora.log

      Donde fecha_y_hora corresponde a la fecha en que el archivo fue creado???

      Espero me puedan ayudar.

      Muchas Gracias.

      Max dijo...

      Hola Shianim, nunca lo he hecho pero calculo que se puede hacer sin problemas agregando en el nombre del archivo: logFile%d{HH:mm:ss,SSS} o el formato que quieras. Probalo y contame :)

      El lado oscuro de java dijo...

      Hola muy buena pagina! yo tambien estoy documentando info de log4j en mi blog, te tomo como fuente saludos!

      Anónimo dijo...

      como puedo mapear un entero en el log4j.xml para ingresarlo a la base de datos....se puede o solo se pueden con Strings, ya que quisiera guardar unos valores enteros

      Anónimo dijo...

      Excelente blog! Me sirvio mucho! :D

      Anónimo dijo...

      muy interesante el blog y felicitaciones al que lo hizo, weno una pregunta, puedo registrar en el log que registro modifique o cree en mi aplicacion, o almenos mostrar la consulta como lo muestra hibernate en la consola, gracias

      Anónimo dijo...

      He hecho todo como en el ejemplo y no me crea el fichero ni me saca nada por pantalla. ¿donde puede estar el error?

      Max dijo...

      Muchas gracias por los comentarios. Para el ultimo usuario: deberia ver que error te tira como para guiarme.

      Dan dijo...

      Excelente trabajo, Max.

      Ya conocía la potencia de log4j pero hay un montón de funcionalidad fuera de lo habitual (como el JDBCAppender) de lo más interesante. Muchas gracias por tu contribución.

      Estoy trabajando en un proyecto en el que se desea generar un fichero de log por cada clase java (no comments). ¿Conoces alguna forma más "ágil" de hacer esto sin tener que definir un appender por cada una de las tropecientasmil clases?

      Muchas gracias por adelantado y de nuevo enhorabuena por el blog.

      Anónimo dijo...

      Gran articulo!!!

      De todos los que he visto acerca del Log4j el mejor!!!

      He conseguido que me funcione correctamente, he cambiado la ruta del archivo de log que quiero que me cree, pero este no se crea ¿Por qué puede ser?