Log4j2死锁

Question

我的应用程序是一个使用 log4j2 并在 Wildfly 服务器中运行的 sprint 启动应用程序。零日攻击后，我们升级到最新的 log4j2 版本（2.16）。但是在 log4j 升级之后，我的应用程序偶尔会停止工作。当我查看线程转储时，我发现 log4j 造成了死锁。这是我的 log4j 配置。升级前一切正常。

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

在分析这个问题时，我发现了 log4j 代码中可能存在的缺陷。不确定这是否会导致死锁。

Log4J 可能的错误 - 根据发行说明，修复了 在未启用缓冲 i/o 时在 RollingFileAppender 上启用立即刷新。 (LOG4J2-3114)。但代码在 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;
        }
...

应该是if(!bufferedIo) { immediateFlush = true; }。我的一个 appender 明确地将 bufferedIo 值设置为 true。我知道 log4j 默认执行 bufferedio 并且没有必要显式设置此标志。但不幸的是，我正在处理的代码是遗留代码，升级前配置工作正常。

Threaddump “默认任务 128”#450 prio=5 os_prio=0 tid=0x00007f31f80cf800 nid=0x14c8 等待监视器条目 [0x00007f31a7d88000] java.lang.Thread.State：阻塞（在对象监视器上）在 org.apache.logging.log4j.core.appender.OutputStreamManager.writeBytes(OutputStreamManager.java:352) - 等待锁定 <0x00000000c0e70eb0> (a org.apache.logging.log4j.core.appender.OutputStreamManager) 在 org.apache.logging.log4j.core.layout.TextEncoderHelper.writeEncodedText(TextEncoderHelper.java:96) 在 org.apache.logging.log4j.core.layout.TextEncoderHelper.encodeText(TextEncoderHelper.java:65) 在 org.apache.logging.log4j.core.layout.StringBuilderEncoder.encode(StringBuilderEncoder.java:68) 在 org.apache.logging.log4j.core.layout.StringBuilderEncoder.encode(StringBuilderEncoder.java:32) 在 org.apache.logging.log4j.core.layout.PatternLayout.encode(PatternLayout.java:228) 在 org.apache.logging.log4j.core.layout.PatternLayout.encode(PatternLayout.java:60) 在 org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.directEncodeEvent(AbstractOutputStreamAppender.java:197) 在 org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.tryAppend(AbstractOutputStreamAppender.java:190) 在 org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.append(AbstractOutputStreamAppender.java:181) 在 org.apache.logging.log4j.core.config.AppenderControl.tryCallAppender(AppenderControl.java:161) 在 org.apache.logging.log4j.core.config.AppenderControl.callAppender0(AppenderControl.java:134) 在 org.apache.logging.log4j.core.config.AppenderControl.callAppenderPreventRecursion(AppenderControl.java:125) 在 org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:89) 在 org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:542) 在 org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(LoggerConfig.java:500) 在 org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:483) 在 org.apache.logging.log4j.core.config.LoggerConfig.log 父级（LoggerConfig.java:533）在 org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(LoggerConfig.java:502) 在 org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:483) 在 org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:388) 在 org.apache.logging.log4j.core.config.AwaitCompletionReliabilityStrategy.log(AwaitCompletionReliabilityStrategy.java:63) 在 org.apache.logging.log4j.core.Logger.logMessage(Logger.java:153) 在 org.apache.logging.slf4j.Log4jLogger.log(Log4jLogger.java:376) 在 org.apache.commons.logging.impl.SLF4JLocationAwareLog.error(SLF4JLocationAwareLog.java:203) 在 org.springframework.boot.web.support.ErrorPageFilter.handleCommittedResponse(ErrorPageFilter.java:225)

Answer 1

在这个话题 https://developer.jboss.org/thread/241453 中找到了我的答案。这是一个 log4j/jboss 配置问题。解决方法是从 jboss 部署配置中排除 jboss 日志子系统，或者删除控制台附加程序。感谢 Log4J 团队的 Ralph Goers 指导我进入 jboss 线程。

我已经关闭了我向 https://issues.apache.org/jira/browse/LOG4J2-3274 提出的问题。我在这个问题中分享的代码片段来自 log4j-1.2 兼容性适配器，它对我的代码没有任何影响，因为我已经在使用最新的 api 版本。

Log4j2死锁

Log4j2 deadlock

java

spring-boot

log4j2