業務系統日誌追蹤
1、遇到的問題
開發中常常會列印業務日誌,這些日誌在排查問題或跟蹤呼叫流程時非常有用,很多業務日誌並沒有考慮排查問題時的便利性,看似都記錄了日誌,一旦出現了線上問題,排查起來特別麻煩,很多時候又不方便讓使用者重現問題,造成解決問題週期長甚至是無法解決問題;如果日誌記錄的好,可以根據關鍵字搜尋得出一條呼叫鏈日誌,順著這個日誌鏈條就可以看出程式的執行全過程了。
2、如何記錄日誌
當然,應用、環境、ip、日誌時間、日誌級別、執行緒、輸入輸出引數…這些都是必要便於排錯的日誌資訊就不多說了,重點說下如何記錄跟蹤一次呼叫流程的日誌記錄方法。
一種方法是:列印日誌時候指明業務線,比如支付的流程裡,所有步驟業務日誌統一字首 "支付流程:userId:",那麼排查問題時候就可以根據關鍵字和userId來快速得到某個userid在支付流程裡的所有軌跡。
但是這種方法有如下問題:
1、所有log統一字首實行起來不太容易
2、同一個userid的log可能會非常多,並不能按request來歸類
3、如果涉及到了公共方法呼叫(同時被多個業務流程呼叫),統一字首很難實施
……
另一種方法是使用filter(filter使用傳送門)給每個request生成唯一標識,在log裡帶上這個標識,將一個request的log通過唯一標識串成一串。
@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有值了,但是卻重複了,很明顯是因為執行緒複用造成的問題。
最終解決辦法:
1、獲取主執行緒設定的logFlowId
2、執行前設定到子執行緒裡
3、用完後清除子執行緒變數
輸出日誌如下所示:
如果是分散式應用跟蹤,可以通過header透傳方式,將logFlowId傳入下一個應用裡。