问题出现在前司的项目上,虽然已经离职一年多了,但有问题经常会找到我帮忙处理,并支付一点辛苦费。

项目是采用 springCloud 微服务创建的,目前有五六个服务分布在几台服务器上。

这次的问题现象是,用户创建订单后,会莫名其妙自动取消,明白问题后,首先检查该问题订单的服务日志,日志一切正常,正常下单,正常支付,正常修改订单状态。

然后检查代码,发现在另一个服务上,有一个定时任务,采用 spring 的定时任务,通过时间轮来每分钟读取数据库,获取超过设定的事件后还没有支付的订单,然后取消,而这个业务的自动取消设置的未支付 3 分钟后自动取消。顺便提一下,我感觉这种每分钟读取一次数据库来取消订单的做法有点 low,当时在职的时候想去优化一下,但一直没时间,直到拖了我三个月工资后,我提桶跑路(代码和人有一个能跑就行)。

然而这个跑定时任务的服务在另一台服务器上,检查了定时任务的日志,发现定时任务读取未支付订单时,把这单已经支付了的订单给读取出来了,我觉得很不可思议,数据库里检查了一下订单支付时间和订单的取消时间,竟然相差 3 分钟,也就是说,这个订单在支付完成三分钟后,定时任务读取未支付订单把它读取出来了,并做了取消订单的操作。

我又检查了几遍日志和代码,发现代码确实没有问题,订单被取消前,也没有其他的地方修改订单的状态,但一个支付成功的订单就这么被识别为未支付的订单了,这就奇怪了,花费了两三个小时反复检查日志和代码后,我给前司对接的人说,这大概是个灵异事件。

前司同事提议要不换成测试环境再试试,我说可以,然后切换到测试服务器准备查看实时日志,过了一会儿,前司同事给我发来一个截图,上面是新下的一个订单,她特别标记出来了下单时间,和她当时的系统时间,竟然对不上,下单时间竟然比当前时间还早三分钟。

我一下想到一个可能,我去那台业务服务器上查看了当前时间,又去定时任务那台服务器看了下时间,竟然相差 3 分钟,而且定时任务的服务器时间是正确的北京时间,定时任务服务器的时间比北京时间慢了 3 分钟!

一下子就都说得通了,这三分钟的时间差让我耗了两个小时检查代码和日志,业务服务器下单后,下单时间比实际的当前时间早了三分钟,在用户支付的间隙,正常时间服务器跑的定时任务读取超过三分钟的订单自动取消,读取到了这个订单,就造成了用户那边支付完成,定时任务又执行读取好的订单列表去取消。

真相大白后,我准备修改时间不对的服务器时间,检查时区,发现这台服务器的时区是:Time zone: Asia/Shanghai (CST, +0800),而那台正常时间的服务器,时区也是:Time zone: Asia/Shanghai (CST, +0800),但同一个时区,两台服务器获取到的 Universal time 竟然会相差三分钟,网上搜索了这个问题,发现并没有搜索到结果,只好手动卡点设置时间与北京时间同步,如果有知道这个问题原因的小伙伴,麻烦给我解惑一下,谢谢~

最后修改:2023 年 09 月 26 日
請我飲一杯咖啡