Optimización de logs con Spring 3

Otro tipo de log, por PhillipC, en Flickr (4631450250) con licencia CC by

Cualquier aplicación empresarial que vaya a ser desplegada en un entorno de producción necesita un sistema de logs que permita registrar los mensajes que la aplicación emite con el objetivo de saber qué hace nuestra aplicación, corregir fallos o detectar anomalías en sistemas críticos. Vamos a tratar en este artículo de configurar de forma eficiente un sistema de logs para Java con Spring 3.

El problema

¡¡Ponga un sistema de logs en su vida!! No lo dejes para mañana, tu aplicación necesita un buen sistema de logs que permita registrar lo que está sucediendo en tu sistema. Los mensajes que se suelen registrar pueden catalogarse en varios tipos en función de la criticidad de los mismos. Así pues podemos encontrar mensajes informativos (info), mensajes de advertencia (warn) o mensajes de error(error) entre otros muchos.

En el mundo Java, una de las librerías que más se utiliza para implementar logs es log4j (http://logging.apache.org/log4j/). En nuestro caso, vamos a utilizar como fachada del sistema el Jakarta Commons Logging para evitar acoplarnos a una implementación concreta en un futuro.

Hasta aquí no descubro nada nuevo. El problema puede venir cuando no configuramos de forma eficiente nuestro sistema pudiendo provocar ineficiencia y pérdidas de rendimiento. Vamos a ver un ejemplo bastante común de configuración de un sistema de logs.

El ejemplo utiliza Spring Framework en su versión 3.0, para configurar las clases necesarias.

Paso 1: Escribimos el test del servicio que queremos probar. Como es un ejemplo el test es sencillo quedando así:

package com.farmerdev.spring.logs;
 
import javax.inject.Inject;
 
import org.junit.Assert;
import org.junit.Test;
import org.junit.runner.RunWith;
import org.springframework.test.context.ContextConfiguration;
import org.springframework.test.context.junit4.SpringJUnit4ClassRunner;
 
import com.farmerdev.spring.logs.services.SimpleService;
 
@ContextConfiguration("classpath:spring/context-test.xml")
@RunWith(SpringJUnit4ClassRunner.class)
public class SimpleTradicionaLogTest {
	@Inject
	private SimpleService simpleService;
 
	@Test
	public void simpleTraditionalLogging(){
 
		simpleService.businessMethod();
 
		Assert.assertNotNull(simpleService);
	}
 
}

Paso 2: El fichero de configuración del test con spring es (context-test.xml):

<?xml version="1.0" encoding="UTF-8"?>
<beans xmlns="http://www.springframework.org/schema/beans"
	xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
	xmlns:context="http://www.springframework.org/schema/context"
	xmlns:p="http://www.springframework.org/schema/p"
	xsi:schemaLocation="http://www.springframework.org/schema/beans http://www.springframework.org/schema/beans/spring-beans.xsd
		http://www.springframework.org/schema/context http://www.springframework.org/schema/context/spring-context-3.0.xsd">
 
	<import resource="classpath:spring/context-root.xml"/>
</beans>

Este fichero a su vez importa el otro fichero global llamado context-root.xml:

<?xml version="1.0" encoding="UTF-8"?>
<beans xmlns="http://www.springframework.org/schema/beans"
	xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
	xmlns:context="http://www.springframework.org/schema/context"
	xsi:schemaLocation="http://www.springframework.org/schema/beans http://www.springframework.org/schema/beans/spring-beans.xsd
		http://www.springframework.org/schema/context http://www.springframework.org/schema/context/spring-context-3.0.xsd">
 
	<context:component-scan base-package="com.farmerdev.spring.logs"/>
</beans>

Con la etiquetaconseguimos que Spring incluya todos los beans que se encuentren anotados con @Service dentro de su contexto, es decir, los pueda gestionar su contenedor.

Paso 3: Necesitamos el fichero de configuración del log4j:

log4j.rootCategory=INFO, stdout
 
log4j.appender.stdout=org.apache.log4j.ConsoleAppender
log4j.appender.stdout.layout=org.apache.log4j.PatternLayout
log4j.appender.stdout.layout.ConversionPattern=%d %p [%c] - %n

Paso 4: Nos disponemos a escribir el código del servicio que estamos implementando:

4.1 Primero, la interfaz:

package com.farmerdev.spring.logs.services;
 
public interface SimpleService {
 
	void businessMethod();
 
}

4.2 Ahora, la implementación:

package com.farmerdev.spring.logs.services;
 
import org.apache.commons.logging.Log;
import org.apache.commons.logging.LogFactory;
import org.springframework.stereotype.Service;
 
@Service
public class SimpleServiceImpl implements SimpleService {
	private static final Log logger = LogFactory.getLog(SimpleServiceImpl.class);
	public void businessMethod() {
		logger.info(" ----- Log trace example ---");
 
	}
 
}

Podemos observar que la clase de log (Log) pertenece realmente a la librería Jakarta Commons Logging que utilizamos para evitar acoplar nuestro código a una implementación concreta. Será Commons Logging el que utilizará Log4J finalmente.

Si ejecutamos la aplicación en nuestro editor favorito obtendremos las siguientes trazas (se han omitido algunas para simplificar el resultado):

2011-10-10 12:38:39,736 INFO [org.springframework.beans.factory.support.DefaultListableBeanFactory] - 
2011-10-10 12:38:39,753 INFO [com.farmerdev.spring.logs.services.SimpleServiceImpl] - &lt; ----- Log trace example ---&gt;
2011-10-10 12:38:39,758 INFO [org.springframework.context.support.GenericApplicationContext] -

El problema de esta configuración es que estamos creando una instancia de Log para cada una de las clases de la aplicación. Al ser una propiedad static solo tendremos una instancia por clase pero, si nuestra aplicación está compuesta por N clases, nos encontraremos con N instancias Log asociadas. Esto puede repercutir en un mayor consumo de memoria al tener muchas instancias Log. Además nos encontramos con código duplicado para obtener la instancia del log en todas nuestras clases.

¿Cómo podemos mejorar nuestro sistema de logs?

Logs con Spring

Pues aprovechamos que usamos Spring para realizar una serie de cambios en nuestras clases:

Paso 1: Modificación del servicio

package com.farmerdev.spring.logs.services.impl;
 
import javax.inject.Inject;
 
import org.apache.commons.logging.Log;
import org.apache.commons.logging.LogFactory;
import org.springframework.stereotype.Service;
 
import com.farmerdev.spring.logs.services.SimpleService;
 
@Service
public class SimpleServiceImpl implements SimpleService {
	@Inject
	private  Log logger;
	public void businessMethod() {
		logger.info(" ----- Log trace example ---");
 
	}
 
}

Como podemos observar, estamos utilizando toda la potencia de Spring 3 y su anotación @Inject para realizar la inyección de dependencias de la clase de Log. Delegamos por tanto, toda la gestión y creación de la clase de log a Spring.

Paso 2: Debemos añadir la configuración del logger en Spring:

<?xml version="1.0" encoding="UTF-8"?>
<beans xmlns="http://www.springframework.org/schema/beans"
	xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
	xmlns:context="http://www.springframework.org/schema/context"
	xmlns:p="http://www.springframework.org/schema/p"
	xsi:schemaLocation="http://www.springframework.org/schema/beans http://www.springframework.org/schema/beans/spring-beans.xsd
		http://www.springframework.org/schema/context http://www.springframework.org/schema/context/spring-context-3.0.xsd">
 
	<context:component-scan base-package="com.farmerdev.spring.logs"/>
 
 
	<bean id="mylog" class="org.springframework.beans.factory.config.CommonsLogFactoryBean"
		p:logName="myLog"/>
 
</beans>

La traza que obtenemos es la siguiente:

2011-10-10 12:53:12,351 INFO [myLog] - &lt; ----- Log trace example ---&gt;
2011-10-10 12:53:12,351 INFO [myLog] -

Hemos conseguido que aparezcan nuestras trazas pero podemos observar que no aparecen el nombre de las clases donde se han producido esas trazas. Lo único que aparece es myLog que es el nombre con que anteriormente configuramos el log en Spring.

Lo único que debemos cambiar para solucionar este problema es el fichero de configuración de log4j (log4j.properties). Donde antes aparecía:

log4j.appender.stdout.layout.ConversionPattern=%d %p [%c] - %n

Ahora lo sustituimos por:

log4j.appender.stdout.layout.ConversionPattern=%d %p [%C] - %n

Vemos que el cambio consiste en cambiar c por C. Tan sencillo como esto, así conseguiremos que lo que aparezca sea el nombre donde se genera la traza. Algo como esto:

2011-10-10 12:57:06,020 INFO [com.farmerdev.spring.logs.services.impl.SimpleServiceImpl] - &lt; ----- Log trace example ---&gt;
2011-10-10 12:57:06,023 INFO [com.farmerdev.spring.logs.services.impl.JustAnotherServiceImpl] -

Conclusiones

Con este sencillo cambio hemos conseguimos tener una sola instancia de nuestros logs para toda la aplicación ya que cualquier clase definida en Spring, por defecto, es Singleton (solo una instancia por JVM). Además, conseguimos que solo haya que configurar estos logs en un solo punto ya que el resto de clases solo tendrán que incluir la Inyección con @Inject.
Nota: Para los que utilicéis versiones anteriores a la 3.0 podemos conseguir el mismo efecto con @Autowired.

Acerca de Israel Alcazar

Responsable del departamento de Formación en atSistemas y miembro de la oficina técnica, compagina esta actividad con la de Scrum Master y Coach técnico en varios equipos donde también participa en labores de arquitectura y soporte al desarrollo. La mejora continua es una de sus obsesiones por ello se encuentra en búsqueda continua de nuevas formas de trabajar. Firme defensor de los principios ágiles cuenta con Java como su lenguaje principal aunque Ruby y Groovy están empezando a tener cabida en su vida. Dedica gran parte de su tiempo a compartir su conocimiento en cursos y charlas técnicas en diferentes grupos y conferencias. http://twitter.com/ialcazar
  

Comentarios (3)

  1. Angel Ruiz 27/10/2011 a las 02:10

    FYI: creo que el artículo se te ha quedado muy cojo, ya que lo mejor que puedes hacer para optimizar los logs te lo dicen en el manual de referencia de Spring y consiste precisamente en no usar commons-logging: http://static.springsource.org/spring/docs/3.1.0.RC1/spring-framework-reference/html/overview.html#d0e772

    Cheers,
    Angel.

  2. Israel Alcazar 28/10/2011 a las 09:10

    Hola Angel, gracias por tu comentario. No conocía este problema que comentas. De todas formas, mi artículo lo que intenta explicar es que no es necesario tener una instancia de cada Logger en cada clase Java sino que podemos configurarlo para que esta se inyecte automáticamente.

    Aun así, me apunto la referencia que comentas.

    Un saludo,

    Israel

  3. Juan Paleo 07/11/2011 a las 12:11

    Una pregunta para Angel Ruiz:

    ¿Podrías indicarnos como configurar los logs como lo hace Israel Alcazar en este artículo pero utilizando SLF4J?, es decir, que se puedan injectar automáticamente mediante @Inject o @Autowired. En la entrada de springsource no lo veo.

    Gracias a ambos por la información.

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>