[jira] [Created] (LOG4J2-807) Disruptor is null when configuration is reloaded (asyncRoot + monitorInterval)

[Florin Marinoiu (JIRA)]

Florin Marinoiu created LOG4J2-807:
--------------------------------------

Summary: 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


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.2#6252)

[Florin Marinoiu (JIRA)]

[ https://issues.apache.org/jira/browse/LOG4J2-807?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]

Florin Marinoiu updated LOG4J2-807:
-----------------------------------

Attachment: async-root-reload.log

Complete log

Post by Florin Marinoiu (JIRA)
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
Attachments: async-root-reload-test.zip, async-root-reload.log
{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}
{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}
{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.2#6252)

[Florin Marinoiu (JIRA)]

[ https://issues.apache.org/jira/browse/LOG4J2-807?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]

Florin Marinoiu updated LOG4J2-807:
-----------------------------------

Attachment: async-root-reload-test.zip

Eclipse/Maven project to reproduce the problem

Post by Florin Marinoiu (JIRA)
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
Attachments: async-root-reload-test.zip, async-root-reload.log
{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}
{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}
{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.2#6252)

[Florin Marinoiu (JIRA)]

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

Florin Marinoiu edited comment on LOG4J2-807 at 8/29/14 3:02 PM:
-----------------------------------------------------------------

I attached the complete log file


was (Author: florin.marinoiu):
Complete log

Post by Florin Marinoiu (JIRA)
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
Attachments: async-root-reload-test.zip, async-root-reload.log
{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}
{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}
{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.2#6252)

[Florin Marinoiu (JIRA)]

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

Florin Marinoiu edited comment on LOG4J2-807 at 8/29/14 3:02 PM:
-----------------------------------------------------------------

I attached a Eclipse/Maven project to reproduce the problem


was (Author: florin.marinoiu):
Eclipse/Maven project to reproduce the problem

Post by Florin Marinoiu (JIRA)
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
Attachments: async-root-reload-test.zip, async-root-reload.log
{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}
{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}
{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.2#6252)

[Gary Gregory (JIRA)]

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

Gary Gregory commented on LOG4J2-807:
-------------------------------------

I added a test for this which passes but prints NPE on the console. This test should fail but how can we detect the error condition?

Post by Florin Marinoiu (JIRA)
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
Attachments: async-root-reload-test.zip, async-root-reload.log
{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}
{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}
{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.2#6252)

[Gary Gregory (JIRA)]

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

Gary Gregory edited comment on LOG4J2-807 at 8/29/14 3:44 PM:
--------------------------------------------------------------

I pushed a test for this which passes but prints NPE on the console. This test should fail but how can we detect the error condition?

Note: that we use Git, not SVN now.


was (Author: garydgregory):
I added a test for this which passes but prints NPE on the console. This test should fail but how can we detect the error condition?

Post by Florin Marinoiu (JIRA)
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
Attachments: async-root-reload-test.zip, async-root-reload.log
{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}
{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}
{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.2#6252)

[Remko Popma (JIRA)]

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

Remko Popma commented on LOG4J2-807:
------------------------------------

AsyncLoggerConfigHelper uses a reference counting mechanism to prevent the shared disruptor instance from being released while still in use. At first glance it looks like there may be a problem with that ref count tracking. There is internal logging when the reference count is increased or decreased but this happens at TRACE level. Could you change your setting to {{<Configuration status="TRACE"...}} and attach that log?

Post by Florin Marinoiu (JIRA)
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
Attachments: async-root-reload-test.zip, async-root-reload.log
{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}
{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}
{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.2#6252)

[Florin Marinoiu (JIRA)]

[ https://issues.apache.org/jira/browse/LOG4J2-807?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]

Florin Marinoiu updated LOG4J2-807:
-----------------------------------
Attachment: async-root-reload - trace.log

Here's the log with TRACE level.

Post by Florin Marinoiu (JIRA)
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
Attachments: async-root-reload - trace.log, async-root-reload-test.zip, async-root-reload.log
{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}
{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}
{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)

[Florin Marinoiu (JIRA)]

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

Florin Marinoiu commented on LOG4J2-807:
----------------------------------------

The FileConfigurationMonitor is restarting config on another Thread, I guess that's why the disruptor is null in the AsyncLoggerConfigHelper and logs to status logger:
{code}
2014-09-02 09:24:09,779 FATAL Ignoring log event after log4j was shut down
2014-09-02 09:24:10,779 FATAL Ignoring log event after log4j was shut down
2014-09-02 09:24:11,779 FATAL Ignoring log event after log4j was shut down
{code}
after reconfiguration.

Post by Florin Marinoiu (JIRA)
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
Attachments: async-root-reload - trace.log, async-root-reload-test.zip, async-root-reload.log
{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}
{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}
{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)

[Florin Marinoiu (JIRA)]

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

Florin Marinoiu commented on LOG4J2-807:
----------------------------------------

Looks like {code}AsyncLoggerConfigHelper#release(){code} is called after {code}AsyncLoggerConfigHelper#claim()/initDisruptor(){code}

Post by Florin Marinoiu (JIRA)
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
Attachments: async-root-reload - trace.log, async-root-reload-test.zip, async-root-reload.log
{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}
{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}
{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)

[Florin Marinoiu (JIRA)]

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

Florin Marinoiu edited comment on LOG4J2-807 at 9/2/14 2:35 PM:
----------------------------------------------------------------

The FileConfigurationMonitor is restarting config on another Thread, The disruptor is null in the AsyncLoggerConfigHelper and logs to status logger:
{code}
2014-09-02 09:24:09,779 FATAL Ignoring log event after log4j was shut down
2014-09-02 09:24:10,779 FATAL Ignoring log event after log4j was shut down
2014-09-02 09:24:11,779 FATAL Ignoring log event after log4j was shut down
{code}
after reconfiguration.


was (Author: florin.marinoiu):
The FileConfigurationMonitor is restarting config on another Thread, I guess that's why the disruptor is null in the AsyncLoggerConfigHelper and logs to status logger:
{code}
2014-09-02 09:24:09,779 FATAL Ignoring log event after log4j was shut down
2014-09-02 09:24:10,779 FATAL Ignoring log event after log4j was shut down
2014-09-02 09:24:11,779 FATAL Ignoring log event after log4j was shut down
{code}
after reconfiguration.

Post by Florin Marinoiu (JIRA)
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
Attachments: async-root-reload - trace.log, async-root-reload-test.zip, async-root-reload.log
{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}
{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}
{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)

[Remko Popma (JIRA)]

[ https://issues.apache.org/jira/browse/LOG4J2-807?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]

Remko Popma reassigned LOG4J2-807:
----------------------------------

Assignee: Remko Popma

Post by Florin Marinoiu (JIRA)
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
Attachments: async-root-reload - trace.log, async-root-reload-test.zip, async-root-reload.log
{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}
{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}
{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)

[Remko Popma (JIRA)]

[ https://issues.apache.org/jira/browse/LOG4J2-807?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]

Remko Popma updated LOG4J2-807:
-------------------------------
Fix Version/s: 2.1

Post by Florin Marinoiu (JIRA)
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
{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}
{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}
{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)

[Remko Popma (JIRA)]

[ 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}

Post by Florin Marinoiu (JIRA)
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
{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}
{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}
{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)

[Remko Popma (JIRA)]

[ https://issues.apache.org/jira/browse/LOG4J2-807?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]

Remko Popma resolved LOG4J2-807.
--------------------------------
Resolution: Fixed

Fixed in master in commits 0f8acc5 and 23b48b3.
Please verify and close.

Post by Florin Marinoiu (JIRA)
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
{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}
{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}
{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)

[Florin Marinoiu (JIRA)]

[ https://issues.apache.org/jira/browse/LOG4J2-807?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]

Florin Marinoiu closed LOG4J2-807.
----------------------------------

Tested, the asynRoot is correctly reloaded.
Thank you !

Post by Florin Marinoiu (JIRA)
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
{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}
{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}
{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)