Distributed Link Tracing: TraceIdFilter + MDC + Skywalking

Let's grow together every evening at 18:00!

Source: juejin.cn/post/7278498472860581925

Pain Points
Solution
MDC Principle
Logback Placeholders

Pain Points

When checking online logs, the logs from multiple threads within the same Pod are interleaved, making it difficult to trace the log information corresponding to each request.

After the log collection tool gathers logs from multiple Pods into the same database, the situation becomes even more chaotic.

Solution

TraceId + MDC

MDC:

https://logback.qos.ch/manual/mdc.html

Each time a request is made from the frontend, add the X-App-Trace-Id request header. The value of X-App-Trace-Id can be generated using 【timestamp + UUID】 to ensure the uniqueness of the traceId.
The backend retrieves the value of X-App-Trace-Id in the TraceIdFilter:String traceId = httpServletRequest.getHeader(TRACE_ID_HEADER_KEY). If the request does not carry the X-App-Trace-Id header, the backend service can generate a traceId using UUID or the Snowflake algorithm.
Put the traceId into the slf4j MDC:MDC.put(MDC_TRACE_ID_KEY, traceId), and use the %X{traceId} placeholder in the logback pattern to print the traceId.

public void doFilter(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);
    }
}

&lt;?xml version="1.0" encoding="UTF-8"?&gt;
&lt;configuration debug="false"&gt;
    &lt;property name="pattern" value="[%d{yyyy-MM-dd HH:mm:ss.SSS}] %-5level [%thread] %logger %line [%X{traceId}] [%tid] - %msg%n"/&gt;

Integrating Feign

When making inter-service calls, it is necessary to pass the traceId from the MDC to the called service. In our project, we uniformly use Feign Client to implement HTTP remote calls between services. In the Feign RequestInterceptor, retrieve the traceId from the MDC and put it into the request header:requestTemplate.header(TRACE_ID_HEADER_KEY, MDC.get(MDC_TRACE_ID_KEY));

@Override
public void apply(RequestTemplate template) {
    template.header(TRACE_ID_HEADER_KEY, MDC.get(MDC_TRACE_ID_KEY));
}

Multi-thread Adaptation

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.

Before executing tasks in child threads, set the MDC content of the parent thread into the MDC of the child thread; after the child thread task is completed, clear the content in the child thread’s MDC.

Adapting to JDK ThreadPoolExecutor:

public class MdcAwareThreadPoolExecutor extends ThreadPoolExecutor {

    @Override
    public void execute(Runnable command) {
        Map&lt;String, String&gt; parentThreadContextMap = MDC.getCopyOfContextMap();
        super.execute(MdcTaskUtils.adaptMdcRunnable(command, parentThreadContextMap));
    }
}

Adapting to Spring TaskDecorator:

@Component
public class MdcAwareTaskDecorator implements TaskDecorator {

    @Override
    public Runnable decorate(Runnable runnable) {
        Map&lt;String, String&gt; parentThreadContextMap = MDC.getCopyOfContextMap();
        return MdcTaskUtils.adaptMdcRunnable(runnable, parentThreadContextMap);
    }
}

MdcTaskUtils#adaptMdcRunnable(): Using the decorator pattern, it decorates the native Runnable runnable object. Before executing the native Runnable object, it sets the parent thread’s MDC into the child thread, and after the native Runnable object execution ends, it clears the content in the child thread’s MDC.

@Slf4j
public abstract class MdcTaskUtils {

    public static Runnable adaptMdcRunnable(Runnable runnable, Map&lt;String, String&gt; parentThreadContextMap) {
        return () -&gt; {
            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);
            }
        };
    }
}

Integrating Skywalking

Skywalking officially provides an adaptation for logback version 1.x:apm-toolkit-logback-1.x, which can print the skywalking traceId in logback. This allows combining X-App-Trace-Id and skywalking traceId for easier troubleshooting of interface business and performance issues.

Select the specific implementation class for layout: TraceIdPatternLogbackLayout.
Use %tid in the logback pattern to print the skywalking traceId.

&lt;?xml version="1.0" encoding="UTF-8"?&gt;
&lt;configuration debug="false"&gt;
    &lt;property name="pattern" value="[%d{yyyy-MM-dd HH:mm:ss.SSS}] %-5level [%thread] %logger %line [%X{traceId}] [%tid] - %msg%n"/&gt;

    &lt;appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender"&gt;
        &lt;encoder class="ch.qos.logback.core.encoder.LayoutWrappingEncoder"&gt;
            &lt;layout class="org.apache.skywalking.apm.toolkit.log.logback.v1.x.TraceIdPatternLogbackLayout"&gt;
                &lt;pattern&gt;${pattern}&lt;/pattern&gt;
            &lt;/layout&gt;
        &lt;/encoder&gt;
    &lt;/appender&gt;

TraceIdPatternLogbackLayout class initializes with two PatternConverter:

tid: Uses LogbackPatternConverter to convert the %tid placeholder to the skywalking traceId.
sw_ctx: Uses LogbackSkyWalkingContextPatternConverter to convert the %sw_ctx placeholder to the skywalking context.

public class TraceIdPatternLogbackLayout extends PatternLayout {
    public TraceIdPatternLogbackLayout() {
    }

    static {
        defaultConverterMap.put("tid", LogbackPatternConverter.class.getName());
        defaultConverterMap.put("sw_ctx", LogbackSkyWalkingContextPatternConverter.class.getName());
    }
}

LogbackPatternConverter#convert() method is hardcoded to return “TID: N/A“, what is going on here?

public class LogbackPatternConverter extends ClassicConverter {
    public LogbackPatternConverter() {
    }

    public String convert(ILoggingEvent iLoggingEvent) {
        return "TID: N/A";
    }
}

When starting the Java application, specify the java agent startup parameter -javaagent:/opt/tools/skywalking-agent.jar. The skywalking agent will proxy the LogbackPatternConverter class and override the logic of the convert() method.

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 class LogbackPatternConverter
extends ClassicConverter
implements EnhancedInstance {
   private volatile Object _$EnhancedClassField_ws;
   public static volatile /* synthetic */ InstMethodsInter delegate$mo3but1;
   private static final /* synthetic */ Method cachedValue$oeLgRjrq$u5j8qu3;

   public String convert(ILoggingEvent iLoggingEvent) {
       return (String)delegate$mo3but1.intercept(this, new Object[]{iLoggingEvent}, new LogbackPatternConverter$auxiliary$pJ6Zrqzi(this, iLoggingEvent), cachedValue$oeLgRjrq$u5j8qu3);
   }

   private /* synthetic */ String convert$original$T8InTdln(ILoggingEvent iLoggingEvent) {
/*34*/         return "TID: N/A";
   }

   @Override
   public void setSkyWalkingDynamicField(Object object) {
       this._$EnhancedClassField_ws = object;
   }

   @Override
   public Object getSkyWalkingDynamicField() {
       return this._$EnhancedClassField_ws;
   }

   static {
       ClassLoader.getSystemClassLoader().loadClass("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 */ String convert$original$T8InTdln$accessor$oeLgRjrq(ILoggingEvent iLoggingEvent) {
       return this.convert$original$T8InTdln(iLoggingEvent);
   }
}

MDC Principle

MDC is in the slf4j-api jar package. MDC is a specification of slf4j, and all operations on MDC will fall under the methods of the MDCAdapter interface.

public class MDC {

    static final String NULL_MDCA_URL = "http://www.slf4j.org/codes.html#null_MDCA";
    static final String NO_STATIC_MDC_BINDER_URL = "http://www.slf4j.org/codes.html#no_static_mdc_binder";
    static MDCAdapter mdcAdapter;
    
    public static void put(String key, String val) throws IllegalArgumentException {
        if (key == null) {
            throw new IllegalArgumentException("key parameter cannot be null");
        }
        if (mdcAdapter == null) {
            throw new IllegalStateException("MDCAdapter cannot be null. See also " + NULL_MDCA_URL);
        }
        mdcAdapter.put(key, val);
    }
}

MDCAdapter is the MDC adapter interface provided by slf4j, which is the specification for MDC. Any logging framework that wants to use MDC functionality must comply with the MDCAdapter interface specification and implement the methods in the interface.

// This interface abstracts the service offered by various MDC implementations.
public interface MDCAdapter {

    public void put(String key, String val);

    public String get(String key);
}

The Logback logging framework provides an adaptation for MDCAdapter: LogbackMDCAdapter, which is implemented using ThreadLocal.

public class LogbackMDCAdapter implements MDCAdapter {

    // 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 LBCLASSIC-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&lt;Map&lt;String, String&gt;&gt; copyOnThreadLocal = new ThreadLocal&lt;Map&lt;String, String&gt;&gt;();

    private static final int WRITE_OPERATION = 1;
    private static final int MAP_COPY_OPERATION = 2;

    // keeps track of the last operation performed
    final ThreadLocal&lt;Integer&gt; lastOperation = new ThreadLocal&lt;Integer&gt;();


    public void put(String key, String val) throws IllegalArgumentException {
        if (key == null) {
            throw new IllegalArgumentException("key cannot be null");
        }

        Map&lt;String, String&gt; oldMap = copyOnThreadLocal.get();
        Integer lastOp = getAndSetLastOperation(WRITE_OPERATION);

        if (wasLastOpReadOrNull(lastOp) || oldMap == null) {
            Map&lt;String, String&gt; newMap = duplicateAndInsertNewMap(oldMap);
            newMap.put(key, val);
        } else {
            oldMap.put(key, val);
        }
    }
    
    public String get(String key) {
        final Map&lt;String, String&gt; map = copyOnThreadLocal.get();
        if ((map != null) &amp;&amp; (key != null)) {
            return map.get(key);
        } else {
            return null;
        }
    }
}

Logback Placeholders

PatternLayout class initializes the converters corresponding to commonly used logback placeholders.

public class PatternLayout extends PatternLayoutBase&lt;ILoggingEvent&gt; {

    public static final Map&lt;String, String&gt; DEFAULT_CONVERTER_MAP = new HashMap&lt;String, String&gt;();
    public static final Map&lt;String, String&gt; CONVERTER_CLASS_TO_KEY_MAP = new HashMap&lt;String, String&gt;();
    
    /**
     * @deprecated replaced by DEFAULT_CONVERTER_MAP
     */
    public static final Map&lt;String, String&gt; defaultConverterMap = DEFAULT_CONVERTER_MAP;
    
    public static final String HEADER_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: Converts the %thread  placeholder to the logger thread.

public class ThreadConverter extends ClassicConverter {

    public String convert(ILoggingEvent event) {
        return event.getThreadName();
    }
}

In the PatternLayout, support for MDC is added by default, allowing the %X{key} or %mdc{key} placeholders to be converted to MDC.get(key).

DEFAULT_CONVERTER_MAP.put("X", MDCConverter.class.getName());
DEFAULT_CONVERTER_MAP.put("mdc", MDCConverter.class.getName());

MDCConverter can convert the %X{traceId} or %mdc{traceId} placeholders to MDC.get("traceId")?

When the program starts, ch.qos.logback.core.pattern.parser.Compiler#compile() will parse the user-configured pattern expression to obtain the dynamic placeholders that need to be resolved, such as %d{yyyy-MM-dd HH:mm:ss.SSS} and %X{traceId}. These dynamic placeholders are passed to the DynamicConverter#optionList field (MDCConverter  is essentially a DynamicConverter), and the optionList field contains the names of the placeholders to be processed by the program, such as traceId.

Distributed Link Tracing: TraceIdFilter + MDC + Skywalking — Image

When the program starts, logback performs Convert initialization and calls the MDCConverter#start()<code> method, setting the value of the member variable <code>private String key to traceId (MDCConverter#getFirstOption() returns the user-configured traceId).

In the MDCConverter#convert() method, the traceId placeholder is converted to MDC.get(key): String value = mdcPropertyMap.get(key).