logging-log4j-user mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Ralph Goers <ralph.go...@dslextreme.com>
Subject Re: ConcurrentModificationException when using AsyncLogger
Date Wed, 27 May 2020 01:09:37 GMT
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) <mrathbun1@bloomberg.net>
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:  log4j-user@logging.apache.org <mailto: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:18
> To:  Mitchell Rathbun (BLOOMBERG/ 731 LEX )  <mailto:mrathbun1@bloomberg.net>,
 log4j-user@logging.apache.org <mailto: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 <mailto: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 <mailto:log4j-user-unsubscribe@logging.apache.org>
> For additional commands, e-mail: log4j-user-help@logging.apache.org <mailto:log4j-user-help@logging.apache.org>
> 
> 
> 
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
> For additional commands, e-mail: log4j-user-help@logging.apache.org


Mime
  • Unnamed multipart/alternative (inline, None, 0 bytes)
View raw message