性能文章>一个奇葩的线上问题,导致我排查了一天!>

一个奇葩的线上问题,导致我排查了一天!原创

1年前
320425

昨天线上又出了个问题,花了一天的时间才找到原因,说起来原因其实特别的坑爹啊。


事情是这样的,最近我们上线了一个刷新用户 token 的功能,也就是 APP 里经常有的,只要你经常操作,就能让你一直保持在线状态,不用一直重新登录,需求就是这么一个并不复杂的需求,也很快的上线了。


但是上线之后发现了一个用户在某段时间持续长达 15 天没有调用过刷新 token 的接口,还一直保持在登录状态(默认 token 失效是 7 天),这个就很奇怪了。


由于我并不是主要的开发,我是负责协助调查原因。


根据开发的口述,我得到的信息如下:


根据数据库日志发现,用户在8月份只登录了两次,两次时间间隔有 15 天之长,另外排除了日志丢失的问题,登录这个日志是同步保存并且在一个事务内的,不存在丢失的可能。


根据 ELK 网关日志发现,用户在这 15 天之内,基本上每天都会使用 APP,而且都还是需要登录的接口。

231A44E1-D80D-4DFB-8CD1-F3E958129FF3.png


根据 ELK 用户服务日志发现,用户并没有在这段时间内刷新过 token,按照道理应该在 7 天后过期,但是却持续了 15 天。


以上的情况,我基本上都看到了,也一一验证过,确实情况就是这样。


那么,我们排查的方向也就确定到,是不是有其他的 BUG 导致用户的 token 会续期的问题?按说如果是这样的话,那么这个问题应该早就存在很久了,不可能等到这个需求上线才出现,也从未看到过任何这方面问题的反馈。


于是,我筛查了一部分用户的日志,发现登陆其实都挺有规律的,大部分情况都会在 <=7 天的时间有一次登陆,超过 7 天的情况看日志也发现是没有接口调用的,大概说明了这个问题是没有出现过的。


难道是这次的上线导致的 bug?


于是咨询了 QA 相关的测试情况以及开发提供的最近线上调用的日志和情况来看,没有什么问题。我还特意去翻看了一遍代码,担心有 BUG 导致给 token 续期了,然而排查后有没有发现问题。至此,排查好像陷入了僵局,于是只能从其他方面找思路。


我询问了关于整个业务的调用链路,简单来说就是用户登录的时候去请求 token,然后保存下来,以后每次请求的时候都带上 token,然后鉴权的服务会去校验 token 的有效性。


那么,我不禁怀疑,难道鉴权的服务存在什么问题???


于是又苦哈哈地排查了一遍鉴权服务的代码,发现代码写的非常垃圾,token 的保存写的到处都是,得有10几个调用的地方。


通过 CAT 排查了一遍这些接口,发现其实大部分的接口最近一个月都没有调用,和开发也确认了一下,这些接口基本都是老接口,已经没有用了。
只有一个有存在调用的地方,也就是我们现在用的鉴权,这个地方只是简单的去 redis 中判断一下 token 是不是存在,在本地和测试环境中也去验证了一把,并没有发现问题。


OK,到此为止,时间也已经到了下午了,包括我在内的几个排查人员已经快要炸了,这个问题已经找了快一天了,没有发现任何问题,整个事情也就陷入了停滞状态。


我默默地点了根烟,你还别说,小苏还真是好抽的很(友情提醒,抽烟有害身体健康)。


我不禁想到以前 leader 说,我以前他么就不抽烟,然后组里其他几个人每次查问题查不到原因,就跑出去抽烟,结果一回来他们说问题找到了,于是我不得不也抽烟。。。


所以怎么说,抽烟能给人带来思路啊。


我不禁想到一个问题,他们说的只是他们说的,虽然我看了他们给我的演示,但是,我除了看到了用户的登录日志,和他们给我看到的网关日志、服务调用的日志之外,我其实并没有去自己去验证他们的说法。


于是,我先从数据库查看了登录日志,发现这个确实没问题,代码验证过,确实在登录的事务之内,虽然这个代码写的很垃圾,框了整个登录逻辑,但是这个事务这时候缺他么额外的保证了这个日志的存在的必要性!


我接着看网关日志,发现也没什么问题,用户的鉴权接口基本在一直调用,但是在7天之后也都通过了,并没有提示 token 失效等情况。
于是我再接着看服务本身的调用日志,之前他们给我看的时候,就是这样一个结果,根据日志信息和用户 ID 没有找到日志,因此排除了用户调用过刷新 token 接口的情况。

7799130E-CCEB-4C92-AB5E-D30C0821657F.png


这里我隐隐感觉到不对劲,于是,我换了一个搜索方式,搜用户的设备信息,不搜用户 ID!!!
结果尼玛出现了!!!搜索到了结果,用户在中间调用过一次刷新 token,看了下时间,第一次登陆8月8号,8月23号又登陆了一次,15号刷新了一次,时间刚好吻合,7天!

4E8E4E52-6000-4827-B438-1810768507C4.png


事情到这里也基本上真相大白了,并不是有什么鸡毛的 BUG,纯粹就是我相信了他们的排查结果并且没有去验证!在错误的排查道路上越走越远了我!


真尼玛是炸裂!


OK,到这里不禁要想,为什么用用户 ID 搜不到结果?我把结果告诉开发的时候,他也惊呆了,他说我搜其他用户 ID 可以搜到啊,说完还给我演示了一下。


我就测试了一下,发现确实可以,进一步测试了几个用户 ID,发现有的能搜到,有的不能搜到,这有点奇怪了。仔细看到了一下我们的 token,发现 token.123.456bdf(中间的是用户ID)这样搜是不搜不到的,token.456.bde123这样能搜到。这应该是分词的问题了,数字连在一起被当做一个字符串分词了,所以存在有的能搜索到,有的不能搜索到,测试了一下发现情况确实是这样。

我们可以自己测试一下 ELK 的分词效果,进入首页,然后选择 ES API 交互。

9F7B55C7-F847-46C1-9C53-97A406B3BA5C.png


验证一下我们的猜测是不是因为分词的问题导致的,默认应该是标准分词,analyzer 选择 standard,可以看到输出结果确实是OK的。

A7648C64-7FA7-41D6-97E5-170B11BB14B0.png


再换一个字符串,tokentest 前加上一点数字,分词的结果也确实如我们猜测的那样。

6704651E-52B5-4261-B3B3-09357ECA517A.png


解决方案的话有两个,第一个只能换一个分词器了,比如我们如果用pattern正则分词器就可以达到我们想要的效果,但是用啥分词这个我们说了不算。

E3A99F92-CAA4-4616-BFAC-11F01B4B6830.png


第二个方法其实可以换一个搜索方式,比如message: "*token*" and message:*123456*这样也能搜索到,只是你平时怎么会这样用呢,对吧。

94360DAC-B890-4055-84CA-7C382EC64739.png


总结一下,我们平时在排查问题的过程中,一定要自己动手,不要轻易相信别人说的情况,大胆假设,小心求证,方得善果。
好了,我是艾小仙,我们下个月见。

点赞收藏
分类:标签:
艾小仙
请先登录,查看2条精彩评论吧
快去登录吧,你将获得
  • 浏览更多精彩评论
  • 和开发者讨论交流,共同进步

为你推荐

实现定时任务的六种策略

实现定时任务的六种策略

5
2