Spring MVC結合日誌框架給一次請求日誌列印出唯一標示

https://blog.csdn.net/helloworldwt/article/details/51818309

1.簡介
         在tomcat web專案中， 一次使用者請求在同步情況下都是交給同一個執行緒去處理，如果能知道這個執行緒的處理路徑，可以方便線上問題的排查、程式碼的除錯。因此可以讓同一次請求的執行緒日誌帶上同一個唯一的token，在查詢日誌時，grep token可以把相關的日誌都查詢出來。這時，如果已經在程式碼邏輯關鍵部分已經列印了日誌，那麼可以準確知道這次請求執行了哪些程式碼。

2.日誌框架原理簡析

         日誌框架通常提供了一定的靈活性，以log4j和log4j2為例。

3.實現

3.1 對日誌框架進行擴充

繼承log4j的PatternParser類，並重寫finalizeConverter方法，實現對自定義字元的解析，並ThreadTokenHelper.getThreadToken()返回自定義的token資訊。

public class Log4jExPatternParser extends PatternParser {
    public Log4jExPatternParser(String pattern) {
        super(pattern);
    }
 
    @Override
    protected void finalizeConverter(char c) {
        if (c == 'T') {
            this.addConverter(new ExPatternConverter(this.formattingInfo));
        } else {
            super.finalizeConverter(c);
        }
    }
 
    private static class ExPatternConverter extends PatternConverter {
        public ExPatternConverter(FormattingInfo fi) {
            super(fi);
        }
 
        @Override
        protected String convert(LoggingEvent event) {
            return String.valueOf(ThreadTokenHelper.getThreadToken());
        }
 
    }
}

 繼承log4j的PatternLayout類，並重寫createPatternParser方法。

public class Log4jExPatternLayout extends PatternLayout {
    public Log4jExPatternLayout(String pattern){
        super(pattern);
    }
 
    public Log4jExPatternLayout(){
        super();
    }
 
    @Override
    protected PatternParser createPatternParser(String pattern) {
        return new Log4jExPatternParser(pattern);
    }
}

log4j配置檔案的配置，PatternLayout使用自己定義的Log4jExPatternLayout。[%T]就是我們token資訊的位置，通過上面的重寫log解析，可以解析'T'這個字元。

    <!-- console log-->
	<appender name="stdout" class="org.apache.log4j.ConsoleAppender">
		<param name="Target" value="System.out" />
		<layout class="com.my.extend.log.Log4jExPatternLayout">
			<param name="ConversionPattern" value="%d %p [%c] [%T] - (%m)%n" />
		</layout>
	</appender>

       <!-- root logger -->
	<root>
		<priority value="info" />
		<appender-ref ref="stdout" />
	</root>

3.2 生成唯一token

生成token演算法，head與時間相關，精確到毫秒，body是執行緒號，foot是隨機數。head模一天的毫秒數(86400000)，這樣生成的token在某一天內，可以保證唯一性。

private static String genThreadToken(){
        long head = System.currentTimeMillis()%86400000;
        long body = Thread.currentThread().getId();
        int foot = ThreadLocalRandom.current().nextInt(1000);
        String token = head + "_" + body + "_" + foot;
        ThreadContext.getContext().put("token", token);
        return token;
    }

   token的儲存與清除，token儲存線上程的threadlocal中，每一次請求結束清除執行緒當前的token值，下一次請求就會重新獲取最新的token。如果請求發生異常，也需要清除token。

public class ThreadContext {
 
    private static ThreadContext CONTEXT = new ThreadContext();
 
    private static ThreadLocal<Map<String, Object>> CONTEXT_LOCAL = new ThreadLocal<Map<String, Object>>() {
        @Override
        protected Map<String, Object> initialValue() {
            return new HashMap<String, Object>();
        }
    };
 
    private ThreadContext() {
    }
 
    public static ThreadContext getContext() {
        return CONTEXT;
    }
 
    public boolean put(String key, Object value) {
        CONTEXT_LOCAL.get().put(key, value);
        return true;
    }
 
    public Object get(String key) {
        return CONTEXT_LOCAL.get().get(key);
    }
 
    public Object remove(String key) {
        return CONTEXT_LOCAL.get().remove(key);
    }
 
    public void clear() {
        CONTEXT_LOCAL.get().clear();
    }
}

public static String getThreadToken(){
        String token = (String) ThreadContext.getContext().get("token");
        if(token == null){
            return genThreadToken();
        }
        return token;
    }
 
    public static void clear(){
        ThreadContext.getContext().remove("token");
    }

3.3 請求的處理

通過Spring MVC攔截器intercepter，可以在一個請求前後做一些處理，通過把唯一token儲存線上程中的ThreadLocal中，token能在同一個執行緒中進行傳遞。在這裡主要需要，當一個請求結束後，把儲存在當前ThreadLocal中的token清除，那麼當下一個請求處理時，會重新獲取新的token儲存在ThreadLocal中。遇到異常丟擲時，程式碼不會執行到這裡，這時需要在異常處理的地方對執行緒ThreadLocal中的token進行清除。
         intercepter清除token，同時可以列印出請求訪問的相關資訊，訪問使用者， 引數，執行時間
 

public class RequestLoggerHandler extends HandlerInterceptorAdapter {
    private static Logger LOGGER = LogManager.getLogger(RequestLoggerHandler.class);
 
    private ThreadLocal<Long> startTime = new ThreadLocal<>();
 
    @Override
    public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler) throws Exception {
        String url = request.getRequestURI();
        if (DefaultConstant.DEFAULT_WELCOME_URL.equals(url)){
            return true;
        }
        startTime.set(System.currentTimeMillis());
        OpWorker user = new OpWorker(); //TODO
        AjaxRequest ajaxRequest = new AjaxRequest();
        LOGGER.info("[http]preHandle url: {"+request.getRequestURL()+"}, user:{"+JSON.toJSONString(user)+"}, httpBodyParams: {"+toJSONString(ajaxRequest.getParams())+"}, urlParams: {"+toJSONString(request.getQueryString())+"}" );
        return true;
    }
 
    @Override
    public void postHandle(HttpServletRequest request, HttpServletResponse response,
                           Object handler, ModelAndView modelAndView) throws Exception {
        String url = request.getRequestURI();
        if (DefaultConstant.DEFAULT_WELCOME_URL.equals(url)){
            return;
        }
 
        Long causeTime = System.currentTimeMillis() - startTime.get();
        LOGGER.info("[http]postHandle url: {"+request.getRequestURL()+"}, cause\t"+causeTime+"\tms");
        ThreadTokenHelper.clear();
    }
 
    private String toJSONString(Object object){
        try {
            if (object == null){
                return "";
            }
            return JSON.toJSONString(object);
        }catch (Exception e){
            LOGGER.warn("request請求引數序列化{}異常......");
            e.printStackTrace();
        }
        return null;
    }
}

 在Spring配置檔案中的配置

<mvc:interceptor>
    		<mvc:mapping path="/**/*" />
			<bean class="com.ttyc.ebike.op.backend.interceptor.RequestLoggerHandler" />
		</mvc:interceptor>

3.4 日誌示例

下圖紅框內，就是一次請求唯一token資訊，可以看到，兩個token是相同的。通過grep 'token' log就可以把這次請求的所有日誌都查詢出來，可以追蹤程式的執行，方便排查問題。

4.注意

因為每一個請求都是繫結一個執行緒，並生成唯一token與此執行緒繫結，通過spring inteceptor在請求後清除此請求的token資訊。如果發生異常時，會導致inteceptor不能在請求後清除token資訊，會導致請求的token資訊重複。這個時候需要在異常攔截的地方，手動清除下儲存線上程token資訊。

4.1 異常情況

因為每一個請求都是繫結一個執行緒，並生成唯一token與此執行緒繫結，通過spring inteceptor在請求後清除此請求的token資訊。如果發生異常時，會導致inteceptor不能在請求後清除token資訊，會導致請求的token資訊重複。這個時候需要在異常攔截的地方，手動清除下儲存線上程token資訊。

4.2 多執行緒處理

有這樣的場景，一個API在處理過程中，需要呼叫非同步方法傳送訊息，在呼叫非同步方法時就會有第二條執行緒來處理，這個時候，一個請求就會有兩個token資訊。通過查詢一個token，只能得到部分日誌。

4.3 單執行緒處理多工

在使用訊息佇列的業務裡，消費者可用使用單執行緒來處理多條訊息，每一條訊息是一個任務，應該在每一條訊息處理後，手動清除下執行緒中的token資訊，這樣在處理下一條訊息時，日誌資訊中會是新的token，從而不會與上一條訊息的處理日誌產生混淆。