目录
第一步:消费者项目里:使用的日志工具是logback ,下面看日志配置文件logback-spring.xml内容,重点是:[%thread]:打印日志时获取当前线程的名称
第二步:消费者项目里:写个拦截器,主要是preHandle方法,给当前请求的线程设置一个线程名称
第四步:消费者项目里:写个过滤器,注意当前过滤器实现的dubbo的Filter类,即:com.alibaba.dubbo.rpc.Filter类。不是spring的Filter。
第六步:消费者项目里:你写好了dubbo的Filter之后,就要用,怎么用呢?看下图:
第八步:提供者项目里:日志工具使用的是log4j,虽然与消费者使用的日志工具不同但是不影响。下面看logback-spring.xml内容,重点是:[%t]:打印日志时获取当前线程的名称。
第十一步:提供者项目里:写好了提供者的dubbo Filter之后,就要用,怎么用呢?看下面代码的@service注解的filter属性,将你的logFilter作为filter属性的属性值即可。
第十二步:启动项目,消费者调用提供者,我们可以看到提供者的日志为:
第十四步:转发请尊重原创,请带 原创地址:https://blog.csdn.net/qq_23167527
背景:互联网金融app的后台,非常的频繁调用复杂的借还款流程就会打印很多日志,当出现问题的时候,由于系统间的嵌套调用,我们就可能在一台服务器里的多个项目(甚至多台服务器里的多个项目)去追日志。就算只是一个项目,当请求的频繁时一个请求的日志也可能被不是当前请求的日志无规律插队。所以我们就只能花费更多的时间根据接口名、方法名或参数等数据去查日志。为此,我特意在我当前正在开发的项目里解决了这个问题,让一个请求的所有日志拥有同一个标识。
开发框架:springboot+dubbo+zk
第一步:消费者项目里:使用的日志工具是logback ,下面看日志配置文件logback-spring.xml内容,重点是:[%thread]:打印日志时获取当前线程的名称
<?xml version="1.0" encoding="UTF-8" ?>
<configuration scan="true" scanPeriod="60 seconds" debug="false">
<!-- 控制台设置 -->
<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
<!-- encoder 默认配置为PatternLayoutEncoder -->
<encoder>
<pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %level %c[%L] : %msg%n
</pattern>
</encoder>
</appender>
<!-- * 通配符 设置log打印级别 对所有类有效TRACE, DEBUG, INFO, WARN, ERROR, ALL 和 OFF -->
<root level="INFO">
<appender-ref ref="STDOUT" />
<!-- <appender-ref ref="rollingFileAppender" /> -->
</root>
</configuration>
第二步:消费者项目里:写个拦截器,主要是preHandle方法,给当前请求的线程设置一个线程名称
package com.quanran.third.web.interceptors;
import java.util.Random;
import com.quanran.common.util.RandomUtil;
import lombok.extern.slf4j.Slf4j;
import org.springframework.stereotype.Controller;
import org.springframework.web.servlet.HandlerInterceptor;
import org.springframework.web.servlet.ModelAndView;
import javax.servlet.http.HttpServletRequest;
import javax.servlet.http.HttpServletResponse;
@Controller
@Slf4j
public class ThreadInterceptor implements HandlerInterceptor {
@Override
public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler) {
// 当前线程上下文唯一标示
Thread.currentThread().setName(getRandomStr(12));
return true;
}
@Override
public void postHandle(HttpServletRequest request, HttpServletResponse response, Object handler,
ModelAndView modelAndView) {
}
@Override
public void afterCompletion(HttpServletRequest request, HttpServletResponse response, Object handler, Exception ex) {
}
/**
* 生成指定长度的随机字符串
*
* @len 要生成的字符串的长度
* @return 随机字符串
*/
private String getRandomStr(int length) {
if (length <= 0) {
length = 32;
}
String CHARS = "abcdefghijklmnopqrstuvwxyz0123456789ABCDEFGHIJKLMNOPQRSTUVWXYZ";
StringBuilder sb = new StringBuilder();
for (int i = 0; i < length; i++) {
int index = new Random().nextInt(CHARS.length());
sb.append(CHARS.charAt(index));
}
return sb.toString();
}
}
第三步:消费者项目里:将刚才的拦截器注册
package com.quanran.config.context;
import org.springframework.context.annotation.Configuration;
import org.springframework.web.servlet.config.annotation.InterceptorRegistry;
import org.springframework.web.servlet.config.annotation.WebMvcConfigurerAdapter;
import com.quanran.third.web.interceptors.ErrorInterceptor;
@Configuration
public class InterceptorConfig extends WebMvcConfigurerAdapter {
@Override
public void addInterceptors(InterceptorRegistry registry) {
registry.addInterceptor(new ThreadInterceptor()).addPathPatterns("/**");
super.addInterceptors(registry);
}
}
至此,如果你的项目没有调用别的dubbo服务,只是本项目自身的注入调用,那么你现在启动项目,打印出来的日志就实现了一个请求的日志追踪。如下图,黄色标识的是同一个请求的日志:
第四步:消费者项目里:写个过滤器,注意当前过滤器实现的dubbo的Filter类,即:com.alibaba.dubbo.rpc.Filter类。不是spring的Filter。
package com.quanran.service.consumer;
import java.lang.reflect.Field;
import lombok.extern.slf4j.Slf4j;
import net.sf.json.JSONObject;
import com.alibaba.dubbo.rpc.Filter;
import com.alibaba.dubbo.rpc.Invocation;
import com.alibaba.dubbo.rpc.Invoker;
import com.alibaba.dubbo.rpc.Result;
import com.alibaba.dubbo.rpc.RpcContext;
import com.alibaba.dubbo.rpc.RpcException;
import com.quanran.dubbo.exception.QuanRanException;
/**
* <p>Description: [dubbo的过滤器Filter]</p>
* Created on 2018年9月10日 下午5:50:35
* @author <a href="mailto: [email protected]">全冉</a>
* @version 1.0
* Copyright (c) 2018 全冉技术部
*/
@Slf4j
public class LogFilter implements Filter {
@Override
public Result invoke(Invoker<?> invoker, Invocation invocation) throws RpcException {
/**
* 这个for循环的作用:将消费者里此次请求的线程名称赋值到调用dubbo的参数属性里,由此让dubbo服务里的线程名和消费者统一
*/
for(Object object : invocation.getArguments()){
Field field = getFieldByClasss("traceId",object);// 字符串traceId是此次dubbo请求参数对象里的一个字段属性
if(field != null) {
field.setAccessible(true);// 设置成true的作用就是让我们在用反射时可以对私有变量操作
try {
field.set(object, Thread.currentThread().getName());// field的set方法两个参数:第一个参数是对象,第二个参数是将第一个参数里field字段的终值(终值就是要赋的值)
} catch (IllegalAccessException e) {
e.printStackTrace();
}
}
}
/**
* 拼接dubbo服务的参数成字符串
*/
StringBuffer sb = new StringBuffer();
int index = 1;
// 请求参数的循环拼接
for(Object object : invocation.getArguments()){
// isPrimitive()为true则当前object的类类型是基本类型,比如:byte,char,short,int,long,float,double,boolean和void
if(object.getClass().isPrimitive() ||
"class java.lang.String".equals(object.getClass().toString()) ||
"class java.lang.Boolean".equals(object.getClass().toString())) {
sb.append("参数" + index + " :").append(String.valueOf(object));
if(index != invocation.getArguments().length){
sb.append("\r\n");
}
}else{
// isPrimitive()为false则当前object的类类型不是基本类型的,是Object,是对象
try {
sb.append("参数" + index + " :").append(JSONObject.fromObject(object).toString());
if(index != invocation.getArguments().length){
sb.append("\r\n");
}
}catch (Exception e){
sb.append("参数" + index + " :").append(object.toString());
if(index != invocation.getArguments().length){
sb.append("\r\n");
}
}
}
index ++;
}
/**
* 调取dubbo服务打印调取日志
*/
long start = System.currentTimeMillis();
log.info("RPC调用开始,接口:{} ,方法{} , 参数{}",invoker.getInterface(),invocation.getMethodName(),sb.toString());
Result result = invoker.invoke(invocation);// 继续调用dubbo服务,dubbo服务的响应结果存放在了Result中
String serverIp = RpcContext.getContext().getRemoteHost();// 获取调用的提供者IP地址
if(result.hasException()){
if(result.getException() instanceof QuanRanException){
log.error("RPC({})调用发生异常,errcode = {} , errmsg = {}" ,serverIp,((QuanRanException)result.getException()).getErrorCode(),((QuanRanException)result.getException()).getErrorMessage());
}else{
log.error("RPC({})调用发生异常,{}" ,serverIp,result.getException());
}
}else {
long elapsed = System.currentTimeMillis() - start;
try {
log.info("RPC({})调用结束,返回值{} ,耗时间 {} 毫秒",serverIp,JSONObject.fromObject(result.getValue()).toString(), elapsed);
}catch (Exception e){
log.info("RPC({})调用结束,返回值{} ,耗时间 {} 毫秒",serverIp,result.getValue().toString(), elapsed);
}
}
return result;
}
/**
* <p>Discription:[返回指定的字段名fileName的File对象]</p>
* Created on 2018年9月10日 下午5:48:03
* @param fieldName 指定的字段名
* @param object 当前dubbo调用的参数
* @return Field 返回指定的字段名fileName的File对象
* @author:[全冉]
*/
private Field getFieldByClasss(String fieldName, Object object) {
Field field = null;
Class<?> clazz = object.getClass();
for (; clazz != Object.class; clazz = clazz.getSuperclass()) {// getSuperclass获取普通函数的父类Class对象
try {
field = clazz.getDeclaredField(fieldName);// getDeclaredField获取指定name的类里属性
} catch (Exception e) {
}
}
return field;
}
}
第五步:消费者项目里:写完dubbo的Filter之后,还不算完,一定要在消费者项目的src/main/resources/META-INF下,建立dubbo文件夹,dubbo文件夹下在建立名为"com.alibaba.dubbo.rpc.Filter"的文件,这个文件内容为:logFilter=com.quanran.service.consumer.LogFilter。如图:
第六步:消费者项目里:你写好了dubbo的Filter之后,就要用,怎么用呢?看下图:
我当前的项目里,引入dubbo服务不是走的.xml配置的方式,而是注解的方式。至于注解方式怎么将过滤器作用于dubbo的service,自查。
第七步:消费者项目里:消费者调用dubbo服务
GetOrganizationPorductTypeResp getOrganizationPorductTypeResp = null;
try {
GetOrganizationPorductTypeReq getOrganizationPorductTypeReq = new GetOrganizationPorductTypeReq();
getOrganizationPorductTypeReq.setOrganizationNo(orgNo);
log.info("调取dubbo服务,获取机构下的产品");
getOrganizationPorductTypeResp = organizationServiceFacade.getOrganizationPorductType(getOrganizationPorductTypeReq);
}catch (BusinessException e){
log.error("获取机构下的产品失败, errcode = " + e.getErrorCode()+" , errmsg = " + e.getErrorMessage());
return null;
}
其中,dubbo服务的参数类GetOrganizationPorductTypeReq 如下(在提供者项目里定义的类):
package com.quanran.domain.organization;
import com.quanran.annotation.OrganizationNo;
import com.quanran.annotation.common.NotBlank;
import com.quanran.dubbo.params.BaseReqParams;
import lombok.AllArgsConstructor;
import lombok.Data;
import lombok.NoArgsConstructor;
@Data
@AllArgsConstructor
@NoArgsConstructor
public class GetOrganizationPorductTypeReq extends BaseReqParams {
@OrganizationNo
private String organizationNo;
}
BaseReqParams类如下(在提供者项目里定义的类):
package com.quanran.dubbo.params;
import lombok.Data;
import java.io.Serializable;
@Data
public abstract class BaseReqParams implements Serializable {
private static final long serialVersionUID = 1L;
// 消费者传过来的当前线程名称
private String traceId;
}
第八步:提供者项目里:日志工具使用的是log4j,虽然与消费者使用的日志工具不同但是不影响。下面看logback-spring.xml内容,重点是:[%t]:打印日志时获取当前线程的名称。
第九步:提供者项目里:也要写个dubbo的Filter过滤器,注意当前过滤器实现的dubbo的Filter类,即:com.alibaba.dubbo.rpc.Filter类。不是spring的Filter。内容如下:
package com.quanran.dubbo.filter;
import java.lang.reflect.Field;
import java.util.Random;
import lombok.extern.slf4j.Slf4j;
import com.alibaba.dubbo.rpc.Filter;
import com.alibaba.dubbo.rpc.Invocation;
import com.alibaba.dubbo.rpc.Invoker;
import com.alibaba.dubbo.rpc.Result;
import com.alibaba.dubbo.rpc.RpcContext;
import com.alibaba.dubbo.rpc.RpcException;
import com.quanran.dubbo.exception.BusinessException;
import com.quanran.dubbo.result.BusinessExceptionResultImpl;
@Slf4j
public class LogFilter implements Filter {
@Override
public Result invoke(Invoker<?> invoker, Invocation invocation) throws RpcException {
// 先给当前线程赋个初始随机数,预防调用当前dubbo项目的消费者没有传traceId字段
Thread.currentThread().setName(getRandomStr(8));
// 通过以下for循环,拿到消费者传过来的traceId字段,即 当前请求的线程名称
for(Object object : invocation.getArguments()){
Field field = getFieldByClasss("traceId",object);// 字符串traceId是此次dubbo请求参数对象里的一个字段属性
if(field != null) {
field.setAccessible(true);// 设置成true的作用就是让我们在用反射时可以对私有变量操作
try {
Object traceId = field.get(object);
if(traceId != null) {
Thread.currentThread().setName((String) traceId);// 将当前线程的名称设置成消费者传过来的名称
}
} catch (IllegalAccessException e) {
e.printStackTrace();
}
}
}
String clientIp = RpcContext.getContext().getRemoteHost();// 获取消费者的ip地址
log.info(clientIp + " --->" + invocation.getArguments()[0]);
long l = System.currentTimeMillis();
Result result = invoker.invoke(invocation);// 调用服务的方法
long cost = System.currentTimeMillis() - l;
// 以下代码就是根据返回的数据 打印日志
String backMessage = null;
if(result.hasException()){
if(!(result.getException() instanceof BusinessException)){
result.getException().printStackTrace();
backMessage = result.getException().toString();
result = new BusinessExceptionResultImpl("-1","未知错误");
}else{
backMessage = "errCode = " + ((BusinessException)result.getException()).getErrorCode()+", errMsg = "+((BusinessException)result.getException()).getErrorMessage();
}
}else{
backMessage = result.getValue().toString();
if(backMessage.length() > 500){
backMessage = backMessage.substring(0,500) + " ... ";
}
}
log.info(clientIp + "<--" + backMessage + " cost :" + cost+"\r\n");
if(cost > 2500) {
log.info(clientIp + "<--" + backMessage + " cost :" + cost+" , cost long ! \r\n");
}
return result;
}
/**
* <p>Discription:[返回指定的字段名fileName的File对象]</p>
* Created on 2018年9月10日 下午5:48:03
* @param fieldName 指定的字段名
* @param object 当前dubbo调用的参数
* @return Field 返回指定的字段名fileName的File对象
* @author:[全冉]
*/
private Field getFieldByClasss(String fieldName, Object object) {
Field field = null;
Class<?> clazz = object.getClass();
for (; clazz != Object.class; clazz = clazz.getSuperclass()) {// getSuperclass获取普通函数的父类Class对象
try {
field = clazz.getDeclaredField(fieldName);// getDeclaredField获取指定name的类里属性
} catch (Exception e) {
}
}
return field;
}
/**
* 生成指定长度的随机字符串
*
* @len 要生成的字符串的长度
* @return 随机字符串
*/
private String getRandomStr(int length) {
if (length <= 0) {
length = 32;
}
String CHARS = "abcdefghijklmnopqrstuvwxyz0123456789ABCDEFGHIJKLMNOPQRSTUVWXYZ";
StringBuilder sb = new StringBuilder();
for (int i = 0; i < length; i++) {
int index = new Random().nextInt(CHARS.length());
sb.append(CHARS.charAt(index));
}
return sb.toString();
}
}
第十步:提供者项目里:也要在提供者项目的src/main/resources/META-INF下,建立dubbo文件夹,dubbo文件夹下在建立名为"com.alibaba.dubbo.rpc.Filter"的文件,这个文件内容为:logFilter=com.quanran.dubbo.filter.LogFilter。如图:
第十一步:提供者项目里:写好了提供者的dubbo Filter之后,就要用,怎么用呢?看下面代码的@service注解的filter属性,将你的logFilter作为filter属性的属性值即可。
package com.quanran.dubbo.impl;
import java.util.List;
import lombok.extern.slf4j.Slf4j;
import com.quanran.dubbo.exception.BusinessException;
import org.springframework.beans.factory.annotation.Autowired;
import org.springframework.stereotype.Component;
import com.alibaba.dubbo.config.annotation.Service;
import com.quanran.domain.OrganizationProduct;
import com.quanran.domain.organization.GetOrganizationPorductTypeReq;
import com.quanran.domain.organization.GetOrganizationPorductTypeResp;
import com.quanran.dubbo.IOrganizationServiceFacade;
import com.quanran.service.organization.OrganizationService;
@Slf4j
@Service(version = "1.0.0", filter = "logFilter", timeout = 10000)
@Component
public class OrganizationServiceFacadeImpl implements IOrganizationServiceFacade {
@Autowired
private OrganizationService organizationService;
@Override
public GetOrganizationPorductTypeResp getOrganizationPorductType(
GetOrganizationPorductTypeReq getOrganizationPorductTypeReq)throws BusinessException {
log.info("测试日志:全冉是最帅的...");
GetOrganizationPorductTypeResp getOrganizationPorductTypeResp = new GetOrganizationPorductTypeResp();
List<OrganizationProduct> list = organizationService.getOrganizationPorductType(getOrganizationPorductTypeReq.getOrganizationNo());
getOrganizationPorductTypeResp.setList(list);
return getOrganizationPorductTypeResp;
}
}
第十二步:启动项目,消费者调用提供者,我们可以看到提供者的日志为:
你看,提供者的这个线程名称 是否 与第三步处的消费者线程名称一致?
至此,我们就是实现了一个基于RPC调用的轻量服务追踪功能。
第十三步:请允许我调皮一下,不是都完了了么,为什么还有第十三步?因为上面从消费者到提供者的执行过程都是同步的,那实际开发过程中,不可避免的要碰到一些异步操作。那异步操作打印的日志,是一个新的线程,那么线程名称肯定和之前的同步线程名称不一样,怎么办呢?看下面代码:
package com.quanran;
import lombok.extern.slf4j.Slf4j;
import org.apache.commons.lang.StringUtils;
import org.springframework.scheduling.annotation.Async;
@Slf4j
public class TestClass {
/**
* <p>Discription:[syncMethod方法是一个普通的业务方法:此方法同步执行完众多业务之后,调用了一个异步方法asynMethod,然后返回了success]</p>
* Created on 2018年9月11日 下午3:39:50
* @param args void
* @author:[全冉]
*/
public String syncMethod() {
// 众多业务代码 START...
// ......
// 众多业务代码 END...
log.info("全冉调用异步方法 START...");
asynMethod(Thread.currentThread().getName());
return "success";
}
/**
* <p>Discription:[调用者将自己的同步线程名称传过来,我们只需要将异步线程名称设置成和同步线程一样的名字,那么异步线程打印的日志就拥有和同步线程一样的标识了]</p>
* Created on 2018年9月11日 下午3:41:57
* ps:实际开发中,异步方法不可能和调用方法在同一个Class中,如果在同一个java类中,那么异步注解@Async不会起作用。我在这里这么用只是为了方便。
* @param traceId void
* @author:[全冉]
*/
@Async
public void asynMethod(String traceId) {
log.info("异步方法 START...");
if(StringUtils.isNotEmpty(traceId)){
Thread.currentThread().setName(traceId);
}
// 众多业务代码 START...
// ......
// 众多业务代码 END...
log.info("异步方法 END...");
}
}