Mailing-List: contact log4j-user-help@logging.apache.org; run by ezmlm
Precedence: bulk
Reply-To: "Log4J Users List" <log4j-user@logging.apache.org>
Received-SPF: pass (nike.apache.org: domain of dutoitns@gmail.com designates
 209.85.220.171 as permitted sender)
MIME-Version: 1.0
In-Reply-To: <EC824549-FE84-48E1-9F63-51DC92A12192@gmail.com>
References: 
 <CAN25sNJD_ycc5o7ZXcvhVB2b7vHS_aVhJZJ7jStFTiuWvBniSQ@mail.gmail.com>
	<EC824549-FE84-48E1-9F63-51DC92A12192@gmail.com>
Date: Mon, 22 Jun 2015 13:34:49 +0200
Message-ID: 
 <CAN25sNLHSd36AvijKhCMbh7UMyKvCqv7Q6znWE+PV0vkLCDYwg@mail.gmail.com>
Subject: Re: flushing async loggers
From: Serdyn du Toit <dutoitns@gmail.com>
To: Log4J Users List <log4j-user@logging.apache.org>
Content-Type: multipart/alternative; boundary=001a113562ce566c02051919a9bc

--001a113562ce566c02051919a9bc
Content-Type: text/plain; charset=UTF-8

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 <remko.popma@gmail.com> 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 <dutoitns@gmail.com> 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: log4j-user-unsubscribe@logging.apache.org
> For additional commands, e-mail: log4j-user-help@logging.apache.org
>
>

--001a113562ce566c02051919a9bc--