通过 MDC 让你方便的跟踪你的定时任务日志

Posted 2021-12-29 carl-zhao

当我们程序出现了 debug 的时候，我们一般的解决方法就是查看日志。在开发环境还好，我们本地启动服务一般只会有一个请求，查看日志或者本地 debug 都非常方便。但是如果我们是线上发生了问题，这个时候请求量就比较多。如果我们的调用链比较长的话，要把整个日志关联起来就不太方便。这个时候我们就需要使用到日志当中的 MDC 了。

下面是日志框架 logback 的 MDC ，当然主流的日志框架基本都支持这个特性。简单来说：MDC 其实一种较轻的技术是对服务于给定客户机的每个日志请求进行惟一的标记。大体的实现方式如下：

• 在程序入口中通过调用 MDC.put(跟踪号, 唯一标记) ，把跟踪号放入日志框架上下文当中
• 然后在日志模板当中通过 [%X跟踪号]，在日志打印时一次调用都会带有这个唯一标记的跟踪号了(不可以跨线程)

在进行 RPC 调用的时候，我们可以根据上游传递的跟踪号可以把一个微服务里面的整个调用链条很完整的串联起来。但是如果我们的定时任务如果有问题的时候，我们如何能够通过日志来完整的查看整个调用链呢？

其实我们在进行任务调用的时候，在任务执行之前手动的添加一个跟踪号，并且在任务调用完成清除这个跟踪号就行了。但是这样在每个任务都需要执行同样的操作。然后博主就想使用模板的方式来进行调用。这里就借鉴了一下 Spring 的模板处理逻辑。

首先定义一个接口用于处理真正的任务逻辑(可以理解成为Spring 事务处理的 TransactionCallback)

业务处理接口定义

@FunctionalInterface
public interface LoggerCallback<T> 

    /**
     * 任务操作
     * @return
     */
    T doInExecute();

然后我们再定义一个日志模板。

日志模板

public class LoggerTemplate 

    public <T> T execute(String mdcKey, JobLoggerCallback<T> action)
        String uuid = UUID.randomUUID().toString().replaceAll("-", "");
        MDC.put(mdcKey, uuid);
        try 
            return action.doInExecute();
         finally 
            MDC.clear();
        
    

通过这个日志模板我们在业务调用开始前就进行添加 MDC 跟踪号，然后在调用完成之后调用清除 MDC 跟踪号。

下面我以在 xxl-job 进行任务操作举例。

@Slf4j
@Component
public class DemoJob 

    @Resource(name = "loggerTemplate")
    protected LoggerTemplate loggerTemplate;

    @XxlJob(value = "demoJob")
    public ReturnT<String> execute(String param) 
        return loggerTemplate.execute("ctxLogId", () -> 
            log.info("DemoJob.execute task Start ......");
            try 
                // TODO 执行业务操作
             catch (Exception e) 
                LogUtil.error("DemoJob.execute is error", e);
                return ReturnT.FAIL;
            
            log.info("DemoJob.execute task End ......");
            return ReturnT.SUCCESS;
        );
    

在这里我们思考一下，在执行定义任务的时候，我们都是批量的操作数据。如果我们的操作的批次比较大，但是我们执行异常的数据只有一条。这个时候我们通过上面的跟踪号查询其实量也挺大的。那么我们可以通过上面的跟踪号关联上所有的任务，然后我们在进行单个数据操作的时候在之前的跟踪号上面再添加一下我们的业务唯一号。这样就可以了兼顾了。

我们就在日志模板上面添加一个方法就行了，添加了的日志模板代码如下：

public class LoggerTemplate 

    public <T> T execute(String mdcKey, JobLoggerCallback<T> action)
        String uuid = UUID.randomUUID().toString().replaceAll("-", "");
        MDC.put(mdcKey, uuid);
        try 
            return action.doInExecute();
         finally 
            MDC.clear();
        
    

    public <T> T render(String mdcKey, String appendValue, JobLoggerCallback<T> action)
        String mdc = MDC.get(mdcKey);
        String newMdc = StringUtils.join(mdc, ":", appendValue);
        MDC.put(mdcKey, newMdc);
        try 
            return action.doInExecute();
         finally 
            MDC.put(mdcKey, mdc);
        
    

在这里我们需要注意一下，就是在执行完成逻辑之后，需要把原来的MDC跟踪号重新添加到 MDC 里面，因为后续的任务还需要使用。

针对于我们处理定时任务的逻辑如下：

@Slf4j
@Component
public class DemoJob 

    @Resource(name = "loggerTemplate")
    protected LoggerTemplate loggerTemplate;

    @XxlJob(value = "demoJob")
    public ReturnT<String> execute(String param) 
        return loggerTemplate.execute("ctxLogId", () -> 
            log.info("DemoJob.execute task Start ......");
            try 
                // TODO 查询数据库需要处理的数据
                List list =  getDataForDB();
                
                if(CollectionUtils.isEmpty(list)) 
                    return;
                
                
                list.stream().forEach(v -> 
                    loggerTemplate.render("ctxLogId", v.getId(), v);
                );
                
             catch (Exception e) 
                LogUtil.error("DemoJob.execute is error", e);
                return ReturnT.FAIL;
            
            log.info("DemoJob.execute task End ......");
            return ReturnT.SUCCESS;
        );
    

    /**
     * 处理单条业务逻辑
     * @param v
     */
    private void processOne(Object v) 
        // TODO 处理业务逻辑