You are viewing a plain text version of this content. The canonical link for it is here.
Posted to log4j-user@logging.apache.org by "Mitchell Rathbun (BLOOMBERG/ 731 LEX)" <mr...@bloomberg.net> on 2020/05/23 22:46:42 UTC
ConcurrentModificationException when using AsyncLogger
We recently started occasionally getting the following error:
2020-05-22 05:54:07,995 INFO STDERR [Thread-2] {} 2020-05-22 05:54:07,994 Log4j2-TF-2-AsyncLoggerConfig-1 ERROR An exception occurred processing Appender WINGMAN java.util.ConcurrentModificationException
2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {} at java.util.HashMap$HashIterator.nextNode(HashMap.java:1442)
2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {} at java.util.HashMap$KeyIterator.next(HashMap.java:1466)
2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {} at org.apache.logging.log4j.message.ParameterFormatter.appendCollection(ParameterFormatter.java:599)
2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {} at org.apache.logging.log4j.message.ParameterFormatter.appendPotentiallyRecursiveValue(ParameterFormatter.java:507)
2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {} at org.apache.logging.log4j.message.ParameterFormatter.recursiveDeepToString(ParameterFormatter.java:432)
2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {} at org.apache.logging.log4j.message.ParameterFormatter.formatMessage2(ParameterFormatter.java:189)
2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {} at org.apache.logging.log4j.message.ParameterizedMessage.formatTo(ParameterizedMessage.java:225)
2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {} at org.apache.logging.log4j.core.pattern.MessagePatternConverter.format(MessagePatternConverter.java:119)
2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {} at org.apache.logging.log4j.core.pattern.PatternFormatter.format(PatternFormatter.java:38)
2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {} at org.apache.logging.log4j.core.layout.PatternLayout$PatternSerializer.toSerializable(PatternLayout.java:333)
2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {} at org.apache.logging.log4j.core.layout.PatternLayout.toText(PatternLayout.java:232)
2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {} at org.apache.logging.log4j.core.layout.PatternLayout.encode(PatternLayout.java:217)
2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {} at org.apache.logging.log4j.core.layout.PatternLayout.encode(PatternLayout.java:57)
2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {} at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.directEncodeEvent(AbstractOutputStreamAppender.java:177)
2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {} at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.tryAppend(AbstractOutputStreamAppender.java:170)
2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {} at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.append(AbstractOutputStreamAppender.java:161)
2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {} at org.apache.logging.log4j.core.appender.RollingRandomAccessFileAppender.append(RollingRandomAccessFileAppender.java:218)
2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {} at org.apache.logging.log4j.core.config.AppenderControl.tryCallAppender(AppenderControl.java:156)
2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {} at org.apache.logging.log4j.core.config.AppenderControl.callAppender0(AppenderControl.java:129)
2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {} at org.apache.logging.log4j.core.config.AppenderControl.callAppenderPreventRecursion(AppenderControl.java:120)
2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {} at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:84)
2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {} at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:448)
2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {} at org.apache.logging.log4j.core.async.AsyncLoggerConfig.asyncCallAppenders(AsyncLoggerConfig.java:115)
2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {} at org.apache.logging.log4j.core.async.AsyncLoggerConfigDisruptor$Log4jEventWrapperHandler.onEvent(AsyncLoggerConfigDisruptor.java:112)
2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {} at org.apache.logging.log4j.core.async.AsyncLoggerConfigDisruptor$Log4jEventWrapperHandler.onEvent(AsyncLoggerConfigDisruptor.java:98)
2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {} at com.lmax.disruptor.BatchEventProcessor.processEvents(BatchEventProcessor.java:169)
2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {} at com.lmax.disruptor.BatchEventProcessor.run(BatchEventProcessor.java:126)
2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {} at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {} at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {} at java.lang.Thread.run(Thread.java:748)
2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {}
We are using a RollingRandomAccessFileAppeneder with an AsyncLogger, and recently upgraded our log4j2 version to 2.13.2. The system property Log4jContextSelector is set to org.apache.logging.log4j.core.selector.BasicContextSelector. It seems from the few posts I have seen online that this shouldn't happen if async logging is being used. So I have two questions:
1. Why are we seeing this/what generally could cause this?
2. When this error occurs, the file that logs were being written to gets overwritten completely with the stack trace posted above. The process continues to run after this but no new logs ever get written to the file. This makes this a critical error and also makes it very difficult to debug why this error is happening to begin with. Is there a way to prevent this from happening so that the error just gets appended to the file instead of overwriting everything that is there?
Re: ConcurrentModificationException when using AsyncLogger
Posted by Matt Sicker <bo...@gmail.com>.
Looks like one of the parameters to a log message is a HashMap which
gets modified while the log message was being constructed in another
thread. Using a synchronous appender would avoid the issue from
popping up since it's an issue of thread safety.
On Sat, 23 May 2020 at 17:46, Mitchell Rathbun (BLOOMBERG/ 731 LEX)
<mr...@bloomberg.net> wrote:
>
> We recently started occasionally getting the following error:
>
> 2020-05-22 05:54:07,995 INFO STDERR [Thread-2] {} 2020-05-22 05:54:07,994 Log4j2-TF-2-AsyncLoggerConfig-1 ERROR An exception occurred processing Appender WINGMAN java.util.ConcurrentModificationException
> 2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {} at java.util.HashMap$HashIterator.nextNode(HashMap.java:1442)
> 2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {} at java.util.HashMap$KeyIterator.next(HashMap.java:1466)
> 2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {} at org.apache.logging.log4j.message.ParameterFormatter.appendCollection(ParameterFormatter.java:599)
> 2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {} at org.apache.logging.log4j.message.ParameterFormatter.appendPotentiallyRecursiveValue(ParameterFormatter.java:507)
> 2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {} at org.apache.logging.log4j.message.ParameterFormatter.recursiveDeepToString(ParameterFormatter.java:432)
> 2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {} at org.apache.logging.log4j.message.ParameterFormatter.formatMessage2(ParameterFormatter.java:189)
> 2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {} at org.apache.logging.log4j.message.ParameterizedMessage.formatTo(ParameterizedMessage.java:225)
> 2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {} at org.apache.logging.log4j.core.pattern.MessagePatternConverter.format(MessagePatternConverter.java:119)
> 2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {} at org.apache.logging.log4j.core.pattern.PatternFormatter.format(PatternFormatter.java:38)
> 2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {} at org.apache.logging.log4j.core.layout.PatternLayout$PatternSerializer.toSerializable(PatternLayout.java:333)
> 2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {} at org.apache.logging.log4j.core.layout.PatternLayout.toText(PatternLayout.java:232)
> 2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {} at org.apache.logging.log4j.core.layout.PatternLayout.encode(PatternLayout.java:217)
> 2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {} at org.apache.logging.log4j.core.layout.PatternLayout.encode(PatternLayout.java:57)
> 2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {} at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.directEncodeEvent(AbstractOutputStreamAppender.java:177)
> 2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {} at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.tryAppend(AbstractOutputStreamAppender.java:170)
> 2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {} at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.append(AbstractOutputStreamAppender.java:161)
> 2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {} at org.apache.logging.log4j.core.appender.RollingRandomAccessFileAppender.append(RollingRandomAccessFileAppender.java:218)
> 2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {} at org.apache.logging.log4j.core.config.AppenderControl.tryCallAppender(AppenderControl.java:156)
> 2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {} at org.apache.logging.log4j.core.config.AppenderControl.callAppender0(AppenderControl.java:129)
> 2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {} at org.apache.logging.log4j.core.config.AppenderControl.callAppenderPreventRecursion(AppenderControl.java:120)
> 2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {} at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:84)
> 2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {} at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:448)
> 2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {} at org.apache.logging.log4j.core.async.AsyncLoggerConfig.asyncCallAppenders(AsyncLoggerConfig.java:115)
> 2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {} at org.apache.logging.log4j.core.async.AsyncLoggerConfigDisruptor$Log4jEventWrapperHandler.onEvent(AsyncLoggerConfigDisruptor.java:112)
> 2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {} at org.apache.logging.log4j.core.async.AsyncLoggerConfigDisruptor$Log4jEventWrapperHandler.onEvent(AsyncLoggerConfigDisruptor.java:98)
> 2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {} at com.lmax.disruptor.BatchEventProcessor.processEvents(BatchEventProcessor.java:169)
> 2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {} at com.lmax.disruptor.BatchEventProcessor.run(BatchEventProcessor.java:126)
> 2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {} at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
> 2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {} at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
> 2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {} at java.lang.Thread.run(Thread.java:748)
> 2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {}
>
> We are using a RollingRandomAccessFileAppeneder with an AsyncLogger, and recently upgraded our log4j2 version to 2.13.2. The system property Log4jContextSelector is set to org.apache.logging.log4j.core.selector.BasicContextSelector. It seems from the few posts I have seen online that this shouldn't happen if async logging is being used. So I have two questions:
>
> 1. Why are we seeing this/what generally could cause this?
>
> 2. When this error occurs, the file that logs were being written to gets overwritten completely with the stack trace posted above. The process continues to run after this but no new logs ever get written to the file. This makes this a critical error and also makes it very difficult to debug why this error is happening to begin with. Is there a way to prevent this from happening so that the error just gets appended to the file instead of overwriting everything that is there?
--
Matt Sicker <bo...@gmail.com>
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-user-help@logging.apache.org
Re: ConcurrentModificationException when using AsyncLogger
Posted by Ralph Goers <ra...@dslextreme.com>.
This stack trace is not from Log4j 2.13.2. The line numbers don’t match. This error indicates that one of the parameters being passed on the logging method is a Collection. The Layout is iterating over the Collection in an attempt to format it. However, some other thread is modifying the Collection while the Async Logger thread is trying to iterate through it. Log4j has no way to prevent this as it is an object owned by the application.
1. See above.
2. It would be expected that the stack trace would be coming from the StatusLogger, which appears to be the case. I don’t see any reason logging would continue to fail. The AppenderControl should catch the error. However, if you have configured the Appender to not ignore exceptions then it is possible that that AsyncLoggerConfig is not handling the error. We will have to look further to see if that is the case.
Ralph
> On May 23, 2020, at 3:46 PM, Mitchell Rathbun (BLOOMBERG/ 731 LEX) <mr...@bloomberg.net> wrote:
>
> We recently started occasionally getting the following error:
>
> 2020-05-22 05:54:07,995 INFO STDERR [Thread-2] {} 2020-05-22 05:54:07,994 Log4j2-TF-2-AsyncLoggerConfig-1 ERROR An exception occurred processing Appender WINGMAN java.util.ConcurrentModificationException
> 2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {} at java.util.HashMap$HashIterator.nextNode(HashMap.java:1442)
> 2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {} at java.util.HashMap$KeyIterator.next(HashMap.java:1466)
> 2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {} at org.apache.logging.log4j.message.ParameterFormatter.appendCollection(ParameterFormatter.java:599)
> 2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {} at org.apache.logging.log4j.message.ParameterFormatter.appendPotentiallyRecursiveValue(ParameterFormatter.java:507)
> 2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {} at org.apache.logging.log4j.message.ParameterFormatter.recursiveDeepToString(ParameterFormatter.java:432)
> 2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {} at org.apache.logging.log4j.message.ParameterFormatter.formatMessage2(ParameterFormatter.java:189)
> 2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {} at org.apache.logging.log4j.message.ParameterizedMessage.formatTo(ParameterizedMessage.java:225)
> 2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {} at org.apache.logging.log4j.core.pattern.MessagePatternConverter.format(MessagePatternConverter.java:119)
> 2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {} at org.apache.logging.log4j.core.pattern.PatternFormatter.format(PatternFormatter.java:38)
> 2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {} at org.apache.logging.log4j.core.layout.PatternLayout$PatternSerializer.toSerializable(PatternLayout.java:333)
> 2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {} at org.apache.logging.log4j.core.layout.PatternLayout.toText(PatternLayout.java:232)
> 2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {} at org.apache.logging.log4j.core.layout.PatternLayout.encode(PatternLayout.java:217)
> 2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {} at org.apache.logging.log4j.core.layout.PatternLayout.encode(PatternLayout.java:57)
> 2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {} at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.directEncodeEvent(AbstractOutputStreamAppender.java:177)
> 2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {} at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.tryAppend(AbstractOutputStreamAppender.java:170)
> 2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {} at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.append(AbstractOutputStreamAppender.java:161)
> 2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {} at org.apache.logging.log4j.core.appender.RollingRandomAccessFileAppender.append(RollingRandomAccessFileAppender.java:218)
> 2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {} at org.apache.logging.log4j.core.config.AppenderControl.tryCallAppender(AppenderControl.java:156)
> 2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {} at org.apache.logging.log4j.core.config.AppenderControl.callAppender0(AppenderControl.java:129)
> 2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {} at org.apache.logging.log4j.core.config.AppenderControl.callAppenderPreventRecursion(AppenderControl.java:120)
> 2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {} at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:84)
> 2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {} at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:448)
> 2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {} at org.apache.logging.log4j.core.async.AsyncLoggerConfig.asyncCallAppenders(AsyncLoggerConfig.java:115)
> 2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {} at org.apache.logging.log4j.core.async.AsyncLoggerConfigDisruptor$Log4jEventWrapperHandler.onEvent(AsyncLoggerConfigDisruptor.java:112)
> 2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {} at org.apache.logging.log4j.core.async.AsyncLoggerConfigDisruptor$Log4jEventWrapperHandler.onEvent(AsyncLoggerConfigDisruptor.java:98)
> 2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {} at com.lmax.disruptor.BatchEventProcessor.processEvents(BatchEventProcessor.java:169)
> 2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {} at com.lmax.disruptor.BatchEventProcessor.run(BatchEventProcessor.java:126)
> 2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {} at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
> 2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {} at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
> 2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {} at java.lang.Thread.run(Thread.java:748)
> 2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {}
>
> We are using a RollingRandomAccessFileAppeneder with an AsyncLogger, and recently upgraded our log4j2 version to 2.13.2. The system property Log4jContextSelector is set to org.apache.logging.log4j.core.selector.BasicContextSelector. It seems from the few posts I have seen online that this shouldn't happen if async logging is being used. So I have two questions:
>
> 1. Why are we seeing this/what generally could cause this?
>
> 2. When this error occurs, the file that logs were being written to gets overwritten completely with the stack trace posted above. The process continues to run after this but no new logs ever get written to the file. This makes this a critical error and also makes it very difficult to debug why this error is happening to begin with. Is there a way to prevent this from happening so that the error just gets appended to the file instead of overwriting everything that is there?
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-user-help@logging.apache.org