记一个折磨了我一天半的 Bug

2019/05/25 Java

最近开始学习后台开发,虽然与我以前从事的 Android 开发一样都是使用 Java 语言,但是技术栈完全不同,有太多的必备的「新」概念要去学习,而在对它们,以及别人写的代码有充分的了解之前,就可能会遇上这种一杯茶,一根烟,一个 Bug 一天根本改不完的情况。

最近遇见的这个 Bug 是在修改项目遗留的问题时偶然发现的,简而言之就是这样:

服务 A 在从外界接收到推送的一条数据后,将数据插入到库里,然后通过 MQ 推送一条消息给 服务 B服务 B 会根据收到的消息进行一些处理,其中包括远程调用 服务 A 的方法去查询这条数据,但是在测试环境总是报查询不到这条数据。

遇到问题之后,先进行了一些排查:

  • 怀疑传参或者数据插库没有成功,于是将查询参数打印出来,手动复制参数到库里去查——有数据;

  • 怀疑实际执行的 SQL 有问题,于是请同事帮忙配置 MyBatis 在日志里输出 SQL,原样复制出来去库里查——有数据;

  • 在本地连接测试环境数据库,代码里下断点调试——能正常取到数据;

纳闷了一阵以后,继续排查:

  • 怀疑测试环境程序数据库连接有问题,于是测试了一些其它查库的功能——数据正常;

  • 怀疑测试环境的包有问题,于是请运维同事将 jar 包从容器里拷贝下来,核对配置——没问题;

  • 怀疑测试环境远程调用失败了,于是在远程调用处加日志——没有异常;

  • 怀疑测试环境注册了多余的 服务 A 的节点,于是去 Dubbo Admin 里核对节点——数量正常,网段正常;

  • 怀疑测试环境的部署的 服务 A 的某个节点部署有问题,于是请运维同事一个一个 telnet 上去手动执行远程调用——能正常取到数据;

  • 在一条失败 case 之后,马上向 服务 B 手动再次推送相同的消息——能取到数据;

直到我终于留意到一个现象:从日志来看,服务 A 插库与 服务 B 远程调用 服务 A 的方法的时间只相差 1 毫秒。会不会是一切发生得太快了,库里还查不到刚刚写入的数据?抑或者查询的时候插库还根本没有生效?

带着这个疑惑我终于认真去看插库并发消息那块的代码了,于是就看到这样一段代码:

@Override
@Transactional(...)
public boolean doSomething() {
    ...

    // 插入数据

    // 发送消息

    ...
}

是的没错,插入数据和发送消息写在了一个事务里面。虽然我对数据库了解不多,但对事务的特性还是有所了解——发送消息的时候,数据库里确实还没有刚刚插入的数据,事务提交后才会生效,也就是说,服务 B 收到消息后远程调用回 服务 A 想查找刚刚插入的数据,能否查到全凭运气,取决于此时事务已经执行完。

问题时序示意:

要确保消息发出时数据库里已经存在数据了也很简单,将事务粒度控制一下,只包含插入数据这块逻辑即可,插入成功了再发送消息。

PS:如果对消息投递可靠性要求高,可能需要对投递消息失败的情况做一些补偿机制。

@Override
public boolean doSomething() {
    ...

    // 事务开始

    // 插入数据

    // 事务结束

    if (插入数据成功) {
        // 发送消息
    }

    ...
}

正常时序示意:

总结:

  1. 在理解别人写的逻辑的时候不要做预设,你认为别人不可能犯如此低级的错误而直接排除在外的情况,可能恰好是问题所在;

  2. 在排查可能是时序导致的问题时,少用断点调试,用日志更合适;

  3. 本地调试时尽量将场景模拟完整一点,从中途某一环开始则有可能越过问题触发条件而无法复现。

Search

    Table of Contents