實現一個請求的所有日誌都擁有同一個標識，簡稱：實現基於RPC呼叫的輕量服務追蹤。
阿新 • • 發佈：2018-12-25
目錄
第一步：消費者專案裡：使用的日誌工具是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...");
}
}