Java如何通过日志排查问题

问题：

大家有没有遇到过这样一种场景，在一个接口或者方法当中，业务逻辑很复杂，方法嵌套调用层级很深，此时要定位业务流程的走向，是不是要在每个方法中打日志，而这些日志是不串联的，比如，一个接口调用下来，程序没有报错，但没有按预期执行，怎么排查，就得翻这个方法调用时的每一条记录日志，而代码是并行执行的，程序中不可能只有这一个方法调用，那就会有其它日志夹杂在我们希望查看的日志中间。影响我们的定位。如何解决？

方法一：

最先想到的方法就是在这个方法的每个日志当中都加一个标志，这样通过日志来过滤不就可以了吗？这也许是一个方法，但在一个大方法里面，要在每一处记日志的地方都增加标记，一来繁琐，二来要在日志中定位也很麻烦。

方法二：

本文就提供一个使用Java中的ThreadLocal方法来记录日志的方案，大家知道ThreadLocal可以跨方法获取，只要在同一个线程当中执行，每个方法都可以获取ThreadLocal对象，Spring中的@Transactional注解就是通过ThreadLocal来存储数据源的，这里我们通过ThreadLocal来存储日志，在方法的最后，我们统一记录一条日志，在这一条日志当中，可以清楚地看到每一条记录的执行步骤。缺点就是在多线程当中会有问题。

下面我们看看是如何实现的。

package com.zhixinyi.job.common;

import com.zhixinyi.job.util.LogUtils;

import java.util.ArrayList;
import java.util.List;

public class TraceContext {
    private static class TraceContent {
        private String key;
        private String value;
        private long currentMills;

        public TraceContent(String key, String value) {
            this.key = key;
            this.value = value;
            this.currentMills = System.currentTimeMillis();
        }

        public String getKey() {
            return key;
        }

        public void setKey(String key) {
            this.key = key;
        }

        public String getValue() {
            return value;
        }

        public void setValue(String value) {
            this.value = value;
        }

        public long getCurrentMills() {
            return currentMills;
        }

        public void setCurrentMills(long currentMills) {
            this.currentMills = currentMills;
        }
    }

    private List<TraceContent> contextContent;

    public TraceContext() {
        contextContent = new ArrayList<>();
    }

    private static ThreadLocal<TraceContext> traceContextThreadLocal = new ThreadLocal<TraceContext>() {
        @Override
        protected TraceContext initialValue() {
            return new TraceContext();
        }
    };

    public static TraceContext getCurrentContext() {
        return traceContextThreadLocal.get();
    }

    public void begin() {
        synchronized (this) {
            clear();
        }
    }

    public void clear() {
        if (contextContent != null && contextContent.size() > 0) {
            contextContent.clear();
        }
        filter1 = "";
        filter2 = "";
        warning = false;
        throwable = null;
        subCategory = "";
    }

    public void put(String key, String value) {
        synchronized (this) {
            contextContent.add(new TraceContent(key, value));
        }
    }

    private String filter1 = "";

    public void putFilter1(String filter1) {
        this.filter1 = filter1;
    }

    private String filter2 = "";

    public void putFilter2(String filter2) {
        this.filter2 = filter2;
    }

    private boolean warning = false;

    public void putWarn(boolean warning) {
        this.warning = warning;
    }

    private Throwable throwable = null;

    public void putException(Throwable ex) {
        this.throwable = ex;
    }

    private String subCategory = "";

    public void putSubCategory(String subCategory) {
        this.subCategory = subCategory;
    }

    public void commit() {
        try {
            synchronized (this) {
                StringBuilder sb = new StringBuilder();
                long firstMills = 0;
                if (contextContent != null && contextContent.size() > 0) {
                    firstMills = contextContent.get(0).currentMills;
                }
                for (TraceContent item : contextContent) {
                    sb.append(String.format("%d-%s : %s", (item.getCurrentMills() - firstMills), item.getKey(), item.getValue()));
                    sb.append("\r\n");
                }
                String msg = sb.toString();

                if (!warning) {
                    if (throwable == null) {
                        LogUtils.infoOrError(subCategory,filter1, filter2, msg, null, null);
                    } else {
                        LogUtils.infoOrError(subCategory, filter1, filter2, msg, null, throwable);
                    }
                } else {
                    String exMsg = throwable == null ? "" : throwable.getMessage();
                    BusinessException be = new BusinessException(0, exMsg);
                    LogUtils.infoOrError(subCategory, filter1, filter2, msg, null, be);
                }

                clear();
            }
        } catch (Exception ex) {
            LogUtils.infoOrError(subCategory, filter1, filter2, "", null, ex);
        }
    }
}

程序代码中的使用：

public void dispatchNormalOrderHandler(){
        try {
 
            TraceContext.getCurrentContext().putSubCategory("dispatchNormalOrderHandler");
            List<TrainOrderDispatch> trainOrderDispatches = selectWaitingDispatch();
            if(trainOrderDispatches == null || trainOrderDispatches.size() == 0){
                TraceContext.getCurrentContext().put("no_dispatch_order", "no_dispatch_order");
                return;
            }

            SupplierMachine testMachine = getTestMachine();
            List<SupplierMachine> allValidMachines = getAllValidMachines();
            TraceContext.getCurrentContext().put("all_machines", JsonUtils.objectToJson(allValidMachines.stream().map(m -> m.getId()).collect(Collectors.toList())));

            .........

            SupplierMachine supplierMachine = noDispatchedMachines.stream().min(Comparator.comparing(SupplierMachine::getCurrentNum)).get();
            dispatchSuccess(trainOrderDispatch, supplierMachine);


        }catch (Exception ex){
            LogUtils.infoOrError("dispatchNormalOrderHandler", ex);
        }finally {
            TraceContext.getCurrentContext().commit();
        }
}

private void dispatchSuccess(TrainOrderDispatch trainOrderDispatch, SupplierMachine machine){
        LambdaUpdateWrapper<TrainOrderDispatch> trainOrderDispatchLambdaUpdateWrapper = new LambdaUpdateWrapper<>();
        trainOrderDispatchLambdaUpdateWrapper.eq(TrainOrderDispatch::getId, trainOrderDispatch.getId());
        trainOrderDispatchLambdaUpdateWrapper.eq(TrainOrderDispatch::getDispatchStatus, trainOrderDispatch.getDispatchStatus());
        TrainOrderDispatch updateDispatch = new TrainOrderDispatch();
        updateDispatch.setDispatchStatus((byte)3);
        updateDispatch.setAgentIdStr(getAgentIdStr(trainOrderDispatch.getAgentIdStr(), machine.getId()));
        updateDispatch.setDispatchCount(trainOrderDispatch.getDispatchCount()+1);
        updateDispatch.setDispatchSuccessTime(LocalDateTime.now());
        int ret = trainOrderDispatchMapper.update(updateDispatch, trainOrderDispatchLambdaUpdateWrapper);
        if(ret <= 0){
            TraceContext.getCurrentContext().put("update_dispatch", "fail");
            return;
        }

       ........

        orderLogService.log(trainOrderDispatch.getOrderNumber(), "分单", String.format("分单成功，票机ID=%s", machine.getId().toString()));

        String msg = String.format("orderNumber=%s, machineId=%s", trainOrderDispatch.getOrderNumber(), machine.getId().toString());
        TraceContext.getCurrentContext().put("dispatch_success", msg);
    }