JAVA通过Logback实现日志traceId功能
1、背景
在项目中随着项目的业务越来越复杂，以及项目的微服务化等，导致平常的项目中出现如:同一次操作日志散乱等现象，对通过查询日志的方式排查问题造成极大困扰.因此迫切需要一种可以追溯当前链路操作日志的手段.
为什么需要实现traceId呢?traceId也是属于追溯当前链路操作日志的一种有效手段.当有效的日志信息不是很明显，我们需要追溯本次操作整个链路的关键信息时,由于日志的散乱，可能在此事上面耗费较大的精力并且结果还可能有误，因此traceId就显得至关重要了。
traceId: 日志中每一次操作都有该次操作的唯一traceId,属于当前操作的所有相关日志都记录了本次的traceId,回溯的时候只需要通过traceId就能获取到指定操作的全链路日志信息.这样可以保证获取的信息都是咱想要的.也节省了不少排查问题的精力
2、目的
通过实现traceId功能,获取当前操作链路的以下日志信息:
a、当前操作http请求伴有traceId的日志信息
b、当前操作java服务端伴有traceId的日志信息
c、当前操作java服务端伴有traceId的dubbo consumer日志信息
d、当前操作java服务端伴有traceId的dubbo provider日志信息
e、其他可以串起来的服务日志信息，如MQ、异步线程等......
3、思路
假设当前项目的请求的链路含有： 前端http调用 -> 后端接受(当前为Java) -> 后端接受处理 -> 发送MQ || 开启异步线程 || 调用RPC接口(本次以dubbo为例)
所以咱只要能将执行链路上每个链路节点信息的通过其可传递性将当前操作的traceId串起来,那么问题就解决了.
4、后端Java方案
当前方案部分可实现目标:
1、前端http请求的入参、响应状态、响应时间等信息
2、调用dubbo provider服务的入参、ip、响应参数、耗时等信息
3、接受dubbo consumer服务的入参、ip、响应参数等信息
4、异步线程的有效信息等
....
当前选用springmvc+spring+dubbo作为框架模板，日志输出使用logback.
核心思想利用slf4j的MDC进行服务端日志串联操作.
5、核心实现:
step1：后端连接前端http处理
a) web.xml中配置<filter>&&<filter-mapping>,处理指定规则内的请求.
b) 创建HttpAccessDataLogFilter继承OncePerRequestFilter对请求信息进行拦截处理:
①获取前端传递过来的traceId(如果有的话),如果没有，则生成当前操作下的traceId(有很多方式，本方案采用ip地址+进程id+原子计数的方式).
②将traceId放入slf4j的MDC.
③记录所需的日志.
核心代码如下:
web.xml.
<filter>
<filter-name>requestLogFilter</filter-name>
<filter-class>com.toxic.anepoch.common.web.filter.HttpAccessDataLogFilter</filter-class>
<init-param>
<param-name>loggerName</param-name>
<param-value>requestLogFilter</param-value>
</init-param>
</filter>
<filter-mapping>
<filter-name>requestLogFilter</filter-name>
<url-pattern>/*</url-pattern>
</filter-mapping>
HttpAccessDataLogFilter.
String traceID = request.getHeader("TRACE_ID");
if (StringUtils.isBlank(traceID)) {
traceID = TraceIdGenerator.generate();
}
MDC.put(TraceConstants.TOXIC_TRACE_ID, traceID);
//匹配当前请求的url是否需要被过滤 - 如果需要过滤则移除掉traceId
if (UriMatcherUtils.match(excludeUri, request.getRequestURI())) {
try {
filterChain.doFilter(request, response);
} finally {
MDC.remove(TraceConstants.TOXIC_TRACE_ID);
}
return;
}
long start = System.currentTimeMillis();
CachedHttpServletRequestWrapper httpServletRequestWrapper = new CachedHttpServletRequestWrapper(request,
INIT_CACHE_LEN, MAX_CACHE_LEN);
CachedHttpServletResponseWrapper httpServletResponseWrapper = new CachedHttpServletResponseWrapper(response,
INIT_CACHE_LEN, MAX_CACHE_LEN);
try {
filterChain.doFilter(httpServletRequestWrapper, httpServletResponseWrapper);
} finally {
long end = System.currentTimeMillis();
saveLogData(traceID, request, httpServletRequestWrapper, httpServletResponseWrapper, end - start);
MDC.remove(TraceConstants.TOXIC_TRACE_ID);
}
step2：后端当前线程处理
直接使用LOGGER输出想要的数据即可.
测试代码
private static final Logger LOGGER = LoggerFactory.getLogger(TestRemoteController.class);
@Resource
private TestGeneralRemote testGeneralRemote;
@RequestMapping(value = "/remote")
public String testRemote(){
LOGGER.info("测试traceId功能开始......");
LOGGER.info(testGeneralRemote.testRpc("toxic test log ......",Lists.newArrayList("str1","str2")));
return "success";
}
step3：作为dubbo - consumer时候使用
a) 利用dubbo的spi机制,创建DubboConsumerDataLogFilter实现dubbo的filter接口,使用@Activate(group = Constants.CONSUMER)标识当前class.
b) 使用dubbo的RpcContext作为媒介,将当前的traceId传递下去
c) 记录想要搜集的日志信息
核心代码:
DubboConsumerDataLogFilter.
@Override
public Result invoke(Invoker<?> invoker, Invocation invocation) throws RpcException {
RpcContext context = RpcContext.getContext();
context.setAttachment(TraceConstants.TOXIC_TRACE_ID, this.getTraceId());
long start = System.currentTimeMillis();
RpcException ex = null;
Result result = null;
try {
result = invoker.invoke(invocation);
} catch (RpcException e) {
ex = e;
}
long elapsed = System.currentTimeMillis() - start;
//使用logger记录日志
LOGGER.info(this.buildConditionLog(invoker, invocation, elapsed));
if (Objects.nonNull(ex)) {
throw ex;
}
return result;
}
log builder.
/**
* 构建需要打印的consumer log信息
*
* @param currentInvoker invoker
* @param currentInvocation invocation
* @param timeConsume 总耗时
* @return log信息
*/
private String buildConditionLog(Invoker currentInvoker, Invocation currentInvocation, Long timeConsume) {
return DubboConditionLogBuilder
//builder
.builder(RpcContext.getContext())
//build condition
.buildStandardCondition(currentInvoker, currentInvocation, timeConsume)
//build
.build();
}
/**
* 构建标准日志打印
*
* @return this
*/
public DubboConditionLogBuilder buildStandardCondition(Invoker currentInvoker, Invocation currentInvocation, Long timeConsume) {
//调用发起时间
this.buildInvokeTimeCondition()
//traceId
.buildTraceIdCondition()
//总耗时
.buildTimeConsumeCondition(timeConsume)
//ip端口指向
.buildAddressCondition()
//调用provider的service信息
.buildServiceNameCondition(currentInvoker)
//调用provider的method信息
.buildMethodNameCondition(currentInvocation)
//调用方法的方法类型信息
.buildMethodParameterTypesCondition(currentInvocation)
//调用方的入参信息
.buildArgumentsCondition(currentInvocation);
return this;
}
step4：作为dubbo - provider时候使用
a) 利用dubbo的spi机制,创建DubboProviderDataLogFilter实现dubbo的filter,使用@Activate(group = Constants.PROVIDER)标识当前class.
b) 从dubbo的RpcContext中取出traceId，放入当前线程的MDC中
c) 记录想要搜集的日志信息
核心代码：
DubboProviderDataLogFilter.
@Override
public Result invoke(Invoker<?> invoker, Invocation invocation) throws RpcException {
RpcContext rpcContext = RpcContext.getContext();
MDC.put(TraceConstants.TOXIC_TRACE_ID, rpcContext.getAttachment(TraceConstants.TOXIC_TRACE_ID));
long start = System.currentTimeMillis();
RpcException ex = null;
Result result = null;
try {
result = invoker.invoke(invocation);
} catch (RpcException e) {
ex = e;
}
long elapsed = System.currentTimeMillis() - start;
//使用logger记录日志
LOGGER.info(this.buildConditionLog(invoker, invocation, elapsed));
if (Objects.nonNull(ex)) {
throw ex;
}
return result;
}
log builder
/**
* 构建需要打印的provider log信息
*
* @param currentInvoker invoker
* @param currentInvocation invocation
* @param timeConsume 总耗时
* @return log信息
*/
private String buildConditionLog(Invoker currentInvoker, Invocation currentInvocation, Long timeConsume) {
return DubboConditionLogBuilder
//builder
.builder(RpcContext.getContext())
//build condition
.buildStandardCondition(currentInvoker, currentInvocation, timeConsume)
//build
.build();
}
/**
* 构建标准日志打印
*
* @return this
*/
public DubboConditionLogBuilder buildStandardCondition(Invoker currentInvoker, Invocation currentInvocation, Long timeConsume) {
//调用发起时间
this.buildInvokeTimeCondition()
//traceId
.buildTraceIdCondition()
//总耗时
.buildTimeConsumeCondition(timeConsume)
//ip端口指向
.buildAddressCondition()
//调用provider的service信息
.buildServiceNameCondition(currentInvoker)
//调用provider的method信息
.buildMethodNameCondition(currentInvocation)
//调用方法的方法类型信息
.buildMethodParameterTypesCondition(currentInvocation)
//调用方的入参信息
.buildArgumentsCondition(currentInvocation);
return this;
}
step5: 异步线程
开启异步线程的时候将traceId一并放入MDC即可
...
step6: 其他情况
视情况而定,找到可以衔接的点一般都可以衔接上,如mq消息等等......
最后看下效果:
step1、 发送http请求
image.png
step2、查看http-request.log日志信息
image.png
step3、查看dubbo-access-consumer.log日志信息
image.png
查看
step4、查看dubbo-access-provider.log日志信息
image.png
未完待续......
