Synchronization Issues Between StatusLogger and AsyncRoot

classic Classic list List threaded Threaded
1 message Options
Reply | Threaded
Open this post in threaded view

Synchronization Issues Between StatusLogger and AsyncRoot

Mitchell Rathbun (BLOOMBERG/ 731 LEX)
I recently posted about issues with ConcurrentModificationException: 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, 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"?>

<shutdownHook="disable" packages="">
    <Property name="filePattern">%d{yyyy-MM-dd}.${}.%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>
        <PatternLayout pattern="${layoutPatternForError}"/>
    <!--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"
        <PatternLayout pattern="${layoutPattern}"/>
            <OnStartupTriggeringPolicy />
            <SizeBasedTriggeringPolicy size="512 MB"/>
            <TimeBasedTriggeringPolicy interval="1" modulate="true"/>
        <DefaultRolloverStrategy max="30"/>
    <asyncLogger name="" level="info" additivity="false">
        <appender-ref ref="ActLogAppender"/>
    <asyncRoot level="info">
        <appender-ref ref="WINGMAN"/>
        <appender-ref ref="ActLogAppender" level="ERROR"/>