4

My application is a sprint boot application that uses log4j2 and runs in a Wildfly server. After the zero day attak, we upgraded to the latest log4j2 version(2.16). But after the log4j upgrade, my application stops working once in a while. And when I looked at the threaddumps, I found that there is a deadlock created by log4j. Here is my log4j configuration. It was working fine before the upgrade.

<?xml version="1.0" encoding="UTF-8" ?>
<Configuration>

    <Properties>
        <Property name="LOGDIR">${sys:jboss.server.log.dir}/application</Property>
        <Property name="FILE_LOG_PATTERN">%d %-5p [%-8.8t] %-25.25c{1} | [%X{correlationId}] %m%n</Property>
    </Properties>

    <Appenders>

        <Console name="SYSOUT" target="SYSTEM_OUT" follow="true">
            <PatternLayout pattern="${FILE_LOG_PATTERN}"/>
        </Console>

        <RollingFile name="CSL" fileName="${LOGDIR}/csl.log"
                     filePattern="${LOGDIR}/csl.%d{yyyy-MM-dd}.log.gz" ignoreExceptions="false">
            <PatternLayout pattern="${FILE_LOG_PATTERN}"/>
            <Policies>
                <TimeBasedTriggeringPolicy/>
            </Policies>
            <DefaultRolloverStrategy>
                <Delete basePath="${LOGDIR}" maxDepth="1">
                    <IfAny>
                        <IfFileName glob="csl*.log.gz" />
                        <IfFileName glob="access_log*.log" />
                    </IfAny>
                    <IfLastModified age="7d" />
                </Delete>
            </DefaultRolloverStrategy>
        </RollingFile>

        <RollingFile name="OTR" fileName="${LOGDIR}/otr.log"
                     filePattern="${LOGDIR}/otr.%d{yyyy-MM-dd}.log.gz" ignoreExceptions="true"
                     bufferedIO="true">
            <PatternLayout pattern="${FILE_LOG_PATTERN}"/>
            <Policies>
                <TimeBasedTriggeringPolicy/>
            </Policies>
            <DefaultRolloverStrategy>
                <Delete basePath="${LOGDIR}" maxDepth="1">
                    <IfFileName glob="otr*.log.gz" />
                    <IfLastModified age="23d" />
                </Delete>
            </DefaultRolloverStrategy>
        </RollingFile>

    </Appenders>

    <Loggers>
        <Logger name="org.apache.catalina.startup.DigesterFactory" level="error" />
        <Logger name="org.apache.catalina.util.LifecycleBase" level="error" />
        <Logger name="org.apache.coyote.http11.Http11NioProtocol" level="warn" />
        <logger name="org.apache.sshd.common.util.SecurityUtils" level="warn"/>
        <Logger name="org.apache.tomcat.util.net.NioSelectorPool" level="warn" />
        <Logger name="org.eclipse.jetty.util.component.AbstractLifeCycle" level="error" />
        <Logger name="org.hibernate.validator.internal.util.Version" level="warn" />
        <logger name="org.springframework.boot.actuate.endpoint.jmx" level="warn"/>

        <logger name="org.springframework" level="info"/>
        <logger name="org.springframework.aop.framework" level="warn"/>
        <logger name="org.apache.jasper.servlet.JspServlet" level="trace"/>
        <logger name="com.zaxxer.hikari.pool.HikariPool" level="debug"/>
        <logger name="com.google.code.ssm.spring.SSMCache" level="warn"/>

        <logger name="com.faskan" level="info" additivity="false">
            <appender-ref ref="OTR" />
            <appender-ref ref="CSL" />
        </logger>

        <Root level="info">
            <AppenderRef ref="CSL"/>
            <AppenderRef ref="SYSOUT"/>
        </Root>
    </Loggers>

</Configuration>

When analysing this issue, I came through a possible defect in log4j code. Not sure if that can result in a deadlock.

Log4J possible bug - As per the release notes, there was a fix to Enable immediate flush on RollingFileAppender when buffered i/o is not enabled. (LOG4J2-3114). But the code just does the opposite in RollingFileAppenderBuilder.

private Appender createAppender(final String name, final Log4j1Configuration config, final Layout layout,
            final Filter filter, final boolean bufferedIo, boolean immediateFlush, final String fileName,
            final String level, final String maxSize, final String maxBackups) {
        org.apache.logging.log4j.core.Layout<?> fileLayout = null;
        if (bufferedIo) {
            immediateFlush = true;
        }
...

It should have been if(!bufferedIo) { immediateFlush = true; }. And one of my appender explicitly sets bufferedIo value to true. I know that log4j does a bufferedio by default and it is not necessary to set this flag explicitly. But unfortunately the code that I am working on is a legacy code and the configuration was working fine before the upgrade.

Threaddump "default task-128" #450 prio=5 os_prio=0 tid=0x00007f31f80cf800 nid=0x14c8 waiting for monitor entry [0x00007f31a7d88000] java.lang.Thread.State: BLOCKED (on object monitor) at org.apache.logging.log4j.core.appender.OutputStreamManager.writeBytes(OutputStreamManager.java:352) - waiting to lock <0x00000000c0e70eb0> (a org.apache.logging.log4j.core.appender.OutputStreamManager) at org.apache.logging.log4j.core.layout.TextEncoderHelper.writeEncodedText(TextEncoderHelper.java:96) at org.apache.logging.log4j.core.layout.TextEncoderHelper.encodeText(TextEncoderHelper.java:65) at org.apache.logging.log4j.core.layout.StringBuilderEncoder.encode(StringBuilderEncoder.java:68) at org.apache.logging.log4j.core.layout.StringBuilderEncoder.encode(StringBuilderEncoder.java:32) at org.apache.logging.log4j.core.layout.PatternLayout.encode(PatternLayout.java:228) at org.apache.logging.log4j.core.layout.PatternLayout.encode(PatternLayout.java:60) at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.directEncodeEvent(AbstractOutputStreamAppender.java:197) at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.tryAppend(AbstractOutputStreamAppender.java:190) at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.append(AbstractOutputStreamAppender.java:181) at org.apache.logging.log4j.core.config.AppenderControl.tryCallAppender(AppenderControl.java:161) at org.apache.logging.log4j.core.config.AppenderControl.callAppender0(AppenderControl.java:134) at org.apache.logging.log4j.core.config.AppenderControl.callAppenderPreventRecursion(AppenderControl.java:125) at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:89) at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:542) at org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(LoggerConfig.java:500) at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:483) at org.apache.logging.log4j.core.config.LoggerConfig.logParent(LoggerConfig.java:533) at org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(LoggerConfig.java:502) at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:483) at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:388) at org.apache.logging.log4j.core.config.AwaitCompletionReliabilityStrategy.log(AwaitCompletionReliabilityStrategy.java:63) at org.apache.logging.log4j.core.Logger.logMessage(Logger.java:153) at org.apache.logging.slf4j.Log4jLogger.log(Log4jLogger.java:376) at org.apache.commons.logging.impl.SLF4JLocationAwareLog.error(SLF4JLocationAwareLog.java:203) at org.springframework.boot.web.support.ErrorPageFilter.handleCommittedResponse(ErrorPageFilter.java:225)

7
  • 4
    Note: if you think they have a bug in their code, you should probably write up a defect on their issue tracker.
    – GhostCat
    Dec 22, 2021 at 14:30
  • 1
    Is there a question? Dec 22, 2021 at 14:39
  • Can the issue that I mentioned attribute to a deadlock? Dec 22, 2021 at 14:59
  • 1
    If you know what the problem is, then 1) submit a bug report with the fix, and 2) build and use a patched version until they merge your patch and release it.
    – Stephen C
    Dec 22, 2021 at 15:00
  • "Can the issue that I mentioned attribute to a deadlock?" - I don't know how we can know that. We don't have access to the thread dumps that lead to you concluding that this was the possible cause. But if you think the bug you have found is the cause ... try fixing it and seeing if the deadlock recurs.
    – Stephen C
    Dec 22, 2021 at 15:03

1 Answer 1

2

Found my answer in this thread https://developer.jboss.org/thread/241453. It is a log4j/jboss configuration issue. The fix is to either exclude jboss logging subsystem from jboss deployment configuration or get rid of the console appender. Thanks to Ralph Goers from Log4J team for guiding me towards the jboss thread.

I have closed the issue that I raised to https://issues.apache.org/jira/browse/LOG4J2-3274. The code snippet that I shared in this question was from log4j-1.2 compatibility adapter which doesn't has any impact in my code because I am already using the latest api version.

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.