> One thing to try would be to simply obtain a Logger in the static block of your LogManager. That will force initialization to complete and Java ensures that a class is only > loaded once so there is no multi-threading issue. (Perhaps this is essentially what happens in your LogManager static block, which explains why the problem went away.)
Agreed, so normally you would only have a static field calling LoggerFactory.getLogger(..) while now I have a method that calls LoggerFactory.getLogger(..) which multiple threads can access at the same time. (Can the classloader perform static field initialization for different classes at the same time? Assuming not) Just one more thing I want to point out, just because its interesting - Everything works now, but I realized afterwards that I was calling ExecutorService#awaitTermination() on the ExecutorService I was using to start the threads. So by the time the test was finished - there will be only one thread. If I remove the ExecutorService#awaitTermination() call then I get the following error with only partial log output: 2015-06-23 09:24:07,154 FATAL Ignoring log event after log4j was shut down I consider this a JUnit "feature" though, it doesn't seem to wait for other threads once the main thread exists the test. Looking at a graceful Tomcat shutdown - Tomcat actually does wait for other threads to finish, so I wouldn't have any similar problems in my production environment. Just wanted to point that out because its interesting - using ExecutorService#awaitTermination going forward. Thanks Remko! Appreciated! On Mon, Jun 22, 2015 at 2:29 PM, Remko Popma <[email protected]> wrote: > Hmm, all highly confusing. > First, using an async appender (as opposed to async loggers) should not > make a difference to the original problem. > > The SLF4J error may be a hint to the underlying problem. I gather that > your test case involves creating multiple application threads that all > start to log at the same time, using your custom LogManager class. > > Common use of either log4j or slf4j is to initialize a private static > final field with a Logger obtained from the LogManager and use that Logger > for all logging done in that class. The first time such a class is loaded, > the logging subsystem is initialized. So I never have the problem of > multiple threads trying to initialize the logging subsystem at the same > time. That said, I believe log4j2's initialization is thread-safe. Less > sure about slf4j. > > One thing to try would be to simply obtain a Logger in the static block of > your LogManager. That will force initialization to complete and Java > ensures that a class is only loaded once so there is no multi-threading > issue. (Perhaps this is essentially what happens in your LogManager static > block, which explains why the problem went away.) > > Sent from my iPhone > > > On 2015/06/22, at 20:34, Serdyn du Toit <[email protected]> wrote: > > > > Thanks Remko! > > > >> How do you ensure your LogManager class is loaded before your app calls > > any other log4j code? > > My LogManager class separates my code from a direct dependency on log4j > > classes. So all interaction with log4j only happens in my LogManager > class. > > > > Still - you made me doubt that my System.getProperty(..) call might be > > working so I > > 1. ran my test passing in the system property as a VM argument > > 2. refactored my log4j2.xml to explicitly use an async appender > > (sorry, I haven't had a look at jstack yet) > > > > Initially I still had a few problems but then things started working. > Here > > is what I found - > > The async appender works. BUT SO DOES MY CURRENT CONFIGURATION. I NOW > > HAVE A MORE FINE-GRAINED IDEA ABOUT WHAT THE PROBLEM IS: > > > > If I start my test with a synchronous LogManager.trace(..) statement (in > > other words before kicking of a multitude of asynchronous threads) > > everything works!!! If I however only start logging from within the > > asynchronous threads then I get the following console output and logging > is > > incomplete: > > SLF4J: The following loggers will not work because they were created > > SLF4J: during the default configuration phase of the underlying logging > > system. > > SLF4J: See also http://www.slf4j.org/codes.html#substituteLogger > > SLF4J: com.cq.core.util.extension.date.test.DateUtil_ConcurrentTest$1 > > SLF4J: com.cq.core.util.extension.date.test.DateUtil_ConcurrentTest$1 > > SLF4J: com.cq.core.util.extension.date.test.DateUtil_ConcurrentTest$1 > > SLF4J: com.cq.core.util.extension.date.test.DateUtil_ConcurrentTest$1 > > SLF4J: com.cq.core.util.extension.date.test.DateUtil_ConcurrentTest$1 > > SLF4J: com.cq.core.util.extension.date.test.DateUtil_ConcurrentTest$1 > > SLF4J: com.cq.core.util.extension.date.test.DateUtil_ConcurrentTest$1 > > 13:18:33.654 [pool-1-thread-5] DEBUG > > com.cq.core.util.extension.date.test.DateUtil_ConcurrentTest$1 - > Executing > > async command: > > com.cq.core.util.extension.date.test.DateUtil_ConcurrentTest$1 > > 13:18:33.655 [pool-1-thread-5] TRACE > > com.cq.core.util.extension.date.test.DateUtil_ConcurrentTest - logging > with > > log4j1996961461 > > 13:18:33.657 [main] TRACE > > com.cq.core.util.extension.date.test.DateUtil_ConcurrentTest - ALL DONE > > > > Initially I thought - meh, the logging system isn't initialized properly > > and a few logging statements get lost in those few milliseconds. But its > > more severe than that, because above you see one statement of the form: > > 13:18:33.655 [pool-1-thread-5] TRACE > > com.cq.core.util.extension.date.test.DateUtil_ConcurrentTest - logging > with > > log4j1996961461 > > > > But I should be seeing a 100! So its not just logging statements getting > > dropped, but its as if the logger then fails all the time going > forward... > > > > As said - if I start my test with a synchronous LogManager.trace(..) > > statement this error doesn't appear and I see everything I need to. So > I'm > > thinking that Log4j initializes differently if I first start using it in > a > > synchronous way...? Or it doesn't like a burst of asynchronous attempts > > initially...? > > > > Instead of starting every test with a synchronous LogManager.trace(..) > > statement I've added the following static block to my LogManager class: > > static { > > // this is a hack > > debug(LogManager.class, "Logging system initialization"); > > } > > > > And now everything works :) > > > > Your thoughts? But cool, everything works now - but I'm still interested > > in any input you might have (because it is a bit of a hack, with zero > > understanding of what's happening on my part) > > > > > >> On Mon, Jun 22, 2015 at 1:30 AM, Remko Popma <[email protected]> > wrote: > >> > >> Async loggers will call flush() when the queue is empty. If you are not > >> seeing all expected output in the file I suspect that async loggers are > not > >> actually enabled. > >> > >> You can verify with jstack or break your program in a debugger. There > >> should be an "AsyncLogger..." thread. > >> > >> How do you ensure your LogManager class is loaded before your app calls > >> any other log4j code? > >> > >> Remko > >> > >> Sent from my iPhone > >> > >>> On 2015/06/22, at 6:54, Serdyn du Toit <[email protected]> wrote: > >>> > >>> Hi, > >>> > >>> How do I flush async loggers? > >>> > >>> I'm currently testing some code with multiple threads - when the test > is > >>> finished almost none of the log statements have been printed. This > also > >>> makes me worried about my production code's logging when the server > >>> gracefully shuts down (will it just not log as it the case in my test, > or > >>> will it actually flush...) > >>> > >>> The only clue I've found on how to do this is the following > stackoverflow > >>> thread: > >> > http://stackoverflow.com/questions/3060240/how-do-you-flush-a-buffered-log4j-fileappender > >>> > >>> But the solution just doesn't seem to work for me. > >>> > >>> I don't think its relevant to the question, but here is my log4j.xml > >>> > >>> <?xml version="1.0" encoding="UTF-8"?> > >>> <configuration status="WARN"> > >>> <appenders> > >>> <Console name="CONSOLE" target="SYSTEM_OUT"> > >>> <PatternLayout pattern="%d{HH:mm:ss.SSS} [%t] %-5level %logger{36} - > >>> %msg%n" /> > >>> </Console> > >>> <RollingRandomAccessFile name="FILE" fileName="logs/webapplog.log" > >>> > >>> filePattern="logs/$${date:yyyy-MM}/webapplog-%d{yyyy-MM-dd}-%i.log.gz"> > >>> <PatternLayout pattern="%d{HH:mm:ss.SSS} [%t] %-5level %logger{36} > - > >>> %msg%n" /> > >>> <Policies> > >>> <TimeBasedTriggeringPolicy /> > >>> </Policies> > >>> </RollingRandomAccessFile> > >>> </appenders> > >>> <loggers> > >>> > >>> ...snip... > >>> > >>> <root level="WARN"> > >>> <appender-ref ref="CONSOLE" /> > >>> <appender-ref ref="FILE" /> > >>> </root> > >>> </loggers> > >>> </configuration> > >>> > >>> And then I have a LogManager class encapsulating all my logging code > that > >>> enables async logging: > >>> > >>> public class LogManager { > >>> > >>> // Enable Log4j2 async logging > >>> static { > >>> System.setProperty("Log4jContextSelector", > >>> "org.apache.logging.log4j.core.async.AsyncLoggerContextSelector"); > >>> } > >>> > >>> ...etc... > >>> } > >>> > >>> Any help appreciated!!! > >> > >> --------------------------------------------------------------------- > >> To unsubscribe, e-mail: [email protected] > >> For additional commands, e-mail: [email protected] > >> > >> > > --------------------------------------------------------------------- > To unsubscribe, e-mail: [email protected] > For additional commands, e-mail: [email protected] > >
