Mailing-List: contact log4j-dev-help@logging.apache.org; run by ezmlm
Precedence: bulk
Reply-To: "Log4J Developers List" <log4j-dev@logging.apache.org>
Date: Mon, 22 Sep 2014 10:06:34 +0000 (UTC)
From: "Remko Popma (JIRA)" <jira@apache.org>
To: log4j-dev@logging.apache.org
Message-ID: <JIRA.12737811.1409324418000.93000.1411380394086@Atlassian.JIRA>
In-Reply-To: <JIRA.12737811.1409324418000@Atlassian.JIRA>
References: <JIRA.12737811.1409324418000@Atlassian.JIRA>
 <JIRA.12737811.1409324418212@arcas>
Subject: [jira] [Commented] (LOG4J2-807) Disruptor is null when
 configuration is reloaded (asyncRoot + monitorInterval)
MIME-Version: 1.0
Content-Type: text/plain; charset=utf-8
Content-Transfer-Encoding: 7bit


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