Error message here!

Hide Error message here!

忘记密码?

Error message here!

请输入正确邮箱

Hide Error message here!

密码丢失?请输入您的电子邮件地址。您将收到一个重设密码链接。

Error message here!

返回登录

Close

业务系统日志追踪

Mr.yang.localhost 2019-02-02 17:23:00 阅读数:139 评论数:0 点赞数:0 收藏数:0

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传入下一个应用里。

3、附录

demo

版权声明
本文为[Mr.yang.localhost]所创,转载请带上原文链接,感谢
https://www.cnblogs.com/mr-yang-localhost/p/10348345.html

编程之旅,人生之路,不止于编程,还有诗和远方。
阅代码原理,看框架知识,学企业实践;
赏诗词,读日记,踏人生之路,观世界之行;

支付宝红包,每日可领