SpringCloud之个性化日志追踪

方案背景

日志跟踪技术使得查找一次调用所产生的日志信息变得方便。当需要排查一些问题时，可以根据报错的上下文进行分析，给问题诊断带来方便。在spring cloud微服务中，单体应用的日志跟踪技术已经不能满足需求，因而一般采用Spring Cloud Sleuth组件提供的功能来完成分布式日志跟踪。

Spring Cloud Sleuth组件会在zuul网关中，对于每个请求生成一个日志id，之后会通过http header的方式将id带到不同的服务应用中。在特定应用中，通过sl4j及特定的日志输出架构（比如logback）实施单体应用的日志跟踪。

Spring Cloud Sleuth默认的解决方案是在一次请求所生产的每条日志中添加日志id，然后通过日志id来关联该次请求的日志信息。在某些业务场景，可能需要对默认的解决方案进行功能的扩展，比如：

业务上对日志id的格式有要求，比如需要从日志id中看出请求的时间点等。
出于监控的需求，需要在每条日志中加入客户端请求的ip信息等。
本方案便是通过扩展Spring Cloud Sleuth默认的解决方案的功能达到满足以上业务点。

实现分析

服务本身对traceId的处理。
Sleuth通过Filter的方式，在filter中对请求头的处理来实现traceId的追踪。

先判断http头中是否存在“X-B3-TraceId”，不存在，则生成新的traceId；存在，则以头X-B3-TraceId的值作为traceId。最后将X-B3-TraceId的值放到MDC中，以便日志输出中带上X-B3-TraceId。这样使得在本服务中，用户请求产生的日志输出都会带有traceId。

服务间对traceId的处理
在微服务中，服务A向服务B发起调用请求。那如何将A中的traceId传递给B呢？首先，先要了解服务A是如何调用服务B的。

1、网关接收到进行，进行请求转发

Sleuth在ZuulFilter（TracePreZuulFilter）中将traceId添加到http头X-B3-TraceId中，以便所转发请求对应的服务能从头中获取到traceId。同时还将traceId放到MDC中，以便本应用在输出日志时带traceId。

2、服务内部通过feign注解调用另一个服务

由于feign注解的实现是通过生成Hystrix的代理类来完成请求的处理，而Hystrix在进行请求发送时是通过异步的方式调用ribbon的组件进行负载均衡，然后通过Feign.Client的execute方法来进行请求的发送。故此时需要解决以下两个问题：

（1）如何在异步线程中传递traceId。

Sluth是通过实现HystrixConcurrencyStrategy接口来解决traceId异步传递的问题。Hystrix在实际调用时，会调用HystrixConcurrencyStrategy的wrapCallable方法。因此，通过实现这个接口，在wrapCallable中将traceId存放起来（具体参见SleuthHystrixConcurrencyStrategy

）。

（2）Feign如何在服务中传递traceId。

Sluth通过实现Feign.Client，在execute前将traceId存放到X-B3-TraceId头中来实现（具体参见TraceFeignClient）。

方案实施

网关生成额外的跟踪信息
实现ZuulFilter接口，在其run方法中将额外的信息放到http头中及MDC中。如下：



 



源码：

package com.yao.springcloud.filters;
 
 
import com.netflix.zuul.ZuulFilter;
import com.netflix.zuul.context.RequestContext;
import com.yao.springcloud.ConstantsName;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.slf4j.MDC;
 
import java.util.Map;
 
 
public class TracePreFilter extends ZuulFilter {
    private static Logger LOGGER = LoggerFactory.getLogger(TracePreFilter.class);
 
    @Override
    public String filterType() {
        return "pre";
    }
 
    @Override
    public int filterOrder() {
        return 1;
    }
 
    @Override
    public boolean shouldFilter() {
        return true;
    }
 
 
    @Override
    public Object run() {
        LOGGER.info("TracePreFilter run");
        RequestContext ctx = RequestContext.getCurrentContext();
        Map<String, String> requestHeaders = ctx.getZuulRequestHeaders();
 
        String clientIp = ctx.getRequest().getRemoteAddr();
        //设置头信息
        setHeader(requestHeaders, ConstantsName.CLIENT_IP, clientIp);
        //添加到MDC中
        MDC.put(ConstantsName.CLIENT_IP, clientIp);
        LOGGER.info("TracePreFilter END");
 
        return null;
    }
 
 
    /**
     * 设置请求头
     *
     * @param request 请求头
     * @param name    参数名
     * @param value   参数值
     */
    public void setHeader(Map<String, String> request, String name, String
            value) {
        if (value != null) {
            request.put(name, value);
        }
    }
 
}
web filter中将额外的跟踪信息保存到MDC中
web filter将额外的跟踪信息从http header中取出来，然后放到MDC中。该步确保在一个服务中可以从MDC中获取到相关信息。



 源码：

package com.yao.springcloud.web;
 
import com.yao.springcloud.ConstantsName;
import org.apache.commons.lang.StringUtils;
import org.slf4j.MDC;
import org.springframework.core.annotation.Order;
import org.springframework.web.filter.OncePerRequestFilter;
 
import javax.servlet.FilterChain;
import javax.servlet.ServletException;
import javax.servlet.http.HttpServletRequest;
import javax.servlet.http.HttpServletResponse;
import java.io.IOException;
 
@Order(ConstantsName.TRACE_FILTERORDER)
public class WebTraceFilter extends OncePerRequestFilter {
    @Override
    protected void doFilterInternal(HttpServletRequest httpServletRequest, HttpServletResponse httpServletResponse,
                                    FilterChain filterChain) throws ServletException, IOException {
        String clientIp = httpServletRequest.getHeader(ConstantsName.CLIENT_IP);
        if(StringUtils.isNotEmpty(clientIp)){//如果为空，则表示第一次访问，即网关端的请求
            MDC.put(ConstantsName.CLIENT_IP, clientIp);
        }
        filterChain.doFilter(httpServletRequest, httpServletResponse);
        //确保每个应用处理完后 清除相关MDC的内容
        MDC.remove(ConstantsName.CLIENT_IP);
 
    }
}
 

 在hystrix异步线程中添加额外的跟踪信息
该步骤主要是将MDC中添加的额外信息放到异步线程中，解决通过hystrix进行异步调用时无法在异步线程中取得所需要信息的问题。





源码：

package com.yao.springcloud.hystrix;
 
 
import com.netflix.hystrix.strategy.concurrency.HystrixConcurrencyStrategy;
import com.netflix.hystrix.strategy.eventnotifier.HystrixEventNotifier;
import com.netflix.hystrix.strategy.metrics.HystrixMetricsPublisher;
import com.netflix.hystrix.strategy.properties.HystrixPropertiesStrategy;
import com.yao.springcloud.ConstantsName;
import org.apache.commons.logging.Log;
import org.apache.commons.logging.LogFactory;
import org.slf4j.MDC;
import org.springframework.cloud.sleuth.Span;
import org.springframework.cloud.sleuth.TraceKeys;
import org.springframework.cloud.sleuth.Tracer;
import org.springframework.cloud.sleuth.instrument.hystrix.SleuthHystrixConcurrencyStrategy;
 
import java.lang.invoke.MethodHandles;
import java.util.concurrent.Callable;
 
 
public class TraceSleuthHystrixConcurrencyStrategy extends SleuthHystrixConcurrencyStrategy {
    private static final Log log = LogFactory.getLog(TraceSleuthHystrixConcurrencyStrategy.class);
    private static final String HYSTRIX_COMPONENT = "hystrix";
    private final Tracer tracer;
    private final TraceKeys traceKeys;
    private HystrixConcurrencyStrategy delegate;
 
 
 
    public HystrixConcurrencyStrategy getDelegate() {
        return delegate;
    }
 
    public void setDelegate(HystrixConcurrencyStrategy delegate) {
        this.delegate = delegate;
    }
 
    public Tracer getTracer() {
        return tracer;
    }
 
    public TraceKeys getTraceKeys() {
        return traceKeys;
    }
 
    public TraceSleuthHystrixConcurrencyStrategy(Tracer tracer, TraceKeys traceKeys) {
        super(tracer, traceKeys);
        this.tracer = tracer;
        this.traceKeys = traceKeys;
    }
 
 
    @Override
    public <T> Callable<T> wrapCallable(Callable<T> callable) {
        if (callable instanceof TraceHystrixTraceCallable) {
            return callable;
        }
        Callable<T> wrappedCallable = this.delegate != null ? this.delegate.wrapCallable(callable) : callable;
        if (wrappedCallable instanceof TraceHystrixTraceCallable) {
            return wrappedCallable;
        }
        return new TraceHystrixTraceCallable<>(this.tracer, this.traceKeys, wrappedCallable);
    }
 
    private void logCurrentStateOfHysrixPlugins(HystrixEventNotifier eventNotifier,
            HystrixMetricsPublisher metricsPublisher, HystrixPropertiesStrategy propertiesStrategy) {
        if (log.isDebugEnabled()) {
            log.debug("Current Hystrix plugins configuration is [" + "concurrencyStrategy [" + this.delegate
                    + "]," + "eventNotifier [" + eventNotifier + "]," + "metricPublisher [" + metricsPublisher
                    + "]," + "propertiesStrategy [" + propertiesStrategy + "]," + "]");
            log.debug("Registering Sleuth Hystrix Concurrency Strategy.");
        }
    }
 
    // Visible for testing
    static class TraceHystrixTraceCallable<S> implements Callable<S> {
 
        private static final Log log = LogFactory.getLog(MethodHandles.lookup().lookupClass());
 
        private Tracer tracer;
        private TraceKeys traceKeys;
        private Callable<S> callable;
        private String userIp;
        private String accessPath;
        private String userName;
        private Span parent;
        private String domain;
        private String clientIp;
 
        public Tracer getTracer() {
            return tracer;
        }
 
        public void setTracer(Tracer tracer) {
            this.tracer = tracer;
        }
 
        public TraceKeys getTraceKeys() {
            return traceKeys;
        }
 
        public void setTraceKeys(TraceKeys traceKeys) {
            this.traceKeys = traceKeys;
        }
 
        public Callable<S> getCallable() {
            return callable;
        }
 
        public void setCallable(Callable<S> callable) {
            this.callable = callable;
        }
 
        public String getUserIp() {
            return userIp;
        }
 
        public void setUserIp(String userIp) {
            this.userIp = userIp;
        }
 
        public String getAccessPath() {
            return accessPath;
        }
 
        public void setAccessPath(String accessPath) {
            this.accessPath = accessPath;
        }
 
        public String getUserName() {
            return userName;
        }
 
        public void setUserName(String userName) {
            this.userName = userName;
        }
 
        public Span getParent() {
            return parent;
        }
 
        public void setParent(Span parent) {
            this.parent = parent;
        }
 
        public TraceHystrixTraceCallable(Tracer tracer, TraceKeys traceKeys, Callable<S> callable) {
            this.tracer = tracer;
            this.traceKeys = traceKeys;
            this.callable = callable;
            this.parent = tracer.getCurrentSpan();
            this.clientIp = MDC.get(ConstantsName.CLIENT_IP);
        }
 
        @Override
        public S call() throws Exception  {
            Span span = this.parent;
            boolean created = false;
            MDC.put(ConstantsName.CLIENT_IP,this.clientIp);
            if (span != null) {
                span = this.tracer.continueSpan(span);
                if (log.isDebugEnabled()) {
                    log.debug("Continuing span " + span);
                }
            } else {
                span = this.tracer.createSpan(HYSTRIX_COMPONENT);
                created = true;
                if (log.isDebugEnabled()) {
                    log.debug("Creating new span " + span);
                }
            }
            if (!span.tags().containsKey(Span.SPAN_LOCAL_COMPONENT_TAG_NAME)) {
                this.tracer.addTag(Span.SPAN_LOCAL_COMPONENT_TAG_NAME, HYSTRIX_COMPONENT);
            }
            String asyncKey = this.traceKeys.getAsync().getPrefix()
                    + this.traceKeys.getAsync().getThreadNameKey();
            if (!span.tags().containsKey(asyncKey)) {
                this.tracer.addTag(asyncKey, Thread.currentThread().getName());
            }
            try {
                return this.callable.call();
            } finally {
                MDC.remove(ConstantsName.CLIENT_IP);
                if (created) {
                    if (log.isDebugEnabled()) {
                        log.debug("Closing span since it was created" + span);
                    }
                    this.tracer.close(span);
                } else if (this.tracer.isTracing()) {
                    if (log.isDebugEnabled()) {
                        log.debug("Detaching span since it was continued " + span);
                    }
                    this.tracer.detach(span);
                }
            }
        }
 
    }
 
}
 在异步线程中发起http请求前，将信息添加到header中
hystrix在进行发送前会通过RequestInterceptor对请求信息进行预处理（见SynchronousMethodHandler->executeAndDecode->targetRequest方法）。因此，除了重写Feign.Client方法外，最简单的方式就是添加一个RequestInterceptor，在RequestInterceptor中将额外的跟踪信息添加到http头中。





源码：

package com.yao.springcloud.feign;
 
import feign.RequestInterceptor;
import feign.RequestTemplate;
 
/**
 * Created by micat707 on 2017/6/5.
 */
public class TraceFeignRequestInterceptor implements RequestInterceptor  {
 
    /**
     *
     * apply:
     *
     * @return void
     * @author：micat707
     * @date：2017年11月4日 下午4:53:59
     */
    @Override
    public void apply(RequestTemplate template) {
        TraceFeignRequestTemplateInjector.inject(template);
    }
}
package com.yao.springcloud.feign;
 
import com.yao.springcloud.ConstantsName;
import feign.RequestTemplate;
import org.slf4j.MDC;
import org.springframework.util.StringUtils;
 
 
public class TraceFeignRequestTemplateInjector {
 
 
    public static void inject(RequestTemplate carrier) {
        String clientIp = MDC.get("CLIENT_IP");
        setHeader(carrier, ConstantsName.CLIENT_IP, clientIp);
    }
 
 
    protected static void setHeader(RequestTemplate request, String name,
                                    String value) {
        if (StringUtils.hasText(value) && !request.headers().containsKey(name)) {
            request.header(name, value);
        }
    }
}
 

附
源码地址：https://github.com/micat707/myprojects/tree/master/spring-cloud-solutions