简要

这篇文章是在公司内部做的一次关于Java日志的一次技术分享，所以部分敏感图片、文字打了马赛克还请谅解，欢迎指点，大佬勿喷。

背景

一、【冥思苦想】为什么要做日志追踪？

1.场景再现

这里我们试想，小赵(C服务)打印异常，假设是参数错误，导致执行sql报错，那么小赵只能找到小李询问参数问题，然后小李(B服务)在找小张(A服务)询问，这样岂不是如此费劲，那么有没有什么办法小张不用打电话自己查询日志就能查到呢，或者可以直接定位到时小赵的服务(服务C)出了问题，这里先给大家留下一个悬念。

2.案例分析

1.Java单点应用示例分析

分析
总所周知Java是多线程的，因此在并发情况下我们会经常发现应用打印的log日志会出现不连续现象，例如如下示例

2.跨服务Log定位示例分析

这里service-A某个服务调用 service-B 服务/api/purchase/query-forecast-base接口，假设这里 service-A 接口报异常，那么我们如何排查这个问题呢？毫无疑问，我们会打开service-A的日志，看异常。由于Java是多线程应用，所以service-A自身的log日志就已经“琳琅满目了”，排查起来极其困难，在加上这里service-B 调用的service-A没有标识(requestId)我们只能通过参数去搜索，例如productId,试想productId如果打印的很多，那岂不是会搜索到很多无用的log信息，导致我们定位排查问题的时间大大打折扣，岂不是排问题1小时解决问题10分钟，这可不是我们想要的结果。

二、【勤奋好学】如何做好日志追踪？

1.做好日志规范

俗话说无规矩不成方圆，做好日志规范、编码规范、技术栈规范、域名规范、项目结构规范才能便于后续对整体微服务的监控与管理。而所谓的日志规范到底应该规范哪些内容呢？？
1）统一打印格式规范
所谓打印格式规范则是日志中应该打印哪些信息,常见有，时间、级别、线程ID、类名、方法名、Message消息体。例如

时间 + 空格 + 日志级别 + 空格 + [docker宿主机hostname] + 空格 + [worker] +空格 + [项目服务名] + 空格 + [requestId] + 空格 + [环境] + 空格 + [实例Id] + 空格 + 数据内容

服务名：添加服务名便于定位当前日志归宿玉哪个服务；
requestId: 用于链路追踪使用，方便定位一个线程下所有日志信息，排除其他干扰日志；
环境：由于测试、线上都是多环境日志，有可能造成不同环境日志打到同一个kibana上，如果建立多个kibana不变维护，所以这里建议区分环境信息，测试、灰度、线上等；
实例Id: 由于大部门微服务都是基于docker多实例部署，如果一个实例因为物理环境，或者等其他原因引起问题，则不便于区分是哪台实例出了问题，所以这里可以通过docker容器的实例ID来快速定位;
2）统一打印规范
这里我们先来看下Java中常见的4种日志级别如下
INFO: 毫无争议，这里info既标准的信息输出，可以打印一些业务关键参数等，如比较重要的方法或者逻辑可以通过info级别打印一些变量相关信息，则出现bug或者异常方便定位问题；
WARN:这里警告级别，建议打印一些业务异常，例如一些参数非空校验，用户为登录，或者在预料之内发生的异常，切不会因为异常影响业务的正常进行这一类可以使用此warn级别；
DEBUG:调试模式日志使用相对比较少，如果当你打印INFO相关日志，太多，或者有些日志可有可无无关紧要相关信息可使用这个级别，一般debug只在测试打开，线上不会打印debug，所以可以在测试调试问题的时候使用；
ERROR：既系统异常日志，如果你的微服务发生了未在预料之内的异常，例如空指针、数据越界、序列化json错误等，当然这里ERROR并不是局限于异常才会使用error，如果你的业务某些逻辑，也可以打印error。例如调用查询数据库里某关联数据，理论上一定有值，但是查询的确实空，那么也可以打印error，因为我们log监控平台是基于error监控的，所以这样有了error日志便可以及时发现问题，从而可以更主动的去解决项目潜在的风险或bug。

2.为每个线程申请唯一Log标识【requestId】

在上边讲到的场景一，和场景二中，我们知道了由于Java是多线程语言，线程交替执行造成日志打印不连续，那我们想想有没有什么办法来解决呢？答案肯定是有的，试想打印出来的日志是不连续的，造成了我们查询日志的是会有一些干扰日志(其他线程打印的日志),那么我们是否可以排除或者过滤掉其他日志不就可以了 吗，例如在终端可以使用 cat xxx.log grep "关键词" 这样定位过滤，在kibana上可以添加 filter关键词来过滤，这样就可以清晰的看到了我们想看到的日志了吗。这就是requestId 的作用，这里有人可能会说线程id不也可以么，但是别忘记了java是多线程的，spring框架也是基于线程池来实现的，所以项目启动之后线程id就已经固定了，如果哪些线程空闲，就由哪些线程来执行，这样一个线程id在一个小时内可能会被多次执行，那么每次的执行的参数又不用，所以定位日志也是极其困难的，这里的requestId则不然，他是每次线程开始之前，都生成唯一的uuid，这样就避免了这个问题，示例如图。

3.借助三方工具监控ERROR告警

这里一些监控告警方式相对比较多，对项目有侵入的方式有,sentry、微信机器人等，但是这种方式都需要侵入代码，也就是需要在项目中引入监控，定义全局异常拦截器然后在发送异常的时候通知各个告警平台。

三、【雪中送炭】实战Java经典示例

1.Log4j MDC简介。

log4j日志的MDC其实就是一个线程的上下文Context对象，类似于ThreadLocal，可以存储一些变量数据在这个对象中，之后通过 log4j,xml配置文件通过 -X{属性名}进行取值，从而打印在日志中，其作用就是解决分布式环境下复杂的日志跟踪调试问题。
官方文档：https://logging.apache.org/log4j/2.x/manual/thread-context.html

2.配置全局过滤器处理初始化MDC。

Java中请求过滤器配置如下

@Order(0)
@Component
@WebFilter(filterName = "requestIdFilter", urlPatterns = "/**")
public class RequestIdFilter implements Filter {
 
    private static final String HEADER_REQUEST_ID = "Request-Id";
 
    private static final String HEADER_X_REQUEST_ID = "X-Request-Id";
 
    private static final String REQUEST_ID = "requestId";
 
    @Override
    public void doFilter(ServletRequest request, ServletResponse response, FilterChain chain)
        throws IOException, ServletException {
        HttpServletRequest httpServletRequest = (HttpServletRequest) request;
        HttpServletResponse httpServletResponse = (HttpServletResponse) response;
        try {
            //获取并设置RequestId
            MDC.put(REQUEST_ID, this.getRequestId(httpServletRequest));
            chain.doFilter(httpServletRequest, httpServletResponse);
        } finally {
            MDC.clear();
        }
    }
    /**
     * 获取请求RequestId
     *
     * @param httpServletRequest 请求
     * @return requestId
     */
    private String getRequestId(HttpServletRequest httpServletRequest) {
        String requestId = httpServletRequest.getHeader(HEADER_REQUEST_ID);
        if (StringUtils.isBlank(requestId)) {
            requestId = httpServletRequest.getHeader(REQUEST_ID);
        }
        if (StringUtils.isBlank(requestId)) {
            requestId = httpServletRequest.getHeader(HEADER_X_REQUEST_ID);
        }
        if (StringUtils.isBlank(requestId)) {
            requestId = UUID.randomUUID().toString().replace("-", "");
        }
        return requestId;
    }
}

Log4j 配置文件日志格式配置

%d{yyyy-MM-dd HH:mm:ss.SSS} %-5level [${hostname}] [%X{requestId}] [%X{traceId}] [%thread] [%tid] %logger{50} %L -%msg%n

注意：这里用的是filter过滤器，不建议使用拦截器。

3.线程池配置MDC。

线程池在业务开发中经常会使用到，由于MDC底层实现是基于Threadlocal 实现的，由于在Filter配置的requestId,只属于主线程的上下文，如果在主线程中使用了线程池，开启了子线程，由于主、子线程MDC是相互隔离的，所以子线程中X-X{requestId}将无法获取到主线程filter中设置的requestId的,所以采用了一种比较巧妙的方式，因为每个线程最终都会执行 Runable,run方法，所以这里只需包装一下Runable，然后分开在启用之前这是requestId,run方法结束之后清理MDC。示例如下。

public class ThreadMdcUtil {
 
    public static <T> Callable<T> wrap(final Callable<T> callable, final Map<String, String> context) {
        return () -> {
            if (context == null) {
                MDC.clear();
            } else {
                MDC.setContextMap(context);
            }
            try {
                return callable.call();
            } finally {
                MDC.clear();
            }
        };
    }
 
    public static Runnable wrap(final Runnable runnable, final Map<String, String> context) {
        return () -> {
            if (context == null) {
                MDC.clear();
            } else {
                MDC.setContextMap(context);
            }
            try {
                runnable.run();
            }finally {
                MDC.clear();
            }
        };
    }
}

    private static class MyThreadPoolExecutor extends ThreadPoolExecutor {

        public MyThreadPoolExecutor(int corePoolSize, int maximumPoolSize, long keepAliveTime, TimeUnit unit,
            BlockingQueue<Runnable> workQueue) {
            super(corePoolSize, maximumPoolSize, keepAliveTime, unit, workQueue);
        }

        public MyThreadPoolExecutor(int corePoolSize, int maximumPoolSize, long keepAliveTime, TimeUnit unit,
            BlockingQueue<Runnable> workQueue, ThreadFactory threadFactory) {
            super(corePoolSize, maximumPoolSize, keepAliveTime, unit, workQueue, threadFactory);
        }

        public MyThreadPoolExecutor(int corePoolSize, int maximumPoolSize, long keepAliveTime, TimeUnit unit,
            BlockingQueue<Runnable> workQueue, RejectedExecutionHandler handler) {
            super(corePoolSize, maximumPoolSize, keepAliveTime, unit, workQueue, handler);
        }

        public MyThreadPoolExecutor(int corePoolSize, int maximumPoolSize, long keepAliveTime, TimeUnit unit,
            BlockingQueue<Runnable> workQueue, ThreadFactory threadFactory, RejectedExecutionHandler handler) {
            super(corePoolSize, maximumPoolSize, keepAliveTime, unit, workQueue, threadFactory, handler);
        }

        @Override
        public void execute(Runnable command) {
            super.execute(ThreadMdcUtil.wrap(command, MDC.getCopyOfContextMap()));
        }

        @Override
        public Future<?> submit(Runnable task) {
            return super.submit(ThreadMdcUtil.wrap(task, MDC.getCopyOfContextMap()));
        }

        @Override
        public <T> Future<T> submit(Runnable task, T result) {
            return super.submit(ThreadMdcUtil.wrap(task, MDC.getCopyOfContextMap()), result);
        }

        @Override
        public <T> Future<T> submit(Callable<T> task) {
            return super.submit(ThreadMdcUtil.wrap(task, MDC.getCopyOfContextMap()));
        }

        @Override
        protected void afterExecute(Runnable r, Throwable t) {
            if (Objects.nonNull(t)) {
                String msg = String.format("线程：%s 执行错误：", Thread.currentThread().getName());
                log.error(msg, t);
            }
            super.afterExecute(r, t);
            ThreadLocalContextHelper.clearAll();
            MDC.clear();
        }
    }

    @Bean("global Executor")
    public ExecutorService getVendorInfoExecutor() {
        return new MyThreadPoolExecutor(10, 15, DEFAULT_KEEP_ALIVE, TimeUnit.SECONDS,
            new LinkedBlockingDeque<>(DEFAULT_MAX_SIZE), new ThreadPoolExecutor.CallerRunsPolicy());
    }

3.Feign中的那些坑。

由于feign开启熔断之后存在和线程池类似的问题，线程可以配置，但是feign熔断却不可以指定线程池配置，所以这里采用了HystrixCommandExecutionHook来解决。
Feign请求三方服务请求头配置

/**
 * RequestId Feign全局拦截器配置类
 */
@Slf4j
@Component
@ConditionalOnClass(RequestInterceptor.class)
public class RequestIdFeignInterceptor implements RequestInterceptor {
 
    private static final String REQUEST_ID = "requestId";
 
    @Override
    public void apply(RequestTemplate template) {
        template.header(REQUEST_ID, MDC.get(REQUEST_ID));
    }
}

Feign线程打印log日志配置

public class HystrixCredentialsContext extends HystrixCommandExecutionHook {
 
    private static final HystrixRequestVariableDefault<Map<String, String>> HYSTRIX_REQUEST_VARIABLE_DEFAULT =
        new HystrixRequestVariableDefault<>();
 
    @Override
    public <T> void onStart(HystrixInvokable<T> commandInstance) {
        setMDCContext();
    }
 
    @Override
    public <T> void onThreadStart(HystrixInvokable<T> commandInstance) {
        Map<String, String> map = HYSTRIX_REQUEST_VARIABLE_DEFAULT.get();
        if(MapUtils.isNotEmpty(map)){
            MDC.setContextMap(map);
        }
    }
 
    @Override
    public <T> Exception onError(HystrixInvokable<T> commandInstance, FailureType failureType, Exception e) {
        clearLogContext();
        return e;
    }
 
    @Override
    public <T> void onSuccess(HystrixInvokable<T> commandInstance) {
        clearLogContext();
    }

    /**
     * 主线程同步变量到子线程 MDC
     */
    private void setMDCContext() {
        if (!HystrixRequestContext.isCurrentThreadInitialized()) {
            HystrixRequestContext.initializeContext();
        }
        HYSTRIX_REQUEST_VARIABLE_DEFAULT.set(MDC.getCopyOfContextMap());
    }
 
    /**
     * 清理
     */
    private void clearLogContext() {
        if (HystrixRequestContext.isCurrentThreadInitialized()) {
            HystrixRequestContext.getContextForCurrentThread().shutdown();
        }
        MDC.clear();
    }
}

4.其他配置例：Xxjob、Mq

这里在设置MDC,requestId的同时设置sentry requestId这边可以通过sentry告警日志拿到requestId,然后快速定位错误日志信息。

5.验证

1.Sentry验证。

2.微信告警验证。

4.kibana验证。

四、【工欲善其事必先利其器】日志查询神器 Kibana

日志查询神器 Kibana简单使用

五、【恩重如山】参考

https://logging.apache.org/log4j/2.x/manual/thread-context.html
https://juejin.cn/post/6871967909581848583#heading-7
https://docs.spring.io/spring-cloud-openfeign/docs/2.2.5.RELEASE/reference/html/#spring-cloud-feign