logging-log4j-user mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Mitchell Rathbun (BLOOMBERG/ 731 LEX)" <mrathb...@bloomberg.net>
Subject Re: ConcurrentModificationException when using AsyncLogger
Date Wed, 27 May 2020 00:33:37 GMT
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:23To:  log4j-user@logging.apache.org
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: log4j-user@logging.apache.org At: 05/23/20 20:27:18To:  Mitchell Rathbun (BLOOMBERG/
731 LEX ) ,  log4j-user@logging.apache.org
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) 
<mrathbun1@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(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: log4j-user-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-user-help@logging.apache.org


Mime
View raw message