最近我们的线上mongo集群发生了一次事故，主要原因是后台应用在进行mongo读写的时候报错，错误描述是pymongo.errors.OperationFailure: Encountered non-retryable error during query :: caused by :: cannot add session into the cache，由于这次问题影响比较严重，决定专门记录一下问题排查和解决的过程。

环境描述

虚拟机资源: CPU20核，内存32GB，磁盘读写较差

操作系统: ubuntu16.04，内核版本4.4.0-62-generic

mongo版本: 4.0.2，集群拥有三个分片，每个分片分别有主节点、副节点和仲裁节点，三个分片分配在三台不同虚拟机上

mongo驱动: motor2.0对应pymongo3.10.1

问题排查过程

最初出现这个情况的时候，没太在意，以为是单纯的由于mongo集群所在的机器磁盘读写速度太慢加上当时整体读写负载较高导致的。于是就将当时读写比较频繁的业务迁到了其他环境。

在主要的读写压力迁出之后，仍然发现mongo集群报错，就感觉可能是解决问题的方向不对了。

一顿google之后，发现网上无外乎两种解决办法：

  1. mongo版本的问题，有的人说回退到mongo3.6之后升级到mongo4.2就没问题了，无奈我们的实际情况不允许做这么大的变动；
  2. pymongo版本的问题，有人说遇到这个问题之后，将pymongo版本回退到3.7就没事了，做了尝试之后发现根本不起效。

无奈，网上没有合适的解决方案只能自己硬着头皮上了。

客户端排查

上边说到，在mongo集群整体负载较低的时候，仍然会报错，那会不会是因为我们写的代码有问题呢？以报错内容查起，cannot add session into the cache

会不会是因为操作不当，客户端一直在向mongo集群创建连接呢？查看了mongo集群的连接数之后，总共也就1000多个连接，根本不算啥。

那就看看报错中的session数目吧

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14

db.serverStatus().logicalSessionRecordCache
{
        "activeSessionsCount" : 983723,
        "sessionsCollectionJobCount" : 1478,
        "lastSessionsCollectionJobDurationMillis" : 1154,
        "lastSessionsCollectionJobTimestamp" : ISODate("2020-07-15T14:07:38.978Z"),
        "lastSessionsCollectionJobEntriesRefreshed" : 0,
        "lastSessionsCollectionJobEntriesEnded" : 0,
        "lastSessionsCollectionJobCursorsClosed" : 0,
        "transactionReaperJobCount" : 0,
        "lastTransactionReaperJobDurationMillis" : 0,
        "lastTransactionReaperJobTimestamp" : ISODate("2020-07-17T11:02:38.976Z"),
        "lastTransactionReaperJobEntriesCleanedUp" : 0
}

好家伙，activeSessionsCount这个数值怎么会这么高啊，查询了mongo相关的文档之后，发现默认最大支持的activeSessionsCount数值是100万，看来cannot add session into the cache应该就指的是这个值已经快达到阈值，没法再生成新的session了。

重启是程序员的好朋友，看到mongo server端已经这么多session了，实在不行就重启一下整个集群，或许会好呢？

集群重启之后，果然不在报错，大家都各自去忙了。可是好了没一个小时，又开始不定期报错了，再看下activeSessionsCount指标，果然，一个小时内，又创建了60多万的session。

结合当前的状况和文档对mongo server session的解释：

  • 读写压力较低
  • mongo连接数较小
  • activeSessionsCount值爆表

那是什么原因会导致这个指标增长速率这么高且高居不下呢？

查看pymongo代码之后(主要是client_session.py)，发现客户端会在几乎所有操作：包括读、写、聚合各类操作都会使用到session，但是在正常情况下使用（比如常规的读写和数据聚合）session应该不会一直创建，创建好的session会被安排在_ServerSessionPool这样一个双向队列中维护循环使用。通过修改pymongo中的代码，我们可以先定位到session创建速率这么高，到底是谁在搞鬼。

一顿操作之后，发现创建mongo连接之后，在最开始的读写操作过程中，确实会创建一批session，然后就不会继续疯狂创建，而是使用_ServerSessionPool中已有的session。而list_database_names()以及list_collection_names()好像不按套路出牌，每次调用都会创建新的session，并且有的同学居然非常高频的调用这些方法。

发现增长速率快的原因之后，通过修改我们的业务代码，确实可以部分规避这个问题，但是问题并没有完全解决掉。之前的增长速率基本上是200个/s，避免使用上述方法之后增长速率有所减缓但是仍然还保持5个/s，看着activeSessionsCount指标只增不减感觉和官方文档中描述的也不一样啊，问题到底出在哪里呢？

logicalSession

解决了session疯狂创建的问题之后，必须找到activeSessionsCount只增不降的原因。

又是一顿google，好像找到了一些线索：

Logical Sessions in MongoDB

Path to Transactions - Logical Sessions

结合上边的官方文档和视频说明，对logicalSession有了一个更好的理解，结合他们的设计思路越发觉得现在遇到的情况非常怪异。查看下mongo集群的日志，应该会有帮助。

果然，在mongos的日志中，发现大量这样的报错信息：

I CONTROL [LogicalSessionCacheRefresh] Failed to refresh session cache: NoProgressMade: no progress was made executing batch write op in config.system.sessions after 5 rounds (458 ops completed in 7 rounds total)

隐隐觉得应该就是这个问题了，按我现在对session的理解，session的生命周期应该是这样的：

  1. mongo-driver 创建并使用session进行数据库操作
  2. mongo server周期性地(默认周期是五分钟)将session转存入config.system.sessions
  3. mongo server按设置好的session过期时间将session从config.system.sessions中移除

那按现在mongos的日志，无法将session写入config.system.sessions，那么会带来两个后果：

  1. session一直在内存中，activeSessionsCount指标只增不减
  2. config.system.sessions表中没有session，无法移除，lastSessionsCollectionJobEntriesRefreshed指标总是0

现在的问题就在于怎么才能让session从内存正常的转移到config.system.sessions表中，死马当做活马医吧。

看了config.system.sessions表中的内容之后，应该不是什么重要的东西，那就直接drop掉。按mongo官网的说明，重启mongo节点之后，会重新自动创建这个表的。重启集群之后发现果然表被自动创建了，观察了5分钟之后，mongos仍然报错，但是报错内容不一样了 I CONTROL [LogicalSessionCacheRefresh] Sessions collection is not set up; waiting until next sessions refresh interval: Collection config.system.sessions is not sharded。虽然集群自动创建了config.system.sessions，但是没有自动分片，看了这个表中的数据结构之后决定手动按{"_id":1}对这个表分片。

不待集群重启，很快到了下一个session回收周期：

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14

mongos> db.serverStatus().logicalSessionRecordCache
{
        "activeSessionsCount" : 12,
        "sessionsCollectionJobCount" : 2,
        "lastSessionsCollectionJobDurationMillis" : 1525,
        "lastSessionsCollectionJobTimestamp" : ISODate("2020-07-17T11:12:38.979Z"),
        "lastSessionsCollectionJobEntriesRefreshed" : 208788,
        "lastSessionsCollectionJobEntriesEnded" : 0,
        "lastSessionsCollectionJobCursorsClosed" : 0,
        "transactionReaperJobCount" : 0,
        "lastTransactionReaperJobDurationMillis" : 0,
        "lastTransactionReaperJobTimestamp" : ISODate("2020-07-17T11:02:38.976Z"),
        "lastTransactionReaperJobEntriesCleanedUp" : 0
}

mongo sever终于能够自己回收session了！

小结

线上的这次故障，其实也是我们长期欠下的技术债。以后再遇到类似的问题时，可能直接从问题本身查起会更加快捷有效。而之所以会出现session从内存无法写入到config.system.sessions表，目前的推测是由于最近mongo节点读写压力大、分片节点经常切换且整个mongo集群结构调整导致。