业务系统日志追踪 - 好文

1、遇到的问题

开发中常常会打印业务日志，这些日志在排查问题或跟踪调用流程时非常有用，很多业务日志并没有考虑排查问题时的便利性，看似都记录了日志，一旦出现了线上问题，排查起来特别麻烦，很多时候又不方便让用户重现问题，造成解决问题周期长甚至是无法解决问题；如果日志记录的好，可以根据关键字搜索得出一条调用链日志，顺着这个日志链条就可以看出程序的执行全过程了。

2、如何记录日志

当然，应用、环境、ip、日志时间、日志级别、线程、输入输出参数…这些都是必要便于排错的日志信息就不多说了，重点说下如何记录跟踪一次调用流程的日志记录方法。

一种方法是：打印日志时候指明业务线，比如支付的流程里，所有步骤业务日志统一前缀
"支付流程:userId:"，那么排查问题时候就可以根据关键字和userId来快速得到某个userid在支付流程里的所有轨迹。

但是这种方法有如下问题：

1、所有log统一前缀实行起来不太容易

2、同一个userid的log可能会非常多，并不能按request来归类

3、如果涉及到了公共方法调用（同时被多个业务流程调用），统一前缀很难实施

……

另一种方法是使用filter（filter使用传送门
<https://www.cnblogs.com/mr-yang-localhost/p/7784607.html#_label2>
）给每个request生成唯一标识，在log里带上这个标识，将一个request的log通过唯一标识串成一串。
@WebFilter(filterName = "myFilter",urlPatterns = "/*") public class LogFilter
implements Filter { @Override public void init(FilterConfig filterConfig) throws
ServletException { } @Overridepublic 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(); } @Overridepublic 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传入下一个应用里。

3、附录

demo
<https://github.com/yangyp8110/xx-dem/wiki/%E5%88%86%E5%B8%83%E5%BC%8F%E6%97%A5%E5%BF%97%E8%BF%BD%E8%B8%AA>

热门工具换一换