前言
在大型系统运维中，很大程度上是需要依赖日志的。在java大型web工程中，一般都会使用slf4j+logback这一个组合来实现日志的管理。
logback中很多现成的占位符可以可以直接使用，比如线程号【%t】、时间【%d】、日志等级【%p】，更多详细的占位符可以参考后文的占位符总结。
实际应用中，仅仅使用这些已经存在的占位符可能不够，比如我想给我的日志加一个traceId，通过这个traceId我可以快速的定位到我这个请求的所有日志，方便日志追踪。
针对日志中自定义占位符，logback提供了两种解决方案。下面分别来介绍一下
自定义traceId占位符
使用MDC
mdc的全称是Mapped Diagnostic Context，是Logback日志框架中的一个功能，它允许你在同一个线程的执行路径上设置一系列的上下文信息（即键值对），这些上下文信息可以自动地添加到日志输出中
logback.xml配置
<?xml version="1.0" encoding="UTF-8"?>
<configuration scan="true" scanPeriod="60 seconds" debug="false">
<contextName>${APP_NAME}</contextName>
<property name="APP_NAME" value="MouseDemo"/>
<property name="LOG_PATH" value="./system_log/MouseDemo"/>
<property name="CONSOLE_LOG_PATTERN"
value="%d | %X{traceId}| %highlight(%-5level) | %boldYellow(%thread) | %boldGreen(%logger) | %msg%n"/>
<!--输出到控制台-->
<appender name="console" class="ch.qos.logback.core.ConsoleAppender">
<encoder>
<pattern>${CONSOLE_LOG_PATTERN}</pattern>
<charset>UTF-8</charset>
</encoder>
</appender>
<root level="info">
<appender-ref ref="console"/>
</root>
</configuration>在logback中，自定义的占位符是通过%X{配置的键}来获取的
设置MDC
在web工程中，设置traceId的时机很重要，一般是放在拦截器中。
自定义一个拦截器
package com.tml.mouseDemo.config;
import cn.hutool.core.lang.UUID;
import lombok.extern.slf4j.Slf4j;
import org.slf4j.MDC;
import org.springframework.web.servlet.HandlerInterceptor;
import javax.servlet.http.HttpServletRequest;
import javax.servlet.http.HttpServletResponse;
import static com.tml.mouseDemo.constants.CommonConstants.TRACE_ID;
@Slf4j
public class TraceInterceptor implements HandlerInterceptor {
@Override
public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler) throws Exception {
String traceId = UUID.fastUUID().toString(true);
log.info("TraceInterceptor preHandle,generate traceId is:{}", traceId);
MDC.put(TRACE_ID, traceId);
return true;
}
@Override
public void afterCompletion(HttpServletRequest request, HttpServletResponse response, Object handler, Exception ex) throws Exception {
log.info("TraceInterceptor afterCompletion,ready to clean traceId:{}", MDC.get(TRACE_ID));
MDC.remove(TRACE_ID);
}
}
注册拦截器
package com.tml.mouseDemo.config;
import org.springframework.context.annotation.Bean;
import org.springframework.context.annotation.Configuration;
import org.springframework.http.converter.HttpMessageConverter;
import org.springframework.http.converter.StringHttpMessageConverter;
import org.springframework.web.servlet.config.annotation.InterceptorRegistry;
import org.springframework.web.servlet.config.annotation.WebMvcConfigurationSupport;
import org.springframework.web.servlet.config.annotation.WebMvcConfigurer;
import java.nio.charset.Charset;
import java.util.List;
@Configuration
public class WebAppConfig implements WebMvcConfigurer {
@Bean
public HttpMessageConverter<String> responseBodyConverter() {
StringHttpMessageConverter stringHttpMessageConverter = new StringHttpMessageConverter(Charset.forName("UTF-8"));
return stringHttpMessageConverter;
}
@Override
public void configureMessageConverters(List<HttpMessageConverter<?>> converters) {
converters.add(responseBodyConverter());
}
@Override
public void addInterceptors(InterceptorRegistry registry) {
registry.addInterceptor(new TraceInterceptor()).addPathPatterns("/**");
registry.addInterceptor(new RequestInterceptor()).addPathPatterns("/**");
}
}
演示案例
经过上面两步的配置，日志上就会额外多一个traceId了
先定义一个service类
package com.tml.mouseDemo.service;
import lombok.extern.slf4j.Slf4j;
import org.springframework.stereotype.Service;
@Service
@Slf4j
public class TraceService {
public void trace(String type) throws InterruptedException {
log.info("trace start,type:{}", type);
Thread.sleep(1000L);
log.info("trace end");
}
}
定义一个restful接口
package com.tml.mouseDemo.controller;
import com.tml.mouseDemo.constants.CommonResponse;
import com.tml.mouseDemo.service.TraceService;
import lombok.extern.slf4j.Slf4j;
import org.springframework.beans.factory.annotation.Autowired;
import org.springframework.web.bind.annotation.PostMapping;
import org.springframework.web.bind.annotation.RestController;
import java.util.concurrent.Executor;
import java.util.concurrent.ThreadPoolExecutor;
@RestController
@Slf4j
public class TraceController {
@Autowired
private TraceService traceService;
@PostMapping("/trace")
public CommonResponse<String> trace(String type) throws InterruptedException {
log.info("trace type:{}", type);
traceService.trace(type);
return CommonResponse.success("success");
}
}
这里的案例是单线程，看下运行结果
日志中，确实是多了一个traceId，符合预期
不过MDC有其局限性，仅支持单线程的数据传递。因为其底层是基于ThreadLocal来实现的，如下图
局限性
下面来看一下再多线程环境下，使用MDC会有什么样的效果
package com.tml.mouseDemo.controller;
import com.tml.mouseDemo.constants.CommonResponse;
import com.tml.mouseDemo.service.TraceService;
import lombok.extern.slf4j.Slf4j;
import org.springframework.beans.factory.annotation.Autowired;
import org.springframework.web.bind.annotation.PostMapping;
import org.springframework.web.bind.annotation.RestController;
import java.util.concurrent.Executor;
import java.util.concurrent.ThreadPoolExecutor;
@RestController
@Slf4j
public class TraceController {
@Autowired
private ThreadPoolExecutor executor;
@Autowired
private Executor ttlExecutor;
@Autowired
private TraceService traceService;
@PostMapping("/traceWithThread")
public CommonResponse<String> traceWithThread(String type) throws InterruptedException {
log.info("traceWithThread type:{}", type);
traceService.trace(type);
//模拟异步发短信
new Thread(() -> {
try {
Thread.sleep(2000);
String sendMsg = "hello world";
log.info("sendMsg:{}", sendMsg);
} catch (Exception e) {
log.error("traceWithThread occur error", e);
}
}, "trace--001").start();
return CommonResponse.success("success");
}
}
这里通过在主线程中new一个子线程来模拟多线程，运行一下看下结果
从图中可以看出，子线程的日志中是没有输出traceId的，这个就是MDC的局限性。看过前文阿里巴巴TransmittableThreadLocal使用指南的朋友们应该知道，这种new出来的线程不支持，那么使用线程池也肯定是不支持数据传递。
使用自定义Converter
相比MDC，使用自定义的Converter就会显得更加的灵活了，看下使用自定义的Converter的使用流程
定义traceId的存取
package com.tml.mouseDemo.config;
import com.alibaba.ttl.TransmittableThreadLocal;
public class TraceContext {
private static final ThreadLocal<String> TRACE_CONTEXT = new TransmittableThreadLocal<>();
public static String get() {
return TRACE_CONTEXT.get();
}
public static void set(String age) {
TRACE_CONTEXT.set(age);
}
public static void clean() {
if (TRACE_CONTEXT.get() != null) {
TRACE_CONTEXT.remove();
}
}
}
MDC使用的是ThreadLocalL来存储，我们这里自定义采用阿里巴巴的TransmittableThreadLocal，为什么要使用这个，详细的可以参考这篇博文阿里巴巴TransmittableThreadLocal使用指南
定义Converter
package com.tml.mouseDemo.core.log;
import ch.qos.logback.classic.pattern.ClassicConverter;
import ch.qos.logback.classic.spi.ILoggingEvent;
import com.tml.mouseDemo.config.TraceContext;
import java.util.Optional;
public class TraceIdConverter extends ClassicConverter {
@Override
public String convert(ILoggingEvent iLoggingEvent) {
return Optional.ofNullable(TraceContext.get()).orElse("");
}
}
拦截器调整
package com.tml.mouseDemo.config;
import cn.hutool.core.lang.UUID;
import lombok.extern.slf4j.Slf4j;
import org.springframework.web.servlet.HandlerInterceptor;
import javax.servlet.http.HttpServletRequest;
import javax.servlet.http.HttpServletResponse;
@Slf4j
public class TraceInterceptor implements HandlerInterceptor {
@Override
public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler) throws Exception {
String traceId = UUID.fastUUID().toString(true);
log.info("TraceInterceptor preHandle,generate traceId is:{}", traceId);
TraceContext.set(traceId);
return true;
}
@Override
public void afterCompletion(HttpServletRequest request, HttpServletResponse response, Object handler, Exception ex) throws Exception {
log.info("TraceInterceptor afterCompletion,ready to clean traceId:{}", TraceContext.get());
TraceContext.clean();
}
}
改成从TraceContext中获取traceId，拦截器的注册和上文的保持一致。
注册Converter
<conversionRule conversionWord="traceId" converterClass="com.tml.mouseDemo.core.log.TraceIdConverter"/>logback.xml配置
<?xml version="1.0" encoding="UTF-8"?>
<configuration scan="true" scanPeriod="60 seconds" debug="false">
<conversionRule conversionWord="traceId" converterClass="com.tml.mouseDemo.core.log.TraceIdConverter"/>
<contextName>${APP_NAME}</contextName>
<property name="APP_NAME" value="MouseDemo"/>
<property name="LOG_PATH" value="./system_log/MouseDemo"/>
<property name="CONSOLE_LOG_PATTERN"
value="%d | %traceId| %highlight(%-5level) | %boldYellow(%thread) | %boldGreen(%logger) | %msg%n"/>
<!--输出到控制台-->
<appender name="console" class="ch.qos.logback.core.ConsoleAppender">
<encoder>
<pattern>${CONSOLE_LOG_PATTERN}</pattern>
<charset>UTF-8</charset>
</encoder>
</appender>
<root level="info">
<appender-ref ref="console"/>
</root>
</configuration>这里直接使用注册的Converter的traceId来作为占位符，而不是使用%X{键}来获取traceId
演示案例
直接new线程
代码案例和MDC中使用new创建线程一样，直接看下运行结果
子线程的日志中有traceId，并且是和父线程的traceId保持一致，达到预期
使用线程池
为了达到演示效果，我这里定义了两个线程池
package com.tml.mouseDemo.config;
import com.alibaba.ttl.threadpool.TtlExecutors;
import com.google.common.util.concurrent.ThreadFactoryBuilder;
import com.google.gson.Gson;
import com.google.gson.GsonBuilder;
import lombok.extern.slf4j.Slf4j;
import org.springframework.context.annotation.Bean;
import org.springframework.context.annotation.Configuration;
import java.util.concurrent.*;
@Slf4j
@Configuration
public class CommonConfig {
Thread.UncaughtExceptionHandler exceptionHandler = (Thread t, Throwable e) -> {
log.info("current thread occurs error！", e);
};
@Bean
public ThreadPoolExecutor executor() {
ThreadFactory threadFactory = new ThreadFactoryBuilder().
setUncaughtExceptionHandler(exceptionHandler).
setNameFormat("mouse-worker-%d").build();
int processors = Runtime.getRuntime().availableProcessors();
log.info("processors:{}", processors);
ThreadPoolExecutor executor = new ThreadPoolExecutor(1,
processors * 2,
0L,
TimeUnit.MILLISECONDS,
new LinkedBlockingDeque<>(1000),
threadFactory,
new ThreadPoolExecutor.AbortPolicy());
return executor;
}
/**
* 使用阿里的 TransmittableThreadLocal 装饰线程池
* @return
*/
@Bean
public Executor ttlExecutor() {
ThreadFactory threadFactory = new ThreadFactoryBuilder().
setUncaughtExceptionHandler(exceptionHandler).
setNameFormat("mouse-worker-ttl-%d").build();
int processors = Runtime.getRuntime().availableProcessors();
log.info("processors:{}", processors);
ThreadPoolExecutor executor = new ThreadPoolExecutor(1,
processors * 2,
0L,
TimeUnit.MILLISECONDS,
new LinkedBlockingDeque<>(1000),
threadFactory,
new ThreadPoolExecutor.AbortPolicy());
Executor ttlExecutor = TtlExecutors.getTtlExecutor(executor);
return ttlExecutor;
}
}
这里线程池的核心线程数设置为1，是为了方便测试，和这篇文章的思路一致web项目国际化指南
测试代码
package com.tml.mouseDemo.controller;
import com.tml.mouseDemo.constants.CommonResponse;
import com.tml.mouseDemo.service.TraceService;
import lombok.extern.slf4j.Slf4j;
import org.springframework.beans.factory.annotation.Autowired;
import org.springframework.web.bind.annotation.PostMapping;
import org.springframework.web.bind.annotation.RestController;
import java.util.concurrent.Executor;
import java.util.concurrent.ThreadPoolExecutor;
@RestController
@Slf4j
public class TraceController {
@Autowired
private ThreadPoolExecutor executor;
@Autowired
private Executor ttlExecutor;
@Autowired
private TraceService traceService;
@PostMapping("/traceWithThreadPool")
public CommonResponse<String> traceWithThreadPool(String type) throws InterruptedException {
log.info("traceWithThreadPool type:{}", type);
traceService.trace(type);
//模拟异步发短信
executor.execute(() -> {
try {
Thread.sleep(2000);
String sendMsg = "hello world";
log.info("sendMsg:{}", sendMsg);
} catch (Exception e) {
log.error("traceWithThreadPool occur error", e);
}
});
//模拟异步发短信
ttlExecutor.execute(() -> {
try {
Thread.sleep(2000);
String sendMsg = "hello world";
log.info("sendMsg:{}", sendMsg);
} catch (Exception e) {
log.error("traceWithThreadPool occur error", e);
}
});
return CommonResponse.success("success");
}
}
运行两次，看下效果
可以看到，使用ttl装饰的线程池的日志是正常的，使用普通的线程池的日志的traceId错乱了，这个也是尤其需要注意的点。
总结
在logback中，可以使用多种方式来自定义占位符，通常一般的做法主要是上面两种。使用MDC的方式就是简单，不过他的缺陷也是显而易见的，就是他不支持多线程的数据传递。
所以，如果你的项目中想要自定义占位符，强烈建议使用自定义Convertor的方式。详细的代码已上传至github，欢迎前来围观我的github
常见的日志占位符总结
这里总结下logback中常见的占位符，欢迎补充
| 占位符名称 | 占位符含义 | 备注 |
| %d | 日期和时间 | %d{HH:mm:ss.SSS} %d{yyyy-MM-dd HH:mm:ss} 可以自定义时间的格式 |
| %t | 线程名称 | |
| %p | 日志的优先级 | |
| %c | 日志记录器名称 | 一般表示类名，可以%c{20}，可以通过 这样来设置类名的最大长度 |
| %m | 日志消息 | |
| %n | 换行符 | |
| %L | 日志行号 | |
| %X{key} | 代表 MDC中存储的 key 对应的信息 | 不建议使用，不支持多线程 |
![[c语言日寄]内存初阶：大端字节序和小端字节序](https://i-blog.csdnimg.cn/direct/556c5a2c798045c6aeacdb24ace3e13e.gif#pic_center)
