Log4j 2
  1. Log4j 2
  2. LOG4J2-392

Intermittent errors with appenders

    Details

    • Type: Bug Bug
    • Status: Resolved
    • Priority: Major Major
    • Resolution: Fixed
    • Affects Version/s: 2.0-beta8, 2.0-beta9
    • Fix Version/s: 2.0-rc2, 2.1
    • Component/s: Appenders
    • Labels:
      None
    • Environment:

      Windows 7 SP1 64bit

      Description

      I intermittently receive following errors after upgrading to beta 8. EVERYTHING was working well with beta 6:

      • 1st error (happens most frequently)
        2013-09-05 10:48:37,722 ERROR Attempted to append to non-started appender LogFile
      • 2nd error:
        2013-09-05 10:49:38,268 ERROR Attempted to append to non-started appender LogFile
        2013-09-05 10:49:38,268 ERROR Unable to write to stream log/ui-selenium-tests.log for appender LogFile
        2013-09-05 10:49:38,269 ERROR An exception occurred processing Appender LogFile org.apache.logging.log4j.core.appender.AppenderRuntimeException: Error writing to RandomAccessFile log/ui-selenium-tests.log
        at org.apache.logging.log4j.core.appender.rolling.FastRollingFileManager.flush(FastRollingFileManager.java:108)
        at org.apache.logging.log4j.core.appender.rolling.FastRollingFileManager.write(FastRollingFileManager.java:89)
        at org.apache.logging.log4j.core.appender.OutputStreamManager.write(OutputStreamManager.java:129)
        at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.append(AbstractOutputStreamAppender.java:115)
        at org.apache.logging.log4j.core.appender.FastRollingFileAppender.append(FastRollingFileAppender.java:97)
        at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:102)
        at org.apache.logging.log4j.core.appender.AsyncAppender$AsyncThread.run(AsyncAppender.java:228)
        Caused by: java.io.IOException: Write error
        at java.io.RandomAccessFile.writeBytes(Native Method)
        at java.io.RandomAccessFile.write(Unknown Source)
        at org.apache.logging.log4j.core.appender.rolling.FastRollingFileManager.flush(FastRollingFileManager.java:105)
        ... 6 more
      1. log4j2.xml
        3 kB
        ilynaf
      2. Log4J2.zip
        4.18 MB
        ilynaf
      3. AppenderOverwhelmer.java
        0.3 kB
        Andre Bogus

        Issue Links

          Activity

          Hide
          ilynaf added a comment -

          Also happens with RollingFile appender

          Show
          ilynaf added a comment - Also happens with RollingFile appender
          Hide
          Ralph Goers added a comment -

          Do you have the rest of the stack trace? Is there another "Caused by" further down?

          Show
          Ralph Goers added a comment - Do you have the rest of the stack trace? Is there another "Caused by" further down?
          Hide
          ilynaf added a comment -

          Unfortunately, this is all we have for the stack trace

          Show
          ilynaf added a comment - Unfortunately, this is all we have for the stack trace
          Hide
          Andre Bogus added a comment - - edited

          We appear to have the same problem using beta 9 with async appenders, however not all of our applications exhibit the same problem.

          I will look into the culprits and try to find out what triggers the problem.

          In the meantime, could someone with higher privileges in this issue tracker add 2.0-beta9 to the affected versions?

          Update: The problem appears when using asynchronous loggers. The applications in question exit via thrown exception to the default VM exception handler. No log4j exception handler has been installed. Note that I cannot reproduce the problem using a small test application that only logs once and then throws an exception, so it appears that something else is amiss.

          Show
          Andre Bogus added a comment - - edited We appear to have the same problem using beta 9 with async appenders, however not all of our applications exhibit the same problem. I will look into the culprits and try to find out what triggers the problem. In the meantime, could someone with higher privileges in this issue tracker add 2.0-beta9 to the affected versions? Update: The problem appears when using asynchronous loggers. The applications in question exit via thrown exception to the default VM exception handler. No log4j exception handler has been installed. Note that I cannot reproduce the problem using a small test application that only logs once and then throws an exception, so it appears that something else is amiss.
          Hide
          Remko Popma added a comment -

          Andre,
          Thanks for looking into this. I added 2.0-beta9 to the affected versions. You mention you are seeing the same problem, is that problem #1 or #2? (Or both?)

          Ilynaf and Andre,
          Does this problem happen with a web application or with a stand-alone java application? (Details on java version, web container version, OS, etc may be useful.)

          Just judging from the error stack trace, it looks as if the appender is trying to write to a file that has been closed.
          Would it be possible for you to provide a small program that reproduces the issue?

          Show
          Remko Popma added a comment - Andre, Thanks for looking into this. I added 2.0-beta9 to the affected versions. You mention you are seeing the same problem, is that problem #1 or #2? (Or both?) Ilynaf and Andre, Does this problem happen with a web application or with a stand-alone java application? (Details on java version, web container version, OS, etc may be useful.) Just judging from the error stack trace, it looks as if the appender is trying to write to a file that has been closed. Would it be possible for you to provide a small program that reproduces the issue?
          Hide
          ilynaf added a comment - - edited

          I've attached a Java project for reproduction. This issue happens when I run a Java class which extends AbstractTestNGSpringContextTests using TestNG plugin for Eclipse:

          Env:

          • Eclipse: Kepler 64bit (4.3.1.M20130911-1000)
          • TestNG plugin: 6.8.6.20130914_0724
          • OS: Windows 7 SP1 64 bit
          • JDK: 1.7.0_45 64bit

          How to reproduce:

          • Install TestNG plugin into Eclipse
          • Import the attached Java project to Eclipse
          • Run TempTest as TestNG Test (Ctrl + F11)
          • Look for error in Eclipse console

          I hope this will help

          Show
          ilynaf added a comment - - edited I've attached a Java project for reproduction. This issue happens when I run a Java class which extends AbstractTestNGSpringContextTests using TestNG plugin for Eclipse: Env: Eclipse: Kepler 64bit (4.3.1.M20130911-1000) TestNG plugin: 6.8.6.20130914_0724 OS: Windows 7 SP1 64 bit JDK: 1.7.0_45 64bit How to reproduce: Install TestNG plugin into Eclipse Import the attached Java project to Eclipse Run TempTest as TestNG Test (Ctrl + F11) Look for error in Eclipse console I hope this will help
          Hide
          Andre Bogus added a comment -

          Hi again,

          Remko, We are using standalone OpenJDK 1.7.0_25 on Windows 7SP1 64bit, Debian and LUbuntu.

          Another bit of evidence: The executable classes for the programs in question all extend other classes with or without logging. I have not yet found an error with programs where the main class does not extend anything (except the default Object). However, I have not enough specimen to be sufficiently confident (at a p-value of 5%).

          Regards,
          Andre

          Show
          Andre Bogus added a comment - Hi again, Remko, We are using standalone OpenJDK 1.7.0_25 on Windows 7SP1 64bit, Debian and LUbuntu. Another bit of evidence: The executable classes for the programs in question all extend other classes with or without logging. I have not yet found an error with programs where the main class does not extend anything (except the default Object). However, I have not enough specimen to be sufficiently confident (at a p-value of 5%). Regards, Andre
          Hide
          Andre Bogus added a comment -

          Hi again. I now think the problem is that the classes in question log a lot - so much that they overwhelm the appender, creating a huge backlog, which the AsyncLoggerThread is trying to finish. The shutdown hook apparently closes all files, which is the right thing to do - but it would be even better to join the appender thread before doing that.

          I'm attaching a very small intuitive program that exhibits the problematic behavior, just by logging a lot.

          Regards,
          Andre

          Show
          Andre Bogus added a comment - Hi again. I now think the problem is that the classes in question log a lot - so much that they overwhelm the appender, creating a huge backlog, which the AsyncLoggerThread is trying to finish. The shutdown hook apparently closes all files, which is the right thing to do - but it would be even better to join the appender thread before doing that. I'm attaching a very small intuitive program that exhibits the problematic behavior, just by logging a lot. Regards, Andre
          Hide
          Andre Bogus added a comment - - edited

          Btw. this also explains why the problem did not happen in beta6 - AFAIR beta8 was the first version to "fix" a hanging threads issue by making the async logger thread a daemon thread.

          Update: Having looked inside the code, it appears that the shutdown thread should wait for 10 seconds giving the loggers time to finish. I can testify that the VM shutdown is quite immediate, so this does not appear to happen (I just re-checked with a System.err.println("Done"); at the end, this comes a mere microsecond before the error).

          Unfortunately, I have not yet managed to reproduce the problem under a debugger, so I'm a little stumped on how to progress.

          Regards,
          Andre

          Show
          Andre Bogus added a comment - - edited Btw. this also explains why the problem did not happen in beta6 - AFAIR beta8 was the first version to "fix" a hanging threads issue by making the async logger thread a daemon thread. Update: Having looked inside the code, it appears that the shutdown thread should wait for 10 seconds giving the loggers time to finish. I can testify that the VM shutdown is quite immediate, so this does not appear to happen (I just re-checked with a System.err.println("Done"); at the end, this comes a mere microsecond before the error). Unfortunately, I have not yet managed to reproduce the problem under a debugger, so I'm a little stumped on how to progress. Regards, Andre
          Hide
          Remko Popma added a comment -

          Thanks Andre,
          Sorry for the slow response time... I've been swamped with $work. I hope to be able to take a look at this and some other issues this weekend.

          Show
          Remko Popma added a comment - Thanks Andre, Sorry for the slow response time... I've been swamped with $work. I hope to be able to take a look at this and some other issues this weekend.
          Hide
          Andre Bogus added a comment -

          Hi Remko,

          No need to be sorry. It's not as if I pay you to work on this Maybe I'll find a few spare minutes until the weekend to btrace the ShutdownThread, to find out why it does not wait, btw. if it gets started at all. Otherwise, good luck.

          Keep up the good work!

          Regards,
          Andre

          Show
          Andre Bogus added a comment - Hi Remko, No need to be sorry. It's not as if I pay you to work on this Maybe I'll find a few spare minutes until the weekend to btrace the ShutdownThread, to find out why it does not wait, btw. if it gets started at all. Otherwise, good luck. Keep up the good work! Regards, Andre
          Hide
          Andre Bogus added a comment -

          Hi again,

          I finally managed to debug this thing. Interestingly, the logger in my example is not an org.apache.logging.log4j.core.async.AsyncLogger, as I would have expected, but a plain org.apache.logging.log4j.core.Logger. Despite my configuration having not a single synchronous <logger> or <root> entry, the context isn't even an AsyncLoggerContext. The reason appears to be that in org.apache.logging.log4j.core.impl.Log4jContextFactory.<init>, in line 44, the resulting LOG4J_CONTEXT_SELECTOR property (which refers to the "Log4jContextSelector" system property) is null, therefore the selector will be instantiated as a ClassLoaderContextSelector, which has absolutely no ties to the async package.

          Now I have two possible recourses:
          1. Ask my colleagues to add static

          { System.setProperty("Log4jContextSelector", "org.apache.logging.log4j.core.async.AsyncLoggerContextSelector"); }

          to their classes
          2. Change the ClassLoaderContextSelector to somehow distinguish between synchronous and asynchronous LoggerContexts.

          The first one is only a viable workaround if there are only asynchronous loggers. I am unsure how to implement the second. Maybe someone more competent than me in Log4j2 development could have a look?

          Regards,
          Andre

          Show
          Andre Bogus added a comment - Hi again, I finally managed to debug this thing. Interestingly, the logger in my example is not an org.apache.logging.log4j.core.async.AsyncLogger, as I would have expected, but a plain org.apache.logging.log4j.core.Logger. Despite my configuration having not a single synchronous <logger> or <root> entry, the context isn't even an AsyncLoggerContext. The reason appears to be that in org.apache.logging.log4j.core.impl.Log4jContextFactory.<init>, in line 44, the resulting LOG4J_CONTEXT_SELECTOR property (which refers to the "Log4jContextSelector" system property) is null, therefore the selector will be instantiated as a ClassLoaderContextSelector, which has absolutely no ties to the async package. Now I have two possible recourses: 1. Ask my colleagues to add static { System.setProperty("Log4jContextSelector", "org.apache.logging.log4j.core.async.AsyncLoggerContextSelector"); } to their classes 2. Change the ClassLoaderContextSelector to somehow distinguish between synchronous and asynchronous LoggerContexts. The first one is only a viable workaround if there are only asynchronous loggers. I am unsure how to implement the second. Maybe someone more competent than me in Log4j2 development could have a look? Regards, Andre
          Hide
          Andre Bogus added a comment -

          Hi again,

          @Remko: Great to see you working on this. If I can be of any assistance, let me know.

          Regards,
          Andre

          Show
          Andre Bogus added a comment - Hi again, @Remko: Great to see you working on this. If I can be of any assistance, let me know. Regards, Andre
          Hide
          Remko Popma added a comment -

          I modified BaseConfiguration.stop() to ensure that all loggers and appenders are stopped in this order:

          1. -AsyncLogger Disruptor thread- (this is not possible yet until we have a solution for LOG4J2-493)
          2. AsyncLoggerConfig Disruptor thread(s)
          3. AsyncAppender(s)
          4. other appenders
          5. non-async LoggerConfigs
          6. root LoggerConfig (if non-async)

          Committed in revision 1565254.
          Please verify and close.

          Show
          Remko Popma added a comment - I modified BaseConfiguration.stop() to ensure that all loggers and appenders are stopped in this order: - AsyncLogger Disruptor thread - (this is not possible yet until we have a solution for LOG4J2-493 ) AsyncLoggerConfig Disruptor thread(s) AsyncAppender(s) other appenders non-async LoggerConfigs root LoggerConfig (if non-async) Committed in revision 1565254. Please verify and close.
          Hide
          Andre Bogus added a comment -

          Hi Remko,

          I just built HEAD and tested the AppenderOverwhelmer again. This indeed removes the AppenderRuntimeException. However, running the AppenderOverwhelmer gets out only 3.047 of 10.000 messages to stdout on my machine before exiting with only a number of status debug messages.

          In my very humble opinion, this change makes it worse, not better. Before there was at least an error that implied that messages had not been written out. Now they are silently discarded. Ok, I get it, don't use async loggers for anything that should be logged under all circumstances, but adding a status error method if logs are being discarded, even better combined with a grace period (perhaps only if there are log messages waiting in the ring buffer) for async loggers would be really helpful.

          Please suggest how you want to go forward. If you like, I can close the bug and open a new one describing the behavior I discussed above.

          Regards,
          Andre

          Show
          Andre Bogus added a comment - Hi Remko, I just built HEAD and tested the AppenderOverwhelmer again. This indeed removes the AppenderRuntimeException. However, running the AppenderOverwhelmer gets out only 3.047 of 10.000 messages to stdout on my machine before exiting with only a number of status debug messages. In my very humble opinion, this change makes it worse, not better. Before there was at least an error that implied that messages had not been written out. Now they are silently discarded. Ok, I get it, don't use async loggers for anything that should be logged under all circumstances, but adding a status error method if logs are being discarded, even better combined with a grace period (perhaps only if there are log messages waiting in the ring buffer) for async loggers would be really helpful. Please suggest how you want to go forward. If you like, I can close the bug and open a new one describing the behavior I discussed above. Regards, Andre
          Hide
          Remko Popma added a comment -

          Andre, thanks for checking!
          I think that you have started to run into a different existing issue (LOG4J2-520) now. I'll start to look at that one next. I hope this issue is fixed now but I'd like ilynaf (who originally reported it) to also confirm the solution works for them before closing this ticket.

          ilynaf, sorry for taking so long to address this issue. Can you also confirm if the problem you were seeing no longer occurs with the latest version of trunk?

          Show
          Remko Popma added a comment - Andre, thanks for checking! I think that you have started to run into a different existing issue ( LOG4J2-520 ) now. I'll start to look at that one next. I hope this issue is fixed now but I'd like ilynaf (who originally reported it) to also confirm the solution works for them before closing this ticket. ilynaf, sorry for taking so long to address this issue. Can you also confirm if the problem you were seeing no longer occurs with the latest version of trunk?
          Hide
          Remko Popma added a comment -

          Re-opening as the current fix may result in dropped events in case of slow appenders (LOG4J2-520).

          Show
          Remko Popma added a comment - Re-opening as the current fix may result in dropped events in case of slow appenders ( LOG4J2-520 ).
          Hide
          Remko Popma added a comment -

          The previous solution cleared the appenders from the logger config too soon.
          The new solution first signals to all AsyncLoggerConfig instances that the application is being stopped. When all AsyncLoggerConfig instances are signalled, and the usage count drops to zero, the shared Disruptor is shut down. (It will process all enqueued events before actually stopping.)

          Only after all enqueued events have been processed are the appenders stopped and cleared from the logger configs.

          Fixed in revision 1592463.
          Please verify and close.

          Show
          Remko Popma added a comment - The previous solution cleared the appenders from the logger config too soon. The new solution first signals to all AsyncLoggerConfig instances that the application is being stopped. When all AsyncLoggerConfig instances are signalled, and the usage count drops to zero, the shared Disruptor is shut down. (It will process all enqueued events before actually stopping.) Only after all enqueued events have been processed are the appenders stopped and cleared from the logger configs. Fixed in revision 1592463. Please verify and close.
          Hide
          Andre Bogus added a comment -

          Sorry for the delay, I'm down with laryngitis. I just re-compiled and re-checked. I can confirm that r1592539 fixes the problem in my environment.

          Show
          Andre Bogus added a comment - Sorry for the delay, I'm down with laryngitis. I just re-compiled and re-checked. I can confirm that r1592539 fixes the problem in my environment.
          Hide
          Remko Popma added a comment -

          Great, thanks for the confirmation. Get well soon!

          Show
          Remko Popma added a comment - Great, thanks for the confirmation. Get well soon!
          Hide
          Remko Popma added a comment - - edited

          Reopening this issue: When investigating LOG4J2-593 with a configuration containing an <AsyncLogger>, I found that the fix still has problems.

          This is what happens:

          2014-06-14 23:45:46,080 TRACE AsyncLoggerConfigHelper not starting new disruptor, using existing object. Ref count is 2.
          2014-06-14 23:45:46,080 TRACE AbstractConfiguration stopping...
          2014-06-14 23:45:46,080 TRACE AsyncLoggerConfigHelper: not shutting down disruptor: ref count is 1.
          2014-06-14 23:45:46,081 TRACE AbstractConfiguration stopped 1 AsyncLoggerConfigs.
          2014-06-14 23:45:46,081 TRACE AsyncAppender stopping. Queue still has 0 events.
          2014-06-14 23:45:46,081 TRACE AsyncAppender.AsyncThread shutting down. Processing remaining 0 queue events.
          2014-06-14 23:45:46,081 TRACE AsyncAppender.AsyncThread stopped. Queue has 0 events remaining. Processed 0 and ignored 0 events since shutdown started.
          2014-06-14 23:45:46,082 TRACE AsyncAppender stopped. Queue has 0 events.
          2014-06-14 23:45:46,082 TRACE AbstractConfiguration stopped 1 AsyncAppenders.
          2014-06-14 23:45:46,082 TRACE AbstractConfiguration stopped 3 Appenders.
          2014-06-14 23:45:46,082 TRACE AsyncLoggerConfigHelper: shutting down disruptor: ref count is 0.
          2014-06-14 23:45:46,083 TRACE AbstractConfiguration stopped 2 Loggers.
          2014-06-14 23:45:46,083 DEBUG Unregistering MBean org.apache.logging.log4j2:type=AsyncLoggerContext
          ...
          2014-06-14 23:45:46,084 DEBUG Unregistering MBean org.apache.logging.log4j2:type=AsyncLoggerContext,component=Loggers,name=com.foo.Bar
          2014-06-14 23:45:46,084 DEBUG Unregistering MBean org.apache.logging.log4j2:type=AsyncLoggerContext,component=Loggers,name=
          ...
          2014-06-14 23:45:46,086 DEBUG Unregistering MBean org.apache.logging.log4j2:type=AsyncLoggerContext,component=Loggers,name=com.foo.Bar,subtype=RingBuffer
          2014-06-14 23:45:46,087 DEBUG Registering MBean org.apache.logging.log4j2:type=AsyncLoggerContext
          ...
          2014-06-14 23:45:46,088 DEBUG Registering MBean org.apache.logging.log4j2:type=AsyncLoggerContext,component=Loggers,name=
          2014-06-14 23:45:46,088 DEBUG Registering MBean org.apache.logging.log4j2:type=AsyncLoggerContext,component=Loggers,name=com.foo.Bar
          2014-06-14 23:45:46,089 ERROR Could not register mbeans java.lang.NullPointerException
          	at org.apache.logging.log4j.core.async.AsyncLoggerConfigHelper.createRingBufferAdmin(AsyncLoggerConfigHelper.java:357)
          	at org.apache.logging.log4j.core.async.AsyncLoggerConfig.createRingBufferAdmin(AsyncLoggerConfig.java:146)
          	at org.apache.logging.log4j.core.jmx.Server.registerLoggerConfigs(Server.java:328)
          	at org.apache.logging.log4j.core.jmx.Server.reregisterMBeansAfterReconfigure(Server.java:158)
          	at org.apache.logging.log4j.core.jmx.Server.reregisterMBeansAfterReconfigure(Server.java:119)
          	at org.apache.logging.log4j.core.LoggerContext.setConfiguration(LoggerContext.java:362)
          	at org.apache.logging.log4j.core.LoggerContext.start(LoggerContext.java:169)
          	at org.apache.logging.log4j.core.jmx.LoggerContextAdmin.setConfigText(LoggerContextAdmin.java:183)
          

          AsyncLoggerConfigHelper currently has a single static Disruptor instance that is shared between multiple AsyncLoggerConfig instances. It keeps track of the reference count to decide when there are no more references and the Disruptor should be shut down.

          The reference count is increased when an AsyncLoggerConfig is started, and decreased when an AsyncLoggerConfig is stopped.

          With the current fix for this issue, AbstractConfiguration.stop() may call AsyncLoggerConfig.stop() multiple times on the same instance, which results in an incorrect reference count, causing the NPE above.

          Show
          Remko Popma added a comment - - edited Reopening this issue: When investigating LOG4J2-593 with a configuration containing an <AsyncLogger> , I found that the fix still has problems. This is what happens: 2014-06-14 23:45:46,080 TRACE AsyncLoggerConfigHelper not starting new disruptor, using existing object. Ref count is 2. 2014-06-14 23:45:46,080 TRACE AbstractConfiguration stopping... 2014-06-14 23:45:46,080 TRACE AsyncLoggerConfigHelper: not shutting down disruptor: ref count is 1. 2014-06-14 23:45:46,081 TRACE AbstractConfiguration stopped 1 AsyncLoggerConfigs. 2014-06-14 23:45:46,081 TRACE AsyncAppender stopping. Queue still has 0 events. 2014-06-14 23:45:46,081 TRACE AsyncAppender.AsyncThread shutting down. Processing remaining 0 queue events. 2014-06-14 23:45:46,081 TRACE AsyncAppender.AsyncThread stopped. Queue has 0 events remaining. Processed 0 and ignored 0 events since shutdown started. 2014-06-14 23:45:46,082 TRACE AsyncAppender stopped. Queue has 0 events. 2014-06-14 23:45:46,082 TRACE AbstractConfiguration stopped 1 AsyncAppenders. 2014-06-14 23:45:46,082 TRACE AbstractConfiguration stopped 3 Appenders. 2014-06-14 23:45:46,082 TRACE AsyncLoggerConfigHelper: shutting down disruptor: ref count is 0. 2014-06-14 23:45:46,083 TRACE AbstractConfiguration stopped 2 Loggers. 2014-06-14 23:45:46,083 DEBUG Unregistering MBean org.apache.logging.log4j2:type=AsyncLoggerContext ... 2014-06-14 23:45:46,084 DEBUG Unregistering MBean org.apache.logging.log4j2:type=AsyncLoggerContext,component=Loggers,name=com.foo.Bar 2014-06-14 23:45:46,084 DEBUG Unregistering MBean org.apache.logging.log4j2:type=AsyncLoggerContext,component=Loggers,name= ... 2014-06-14 23:45:46,086 DEBUG Unregistering MBean org.apache.logging.log4j2:type=AsyncLoggerContext,component=Loggers,name=com.foo.Bar,subtype=RingBuffer 2014-06-14 23:45:46,087 DEBUG Registering MBean org.apache.logging.log4j2:type=AsyncLoggerContext ... 2014-06-14 23:45:46,088 DEBUG Registering MBean org.apache.logging.log4j2:type=AsyncLoggerContext,component=Loggers,name= 2014-06-14 23:45:46,088 DEBUG Registering MBean org.apache.logging.log4j2:type=AsyncLoggerContext,component=Loggers,name=com.foo.Bar 2014-06-14 23:45:46,089 ERROR Could not register mbeans java.lang.NullPointerException at org.apache.logging.log4j.core.async.AsyncLoggerConfigHelper.createRingBufferAdmin(AsyncLoggerConfigHelper.java:357) at org.apache.logging.log4j.core.async.AsyncLoggerConfig.createRingBufferAdmin(AsyncLoggerConfig.java:146) at org.apache.logging.log4j.core.jmx.Server.registerLoggerConfigs(Server.java:328) at org.apache.logging.log4j.core.jmx.Server.reregisterMBeansAfterReconfigure(Server.java:158) at org.apache.logging.log4j.core.jmx.Server.reregisterMBeansAfterReconfigure(Server.java:119) at org.apache.logging.log4j.core.LoggerContext.setConfiguration(LoggerContext.java:362) at org.apache.logging.log4j.core.LoggerContext.start(LoggerContext.java:169) at org.apache.logging.log4j.core.jmx.LoggerContextAdmin.setConfigText(LoggerContextAdmin.java:183) AsyncLoggerConfigHelper currently has a single static Disruptor instance that is shared between multiple AsyncLoggerConfig instances. It keeps track of the reference count to decide when there are no more references and the Disruptor should be shut down. The reference count is increased when an AsyncLoggerConfig is started, and decreased when an AsyncLoggerConfig is stopped. With the current fix for this issue, AbstractConfiguration.stop() may call AsyncLoggerConfig.stop() multiple times on the same instance, which results in an incorrect reference count, causing the NPE above.
          Hide
          Remko Popma added a comment -

          Fixed in revision 1602598.

          The new solution brings back some code from a previous solution that keeps track of the AsyncLoggerConfig instances that have been stopped to prevent the same instance from being stopped more than once.

          At the same time, the new solution still correctly clears the appenders for all LoggerConfigs, and still does this after all AsyncLoggerConfigs have been stopped.

          I verified that the AppenderOverwhelmer test still works correctly, and also verified that the above NPE (premature Disruptor shutdown) problem no longer occurs.

          Show
          Remko Popma added a comment - Fixed in revision 1602598. The new solution brings back some code from a previous solution that keeps track of the AsyncLoggerConfig instances that have been stopped to prevent the same instance from being stopped more than once. At the same time, the new solution still correctly clears the appenders for all LoggerConfigs, and still does this after all AsyncLoggerConfigs have been stopped. I verified that the AppenderOverwhelmer test still works correctly, and also verified that the above NPE (premature Disruptor shutdown) problem no longer occurs.
          Hide
          Remko Popma added a comment -

          Additional fix in revision 1602666.

          Similar to stopping, the same care must be taken when starting LoggerConfigs: avoid starting the same LoggerConfig instance twice as it will mess up the AsyncLoggerConfigHelper ref count.

          Show
          Remko Popma added a comment - Additional fix in revision 1602666. Similar to stopping, the same care must be taken when starting LoggerConfigs: avoid starting the same LoggerConfig instance twice as it will mess up the AsyncLoggerConfigHelper ref count.

            People

            • Assignee:
              Remko Popma
              Reporter:
              ilynaf
            • Votes:
              1 Vote for this issue
              Watchers:
              4 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved:

                Development