[
https://issues.apache.org/jira/browse/LOG4J2-807?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14143065#comment-14143065
]
Remko Popma commented on LOG4J2-807:
------------------------------------
The problem is caused by a bug in AbstractConfiguration:
During reconfiguration, a new configuration is started with new appenders and
loggers. This increases the AsyncLoggerConfigHelper ref count to 2. (So far so
good.)
After that, the old configuration is stopped. This logic has a bug, resulting
in the root async logger being stopped twice. This brings down the ref count to
zero and the Disruptor is shut down. Subsequent logging will fail.
Apart from fixing this bug, I'll also improve the trace logging for async
loggers a little so that it is easier to see what is going on. The current log
does not show that it is the same logger that is stopped twice, because the
root logger name is the empty string. I'll output "root" instead in the trace
logs to aid future debugging.
Current:
{code}
2014-09-22 19:01:50,617 TRACE AsyncLoggerConfig[] stopping...
2014-09-22 19:01:50,617 TRACE AsyncLoggerConfigHelper: not shutting down
disruptor: ref count is 1.
2014-09-22 19:01:50,617 TRACE AsyncLoggerConfig[] stopping...
2014-09-22 19:01:50,617 TRACE AsyncLoggerConfigHelper: shutting down disruptor:
ref count is 0.
{code}
After:
{code}
2014-09-22 19:01:50,617 TRACE AsyncLoggerConfig[root] stopping...
2014-09-22 19:01:50,617 TRACE AsyncLoggerConfigHelper: not shutting down
disruptor: ref count is 1.
2014-09-22 19:01:50,617 TRACE AsyncLoggerConfig[root] stopping...
2014-09-22 19:01:50,617 TRACE AsyncLoggerConfigHelper: shutting down disruptor:
ref count is 0.
{code}
> Disruptor is null when configuration is reloaded (asyncRoot + monitorInterval)
> ------------------------------------------------------------------------------
>
> Key: LOG4J2-807
> URL: https://issues.apache.org/jira/browse/LOG4J2-807
> Project: Log4j 2
> Issue Type: Bug
> Affects Versions: 2.0.2
> Reporter: Florin Marinoiu
> Assignee: Remko Popma
> Fix For: 2.1
>
> Attachments: async-root-reload - trace.log,
> async-root-reload-test.zip, async-root-reload.log
>
>
> We have a XML configuration with <asyncRoot> and monitorInterval. When the
> configuration file is reloaded I have a NPE and log4j become unavailable:
> {code}
> 2014-08-29 10:39:59,079 ERROR Could not register mbeans
> java.lang.NullPointerException
> at
> org.apache.logging.log4j.core.async.AsyncLoggerConfigHelper.createRingBufferAdmin(AsyncLoggerConfigHelper.java:360)
> at
> org.apache.logging.log4j.core.async.AsyncLoggerConfig.createRingBufferAdmin(AsyncLoggerConfig.java:148)
> {code}
> Here is my config:
> {code}
> <?xml version="1.0" encoding="UTF-8"?>
> <Configuration name="asynRootConfig" monitorInterval="5" status="debug">
> <Appenders>
> <RandomAccessFile name="FILE_APPENDER" fileName="application.log"
> immediateFlush="false" append="true">
> <PatternLayout>
> <Pattern>%d %-5p [%c{1.}] %m%n</Pattern>
> </PatternLayout>
> </RandomAccessFile>
> </Appenders>
> <Loggers>
> <asyncRoot level="debug">
> <AppenderRef ref="FILE_APPENDER" />
> </asyncRoot>
> </Loggers>
> </Configuration>
> {code}
> And a code snippet to reproduce:
> {code}
> public class Log4jAsyncRootReloadTest {
> public static void main(String[] args) throws InterruptedException {
> final File config = new File("./log4j2.xml");
> System.setProperty("log4j.configurationFile", "file://" +
> config.getAbsolutePath().replaceAll("\\\\", "/"));
> Logger logger = LogManager.getLogger(Log4jAsyncRootReloadTest.class);
> logger.info("Log4j configured, will be reconfigured in aprox. 5 sec");
> config.setLastModified(System.currentTimeMillis());
> for (int i = 0; i < 10; i++) {
> Thread.sleep(1000);
> logger.info("Log4j waiting for reconfiguration");
> }
> }
> }
> {code}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
