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] > >
