Optimización de logs con Spring 3

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í:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27

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):

1
2
3
4
5
6
7
8
9
10

<?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:

1
2
3
4
5
6
7
8
9

<?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:

1
2
3
4
5

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:

1
2
3
4
5
6
7

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

4.2 Ahora, la implementación:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15

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):

1
2
3

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] - < ----- Log trace example --->
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

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20

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:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15

<?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:

1
2

2011-10-10 12:53:12,351 INFO [myLog] - < ----- Log trace example --->
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:

1

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

Ahora lo sustituimos por:

1

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:

1
2

2011-10-10 12:57:06,020 INFO [com.farmerdev.spring.logs.services.impl.SimpleServiceImpl] - < ----- Log trace example --->
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.