Log4j2异步打印可变对象的问题

现象

应用代码如下：

        Test test = new Test();
        test.setA(1);
        test.setB("1");
        log.info("before modification: {} \t ",test);
        test.setA(2);
        test.setB("2");
        log.info("after modification: {} \t ",test);

问题应用的日志控制台输出和文件输出为：

2023-11-18 20:45:32.391 INFO  [main]  before modification: ExpressServerApplication.Test(a=2, b=2) 	 
2023-11-18 20:45:32.391 INFO  [main] after modification: ExpressServerApplication.Test(a=2, b=2)

修改前后打的日志都是改之后的内容a=2, b=2。

但是同样的依赖版本和Log4j2配置新起了一个Spring Boot 应用进行自测，日志输出确又是正常的：

2023-11-18 21:19:28.750 INFO  [main] before modification: DemoLoggingApplication.Test(a=1, b=1) 	 
2023-11-18 21:21:21.029 INFO  [main] after modification: DemoLoggingApplication.Test(a=2, b=2)

pom依赖和版本如下：


<dependency>
    <groupId>org.slf4j</groupId>
    <artifactId>slf4j-api</artifactId>
    <version>1.7.25</version>
</dependency>
<dependency>
<groupId>org.apache.logging.log4j</groupId>
<artifactId>log4j-slf4j-impl</artifactId>
<version>2.7</version>
</dependency>
<dependency>
<groupId>org.apache.logging.log4j</groupId>
<artifactId>log4j-core</artifactId>
<version>2.7</version>
</dependency>
        // 异步日志支持
<dependency>
<groupId>com.lmax</groupId>
<artifactId>disruptor</artifactId>
<version>3.4.0</version>
</dependency>
        // 配置文件是YAML或YML时需添加该依赖
<dependency>
<groupId>com.fasterxml.jackson.dataformat</groupId>
<artifactId>jackson-dataformat-yaml</artifactId>
</dependency>

日志门面使用Slf4j；日志实现使用Log4j2，使用混合异步方式，其配置如下：

<?xml version="1.0" encoding="UTF-8"?>
<Configuration>
    <Properties>
        <property name="baseLogDir">./app/log</property>
        <property name="logPattern">%d{yyyy-MM-dd HH:mm:ss.SSS} %-5level [%logger{0}:%line][%thread] %X{logger_id} -
            [TID: %X{EagleEye-TraceID}] %msg%n
        </property>
    </Properties>

    <Appenders>
        <Console name="console" target="SYSTEM_OUT">
            <PatternLayout pattern="${logPattern}"/>
            <ThresholdFilter level="DEBUG" onMatch="ACCEPT" onMismatch="DENY"/>
        </Console>

        <RollingFile name="business" fileName="${baseLogDir}/app.log"
                     filePattern="${baseLogDir}/main/%d{yyyy-MM-dd}/app-%d{yyyy-MM-dd}-%i.log">
            <PatternLayout pattern="${logPattern}"/>
            <ThresholdFilter level="INFO" onMatch="ACCEPT" onMismatch="DENY"/>
            <!--            滚动策略 -->
            <Policies>
                <!--                时间间隔-->
                <TimeBasedTriggeringPolicy interval="1" modulate="true"/>
                <SizeBasedTriggeringPolicy size="200M"/>
            </Policies>

            <DefaultRolloverStrategy max="99999">
                <Delete basePath="${baseLogDir}/main" maxDepth="3">
                    <IfFileName glob="app-20*"/>
                    <IfLastModified age="30d"/>
                </Delete>
            </DefaultRolloverStrategy>
        </RollingFile>

        <RollingFile name="error" fileName="${baseLogDir}/error.log"
                     filePattern="${baseLogDir}/error/%d{yyyy-MM-dd}/error-%d{yyyy-MM-dd}-%i.log">
            <PatternLayout pattern="${logPattern}"/>
            <ThresholdFilter level="ERROR" onMatch="ACCEPT" onMismatch="DENY"/>
            <Policies>
                <TimeBasedTriggeringPolicy interval="1" modulate="true"/>
                <SizeBasedTriggeringPolicy size="200M"/>
            </Policies>

            <DefaultRolloverStrategy max="99999">
                <Delete basePath="${baseLogDir}/error" maxDepth="3">
                    <IfFileName glob="error-20*"/>
                    <IfLastModified age="30d"/>
                </Delete>
            </DefaultRolloverStrategy>
        </RollingFile>
    </Appenders>

    <Loggers>
        <AsyncRoot level="info" includeLocation="true">
            <AppenderRef ref="console"/>
            <AppenderRef ref="business"/>
            <AppenderRef ref="error"/>
        </AsyncRoot>
    </Loggers>
</Configuration>

原因剖析

异步基本原理

Log4j2异步日志基于 LMAX Disruptor 实现，借助该并发框架，在多线程场景下，Asynchronous Loggers 相比于Log4j1.x和Logback在吞吐量上提升18倍且在延迟上低了几个数量级。

首先简单介绍一下 Disruptor 框架。

Disruptor

LMAX是一家交易平台，交易系统需要达到 低延时、高吞吐 两个目标。而阻碍Java系统以上目标的两个原因：

CPU缓存行失效
Locks需要进入内核态，代价大

由此诞生无锁的Disruptor并发框架。

Disruptor 借助Ring Buffer数据结构，Ring Buffer用于存放线程间通信的内容.

详见：
高性能队列——Disruptor
Log4j 2 Async Logging 的原理和实现

Log4j2异步日志

异步日志的优点：

高吞吐
log方法耗时短，低延时

异步日志的缺点：

异步打日志时错误处理
打印可变内容可能打印错误内容：In some rare cases, care must be taken with mutable messages. Most of the time you don’t
need to worry about this （这句话不合事实） . Log4 will ensure that log messages like logger.debug(“My object is {}”, myObject) will use the state of the myObject parameter at the time of the call to logger.debug(). The log
message will not change even if myObject is modified later. It is safe to asynchronously log mutable objects because most Message implementations built-in to Log4j take a snapshot of the parameters. There are some exceptions however: MapMessage and StructuredDataMessage are mutable by design (事实还包含ParameterizedMessage): fields can be added to these messages after the message object was created. These messages should not be modified after they are logged with asynchronous loggers or asynchronous appenders; you may or may not see the modifications in the resulting log output. Similarly, custom Message implementations should be designed with asynchronous use in mind, and either take a snapshot of their parameters at construction time, or document their thread-safety characteristics.
不利于CPU资源少的运行环境，因为需要额外后台线程进行磁盘IO
如果打印日志比刷到磁盘还要快时，会导致队列排满，此时默认策略为使用当前线程执行append操作（类似线程池的CallerRun拒绝策略）。

详见：Asynchronous Loggers for Low-Latency Logging

现象原因

经过调试发现问题应用和自测应用传入Ring Buffer的LoggerEvent类型不同：

问题应用：Log4jLogEvent
自测应用：MutableLogEvent

Log4j2是否开启LocalThreads配置项影响了LogEventFactory的实现类，从而生成了不同的LoggerEvent
。关键代码就在org.apache.logging.log4j.util.Constants中，：

package org.apache.logging.log4j.util;

public final class Constants {
    // 是否是WEB，问题应用是WEB，自测应用不是WEB，
    public static final boolean IS_WEB_APP = PropertiesUtil.getProperties().getBooleanProperty("log4j2.is.webapp", isClassAvailable("javax.servlet.Servlet"));
    // 问题应用关闭了ThreadLocals，自测应用开启了ThreadLocals
    public static final boolean ENABLE_THREADLOCALS;
    // ...
    static {
        ENABLE_THREADLOCALS = !IS_WEB_APP && PropertiesUtil.getProperties().getBooleanProperty("log4j2.enable.threadlocals", true);
    }
}

是否开启ThreadLocals直接影响了LoggerEventFacotry的实现类：

package org.apache.logging.log4j.core.config;
public class LoggerConfig extends AbstractFilterable {
       // ...
       static {
       // 是否指定了Log4jLogEventFactory
        String factory = PropertiesUtil.getProperties().getStringProperty("Log4jLogEventFactory");
        if (factory != null) {
            try {
                Class<?> clazz = LoaderUtil.loadClass(factory);
                if (clazz != null && LogEventFactory.class.isAssignableFrom(clazz)) {
                    LOG_EVENT_FACTORY = (LogEventFactory)clazz.newInstance();
                }
            } catch (Exception var2) {
                LOGGER.error("Unable to create LogEventFactory {}", factory, var2);
            }
        }
        // 没有指定，则看ThreadLocals是否开启
        // 开启则 ReusableLogEventFactory，会生成 MutableLogEvent，如问题应用
        // 关闭则 DefaultLogEventFactory，会生成 Log4jLogEvent，如自测应用
        if (LOG_EVENT_FACTORY == null) {
            LOG_EVENT_FACTORY = (LogEventFactory)(Constants.ENABLE_THREADLOCALS ? new ReusableLogEventFactory() : new DefaultLogEventFactory());
        }

    }
}

在自测应用中禁用ThreadLocals，复现了错误打印可变对象内容的现象。

由此，产生3个疑问：

开启Threadlocal时的ReusableLogEventFactory有什么优势？
为什么WEBAPP必须关闭ThreadLocals?
为什么从Log4jLogEvent打印可变对象的日志会错?

Garbage-free Steady State Logging

之前的许多日志框架会生成很多临时对象，比如log event objects, Strings, char arrays, byte arrays，这会造成GC压力。针对GC问题，2.6版本的Log4j2后提供2个模式:

garbage free mode: objects and buffers are reused and no temporary objects are allocated as much as possible
low garbage mode: not completely garbage free but does not use ThreadLocal fields, it’s the default mode when Log4j
detects it is running in a web application.

所以ReusableLogEventFactory利用ThreadLocals提供LogEvent的重用，避免频繁GC。

WEBAPP的Log4j2必须禁用ThreadLocals

To avoid causing memory leaks, Log4j will not use these ThreadLocals when it detects that it is used in a web
application (when the javax.servlet.Servlet class is in the classpath, or when system property log4j2.is.webapp is set
to “true”).

WEBAPP能在不重启Servlet容器的情况下重新加载应用，如果使用ThreadLocals，共用的线程池的线程的ThreadLocals会引用老版本的LogEvent，这样LogEvent不会被GC到，导致内存泄漏。

如果保证线程池不会被公用且重新加载应用时线程池也会关闭再重启，就可以开启Garbage-free

详见：
Why WEBAPP not using ThreadLocals
why log4j gc free logging is not suitable for webapp

关于这里的ThreadLocal，可以看下京东的技术文章：记一次疑似JVM内存泄漏的排查过程

格式化日志内容的时机

org.apache.logging.log4j.core.LogEvent中会携带org.apache.logging.log4j.message.Message信息，比如：

WEBAPP中Log4jLogEvent携带ParameterizedMessage
MutableLogEvent携带ReusableParameterizedMessage

不同类型的Message对于占位符{}的字符串填充对象的时机不同，填充时占位符的对象内容才是真正被log到appender的内容。

对于ReusableParameterizedMessage，在org.apache.logging.log4j.core.impl.ReusableLogEventFactory#createEvent
方法中调用MutableLogEvent#setMessage时会填充{}，该过程在进入RingBuffer之前由log的线程在log.info方法调用中同步进行。
对于ParameterizedMessage，填充{}却是由Disruptor的handler线程池(只有一个线程，日志多时处理LogEvent延迟大)
来完成，如下图所示，在handler填充{}对象时，log的线程可能已经把该对象改变内容了。

在这里插入图片描述

因此，WEBAPP打印日志时，传入的对象应为"不可变对象"：

要么类似String这种类型（String.valueOf(…)或转JSON）
要么确保对象后续不再变更。

org.apache.logging.log4j.message.Message的注释说明也应证了这一点：

Note: Message objects should not be considered to be thread safe nor should they be assumed to be safely reusable even
on the same thread. The logging system may provide information to the Message objects and the Messages might be queued
for asynchronous delivery. Thus, any modifications to a Message object by an application should by avoided after
the Message has been passed as a parameter on a Logger method.

或者自定义LogEventFacotry，在createEvent时同步填充{}：

创建自定义LogEventFacotry

package com.example.demologging;

import java.lang.reflect.Field;
import java.util.List;
import org.apache.logging.log4j.Level;
import org.apache.logging.log4j.Marker;
import org.apache.logging.log4j.core.LogEvent;
import org.apache.logging.log4j.core.config.Property;
import org.apache.logging.log4j.core.impl.Log4jLogEvent;
import org.apache.logging.log4j.core.impl.LogEventFactory;
import org.apache.logging.log4j.core.layout.AbstractStringLayout;
import org.apache.logging.log4j.message.Message;
import org.apache.logging.log4j.message.ParameterizedMessage;
import org.apache.logging.log4j.util.PropertiesUtil;

/**
 * {@link AbstractStringLayout}
 * @author: baotingyu
 * @date: 2023/11/19
 **/
public class SyncFormatLog4jLogEventFactory implements LogEventFactory {
    protected static final int MAX_STRING_BUILDER_SIZE = Math.max(1024, size("log4j.layoutStringBuilder.maxSize", 2048));
    private static final ThreadLocal<StringBuilder> threadLocal = new ThreadLocal<>();

    private static int size(String property, int defaultValue) {
        return PropertiesUtil.getProperties().getIntegerProperty(property, defaultValue);
    }
    protected static StringBuilder getStringBuilder() {
        StringBuilder result = threadLocal.get();
        if (result == null) {
            result = new StringBuilder(1024);
            threadLocal.set(result);
        }

        trimToMaxSize(result);
        result.setLength(0);
        return result;
    }

    protected static void trimToMaxSize(StringBuilder stringBuilder) {
        if (stringBuilder.length() > MAX_STRING_BUILDER_SIZE) {
            stringBuilder.setLength(MAX_STRING_BUILDER_SIZE);
            stringBuilder.trimToSize();
        }

    }
    public LogEvent createEvent(String loggerName, Marker marker, String fqcn, Level level, Message data, List<Property> properties, Throwable t) {
        if(data instanceof ParameterizedMessage){
            try {
                // ThreadLocal重用StringBuilder
                StringBuilder builder = getStringBuilder();
                ((ParameterizedMessage) data).formatTo(builder);
                Field formattedMessage = data.getClass().getDeclaredField("formattedMessage");
                formattedMessage.setAccessible(true);
                formattedMessage.set(data,builder.toString());
            } catch (NoSuchFieldException | IllegalAccessException e) {
                System.err.println(this.getClass().getSimpleName()+"fail to createEvent:"+e.getMessage());
            }

        }
        return new Log4jLogEvent(loggerName, marker, fqcn, level, data, properties, t);
    }
}

指定自定义LogEventFacotry：在resources目录下创建log4j2.component.properties
文件（log4j2按文件名称加载）,内容为Log4jLogEventFactory=com.example.demologging.SyncFormatLogEventFactory

Java日志体系

顺便记录一下Java日志体系。

最初，Java并没有日志模块，都是通过System.out或System.err输出。1996年，Ceki Gülcü 主导编写了 Log4j
日志框架；2002年，Java官方推出了一个日志模块JUL(Java Util Logging)
，但是这时候Log4j已经成了事实日志框架，用的人更多；Apache在日志框架上抽象了一套标准，即一套日志门面 JCL (Jakarta Commons Logging)，JCL
日志门面可以兼容Log4j日志实现和JUL日志实现；但是JCL问题很多，Ceki
Gülcü再次发功，另写了一套日志门面Slf4j(Simple Logging Facade for Java)，但是这个协议如何兼容之前的Log4j和JUL
呢？通过桥接包做适配，那之前用JCL门面的怎么用Slf4j门面呢？通过桥接包做适配；接入日志实现还得加桥接包，太麻烦，不如自己搞个新的日志实现，于是Ceki
Gülcü又发功了，写了日志实现 Logback，直接接入Slf4j，且针对之前的Log4j进行了改进；Apache看Logback
改进很多，也“借鉴”Logback开发了新的日志实现 Log4j2，更甚者的Log4j2也搞了分离的设计，分化成log4j-api
和log4j-core，log4j-api也是日志门面，log4j-core才是日志实现，包名没有2，我真服了。

在这里插入图片描述

以上，我们在选择日志时，可以引入多个日志门面但只能引入一个日志实现。代码中打日志都用日志门面的api打印，而日志配置文件根据你的日志实现不同而不同。

桥接包实现主要分为两部分（以log4j-slf4-impl为例）

LoggerFactory: org.slf4j.ILoggerFactory 生成 Log4j2的 org.apache.logging.log4j.Logger
Logger: org.slf4j.Logger 桥接到 org.apache.logging.log4j.Logger

桥接类分别为：

LoggerFactory: log4j-slf4-impl包中的org.apache.logging.slf4j.Log4jLoggerFactory ，该工厂直接返回 log4j-slf4-impl
的org.apache.logging.slf4j.Log4jLogger
Logger: log4j-slf4-impl包中的org.apache.logging.slf4j.Log4jLogger

org.apache.logging.log4j.Logger，使用组合的方式在字段中组合了Log4j2的org.apache.logging.log4j.spi.ExtendedLogger
，很简单的实现。

而org.apache.logging.slf4j.Log4jLoggerFactory作为桥接类，就有些技巧了，其UML图如下：

在这里插入图片描述