業務系統日誌追蹤

時間  2019-11-09
標籤 業務 系統 日誌 追蹤 简体版
原文   原文鏈接

一、遇到的問題

開發中經常會打印業務日誌，這些日誌在排查問題或跟蹤調用流程時很是有用，不少業務日誌並無考慮排查問題時的便利性，看似都記錄了日誌，一旦出現了線上問題，排查起來特別麻煩，不少時候又不方便讓用戶重現問題，形成解決問題週期長甚至是沒法解決問題；若是日誌記錄的好，能夠根據關鍵字搜索得出一條調用鏈日誌，順着這個日誌鏈條就能夠看出程序的執行全過程了。html

二、如何記錄日誌

固然，應用、環境、ip、日誌時間、日誌級別、線程、輸入輸出參數…這些都是必要便於排錯的日誌信息就很少說了，重點說下如何記錄跟蹤一次調用流程的日誌記錄方法。git

一種方法是：打印日誌時候指明業務線，好比支付的流程裏，全部步驟業務日誌統一前綴 "支付流程:userId:"，那麼排查問題時候就能夠根據關鍵字和userId來快速獲得某個userid在支付流程裏的全部軌跡。github

可是這種方法有以下問題：web

一、全部log統一前綴實行起來不太容易api

二、同一個userid的log可能會很是多，並不能按request來歸類app

三、若是涉及到了公共方法調用（同時被多個業務流程調用），統一前綴很難實施dom

……異步

另外一種方法是給每一個request生成惟一的標識，給打印log的地方埋點這個標識，根據這個標識能夠自動造成log鏈路。分佈式

 

本身埋點方式

 

使用filter（filter使用傳送門）給每一個request生成惟一標識，在log裏帶上這個標識，將一個request的log經過惟一標識串成一串。 ide

@WebFilter(filterName = "myFilter",urlPatterns = "/*")
public class LogFilter implements Filter {
    @Override
    public void init(FilterConfig filterConfig) throws ServletException {

    }

    @Override
    public void doFilter(ServletRequest request, ServletResponse response, FilterChain chain) throws IOException, ServletException {
        String replace = UUID.randomUUID().toString().replace("-", "");
        LogHolder.setLogId(replace);
        LogUtil.info("thread:"+Thread.currentThread().getName() + ",uuid : " + replace+",url:"+((HttpServletRequest) request).getRequestURI());
        chain.doFilter(request, response);
        LogHolder.remove();
    }

    @Override
    public void destroy() {

    }
}
View Code

LogUtil：

@Slf4j
public class LogUtil {

    public static void info(String content, Object... args) {
        log.info(String.format("LogFlowId: %s , %s", LogHolder.getLogId(), content), args);
    }

    public static void warn(String content, Object... args) {
        log.info(String.format("LogFlowId: %s , %s", LogHolder.getLogId(), content), args);
    }

    public static void error(String content, Exception ex) {
        log.error(String.format("LogFlowId: %s , %s", LogHolder.getLogId(), content), ex); 
　　}
}

業務場景： 

    @RequestMapping("/log")
    public void writelog() throws InterruptedException {
        LogUtil.info("request begin");
        test();
        LogUtil.info("request end");
    }

    private void test() throws InterruptedException {
        long l = System.currentTimeMillis();
        Thread.sleep(1000);
        LogUtil.info("操做耗時：" + (System.currentTimeMillis() - l) + " ms");
    }
View Code

輸出日誌以下：

能夠根據任意一步的logFlowId檢索出整個request生命週期內的全部log。

對於通常的狀況均可以實現，可是若是程序裏使用了線程池會不會有線程複用的問題？來驗證一下：

業務代碼修改以下： 

    @RequestMapping("/log")
    public void writelog() {
        LogUtil.info("request begin");
        ExecuterServiceUtil.run(() -> test());
        LogUtil.info("request end");
    }

    public void test() {
        long l = System.currentTimeMillis();
        try {
            Thread.sleep(1000);
        } catch (InterruptedException e) {
            e.printStackTrace();
        }
        LogUtil.info("操做耗時：" + (System.currentTimeMillis() - l) + " ms");
    }
View Code

獲取不到設置在ThreadLocal裏的logFlowId了，這是由於線程池從新開闢了子線程，子線程不能訪問主線程設置的logFlowId，可使用 InheritableThreadLocal 來解決問題。

修改LogHolder爲：

public class LogHolder {
    private LogHolder() {
    }

    public static final ThreadLocal<String> LOG_ID = new InheritableThreadLocal<>();

    public static String getLogId() {
        return LOG_ID.get();
    }

    public static void setLogId(String logId) {
        LOG_ID.set(logId);
    }

    public static void remove() {
        LOG_ID.remove();
    }
}
View Code

再次運行發現logFlowId有值了，可是卻重複了，很明顯是由於線程複用形成的問題。

最終解決辦法：

一、獲取主線程設置的logFlowId

二、執行前設置到子線程裏

三、用完後清除子線程變量

輸出日誌以下所示：

若是是分佈式應用跟蹤，能夠經過header透傳方式，將logFlowId傳入下一個應用裏。

附錄

demo

使用MDC

使用攔截器

使用前(preHandle)生成並設置log_trace_id，在使用完(afterCompletion)清除log_trace_id

public class LogInterceptor implements HandlerInterceptor {

    private static final String DEMO_LOG_TRACE_ID = "demo_log_trace_id";
    @Override
    public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler) throws Exception {
        MDC.put(DEMO_LOG_TRACE_ID, UUIdUtil.getUUID());
        return true;
    }

    @Override
    public void postHandle(HttpServletRequest request, HttpServletResponse response, Object handler, ModelAndView modelAndView) throws Exception {
    }

    @Override
    public void afterCompletion(HttpServletRequest request, HttpServletResponse response, Object handler, Exception ex) throws Exception {
        MDC.remove(DEMO_LOG_TRACE_ID);
    }
}

一樣的，若是使用線程池，會有相似的問題。咱們繼承線程池方法，稍做修改

public class ThreadExecutorPoolUtils extends ThreadPoolTaskExecutor {

    /**
     * 全部線程都會委託給這個execute方法，在這個方法中咱們把父線程的MDC內容賦值給子線程
     * https://logback.qos.ch/manual/mdc.html#managedThreads
     *
     * @param runnable
     */
    @Override
    public void execute(Runnable runnable) {
        // 獲取父線程MDC中的內容，必須在run方法以前，不然等異步線程執行的時候有可能MDC裏面的值已經被清空了，這個時候就會返回null
        Map<String, String> context = MDC.getCopyOfContextMap();
        super.execute(() -> run(runnable, context));
    }

    @Override
    public Future<?> submit(Runnable runnable) {
        // 獲取父線程MDC中的內容，必須在run方法以前，不然等異步線程執行的時候有可能MDC裏面的值已經被清空了，這個時候就會返回null
        Map<String, String> context = MDC.getCopyOfContextMap();
       return super.submit(()->run(runnable, context));
    }

    @Override
    public <T> Future<T> submit(Callable<T> callable) {
        // 獲取父線程MDC中的內容，必須在run方法以前，不然等異步線程執行的時候有可能MDC裏面的值已經被清空了，這個時候就會返回null
        Map<String, String> context = MDC.getCopyOfContextMap();
        return super.submit(() -> call(callable, context));
    }

    /**
     * 子線程委託的執行方法
     *
     * @param runnable {@link Runnable}
     * @param context  父線程MDC內容
     */
    private void run(Runnable runnable, Map<String, String> context) {
        // 將父線程的MDC內容傳給子線程
        MDC.setContextMap(context);
        try {
            // 執行異步操做
            runnable.run();
        } finally {
            // 清空MDC內容
            MDC.clear();
        }
    }

    /**
     * 子線程委託的執行方法
     *
     * @param callable {@link Callable}
     * @param context  父線程MDC內容
     */
    private <T> T call(Callable<T> callable, Map<String, String> context) throws Exception {
        // 將父線程的MDC內容傳給子線程
        MDC.setContextMap(context);
        try {
            // 執行異步操做
            return callable.call();
        } finally {
            // 清空子線程MDC內容，防止線程複用問題
            MDC.clear();
        }
    }
}
View Code

logback-xml配置

<pattern>[%d{yyyy-MM-dd HH:mm:ss.SSS}] [%thread] [%level] [%X{demo_log_trace_id}] %logger:%L x:\(%X\) - %msg%n</pattern>

輸出日誌格式

2019-02-02 10:27:14.279 [INFO][Test-Thread-Pool3]:demo.web.api.DemoController [lambda$mutilLog$0:69] [d4676669641a4c6ab94f841d77c2b18e] Test-Thread-Pool3 runs >>>>>, activeAccount:4, corePoolSize:4, maxPoolSize:5, maxPoolSize:Test-Thread-Group, poolSize:4
2019-02-02 10:27:14.279 [INFO][Test-Thread-Pool3]:demo.web.api.DemoController [lambda$mutilLog$0:69] [d4676669641a4c6ab94f841d77c2b18e] Test-Thread-Pool3 runs >>>>>, activeAccount:4, corePoolSize:4, maxPoolSize:5, maxPoolSize:Test-Thread-Group, poolSize:4
2019-02-02 10:27:14.280 [INFO][Test-Thread-Pool3]:demo.web.api.DemoController [lambda$mutilLog$0:69] [d4676669641a4c6ab94f841d77c2b18e] Test-Thread-Pool3 runs >>>>>, activeAccount:4, corePoolSize:4, maxPoolSize:5, maxPoolSize:Test-Thread-Group, poolSize:4
2019-02-02 10:27:14.280 [INFO][Test-Thread-Pool3]:demo.web.api.DemoController [lambda$mutilLog$0:69] [d4676669641a4c6ab94f841d77c2b18e] Test-Thread-Pool3 runs >>>>>, activeAccount:4, corePoolSize:4, maxPoolSize:5, maxPoolSize:Test-Thread-Group, poolSize:4
2019-02-02 10:27:14.280 [INFO][Test-Thread-Pool3]:demo.web.api.DemoController [lambda$mutilLog$0:69] [d4676669641a4c6ab94f841d77c2b18e] Test-Thread-Pool3 runs >>>>>, activeAccount:4, corePoolSize:4, maxPoolSize:5, maxPoolSize:Test-Thread-Group, poolSize:4
2019-02-02 10:27:14.280 [INFO][Test-Thread-Pool3]:demo.web.api.DemoController [lambda$mutilLog$0:69] [d4676669641a4c6ab94f841d77c2b18e] Test-Thread-Pool3 runs >>>>>, activeAccount:4, corePoolSize:4, maxPoolSize:5, maxPoolSize:Test-Thread-Group, poolSize:4
2019-02-02 10:27:14.280 [INFO][Test-Thread-Pool3]:demo.web.api.DemoController [lambda$mutilLog$0:69] [d4676669641a4c6ab94f841d77c2b18e] Test-Thread-Pool3 runs >>>>>, activeAccount:4, corePoolSize:4, maxPoolSize:5, maxPoolSize:Test-Thread-Group, poolSize:4
2019-02-02 10:27:14.281 [INFO][Test-Thread-Pool3]:demo.web.api.DemoController [lambda$mutilLog$0:69] [d4676669641a4c6ab94f841d77c2b18e] Test-Thread-Pool3 runs >>>>>, activeAccount:4, corePoolSize:4, maxPoolSize:5, maxPoolSize:Test-Thread-Group, poolSize:4
2019-02-02 10:27:14.282 [INFO][Test-Thread-Pool3]:demo.web.api.DemoController [lambda$mutilLog$0:69] [d4676669641a4c6ab94f841d77c2b18e] Test-Thread-Pool3 runs >>>>>, activeAccount:4, corePoolSize:4, maxPoolSize:5, maxPoolSize:Test-Thread-Group, poolSize:4
2019-02-02 10:27:14.282 [INFO][Test-Thread-Pool3]:demo.web.api.DemoController [lambda$mutilLog$0:69] [d4676669641a4c6ab94f841d77c2b18e] Test-Thread-Pool3 runs >>>>>, activeAccount:4, corePoolSize:4, maxPoolSize:5, maxPoolSize:Test-Thread-Group, poolSize:4
2019-02-02 10:27:14.282 [INFO][Test-Thread-Pool3]:demo.web.api.DemoController [lambda$mutilLog$0:69] [d4676669641a4c6ab94f841d77c2b18e] Test-Thread-Pool3 runs >>>>>, activeAccount:4, corePoolSize:4, maxPoolSize:5, maxPoolSize:Test-Thread-Group, poolSize:4
2019-02-02 10:27:14.282 [INFO][Test-Thread-Pool3]:demo.web.api.DemoController [lambda$mutilLog$0:69] [d4676669641a4c6ab94f841d77c2b18e] Test-Thread-Pool3 runs >>>>>, activeAccount:4, corePoolSize:4, maxPoolSize:5, maxPoolSize:Test-Thread-Group, poolSize:4
2019-02-02 10:27:14.282 [INFO][Test-Thread-Pool3]:demo.web.api.DemoController [lambda$mutilLog$0:69] [d4676669641a4c6ab94f841d77c2b18e] Test-Thread-Pool3 runs >>>>>, activeAccount:4, corePoolSize:4, maxPoolSize:5, maxPoolSize:Test-Thread-Group, poolSize:4
2019-02-02 10:27:14.255 [INFO][Test-Thread-Pool4]:demo.web.api.DemoController [lambda$mutilLog$0:69] [d4676669641a4c6ab94f841d77c2b18e] Test-Thread-Pool4 runs >>>>>, activeAccount:4, corePoolSize:4, maxPoolSize:5, maxPoolSize:Test-Thread-Group, poolSize:4
2019-02-02 10:27:14.260 [INFO][Test-Thread-Pool2]:demo.web.api.DemoController [lambda$mutilLog$0:69] [d4676669641a4c6ab94f841d77c2b18e] Test-Thread-Pool2 runs >>>>>, activeAccount:4, corePoolSize:4, maxPoolSize:5, maxPoolSize:Test-Thread-Group, poolSize:4
2019-02-02 10:27:14.282 [INFO][Test-Thread-Pool4]:demo.web.api.DemoController [lambda$mutilLog$0:69] [d4676669641a4c6ab94f841d77c2b18e] Test-Thread-Pool4 runs >>>>>, activeAccount:4, corePoolSize:4, maxPoolSize:5, maxPoolSize:Test-Thread-Group, poolSize:4
2019-02-02 10:27:14.282 [INFO][Test-Thread-Pool3]:demo.web.api.DemoController [lambda$mutilLog$0:69] [d4676669641a4c6ab94f841d77c2b18e] Test-Thread-Pool3 runs >>>>>, activeAccount:4, corePoolSize:4, maxPoolSize:5, maxPoolSize:Test-Thread-Group, poolSize:4
相關文章
相關標籤/搜索
每日一句
    每一个你不满意的现在，都有一个你没有努力的曾经。
本站公眾號
   歡迎關注本站公眾號,獲取更多信息
聯繫我們 最近搜索 最新文章 沪ICP备13005482号-10 MyBatis教程 SQL 教程 MySQL教程 Java 教程 Thymeleaf 教程 Hibernate教程 Spring教程 Redis教程