Slf4j.MDC源码分析：以及利用MDC和AOP进行日志追踪

- 日理万妓 2022-05-14 14:40 664阅读 0赞

在 Java 开发中，日志的打印输出是必不可少的，`Slf4j + LogBack` 的组合是最通用的方式。但是，在分布式系统中，各种无关日志穿行其中，导致我们可能无法直接定位整个操作流程。因此，我们可能需要对一个用户的操作流程进行归类标记，既在其日志信息上添加一个唯一标识，比如使用线程+时间戳，或者用户身份标识等；从大量日志信息中grep出某个用户的操作流程。

## MDC ( Mapped Diagnostic Contexts ) ##

*  顾名思义，其目的是为了便于我们诊断线上问题而出现的方法工具类。虽然，Slf4j 是用来适配其他的日志具体实现包的，但是针对 MDC功能，目前只有logback 以及 log4j 支持。
 *  MDC 主要用于保存上下文，区分不同的请求来源。
 *  MDC 管理是按线程划分，并且子线程会自动继承母线程的上下文。

#### MDC使用方式： ####

一般，我们在代码中，只需要将指定的值`put`到线程上下文的Map中，然后，在对应的地方使用 `get`方法获取对应的值。此外，对于一些线程池使用的应用场景，可能我们在最后使用结束时，需要调用`clear`方法来清洗将要丢弃的数据。

## MDC简单使用案例 ##

Tip:此处先举例一个简单的案例，待到对MDC远离分析完毕，再来一个项目实战的案例。

1、在MDC中添加标识：

public class LogTest { 
        private static final Logger logger = LoggerFactory.getLogger(LogTest.class);
     
        public static void main(String[] args) { 
     
            MDC.put("mdc_key", "0000000000001");
            logger.info("这是一条测试日志。");
        }
     
    }

2、在logback.xml中配置日志格式：  
（关键点在于：traceId:\[%X\{mdc\_trace\_id\}\]）

<?xml version="1.0" encoding="UTF-8"?>
    <configuration>
        
        .....
     
        <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
            <encoder>
                <pattern>[%d{yy-MM-dd.HH:mm:ss.SSS}]  - traceId:[%X{mdc_key}] - %m%n</pattern>
                <charset>UTF-8</charset>
            </encoder>
        </appender>
    </configuration>

3、输出结果：

[18-10-26.10:43:00.281]  - traceId:[0000000000001] - 这是一条测试日志。

--------------------

## MDC源码探索 ##

MDC 的功能实现很简单，就是在线程上下文中，维护一个 `Map<String,String>` 属性来支持日志输出的时候，当我们在配置文件`logback.xml` 中配置了`%X{key}`，则后台日志打印出对应的 `key` 的值。

其实对于MDC，可以简单将其理解为一个线程级的容器。对于标识的操作其实也很简单，大部分就是`put、get和clear`。

先来看看 `org.slf4j.MDC`

//
    // Source code recreated from a .class file by IntelliJ IDEA
    // (powered by Fernflower decompiler)
    //
    
    package org.slf4j;
    
    import java.io.Closeable;
    import java.util.Map;
    import org.slf4j.helpers.NOPMDCAdapter;
    import org.slf4j.helpers.Util;
    import org.slf4j.impl.StaticMDCBinder;
    import org.slf4j.spi.MDCAdapter;
    
    public class MDC { 
        
        static MDCAdapter mdcAdapter;
    
        除了put\get\remove\clear外，其他方法省略....
    
        public static void put(String key, String val) throws IllegalArgumentException { 
            if (key == null) { 
                throw new IllegalArgumentException("key parameter cannot be null");
            } else if (mdcAdapter == null) { 
                throw new IllegalStateException("MDCAdapter cannot be null. See also http://www.slf4j.org/codes.html#null_MDCA");
            } else { 
                mdcAdapter.put(key, val);
            }
        }
    
    
        public static String get(String key) throws IllegalArgumentException { 
            if (key == null) { 
                throw new IllegalArgumentException("key parameter cannot be null");
            } else if (mdcAdapter == null) { 
                throw new IllegalStateException("MDCAdapter cannot be null. See also http://www.slf4j.org/codes.html#null_MDCA");
            } else { 
                return mdcAdapter.get(key);
            }
        }
    
        public static void remove(String key) throws IllegalArgumentException { 
            if (key == null) { 
                throw new IllegalArgumentException("key parameter cannot be null");
            } else if (mdcAdapter == null) { 
                throw new IllegalStateException("MDCAdapter cannot be null. See also http://www.slf4j.org/codes.html#null_MDCA");
            } else { 
                mdcAdapter.remove(key);
            }
        }
    
        public static void clear() { 
            if (mdcAdapter == null) { 
                throw new IllegalStateException("MDCAdapter cannot be null. See also http://www.slf4j.org/codes.html#null_MDCA");
            } else { 
                mdcAdapter.clear();
            }
        }
    
    
        static { 
            try { 
                mdcAdapter = StaticMDCBinder.SINGLETON.getMDCA();
            } catch (NoClassDefFoundError var2) { 
                mdcAdapter = new NOPMDCAdapter();
                String msg = var2.getMessage();
                if (msg == null || msg.indexOf("StaticMDCBinder") == -1) { 
                    throw var2;
                }
    
                Util.report("Failed to load class \"org.slf4j.impl.StaticMDCBinder\".");
                Util.report("Defaulting to no-operation MDCAdapter implementation.");
                Util.report("See http://www.slf4j.org/codes.html#no_static_mdc_binder for further details.");
            } catch (Exception var3) { 
                Util.report("MDC binding unsuccessful.", var3);
            }
    
        }
    
    }

观察上面的方法，各个方法都是在对 `mdcAdapter`变量进行操作。

mdcAdapter.put(key, val);
     mdcAdapter.get(key);
     mdcAdapter.remove(key);
     mdcAdapter.clear();

查看`mdcAdapter`变量的初始化过程：

mdcAdapter = StaticMDCBinder.SINGLETON.getMDCA();

查看：

StaticMDCBinder.java

public class StaticMDCBinder { 
        public static final StaticMDCBinder SINGLETON = new StaticMDCBinder();
    
        private StaticMDCBinder() { 
        }
    
        public MDCAdapter getMDCA() { 
            return new LogbackMDCAdapter();
        }
    
        public String getMDCAdapterClassStr() { 
            return LogbackMDCAdapter.class.getName();
        }
    }

这样，就能找到我们容器真正的宿主`mdcAdapter`其实是类：`LogbackMDCAdapter`，查看其源码：

//
    // Source code recreated from a .class file by IntelliJ IDEA
    // (powered by Fernflower decompiler)
    //
    
    package ch.qos.logback.classic.util;
    
    import java.util.Collections;
    import java.util.HashMap;
    import java.util.Map;
    import java.util.Set;
    import org.slf4j.spi.MDCAdapter;
    
    public final class LogbackMDCAdapter implements MDCAdapter { 
        final InheritableThreadLocal<Map<String, String>> copyOnInheritThreadLocal = new InheritableThreadLocal();
        private static final int WRITE_OPERATION = 1;
        private static final int READ_OPERATION = 2;
        final ThreadLocal<Integer> lastOperation = new ThreadLocal();
    
    
        public void put(String key, String val) throws IllegalArgumentException { 
            if (key == null) { 
                throw new IllegalArgumentException("key cannot be null");
            } else { 
                Map<String, String> oldMap = (Map)this.copyOnInheritThreadLocal.get();
                Integer lastOp = this.getAndSetLastOperation(1);
                if (!this.wasLastOpReadOrNull(lastOp) && oldMap != null) { 
                    oldMap.put(key, val);
                } else { 
                    Map<String, String> newMap = this.duplicateAndInsertNewMap(oldMap);
                    newMap.put(key, val);
                }
    
            }
        }
    
        public void remove(String key) { 
            if (key != null) { 
                Map<String, String> oldMap = (Map)this.copyOnInheritThreadLocal.get();
                if (oldMap != null) { 
                    Integer lastOp = this.getAndSetLastOperation(1);
                    if (this.wasLastOpReadOrNull(lastOp)) { 
                        Map<String, String> newMap = this.duplicateAndInsertNewMap(oldMap);
                        newMap.remove(key);
                    } else { 
                        oldMap.remove(key);
                    }
    
                }
            }
        }
    
        public void clear() { 
            this.lastOperation.set(1);
            this.copyOnInheritThreadLocal.remove();
        }
    
        public String get(String key) { 
            Map<String, String> map = this.getPropertyMap();
            return map != null && key != null ? (String)map.get(key) : null;
        }
    
       
    
       
    }

从上面的源码可以得知，之所以能保证不同线程都存在自己的标识，原因在于`ThreadLocal`。  
在 `ThreadLocal` 中，每个线程都拥有了自己独立的一个变量，线程间不存在共享竞争发生，并且它们也能最大限度的由CPU调度，并发执行。  
对于`ThreadLocal`的介绍，可以参考我的另一篇博客[《深入理解ThreadLocal的原理和内存泄漏问题》][ThreadLocal]，此处不再赘述。  
但是，`ThreadLocal`有一个问题，就是它只保证在同一个线程间共享变量，也就是说如果这个线程起了一个新线程，那么新线程是不会得到父线程的变量信息的。  
因此，为了保证子线程可以拥有父线程的某些变量视图，JDK提供了一个数据结构，`InheritableThreadLocal`。其源码如下：

public class InheritableThreadLocal<T> extends ThreadLocal<T> { 
        /** * 根据创建子线程时父线程的值，计算该可继承线程本地变量的子线程的初始值。 *在启动子之前，从父线程中调用此方法。 */
        protected T childValue(T parentValue) { 
            return parentValue;
        }
    
        /** * Get the map associated with a ThreadLocal. * * @param t the current thread */
        ThreadLocalMap getMap(Thread t) { 
           return t.inheritableThreadLocals;
        }
    
        /** * Create the map associated with a ThreadLocal. * * @param t the current thread * @param firstValue value for the initial entry of the table. */
        void createMap(Thread t, T firstValue) { 
            t.inheritableThreadLocals = new ThreadLocalMap(this, firstValue);
        }
    }

MDC存放变量的来龙去脉基本从上面源码都可以理清楚了，那么对于logback.xml中是如何获取到MDC的变量呢？

%X{mdc_key}

同样，`logback.xml`配置文件支持了多种格式的日志输出，比如`%highlight、%d等等`，这些标志，在`PatternLayout.java`中维护。

PatternLayout.java:

public class PatternLayout extends PatternLayoutBase<ILoggingEvent> { 
        public static final Map<String, String> defaultConverterMap = new HashMap();
        public static final String HEADER_PREFIX = "#logback.classic pattern: ";
    
        public PatternLayout() { 
            this.postCompileProcessor = new EnsureExceptionHandling();
        }
    
        public Map<String, String> getDefaultConverterMap() { 
            return defaultConverterMap;
        }
    
        public String doLayout(ILoggingEvent event) { 
            return !this.isStarted() ? "" : this.writeLoopOnConverters(event);
        }
    
        protected String getPresentationHeaderPrefix() { 
            return "#logback.classic pattern: ";
        }
    
        static { 
            defaultConverterMap.putAll(Parser.DEFAULT_COMPOSITE_CONVERTER_MAP);
            defaultConverterMap.put("d", DateConverter.class.getName());
            defaultConverterMap.put("date", DateConverter.class.getName());
            defaultConverterMap.put("r", RelativeTimeConverter.class.getName());
            defaultConverterMap.put("relative", RelativeTimeConverter.class.getName());
            defaultConverterMap.put("level", LevelConverter.class.getName());
            defaultConverterMap.put("le", LevelConverter.class.getName());
            defaultConverterMap.put("p", LevelConverter.class.getName());
            defaultConverterMap.put("t", ThreadConverter.class.getName());
            defaultConverterMap.put("thread", ThreadConverter.class.getName());
            defaultConverterMap.put("lo", LoggerConverter.class.getName());
            defaultConverterMap.put("logger", LoggerConverter.class.getName());
            defaultConverterMap.put("c", LoggerConverter.class.getName());
            defaultConverterMap.put("m", MessageConverter.class.getName());
            defaultConverterMap.put("msg", MessageConverter.class.getName());
            defaultConverterMap.put("message", MessageConverter.class.getName());
            defaultConverterMap.put("C", ClassOfCallerConverter.class.getName());
            defaultConverterMap.put("class", ClassOfCallerConverter.class.getName());
            defaultConverterMap.put("M", MethodOfCallerConverter.class.getName());
            defaultConverterMap.put("method", MethodOfCallerConverter.class.getName());
            defaultConverterMap.put("L", LineOfCallerConverter.class.getName());
            defaultConverterMap.put("line", LineOfCallerConverter.class.getName());
            defaultConverterMap.put("F", FileOfCallerConverter.class.getName());
            defaultConverterMap.put("file", FileOfCallerConverter.class.getName());
            defaultConverterMap.put("X", MDCConverter.class.getName());
            defaultConverterMap.put("mdc", MDCConverter.class.getName());
            defaultConverterMap.put("ex", ThrowableProxyConverter.class.getName());
            defaultConverterMap.put("exception", ThrowableProxyConverter.class.getName());
            defaultConverterMap.put("rEx", RootCauseFirstThrowableProxyConverter.class.getName());
            defaultConverterMap.put("rootException", RootCauseFirstThrowableProxyConverter.class.getName());
            defaultConverterMap.put("throwable", ThrowableProxyConverter.class.getName());
            defaultConverterMap.put("xEx", ExtendedThrowableProxyConverter.class.getName());
            defaultConverterMap.put("xException", ExtendedThrowableProxyConverter.class.getName());
            defaultConverterMap.put("xThrowable", ExtendedThrowableProxyConverter.class.getName());
            defaultConverterMap.put("nopex", NopThrowableInformationConverter.class.getName());
            defaultConverterMap.put("nopexception", NopThrowableInformationConverter.class.getName());
            defaultConverterMap.put("cn", ContextNameConverter.class.getName());
            defaultConverterMap.put("contextName", ContextNameConverter.class.getName());
            defaultConverterMap.put("caller", CallerDataConverter.class.getName());
            defaultConverterMap.put("marker", MarkerConverter.class.getName());
            defaultConverterMap.put("property", PropertyConverter.class.getName());
            defaultConverterMap.put("n", LineSeparatorConverter.class.getName());
            defaultConverterMap.put("black", BlackCompositeConverter.class.getName());
            defaultConverterMap.put("red", RedCompositeConverter.class.getName());
            defaultConverterMap.put("green", GreenCompositeConverter.class.getName());
            defaultConverterMap.put("yellow", YellowCompositeConverter.class.getName());
            defaultConverterMap.put("blue", BlueCompositeConverter.class.getName());
            defaultConverterMap.put("magenta", MagentaCompositeConverter.class.getName());
            defaultConverterMap.put("cyan", CyanCompositeConverter.class.getName());
            defaultConverterMap.put("white", WhiteCompositeConverter.class.getName());
            defaultConverterMap.put("gray", GrayCompositeConverter.class.getName());
            defaultConverterMap.put("boldRed", BoldRedCompositeConverter.class.getName());
            defaultConverterMap.put("boldGreen", BoldGreenCompositeConverter.class.getName());
            defaultConverterMap.put("boldYellow", BoldYellowCompositeConverter.class.getName());
            defaultConverterMap.put("boldBlue", BoldBlueCompositeConverter.class.getName());
            defaultConverterMap.put("boldMagenta", BoldMagentaCompositeConverter.class.getName());
            defaultConverterMap.put("boldCyan", BoldCyanCompositeConverter.class.getName());
            defaultConverterMap.put("boldWhite", BoldWhiteCompositeConverter.class.getName());
            defaultConverterMap.put("highlight", HighlightingCompositeConverter.class.getName());
            defaultConverterMap.put("lsn", LocalSequenceNumberConverter.class.getName());
        }
    }

上面的`defaultConverterMap.put("X", MDCConverter.class.getName());`就可以体现出我们logback.xml配置这样写的原因。

MDC使用原理探究到这就结束了。

**还有一点需要阐述一下**：对于涉及到ThreadLocal相关使用的接口，都需要去考虑在使用完上下文对象时，清除掉对应的数据，以避免内存泄露问题。所以MDC.clear()非常重要。

## 实战项目举例： ##

简述：实战时可以借助`springAOP`对各个业务入口进行代理，然后在执行业务代码前，先往`MDC`添加一个唯一标识，业务代码执行后再执行`clear`；

1、首先自定义一个注解：

import java.lang.annotation.*;
    
    @Documented
    @Target(value= ElementType.METHOD)
    @Retention(RetentionPolicy.RUNTIME)
    @Inherited
    public @interface TraceID { 
    
    }

2、编写AOP切面：

@Aspect
    @Component
    public class TraceIDAscept { 
    
    
        public static Logger logger = LoggerFactory.getLogger(TraceIDAscept.class);
    
        //针对带有注解 @TraceIDd 的方法 
        @Around("@annotation(TraceID)&&@annotation(TraceID)")
        public Object process(ProceedingJoinPoint joinPoint , TraceID traceID) { 
            try { 
                MDC.put("mdc_key", UUID.randomUUID().toString());
                Object obj = joinPoint.proceed() ;
                return obj;
            } catch (Throwable e) { 
                logger.error("MDC标识添加异常 ", e);
                throw new RuntimeException("MDC标识添加异常");
            } finally { 
                MDC.clear();
            }
        }
    
    }

3、配置logback.xml：

<appender name="console" class="ch.qos.logback.core.ConsoleAppender">
            <encoder charset="UTF-8">
                <pattern>[%d{yyyy-MM-dd HH:mm:ss} %highlight(%-5p) %logger.%M\(%F:%L\)] %X{mdc_key} %msg%n</pattern>
            </encoder>
        </appender>
        <root level="INFO">
            <appender-ref ref="console" />
        </root>

4、spring配置文件开启切面代理：

<aop:aspectj-autoproxy proxy-target-class="true"/>

5、到所需的服务入口添加注解 @TraceID ，就大功告成了。

@Controller
    @RequestMapping(value = "/log")
    public class LogController { 
    
        private static final Logger logger = LoggerFactory.getLogger();
    
        @RequestMapping("mdc")
        @TraceID
        public String testMdc(){ 
            
            logger.info("test");
            logger.info("trace Id");
            return null;
    
        }
    
    }

## 大功告成！ ##

[ThreadLocal]: https://blog.csdn.net/qq_33404395/article/details/82356344