全链路日志追踪-trace_id方式

全链路日志追踪过程：

nginx---> 网关--->服务A----服务.......

1、nginx相关配置

(1) nginx.conf

# HTTPS server
server {
listen 443 ssl http2;
server_name mp-sit.smartmidea.net;

ssl_protocols TLSv1.1 TLSv1.2;

ssl_certificate smartmidea.net.cer;
ssl_certificate_key smartmidea.net.key;

ssl_session_cache shared:SSL:1m;
ssl_session_timeout 5m;

ssl_ciphers HIGH:!aNULL:!MD5;
ssl_prefer_server_ciphers on;

include /apps/svr/nginx-1.17.5/conf/log_trace_proc.conf;   //此文件是申城trace_id 、trace_path     具体内容如下

###########

set $trace_id $http_mc_trace_id;
set $trace_path $http_mc_trace_path;
set $curr_path "$msec:nginx:${server_addr}:${server_port}";
if ($trace_id != ''){
set $trace_path "${trace_path}${dollar}${curr_path}";
}
if ($trace_id = '') {
set $trace_id $request_id;              //nginx版本要求（>1.11.0,下图为nginx官方关于$request_id申城唯一标识
set $trace_id "${trace_id}${dollar}${trace_id}";   // ${dollar}=$
set $trace_path "${curr_path}";
}

###########

include /apps/svr/nginx-1.17.5/conf/vhost.conf;
}

#日志格式及通用变量配置
log_format trace_log 'mp-nginx|$trace_id|$trace_path|$remote_addr|'
'$server_addr|$server_port|$http_traceId|$msec|$request_time|'
'$request_method|$request_uri|$status|$request_length|$body_bytes_sent|'
'$http_referer|$http_user_agent|$upstream_addr|$http_host';
access_log /apps/svr/nginx-1.17.5/logs/tracelog-mp-nginx.log trace_log;

}

(2) vhost.conf

location = /service {
proxy_redirect off;
proxy_ignore_client_abort on;
proxy_set_header Host $host;
proxy_set_header X-Real-IP $remote_addr;
proxy_set_header X-Forwarded-For $proxy_add_x_forwarded_for;
proxy_set_header X-Forwarded-Proto $scheme;
proxy_set_header mc-trace-id $trace_id;
proxy_set_header mc-trace-path $trace_path;    //mc-trace-id   mc-trace-path 在头部转发到对应服务中；

(3) nginx日志位置：

2、服务A获取日志并打印到对应文件夹位置

(1) log4配置文件如下

<?xml version="1.0" encoding="UTF-8"?>
<!-- Configuration后面的status，这个用于设置log4j2自身内部的信息输出，可以不设置，当设置成trace时，
     你会看到log4j2内部各种详细输出。可以设置成OFF(关闭) 或 Error(只输出错误信息)。
     30s 刷新此配置
-->
<configuration status="WARN" monitorInterval="30">

    <!-- 日志文件目录、压缩文件目录、日志格式配置 -->
    <properties>
        <Property name="modelName">服务A</Property>
        <Property name="fileName">/apps/logs/${modelName}</Property>
        <Property name="fileGz">/apps/logs/${modelName}</Property>
        <Property name="LOG_PATTERN">%d{yyyy-MM-dd HH:mm:ss.SSS} %5p -%X{requestId}- [%15.15t] %-40.40c{1.} : %m%n%xwEx</Property>
    </properties>

    <Appenders>
        <!-- 输出控制台日志的配置 -->
        <Console name="console" target="SYSTEM_OUT">
            <!--控制台只输出level及以上级别的信息（onMatch），其他的直接拒绝（onMismatch）-->
            <ThresholdFilter level="debug" onMatch="ACCEPT" onMismatch="DENY"/>
            <!-- 输出日志的格式 -->
            <PatternLayout pattern="${LOG_PATTERN}"/>
        </Console>

        <!-- 打印出所有的信息，每次大小超过size，则这size大小的日志会自动存入按年份-月份建立的文件夹下面并进行压缩，作为存档 -->
        <RollingRandomAccessFile name="infoFile" fileName="${fileName}/${modelName}-info.log" immediateFlush="false"
                                 filePattern="${fileGz}/$${date:yyyy-MM}/${modelName}-info-%d{yyyy-MM-dd}-%i.log.gz">
            <PatternLayout pattern="${LOG_PATTERN}"/>

            <Policies>
                <SizeBasedTriggeringPolicy size="32 MB"/>
            </Policies>

            <Filters>
                <ReportLogFilter onMatch="DENY" onMismatch="ACCEPT" />                //info日志 ReportLogFilter 过滤掉

                <!-- 只记录info和warn级别信息 -->
                <!--<ThresholdFilter level="error" onMatch="DENY" onMismatch="NEUTRAL"/>-->
                <ThresholdFilter level="info" onMatch="ACCEPT" onMismatch="DENY"/>
            </Filters>

            <!-- 指定每天的最大压缩包个数，默认500个，超过了会覆盖之前的 -->
           <!-- <DefaultRolloverStrategy max="500"/>-->
        </RollingRandomAccessFile>

        <!-- 存储所有error信息 -->
        <RollingRandomAccessFile name="errorFile" fileName="${fileName}/${modelName}-error.log" immediateFlush="false"
                                 filePattern="${fileGz}/$${date:yyyy-MM}/%d{yyyy-MM-dd}-%i.${modelName}-error.gz">
            <PatternLayout pattern="${LOG_PATTERN}"/>

            <Policies>
                <SizeBasedTriggeringPolicy size="32 MB"/>
            </Policies>

            <Filters>
                <!-- 只记录error级别信息 -->
                <ThresholdFilter level="error" onMatch="ACCEPT" onMismatch="DENY"/>
            </Filters>

            <!-- 指定每天的最大压缩包个数，默认500个，超过了会覆盖之前的 -->
            <!--<DefaultRolloverStrategy max="500"/>-->
        </RollingRandomAccessFile>

        <!-- 记录上报日志 -->
        <RollingRandomAccessFile name="reportFile" fileName="${fileName}/${modelName}-report.log" immediateFlush="false"
                                 filePattern="${fileGz}/$${date:yyyy-MM}/%d{yyyy-MM-dd}-%i.${modelName}-report.gz">
            <Policies>
                <SizeBasedTriggeringPolicy size="100 MB"/>
            </Policies>

            <Filters>
                <ReportLogFilter onMatch="ACCEPT" onMismatch="DENY" />
                <ThresholdFilter level="info" onMatch="ACCEPT" onMismatch="DENY"/>
            </Filters>
            <DefaultRolloverStrategy max="100"/>
        </RollingRandomAccessFile>

    </Appenders>

    <!-- Mixed sync/async -->
    <Loggers>
        <AsyncRoot level="info">
            <AppenderRef ref="infoFile"/>
            <AppenderRef ref="reportFile"/>
            <AppenderRef ref="errorFile"/>
        </AsyncRoot>
    </Loggers>

</configuration>

(2)   ReportLogFilter  过滤器

import org.apache.logging.log4j.Level;
import org.apache.logging.log4j.Marker;
import org.apache.logging.log4j.core.LogEvent;
import org.apache.logging.log4j.core.Logger;
import org.apache.logging.log4j.core.config.plugins.Plugin;
import org.apache.logging.log4j.core.config.plugins.PluginAttribute;
import org.apache.logging.log4j.core.config.plugins.PluginFactory;
import org.apache.logging.log4j.core.filter.AbstractFilter;
import org.apache.logging.log4j.message.Message;

@Plugin(
        name = "ReportLogFilter",
        category = "Core",
        elementType = "filter",
        printObject = true
)
public final class ReportLogFilter extends AbstractFilter {        // 参照ThresholdFilter 

    private ReportLogFilter(Result onMatch, Result onMismatch) {
        super(onMatch, onMismatch);
    }

    @Override
    public Result filter(Logger logger, Level testLevel, Marker marker, String msg, Object... params) {
        return this.filter(marker);
    }

    @Override
    public Result filter(Logger logger, Level testLevel, Marker marker, Object msg, Throwable t) {
        return this.filter(marker);
    }

    @Override
    public Result filter(Logger logger, Level testLevel, Marker marker, Message msg, Throwable t) {
        return this.filter(marker);
    }

    @Override
    public Result filter(LogEvent event) {
        return filter(event.getMarker());
    }

    private Result filter(Marker marker) {
        return marker != null && ReportLog.isReport(marker.getName()) ? this.onMatch : this.onMismatch;
    }

    @PluginFactory
    public static ReportLogFilter createFilter(@PluginAttribute("onMatch") Result match, @PluginAttribute("onMismatch") Result mismatch) {
        Result onMatch = match == null ? Result.NEUTRAL : match;
        Result onMismatch = mismatch == null ? Result.DENY : mismatch;
        return new ReportLogFilter(onMatch, onMismatch);
    }
}


A -> B -> C

我们需要将A/B/C/三个微服务间的日志按照链式打印，我们都知道Dubbo的RpcContext只能做到消费者和提供者共享同一个RpcContext，比如A->B，那么A和B都可以获取相同内容的RpcContext，但是B->C时，A和C就无法共享相同内容的RpcContext了，也就是无法做到链式打印日志了。

我们可以用左手交换右手的思路来解决，假设左手是线程的ThreadLocal，右手是RpcContext，那么在交换之前，我们首先将必要的日志信息保存到ThreadLocal中。

(3) 服务A 过滤器 --------TraceLogFilter 

import org.springframework.beans.factory.annotation.Autowired;
import org.springframework.beans.factory.annotation.Value;
import org.springframework.boot.web.servlet.FilterRegistrationBean;
import org.springframework.context.annotation.Bean;
import org.springframework.stereotype.Component;
import org.springframework.web.method.HandlerMethod;
import org.springframework.web.servlet.mvc.method.RequestMappingInfo;
import org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerMapping;

import javax.servlet.*;
import javax.servlet.http.HttpServletRequest;
import javax.servlet.http.HttpServletResponse;
import java.io.IOException;
import java.util.Map;
import java.util.concurrent.ConcurrentHashMap;


@Component
public class TraceLogFilter implements Filter {

    @Autowired
    private RequestMappingHandlerMapping requestMappingHandlerMapping;

    @Value("${spring.application.name}")
    private String appName;

    private static Map<String, String> REQUEST_METHOD = new ConcurrentHashMap<>(16);
    private static Map<String, String> REQUEST_RESTFUL_METHOD = new ConcurrentHashMap<>(16);

    @Override
    public void init(FilterConfig filterConfig) throws ServletException {
        LogTrace.init(appName);
        initRequestMethod();
    }

    @Override
    public void doFilter(ServletRequest request, ServletResponse response, FilterChain chain) throws IOException, ServletException {
        BaseHttpRequestWarp requestWarp = new BaseHttpRequestWarp((HttpServletRequest)request);
        BaseHttpResponseWrap responseWrap = new BaseHttpResponseWrap((HttpServletResponse)response);
        try{
            LogTrace.startHttp(requestWarp);
            LogTrace.setCallMethod(matchCallMethod(requestWarp.getRequestURI()));
        }catch (Exception ignore){}

        chain.doFilter(requestWarp, responseWrap);

        try{
            LogTrace.stopHttp(responseWrap);
        }catch (Exception ignore){}

    }

    private String matchCallMethod(String url) {
        if (REQUEST_METHOD.get(url) != null){
            return REQUEST_METHOD.get(url);
        }
        for(Map.Entry<String, String> entry : REQUEST_RESTFUL_METHOD.entrySet()){
            if (matchUrl(entry.getKey(), url)){
                return entry.getValue();
            }
        }
        return null ;
    }

    private boolean matchUrl(String url, String tarUrl){
        String[] tarUrlPiece = tarUrl.split("/");
        String[] urlPiece = url.split("/");
        boolean match = false;
        for (int i=0; i<urlPiece.length; i++){
            match = false;
            if (i >= tarUrlPiece.length){
                break;
            }
            if (urlPiece[i].equals(tarUrlPiece[i]) || (urlPiece[i].startsWith("{") && urlPiece[i].endsWith("}"))){
                match = true;
                continue;
            }
            break;
        }
        return match;
    }

    @Override
    public void destroy() {

    }

    @Bean
    public FilterRegistrationBean registerFilter() {
        FilterRegistrationBean registration = new FilterRegistrationBean();
        registration.setFilter(this);
        registration.addUrlPatterns("/*");
        registration.setName("traceLogFilter");
        registration.setOrder(1);
        return registration;
    }

    private void initRequestMethod(){
        Map<RequestMappingInfo, HandlerMethod> map = requestMappingHandlerMapping.getHandlerMethods();
        for (Map.Entry<RequestMappingInfo, HandlerMethod> m : map.entrySet()){
            RequestMappingInfo info = m.getKey();
            HandlerMethod method = m.getValue();
            for(String url : info.getPatternsCondition().getPatterns()){
                if (url.matches("(.*?)\{(.*?)}(.*?)")){
                    REQUEST_RESTFUL_METHOD.put(url, String.format("%s.%s", String.valueOf(method.getBean()), method.getMethod().getName()));
                }
                REQUEST_METHOD.put(url, String.format("%s.%s", String.valueOf(method.getBean()), method.getMethod().getName()));
            }
        }
    }

    private void setAppName(String appName) {
        this.appName = appName;
    }
}

(4)  LogTrace 实体类 

import com.alibaba.fastjson.JSONObject;
import org.springframework.util.StringUtils;
import java.util.UUID;

public class LogTrace {
   private static final String DEFAULT_TRACE_ID = "mc-trace-id";
   private static final String DEFAULT_TRACE_PATH = "mc-trace-path";

   public static String TRACE_ID() {
      // 后续放入配置
      return DEFAULT_TRACE_ID;
   }

   public static String TRACE_PATH() {
      // 后续放入配置
      return DEFAULT_TRACE_PATH;
   }

   private static ThreadLocal<LogTraceEntity> logVo = new ThreadLocal<LogTraceEntity>();

   private static String logAppName = "default-trace-app";

   {
      String tmp = System.getProperty("java.class.path");
      if(!StringUtils.isEmpty(tmp)) {
         String[] ary = tmp.split("/");
         logAppName = ary[ary.length-1];
      }
   }
   
   public static void init(String appName) {
      logAppName = appName;
   }

   public static void startHttp(IHttpRequest request) {
      String serverIp = request.localHost();
      int serverPort = request.localPort();
      LogTraceEntity log = new LogTraceEntity();
      log.setRequestTime(System.currentTimeMillis());
      log.setAppName(logAppName);
      // log.setClientIp(request.remoteAddress().host());
      log.setClientIp(getClientIp(request));
      log.setClientPort(request.remotePort());
      log.setServerIp(serverIp);
      log.setServerPort(serverPort);
      log.setMethod(request.method());
      long requestLen = request.contentLength();
      log.setRequestLength(requestLen);

      String traceId = request.getHeader(TRACE_ID());
      String tracePath = request.getHeader(TRACE_PATH());
      if (StringUtils.isEmpty(traceId)) {
         traceId = UUID.randomUUID().toString().replace("-", "");
         traceId += "$" + traceId;
         tracePath = "";
      } else {
         tracePath += "$";
      }
      tracePath = String.format("%s%s:%s:%s:%s", tracePath, System.currentTimeMillis(), logAppName, serverIp,
            serverPort);

      log.setTraceId(traceId);
      log.setTracePath(tracePath);
      log.setUrl(request.path());
      log.setQueryParams(request.query());
      logVo.set(log);
   }

   public static void stopHttp(IHttpResponse response) {
      LogTraceEntity log = logVo.get();
      if (log == null) {
         return;
      }
      log.setElapsedTime(System.currentTimeMillis() - log.getRequestTime());
      log.setStatusCode(response.statusCode());
      log.setResponseLength(response.contentLength());
      // 从content中提取内容和businessCode
      String content = response.content();
      if (!StringUtils.isEmpty(content)) {
         JSONObject resJson = JSONObject.parseObject(content);
         log.setBusinessCode(resJson.getString("code"));
         if (content.length() > 300) {
            content = content.substring(0, 300);
         }
         log.setReturnContent(content);
      }
      ReportLog.report(log.toString());   //打印report日志
      logVo.remove();    //释放ThreadLocal

   }

   private static String getClientIp(IHttpRequest request) {
      String ip = request.getHeader("X-Forwarded-For");
      ip = getIpFromHeaderIfNotAlreadySet("X-Real-IP", request, ip);
      ip = getIpFromHeaderIfNotAlreadySet("Proxy-Client-IP", request, ip);
      ip = getIpFromHeaderIfNotAlreadySet("WL-Proxy-Client-IP", request, ip);
      ip = getIpFromHeaderIfNotAlreadySet("HTTP_CLIENT_IP", request, ip);
      ip = getIpFromHeaderIfNotAlreadySet("HTTP_X_FORWARDED_FOR", request, ip);
      ip = getFirstIp(ip);
      if (ip == null || ip.length() == 0 || "unknown".equalsIgnoreCase(ip) || "127.0.0.1".equalsIgnoreCase(ip)) {
         ip = request.remoteHost();
      }
      return ip;
   }

   private static String getFirstIp(String ip) {
      if (ip != null) {
         final int indexOfFirstComma = ip.indexOf(',');
         if (indexOfFirstComma != -1) {
            ip = ip.substring(0, indexOfFirstComma);
         }
      }
      return ip;
   }

   private static String getIpFromHeaderIfNotAlreadySet(String header, IHttpRequest request, String ip) {
      if (StringUtils.isEmpty(ip) || "unknown".equalsIgnoreCase(ip)) {
         ip = request.getHeader(header);
      }
      return ip;
   }

   public static void startRpc(String serverIp, int serverPort, String remoteAddr) {
      LogTraceEntity log = new LogTraceEntity();
      log.setRequestTime(System.currentTimeMillis());
      log.setAppName(logAppName);
      String[] ary = StringUtils.isEmpty(remoteAddr) ? "".split(":") : remoteAddr.split(":");
      log.setClientIp(ary[0]);
      try {
         if (ary.length > 1) {
            log.setClientPort(Integer.valueOf(ary[1]));
         } else {
            log.setClientPort(0);
         }
      } catch (Exception ex) {
      }
      log.setServerIp(serverIp);
      log.setServerPort(serverPort);
      logVo.set(log);
   }
   
   public static void updateRpc(String traceId, String tracePath, String method, long requestLen) {
      LogTraceEntity log = logVo.get();
      log.setMethod(method);
      log.setRequestLength(requestLen);
      if (StringUtils.isEmpty(traceId)) {
         traceId = UUID.randomUUID().toString().replace("-", "");
         traceId += "$" + traceId;
         tracePath = "";
      } else {
         tracePath += "$";
      }
      tracePath = String.format("%s%s:%s:%s:%s", tracePath, System.currentTimeMillis(), logAppName, log.getServerIp(),
            log.getServerPort());

      log.setTraceId(traceId);
      log.setTracePath(tracePath);
      log.setUrl(method);
   }

   public static void stopRpc(String callMethod, int statusCode, long respLength, String content) {
      LogTraceEntity log = logVo.get();
      if (log == null) {
         return ;
      }
      
      if(!StringUtils.isEmpty(callMethod)) {
         log.setCallMethod(callMethod);
      }
      
      log.setElapsedTime(System.currentTimeMillis() - log.getRequestTime());
      log.setStatusCode(statusCode);
      if (log.getBusinessCode() == null || log.getBusinessCode().isEmpty()) {
         log.setBusinessCode(String.valueOf(statusCode));
      }
      log.setResponseLength(respLength);
      // 从content中提取内容和businessCode
      if (!StringUtils.isEmpty(content)) {
         if (content.length() > 300) {
            content = content.substring(0, 300);
         }
         log.setReturnContent(content);
      }

      ReportLog.report(log.toString());
   }

   public static LogTraceEntity get() {
      return logVo.get();
   }

   public static void putData(String key, String val) {
      LogTraceEntity log = logVo.get();
      if (log != null && !StringUtils.isEmpty(key) && !StringUtils.isEmpty(val)) {
         log.pubQueryData(key, val);
      }
   }

   public static void getData(String key) {
      LogTraceEntity log = logVo.get();
      if (log != null) {
         log.getQueryData(key);
      }
   }

   public static void setCallMethod(String callMethod) {
      LogTraceEntity log = logVo.get();
      if (log != null) {
         log.setCallMethod(callMethod);
      }
   }

   public static String getTraceId() {
      LogTraceEntity log = logVo.get();
      if (log != null) {
         return log.getTraceId();
      } else {
         return "";
      }
   }

   public static String getTracePath() {
      LogTraceEntity log = logVo.get();
      if (log != null) {
         return log.getTracePath();
      } else {
         return "";
      }
   }

   public static void setBusinessCode(String businessCode) {
      LogTraceEntity log = logVo.get();
      if (log != null) {
         log.setBusinessCode(businessCode);
      }
   }
}

(5)   ReportLog 实体类

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.slf4j.Marker;
import org.slf4j.MarkerFactory;


public class ReportLog {

    private static final Logger LOGGER = LoggerFactory.getLogger(ReportLog.class);

    private static final Marker REPORT_MARKER = MarkerFactory.getMarker("服务A-REPORT");

    public static void report(String log){
        LOGGER.info(REPORT_MARKER, log);
    }

    public static boolean isReport(String name){
        return REPORT_MARKER.getName().equals(name);
    }
}

打印日志：

2020-04-22 14:29:18.521 INFO -- [nio-7272-exec-7] c.m.p.m.l.ReportLog : 1587536958480|muc-application|0b0391c76aab4271887d6b1d1d78ce6e$0b0391c76aab4271887d6b1d1d78ce6e|1587536958480:服务A-application:0:0:0:0:0:0:0:1:7272||0:0:0:0:0:0:0:1|51387|0:0:0:0:0:0:0:1|7272|31|151|76|POST|/muc/v5/app/mj/user/getOpenIds|404|null|null|404|{"code":404,"msg":"资源不存在","data":"/muc/v5/app/mj/user/getOpenIds"}

(6) 服务A日志

drwxr-xr-x 2 root root 12288 Mar 31 17:27 2020-03
drwxr-xr-x 2 root root 4096 Apr 22 10:15 2020-04
-rw-r--r-- 1 root root 22725584 Apr 22 11:09 服务A-error.log
-rw-r--r-- 1 root root 29789214 Apr 22 14:33 服务A--info.log
-rw-r--r-- 1 root root 50306628 Apr 18 16:02 服务A--report.log