I recently posted about issues with ConcurrentModificationException:
http://mail-archives.apache.org/mod_mbox/logging-log4j-user/202005.mbox/browser.
As part of this, I mentioned that when this happened the beginning of the log
file would be overwritten by the exception stack trace, and sometimes the
entire file would be overwritten and no new logs would be seen. I have since
attempted to recreate this scenario in a test and am seeing similar behavior.
It seems like there are two loggers/appenders with a handle to the same file
that aren't in sync. For example:
2020-06-08 18:56:38,940 INFO worker [main] {} Launching worker for
WingmanTopology6007-33-1591656986 on 60a01395-12d8-4e4f-a597-5db046941e45:19244
with id 3d72ea06-d91d-493a-9529-a6efc12e3d35 and conf
{topology.builtin.metrics.bucket.size.secs=60, nimbus.childopts=-Xmx1024m
-XX:+PrintAdaptiveSizePolicy...........................................storm.local.mode.zmq=false,
storm.log4j2.conf.dir=/ts/config/wingman,
ui.http.creds.plugin=org.apache.storm.security.auth.DefaultHttpCr2020-06-08
18:56:41,054 INFO STDERR [Thread-2] {} 2020-06-08 18:56:41,052
Log4j2-TF-2-AsyncLoggerConfig-1 ERROR An exception occurred processing Appender
WINGMAN java.util.ConcurrentModificationException
This shows an earlier line get overwritten when the
ConcurrentModificationException occurs. I need to figure out what is causing
this and why StatusLogger does not append to the end of the file. Our log4j2
config file:
<?xml version="1.0" encoding="UTF-8"?>
<!--License-->
<shutdownHook="disable" packages="com.bloomberg.aim.wingman.comm.logging">
<properties>
<Property name="filePattern">%d{yyyy-MM-dd}.${sys:storm.id}.%i.gz</Property>
<!--DEFAULT formats a Date in the format "YYYY-MM-DD HH:MM:SS,mmm".
Dedicated date formatter provides better performance than using "%d{yyyy-MM-dd
HH:mm:ss,SSS}"-->
<Property name="layoutPattern">%date{DEFAULT} %-5level %logger{1} [%thread]
%mdc %msg%n</Property>
<!--Location information (method and line in this pattern) is very
expensive. By default, this is disabled for asyncLoggers, since inclusion of
location info makes async loggers 30-100 times slower. So need to decide
whether we want to risk this hit and enable location info at the log level, or
just remove it from "layoutPatternForError", since that currently doesn't do
anything.-->
<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>
<!--We are flushing right away for now. We will revisit in the future to
see if this results in a significant performance hit. -->
<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>
