MongoDB 新特性 Mirrors Reads Bug 发现及分析

1 背景

Mongo组件持续运营过程中，发现“断言”异常，在排除人为操作和客户端异常等噪音后，仍然广泛分布在4系版本中。疑似有大鱼，于是集中力量专项治理。经分析，发现mongo core Bug一项，mongo shell Bug一项，已提交issue，并得到官网确认。其中 SERVER-72532 影响了4.4.11+,5.0.4+, 6.0.0+, 6.2.0-rc4+版本，属于影响范围较大的重要发现，官方暂未发布修复版本。其中 MONGOSH-1357 官方已确认，在版本1.6.2 进行修复。下面具体描述问题的分析过程。

2 问题发现

通过对线上MongoDB集群构建告警监控体系，其中一套线上集群持续发生“客户端断言数量”告警，告警信息如下：

内容：监控点名称：MongoDB-断言数量；总告警条数:45。详细：

[实例：shard1_38_27001，主机：XXX，期望值：0，当前值：8];

[实例：shard1_39_27001，主机：XXX，期望值：0，当前值：8];

[实例：shard2_40_27002，主机：XXX，期望值：0，当前值：4];

[实例：shard2_41_27002，主机：XXX，期望值：0，当前值：8];

[实例：shard2_42_27002，主机：XXX，期望值：0，当前值：9];

[实例：shard3_44_27003，主机：XXX，期望值：0，当前值：10];

[实例：shard3_45_27003，主机：XXX，期望值：0，当前值：10];

……

3 问题分析

问题分析主要从MongoDB的指标、日志、源码三个方面进行分析。其中指标方面主要从访问量、主机、集群各项指标对比分析，尝试找到告警指标与其它监控指标的关联关系。日志方面主要找到导致发生异常的日志详细信息。源码方面主要基于指标、日志分析源码中的问题。

3.1 指标分析

通过对告警信息、监控指标的分析得出以下结论：

– 通过告警信息可以发现，每个分片每秒都有10个左右的断言，10分钟就是6000个断言，这项指标明显偏高，而且判断不会是由于人为操作错误导致的异常，大概率是应用程序或其它MongoDB进程导致。

– 通过告警信息可以发现，发生断言数告警的节点均为各分片的从节点，主节点未发生告警，而应用程序不连从节点，在排除了Exporter嫌疑后，基本确定是MongoDB内部组件引起的告警。

– 通过分析监控指标发现，集群的断言数与应用的操作数趋势一致。由此可以初步判断由于应用的CRUD操作触发了集群内部的异常。

3.2 日志分析

默认的日志级别未打印出有效的异常信息，因此在某个分片的主、从节点分别执行db.setLogLevel(1)命令，将日志级别调高后，抓取更详细的信息如下：

{\”t\”:{\”$date\”:\”2023-01-04T16:02:45.079+08:00\”},\”s\”:\”I\”,  \”c\”:\”NETWORK\”,  \”id\”:51800,   \”ctx\”:\”conn141332\”,\”msg\”:\”client metadata\”,\”attr\”:{\”remote\”:\”主节点IP:51588\”,\”client\”:\”conn141332\”,\”doc\”:{\”driver\”:{\”name\”:\”NetworkInterfaceTL\”,\”version\”:\”4.4.14\”},\”os\”:{\”type\”:\”Linux\”,\”name\”:\”CentOS Linux release 7.6.1810 (Core) \”,\”architecture\”:\”x86_64\”,\”version\”:\”Kernel 3.10.0-957.el7.x86_64\”}}}}

{\”t\”:{\”$date\”:\”2023-01-04T16:02:45.080+08:00\”},\”s\”:\”I\”,  \”c\”:\”ACCESS\”,   \”id\”:20250,   \”ctx\”:\”conn141332\”,\”msg\”:\”Authentication succeeded\”,\”attr\”:{\”mechanism\”:\”SCRAM-SHA-256\”,\”speculative\”:true,\”principalName\”:\”__system\”,\”authenticationDatabase\”:\”local\”,\”remote\”:\”主节点IP:51588\”,\”extraInfo\”:{}}}

{\”t\”:{\”$date\”:\”2023-01-04T17:08:21.381+08:00\”},\”s\”:\”D1\”, \”c\”:\”-\”,        \”id\”:23074,   \”ctx\”:\”conn141332\”,\”msg\”:\”User assertion\”,\”attr\”:{\”error\”:\”CommandNotFound: no such command: \’shardVersion\’\”,\”file\”:\”src/mongo/db/service_entry_point_common.cpp\”,\”line\”:1361}}

{\”t\”:{\”$date\”:\”2023-01-04T17:08:21.381+08:00\”},\”s\”:\”D1\”, \”c\”:\”COMMAND\”,  \”id\”:21966,   \”ctx\”:\”conn141332\”,\”msg\”:\”Assertion while executing command\”,\”attr\”:{\”command\”:\”shardVersion\”,\”db\”:\”orderdb\”,\”error\”:\”CommandNotFound: no such command: \’shardVersion\’\”}}

{\”t\”:{\”$date\”:\”2023-01-04T17:08:21.381+08:00\”},\”s\”:\”I\”,  \”c\”:\”COMMAND\”,  \”id\”:51803,   \”ctx\”:\”conn141332\”,\”msg\”:\”Slow query\”,\”attr\”:{\”type\”:\”command\”,\”ns\”:\”orderdb.$cmd\”,\”command\”:\”unrecognized\”,\”numYields\”:0,\”ok\”:0,\”errMsg\”:\”no such command: \’shardVersion\’\”,\”errName\”:\”CommandNotFound\”,\”errCode\”:59,\”locks\”:{},\”protocol\”:\”op_msg\”,\”durationMillis\”:0}}

{\”t\”:{\”$date\”:\”2023-01-04T17:08:21.381+08:00\”},\”s\”:\”D1\”, \”c\”:\”QUERY\”,    \”id\”:22790,   \”ctx\”:\”conn141332\”,\”msg\”:\”Received interrupt request for unknown op\”,\”attr\”:{\”opId\”:3652609564}}

注意：日志抓取后，记得执行db.setLogLevel(0)恢复日志级别。

相似的日志只在分片的从节点发生，主节点并没有类似的日志，通过分析日志初步得出以下结论：

– 导致User asserts指标告警的原因是MongoDB接收到了不支持的命令：shardVersion。

– 发出shardVersion命令的是主节点IP:51588，根据部署架构，该节点是shard13分片的主节点一个随机端口，因此该主节点是作为客户端主动向从节点发出了一个MongoDB不支持的操作命令shardVersion。

– 代码src/mongo/db/service_entry_point_common.cpp 1361 行，命令解析失败确实会触发 user asserts 指标一直上涨。

– 基于对MongoDB特性的掌握，主从节点之间主要有以下几种情况会发生交互，一是互发心跳，二是数据同步，三是数据预热，得出以下结论：

  – （1）互发心跳方面，从日志中未显示任何心跳信息，且如果心跳包解析异常会触发主从节点切换，而实际情况集群整体运行稳定，因此排除心跳包解析异常的可能性，排除。

  – （2）主从数据同步方面，4.4版本对主从数据同步的方式确实有优化，在4.4以上版本，从节点会以订阅的方式感知主节点的oplog变化，当主节点发生写操作时，会将oplog源源不断的推送到从节点，而4.4以下版本是从节点通过长轮询的方式主动拉取主节点的oplog。因此，数据同步均是从节点作为客户端主动连接主节点，与日志信息不符，排除。

  – （3）数据预热方面，4.4版本新增了主、从节点预热特性，通过查阅官方文档，主节点在发生count、distinct、find、findAndModify、update 操作时，会向从节点主动发起数据预热，即主节点会主动连接从节点按一定的比例进行指令推送，符合现象，因此将排查方向锁定在数据预热部分。

3.3 源码分析

通过以上指标、日志的分析初步锁定在主节点发生count、distinct、find、findAndModify、update操作时，主节点会主动将数据推送给从节点进行预热。对比分析4.4版本与4.2版本代码发现count、distinct、find、findAndModify、update 命令在4.4.11版本发生了变更。在4.4.11版本组装请求时，添加了shardVersion命令。在write_commands.cpp拼接请求时shardVersion被错误的写在请求的第一个字段，导致shardVersion被MongoDB解析成一条命令而导致解析失败。

if (const auto& shardVersion = _commandObj.getField(\”shardVersion\”);

    !shardVersion.eoo()) {

    bob->append(shardVersion);

}

bob->append(\”find\”, _commandObj[\”update\”].String());

extractQueryDetails(_updateOpObj, bob);

bob->append(\”batchSize\”, 1);

bob->append(\”singleBatch\”, true);

3.4 实操验证

通过以上分析，初步确认是由于4.4版本引入的主从节点数据预热新特性导致的命令解析失败。为了验证这个结论，尝试通过禁用数据预热来观察user asserts 是否持续上涨。执行命令：

db.adminCommand( {

  setParameter: 1,

  mirrorReads: { samplingRate: 0.0 }

} )

持续观察user asserts情况可以看出user asserts不再上涨。

shard13 [direct: secondary] admin> db.serverStatus().asserts

{ regular: 0, warning: 0, msg: 0, user: 10007218, rollovers: 0 }

shard13 [direct: secondary] admin> db.serverStatus().asserts

{ regular: 0, warning: 0, msg: 0, user: 10007218, rollovers: 0 }

shard13 [direct: secondary] admin> db.serverStatus().asserts

{ regular: 0, warning: 0, msg: 0, user: 10007218, rollovers: 0 }

shard13 [direct: secondary] admin> db.serverStatus().asserts

{ regular: 0, warning: 0, msg: 0, user: 10007218, rollovers: 0 }

启用数据预热并恢复预热比例为默认值0.01，持续观察user asserts情况可以看出user asserts持续上涨。

shard13 [direct: secondary] admin> db.serverStatus().asserts

{ regular: 0, warning: 0, msg: 0, user: 10007219, rollovers: 0 }

shard13 [direct: secondary] admin> db.serverStatus().asserts

{ regular: 0, warning: 0, msg: 0, user: 10007241, rollovers: 0 }

shard13 [direct: secondary] admin> db.serverStatus().asserts

{ regular: 0, warning: 0, msg: 0, user: 10007257, rollovers: 0 }

到目前为止，通过分析我们已经可以确定是4.4版本MongoDB数据预热特性引发的内核的Bug导致命令解析失败，进而导致user asserts指标持续告警。接下来需要在官方社区上报issue。

3.5 开源社区

MongoDB有单独的JIRA系统来管理社区报告的缺陷，地址：https://jira.mongodb.org。本次发现的 issue 属于MongoDB Core 级别的bug，另外，在禁用数据预热特性时，发现所使用的客户端工具mongosh 1.6.0版本禁用失败，报错信息如下：

db.adminCommand( {

…   setParameter: 1,

…   mirrorReads: { samplingRate: 0.0 }

… } )

MongoServerError: BSON field \’mirrorReads.samplingRate\’ is the wrong type \’int\’, expected type \’double\’

通过客户端工具mongo执行成功，因此判断出客户端工具mongosh 1.6.0在进行小数处理时也存在缺陷，因此一共创建了两个issue，分别是：

https://jira.mongodb.org/browse/SERVER-72532

https://jira.mongodb.org/browse/MONGOSH-1357

并且均得到了官方的有效确认。其中 SERVER-72532 影响了4.4.11以上, 5.0.4以上, 6.0.0以上, 6.2.0-rc4以上版本，属于影响范围较大的重要发现，并且修复版本官方暂未确定。MONGOSH-1357 官方已确认在版本 1.6.2 进行修复。

3.6 影响范围

数据预热属于一个从节点在备生主时性能优化的特性，对集群整体运行及应用使用不构成影响。主要影响数据预热特性及运维监控：

– 影响目前生产环境 4.4.14版本分片集群 update 操作的数据预热，即主节点执行update操作，从节点无法对该操作的数据进行预热。

– 影响 user asserts 指标的监控，可能导致例如认证失败、连接失败等应用使用方式的问题淹没在大量的 user asserts 告警中。

4 解决方法

– 方法一：待官方发布修复版本后，进行版本升级，替换程序，滚动重启即可。

– 方法二：官方建议可以在每个节点禁用数据预热特性，在每个节点执行命令：

db.adminCommand( {

  setParameter: 1,

  mirrorReads: { samplingRate: 0.0 }

} )

– 方法三：官方建议可以在每个节点禁用数据预热特性，滚动重启每个MongoDB进程，加入–setParameter mirrorReads=\'{samplingRate: 0}’ 启动参数。

作者：司冬雨

MongoDB 中文社区成员，现就职于中国联通软件研究院，目前专注于 MongoDB 数据库运维与技术支持，希望能够为社区贡献一份力量。