logging-log4j-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Bart S. (JIRA)" <j...@apache.org>
Subject [jira] [Comment Edited] (LOG4J2-1094) Multi thread initialization problem
Date Thu, 13 Aug 2015 18:16:46 GMT

    [ https://issues.apache.org/jira/browse/LOG4J2-1094?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14695710#comment-14695710
] 

Bart S. edited comment on LOG4J2-1094 at 8/13/15 6:16 PM:
----------------------------------------------------------

What he's saying (that was my line, from the email) is that the first call to any logger for
output is met with an as yet uninitialized logger environment.

The first thread to issue a getLogger() and subsequent logging call sees the environment as
it is before the XML file has finished loading. That is to say, any logging output goes to
the ROOT logger with the DEFAULT pattern with an error level of ERROR, that is to say the
log level is still set to ERROR as it is by default.

Injecting a few additional print statements of those logger variables would show that:

{quote}
write thread-1 to thread-1:ERROR in 1829164700
09:05:46.200 [Thread-0] ERROR thread-1 - message
done thread-1
write thread-2 to thread-2:ALL in 1829164700
[TEST] [ERROR] thread-2 - message
done thread-2
{quote}

Here the first line is a System.out.println, showing the contents of the Logger instance.
The second line shows the output of the first logger -- this is matched by an uninitialized
system. The second [TEST] message is actually the message as shown from the user's loaded
XML config. It uses a different format (PatternLayout pattern). So what we have here is that:

apparently there is a lazy loading of some sort that doesn't block the first logger output
call, but merely serves it using the uninitialized system, as if a reconfiguration is in place
and it just keeps serving logger requests regardless. Not blocking the call.


was (Author: xennex82):
What he's saying (that was my line, from the email) is that the first call to any logger for
output is met with an as yet uninitialized logger environment.

The first thread to issue a getLogger() and subsequent logging call sees the environment as
it is before the XML file has finished loading. That is to say, any logging out put goes to
the ROOT logger with the DEFAULT pattern with an error level of ERROR, that is to say the
log level is still set to ERROR as it is by default.

Injecting a few additional print statements of those logger variables would show that:

{{quote}}
write thread-1 to thread-1:ERROR in 1829164700
09:05:46.200 [Thread-0] ERROR thread-1 - message
done thread-1
write thread-2 to thread-2:ALL in 1829164700
[TEST] [ERROR] thread-2 - message
done thread-2
{{quote}}

Here the first line is a System.out.println, showing the contents of the Logger instance.
The second line shows the output of the first logger -- this is matched by an uninitialized
system. The second [TEST] message is actually the message as shown from the user's loaded
XML config. It uses a different format (PatternLayout pattern). So what we have here is that:

apparently there is a lazy loading of some sort that doesn't block the first logger output
call, but merely serves it using the uninitialized system, as if a reconfiguration is in place
and it just keeps serving logger requests regardless. Not blocking the call.

> Multi thread initialization problem
> -----------------------------------
>
>                 Key: LOG4J2-1094
>                 URL: https://issues.apache.org/jira/browse/LOG4J2-1094
>             Project: Log4j 2
>          Issue Type: Bug
>    Affects Versions: 2.3
>            Reporter: Luca Burgazzoli
>
> I wrote a very simple example which has a behaviour I do not expect:
> If I call LogManager.getLogger(..) from two threads, only one of the loggers logs what
I'd expect but if I add an additional call to LogManager.getLogger(..) before the threads
are started, I see what I'd expect so it looks like there is a problem in multi threaded initialization.
> You can fine the code and the configuration here:
> - https://github.com/lburgazzoli/lb-chronicle/blob/master/chronicle-examples/chronicle-logger-log4j2/src/main/java/com.github.lburgazzoli.openhft.examples.chronicle.logger.log4j2/MtLogging.java
> - https://github.com/lburgazzoli/lb-chronicle/blob/master/chronicle-examples/chronicle-logger-log4j2/src/main/resources/log4j2.xml
> The code above will show:
> {noformat}
>     write thread-1
>     done thread-1 
>     write thread-2
>     [TEST] [INFO ] thread-2 - message
>     done thread-2
> {noformat}
> Any call to LogManager makes it succeed:
> {code}
>     LogManager.getContext(false);
>     th1.start();
>     th2.start();
>     th1.join();
>     th2.join();
> {code}
> New output:
> {noformat}
>     write thread-2
>     write thread-1
>     [TEST] [INFO ] thread-2 - message
>    done thread-2
>    [TEST] [INFO ] thread-1 - message
>    done thread-1
> {noformat}
> The funny thing is that the first thread to arrive is initialized with ERROR level instead
of the ALL that is given to root. In other words it seems that the config has not loaded



--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

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


Mime
View raw message