業務系統日誌追蹤
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傳入下一個應用裡。