最新消息:

消失的DC日志

Arthas niuge678 906浏览 0评论

问题描述

在FantasyApiController中有一个函数updateRealTimePlayerRulePoints,这个函数添加了@DCFilter注解,但是在Kibana中并没有加载出对应的dc日志。

dc日志(data collector)是一个简洁的日志收集框架。可以把带@DCFilter注解的函数,以及对应的参数,返回值,异常等收集并输出到Kibana,方便调查问题。

调查过程

我对消失的日志,十分困惑,查找原因无从入手,但是又特别希望能找到原因。

一开始,我怀疑是参数中@RequestBody这个注解导致的,原因是:
第一,同一个类中,查询函数getRealTimePlayerRulePoints的dc日志正常输出了;
第二,查询函数用的是@RequestParam,没有使用@RequestBody。

于是,我在本地搭架了一个简易的spring-boot程序,专门写了一个controller去进行验证。结果令人失望,没有问题,日志正常输出。

于是,我开始用arthas跟踪dc的代码。首先尝试了watch。

由于DCFilterHandler的doBefore和doAfterReturning有参数信息,我首先尝试了watch这两个函数。此时,我可以确定的是,不管有没有正确输出日志,这两个函数都被触发了。但是,对于为什么没有输出日志,我还是不清楚根源。

于是,我又尝试跟踪了DcUtil.startDc,这个函数有className做为参数,也比较容易watch,但是它没有返回值,我也没有办法观测函数中的临时变量(此时我没有想到去使用trace,trace可以观测每一步的耗时,实际上也就能观测到每一行代码的执行情况)。

我还尝试跟踪了DcUtil.endDc函数和MDC.end函数,此时,我可以确定MDC.end返回了false(但,此时我并没有意识到,这个返回值false的日志没有输出的原因)。

我甚至还尝试跟踪了dc中的logger.info(json)(因为这个参数里有函数名字的信息),来确定程序有没有执行到这里。也尝试跟踪了start函数中的logData.params = JSON.toJSONString(args)。

当我吃中午饭时,意识到trace可以观测每一行代码的执行情况,一切变得简单起来。

而问题的最终解决还不是trace,是watch中OGNL表达式的使用。

类似于groove脚本,在watch函数时,其实可以利用OGNL调用任何函数(例如构造函数、静态函数、普通函数),这样我就能获取当前线程的任何信息。

watch -b com.alibet.dc.DCFilterHandler doAfterReturning '{params,@com.alibet.dc.MDC@adapter()}' 'params[0].signature.method.name.contains("updateRealTimePlayerRulePoints")' -n 5 -x 3

在上面的代码中,可以观测函数执行前adapter()中count的值,有了这个值,问题就很容易解决了。
我注意到出问题的代码,count=0。显然,是有函数把count值减掉了。继续跟踪start函数,发现了嵌套的@DCFilter在start时有一个clean的操作,导致只有最内层的注解起作用,外层的注解都失效了。

MDC.clear();  // 这里出问题了
MDC.start(className, methodName, args, notRequiredParams);

收获

虽然调查了接近两天,但是收获还是不小。

最大的收获是对arthas中watch的使用(OGNL表达式),trace的使用有了进一步的理解。

最后再感叹一下,arthas是真的好用。

转载请注明:牛哥678 » 消失的DC日志

发表我的评论
取消评论

表情

Hi,您需要填写昵称和邮箱!

  • 昵称 (必填)
  • 邮箱 (必填)
  • 网址