spring-data-mongo的坑之id查询

背景

    这是一次生产事故，会后定位到原因是因为spring-data-mongo的id查询导致的，所以将完整的过程都记录一下。我们生产环境有一个mongo表，数据近两千万条，考虑到数据的持续增加，打算进行数据迁移。由于没有现成的索引能进行有效的数据迁移，并且因为表太大也不适合进行建索引，最终的解决方案就是换表。所以这就是一个线上不停机迁表方案，由于该表的读写相对简单，所以采取一次性迁移，流程如下：

1. 新数据写进新表
2. 数据读取时，先查新表，配置中心增加迁移完成的配置开关，如果开关打开表示迁移没有全部完成，当新表查不到则继续查老表。
3. 更新的时候，根据第二部的查询结果对应去更新新表还是老表。

以上就是完成的迁表方案，这个方案对应当先系统的业务，本身是没有问题的。

过程

当我们上线的时候，我们先发布了灰度环境，然后发布了部分的线上机器，观察一段时间后没有明显的错误，出现了一些mongo timeout的错误，以前也偶尔看到过，所以没怎么在意。之后我们将所有机器完成了新代码的覆盖，也没有明显的问题。随着时间的推移，大概2到3个小时左右，线上mongo timeout增多，并且出现time out的语句各种都有，第一时间怀疑是否是数据库有网络波动，运维人员确认后发现不是网络原因。紧接着出现了mongo 重复主键的报错，更是一脸懵逼，再后来用户就开始各种卡了。后来运维人员在mongo的监控记录中发现了一条更新0条的语句，正式本次代码改动的地方:

return if(newTable){
    logMongo.updateFirst(Query.query(Criteria.where("id").`is`(id)),
        Update().set("active_time", LocalDateTime.now()).set("status", Status.ACTIVE),
        Log::class.java).modifiedCount > 0L
}else{
    logMongo.updateFirst(Query.query(Criteria.where("id").`is`(id)),
        Update().set("active_time", LocalDateTime.now()).set("status", Status.ACTIVE),
        "log").modifiedCount > 0L
}

这段代码正是对应上面方案的第三步骤，根据是否是新表，分别更新新老表的中的数据。细心的同学可能看出问题了，这个对id的查询应该写成_id,由于写成了id，而本省表里没有id这个字段，更没有索引，就会导致更新的时候扫描整张表，前面说过这张表近两千万数据，速度可想而知，超时也就顺其自然了。而更巧的是，这段代码刚好是在mq的消费者中，我们消费者的失败策略是不断重试直到成功，也就会导致每次更新timeout，然后又重试。起初只有一条数据死在里面不断地循环，随着时间的推移，死在里面的数据逐渐针对，线上的timeout越来越多，mongo的负载不断上升，其他没有错误的语句由于mongo的负载过高，也都出现了超时。

那为什么会出现主键重复的报错呢，这个主键重复报错的代码，本次迭代也并没有改动，但由于前面思路理清了，就明了了，因为mongo负载增加，导致另外一处插入mongo语句的操作也失败了，而该操作因为只有一次数据库操作，所以并没有增加事务，然后由于mongo负载过高，响应超时，程序报错了，同样也是因为在消费者里，所以开始不断地重试，其实该插入操作只是响应超时，本身是成功的，所以紧接着就不断出现主键插入冲突。

由于在这两个错误mq不断地堆积下，服务器和mongo的负载不断提升，最终所有用户都在喊卡了。

解决

1. 有问题的代码改正后，重新发版本（由于时间较长，所以第一时间回滚了代码，之后再重新发版本）。
2. 将主键冲突的数据全部删除，让mq顺利消费掉。

事后反思

1. 作为一个老程序员，怎么会将_id写成id犯这种低级错误呢，根本原因是原本的代码是这样的额：

    logMongo.updateFirst(Query.query(Criteria.where("id").`is`(id)),
        Update().set("active_time", LocalDateTime.now()).set("status", Status.ACTIVE),
        Log::class.java).modifiedCount > 0L

后来由于迁表Log中的@Document注解从log表改成了log_v2表，所以对老表的修改语句就变成了这样：

    logMongo.updateFirst(Query.query(Criteria.where("id").`is`(id)),
        Update().set("active_time", LocalDateTime.now()).set("status", Status.ACTIVE),
        "log").modifiedCount > 0L

仅仅是将java类替换成了字符串表名，但是上面写id是正确的，而下面直接用表的方式必须写成_id，故而导致了这次生产事故。

2. 其实这种数据在老表，新代码更新老表数据的场景，在测试环境其实可以进行测试，可惜没有测试到，所以测试点的罗列还是要更加详细，很多隐藏在代码中的细节，还需要开发整理好给到测试进行回归，否则很容遗漏。