logging-log4j-user mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Matt Sicker <boa...@gmail.com>
Subject Re: ConcurrentModificationException when using AsyncLogger
Date Sun, 24 May 2020 00:19:59 GMT
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)
<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(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 <boards@gmail.com>

---------------------------------------------------------------------
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