====== Log4j is not process safe ======

Con frecuencia se comenta que [[http://logging.apache.org/log4j/1.2/faq.html#a1.7|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 =====

  * Hemos hecho un programa java que escribe durante un minuto entradas en un fichero de log. Las entradas van numeradas consecutivamente: 0, 1, 2, 3,....
  * Hemos lanzado tres procesos en paralelo en un ordenador con windows, de forma que los tres escribian sobre el mismo fichero de log
  * El log ha quedado con este aspecto: 
<code>
third_proc 5
second_proc 16563
first_proc 32505
second_proc 16564
first_proc 32506
third_proc 6
second_proc 16565
first_proc 32507
</code>
  * Hemos pasado un programa awk para que busque entradas faltantes. 
  * Y las ha encontrado

¿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. 

  - Mantener un fichero de log por proceso java
  - 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**

<code 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 );
    }
    
}
</code>


**La configuracion de log4j**

<code>
# 
# 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
 
 

</code>


**Uno de los programas lanzadores (se usaron tres)**

<code bat>
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


</code>
**Programa verificador AWK**

<code 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
		}
		

</code>


~~DISQUS~~