log4j2中的MDC分析

2021/07/30 1266点热度 0人点赞 0条评论

背景

我们项目中使用的log4j2日志框架,在日志输出的时候,我们有个需求,需要将我们全局唯一的流程流水id打印到log4j的日志文件中。以前一直在用log4j2,也没有好好的了解下其中的原理,这次探索下。

SLF4j

我们都知道,slf4j是门面,log4j2是一种具体的实现。我们先看官网 slf4j的官网SLF4J 全称 Simple Logging Facade for Java 。主要是给java日志访问提供了一个标准,规范的API接口。具体实现由不同的日志框架实现,比如log4j2,logback。

我们看下官网上的实现:

通过上图,我们可以看到应用在使用SLF4j的时候,可以随意切换日志实现与输出。这也是阿里规约里为什么强调日志打印一定要用SLF4j,剥离了技术实现,替换日志框架不用再改代码。

源码追踪

依赖包

        <dependency>
            <groupId>org.apache.logging.log4j</groupId>
            <artifactId>log4j-slf4j-impl</artifactId>
        </dependency>
        <!-- log4j2 无锁并发 -->
        <dependency>
            <groupId>com.lmax</groupId>
            <artifactId>disruptor</artifactId>
            <version>${disruptor.version}</version>
        </dependency>
        <dependency>
            <groupId>ch.qos.logback</groupId>
            <artifactId>logback-classic</artifactId>
            <version>1.2.5</version>
        </dependency>

log4j.xml 通过pattern的表达式将MDC中的内容写入到日志

<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE xml>
<!-- Log4j 2.DSConfig 配置文件。每60秒自动检查和应用配置文件的更新; -->
<Configuration status="warn" monitorInterval="60" strict="true">
    <Properties>
        <Property name="PROJECT_NAME">other</Property>
        <Property name="LOG_HOME">logs/${PROJECT_NAME}</Property>
        <Property name="COMMON_LEVEL">info</Property>
        //重点在这里
        <Property name="LOG_PATTERN">%d{yyyy-MM-dd HH:mm:ss,SSS} [%level]-[Thread:%t]-[%logger{36}]-lsh:%X{lsh}-feignId:%X{feignId}-token:%X{token} - %msg%n</Property>
        <Property name="LEVEL_ERROR">info</Property>
    </Properties>
    <Appenders>
        <!-- 输出到控制台-->
        <Console name="console" target="SYSTEM_OUT" follow="true">
            <PatternLayout charset="utf-8" pattern="${LOG_PATTERN}" />
        </Console>
        <RollingFile name="debugAppender" fileName="${LOG_HOME}/debug.log"
            filePattern="${LOG_HOME}/$${date:yyyy-MM}/debug-%d{MM-dd}.%i.log">
            <filters>
                <ThresholdFilter level="error" onMatch="DENY" onMismatch="NEUTRAL" />
                <ThresholdFilter level="info" onMatch="DENY" onMismatch="NEUTRAL" />
                <ThresholdFilter level="warn" onMatch="DENY" onMismatch="NEUTRAL" />
                <ThresholdFilter level="debug" onMatch="ACCEPT" onMismatch="DENY" />
            </filters>
            <PatternLayout charset="UTF-8">
                <pattern>${LOG_PATTERN}</pattern>
            </PatternLayout>
            <Policies>
                <OnStartupTriggeringPolicy />
                <TimeBasedTriggeringPolicy />
                <!-- 封存文件的大小 -->
                <SizeBasedTriggeringPolicy size="100 MB" />
            </Policies>
            <!-- 封存文件的序号的最大值。(超过最大值时,将有文件被删除)默认7 -->
            <DefaultRolloverStrategy max="500">
                <Delete basePath="${LOG_HOME}" maxDepth="500">
                    <IfFileName glob="*/*/debug-*.log">
                        <IfLastModified age="15d" />
                    </IfFileName>
                </Delete>
            </DefaultRolloverStrategy>
        </RollingFile>
        <RollingFile name="infoAppender" fileName="${LOG_HOME}/info.log"
            filePattern="${LOG_HOME}/$${date:yyyy-MM}/info-%d{MM-dd}.%i.log">
            <filters>
                <ThresholdFilter level="error" onMatch="DENY" onMismatch="NEUTRAL" />
                <ThresholdFilter level="warn" onMatch="DENY" onMismatch="NEUTRAL" />
                <ThresholdFilter level="info" onMatch="ACCEPT" onMismatch="DENY" />
            </filters>
            <PatternLayout charset="UTF-8">
                <pattern>${LOG_PATTERN}</pattern>
            </PatternLayout>
            <Policies>
                <OnStartupTriggeringPolicy />
                <TimeBasedTriggeringPolicy />
                <SizeBasedTriggeringPolicy size="100 MB" />
            </Policies>
            <DefaultRolloverStrategy max="500">
                <Delete basePath="${LOG_HOME}" maxDepth="500">
                    <IfFileName glob="*/*/info-*.log">
                        <IfLastModified age="15d" />
                    </IfFileName>
                </Delete>
            </DefaultRolloverStrategy>
        </RollingFile>
        <RollingFile name="warnAppender" fileName="${LOG_HOME}/warn.log"
            filePattern="${LOG_HOME}/$${date:yyyy-MM}/warn-%d{MM-dd}.%i.log">
            <filters>
                <ThresholdFilter level="error" onMatch="DENY" onMismatch="NEUTRAL" />
                <ThresholdFilter level="warn" onMatch="ACCEPT" onMismatch="DENY" />
            </filters>
            <PatternLayout charset="UTF-8">
                <pattern>${LOG_PATTERN}</pattern>
            </PatternLayout>
            <Policies>
                <OnStartupTriggeringPolicy />
                <TimeBasedTriggeringPolicy />
                <SizeBasedTriggeringPolicy size="100 MB" />
            </Policies>
            <DefaultRolloverStrategy max="500">
                <Delete basePath="${LOG_HOME}" maxDepth="500">
                    <IfFileName glob="*/*/warn-*.log">
                        <IfLastModified age="15d" />
                    </IfFileName>
                </Delete>
            </DefaultRolloverStrategy>
        </RollingFile>
        <RollingFile name="errorAppender" fileName="${LOG_HOME}/error.log"
            filePattern="${LOG_HOME}/$${date:yyyy-MM}/error-%d{MM-dd}.%i.log">
            <filters>
                <ThresholdFilter level="error" onMatch="ACCEPT" onMismatch="DENY" />
            </filters>
            <PatternLayout charset="UTF-8">
                <pattern>${LOG_PATTERN}</pattern>
            </PatternLayout>
            <Policies>
                <OnStartupTriggeringPolicy />
                <TimeBasedTriggeringPolicy />
                <SizeBasedTriggeringPolicy size="100 MB" />
            </Policies>
            <DefaultRolloverStrategy max="500">
                <Delete basePath="${LOG_HOME}" maxDepth="500">
                    <IfFileName glob="*/*/error-*.log">
                        <IfLastModified age="15d" />
                    </IfFileName>
                </Delete>
            </DefaultRolloverStrategy>
        </RollingFile>
    </Appenders>
    <Loggers>
        <AsyncRoot level="${COMMON_LEVEL}" includeLocation="true">
             <AppenderRef ref="console" />
            <AppenderRef ref="debugAppender" />
            <AppenderRef ref="infoAppender" />
            <AppenderRef ref="warnAppender" />
            <AppenderRef ref="errorAppender" />
<!--             <appender-ref ref="KafkaAsyncAppender" /> -->
        </AsyncRoot>
        <!--myibatis log configure -->
        <logger name="org.apache.ibatis" level="TRACE" additivity="false">
        <AppenderRef ref="debugAppender" />
            <AppenderRef ref="infoAppender" />
            <AppenderRef ref="warnAppender" />
            <AppenderRef ref="errorAppender" />
        </logger>
        <logger name="java.sql.Connection" level="DEBUG" additivity="false">
        <AppenderRef ref="debugAppender" />
            <AppenderRef ref="infoAppender" />
            <AppenderRef ref="warnAppender" />
            <AppenderRef ref="errorAppender" />
        </logger>
        <logger name="java.sql.Statement" level="DEBUG" additivity="false">
        <AppenderRef ref="debugAppender" />
            <AppenderRef ref="infoAppender" />
            <AppenderRef ref="warnAppender" />
            <AppenderRef ref="errorAppender" />
        </logger>
        <logger name="java.sql.PreparedStatement" level="DEBUG" additivity="false">
        <AppenderRef ref="debugAppender" />
            <AppenderRef ref="infoAppender" />
            <AppenderRef ref="warnAppender" />
            <AppenderRef ref="errorAppender" />
        </logger>

        <logger name="org.springframework.jdbc" level="DEBUG" additivity="false">
        <AppenderRef ref="debugAppender" />
            <AppenderRef ref="infoAppender" />
            <AppenderRef ref="warnAppender" />
            <AppenderRef ref="errorAppender" />
        </logger>
        <logger name="com.alibaba.dubbo" level="ERROR" additivity="false">
        <AppenderRef ref="debugAppender" />
            <AppenderRef ref="infoAppender" />
            <AppenderRef ref="warnAppender" />
            <AppenderRef ref="errorAppender" />
            <appender-ref ref="KafkaAsyncAppender" />
        </logger>
        <logger name="org.apache.zookeeper" level="ERROR" additivity="false">
        <AppenderRef ref="debugAppender" />
            <AppenderRef ref="infoAppender" />
            <AppenderRef ref="warnAppender" />
            <AppenderRef ref="errorAppender" />
<!--         <appender-ref ref="KafkaAsyncAppender" />-->
        </logger>
        <logger name="com.alibaba.rocketmq" level="ERROR" additivity="false">
        <AppenderRef ref="debugAppender" />
            <AppenderRef ref="infoAppender" />
            <AppenderRef ref="warnAppender" />
            <AppenderRef ref="errorAppender" />
        </logger>

        <!--myibatis log configure -->
        <logger name="org.apache.ibatis" level="TRACE"/>
        <logger name="java.sql.Connection" level="DEBUG"/>
        <logger name="java.sql.Statement" level="DEBUG"/>
        <logger name="java.sql.PreparedStatement" level="DEBUG"/>
        <logger name="com.onecard.loan.mapper" level="DEBUG"/>
        <logger name="com.onecard" level="DEBUG"/>
        <logger name="org.springframework.jdbc" level="DEBUG"/>
        <logger name="com.alibaba.dubbo" level="ERROR"/>
        <logger name="org.apache.zookeeper" level="ERROR"/>
        <logger name="com.alibaba.rocketmq" level="ERROR"/>
    </Loggers>
</Configuration>

public class Log4jMdcTest {
private Logger logger = LoggerFactory.getLogger(Log4jMdcTest.class);

@Test
public void test(){
    MDC.put("lsh", UUID.randomUUID().toString());
    logger.info("test info level ");
}

}


我们通过LoggerFactory.getLogger,一步步的追踪

LoggerFactory.findPossibleStaticLoggerBinderPathSet(){
ClassLoader loggerFactoryClassLoader = LoggerFactory.class.getClassLoader();
Enumeration paths;
if (loggerFactoryClassLoader == null) {
paths = ClassLoader.getSystemResources(STATIC_LOGGER_BINDER_PATH);
} else {
paths = loggerFactoryClassLoader.getResources(STATIC_LOGGER_BINDER_PATH);
}
while (paths.hasMoreElements()) {
URL path = paths.nextElement();
staticLoggerBinderPathSet.add(path);
}

}


我们发现会通过classloader找到所有的org.slf4j.impl.StaticLoggerBinder,看下图。StaticLoggerBinder 是所有实现slf4j接口的日志框架都实现的,且路径固定。

![](https://mmbiz.qpic.cn/mmbiz_png/AaKTtPGkoWKKRDEBLMn1PWr76icSEBJf732mWWPaqsSG0gZnqDibLmaj7qQW9JAQBmyWlVAR86uC1WE9Z7lZ4Ejg/640?wx_fmt=png)

再看日志输出,虽然引入了两个实现jar,但是最终只绑定了一个,按照pom中的引入顺序绑定的

SLF4J: Class path contains multiple SLF4J bindings.
SLF4J: Found binding in [jar:file:/Users/yxk/javaServer/jar/repository/org/apache/logging/log4j/log4j-slf4j-impl/2.13.3/log4j-slf4j-impl-2.13.3.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: Found binding in [jar:file:/Users/yxk/javaServer/jar/repository/ch/qos/logback/logback-classic/1.2.5/logback-classic-1.2.5.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: See http://www.slf4j.org/codes.html#multiple_bindings for an explanation.
SLF4J: Actual binding is of type [org.apache.logging.slf4j.Log4jLoggerFactory]
2021-07-30 09:25:19,210 [INFO]-[Thread:main]-[com.yxkong.other.Log4jMdcTest]-lsh:8dba4b78-d967-4a2f-ade9-8ec7769ecda6-feignId:-token: - test info level


我们继续追踪StaticLoggerBinder,这里是一个单例,具体的实现是Log4jLoggerFactory

public final class StaticLoggerBinder implements LoggerFactoryBinder {
//单例
private static final StaticLoggerBinder SINGLETON = new StaticLoggerBinder();
private StaticLoggerBinder() {
loggerFactory = new Log4jLoggerFactory();
}
}


我们再看下MDC

public class MDC {
private static MDCAdapter bwCompatibleGetMDCAdapterFromBinder() throws NoClassDefFoundError {
try {
//因为log4j2中没有getSingleton()方法,所以一定走catch
return StaticMDCBinder.getSingleton().getMDCA();
} catch (NoSuchMethodError nsme) {
// binding is probably a version of SLF4J older than 1.7.14
return StaticMDCBinder.SINGLETON.getMDCA();
}
}
static {
try {
mdcAdapter = bwCompatibleGetMDCAdapterFromBinder();
} catch (NoClassDefFoundError ncde) {
mdcAdapter = new NOPMDCAdapter();
}
}
}

public final class StaticMDCBinder {
public MDCAdapter getMDCA() {
return new Log4jMDCAdapter();
}
}

//最终发现实现在
public class Log4jMDCAdapter implements MDCAdapter {
public void put(final String key, final String val) {
ThreadContext.put(key, val);
}
}

//我们再看ThreadContext

public final class ThreadContext {
static {
init();
}
static void init() {
//默认true
useStack = !(managerProps.getBooleanProperty(DISABLE_STACK) || disableAll);
//默认true
boolean useMap = !(managerProps.getBooleanProperty(DISABLE_MAP) || disableAll);

    contextStack = new DefaultThreadContextStack(useStack);
    if (!useMap) {
        contextMap = new NoOpThreadContextMap();
    } else {
        contextMap = ThreadContextMapFactory.createThreadContextMap();
    }
}

}

我们再看下:
ThreadContextMapFactory.createThreadContextMap(){
if (result == null) {
result = createDefaultThreadContextMap();
}
return result;
}

private static ThreadContextMap createDefaultThreadContextMap() {
//最终走的是这里
return new CopyOnWriteSortedArrayThreadContextMap();
}
public CopyOnWriteSortedArrayThreadContextMap() {
this.localMap = createThreadLocalMap();
}

private ThreadLocal createThreadLocalMap() {
//在这里我们也能看到log4j2的MDC也是可以支持多线程的,只不过模式是ThreadLocal
if (inheritableMap) {
return new InheritableThreadLocal() {
@Override
protected StringMap childValue(final StringMap parentValue) {
if (parentValue == null) {
return null;
}
final StringMap stringMap = createStringMap(parentValue);
stringMap.freeze();
return stringMap;
}
};
}
// if not inheritable, return plain ThreadLocal with null as initial value
return new ThreadLocal<>();
}


到此,我们可以看到MDC底层用的是ThreadLocal。我可以通过设置环境变量isThreadContextMapInheritable=true开启支持多线程版本的InheritableThreadLocal

当然除了支持开启多线程版本的ThreadLocal,我们也可以重写ThreadPoolTaskExecutor中的submit拷贝主线程到子线程

public class MdcThreadPoolTaskExecutor extends ThreadPoolTaskExecutor {

private static final long serialVersionUID = 53094863482765933L;

private Logger logger = LoggerFactory.getLogger(MdcThreadPoolTaskExecutor.class);

private final static String LSH = "lsh";

@Override
public  Future submit(Callable task) {
    Map context = MDC.getCopyOfContextMap();
    logger.info("----MDC content:{}", context);
    return super.submit(() -> {
        // 将父线程的MDC内容传给子线程
        T result;
        if (MapUtils.isNotEmpty(context) && !Strings.isNullOrEmpty(context.get(LSH))) {
            MDC.setContextMap(context);
        } else {
            MDC.put(LSH, "lsh_" + StringUtils.randomUUIDSplit()); //为空设置新值
        }
        try {
            result = task.call();
        } finally {
            try {
                MDC.clear();
            } catch (Exception e2) {
                logger.warn("mdc clear exception.", e2);
            }
        }
        return result;
    });
}

}



*   MDC最终和业务线程绑定

*   使用ThreadLocal,生命周期随着业务线程结束而结束

*   可以通过设置环境变量isThreadContextMapInheritable=true开启支持多线程版本的ThreadLocal(logback默认InheritableThreadLocal)

今天分析就到这,后续分析一下log4j加载配置文件,以及以及变量如何输出。

参考:

 http://www.slf4j.org/manual.html

https://logging.apache.org/log4j/2.x/manual/layouts.html

如果觉得对你有帮助,请关注公众号:5ycode,后续会不断更新哦

![公众号图片](https://img-blog.csdnimg.cn/20210407102553361.jpg?x-oss-process=image/watermark,type_ZmFuZ3poZW5naGVpdGk,shadow_10,text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L2Y4MDQwNzUxNQ==,size_16,color_FFFFFF,t_70#pic_center)

yxkong

这个人很懒,什么都没留下