4

微服务分布式架构中，如何实现日志链路跟踪

 2 years ago
source link: https://my.oschina.net/u/4526289/blog/5395660
Go to the source link to view the article. You can view the picture content, updated content and better typesetting reading experience. If the link is broken, please click the button below to view the snapshot at that time.
neoserver,ios ssh client

摘要：接口设计出来返回结果值和编码，还有哪些是需要我们优化的结果参数？微服务分布式架构中，如何实现日志链路跟踪？

本文分享自华为云社区《微服务分布式架构中，如何实现日志链路跟踪？》，作者：码农架构。

Logback 背景

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

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

普通debug日志

v2-4ea65c2fb8521cb61cad9ae8597e753a_720w.jpg

SQL执行日志

v2-70ea3a238ca3ff65d8dadc67d211e306_720w.jpg

Logback 配置案例

v2-1a431d5f93b5b865b5781be3c106f487_720w.jpg

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

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

v2-45e654c50989ea683905d3d4fbb45678_720w.jpg

%-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...

v2-035bde2dd10df726ce43b375a0c3b668_720w.jpg

由于案例中是守护线程thread-monitor-daemon，所以不记录链路ID。
对在系统设计的时候对于线程的命名规范也是有约束的

v2-a2f098ea027ce8ed2de01e55b5561f20_720w.jpg

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

回归正题比如下面的例子中记录了请求的链路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的生成写入就需要特殊处理。

v2-abd6077421f0e44c7ba1ac8af42bf202_720w.jpg

链路ID设计

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

v2-c3120dcaa7693bbff4583fffd3a4faa6_720w.jpg

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

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

v2-d642906af82439e4b9f5a66e1efebabc_720w.jpg

在每一次请求中链路编号（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);
			}
		}
}

点击关注，第一时间了解华为云新鲜技术~


report

Recommend

About Joyk


Aggregate valuable and interesting links.
Joyk means Joy of geeK