码农架构 | 微服务分布式架构中,如何实现日志链路跟踪?

Logback 背景


Logback是由log4j创始人设计的另一个开源日志组件,官方网站: http://logback.qos.ch。它当前分为下面下个模块:

  • logback-core:其它两个模块的基础模块
  • logback-classic:它是log4j的一个改良版本,同时它完整实现了slf4j API使你可以很方便地更换成其它日志系统如log4j或JDK14 Logging
  • logback-access:访问模块与Servlet容器集成提供通过Http来访问日志的功能

普通debug日志

码农架构 | 微服务分布式架构中,如何实现日志链路跟踪?


SQL执行日志

码农架构 | 微服务分布式架构中,如何实现日志链路跟踪?

Logback 配置案例


码农架构 | 微服务分布式架构中,如何实现日志链路跟踪?

日志级别排序为: TRACE < DEBUG < INFO < WARN < ERROR

  • %d:表示日期
  • %n:换行
  • %thread:表示线程名
  • %level:日志级别
  • %msg:日志消息
  • %file:表示文件名
  • %class: 表示文件名
  • %logger:Java类名(含包名,这里设定了36位,若超过36位,包名会精简为类似a.b.c.JavaBean)
  • %line:Java类的行号

码农架构 | 微服务分布式架构中,如何实现日志链路跟踪?

注意:

%-4relative %d{yyyy-MM-dd HH:mm:ss.SSS} [%thread][%X{TRACE_ID}] %-5level %logger{100}.%M\(%line\) - %msg%n

在logback中,%relative表示自应用程序启动以来打印相对时间戳(以毫秒为单位). %-4只是元素的对齐方式.

案例

3452487 2021-08-03 15:19:36.940 [thread-monitor-daemon][] WARN  com.xxxx.common.util.MonitorLogger.warn(27) - 发现超时线程notify-replay-consumer...

码农架构 | 微服务分布式架构中,如何实现日志链路跟踪?

由于案例中是守护线程thread-monitor-daemon,所以不记录链路ID。

对在系统设计的时候对于线程的命名规范也是有约束的

码农架构 | 微服务分布式架构中,如何实现日志链路跟踪?

这里就不做详细展开后续有机会会分享。

回归正题比如下面的例子中记录了请求的链路ID

19006989 2021-08-04 22:35:25.776 [http-nio-0.0.0.0-8010-exec-10][1fc8pebmgwukw863w2p342rp2936a3r157w0:0:] INFO  com.xxx.framework.eureka.core.listener.EurekaStateChangeListener.listen(58) -

服务实例[XX-PAAS]注册成功,当前服务器已注册服务实例数量[3]

码农架构 | 微服务分布式架构中,如何实现日志链路跟踪?

对于上图中显示的系统启动时间、当前时间、当前线程、对应路径按照logback官方配置就可以逐步完善对于的日志信息,但是对于链路ID的生成写入就需要特殊处理。

链路ID设计


对于链路追踪设计我个人比较喜欢两种方案

第一种

码农架构 | 微服务分布式架构中,如何实现日志链路跟踪?

在每一次请求中链路编号(traceId)、单元编号(spanId)都是通过HttpHeader的方式进行传递,日志的起始位置会主动生成traceId、spanId,而起始位置的Parent SpanId则是不存在的,值为null。

这样每次通过restTemplate、Openfeign的形式访问其他服务的接口时,就会携带起始位置生成的traceId、spanId到下一个服务单元。


第二种

码农架构 | 微服务分布式架构中,如何实现日志链路跟踪?在每一次请求中链路编号(traceId),没经过一次微服务对于深度(Deep)加1

public static class ThreadTraceListener implements ThreadListener {
        @Override
        public void onThreadBegin(HttpServletRequest request) {
            String traceToken = ThreadLocalUtil.getTranVar(TRACE_ID);
            String fromServer = ThreadLocalUtil.getTranVar(FROM_SERVER);
            int deep;
            String traceId;
            if (StringUtils.isBlank(traceToken)) {
                traceId = IDGenerator.generateID();
                deep = 0;
                traceToken = StringHelper.join(traceId, ":0");
            } else {
                int index = traceToken.lastIndexOf(':');
                traceId = traceToken.substring(0, index);
                deep = Integer.valueOf(traceToken.substring(index + 1));
            }
            ThreadLocalUtil.setLocalVar(TRACE_ID, traceId);
            ThreadLocalUtil.setLocalVar(TRACE_DEEP, deep);
            ThreadLocalUtil.setTranVar(TRACE_ID, StringHelper.join(traceId, ":", deep + 1));
            ThreadLocalUtil.setLocalVar(FROM_SERVER, fromServer);
            ThreadLocalUtil.setTranVar(FROM_SERVER, getCurrentServer());
            MDC.put(TRACE_ID, StringHelper.join(traceToken, ":", fromServer));
        }

        @Override
        public void onThreadEnd(HttpServletRequest request) {
            MDC.remove(TRACE_ID);
        }
    }

针对请求拦截

protected void doFilterInternal(HttpServletRequest request,
            HttpServletResponse response,
            FilterChain chain) throws ServletException, IOException {
        long startTime = System.currentTimeMillis();
        // 从Header中装载传递过来的变量
        Map<String, Object> tranVar = new HashMap<String, Object>();
        Enumeration<String> headers = request.getHeaderNames();
        while (headers.hasMoreElements()) {
            String key = headers.nextElement();
            if (!StringUtils.isEmpty(key)
                    && key.startsWith(ThreadLocalUtil.TRAN_PREFIX)) {
                tranVar.put(key.substring(ThreadLocalUtil.TRAN_PREFIX.length()),
                        request.getHeader(key));
            }
        }
        ThreadLocalHolder.begin(tranVar, request);
        try {
            if (isGateway) {
                response.addHeader("X-TRACE-ID", TraceUtil.getTraceId());
            }
            // 检查RPC调用深度
            checkRpcDeep(request, response);
            // 业务处理
            chain.doFilter(request, response);
            // 记录RPC调用次数
            logRpcCount(request, response);
        } catch (Throwable ex) {
            // 错误处理
            Response<?> result = ExceptionUtil.toResponse(ex);
            Determine determine = ExceptionUtil.determineType(ex);
            ExceptionUtil.doLog(result, determine.getStatus(), ex);
            response.setStatus(determine.getStatus().value());
            response.setCharacterEncoding("UTF-8");
            response.setContentType(MediaType.APPLICATION_JSON_UTF8_VALUE);
            response.getWriter().write(JsonUtil.toJsonString(result));
        } finally {
            try {
                doMonitor(request, response, startTime);
                if (TraceUtil.isTraceLoggerOn()) {
                    log.warn(StringHelper.join(
                            "TRACE-HTTP-", request.getMethod(),
                            " URI:", request.getRequestURI(),
                            ", dt:", System.currentTimeMillis() - startTime,
                            ", rpc:", TraceUtil.getRpcCount(),
                            ", status:", response.getStatus()));
                } else if (log.isTraceEnabled()) {
                    log.trace(StringHelper.join(request.getMethod(),
                            " URI:", request.getRequestURI(),
                            ", dt:", System.currentTimeMillis() - startTime,
                            ", rpc:", TraceUtil.getRpcCount(),
                            ", status:", response.getStatus()));
                }
            } finally {
                ThreadLocalHolder.end(request);
            }
        }
}

若有收获,就点个赞吧


更多技术分享可关注微信公众号:码农架构

专注于系统架构、高可用、高性能、高并发类技术分享

上一篇:Webpack HMR 原理解析


下一篇:优化配置介绍-开发环境