Sistemas de Trazas

Introducción

Quien no ha puesto un System.out.println para escribir en la consola el valor de una variable? Y el típico mensaje ?llega aquí?????. Sin duda alguna, esta es la forma más sencilla y más utilizada de depurar nuestro código.

En base a esta idea se han ido creando sistemas de gestión de logs/trazas que han ido añadiendo diversas funcionalidades demandadas por los programadores.

Este articulo intenta explicar como utilizar los mas conocidos, Jakarta-Log4j, el nuevo paquete de la JDK1.4 java.util.logging y Jakarta-Commons-Logging.

Jakarta-Log4j

Jakarta-Log4j es una de las más antiguas, potentes y conocidas. Entre sus características principales se encuentran:

 

  • Diferentes niveles de traza. (Error, información, depurar.)
  • Filtros según categoría
  • Redirección de las trazas a diferentes destinos. (A un archivo, a consola, a BBDD.)
  • Diferentes formatos de visualización. (Visualizar fecha, línea, nombre de la clase..)
  • Configuración por ficheros

 

Vamos a ir descubriendo estas características paso a paso:

Niveles de Prioridad de Traza

Log4j provee al programador de 5 niveles de traza:

 

  • OFF, no se muestra en ningún caso
  • FATAL, para mostrar mensajes de situaciones que probablemente harán abortar la aplicación
  • ERROR, para mostrar mensajes de errores que no son deseados pero que no interrumpirán la aplicación
  • WARN, para mostrar mensajes de contextos peligros para la aplicación, o ciertas operaciones de uso no recomendado
  • INFO, para mostrar mensajes de información sobre la ejecución de la aplicación, o eventos importantes dentro de la misma
  • DEBUG, para mostrar mensajes interesantes para depurar la aplicación. Muy orientado al tiempo de desarrollo
  • ALL, se muestra en todos los casos

 

Cuando escribimos nuestras aplicaciones, las trazas se escriben en los diferentes niveles dependiendo de la operación que se utilice. Así para escribir en el nivel INFO se usa log.info("Nivel Info"); y para el nivel DEBUG log.debug("Nivel Debug").

Por lo general el nivel de prioridad esta fijado por defecto a INFO, por lo que los mensajes de nivel DEBUG no son visualizados. Este nivel genera un caudal elevado de trazas por lo que su uso suele estar restringido a entornos de desarrollo.

Un apartado importante en el uso de las trazas es como utilizarlas cuando se producen errores/excepciones. No siempre hay que escribir las trazas de excepciones a nivel de error, ya que en algunos casos no interesa que se visualicen.

En caso de escribir componentes que posteriormente utilicen otras personas, convendra relanzar la excepción y escribir la traza a nivel de DEBUG o INFO dependiendo de si el programador sera el propio usuario de la clase o si un tercero sera quien la utilice.

Categorías (ó como filtrar las trazas)

Para ver esta característica es necesario adentrarse un poco más en la configuración y el código necesario para trabajar con Log4j. En el siguiente ejemplo se muestra como tracear una clase.

                    import org.apache.log4j.*
public class Pruebaslog4j {
Logger log = Logger.getLogger(this.getClass());
/** Creates a new instance of Pruebaslog4j */
public Pruebaslog4j () {
try {
log.info("Constructor");
log.warn("nivel WARN");
if (log.isDebugEnabled()) {
log.debug("Traza de nivel debug");
}
} catch (IllegalStateException e) {
log.error("Traza de nivel error", e);
}
}
/**
* @param args the command line arguments
*/
public static void main(String[] args) {
Pruebaslog4j pl4j = new Pruebaslog4j ();
}
}

En la segunda línea se obtiene el objeto con el cual se escriben las trazas, el objeto Logger. Se puede hacer referencia a este objeto bajo el nombre "escritor", ya que es el quien se encarga de escribir los mensajes a los diferentes soportes con los cuales Log4j trabaja.

Para obtener este objeto se le pasa la clase, o el nombre completo de la clase, es decir, paquete.otropaquete.NombreClase, o cualquier otro nombre con el que se defina la categoría de esta traza.

Una categoría suele ser el nombre completo de la clase, ya que normalmente, las aplicaciones se dividen en diversos paquetes. También, si un componente utiliza más de un paquete es común definir la categoría con el nombre del componente, para tratar de la misma forma las trazas escritas en los dos paquetes.

Se puede jerarquizar las categorías, separando los niveles con "."(Puntos). Por tanto si se define la categoría con el nombre componente.primario, primario es una categoría hija de componente. Como veremos mas adelante, las configuraciones que se asocien a componente serán heredadas por primario. Estas configuraciones se realizan en el archivo de configuración.

Archivo de configuración

Log4j se puede configurar desde un archivo XML o desde un archivo de propiedades. Empecemos por la mas antigua y sencilla, el archivo de propiedades.

Para configurar Log4j de esta forma es necesario que el archivo log4j.properties este en el CLASSPATH de nuestra aplicación. Esto quiere decir que tiene que estar en la raíz de nuestro código, o dentro de algún archivo JAR que nuestra aplicación cargue, o al lanzar el programa, fijando la propiedad del sistema con el argumento

java Clase -Dlog4j.configuration=log4j.properties

Este archivo comienza con la configuración del nivel principal de la jerarquía, el ROOT. Bajo este nivel se encuentran todas las categorías de nuestra aplicación. Para configurar el nivel ROOT hay que escribir en el fichero de propiedades la propiedad log4j.rootLogger e igualarla al nivel de prioridad que por defecto se desea fijar. Tras el nivel de prioridad, separados entre comas, los diferentes appenders a los que por defecto se desean redireccionar nuestras trazas. (Aprenders??? la explicación un poco más abajo, paciencia 😉

log4j.rootLogger=DEBUG, Consola, Fichero

En el ejemplo fijamos el nivel por defecto a DEBUG (muy típico cuando estamos desarrollando el código) y redireccionamos a los appenders Consola y Fichero.

Ya tenemos todo nuestro código fijado con un nivel de trazas DEBUG. En muchos casos, no nos interesa ver todas las trazas de una aplicación, por ejemplo, cuando se utiliza un componente cuyo funcionamiento ya ha sido probado. Para subir el nivel de traza a INFO o WARN en dicho componente escribimos la siguiente propiedad en el fichero de configuración.

log4j.Logger.NombreCategoria=INFO

O si se utiliza como nombre de categoría la ruta completa a las clases

log4j.Logger.com.empresa.componente=INFO

Cuando se realiza esta operación, decimos que la categoría tiene un nivel de traza fijado de forma explicita. Esto hace que el paquete "com.empresa.componente" tenga el nivel de traza fijado a INFO, o lo que es lo mismo, no se escribirá ninguna traza de nivel DEBUG dentro de ese paquete. Si el componente tiene subpaquetes, y estos no tienen un nivel de traza fijado de forma explicita, heredan el nivel de traza del paquete que los contiene.

Visto al revés, si un paquete no tiene asignado de forma explicita un nivel de prioridad de traza, el paquete obtiene el nivel del paquete en el que esta contenido. Así de forma recursiva, hasta que se encuentre con un paquete con nivel de traza asignado de forma explicita o con el nivel principal de la jerarquía, con ROOT.

A continuación 3 ejemplos que visualizan el comportamiento de herencia anteriormente descrito. (Fijaros en la última columna)

Nivel Jerarquía Clases CATEGORIA

Nivel de traza asignado de forma explicita

Nivel de traza asignado

root DEBUG DEBUG
X ninguno DEBUG
X.Y ninguno DEBUG
X.Y.Z ninguno DEBUG

Nivel Jerarquía Clases CATEGORIA

Nivel de traza asignado de forma explicita

Nivel de traza asignado

root DEBUG DEBUG
X WARN WARN
X.Y INFO INFO
X.Y.Z DEBUG DEBUG

Nivel Jerarquía Clases CATEGORIA

Nivel de traza asignado de forma explicita

Nivel de traza asignado

root DEBUG DEBUG
X ninguno DEBUG
X.Y ninguno DEBUG
X.Y.Z INFO INFO

Appenders

Una vez establecido el nivel de trazas de nuestro código hay que configurar donde queremos que nuestras trazas sean escritas o direccionadas. Las opciones más utilizadas son a la consola y los archivos de texto, pero Log4j también puede escribir las trazas en base de datos, en una cola de mensajes JMS o en el visor de sucesos de Microsoft Windows.

Veamos como se configurarían los appenders:

Lo primero de todo es definir los nombre de los appenders que se van a utilizar en la propiedad log4j.rootLogger. Recordad que en esta propiedad se fijaba el nivel de traza por defecto y seguido y separados por coma, el nombre de los appenders que se van a usar. Al fijar estos appenders en la categoría principal, todas las trazas de la aplicación serán direccionadas a ellos

log4j.rootLogger=DEBUG, Consola, Fichero

Si se quiere que alguna categoría en concreto sea direccionada a otro appender, definiremos para esa categoría su appender

log4j.Logger.categoriaComponente=INFO, FicheroComponente

Si se realiza este tipo de configuración hay que tener en cuenta que los appenders por defecto son heredados. Log4j utiliza para hablar de esta propiedad el termino "additivity" de appenders.

Para el ejemplo anterior, las trazas escritas para la categoría categoriaComponente, serán direccionadas al appender FicheroComponente, Fichero y Consola, ya que Fichero y Consola son heredados por defecto desde la categoría ROOT.

Si no se desea heredar los appenders, hay que definir la siguiente propiedad en el fichero de configuración:

log4j.logger.append.categoriaComponente=false

Solo queda configurar cada uno de ellos.

Configurar el ConsoleAppender

Para configurar el aprender Consola, lo primero que hay que decirle es el tipo de aprender que es, en este caso de consola, por lo que hay que escribir la siguiente propiedad

log4j.appender.Consola=org.apache.log4j.ConsoleAppender

Lo siguiente será configurar el nivel de traza, ya que cada aprender puede tener uno distinto. Por ejemplo, es bastante común poner la salida a fichero con nivel DEBUG y la salida de consola con nivel INFO.

log4j.appender.Consola.Threshold=INFO

Para acabar con la configuración de la salida, asignamos el appender a un stream. Ya que lo que se busca es escribir en consola, se fija la salida a System.out.

log4j.appender.Consola.Target=System.out

La configuración de un appender para fichero sería muy parecida. Primero se le dice al appender que es de tipo fichero. Existen varios tipos de appender a fichero, los más comunes son RollingFileAppender y DailyRollingFileAppender

 

  • El primero escribe las trazas en un fichero de tamaño máximo configurable. Cuando se llega a ese tamaño, el fichero se renombra a nombreFichero.ext.1, y se continúan escribiendo las trazas en un nuevo fichero nombreFichero.ext.

    Cuando este llegue a su tamaño máximo se renombrara a nombreFichero.ext.1 y el que era nombreFichero.ext.1 pasa a ser nombreFichero.ext.2. Así continuamente, van "rotando" los ficheros, de hay su nombre de RollingFileAppender. En caso de que se llegue al número máximo de ficheros, se borrara el fichero más antiguo.

  • El segundo escribe las trazas en un fichero diario, al acabar el día, Log4j crea un nuevo fichero

 

Configurar un RollingFileAppender

Como siempre le decimos al appender de que tipo es

log4j.appender.Fichero= org.apache.log4j.RollingFileAppender

Le decimos la ruta donde se va a crear el fichero, tomando como raíz el lugar donde se encuentre el fichero. También se puede utilizar una ruta completa (c://log/trazas.log o en UNIX /usr/log/trazas.log)

log4j.appender.Fichero.File=./log/Trazas.log

* Me llevo bastante mal con esta propiedad, muchas veces me veo obligado a escribir la ruta completa para que las trazas se escriban en el fichero.

Por ultimo configuramos el tamaño máximo del fichero, y el número máximo de ficheros que van a rotar.

log4j.appender.Fichero.MaxFileSize=500KB

log4j.appender.Fichero.MaxBackupIndex=10

Con esta configuración tendremos 5 megas de trazas.

Otros Appenders

Con los ejemplos anteriores se muestra la facilidad para configurar los appenders. Log4j tiene multiples appenders a los cuales redireccionar las trazas, ejemplo de configuración básicos serian los siguentes:

JDBCAppender

#Como siempre tipo de appender
log4j.appender.appenderBD=org.apache.log4j.jdbc.JDBCAppender
#url a la base de datos, en este caso ejemplo para mysql
log4j.appender.appenderBD.URL=jdbc:mysql://javahispano/Log4j
#usuario y password de la base de datos
log4j.appender.appenderBD.user=java
log4j.appender.appenderBD.password=hispano
#isntrucción SQL a la que se va a llamar
log4j.appender.appenderBD.sql=INSERT INTO Tabla (fecha,mensaje)
VALUES ('%d','%c - %p - %m')

SMTPAppender

log4j.appender.appenderCorreo.To      =drafts@javahispano.org
log4j.appender.appenderCorreo.From    =lasterra@javahispano.org
log4j.appender.appenderCorreo.Subject =Error Enviado desde Log4j
#Si el servidor requiere autentificación no funcionara :-(
log4j.appender.appenderCorreo.SMTPHost=smtp.javahispano.org 
//or ip-Adress log4j.appender.appenderCorreo.BufferSize=1

Layouts

Este es el último de los elementos configurables, la forma y la información que se escribe en cada traza. A cada appender se le puede añadir un layout. El más común es el PatternLayout, en el cual se configuran una serie de variables, es decir, el patrón, que se cambiaran en el momento de escribir en el appender. Mas claro con un ejemplo

log4j.appender.Consola.layout =PatternLayout

log4j.appender.Consola.layout.ConversionPattern= %d [%p,%c] %m %n

Con ese patrón se visualizaría

Hora [Prioridad de la traza, categoria] El mensaje de la traza
Salto de línea

Un ejemplo

11:55:48,755 [DEBUG,org.javahispano.articulo]
Mensaje de nivel DEBUG

Otras opciones que admite el patrón son

 

  • %F: Nombre del fichero. (Operación muy costosa)
  • %l: Número de línea. (Operación muy costosa)
  • %d{ISO8601}: Fecha en el estándar ISO 8601 (2003-01-12 17:26:30,234)
  • %d{HH:mm:ss,SSS}: Fecha con la misma sintaxis del SimpleDateFormat
  • %r: Milisegundos desde que comenzó el programa
  • %t: Hilo que llamo al Logger.

 

Configurando en XML

Todo lo anteriormente explicado para la configuración de Log4j con el archivo de propiedades log4j.propierties se puede aplicar a la configuración en xml del archivo log4j.xml

Como se ve a continuación, primero se configuran los diferentes appenders, posteriormente se van configurando aquellas categorías a las cuales se les desea efectuar un tratamiento especial, y por ultimo la categoría ROOT.

<log4j:configuration 
xmlns:log4j="http://jakarta.apache.org/log4j/"> <appender name="Fichero"
class="org.apache.log4j.FileAppender"> <param name="File" value="A1.log" /> <param name="Append" value="false" /> <layout class="org.apache.log4j.PatternLayout"> <param name="ConversionPattern"
value="%t %-5p %c{2} - %m%n"/> </layout> </appender> <appender name="Consola"
class="org.apache.log4j.ConsoleAppender"> <layout class="org.apache.log4j.PatternLayout"> <param name="ConversionPattern" value="%d %-5p [%t] %C{2} (%F:%L) - %m%n"/> </layout> </appender> <category name="nombreCategoria"> <priority value="debug" /> <appender-ref ref="Fichero" /> </category> <root> <priority value ="debug" /> <appender-ref ref="Consola" /> </root> </log4j:configuration>

Rendimiento

Log 4j se ha construido intentando lograr el mayor rendimiento posible. El peso de añadir una traza dentro del programa ralentiza su ejecución entre 5 y 50 nanosegundos cuando esta deshabilitada. Si esta habilitada depende del tipo de appender y del layout.

La mayor parte de este tiempo se gasta en construir el String del mensaje. Para evitar este tiempo Log4j tiene las operaciones Logger.isDebugEnabled() Logger.isInfoEnabled, etc.

Gracias a estas operaciones, y añadiendo una condición en el código, podemos ahorrar bastante tiempo a cambio de escribir la condición. Si la velocidad es un aspecto crítico para la aplicación hay que considerar la necesidad de introducir este recurso.

java.util.logging

El nuevo paquete introducido en la JDK1.4 es muy similar al anterior sistema descrito.

El código de las aplicaciones es muy similar, ya que también se utiliza en objeto Logger para escribir las trazas. La definición de los niveles es la siguiente

 

  • SEVERE (valor mas alto)
  • WARNING
  • INFO
  • CONFIG
  • FINE
  • FINER
  • FINEST (valor mas bajo)

 

En vez de appender, este sistema de logging habla de "handlers" (manejadores). La J2SE viene con 5 tipos de handlers:

 

  • Stream
  • Console
  • File
  • Socket
  • Memory

 

De entre todos estos, es el último el que no esta dentro de la distribución de Log4j

A cada handler, al igual que a los appenders de Log4j, se le puede asociar un formato. O bien la traza es un simple String con el mensaje, SimpleFormatter. O bien esta definida en XML, XMLFormatter. Un ejemplo de este último sería:

<record>
<date>2000-08-23 19:21:05</date>
<millis>967083665789</millis>
<sequence>1256</sequence>
<logger>kgh.test.fred</logger>
<level>INFO</level>
<class>kgh.test.XMLTest</class>
<method>writeLog</method>
<thread>10</thread>
<message>Hello world!</message>
</record>

El fichero de configuración viene incluido dentro del JRE.< Directorio _ JRE >/lib/logging.properties.

En el se configuran los handlers que se van a utilizar, asignando a la propiedad handlers los handlers separados por coma

handlers= java.util.logging.FileHandler,
java.util.logging.ConsoleHandler

La configuración de cada handler, primero el lugar donde se van a generar los Logs

java.util.logging.FileHandler.pattern =
%h/java%u.log

 

  • "/" El separador del sistema
  • "%t" El directorio temporal
  • "%h" el directorio del usuario (Mis documentos o /usr/home)
  • "%g" numero generado para distinguir la rotacion de ficheros
  • "%u" numero unico para resolver posibles conflictos

 

Tamaño maximo del fichero

java.util.logging.FileHandler.limit = 50000

Numero de archivos del ciclo de rotación

java.util.logging.FileHandler.count = 1

Formato de escritura

java.util.logging.FileHandler.formatter =
java.util.logging.XMLFormatter

Tambien se puede configurar un nivel de salida. Como ejemplo se muestra esta configuración en el ConsoleHandler

java.util.logging.ConsoleHandler.level = INFO

java.util.logging.ConsoleHandler.formatter = 
java.util.logging.SimpleFormatter

El nivel por defecto

.level=INFO

Se pueden definir diferentes niveles de salida para cada paquete, en java.util.logging no se puede hablar del concepto de categoría.

com.xyz.foo.level = SEVERE

Si en vez de modificar este archivo, queremos configrar nuestra aplicación con otro, al lanzar la aplicación le debemos decir donde se encuentra dicho archivo de la siguiente forma:

java -Djava.util.logging.config.file=rutaAMiarchivo

Jakarta-Commons-Logging (JCL)

En vista de que son varios los sistemas de trazas que actualmente se pueden elegir, bajo el proyecto commons de Jakarta, se ha creado un pequeño subproyecto gracias a el cual se puede intercambiar de un sistema de trazas a otro sin tener que cambiar ni una línea de código.

JCL provee de clases e interfaces que se encargan de llamar a las clases de los verdaderos sistemas de trazas. Por defecto, si las clases de log4j están en el CLASSPATH de la aplicación, serán a ellas a quien se direccione la llamada.

Si estas no son localizadas, y se esta trabajando con la JDK1.4, se realizan llamadas a las clases del paquete java.util.logging.

Y si no el propio JCL las direcciona todas las trazas a System.err.

Para usar JCL solo hay que hacer dos cosas

 

  • Añadir JCL al CLASSPATH de tu aplicación
  • Escribir en tu codigo las sentencias de JCL en vez de las de otro sistema de trazas

 

Por lo tanto, una vez JCL esta en nuestro CLASSPATH, debemos importar las clases que necesitamos

import org.apache.commons.logging.Log;
import org.apache.commons.logging.LogFactory;

Obtener el Log, conocido como Logger en Log4j y java.util.logging

Log log = LogFactory.getLog(this.getClass());

Escribir las trazas igual que en los sistemas anteriormente explicados

                    if (log.isDebugEnabled())
log.debug("mensaje");

Gracias a ese pequeño cambio, podemos usar Log4j, java.util.logging u otro sistema de trazas sin tener que cambiar el código.

Hacer uso de JCL es recomendable si:

  • Estas programando clases que utilizara otro programador
  • Utilizas diferentes sistemas de trazas según el proyecto en el que trabajas
  • Programas clases que se usaran en otros proyectos y/o entornos
  • No tienes muy claro que sistemas de trazas usar

Conclusión

Este artículo muestra los sistemas de trazas mas conocidos. Se puede extraer de la lectura que java.util.logging es una copia de Log4j, con algunas opciones menos pero con la garantía de que va incluido en la JDK.

Para mi no hay dudas, Log4j y JCL es la mejor combinación, pero el gusto y la confianza en los productos Open Source harán que cada uno elija la combinación que mas le guste.

En cualquier caso, cualquiera es mejor que utilizar System.out y me aventuro a decir que mejor que cualquier sistema propio que se haya podido crear.

Enrique Rodríguez Lasterra
http://www.javahispano.org/articles.article.action?id=71

Leave A Comment?