ConcurrentModificationException when using AsyncLogger

classic Classic list List threaded Threaded
7 messages Options
Reply | Threaded
Open this post in threaded view
|

ConcurrentModificationException when using AsyncLogger

Mitchell Rathbun (BLOOMBERG/ 731 LEX)
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?
Reply | Threaded
Open this post in threaded view
|

Re: ConcurrentModificationException when using AsyncLogger

Matt Sicker
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)
<[hidden email]> 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 <[hidden email]>

---------------------------------------------------------------------
To unsubscribe, e-mail: [hidden email]
For additional commands, e-mail: [hidden email]

Reply | Threaded
Open this post in threaded view
|

Re: ConcurrentModificationException when using AsyncLogger

Ralph Goers
In reply to this post by Mitchell Rathbun (BLOOMBERG/ 731 LEX)
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) <[hidden email]> 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: [hidden email]
For additional commands, e-mail: [hidden email]

Reply | Threaded
Open this post in threaded view
|

Re: ConcurrentModificationException when using AsyncLogger

Mitchell Rathbun (BLOOMBERG/ 731 LEX)
In reply to this post by Mitchell Rathbun (BLOOMBERG/ 731 LEX)
The first thing that I wanted to look at is why 2.13.2 is not being used. We are using apache-storm, through which our project has the maven dependency storm-core with a provided scope. Storm-core has dependencies on log4j-api, log4j-core, and log4j-slf4j-impl. It seems like these have provided scope as well, since explicitly declaring a dependency on these log4j dependencies does not result in the version being different than the transitive version included with storm-core (which is 2.8.2, not 2.13.2). Not sure if this is the right place for this issue

From: [hidden email] At: 05/23/20 20:27:18To:  Mitchell Rathbun (BLOOMBERG/ 731 LEX ) ,  [hidden email]
Subject: Re: ConcurrentModificationException when using AsyncLogger

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)
<[hidden email]> 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(ParameterFo
rmatter.java:599)
> 2020-05-22 05:54:07,996 INFO  STDERR [Thread-2] {}      at
org.apache.logging.log4j.message.ParameterFormatter.appendPotentiallyRecursiveVa
lue(ParameterFormatter.java:507)
> 2020-05-22 05:54:07,996 INFO  STDERR [Thread-2] {}      at
org.apache.logging.log4j.message.ParameterFormatter.recursiveDeepToString(Parame
terFormatter.java:432)
> 2020-05-22 05:54:07,996 INFO  STDERR [Thread-2] {}      at
org.apache.logging.log4j.message.ParameterFormatter.formatMessage2(ParameterForm
atter.java:189)
> 2020-05-22 05:54:07,996 INFO  STDERR [Thread-2] {}      at
org.apache.logging.log4j.message.ParameterizedMessage.formatTo(ParameterizedMess
age.java:225)
> 2020-05-22 05:54:07,996 INFO  STDERR [Thread-2] {}      at
org.apache.logging.log4j.core.pattern.MessagePatternConverter.format(MessagePatt
ernConverter.java:119)
> 2020-05-22 05:54:07,996 INFO  STDERR [Thread-2] {}      at
org.apache.logging.log4j.core.pattern.PatternFormatter.format(PatternFormatter.j
ava:38)
> 2020-05-22 05:54:07,996 INFO  STDERR [Thread-2] {}      at
org.apache.logging.log4j.core.layout.PatternLayout$PatternSerializer.toSerializa
ble(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.directEncode
Event(AbstractOutputStreamAppender.java:177)
> 2020-05-22 05:54:07,996 INFO  STDERR [Thread-2] {}      at
org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.tryAppend(Ab
stractOutputStreamAppender.java:170)
> 2020-05-22 05:54:07,996 INFO  STDERR [Thread-2] {}      at
org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.append(Abstr
actOutputStreamAppender.java:161)
> 2020-05-22 05:54:07,996 INFO  STDERR [Thread-2] {}      at
org.apache.logging.log4j.core.appender.RollingRandomAccessFileAppender.append(Ro
llingRandomAccessFileAppender.java:218)
> 2020-05-22 05:54:07,996 INFO  STDERR [Thread-2] {}      at
org.apache.logging.log4j.core.config.AppenderControl.tryCallAppender(AppenderCon
trol.java:156)
> 2020-05-22 05:54:07,996 INFO  STDERR [Thread-2] {}      at
org.apache.logging.log4j.core.config.AppenderControl.callAppender0(AppenderContr
ol.java:129)
> 2020-05-22 05:54:07,996 INFO  STDERR [Thread-2] {}      at
org.apache.logging.log4j.core.config.AppenderControl.callAppenderPreventRecursio
n(AppenderControl.java:120)
> 2020-05-22 05:54:07,996 INFO  STDERR [Thread-2] {}      at
org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderContro
l.java:84)
> 2020-05-22 05:54:07,996 INFO  STDERR [Thread-2] {}      at
org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.jav
a:448)
> 2020-05-22 05:54:07,996 INFO  STDERR [Thread-2] {}      at
org.apache.logging.log4j.core.async.AsyncLoggerConfig.asyncCallAppenders(AsyncLo
ggerConfig.java:115)
> 2020-05-22 05:54:07,996 INFO  STDERR [Thread-2] {}      at
org.apache.logging.log4j.core.async.AsyncLoggerConfigDisruptor$Log4jEventWrapper
Handler.onEvent(AsyncLoggerConfigDisruptor.java:112)
> 2020-05-22 05:54:07,996 INFO  STDERR [Thread-2] {}      at
org.apache.logging.log4j.core.async.AsyncLoggerConfigDisruptor$Log4jEventWrapper
Handler.onEvent(AsyncLoggerConfigDisruptor.java:98)
> 2020-05-22 05:54:07,996 INFO  STDERR [Thread-2] {}      at
com.lmax.disruptor.BatchEventProcessor.processEvents(BatchEventProcessor.java:16
9)
> 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: [hidden email]
For additional commands, e-mail: [hidden email]


Reply | Threaded
Open this post in threaded view
|

Re: ConcurrentModificationException when using AsyncLogger

Mitchell Rathbun (BLOOMBERG/ 731 LEX)
In reply to this post by Mitchell Rathbun (BLOOMBERG/ 731 LEX)
The main reason that I mentioned the version was due to the issue: https://issues.apache.org/jira/browse/LOG4J2-1988. There are multiple comments here that seem to indicate that this exception should never happen with an AsyncLogger since some sort of copy is made when the logging method is called.

Also, for the question of why we are seeing logs from the StatusLogger overriding our file, I thought it would be helpful to attach our config. I don't see where we would be overriding any default exception handling behavior. We are running our process using Apache Storm, which for logging requires us to define a log4j2 config file named worker.xml (which is attached) in a certain directory. So I am wondering if maybe the status logger is behaving differently than it should because of this set up.

From: Mitchell Rathbun (BLOOMBERG/ 731 LEX) At: 05/26/20 20:11:23
To: [hidden email]
Subject: Re: ConcurrentModificationException when using AsyncLogger

The first thing that I wanted to look at is why 2.13.2 is not being used. We are using apache-storm, through which our project has the maven dependency storm-core with a provided scope. Storm-core has dependencies on log4j-api, log4j-core, and log4j-slf4j-impl. It seems like these have provided scope as well, since explicitly declaring a dependency on these log4j dependencies does not result in the version being different than the transitive version included with storm-core (which is 2.8.2, not 2.13.2). Not sure if this is the right place for this issue

From: [hidden email] At: 05/23/20 20:27:18
To: [hidden email], [hidden email]
Subject: Re: ConcurrentModificationException when using AsyncLogger

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)
<[hidden email]> 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(ParameterFo
rmatter.java:599)
> 2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {} at
org.apache.logging.log4j.message.ParameterFormatter.appendPotentiallyRecursiveVa
lue(ParameterFormatter.java:507)
> 2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {} at
org.apache.logging.log4j.message.ParameterFormatter.recursiveDeepToString(Parame
terFormatter.java:432)
> 2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {} at
org.apache.logging.log4j.message.ParameterFormatter.formatMessage2(ParameterForm
atter.java:189)
> 2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {} at
org.apache.logging.log4j.message.ParameterizedMessage.formatTo(ParameterizedMess
age.java:225)
> 2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {} at
org.apache.logging.log4j.core.pattern.MessagePatternConverter.format(MessagePatt
ernConverter.java:119)
> 2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {} at
org.apache.logging.log4j.core.pattern.PatternFormatter.format(PatternFormatter.j
ava:38)
> 2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {} at
org.apache.logging.log4j.core.layout.PatternLayout$PatternSerializer.toSerializa
ble(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.directEncode
Event(AbstractOutputStreamAppender.java:177)
> 2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {} at
org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.tryAppend(Ab
stractOutputStreamAppender.java:170)
> 2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {} at
org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.append(Abstr
actOutputStreamAppender.java:161)
> 2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {} at
org.apache.logging.log4j.core.appender.RollingRandomAccessFileAppender.append(Ro
llingRandomAccessFileAppender.java:218)
> 2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {} at
org.apache.logging.log4j.core.config.AppenderControl.tryCallAppender(AppenderCon
trol.java:156)
> 2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {} at
org.apache.logging.log4j.core.config.AppenderControl.callAppender0(AppenderContr
ol.java:129)
> 2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {} at
org.apache.logging.log4j.core.config.AppenderControl.callAppenderPreventRecursio
n(AppenderControl.java:120)
> 2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {} at
org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderContro
l.java:84)
> 2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {} at
org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.jav
a:448)
> 2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {} at
org.apache.logging.log4j.core.async.AsyncLoggerConfig.asyncCallAppenders(AsyncLo
ggerConfig.java:115)
> 2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {} at
org.apache.logging.log4j.core.async.AsyncLoggerConfigDisruptor$Log4jEventWrapper
Handler.onEvent(AsyncLoggerConfigDisruptor.java:112)
> 2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {} at
org.apache.logging.log4j.core.async.AsyncLoggerConfigDisruptor$Log4jEventWrapper
Handler.onEvent(AsyncLoggerConfigDisruptor.java:98)
> 2020-05-22 05:54:07,996 INFO STDERR [Thread-2] {} at
com.lmax.disruptor.BatchEventProcessor.processEvents(BatchEventProcessor.java:16
9)
> 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: [hidden email]
For additional commands, e-mail: [hidden email]




---------------------------------------------------------------------
To unsubscribe, e-mail: [hidden email]
For additional commands, e-mail: [hidden email]
Reply | Threaded
Open this post in threaded view
|

Re: ConcurrentModificationException when using AsyncLogger

Ralph Goers
OK, I had forgotten about this issue. It was closed quite a while ago. It indicates the issue was fixed in 2.9.1 so upgrading should fix it.

Apache mailing lists generally strip attachments so I can’t view your configuration.  If log4j2.debug is set to true StatusLogger writes all status events to System.err. If that property is not set then it checks to see if there are any StatusListeners. If there are all status events are written to them, otherwise status events are written to System.err if they pass level filtering.  Log4j normally creates a StatusConsoleListerner when the StatusConfiguration is initialized, which normally happens while parsing the configuration. The StatusConsoleListener only logs events that pass the level specified in status attribute of the configuration and normally logs to System.out. Other applications can register their own Listeners or remove Listeners.

Ralph

> On May 26, 2020, at 5:33 PM, Mitchell Rathbun (BLOOMBERG/ 731 LEX) <[hidden email]> wrote:
>
> The main reason that I mentioned the version was due to the issue: https://issues.apache.org/jira/browse/LOG4J2-1988 <https://issues.apache.org/jira/browse/LOG4J2-1988>. There are multiple comments here that seem to indicate that this exception should never happen with an AsyncLogger since some sort of copy is made when the logging method is called.
>
> Also, for the question of why we are seeing logs from the StatusLogger overriding our file, I thought it would be helpful to attach our config. I don't see where we would be overriding any default exception handling behavior. We are running our process using Apache Storm, which for logging requires us to define a log4j2 config file named worker.xml (which is attached) in a certain directory. So I am wondering if maybe the status logger is behaving differently than it should because of this set up.
>
> From: Mitchell Rathbun (BLOOMBERG/ 731 LEX) At: 05/26/20 20:11:23
> To:  [hidden email] <mailto:[hidden email]>
> Subject: Re: ConcurrentModificationException when using AsyncLogger
>
> The first thing that I wanted to look at is why 2.13.2 is not being used. We are using apache-storm, through which our project has the maven dependency storm-core with a provided scope. Storm-core has dependencies on log4j-api, log4j-core, and log4j-slf4j-impl. It seems like these have provided scope as well, since explicitly declaring a dependency on these log4j dependencies does not result in the version being different than the transitive version included with storm-core (which is 2.8.2, not 2.13.2). Not sure if this is the right place for this issue
>
> From: [hidden email] At: 05/23/20 20:27:18
> To:  Mitchell Rathbun (BLOOMBERG/ 731 LEX )  <mailto:[hidden email]>,  [hidden email] <mailto:[hidden email]>
> Subject: Re: ConcurrentModificationException when using AsyncLogger
>
> 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)
> <[hidden email] <mailto:[hidden email]>> 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(ParameterFo
> rmatter.java:599)
> > 2020-05-22 05:54:07,996 INFO  STDERR [Thread-2] {}      at
> org.apache.logging.log4j.message.ParameterFormatter.appendPotentiallyRecursiveVa
> lue(ParameterFormatter.java:507)
> > 2020-05-22 05:54:07,996 INFO  STDERR [Thread-2] {}      at
> org.apache.logging.log4j.message.ParameterFormatter.recursiveDeepToString(Parame
> terFormatter.java:432)
> > 2020-05-22 05:54:07,996 INFO  STDERR [Thread-2] {}      at
> org.apache.logging.log4j.message.ParameterFormatter.formatMessage2(ParameterForm
> atter.java:189)
> > 2020-05-22 05:54:07,996 INFO  STDERR [Thread-2] {}      at
> org.apache.logging.log4j.message.ParameterizedMessage.formatTo(ParameterizedMess
> age.java:225)
> > 2020-05-22 05:54:07,996 INFO  STDERR [Thread-2] {}      at
> org.apache.logging.log4j.core.pattern.MessagePatternConverter.format(MessagePatt
> ernConverter.java:119)
> > 2020-05-22 05:54:07,996 INFO  STDERR [Thread-2] {}      at
> org.apache.logging.log4j.core.pattern.PatternFormatter.format(PatternFormatter.j
> ava:38)
> > 2020-05-22 05:54:07,996 INFO  STDERR [Thread-2] {}      at
> org.apache.logging.log4j.core.layout.PatternLayout$PatternSerializer.toSerializa
> ble(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.directEncode
> Event(AbstractOutputStreamAppender.java:177)
> > 2020-05-22 05:54:07,996 INFO  STDERR [Thread-2] {}      at
> org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.tryAppend(Ab
> stractOutputStreamAppender.java:170)
> > 2020-05-22 05:54:07,996 INFO  STDERR [Thread-2] {}      at
> org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.append(Abstr
> actOutputStreamAppender.java:161)
> > 2020-05-22 05:54:07,996 INFO  STDERR [Thread-2] {}      at
> org.apache.logging.log4j.core.appender.RollingRandomAccessFileAppender.append(Ro
> llingRandomAccessFileAppender.java:218)
> > 2020-05-22 05:54:07,996 INFO  STDERR [Thread-2] {}      at
> org.apache.logging.log4j.core.config.AppenderControl.tryCallAppender(AppenderCon
> trol.java:156)
> > 2020-05-22 05:54:07,996 INFO  STDERR [Thread-2] {}      at
> org.apache.logging.log4j.core.config.AppenderControl.callAppender0(AppenderContr
> ol.java:129)
> > 2020-05-22 05:54:07,996 INFO  STDERR [Thread-2] {}      at
> org.apache.logging.log4j.core.config.AppenderControl.callAppenderPreventRecursio
> n(AppenderControl.java:120)
> > 2020-05-22 05:54:07,996 INFO  STDERR [Thread-2] {}      at
> org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderContro
> l.java:84)
> > 2020-05-22 05:54:07,996 INFO  STDERR [Thread-2] {}      at
> org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.jav
> a:448)
> > 2020-05-22 05:54:07,996 INFO  STDERR [Thread-2] {}      at
> org.apache.logging.log4j.core.async.AsyncLoggerConfig.asyncCallAppenders(AsyncLo
> ggerConfig.java:115)
> > 2020-05-22 05:54:07,996 INFO  STDERR [Thread-2] {}      at
> org.apache.logging.log4j.core.async.AsyncLoggerConfigDisruptor$Log4jEventWrapper
> Handler.onEvent(AsyncLoggerConfigDisruptor.java:112)
> > 2020-05-22 05:54:07,996 INFO  STDERR [Thread-2] {}      at
> org.apache.logging.log4j.core.async.AsyncLoggerConfigDisruptor$Log4jEventWrapper
> Handler.onEvent(AsyncLoggerConfigDisruptor.java:98)
> > 2020-05-22 05:54:07,996 INFO  STDERR [Thread-2] {}      at
> com.lmax.disruptor.BatchEventProcessor.processEvents(BatchEventProcessor.java:16
> 9)
> > 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: [hidden email] <mailto:[hidden email]>
> For additional commands, e-mail: [hidden email] <mailto:[hidden email]>
>
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: [hidden email]
> For additional commands, e-mail: [hidden email]

Reply | Threaded
Open this post in threaded view
|

Re: ConcurrentModificationException when using AsyncLogger

Mitchell Rathbun (BLOOMBERG/ 731 LEX)
In reply to this post by Mitchell Rathbun (BLOOMBERG/ 731 LEX)
Looking at the provided stack trace it does seem that the logs are getting sent to stderr. The main issue is that this is overwriting the log file, instead of appending. It seems like there are two different appenders that are not coordinating with one another when writing to the same file. I'll post our config file here:


<?xml version="1.0" encoding="UTF-8"?>
<!--License-->

<!-- This file is used to configure logs for the worker process
     running the Wingman topology. Logs will be found at
     /ts/pod/px/px<px>/log/hf/wingman/wingmanWorker.<px_override>.log
-->

<configuration shutdownHook="disable" packages="com.bloomberg.aim.wingman.comm.logging">
<properties>
    <Property name="filePattern">%d{yyyy-MM-dd}.${sys:storm.id}.%i.gz</Property>
    <Property name="layoutPattern">%date{DEFAULT} %-5level %logger{1} [%thread] %mdc %msg%n</Property>
    <Property name="layoutPatternForError">%date{DEFAULT} %-5level %logger{2}.%method.%line [%thread] %mdc %msg%n</Property>
    <Property name="fileName">${sys:wingman.worker.log}</Property>
</properties>
<appenders>
    <ActLogAppender
        name="ActLogAppender"
        procName="${sys:wingman.proc.name}">
        <PatternLayout pattern="${layoutPatternForError}"/>
    </ActLogAppender>
    <RollingRandomAccessFile name="WINGMAN"
                                       immediateFlush="false"
                                       fileName="${fileName}"
                                       filePattern="${fileName}.${filePattern}">
        <PatternLayout pattern="${layoutPattern}"/>
        <Policies>
            <OnStartupTriggeringPolicy />
            <SizeBasedTriggeringPolicy size="512 MB"/>
            <TimeBasedTriggeringPolicy interval="1" modulate="true"/>
        </Policies>
        <DefaultRolloverStrategy max="30"/>
    </RollingRandomAccessFile>
</appenders>
<loggers>
    <asyncLogger name="com.bloomberg.aim.wingman.statsLogger" level="info" additivity="false">
        <appender-ref ref="ActLogAppender"/>
    </asyncLogger>
    <asyncRoot level="info">
        <appender-ref ref="WINGMAN"/>
        <appender-ref ref="ActLogAppender" level="ERROR"/>
    </asyncRoot>
</loggers>
</configuration>

From: [hidden email] At: 05/26/20 21:09:59To:  Mitchell Rathbun (BLOOMBERG/ 731 LEX ) ,  [hidden email]
Subject: Re: ConcurrentModificationException when using AsyncLogger

OK, I had forgotten about this issue. It was closed quite a while ago. It
indicates the issue was fixed in 2.9.1 so upgrading should fix it.

Apache mailing lists generally strip attachments so I can’t view your
configuration.  If log4j2.debug is set to true StatusLogger writes all status
events to System.err. If that property is not set then it checks to see if
there are any StatusListeners. If there are all status events are written to
them, otherwise status events are written to System.err if they pass level
filtering.  Log4j normally creates a StatusConsoleListerner when the
StatusConfiguration is initialized, which normally happens while parsing the
configuration. The StatusConsoleListener only logs events that pass the level
specified in status attribute of the configuration and normally logs to
System.out. Other applications can register their own Listeners or remove
Listeners.

Ralph

> On May 26, 2020, at 5:33 PM, Mitchell Rathbun (BLOOMBERG/ 731 LEX)
<[hidden email]> wrote:
>
> The main reason that I mentioned the version was due to the issue:
https://issues.apache.org/jira/browse/LOG4J2-1988 
<https://issues.apache.org/jira/browse/LOG4J2-1988>. There are multiple
comments here that seem to indicate that this exception should never happen
with an AsyncLogger since some sort of copy is made when the logging method is
called.
>
> Also, for the question of why we are seeing logs from the StatusLogger
overriding our file, I thought it would be helpful to attach our config. I
don't see where we would be overriding any default exception handling behavior.
We are running our process using Apache Storm, which for logging requires us to
define a log4j2 config file named worker.xml (which is attached) in a certain
directory. So I am wondering if maybe the status logger is behaving differently
than it should because of this set up.
>
> From: Mitchell Rathbun (BLOOMBERG/ 731 LEX) At: 05/26/20 20:11:23
> To:  [hidden email] <mailto:[hidden email]>
> Subject: Re: ConcurrentModificationException when using AsyncLogger
>
> The first thing that I wanted to look at is why 2.13.2 is not being used. We
are using apache-storm, through which our project has the maven dependency
storm-core with a provided scope. Storm-core has dependencies on log4j-api,
log4j-core, and log4j-slf4j-impl. It seems like these have provided scope as
well, since explicitly declaring a dependency on these log4j dependencies does
not result in the version being different than the transitive version included
with storm-core (which is 2.8.2, not 2.13.2). Not sure if this is the right
place for this issue
>
> From: [hidden email] At: 05/23/20 20:27:18
> To:  Mitchell Rathbun (BLOOMBERG/ 731 LEX )  
<mailto:[hidden email]>,  [hidden email]
<mailto:[hidden email]>
> Subject: Re: ConcurrentModificationException when using AsyncLogger
>
> 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)
> <[hidden email] <mailto:[hidden email]>> 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(ParameterFo
> rmatter.java:599)
> > 2020-05-22 05:54:07,996 INFO  STDERR [Thread-2] {}      at
>
org.apache.logging.log4j.message.ParameterFormatter.appendPotentiallyRecursiveVa
> lue(ParameterFormatter.java:507)
> > 2020-05-22 05:54:07,996 INFO  STDERR [Thread-2] {}      at
>
org.apache.logging.log4j.message.ParameterFormatter.recursiveDeepToString(Parame
> terFormatter.java:432)
> > 2020-05-22 05:54:07,996 INFO  STDERR [Thread-2] {}      at
>
org.apache.logging.log4j.message.ParameterFormatter.formatMessage2(ParameterForm
> atter.java:189)
> > 2020-05-22 05:54:07,996 INFO  STDERR [Thread-2] {}      at
>
org.apache.logging.log4j.message.ParameterizedMessage.formatTo(ParameterizedMess
> age.java:225)
> > 2020-05-22 05:54:07,996 INFO  STDERR [Thread-2] {}      at
>
org.apache.logging.log4j.core.pattern.MessagePatternConverter.format(MessagePatt
> ernConverter.java:119)
> > 2020-05-22 05:54:07,996 INFO  STDERR [Thread-2] {}      at
>
org.apache.logging.log4j.core.pattern.PatternFormatter.format(PatternFormatter.j
> ava:38)
> > 2020-05-22 05:54:07,996 INFO  STDERR [Thread-2] {}      at
>
org.apache.logging.log4j.core.layout.PatternLayout$PatternSerializer.toSerializa
> ble(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.directEncode
> Event(AbstractOutputStreamAppender.java:177)
> > 2020-05-22 05:54:07,996 INFO  STDERR [Thread-2] {}      at
>
org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.tryAppend(Ab
> stractOutputStreamAppender.java:170)
> > 2020-05-22 05:54:07,996 INFO  STDERR [Thread-2] {}      at
>
org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.append(Abstr
> actOutputStreamAppender.java:161)
> > 2020-05-22 05:54:07,996 INFO  STDERR [Thread-2] {}      at
>
org.apache.logging.log4j.core.appender.RollingRandomAccessFileAppender.append(Ro
> llingRandomAccessFileAppender.java:218)
> > 2020-05-22 05:54:07,996 INFO  STDERR [Thread-2] {}      at
>
org.apache.logging.log4j.core.config.AppenderControl.tryCallAppender(AppenderCon
> trol.java:156)
> > 2020-05-22 05:54:07,996 INFO  STDERR [Thread-2] {}      at
>
org.apache.logging.log4j.core.config.AppenderControl.callAppender0(AppenderContr
> ol.java:129)
> > 2020-05-22 05:54:07,996 INFO  STDERR [Thread-2] {}      at
>
org.apache.logging.log4j.core.config.AppenderControl.callAppenderPreventRecursio
> n(AppenderControl.java:120)
> > 2020-05-22 05:54:07,996 INFO  STDERR [Thread-2] {}      at
>
org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderContro
> l.java:84)
> > 2020-05-22 05:54:07,996 INFO  STDERR [Thread-2] {}      at
>
org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.jav
> a:448)
> > 2020-05-22 05:54:07,996 INFO  STDERR [Thread-2] {}      at
>
org.apache.logging.log4j.core.async.AsyncLoggerConfig.asyncCallAppenders(AsyncLo
> ggerConfig.java:115)
> > 2020-05-22 05:54:07,996 INFO  STDERR [Thread-2] {}      at
>
org.apache.logging.log4j.core.async.AsyncLoggerConfigDisruptor$Log4jEventWrapper
> Handler.onEvent(AsyncLoggerConfigDisruptor.java:112)
> > 2020-05-22 05:54:07,996 INFO  STDERR [Thread-2] {}      at
>
org.apache.logging.log4j.core.async.AsyncLoggerConfigDisruptor$Log4jEventWrapper
> Handler.onEvent(AsyncLoggerConfigDisruptor.java:98)
> > 2020-05-22 05:54:07,996 INFO  STDERR [Thread-2] {}      at
>
com.lmax.disruptor.BatchEventProcessor.processEvents(BatchEventProcessor.java:16
> 9)
> > 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: [hidden email]
<mailto:[hidden email]>
> For additional commands, e-mail: [hidden email]
<mailto:[hidden email]>
>
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: [hidden email]
> For additional commands, e-mail: [hidden email]