背景是随着微服务架构的兴起，应用程序被拆分为多个独立的服务，每个服务负责特定的功能。在这种架构下，一个请求可能会经过多个不同的服务，跨越多个服务器和实例。为了追踪和关联请求在分布式系统中的流转路径，分布式日志跟踪变得必要。
分布式日志跟踪是在分布式系统中追踪和关联多个服务之间的请求的过程。它允许你在整个分布式系统中跟踪请求的流转路径，以便进行故障排查、性能分析和日志分析。
常见的分布式日志跟踪方案
基于LOGBACK的分布式日志跟踪方案
LOGBACK介绍
Logback 是一个功能强大、灵活且高效的日志框架，它是由 Ceki Gülcü 创建的，也是 Log4j 框架的继任者。Logback 的设计目标是成为 Java 应用程序的首选日志框架，它具有以下主要特点：
引入LOGBACK
基于spring boot
首先引入maven相关配置
ch.qos.logback
logback-classic
1.2.10
org.slf4j
slf4j-ext
1.7.30
org.slf4j
log4j-over-slf4j
1.7.30
接着配置logback.xml文件，配置文件如下
hello.world
%d{yyyy-MM-dd HH:mm:ss.SSS}|%-5level|${module}|%thid|%localIP|%X{traceId}|%.-51200msg|%logger%n
${log.base}/${module}_running.log
${log.base}/archive/${module}_running.%d{yyyy-MM-dd}.%i.log
30
100MB
false
300
%d{yyyy-MM-dd HH:mm:ss.SSS}|%-5level|${module}|%thid|%localIP|%X{traceId}|%.-51200msg|%logger%n
UTF-8
100MB
0
1024
${log.base}/${module}_interface.log
${log.base}/archive/${module}_interface.%i.log
1
10
false
3000
%d{yyyy-MM-dd HH:mm:ss.SSS}|%-5level|${module}|%thid|%localIP|%X{traceId}|%.-51200msg|%logger%n
UTF-8
100MB
0
1024
相关定制改造
定制基于TurboFilter的TraceIdTurboFilter
核心是将上下文中的traceID放到LOGBACK的MDC上下文中
核心代码如下：
public class TraceIdTurboFilter extends TurboFilter {
private static final String TRACE_ID = "traceId";
@Override
public FilterReply decide(Marker marker, Logger logger, Level level, String s, Object[] objects, Throwable throwable) {
String traceId = Context.getParameter(TRACE_ID,null);
if (StringUtil.isEmpty(traceId)) {
traceId = MDC.get(TRACE_ID);
if (StringUtil.isEmpty(traceId)) {
MDC.put(TRACE_ID, IdGenerator.createID());
}
} else {
MDC.put(TRACE_ID, traceId);
}
return FilterReply.NEUTRAL;
}
}
上下文实现如下，主要逻辑是将rpc调用上下文或者http调用header中的traceID塞入到线程本地变量中
public class Context {
private static final ThreadLocal CONTEXT = new ThreadLocal() {
@Override
protected Context initialValue() {
return new Context();
}
};
private final Map parameters = new HashMap();
private final Map localValues = new HashMap();
public Context() {
}
public static void setContext(Context context) {
CONTEXT.set(context);
}
public static Context getContext() {
return CONTEXT.get();
}
public static void setParameter(String key, String value) {
CONTEXT.get().parameters.put(key, value);
}
public static String getParameter(String key, String defaultValue) {
return CONTEXT.get().parameters.getOrDefault(key, defaultValue);
}
public static void set(String key, String value) {
CONTEXT.get().localValues.put(key, value);
}
public static String get(String key, String defaultValue) {
return CONTEXT.get().localValues.getOrDefault(key, defaultValue);
}
public static String remove(String key) {
return CONTEXT.get().localValues.remove(key);
}
public static void clear() {
CONTEXT.remove();
}
}
这一块是分布式日志跟踪的核心时间，一个请求从前端进入，生成唯一的traceId，后端各个微服务的请求日志中的该笔请求的日志都是基于该traceID的
后续可以在ELK等平台很容易通过该traceId来找到对应的所有日志
定制日志刷盘处理
基于LOGBACK的RollingFileAppender，如果设置immediateFlush为false，不会立刻刷盘，需要等日志缓冲区满了才会刷盘。这要会导致有些场景，日志不会立刻刷入磁盘，这里需要进行相关改造，增加定制刷盘逻辑
public class SpRollingFileAppender extends RollingFileAppender {
private long idleTimeForceFlush = 0;
private volatile long lastFlushTime = System.currentTimeMillis();
private Timer timer = null;
public long getIdleTimeForceFlush() {
return idleTimeForceFlush;
}
public void setIdleTimeForceFlush(long idleTimeForceFlush) {
this.idleTimeForceFlush = idleTimeForceFlush;
}
@Override
public void start() {
super.start();
if (needForceFlush()) {
timer = new Timer(true);
timer.schedule(new FlushTask(), 1000L, idleTimeForceFlush);
}
}
@Override
protected void subAppend(ILoggingEvent event) {
super.subAppend(event);
if (needForceFlush()) {
lastFlushTime = System.currentTimeMillis();
}
}
private boolean needForceFlush() {
return !isImmediateFlush() && idleTimeForceFlush > 0;
}
private void flush() {
lock.lock();
try {
OutputStream outputStream = getOutputStream();
if (!Objects.isNull(outputStream)) {
outputStream.flush();
}
} catch (Throwable e) {
addStatus(new ErrorStatus("flush IO failure in timer task.", this, e));
} finally {
lock.unlock();
}
}
private class FlushTask extends TimerTask {
@Override
public void run() {
if (System.currentTimeMillis() - lastFlushTime > idleTimeForceFlush) {
flush();
}
}
}
}
定制日志打印相关信息
打印本地IPLocalIPConverter
对文本进行二次处理MessageFilterConverter
获取线程IDThreadIdConverter
因上述基于实现比较简单，不再贴相关代码实现
日志打印最终效果
test_running.log打印效果如下
2023-09-20 17:15:04.374|WARN |test|22|127.0.0.1|205c279beb804a14894d8d33294034c7|removeAbandoned is true, not use in production.|com.alibaba.druid.pool.DruidDataSource
2023-09-20 17:15:04.458|INFO |test|22|127.0.0.1|205c279beb804a14894d8d33294034c7|{dataSource-4} inited|com.alibaba.druid.pool.DruidDataSource
2023-09-20 17:15:04.820|INFO |test|22|127.0.0.1|205c279beb804a14894d8d33294034c7|Started UserPointBalanceMapperTest in 3.69 seconds (JVM running for 5.555)|com.toby.dynamic.data.source.db.dao.UserPointBalanceMapperTest
2023-09-20 17:15:05.050|INFO |test|22|127.0.0.1|205c279beb804a14894d8d33294034c7|changeDataSource to data source=db_w_2|com.toby.dynamic.data.source.db.ShardingDataSourceAspect
2023-09-20 17:15:05.071|INFO |test|22|127.0.0.1|205c279beb804a14894d8d33294034c7|dataSource=db_w_2|com.toby.dynamic.data.source.db.ShardingDataSource
2023-09-20 17:15:05.138|INFO |test|22|127.0.0.1|205c279beb804a14894d8d33294034c7|changeDataSource end.|com.toby.dynamic.data.source.db.ShardingDataSourceAspect
2023-09-20 17:15:05.138|INFO |test|22|127.0.0.1|205c279beb804a14894d8d33294034c7|UserPointBalance{id=null, uid=3, type='2', value=100, expireTime=Sun Dec 31 00:00:00 CST 2023, country='CN'}|com.toby.dynamic.data.source.db.dao.UserPointBalanceMapperTest
