痛点
解决
MDC
原理
Logback 占位符
痛点
查线上日志时,同一个 Pod 内多线程日志交错,很难追踪每个请求对应的日志信息。
日志收集工具将多个 Pod 的日志收集到同一个数据库中后,情况就更加混乱不堪了。
解决
TraceId + MDC
MDC:
https://logback.qos.ch/manual/mdc.html
前端每次请求时,添加 X-App-Trace-Id 请求头,X-App-Trace-Id 值的生成方式可以选择【时间戳 + UUID】,保证 traceId 的唯一性。
后端在 TraceIdFilter 中取出 X-App-Trace-Id 的值:String traceId = httpServletRequest.getHeader(TRACE_ID_HEADER_KEY)。如果请求没有携带 X-App-Trace-Id 请求头,后端服务可以使用 UUID 或者 Snowflake 算法生成一个 traceId。
将 traceId 塞到 slf4j MDC 中:MDC.put(MDC_TRACE_ID_KEY, traceId),在 logback pattern 中使用 %X{traceId} 占位符打印 traceId。
publicvoiddoFilter(ServletRequest request, ServletResponse response, FilterChain chain)
throws IOException, ServletException {
HttpServletRequest httpServletRequest = (HttpServletRequest) request;
String traceId = httpServletRequest.getHeader(TRACE_ID_HEADER_KEY);
if (StrUtil.isBlank(traceId)) {
traceId =UUID.randomUUID().toString();
}
MDC.put(MDC_TRACE_ID_KEY, traceId);
try {
chain.doFilter(request, response);
} finally {
MDC.remove(MDC_TRACE_ID_KEY);
}
}
<?xml version="1.0" encoding="UTF-8"?>
<configuration debug="false">
<property name="pattern" value="[%d{yyyy-MM-dd HH:mm:ss.SSS}] %-5level [%thread] %logger %line [%X{traceId}] [%tid] - %msg%n"/>
整合 Feign
发起服务间调用时,需要将 MDC 中的 traceId 传递到被调用服务。我们项目中统一使用 Feign Client,实现服务间的 HTTP 远程调用,在 Feign RequestInterceptor 中,取出 MDC 中的 traceId,塞到请求头中:requestTemplate.header(TRACE_ID_HEADER_KEY, MDC.get(MDC_TRACE_ID_KEY));
@Override
publicvoidapply(RequestTemplate template) {
template.header(TRACE_ID_HEADER_KEY, MDC.get(MDC_TRACE_ID_KEY));
}
多线程适配
Please note that MDC as implemented by logback- classic assumes that values are placed into the MDC with moderate frequency. Also note that a child thread does not automatically inherit a copy of the mapped diagnostic context of its parent.
在子线程执行任务前,将父线程的 MDC 内容设置到子线程的 MDC 中;在子线程任务执行完成后,清除子线程 MDC 中的内容。
适配 JDK ThreadPoolExecutor:
public classMdcAwareThreadPoolExecutorextendsThreadPoolExecutor {
@Override
publicvoidexecute(Runnable command) {
Map<String, String> parentThreadContextMap =MDC.getCopyOfContextMap();
super.execute(MdcTaskUtils.adaptMdcRunnable(command, parentThreadContextMap));
}
}
适配 Spring TaskDecorator:
@Component
public classMdcAwareTaskDecoratorimplementsTaskDecorator {
@Override
public Runnable decorate(Runnable runnable) {
Map<String, String> parentThreadContextMap =MDC.getCopyOfContextMap();
return MdcTaskUtils.adaptMdcRunnable(runnable, parentThreadContextMap);
}
}
MdcTaskUtils#adaptMdcRunnable():采用装饰者模式,装饰原生的 Runnable runnable 对象,在原生 Runnable 对象执行前,将父线程的 MDC 设置到子线程中,在原生 Runnable 对象执行结束后,清除子线程 MDC 中的内容。
@Slf4j
public abstract classMdcTaskUtils {
publicstatic Runnable adaptMdcRunnable(Runnable runnable, Map<String, String> parentThreadContextMap) {
return () -> {
log.debug("parentThreadContextMap: {}, currentThreadContextMap: {}", parentThreadContextMap,
MDC.getCopyOfContextMap());
if (MapUtils.isEmpty(parentThreadContextMap) ||!parentThreadContextMap.containsKey(MDC_TRACE_ID_KEY)) {
log.debug("can not find a parentThreadContextMap, maybe task is fired using async or schedule task.");
MDC.put(MDC_TRACE_ID_KEY, UUID.randomUUID().toString());
} else {
MDC.put(MDC_TRACE_ID_KEY, parentThreadContextMap.get(MDC_TRACE_ID_KEY));
}
try {
runnable.run();
} finally {
MDC.remove(MDC_TRACE_ID_KEY);
}
};
}
}
整合 Skywalking
Skywalking 官方提供了对 logback 1.x 版本的适配:apm-toolkit-logback-1.x,可以在 logback 中打印 skywalking traceId,可以将 X-App-Trace-Id 和 skywalking traceId 结合起来,方便接口业务和性能问题的排查。
layout 具体实现类选择 TraceIdPatternLogbackLayout。在 logback pattern 中使用 %tid 打印 skywalking traceId。
<?xml version="1.0" encoding="UTF-8"?>
<configuration debug="false">
<property name="pattern" value="[%d{yyyy-MM-dd HH:mm:ss.SSS}] %-5level [%thread] %logger %line [%X{traceId}] [%tid] - %msg%n"/>
<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
<encoder class="ch.qos.logback.core.encoder.LayoutWrappingEncoder">
<layout class="org.apache.skywalking.apm.toolkit.log.logback.v1.x.TraceIdPatternLogbackLayout">
<pattern>${pattern}</pattern>
</layout>
</encoder>
</appender>
TraceIdPatternLogbackLayout 类初始化时,添加了两个 PatternConverter:
tid:使用 LogbackPatternConverter,将 %tid 占位符转换为 skywalking traceId。
sw_ctx:使用 LogbackSkyWalkingContextPatternConverter,将 %sw_ctx 占位符转换为 skywalking context。
public classTraceIdPatternLogbackLayoutextendsPatternLayout {
publicTraceIdPatternLogbackLayout() {
}
static {
defaultConverterMap.put("tid", LogbackPatternConverter. class.getName());
defaultConverterMap.put("sw_ctx", LogbackSkyWalkingContextPatternConverter. class.getName());
}
}
LogbackPatternConverter#convert() 方法写死了返回 "TID: N/A",这是怎么回事呢?
public classLogbackPatternConverterextends classicConverter {
publicLogbackPatternConverter() {
}
publicStringconvert(ILoggingEvent iLoggingEvent) {
return"TID: N/A";
}
}
启动 Java 应用时,指定 java agent 启动参数 -javaagent:-javaagent:/opt/tools/skywalking-agent.jar。skywalking agent 会代理 LogbackPatternConverter 类,重写 convert() 方法的逻辑。
package org.apache.skywalking.apm.toolkit.log.logback.v1.x;
import ch.qos.logback. classic.pattern. classicConverter;
import ch.qos.logback. classic.spi.ILoggingEvent;
import java.lang.reflect.Method;
import org.apache.skywalking.apm.agent.core.plugin.interceptor.enhance.EnhancedInstance;
import org.apache.skywalking.apm.agent.core.plugin.interceptor.enhance.InstMethodsInter;
import org.apache.skywalking.apm.toolkit.log.logback.v1.x.LogbackPatternConverter$auxiliary$pJ6Zrqzi;
public classLogbackPatternConverter
extends classicConverter
implementsEnhancedInstance {
private volatile Object _$Enhanced classField_ws;
publicstatic volatile /* synthetic */ InstMethodsInter delegate$mo3but1;
privatestatic final /* synthetic */ Method cachedValue$oeLgRjrq$u5j8qu3;
publicStringconvert(ILoggingEvent iLoggingEvent) {
return (String)delegate$mo3but1.intercept(this, newObject[]{iLoggingEvent}, newLogbackPatternConverter$auxiliary$pJ6Zrqzi(this, iLoggingEvent), cachedValue$oeLgRjrq$u5j8qu3);
}
private/* synthetic */Stringconvert$original$T8InTdln(ILoggingEvent iLoggingEvent) {
/*34*/return"TID: N/A";
}
@Override
publicvoidsetSkyWalkingDynamicField(Object object) {
this._$Enhanced classField_ws= object;
}
@Override
publicObjectgetSkyWalkingDynamicField() {
returnthis._$Enhanced classField_ws;
}
static {
classLoader.getSystem classLoader().load class("org.apache.skywalking.apm.dependencies.net.bytebuddy.dynamic.Nexus").getMethod("initialize", class. class, Integer.TYPE).invoke(null, LogbackPatternConverter. class, -1942176692);
cachedValue$oeLgRjrq$u5j8qu3 = LogbackPatternConverter. class.getMethod("convert", ILoggingEvent. class);
}
final /* synthetic */Stringconvert$original$T8InTdln$accessor$oeLgRjrq(ILoggingEvent iLoggingEvent) {
returnthis.convert$original$T8InTdln(iLoggingEvent);
}
}
MDC 原理
MDC 在 slf4j-api jar 包中,MDC 是 slf4j 的规范,对 MDC 的所有操作都会落到 MDCAdapter 接口的方法上。
public classMDC {
static final StringNULL_MDCA_URL="http://www.slf4j.org/codes.html#null_MDCA";
static final StringNO_STATIC_MDC_BINDER_URL="http://www.slf4j.org/codes.html#no_static_mdc_binder";
static MDCAdapter mdcAdapter;
publicstaticvoidput(String key, String val) throws IllegalArgumentException {
if (key ==null) {
thrownewIllegalArgumentException("key parameter cannot be null");
}
if (mdcAdapter ==null) {
thrownewIllegalStateException("MDCAdapter cannot be null. See also "+NULL_MDCA_URL);
}
mdcAdapter.put(key, val);
}
}
MDCAdapter 是 slf4j 提供的 MDC 适配器接口,也就是 MDC 的规范。任何日志框架想要使用 MDC 功能,需要遵守 MDCAdapter 接口接口规范,实现接口中的方法。
// This interface abstracts the service offered by various MDC implementations.
publicinterfaceMDCAdapter {
publicvoidput(String key, String val);
publicStringget(String key);
}
Logback 日志框架提供了对 MDCAdapter 的适配:LogbackMDCAdapter,底层采用 ThreadLocal 实现。
public classLogbackMDCAdapterimplementsMDCAdapter {
// The internal map is copied so as
// We wish to avoid unnecessarily copying of the map. To ensure
// efficient/timely copying, we have a variable keeping track of the last
// operation. A copy is necessary on 'put' or 'remove' but only if the last
// operation was a 'get'. Get operations never necessitate a copy nor
// successive 'put/remove' operations, only a get followed by a 'put/remove'
// requires copying the map.
// See http://jira.qos.ch/browse/LOGBACK-620 for the original discussion.
// We no longer use CopyOnInheritThreadLocal in order to solve LB classIC-183
// Initially the contents of the thread local in parent and child threads
// reference the same map. However, as soon as a thread invokes the put()
// method, the maps diverge as they should.
final ThreadLocal<Map<String, String>> copyOnThreadLocal =newThreadLocal<Map<String, String>>();
privatestatic final int WRITE_OPERATION=1;
privatestatic final int MAP_COPY_OPERATION=2;
// keeps track of the last operation performed
final ThreadLocal<Integer> lastOperation =newThreadLocal<Integer>();
publicvoidput(String key, String val) throws IllegalArgumentException {
if (key ==null) {
thrownewIllegalArgumentException("key cannot be null");
}
Map<String, String> oldMap = copyOnThreadLocal.get();
Integer lastOp =getAndSetLastOperation(WRITE_OPERATION);
if (wasLastOpReadOrNull(lastOp) || oldMap ==null) {
Map<String, String> newMap =duplicateAndInsertNewMap(oldMap);
newMap.put(key, val);
} else {
oldMap.put(key, val);
}
}
publicStringget(String key) {
final Map<String, String> map = copyOnThreadLocal.get();
if ((map !=null) && (key !=null)) {
return map.get(key);
} else {
returnnull;
}
}
}
Logback 占位符
PatternLayout 类初始化时,设置了 logback 常用占位符对应的 Converter。
public classPatternLayoutextendsPatternLayoutBase<ILoggingEvent> {
publicstatic final Map<String, String>DEFAULT_CONVERTER_MAP=newHashMap<String, String>();
publicstatic final Map<String, String>CONVERTER_ class_TO_KEY_MAP=newHashMap<String, String>();
/**
* @deprecated replaced by DEFAULT_CONVERTER_MAP
*/
publicstatic final Map<String, String> defaultConverterMap =DEFAULT_CONVERTER_MAP;
publicstatic final StringHEADER_PREFIX="#logback. classic pattern: ";
static {
DEFAULT_CONVERTER_MAP.putAll(Parser.DEFAULT_COMPOSITE_CONVERTER_MAP);
DEFAULT_CONVERTER_MAP.put("d", DateConverter. class.getName());
DEFAULT_CONVERTER_MAP.put("date", DateConverter. class.getName());
CONVERTER_ class_TO_KEY_MAP.put(DateConverter. class.getName(), "date");
DEFAULT_CONVERTER_MAP.put("r", RelativeTimeConverter. class.getName());
DEFAULT_CONVERTER_MAP.put("relative", RelativeTimeConverter. class.getName());
CONVERTER_ class_TO_KEY_MAP.put(RelativeTimeConverter. class.getName(), "relative");
DEFAULT_CONVERTER_MAP.put("level", LevelConverter. class.getName());
DEFAULT_CONVERTER_MAP.put("le", LevelConverter. class.getName());
DEFAULT_CONVERTER_MAP.put("p", LevelConverter. class.getName());
CONVERTER_ class_TO_KEY_MAP.put(LevelConverter. class.getName(), "level");
DEFAULT_CONVERTER_MAP.put("t", ThreadConverter. class.getName());
DEFAULT_CONVERTER_MAP.put("thread", ThreadConverter. class.getName());
CONVERTER_ class_TO_KEY_MAP.put(ThreadConverter. class.getName(), "thread");
DEFAULT_CONVERTER_MAP.put("lo", LoggerConverter. class.getName());
DEFAULT_CONVERTER_MAP.put("logger", LoggerConverter. class.getName());
DEFAULT_CONVERTER_MAP.put("c", LoggerConverter. class.getName());
CONVERTER_ class_TO_KEY_MAP.put(LoggerConverter. class.getName(), "logger");
DEFAULT_CONVERTER_MAP.put("m", MessageConverter. class.getName());
DEFAULT_CONVERTER_MAP.put("msg", MessageConverter. class.getName());
DEFAULT_CONVERTER_MAP.put("message", MessageConverter. class.getName());
CONVERTER_ class_TO_KEY_MAP.put(MessageConverter. class.getName(), "message");
DEFAULT_CONVERTER_MAP.put("C", classOfCallerConverter. class.getName());
DEFAULT_CONVERTER_MAP.put(" class", classOfCallerConverter. class.getName());
CONVERTER_ class_TO_KEY_MAP.put( classOfCallerConverter. class.getName(), " class");
DEFAULT_CONVERTER_MAP.put("M", MethodOfCallerConverter. class.getName());
DEFAULT_CONVERTER_MAP.put("method", MethodOfCallerConverter. class.getName());
CONVERTER_ class_TO_KEY_MAP.put(MethodOfCallerConverter. class.getName(), "method");
DEFAULT_CONVERTER_MAP.put("L", LineOfCallerConverter. class.getName());
DEFAULT_CONVERTER_MAP.put("line", LineOfCallerConverter. class.getName());
CONVERTER_ class_TO_KEY_MAP.put(LineOfCallerConverter. class.getName(), "line");
DEFAULT_CONVERTER_MAP.put("F", FileOfCallerConverter. class.getName());
DEFAULT_CONVERTER_MAP.put("file", FileOfCallerConverter. class.getName());
CONVERTER_ class_TO_KEY_MAP.put(FileOfCallerConverter. class.getName(), "file");
DEFAULT_CONVERTER_MAP.put("X", MDCConverter. class.getName());
DEFAULT_CONVERTER_MAP.put("mdc", MDCConverter. class.getName());
DEFAULT_CONVERTER_MAP.put("ex", ThrowableProxyConverter. class.getName());
DEFAULT_CONVERTER_MAP.put("exception", ThrowableProxyConverter. class.getName());
DEFAULT_CONVERTER_MAP.put("rEx", RootCauseFirstThrowableProxyConverter. class.getName());
DEFAULT_CONVERTER_MAP.put("rootException", RootCauseFirstThrowableProxyConverter. class.getName());
DEFAULT_CONVERTER_MAP.put("throwable", ThrowableProxyConverter. class.getName());
DEFAULT_CONVERTER_MAP.put("xEx", ExtendedThrowableProxyConverter. class.getName());
DEFAULT_CONVERTER_MAP.put("xException", ExtendedThrowableProxyConverter. class.getName());
DEFAULT_CONVERTER_MAP.put("xThrowable", ExtendedThrowableProxyConverter. class.getName());
DEFAULT_CONVERTER_MAP.put("nopex", NopThrowableInformationConverter. class.getName());
DEFAULT_CONVERTER_MAP.put("nopexception", NopThrowableInformationConverter. class.getName());
DEFAULT_CONVERTER_MAP.put("cn", ContextNameConverter. class.getName());
DEFAULT_CONVERTER_MAP.put("contextName", ContextNameConverter. class.getName());
CONVERTER_ class_TO_KEY_MAP.put(ContextNameConverter. class.getName(), "contextName");
DEFAULT_CONVERTER_MAP.put("caller", CallerDataConverter. class.getName());
CONVERTER_ class_TO_KEY_MAP.put(CallerDataConverter. class.getName(), "caller");
DEFAULT_CONVERTER_MAP.put("marker", MarkerConverter. class.getName());
CONVERTER_ class_TO_KEY_MAP.put(MarkerConverter. class.getName(), "marker");
DEFAULT_CONVERTER_MAP.put("property", PropertyConverter. class.getName());
DEFAULT_CONVERTER_MAP.put("n", LineSeparatorConverter. class.getName());
DEFAULT_CONVERTER_MAP.put("black", BlackCompositeConverter. class.getName());
DEFAULT_CONVERTER_MAP.put("red", RedCompositeConverter. class.getName());
DEFAULT_CONVERTER_MAP.put("green", GreenCompositeConverter. class.getName());
DEFAULT_CONVERTER_MAP.put("yellow", YellowCompositeConverter. class.getName());
DEFAULT_CONVERTER_MAP.put("blue", BlueCompositeConverter. class.getName());
DEFAULT_CONVERTER_MAP.put("magenta", MagentaCompositeConverter. class.getName());
DEFAULT_CONVERTER_MAP.put("cyan", CyanCompositeConverter. class.getName());
DEFAULT_CONVERTER_MAP.put("white", WhiteCompositeConverter. class.getName());
DEFAULT_CONVERTER_MAP.put("gray", GrayCompositeConverter. class.getName());
DEFAULT_CONVERTER_MAP.put("boldRed", BoldRedCompositeConverter. class.getName());
DEFAULT_CONVERTER_MAP.put("boldGreen", BoldGreenCompositeConverter. class.getName());
DEFAULT_CONVERTER_MAP.put("boldYellow", BoldYellowCompositeConverter. class.getName());
DEFAULT_CONVERTER_MAP.put("boldBlue", BoldBlueCompositeConverter. class.getName());
DEFAULT_CONVERTER_MAP.put("boldMagenta", BoldMagentaCompositeConverter. class.getName());
DEFAULT_CONVERTER_MAP.put("boldCyan", BoldCyanCompositeConverter. class.getName());
DEFAULT_CONVERTER_MAP.put("boldWhite", BoldWhiteCompositeConverter. class.getName());
DEFAULT_CONVERTER_MAP.put("highlight", HighlightingCompositeConverter. class.getName());
DEFAULT_CONVERTER_MAP.put("lsn", LocalSequenceNumberConverter. class.getName());
CONVERTER_ class_TO_KEY_MAP.put(LocalSequenceNumberConverter. class.getName(), "lsn");
DEFAULT_CONVERTER_MAP.put("prefix", PrefixCompositeConverter. class.getName());
}
}
ThreadConverter:将 %thread 占位符转换为 logger 线程。
public classThreadConverterextends classicConverter {
publicStringconvert(ILoggingEvent event) {
return event.getThreadName();
}
)
在 PatternLayout 中,默认添加了对 MDC 的支持,可以将 %X{key} 或者 %mdc{key} 占位符转换为 MDC.get(key)。
DEFAULT_CONVERTER_MAP.put("X", MDCConverter. class.getName());
DEFAULT_CONVERTER_MAP.put("mdc", MDCConverter. class.getName());
MDCConverter 为何可以将 %X{traceId} 或者 %mdc{traceId} 占位符转换为 MDC.get("traceId") ?
在程序启动时,ch.qos.logback.core.pattern.parser.Compiler#compile() 会解析用户配置的 pattern 表达式,得到 pattern 中需要动态解析的占位符,比如 %d{yyyy-MM-dd HH:mm:ss.SSS},%X{traceId}。将这些动态占位符传递给 DynamicConverter#optionList 字段(MDCConverter 本质就是 DynamicConverter),optionList 字段包含程序要处理的占位符名称,比如 traceId。
程序启动时,logback 进行 Convert 初始化,会调用 MDCConverter#start() 方法,将成员变量 private String key 的值设置为 traceId(MDCConverter#getFirstOption() 返回用户配置的 traceId)。
在 MDCConverter#convert() 方法中,将 traceId 占位符转换为 MDC.get(key):String value = mdcPropertyMap.get(key)。
public classMDCConverterextends classicConverter {
privateString key;
privateString defaultValue ="";
@Override
publicvoidstart() {
String[] keyInfo =extractDefaultReplacement(getFirstOption());
key = keyInfo[0];
if (keyInfo[1] !=null) {
defaultValue = keyInfo[1];
}
super.start();
}
@Override
publicStringconvert(ILoggingEvent event) {
Map<String, String> mdcPropertyMap = event.getMDCPropertyMap();
if (mdcPropertyMap ==null) {
return defaultValue;
}
if (key ==null) {
returnoutputMDCForAllKeys(mdcPropertyMap);
} else {
String value = mdcPropertyMap.get(key);
if (value !=null) {
return value;
} else {
return defaultValue;
}
}
}
}
ILoggingEvent 接口的实现类 LoggingEvent 中,对 MDCAdapter 做了适配:
public classLoggingEventimplementsILoggingEvent {
publicMap<String, String>getMDCPropertyMap() {
// populate mdcPropertyMap if null
if (mdcPropertyMap ==null) {
MDCAdapter mdc =MDC.getMDCAdapter();
if (mdc instanceofLogbackMDCAdapter)
mdcPropertyMap = ((LogbackMDCAdapter) mdc).getPropertyMap();
else
mdcPropertyMap = mdc.getCopyOfContextMap();
}
// mdcPropertyMap still null, use emptyMap()
if (mdcPropertyMap ==null)
mdcPropertyMap = Collections.emptyMap();
return mdcPropertyMap;
}
}
如喜欢本文,请点击右上角,把文章分享到朋友圈
如有想了解学习的技术点,请留言给若飞安排分享
因公众号更改推送规则,请点「在看」并加「星标」 第一时间获取精彩技术分享
·END·
相关阅读:
作者:OnebyWang
来源:https://juejin.cn/post/7278498472860581925
版权申明:内容来源网络,仅供学习研究,版权归原创者所有。如有侵权烦请告知,我们会立即删除并表示歉意。谢谢!
架构师
我们都是架构师!
关注 架构师(JiaGouX),添加「星标」
获取每天技术干货,一起成为牛逼架构师
技术群请 加若飞: 1321113940 进架构师群
投稿、合作、版权等邮箱: [email protected]