Logback 添加请求追踪ID
前言
Logback MDC 简介
MDC 的功能和ThreadLocal一致
配置
logback.xml
修改 pattern,在中间添加 %X{TRACE_ID},表示输出日志时 会从 MDC(ThreadLocal)中获取当前线程的TRACE_ID属性
因为 TRACE_ID 是我自定义的所以现在 MDC中没有,所以需要在线程启动时,给他添加 TRACE_ID
<?xml version="1.0" encoding="UTF-8"?>
<configuration debug="false">
<!--设置存储路径变量-->
<property name="LOG_HOME" value="./log"/>
<!--控制台输出appender-->
<appender name="console" class="ch.qos.logback.core.ConsoleAppender">
<!--设置输出格式-->
<encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
<!--格式化输出：%d表示日期，%thread表示线程名，%-5level：级别从左显示5个字符宽度%msg：日志消息，%n是换行符-->
<pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] [%X{TRACE_ID}] %-5level %logger{50} - %msg%n</pattern>
<!--设置编码-->
<charset>UTF-8</charset>
</encoder>
</appender>
<!--指定基础的日志输出级别-->
<root level="INFO">
<!--appender将会添加到这个loger-->
<appender-ref ref="console"/>
</root>
</configuration>
拦截器配置
自定义请求追踪拦截器
用户访问时拦截器会拦截用户请求,然后在当前用户线程MDC中存入 TRACE_ID
/**
* 请求追踪 拦截器
* @author ratel
* @date 2020-05-21
*/
@Slf4j
@Component
public class TraceInterceptor implements HandlerInterceptor {
/** 雪花ID */
@Autowired
private SnowflakeIdWorker snowflakeIdWorker;
private static final ReentrantLock lock = new ReentrantLock();
@Override
public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler) throws Exception {
MDC.put("TRACE_ID", snowflakeIdWorker.nextId() + "");
return true;
}
@Override
public void postHandle(HttpServletRequest request, HttpServletResponse response, Object handler, ModelAndView modelAndView) throws Exception {
}
@Override
public void afterCompletion(HttpServletRequest request, HttpServletResponse response, Object handler, Exception ex) throws Exception {
MDC.clear();
}
}
配置拦截规则
/**
* @author ratel
* @date 2020-05-21
*/
@Slf4j
@Configuration
public class WebConfiguration extends WebMvcConfigurationSupport {
@Autowired
private TraceInterceptor traceInterceptor;
@Autowired
private ShiroProperty shiroProperty;
@Autowired
private ResourceProperties resourceProperties;
/**
* @Description 添加拦截器
* @Author ratel
* @Date 2020-07-07
* @param registry
* @return void
**/
@Override
protected void addInterceptors(InterceptorRegistry registry) {
List<String> exclude = shiroProperty.getExclude();
log.debug("TraceInterceptor exclude url {}",exclude.toString());
//配置拦截器的过滤规则 和 拦截规则
registry.addInterceptor(traceInterceptor).excludePathPatterns(exclude).addPathPatterns("/**");
}
/**
* @Description 解决静态资源404
* @Author ratel
* @Date 2020-07-07
* @param registry
* @return void
**/
@Override
protected void addResourceHandlers(ResourceHandlerRegistry registry) {
//添加静态资源路径由静态资源处理器处理
registry.addResourceHandler("/**").addResourceLocations(resourceProperties.getStaticLocations());
super.addResourceHandlers(registry);
}
}
example
用户访问 -> TraceInterceptor 拦截请求,并添加TRACE_ID > 日志输出，并附带TRADE_ID
小结
经过上面的配置,已经能满足一般情况的使用了,但是遇到异步处理时就会出现问题，因为MDC基于TreadLocal 当A线程通过线程池将任务传递给B线程时,由于 ThreadLocal 是线程独享的，所以 TRACE_ID 并不会传递给B线程
多线程问题
解决方案（重写线程池）
线程池
目的: 重写线程池是为了在主线程将任务传递给线程池中的线程是,我们通过代码 手动将线程ThreadLocal中的map传递到新的线程中去(map 真正存放TRACE_ID的地方)
package com.ratel.hydra.common.concurrent;
import org.slf4j.MDC;
import org.springframework.scheduling.concurrent.ThreadPoolTaskExecutor;
import java.util.Map;
import java.util.concurrent.Callable;
import java.util.concurrent.Future;
/**
* 线程池 实现传递MDC
* @author ratel
* @date 2020-07-07
*/
public class HydraThreadPoolTaskExecutor extends ThreadPoolTaskExecutor {
private static final long serialVersionUID = 1L;
private boolean useFixedContext = false;
private Map<String, String> fixedContext;
public HydraThreadPoolTaskExecutor() {
super();
}
public HydraThreadPoolTaskExecutor(Map<String, String> fixedContext) {
super();
this.fixedContext = fixedContext;
useFixedContext = (fixedContext != null);
}
private Map<String, String> getContextForTask() {
return useFixedContext ? fixedContext : MDC.getCopyOfContextMap();
}
@Override
public void execute(Runnable command) {
super.execute(wrapExecute(command, getContextForTask()));
}
@Override
public <T> Future<T> submit(Callable<T> task) {
return super.submit(wrapSubmit(task, getContextForTask()));
}
private <T> Callable<T> wrapSubmit(Callable<T> task, final Map<String, String> context) {
return () -> {
Map<String, String> previous = MDC.getCopyOfContextMap();
if (context == null) {
MDC.clear();
} else {
MDC.setContextMap(context);
}
try {
return task.call();
} finally {
if (previous == null) {
MDC.clear();
} else {
MDC.setContextMap(previous);
}
}
};
}
private Runnable wrapExecute(final Runnable runnable, final Map<String, String> context) {
return () -> {
Map<String, String> previous = MDC.getCopyOfContextMap();
if (context == null) {
MDC.clear();
} else {
MDC.setContextMap(context);
}
try {
runnable.run();
} finally {
if (previous == null) {
MDC.clear();
} else {
MDC.setContextMap(previous);
}
}
};
}
}
Spring 线程池配置
目的：被 @Aysnc 修饰的方法会通过该线程池中的线程去执行
/**
* @author ratel
* @date 2020-07-07
*/
@Slf4j
@Configuration
@EnableAsync
public class ThreadPoolConfiguartion {
/**
* @Description spring @Asyn注解 公用线程池
* @Author ratel
* @Date 2020-07-07
**/
@Bean
public ThreadPoolTaskExecutor initCommonThreadPool() {
ThreadPoolTaskExecutor threadPool = new HydraThreadPoolTaskExecutor();
threadPool.setCorePoolSize(2);//核心线程数
threadPool.setMaxPoolSize(4);//最大线程数
threadPool.setKeepAliveSeconds(60);//线程存活时间
threadPool.setQueueCapacity(10000);
threadPool.setAllowCoreThreadTimeOut(false);
threadPool.setThreadNamePrefix("common-thread-");//线程池前缀
threadPool.setRejectedExecutionHandler(new ThreadPoolExecutor.CallerRunsPolicy());//拒绝策略， 调用者执行
return threadPool;
}
}
example
访问日志切面：AccessLogAspect
访问日志服务：AccessLogService （用于存储用户访问日志）
场景：用户访问 Controller 接口时，会被切面拦截，然后通过异步的形式记录下用户的访问
AccessLogAspect
/**
* @author ratel
* @date 2020-05-21
*/
@Slf4j
@Aspect
@Component
public class AccessLogAspect {
@Autowired
private AccessLogService service;
@Pointcut("execution(* com.ratel.hydra..*.controller.*.*(..))")
public void accessLogPointcut(){};
@Pointcut("@annotation(com.ratel.hydra.common.annotation.OperatingInfo)")
public void accessLogAnnoPointcut(){};
@Before("accessLogAnnoPointcut()")
public void before(JoinPoint point) {
AccessLogAdd accessLog = constructLog(point);
service.asyncAdd(accessLog);
log.debug("==>>日志切面：{}",JSON.toJSONString(accessLog));
}
private AccessLogAdd constructLog(JoinPoint point){
MethodSignature method = (MethodSignature) point.getSignature();
HttpServletRequest req = getHttpServletRequest();
String ip = getIP(req);
OperatingInfo annotation = point.getTarget().getClass().getAnnotation(OperatingInfo.class);
AccessLogAdd accessLog = new AccessLogAdd()
.setAssessUrl(getUrl(req))
.setIp(ip)
.setOperationContent(annotation == null ? getOperationContent(method) : getOperationContent(method) + annotation.tag())
.setOperationParam(getOperationParam(point))
.setSourceUrl(getSourceUrl(req))
.setUserId(getUserId())
.setLocation(IpUtil.getCityInfo(ip))
.setSourceUrl(WebUtil.getReferer(req))
.setOperatingSystem(WebUtil.getOperatingSystem(req))
.setAccessDevice(WebUtil.getBrowers(req));
log.info(accessLog.getOperationContent());
return accessLog;
}
private HttpServletRequest getHttpServletRequest(){
RequestAttributes requestAttributes = RequestContextHolder.currentRequestAttributes();
return (HttpServletRequest) requestAttributes.resolveReference(RequestAttributes.REFERENCE_REQUEST);
}
private String getUrl(HttpServletRequest request){
return request.getRequestURL().toString();
}
private String getIP(HttpServletRequest request){
return IpUtil.getIpAddr(request);
}
private String getOperationParam(JoinPoint point){
Object[] args = point.getArgs();
if (args == null){
return "";
}
List<Object> list = new ArrayList<>(args.length);
if (args.length == 1 && !WebUtil.isWebObject(args[0])){
return JSON.toJSONString(args[0]);
}
for (Object arg : args) {
if (!WebUtil.isWebObject(arg)){
list.add(arg);
}
}
return JSON.toJSONString(list);
}
private String getOperationContent(MethodSignature method){
OperatingInfo annotation = method.getMethod().getAnnotation(OperatingInfo.class);
if (annotation == null){
return method.getName();
}
String content = annotation.operation();
return content;
}
private String getSourceUrl(HttpServletRequest request){
return "";
}
private Long getUserId(){
Subject subject = SecurityUtils.getSubject();
Object principal = subject.getPrincipal();
return principal == null ? -1L : ((User)principal).getId();
}
}
AccessLogService
/**
* @author ratel
* @date 2020-05-21
*/
public interface AccessLogService {
/**
* @Description 增加一条访问记录
* @Author ratel
* @Date 2020-05-21
* @param add
* @return void
**/
void add(AccessLogAdd add);
/**
* @Description 异步增加一条访问记录
* @Author ratel
* @Date 2020-07-07
* @param add
* @return void
**/
@Async
void asyncAdd(AccessLogAdd add);
}
测试
如图所示 两个不同的线程,一个是 tomcat的线程,一个是我自定义的线程池生产出来的线程，使用的 TRACE_ID 是同一个
推荐
项目日志 可以通过 MongoDB 或搭建 ELK 收集起来，配合请求追踪，线上排查问题非常方便
735
被折叠的 条评论
为什么被折叠?
到【灌水乐园】发言
