一个奇葩的线上问题，导致我排查了一天！

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

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

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

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

根据开发的口述，我得到的信息如下：

1. 根据数据库日志发现，用户在8月份只登录了两次，两次时间间隔有 15 天之长，另外排除了日志丢失的问题，登录这个日志是同步保存并且在一个事务内的，不存在丢失的可能。
2. 根据 ELK 网关日志发现，用户在这 15 天之内，基本上每天都会使用 APP，而且都还是需要登录的接口。

1. 根据 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 接口的情况。

这里我隐隐感觉到不对劲，于是，我换了一个搜索方式，搜用户的设备信息，不搜用户 ID！！！

结果尼玛出现了！！！搜索到了结果，用户在中间调用过一次刷新 token，看了下时间，第一次登陆8月8号，8月23号又登陆了一次，15号刷新了一次，时间刚好吻合，7天！

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

真尼玛是炸裂！

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

我就测试了一下，发现确实可以，进一步测试了几个用户 ID，发现有的能搜到，有的不能搜到，这有点奇怪了。

仔细看到了一下我们的 token，发现 ​​token.123.456bdf​​​（中间的是用户ID）这样搜是不搜不到的，​​token.456.bde123​​这样能搜到。

这应该是分词的问题了，数字连在一起被当做一个字符串分词了，所以存在有的能搜索到，有的不能搜索到，测试了一下发现情况确实是这样。

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

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

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

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

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

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

好了，我是艾小仙，我们下个月见。

文章转载自公众号：艾小仙