使用MDC增强日志记录

怼烎@ 2022-10-15 01:57 327阅读 0赞

### 文章目录 ###

*   *  （一）日志框架
     *   *  1. 日志框架介绍和选择
         *  2. 原理介绍
         *  3. SpringBoot日志框架
     *  （二）使用MDC增强日志记录
     *   *  1. 介绍
         *  2. 普通示例
         *  3. 在Log4j中使用MDC
         *  4. 在SLF4J/LogBack中使用MDC
         *  5. MDC和线程池

## （一）日志框架 ##

### 1. 日志框架介绍和选择 ###

![在这里插入图片描述][20210523104005212.png]  
日志门面：是日志实现的抽象层。

日志实现：具体的日志功能的实现

为什么不直接使用日志实现，而是又弄了一个叫日志门面的东西？

因为日志实现，可能会有一些代码的优化和改动，避免影响用户在项目中的使用，使用日志门面这些统一的接口，假设在实现层代码做了更改，用户在项目中使用日志而调用的接口等等都是不会受影响的。

推荐使用：SLF4j+logback组合

### 2. 原理介绍 ###

slf4j主要是为了给Java日志访问提供一个标准、规范的API框架，其主要意义在于提供接口，具体的实现可以交由其他日志框架，例如log4j和logback等。当然slf4j自己也提供了功能较为简单的实现，但是一般很少用到。对于一般的Java项目而言，日志框架会选择slf4j-api作为门面，配上具体的实现框架（log4j、logback等），中间使用桥接器完成桥接。

### 3. SpringBoot日志框架 ###

![在这里插入图片描述][watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L09jdG9wdXMyMQ_size_16_color_FFFFFF_t_70]  
SpringBoot默认使用SLF4j+logback组合

## （二）使用MDC增强日志记录 ##

### 1. 介绍 ###

Mapped Diagnostic Context（MDC）的基本思想是提供一种方法，用一些在日志记录实际发生的范围内不可用的信息来丰富日志消息，但这些信息确实有助于更好地跟踪程序的执行。

### 2. 普通示例 ###

让我们从一个例子开始。假设我们必须编写一个软件来转移资金。我们设置了一个传输类来表示一些基本信息：唯一的传输id和发送方的名称：

/** * 转账类 */
    @Data
    public class Transfer { 
        /** * 转账事务唯一标识 */
        private String transactionId;
        /** * 收款方 */
        private String sender;
        /** * 转账金额 */
        private BigDecimal amount;
    }

要执行传输，我们需要使用API支持的服务：下面提供一个抽象类TransferService ，其中transfer用于实现具体的转账操作，应用了模板方法设计模式，在转账前后分别调用了相关记录方法

/** * 转账服务 * @author zhangyu */
    public  abstract  class TransferService { 
        public boolean transfer(BigDecimal amount) { 
            beforeTransfer(amount);
            //调用第三方转账接口
            afterTransfer(amount,true);
            return true;
        }
    
        abstract protected void beforeTransfer(BigDecimal amount);
    
        abstract protected void afterTransfer(BigDecimal amount, boolean outcome);
    }

可以重写beforeTransfer（）和afterTransfer（）方法，以便在传输完成之前和之后运行自定义代码。  
我们将利用beforeTransfer（）和afterTransfer（）来记录有关传输的一些信息。  
让我们创建服务实现：

public class LogTransferService extends TransferService { 
        private Logger logger = Logger.getLogger(LogTransferService.class);
    
        @Override
        protected void beforeTransfer(BigDecimal amount) { 
            logger.info("Preparing to transfer " + amount + "$.");
        }
    
        @Override
        protected void afterTransfer(BigDecimal amount, boolean outcome) { 
            logger.info(
                    "Has transfer of " + amount + "$ completed successfully ? " + outcome + ".");
        }
    }

这里要注意的主要问题是，创建日志消息时，无法访问传输对象—只能访问金额，从而无法记录事务id或发送方。  
让我们设置通常的log4j.properties文件来登录控制台：

log4j.appender.consoleAppender=org.apache.log4j.ConsoleAppender
    log4j.appender.consoleAppender.layout=org.apache.log4j.PatternLayout
    log4j.appender.consoleAppender.layout.ConversionPattern=%-4r [%t] %5p %c %x - %m%n
    log4j.rootLogger = TRACE, consoleAppender

这里简单创建一个转账事务工厂类，生成测试数据

public class TransactionFactory { 
         private  final Random random=new Random();
        private final List<String>   senderList= Arrays.asList("Alice","Tom","Bob");
        public Transfer newInstance() { 
            Transfer transfer=new Transfer();
            transfer.setSender(senderList.get(random.nextInt(2)));
            transfer.setAmount(new BigDecimal(random.nextInt(10000)+100));
            transfer.setTransactionId(UUID.randomUUID().toString());
            return  transfer;
        }
    
    }

重写处理线程类

public class Log4JRunnable implements Runnable { 
        private Transfer tx;
        private  TransferService transferService=new LogTransferService();
    
        public Log4JRunnable(Transfer tx) { 
            this.tx = tx;
        }
    
        @Override
        public void run() { 
            transferService.transfer(tx.getAmount());
        }
    }

最后，让我们设置一个小应用程序，它能够通过ExecutorService同时运行多个传输：

public class TransferDemo { 
    
        public static void main(String[] args) { 
    
            ExecutorService executor = Executors.newFixedThreadPool(3);
            TransactionFactory transactionFactory = new TransactionFactory();
            for (int i = 0; i < 10; i++) { 
                Transfer tx = transactionFactory.newInstance();
                Runnable task = new Log4JRunnable(tx);
                executor.submit(task);
            }
            executor.shutdown();
        }
    }

当我们运行同时管理多个传输的演示应用程序时，我们很快就会发现日志并不像我们希望的那样有用。跟踪每次转移的执行情况很复杂，因为记录的唯一有用的信息是转移的金额和执行特定转移的线程的名称。  
此外，无法区分由同一线程执行的相同数量的两个不同事务，因为相关的日志行看起来基本相同：  
![在这里插入图片描述][watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L09jdG9wdXMyMQ_size_16_color_FFFFFF_t_70 1]

### 3. 在Log4j中使用MDC ###

Log4j中的MDC允许我们用appender在实际写入日志消息时可以访问的信息片段填充一个类似于map的结构。  
MDC结构以与ThreadLocal变量相同的方式在内部连接到正在执行的线程。  
【设计思路】  
1：将我们需要的信息填充到MDC中，线程独立  
2：记录日志信息  
3：清除MDC  
为了检索存储在MDC中的变量，应该更改appender的模式。

【代码修改】  
在自定义线程类中通过MDC添加需要的信息

![在这里插入图片描述][watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L09jdG9wdXMyMQ_size_16_color_FFFFFF_t_70 2]

public class Log4JRunnable implements Runnable { 
        private Transfer tx;
        private  TransferService transferService=new LogTransferService();
    
        public Log4JRunnable(Transfer tx) { 
            this.tx = tx;
        }
    
        @Override
        public void run() { 
            MDC.put("transaction.id", tx.getTransactionId());
            MDC.put("transaction.owner", tx.getSender());
            transferService.transfer(tx.getAmount());
            MDC.clear();
        }
    }

MDC.put（）用于在MDC中添加键和相应的值，而MDC.clear（）则清空MDC。

现在让我们更改log4j.properties以打印刚刚存储在MDC中的信息。对于要记录的MDC中包含的每个条目，使用%X\{\}占位符来更改转换模式就足够了：  
![在这里插入图片描述][20210523104647562.png]

log4j.appender.consoleAppender=org.apache.log4j.ConsoleAppender
    log4j.appender.consoleAppender.layout=org.apache.log4j.PatternLayout
    log4j.appender.consoleAppender.layout.ConversionPattern=  %-4r [%t] %5p %c{ 1} %x - %m - tx.id=%X{ transaction.id} tx.owner=%X{ transaction.owner}%n
    log4j.rootLogger = TRACE, consoleAppender

现在，如果我们运行应用程序，我们会注意到每一行还包含有关正在处理的事务的信息，这使我们更容易跟踪应用程序的执行：

![在这里插入图片描述][20210523104659907.png]

### 4. 在SLF4J/LogBack中使用MDC ###

MDC在SLF4J中也可用，条件是底层日志库支持MDC。Logback和Log4j都支持MDC，所以我们不需要特别的东西就可以在标准设置中使用它。  
让我们准备通常的TransferService子类，这次使用Java的简单日志Facade：

【说明】  
代码层面没有任何改变，只需要注意下日志配置文件即可logback.xml

<configuration>
        <appender name="stdout" class="ch.qos.logback.core.ConsoleAppender">
            <encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
                <pattern>%-4r [%t] %5p %c{ 1} - %m - tx.id=%X{ transaction.id} tx.owner=%X{ transaction.owner}%n</pattern>
    	</encoder>
        </appender>
        <root level="TRACE">
            <appender-ref ref="stdout" />
        </root>
    </configuration>

### 5. MDC和线程池 ###

MDC实现通常使用ThreadLocals来存储上下文信息。这是实现线程安全的简单而合理的方法。但是，我们应该小心地将MDC与线程池一起使用。

下面分析下基于ThreadLocal的mdc和线程池的组合可能存在的一些问题

我们从线程池中得到一个线程。然后我们使用MDC.put（）或ThreadContext.put（）在MDC中存储一些上下文信息。我们在一些日志中使用了这些信息，但不知怎么的，我们忘记了清除MDC上下文。借用的线程返回到线程池。一段时间后，应用程序从池中获取相同的线程。因为我们上次没有清理MDC，所以这个线程仍然拥有上一次执行的一些数据。

这可能会导致执行之间出现一些意外的不一致。防止这种情况的一种方法是始终记住在每次执行结束时清除MDC上下文。这种方法通常需要严格的人工监督，因此容易出错。

另一种方法是使用自定义线程池ThreadPoolExecutor，并在每次执行之后执行必要的清理。为此，我们可以扩展ThreadPoolExecutor类并重写afterExecute（）：

public class MdcAwareThreadPoolExecutor extends ThreadPoolExecutor { 
    
        public MdcAwareThreadPoolExecutor(int corePoolSize,
                                          int maximumPoolSize,
                                          long keepAliveTime,
                                          TimeUnit unit,
                                          BlockingQueue<Runnable> workQueue,
                                          ThreadFactory threadFactory,
                                          RejectedExecutionHandler handler) { 
            super(corePoolSize, maximumPoolSize, keepAliveTime, unit, workQueue, threadFactory, handler);
        }
    
        /** * 线程执行完毕，清理MDC数据 * @param r 线程 * @param t 异常 */
        @Override
        protected void afterExecute(Runnable r, Throwable t) { 
            MDC.clear();
            ThreadContext.clearAll();
        }
    }

这样，MDC清理将在每次正常或异常执行之后自动进行。因此，无需手动操作：  
![在这里插入图片描述][watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L09jdG9wdXMyMQ_size_16_color_FFFFFF_t_70 3]  
现在我们可以用新的executor实现重新编写相同的示例：

public class TransferDemo { 
    
        public static void main(String[] args) { 
            ExecutorService executor = new MdcAwareThreadPoolExecutor(3, 3, 0, MINUTES,
                    new LinkedBlockingQueue<>(), Thread::new, new ThreadPoolExecutor.AbortPolicy());
            TransactionFactory transactionFactory = new TransactionFactory();
    
            for (int i = 0; i < 10; i++) { 
                Transfer tx = transactionFactory.newInstance();
                Runnable task = new Log4JRunnable(tx);
                executor.submit(task);
            }
    
            executor.shutdown();
        }
    }

[20210523104005212.png]: /images/20221014/bb1b5f655102474fb1ee64b91c7efd29.png
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L09jdG9wdXMyMQ_size_16_color_FFFFFF_t_70]: /images/20221014/daace93258214e57a8dd3db41108cffd.png
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L09jdG9wdXMyMQ_size_16_color_FFFFFF_t_70 1]: /images/20221014/19ebce8199094889af6d89217dc11d93.png
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L09jdG9wdXMyMQ_size_16_color_FFFFFF_t_70 2]: /images/20221014/47e370673f604c5ba4b0d2378a5d9eda.png
[20210523104647562.png]: /images/20221014/663df85748cf4c2fb883e385b41deff0.png
[20210523104659907.png]: /images/20221014/2fb3a258457843df930d430d2a26acf2.png
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L09jdG9wdXMyMQ_size_16_color_FFFFFF_t_70 3]: /images/20221014/d9cb345b89bc40db80c8564d475c1f34.png