[
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-unsubscr...@logging.apache.org
For additional commands, e-mail: log4j-dev-h...@logging.apache.org
