logging-log4j-user mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Remko Popma <remko.po...@gmail.com>
Subject Re: flushing async loggers
Date Mon, 22 Jun 2015 12:29:25 GMT
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 <dutoitns@gmail.com> 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 <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
>> 
>> 

---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-user-help@logging.apache.org


Mime
View raw message