logging-log4j-user mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Markus Michel <markus.mic...@uni-duesseldorf.de>
Subject Re: Events appear incorrect inside the wrong file
Date Mon, 31 Aug 2009 12:55:12 GMT
Hi!

Some minutes ago I solved the problem by myself:

It seems like log4j is NOT completely thread-save. After synchronizing all
log / trace methods using a separate object (synchronized(synObject) {....}
) everything is working fine. Maybe the lib is writing the messages to a
shared thread-unsafe buffer which is used by all logger instances before
writing them to file?!? (That would explain why sometimes log messages
appear inside the trace file)

2009/8/31 Bender Heri <hbender@ergonomics.ch>

> Maybe the PatternLayout is not threadsafe? Try to instantiate separate
> instances of PatternLayout for each Logger, or synchronize on the sole
> instance of PatternLayout.
> Heri
> PS: It is not quite clear who calls your log method the log-Event, and how
> looks the other log method which writes to the traceLogger?
>

The methods are called by several threads which have access to the
loggingHandler class. Inside the handler there are seperated methods for
logging (-> logLogger) and tracing (-> traceLogger) a message

BTW: Why don't you do the configuring through config file? There is nothing
> special in your configuration which cannot be done by config file!
>
> I think that I don't need a separate config file, because setup is very
simple.

BR,

Markus


>
> -----Urspr√ľngliche Nachricht-----
> Von: Markus Michel [mailto:nemocadneza@googlemail.com]
> Gesendet: Freitag, 28. August 2009 13:58
> An: log4j-user@logging.apache.org
> Betreff: Events appear incorrect inside the wrong file
>
> Hi there!
>
> To be able to log and trace some events I've added a LoggingHandler class
> to my java project. Inside this class I'm using two different log4j logger
> instances - one for logging an event and one for tracing an event into
> different files. The initialization block of the class looks like this:
>
>    public void initialize()
>    {
>        System.out.print("starting logging server ...");
>
>        // create logger instances
>        logLogger = Logger.getLogger("log");
>        traceLogger = Logger.getLogger("trace");
>
>        // create pattern layout
>        String conversionPattern = "%c{2} %d{ABSOLUTE} %r %p %m%n";
>        try
>        {
>            patternLayout = new PatternLayout();
>            patternLayout.setConversionPattern(conversionPattern);
>        }
>        catch (Exception e)
>        {
>            System.out.println("error: could not create logger layout
> pattern");
>            System.out.println(e);
>            System.exit(1);
>        }
>
>        // add pattern to file appender
>        try
>        {
>            logFileAppender = new FileAppender(patternLayout, logFilename,
> false);
>            traceFileAppender = new FileAppender(patternLayout,
> traceFilename, false);
>        }
>        catch (IOException e)
>        {
>            System.out.println("error: could not add logger layout pattern
> to corresponding appender");
>            System.out.println(e);
>            System.exit(1);
>        }
>
>        // add appenders to loggers
>        logLogger.addAppender(logFileAppender);
>        traceLogger.addAppender(traceFileAppender);
>
>        // set logger level
>        logLogger.setLevel(Level.INFO);
>        traceLogger.setLevel(Level.INFO);
>
>        // start logging server
>        loggingServer = new LoggingServer(logLogger, traceLogger,
> serverPort, this);
>        loggingServer.start();
>
>        System.out.println(" done");
>    }
>
> To make sure that only only thread is using the functionality of a logger
> instance at the same time each logging / tracing method calls the logging
> method .info() inside a synchronized-block. One example looks like this:
>
>        public void logMessage(String message)
>    {
>        synchronized (logFileAppender)
>        {
>            if (logLogger.isInfoEnabled() && logFileAppender != null)
>            {
>                logLogger.info(instanceName + ": " + message);
>            }
>        }
>    }
>
> If I look at the log files, I see that sometimes a event appears in the
> wrong file. One example:
>
>    trace 10:41:30,773 11080 INFO masterControl(192.168.2.21): string
> broadcast message was  pushed from 1267093 to vehicle 1055293 (slaveControl
> 1)
>    trace 10:41:30,784 11091 INFO masterControl(192.168.2.21): string
> broadcast message was pushed from 1156513 to vehicle 1105792 (slaveControl
> 1)
>    trace 10:41:30,796 11103 INFO masterControl(192.168.2.21): string
> broadcast message was pushed from 1104306 to vehicle 1055293 (slaveControl
> 1)
>    trace 10:41:30,808 11115 INFO masterControl(192.168.2.21): vehicle
> 1327879 was pushed to slave control 1
>    10:41:30,808 11115 INFO masterControl(192.168.2.21): string broadcast
> message was pushed from 1101572 to vehicle 106741 (slaveControl 1)
>    trace 10:41:30,820 11127 INFO masterControl(192.168.2.21): string
> broadcast message was pushed from 1055293 to vehicle 1104306 (slaveControl
> 1)
>
> I think that the problem occures everytime two event happen at the same
> time
> (here: 10:41:30,808). Does anybody has an idea how to solve my problem? I
> already tried to add a sleep() after the method call, but that doesn't
> helped ...
>
> BR,
>
> Markus
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
> For additional commands, e-mail: log4j-user-help@logging.apache.org
>
>

Mime
  • Unnamed multipart/alternative (inline, None, 0 bytes)
View raw message