Table of Contents

Log4j is not process safe

Con frecuencia se comenta que log4j is thread-safe: de hecho ellos mismos lo dicen.

Lo que nunca se ha afirmado, y no tiene porqué ser cierto, es que log4j sea process safe.

De hecho, no lo es. En ocasiones de fuerte carga se pueden perder entradas de log.

Process safety

Process safety significa que varios procesos de la máquina ejecutandose en paralelo no producirán una inconsistencia de datos. En el caso que nos ocupa, significaría que no se perderían entradas de log a consecuencia de usar log4j en procesos diferentes en la misma máquina escribiendo sobre el mismo fichero. O procesos diferentes en diferentes máquinas escribiendo sobre el mismo fichero (a través de carpetas compartidas o NTFS).

La prueba

third_proc 5
second_proc 16563
first_proc 32505
second_proc 16564
first_proc 32506
third_proc 6
second_proc 16565
first_proc 32507

¿Cuantas? Pues de un fichero de 5.909.368 líneas, 2.351.269 se habían esfumado. Un 39,78% de las entradas. Una segunda ejecución devolvió 5.018.301 líneas y 2.032.111 lineas con error. Un 40%.

Hay que disculpar al muchacho

Si mirais el código fuente, comprobareis que la situación es altamente estresante: se escribían miles de líneas de log por segundo, lo cual es dificil que ocurra en un escenario real, por mucha carga que tenga.

No obstante, sugiero prevencion, especialmente en situaciones de carga fuerte.

  1. Mantener un fichero de log por proceso java
  2. Especialmente delicado es poner el fichero de log en una carpeta compartida (NFS o SAN), y que varias máquinas escriban en ese log: eso multiplicará las perdidas de log

And finnally, the source code

Finalmente el codigo fuente.

Mi fabuloso programa java 

public class App 
{
    private static Logger log = Logger.getLogger( App.class );
 
    /**
     * <p>
     * log4java is known to be thread safe. Ok.</p> 
     * <p>
     * But it's process safe???</p>
     * <p>
     * The purpose of this program is to demonstrate
     * that it is not (or yes) process safe</p>
     * 
     * @param args
     */
    public static void main( String[] args )
    {
    	String myName = System.getProperty("myname","noname");
 
    	long counter = 0; 
    	Date current = new Date();
    	Date end = new Date(current.getTime() + (120 * 1000));
 
    	while( current.getTime() < end.getTime() )
    	{
        	log.error( myName + " " + Long.toString(counter) );
 
        	counter++;
    		current = new Date();
    	} // 
 
    	System.out.println( "value of end:" + end );
 
    	System.exit( 0 );
    }
 
}

La configuracion de log4j 

# 
# log4j.properties - log for java example configuration file 
#
# 
 
 
# log levels
#
# if you put here that "any messages above info will  
# be displayed", what are we talking about???
#
# DEBUG < INFO < WARN < ERROR < FATAL
#
# we are talking that only DEBUG messages will be omitted
#
 
#
#
# LOGGERS
#
#
 
# root logger
# 
# the root logger is the father of all the loggers in log4j
# If you create a logger called "com.foo" and don't provide 
# any configuration, this logger will take the configuration 
# the root logger 
 
# specify that the root logger will be send messages 
# to the "console" appender and the "A1" appender
# Think of appenders as printers where log messages 
# will be printed
#
# See section "appenders" for the configuration of these 
# appenders
#
log4j.rootLogger = INFO, A1
 
 
# and configure the appender "my_own_appender" accordingly. 
# or just leave: 
#
# log4j.com.supermanhamuerto = WARN
#
# to avoid INFO messages from this class
 
#
#
# APPENDERS
#
#
 
# see at the end the list of available appenders
 

# A1 appender
#
# in this case, we will output he content to a file appender 
log4j.appender.A1 = org.apache.log4j.FileAppender
log4j.appender.A1.file = c\:/temp/log4jprocess.log
log4j.appender.A1.layout = org.apache.log4j.PatternLayout
log4j.appender.A1.ConversionPattern = %m%n

Uno de los programas lanzadores (se usaron tres) 

rem
rem log4jtester - 
rem 
 
 
 
set CLASSPATH=./;./log4jProcessSafe.jar;^
./lib/log4j-1.2.16.jar;^
./lib/commons-logging-1.1.1.jar
 
 
java -XX:MaxPermSize=256M -XX:+AggressiveHeap ^
-Dmyname=first_proc ^
com.tests.log4j.App

Programa verificador AWK 

#
# verifier.awk 
#
 
 
BEGIN   {
		IGNORECASE = 1; 
		first_proc = 0; 
		second_proc = 0; 
		third_proc = 0; 
		}
 
/.*/	{
		if( match( $0, "first_proc ([0-9]*)", num ) )
		{
			if( first_proc != num[1] )
			{
				print "first_proc Error!!!! the number ", first_proc, " not appeared"; 
				first_proc = num[1];
			} 
			first_proc++;
 
		} # first_proc
 
		if( match( $0, "second_proc ([0-9]*)", num ) )
		{
			if( second_proc != num[1] )
			{
				print "second_proc Error!!!! the number ", second_proc, " not appeared"; 
				second_proc = num[1];
			} 
			second_proc++;
		} # second_proc
		if( match( $0, "third_proc ([0-9]*)", num ) )
		{
			if( third_proc != num[1] )
			{
				print "third_proc Error!!!! the number ", third_proc, " not appeared"; 
				third_proc = num[1];
			} 
			third_proc++;
		} # third_proc
		}

~~DISQUS~~