问题描述
在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是真的好用。