Distributed Link Tracing: TraceIdFilter + MDC + Skywalking

Click the blue “Most Programmer” to follow me!

Add a “Star“, every day at 18:03, let’s learn technology together.

Source: juejin.cn/post/7278498472860581925

Pain Points
Solution
MDC Principle
Logback Placeholder

Distributed Link Tracing: TraceIdFilter + MDC + Skywalking

Pain Points

When checking online logs, 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 collects 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 for 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 from the TraceIdFilter:String traceId = httpServletRequest.getHeader(TRACE_ID_HEADER_KEY). If the request does not carry the X-App-Trace-Id request 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 service calls, the traceId in the MDC needs to be passed 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-threading 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 to the MDC of the child thread; after the child thread task is completed, clear the contents of the child thread’s MDC.

Adapting 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 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, decorate the native Runnable runnable object. Before executing the native Runnable object, set the parent thread’s MDC into the child thread, and after the native Runnable object execution ends, clear the contents of the child thread’s MDC.

@Slf4j
publicabstractclass 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

The Skywalking official provides adaptation for logback version 1.x:apm-toolkit-logback-1.x, which can print the skywalking traceId in logback. The X-App-Trace-Id and skywalking traceId can be combined to facilitate the investigation of interface business and performance issues.

Select the specific implementation class for layout TraceIdPatternLogbackLayout.
In the logback pattern, use %tid 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 %tid placeholder to skywalking traceId.
sw_ctx: Uses LogbackSkyWalkingContextPatternConverter to convert %sw_ctx placeholder to 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 returns “TID: N/A“, what is going on?

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:-javaagent:/opt/tools/skywalking-agent.jar. The skywalking agent will proxy the LogbackPatternConverter class and overwrite 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;

publicclass LogbackPatternConverter
extends ClassicConverter
implements EnhancedInstance {
   privatevolatile Object _$EnhancedClassField_ws;
   publicstaticvolatile/* synthetic */ InstMethodsInter delegate$mo3but1;
   privatestaticfinal/* 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() {
       returnthis._$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) {
       returnthis.convert$original$T8InTdln(iLoggingEvent);
   }
}

MDC Principle

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

public class MDC {

    staticfinal String NULL_MDCA_URL = "http://www.slf4j.org/codes.html#null_MDCA";
    staticfinal 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) {
            thrownew IllegalArgumentException("key parameter cannot be null");
        }
        if (mdcAdapter == null) {
            thrownew 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 of MDC. Any logging framework that wants to use the 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 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;();

    privatestaticfinalint WRITE_OPERATION = 1;
    privatestaticfinalint 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) {
            thrownew 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 {
            returnnull;
        }
    }
}

Logback Placeholders

PatternLayout class initializes common logback placeholders with corresponding Converters.

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

    publicstaticfinal Map&lt;String, String&gt; DEFAULT_CONVERTER_MAP = new HashMap&lt;String, String&gt;();
    publicstaticfinal Map&lt;String, String&gt; CONVERTER_CLASS_TO_KEY_MAP = new HashMap&lt;String, String&gt;();
    
    /**
     * @deprecated replaced by DEFAULT_CONVERTER_MAP
     */
    publicstaticfinal Map&lt;String, String&gt; defaultConverterMap = DEFAULT_CONVERTER_MAP;
    
    publicstaticfinal 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 %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 %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 processed, 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.

When the program starts, logback initializes Convert and will call the MDCConverter#start() method, setting the member variable 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).

public class MDCConverter extends ClassicConverter {

    private String key;
    private String defaultValue = "";

    @Override
    public void start() {
        String[] keyInfo = extractDefaultReplacement(getFirstOption());
        key = keyInfo[0];
        if (keyInfo[1] != null) {
            defaultValue = keyInfo[1];
        }
        super.start();
    }

    @Override
    public String convert(ILoggingEvent event) {
        Map&lt;String, String&gt; mdcPropertyMap = event.getMDCPropertyMap();

        if (mdcPropertyMap == null) {
            return defaultValue;
        }

        if (key == null) {
            return outputMDCForAllKeys(mdcPropertyMap);
        } else {

            String value = mdcPropertyMap.get(key);
            if (value != null) {
                return value;
            } else {
                return defaultValue;
            }
        }
    }
}

ILoggingEvent interface implementation class LoggingEvent adapts the MDCAdapter:

public class LoggingEvent implements ILoggingEvent {

    public Map&lt;String, String&gt; getMDCPropertyMap() {
        // populate mdcPropertyMap if null
        if (mdcPropertyMap == null) {
            MDCAdapter mdc = MDC.getMDCAdapter();
            if (mdc instanceof LogbackMDCAdapter)
                mdcPropertyMap = ((LogbackMDCAdapter) mdc).getPropertyMap();
            else
                mdcPropertyMap = mdc.getCopyOfContextMap();
        }
        // mdcPropertyMap still null, use emptyMap()
        if (mdcPropertyMap == null)
            mdcPropertyMap = Collections.emptyMap();

        return mdcPropertyMap;
    }
}