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 <[email protected]>
> 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:[email protected]]
> Gesendet: Freitag, 28. August 2009 13:58
> An: [email protected]
> 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: [email protected]
> For additional commands, e-mail: [email protected]
>
>
