官方CS BUG导致mongos不可用问题定位记录

问题

前段时间线上陆续遇到MongoDB 4.2版本sharding实例的mongos crash并且实例不可用的问题，现象为：在mongos的日志中出现如下信息、同时mongos crash，并且重启mongos后仍然会继续crash，无法提供服务，问题比较严重。

[conn132492] operation was interrupted because a client disconnected
[conn132492] terminate() called. No exception is active 0x5620c0615da1 0x5620c0615b58 0x5620c0720386 0x5620c07203c1 0x5620bf8a29ad 0x5620bfb1c5f9 0x5620bfb1cb72 0x5620bfa41f28 0x5620bfa6540c 0x5620bfa5f80f 0x5620bfa62a8c 0x5620bfdca2f2 0x5620bfa5d22d 0x5620bfa604c3 0x5620bfa5e8f7 0x5620bfa5f76b 0x5620bfa62a8c 0x5620bfdca75b

在官方JIRA上搜索这个问题，发现官方已在SERVER-47553已修复。

官方patch说明

原因

When constructing a command response, mongos may need to refresh its set of signing keys if the key for the cluster time isn’t currently known. If the client disconnects before this refresh, the resulting error is not properly handled and causes mongos to crash.

JIRA里对问题原因做了简短的说明，mongos在构造命令的响应时，如果客户端的cluster time对应的signing key在mongos本地还没有，mongos需要去刷新signing keys(后面会介绍)。如果在mongos完成刷新之前客户端断开了连接，由此产生的错误没有被正确的处理，并导致mongos crash。

光从这个解释来看，这个问题还是没有说明白，问题的根因、发生问题的场景仍然不清楚。

下面来分析下mongos crash的原因以及官方是怎么修复的。

分析

mongos crash的原因是由于ON_BLOCK_EXIT会在析构函数里去调用appendRequiredFieldsToResponse这个函数，而这个函数在某些情况下可能会抛异常，导致在析构函数中抛出异常。根据C++规范，在析构函数中抛异常会由于『stack unwinding』导致异常无法被上层应用捕获，最终导致进程调用默认处理函数std::terminate直接crash掉。参考：

https://isocpp.org/wiki/faq/exceptions#ctor-exceptions

官方patch的修改主要就是把appendRequiredFieldsToResponse这个函数移到ON_BLOCK_EXIT之外。在应用了SERVER-47553的patch之后，appendRequiredFieldsToResponse抛出的异常就可以被外层的execCommandClient的try {} catch {} 代码块捕获并处理，就不会导致mongos crash了。

那么appendRequiredFieldsToResponse在什么情况下会抛异常呢？具体的call stack如下：

appendRequiredFieldsToResponse
LogicalTimeValidator::signLogicalTime
KeysCollectionManager::refreshNow
uasserted
uassertedWithLocation
error_details::throwExceptionForStatus

可以看到，是KeysCollectionManager::refreshNow这里抛出的异常。

问题依旧

合并官方patch后，mongos不会crash了，本以为问题就此解决，但是发现mongos仍然无法连接后端server节点，无法提供服务。说明这个问题并没有被解决，那这个问题的根因是什么呢？JIRA的comments里没有提、也没有看到相应的bugfix，那就尝试定位一番。

Root Cause调查

从上面的分析可以看到，官方的修复只是避免了在析构函数中触发异常导致进程crash的问题，但是真正触发异常的函数是KeysCollectionManager::refreshNow，这个函数主要是做signing keys的刷新的，就从这里开始着手查问题。

signing keys介绍

signing keys实际上是一种散列消息认证码（Hash-based message authentication code，缩写为HMAC），官方文档中提供了维基百科的解释，它主要用于对客户端连接的消息进行合法性校验。

mongos在向客户端回消息时会带上这个signing key，客户端后续在发送请求给mongos时也需要带上这个signing key，mongos收到请求后也会对signing key进行validate，如果校验通过，则允许执行该请求，同时mongos根据请求中的clusterTime来推进当前的逻辑时钟。客户端携带的逻辑时钟及signing key包括以下信息：

* logicalTime: {
 *     clusterTime: <Timestamp>,
 *     signature: {
 *         hash: <SHA1 hash of clusterTime as BinData>,
 *         keyId: <long long>
 *     }

signing keys的默认有效期为90天，它保存在config server的admin.system.keys这个集合里，具体内容如下：

mgset-1920xxxx:PRIMARY> use admin
switched to db admin
mgset-1920xxxx:PRIMARY> db.system.keys.find()
{ "_id" : NumberLong("6769505655549067294"), "purpose" : "HMAC", "key" : BinData(0,"QvMiPe8PTTgYRcXMAANFaoiQz5M="), "expiresAt" : Timestamp(1583924359, 0) }
{ "_id" : NumberLong("6769505655549067295"), "purpose" : "HMAC", "key" : BinData(0,"VxoXIXvT1WSj5pcjWzrA9+RWWGY="), "expiresAt" : Timestamp(1591700359, 0) }

问题线索

1. 由于这个问题集中在几天内连续出现，出问题的实例中有几个实例是同一天出现问题，并且这几个实例的创建时间点也是在同一天，从实例创建到出问题时，实例刚好运行180天。
2. 同时发现，出问题的时间点就是第二条signing key的过期时间。比如下图中最新的signing key的expiresAt时间戳是1591700359，对应的时间点为2020-06-09 18:59:19，这个时间点刚好也是发生mongos crash和不可用的时间，并且这个时间点距离config server启动的时间点(2019-12-12 18:56:00)刚好就是180天，即两条signing keys的有效期。

时间点梳理：

1. 在定位问题过程中发现，重启config server可以临时解决这个问题。并且重启后会在config server的primary节点的日志中看到类似如下日志，这条日志就是生成新的signing keys并写入到admin.system.keys集合所产生的。

2020-06-09T14:54:38.966+0800 D2 COMMAND  [monitoring-keys-for-HMAC] run command admin.$cmd { insert: "system.keys", bypassDocumentValidation: false, ordered: true, documents: [ { _id: 6836237915341717510, purpose: "HMAC", key: BinData(0, 01EA7154BBCD234A4B656704BE715FF9ECDB15BF), expiresAt: Timestamp(1591685788, 0) } ], writeConcern: { w: "majority", wtimeout: 60000 }, allowImplicitCollectionCreation: true, $db: "admin" }

结合这两条线索，猜测问题原因是config server没有按时去生成有效的signing key，导致mongos无法获取到有效的signing key。因此，我们首先要搞清楚config server和mongos是如何交互和更新signing keys的。

config server与mongos的交互

对于sharding实例，config server的primary节点(启动时或发生主备切换时)会启动一个monitoring-keys-for-HMAC的线程，这个线程主要负责周期性的根据系统当前的cluster time生成新的signing keys，同时会把signing keys维护在cache中。mongos同样也会启动一个monitoring-keys-for-HMAC的线程(KeysCollectionManager::startMonitoring)，这个后台线程主要干两件事：

• 周期性的从config server的admin.system.keys集合中获取比当前clusterTime时间更晚的keys，并维护在mongos本地的KeysCollectionCache中。但是这个cache的刷新周期是一个比较大的值(默认是90天)，对应的参数名称是KeysRotationIntervalSec，并且只能在启动时设置、运行时不能动态调整。

int KeysRotationIntervalSec{3 * 30 * 24 * 60 * 60};

• mongos在构造命令的响应时，如果客户端携带的cluster time对应的signing key在mongos本地还没有，mongos需要去刷新本地signing keys的cache，实际上就是要从config server上去拉取、看看有没有新的signing keys产生，如果有就拉取过来并存到本地的cache里面。这个主动触发的逻辑是由客户端连接线程通知后台线程去做的(KeysCollectionManager::refreshNow)。

KeysCollectionManager::refreshNow会通知并等待后台线程来更新mongos本地的KeysCollectionCache，等待的超时时间是min(maxTimeMS,30秒)，其中maxTimeMS是用户指定的请求超时。如果这里等待超时，最终会抛出异常。

   // note: waitFor waits min(maxTimeMS, kDefaultRefreshWaitTime).
    // waitFor also throws if timeout, so also throw when notification was not satisfied after
    // waiting.
    if (!refreshRequest->waitFor(opCtx, kDefaultRefreshWaitTime)) {
        uasserted(ErrorCodes::ExceededTimeLimit, "timed out waiting for refresh");
    }

前面提到，每条signing key默认有效期是90天，查看config server的admin.system.keys集合，也可以知道，通常mongos要从config server拉取的新生成的signing keys只不过就一两条记录而已。数据量很少，不太可能超时。

定位

config server的primary节点的monitoring-keys-for-HMAC线程根据signing keys的剩余有效期时间计算下次要在什么时间点生成新的signing keys(最大不超过90天)，在这个时间点之前，monitoring-keys-for-HMAC线程会一直处于睡眠状态，但是在计算这个等待时间的时候，有个整型溢出问题(见下面源码，howMuchSleepNeedFor函数中计算唤醒时间millisBeforeExpire时)，导致没到时间线程就会被唤醒，而monitoring-keys线程发现当前的signing keys仍然是有效的，并没有生成新的key。等到signing keys真正过期时，由于唤醒周期计算错误，monitoring-keys-for-HMAC线程却没有被唤醒并生成新的signing keys，导致mongos始终不能从config server上获取到新的signing keys，KeysCollectionManager::refreshNow超时并抛出异常，在析构函数中触发异常，进而导致进程调用std::terminate使mongos crash。同时由于signing keys过期，mongos也无法正常连接后端mongod节点，导致无法服务。

Milliseconds howMuchSleepNeedFor(const LogicalTime& currentTime,
                                 const LogicalTime& latestExpiredAt,
                                 const Milliseconds& interval) {
    auto currentSecs = currentTime.asTimestamp().getSecs();
    auto expiredSecs = latestExpiredAt.asTimestamp().getSecs();

    if (currentSecs >= expiredSecs) {
        // This means that the last round didn't generate a usable key for the current time.
        // However, we don't want to poll too hard as well, so use a low interval.
        return kRefreshIntervalIfErrored;
    }

// 整型溢出
    auto millisBeforeExpire = 1000 * (expiredSecs - currentSecs);

    if (interval.count() <= millisBeforeExpire) {
        return interval;
    }

    return Milliseconds(millisBeforeExpire);
}

解决

确认了问题的根因后，我们及时提了issue(SERVER-48709)反馈给了MongoDB官方，并给出了修复方法：解决这个整型溢出问题就可以了。官方最终在8月份确认并在4.2.10社区版修复了该问题。

值得注意的是，这个bug在3.6以来的所有版本中均存在，在4.2版本上问题是必现的，如果使用的是4.2.10之前(不含)的社区版本的话，需要及时升级config server的内核版本来避免踩坑，如果无法及时升级，可以通过重启config server来临时解决该问题。另外，阿里云MongoDB第一时间对这个问题做了修复，用户无需再做额外处理。