[SERVER-49390] TooManyLogicalSessions: Cannot add session into the cache (error code 261) on standalone MongoDB Created: 09/Jul/20  Updated: 27/Oct/23  Resolved: 28/Jul/20

Status: Closed
Project: Core Server
Component/s: Internal Code
Affects Version/s: 4.0.19
Fix Version/s: None

Type: Bug Priority: Major - P3
Reporter: Joydip Datta Assignee: Dmitry Agranat
Resolution: Works as Designed Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Related
Operating System: ALL
Participants:

 Description   

I am getting the same error in a mongodb setup (single replicaset; no sharding)

MongoDB Enterprise node01:PRIMARY> show dbs
2020-07-08T12:56:07.934+0000 E QUERY    [js] Error: listDatabases failed:{
	"ok" : 0,
	"errmsg" : "cannot add session into the cache",
	"code" : 261,
	"codeName" : "TooManyLogicalSessions"
} :
_getErrorWithCode@src/mongo/shell/utils.js:25:13
Mongo.prototype.getDBs@src/mongo/shell/mongo.js:139:1
shellHelper.show@src/mongo/shell/utils.js:882:13
shellHelper@src/mongo/shell/utils.js:766:15
@(shellhelp2):1:1

MongoDB version is 4.0.19

MongoDB Enterprise node01:PRIMARY> version()
4.0.19

Following are excerpts from mongod log

2020-07-08T12:56:03.123+0000 I NETWORK  [listener] connection accepted from XX.YY.20.30:47572 #2050276 (5 connections now open)
2020-07-08T12:56:03.124+0000 I NETWORK  [conn2050276] received client metadata from XX.YY.20.30:47572 conn2050276: { application: { name: "MongoDB Shell" }, driver: { name: "MongoDB Internal Client", version: "4.0.19" }, os: { type: "Linux", name: "CentOS Linux release 7.6.1810 (Core) ", architecture: "x86_64", version: "Kernel 3.10.0-957.el7.x86_64" } }
2020-07-08T12:56:03.138+0000 I ACCESS   [conn2050276] Successfully authenticated as principal rootuser on admin from client XX.YY.20.30:47572
2020-07-08T12:56:22.557+0000 I COMMAND  [PeriodicTaskRunner] task: UnusedLockCleaner took: 589ms
2020-07-08T12:57:23.176+0000 I COMMAND  [PeriodicTaskRunner] task: UnusedLockCleaner took: 618ms
2020-07-08T12:58:23.770+0000 I COMMAND  [PeriodicTaskRunner] task: UnusedLockCleaner took: 593ms
2020-07-08T12:59:24.472+0000 I COMMAND  [PeriodicTaskRunner] task: UnusedLockCleaner took: 701ms
2020-07-08T12:59:59.041+0000 I CONTROL  [LogicalSessionCacheReap] Sessions collection is not set up; waiting until next sessions reap interval: sharding state is not yet initialized
2020-07-08T12:59:59.041+0000 I CONTROL  [LogicalSessionCacheRefresh] Sessions collection is not set up; waiting until next sessions refresh interval: sharding state is not yet initialized
2020-07-08T13:00:25.044+0000 I COMMAND  [PeriodicTaskRunner] task: UnusedLockCleaner took: 572ms
2020-07-08T13:01:25.624+0000 I COMMAND  [PeriodicTaskRunner] task: UnusedLockCleaner took: 579ms
2020-07-08T13:02:26.222+0000 I COMMAND  [PeriodicTaskRunner] task: UnusedLockCleaner took: 597ms
2020-07-08T13:03:26.738+0000 I COMMAND  [PeriodicTaskRunner] task: UnusedLockCleaner took: 515ms
2020-07-08T13:04:27.236+0000 I COMMAND  [PeriodicTaskRunner] task: UnusedLockCleaner took: 498ms
2020-07-08T13:04:38.185+0000 I NETWORK  [conn2050276] end connection XX.YY.20.30:47572 (4 connections now open)
2020-07-08T13:04:59.041+0000 I CONTROL  [LogicalSessionCacheReap] Sessions collection is not set up; waiting until next sessions reap interval: sharding state is not yet initialized
2020-07-08T13:04:59.041+0000 I CONTROL  [LogicalSessionCacheRefresh] Sessions collection is not set up; waiting until next sessions refresh interval: sharding state is not yet initialized

Any help would be useful. The cluster is down and this is affecting our workloads.

Also, is there a way to reopen this JIRA or should I open a new one?

When we monitor number of sessions on MongoDB we see it is always increasing.

Command to monitor sessions.

db.aggregate( [  { $listLocalSessions: { allUsers: true } },{$count: "count"} ] )

This was observed in two separate single replicaset unsharded setup. Example RS status:

MongoDB Enterprise node01:PRIMARY> rs.status()
{
	"set" : "node01",
	"date" : ISODate("2020-07-09T06:35:31.919Z"),
	"myState" : 1,
	"term" : NumberLong(32),
	"syncingTo" : "",
	"syncSourceHost" : "",
	"syncSourceId" : -1,
	"heartbeatIntervalMillis" : NumberLong(2000),
	"majorityVoteCount" : 2,
	"writeMajorityCount" : 2,
	"optimes" : {
		"lastCommittedOpTime" : {
			"ts" : Timestamp(1594276531, 1),
			"t" : NumberLong(32)
		},
		"lastCommittedWallTime" : ISODate("2020-07-09T06:35:31.494Z"),
		"readConcernMajorityOpTime" : {
			"ts" : Timestamp(1594276531, 1),
			"t" : NumberLong(32)
		},
		"readConcernMajorityWallTime" : ISODate("2020-07-09T06:35:31.494Z"),
		"appliedOpTime" : {
			"ts" : Timestamp(1594276531, 1),
			"t" : NumberLong(32)
		},
		"durableOpTime" : {
			"ts" : Timestamp(1594276531, 1),
			"t" : NumberLong(32)
		},
		"lastAppliedWallTime" : ISODate("2020-07-09T06:35:31.494Z"),
		"lastDurableWallTime" : ISODate("2020-07-09T06:35:31.494Z")
	},
	"lastStableRecoveryTimestamp" : Timestamp(1594276461, 1),
	"lastStableCheckpointTimestamp" : Timestamp(1594276461, 1),
	"electionCandidateMetrics" : {
		"lastElectionReason" : "electionTimeout",
		"lastElectionDate" : ISODate("2020-06-23T08:17:47.513Z"),
		"electionTerm" : NumberLong(32),
		"lastCommittedOpTimeAtElection" : {
			"ts" : Timestamp(0, 0),
			"t" : NumberLong(-1)
		},
		"lastSeenOpTimeAtElection" : {
			"ts" : Timestamp(1592900226, 1),
			"t" : NumberLong(31)
		},
		"numVotesNeeded" : 2,
		"priorityAtElection" : 1,
		"electionTimeoutMillis" : NumberLong(10000),
		"numCatchUpOps" : NumberLong(0),
		"newTermStartDate" : ISODate("2020-06-23T08:17:48.222Z"),
		"wMajorityWriteAvailabilityDate" : ISODate("2020-06-23T08:17:49.324Z")
	},
	"members" : [
		{
			"_id" : 0,
			"name" : "node01:27201",
			"health" : 1,
			"state" : 1,
			"stateStr" : "PRIMARY",
			"uptime" : 1376299,
			"optime" : {
				"ts" : Timestamp(1594276531, 1),
				"t" : NumberLong(32)
			},
			"optimeDate" : ISODate("2020-07-09T06:35:31Z"),
			"syncingTo" : "",
			"syncSourceHost" : "",
			"syncSourceId" : -1,
			"infoMessage" : "",
			"electionTime" : Timestamp(1592900267, 1),
			"electionDate" : ISODate("2020-06-23T08:17:47Z"),
			"configVersion" : 705572,
			"self" : true,
			"lastHeartbeatMessage" : ""
		},
		{
			"_id" : 1,
			"name" : "node01:27203",
			"health" : 1,
			"state" : 2,
			"stateStr" : "SECONDARY",
			"uptime" : 1376270,
			"optime" : {
				"ts" : Timestamp(1594276521, 1),
				"t" : NumberLong(32)
			},
			"optimeDurable" : {
				"ts" : Timestamp(1594276521, 1),
				"t" : NumberLong(32)
			},
			"optimeDate" : ISODate("2020-07-09T06:35:21Z"),
			"optimeDurableDate" : ISODate("2020-07-09T06:35:21Z"),
			"lastHeartbeat" : ISODate("2020-07-09T06:35:30.675Z"),
			"lastHeartbeatRecv" : ISODate("2020-07-09T06:35:31.791Z"),
			"pingMs" : NumberLong(0),
			"lastHeartbeatMessage" : "",
			"syncingTo" : "node01:27201",
			"syncSourceHost" : "node01:27201",
			"syncSourceId" : 0,
			"infoMessage" : "",
			"configVersion" : 705572
		}
	],
	"ok" : 1,
	"$clusterTime" : {
		"clusterTime" : Timestamp(1594276531, 1),
		"signature" : {
			"hash" : BinData(0,"AAAAAAAAAAAAAAAAAAAAAAAAAAA="),
			"keyId" : NumberLong(0)
		}
	},
	"operationTime" : Timestamp(1594276531, 1)
}



 Comments   
Comment by Dmitry Agranat [ 28/Jul/20 ]

Hi jdatta@imanisdata.com,

We haven’t heard back from you for some time, so I’m going to mark this ticket as resolved. If this is still an issue for you, please provide additional information and we will reopen the ticket.

Regards,
Dima

Comment by Dmitry Agranat [ 20/Jul/20 ]

Hi jdatta@imanisdata.com,

This misconfiguration only impact the config.system.sessions collection and as a result logical sessions lifecycle. Could you clarify what was the reason you have this configuration in your replica set in the first place?

Thanks,
Dima

Comment by Joydip Datta [ 20/Jul/20 ]

Our use case was a single replicaset without sharding. We had two mongods to form a replset. But as you pointed, our mongod.conf file had this entry 

sharding:
 clusterRole: shardsvr

We have now removed this config param and looks like issue is resolved now. We ran the same repro script (noted above) over 2 days and verified that TooManyLogicalSessions issue did not reproduce. 

 

Can you please check, if this is a misconfiguration, then how our replset setup was otherwise running fine?

 

Comment by Dmitry Agranat [ 19/Jul/20 ]

jdatta@imanisdata.com another thing that we'd like to understand is where this misconfiguration originates from. This would help us to review and adjust our current instructions/documentation which might have caused this.

Comment by Joydip Datta [ 17/Jul/20 ]

Thanks I will check this and get back to you. 

Comment by Dmitry Agranat [ 16/Jul/20 ]

Hi jdatta@imanisdata.com,

The reason you hit this issue is because the config.system.sessions collection does not exist. The sessions purging is done via TTL index on this collection.

The root cause for this issue is your configuration which currently include:

sharding: { clusterRole: "shardsvr" }

In addition, MongoDB has detected this mis-configuration and reported here:

2020-04-13T16:38:42.191+0530 W  SHARDING [initandlisten] Started with --shardsvr, but no shardIdentity document was found on disk in admin.system.version. This most likely means this server has not yet been added to a sharded cluster.

Please fix your configuration and report back with new results.

Thanks,
Dima

Comment by Joydip Datta [ 13/Jul/20 ]

[root@node01 ~]# mongo node01:27201 -u rootuser -p rootuser --authenticationDatabase admin
MongoDB shell version v4.0.19
connecting to: mongodb://node01:27201/test?authSource=admin&gssapiServiceName=mongodb
Implicit session: session { "id" : UUID("65a7420f-6b87-4d8d-8e12-0dc9b09d6955") }
MongoDB server version: 4.0.19
 
MongoDB Enterprise node01:PRIMARY> use config
switched to db config
MongoDB Enterprise node01:PRIMARY> show collections
transactions
MongoDB Enterprise node01:PRIMARY> db.system.sessions.find()
Error: error: {
	"ok" : 0,
	"errmsg" : "not authorized on config to execute command { find: \"system.sessions\", filter: {}, lsid: { id: UUID(\"65a7420f-6b87-4d8d-8e12-0dc9b09d6955\") }, $db: \"config\" }",
	"code" : 13,
	"codeName" : "Unauthorized"
}
MongoDB Enterprise node01:PRIMARY> ^C

Comment by Dmitry Agranat [ 12/Jul/20 ]

Thanks jdatta@imanisdata.com for the repro, one last question, can you check that the config.system.sessions collection exist?

Comment by Joydip Datta [ 10/Jul/20 ]

We could reproduce this with a simple script that opens a lot of MongoDB sessions and runs a find query in a tight loop. We ran 5 such scripts in parallel.

while true
do
	for i in {1..10000}; do
		mongo  node1:27201  --ssl --sslCAFile /data1/mongodb/certs/node.pem --eval 'db.getSiblingDB("aaadbRGLDAPr1").c11.find({ "_id" : "yOKubsKOIv"})'
	done
done

In a separate script, we monitored the number of sessions in the MongoDB server using the following script. This script prints the number of sessions every 2 mins.

while true
do
	echo `date` >> ~/mongo_sessions/result
	mongo  node1:27201  --ssl --sslCAFile /data1/mongodb/certs/node1.pem --eval 'db.aggregate( [  { $listLocalSessions: { allUsers: true } },{$count: "count"} ] )'| grep "count" >> ~/mongo_sessions/result
	sleep 120
done

From the output of the monitoring script, we can clearly see the number of sessions keeps on increasing beyond control. There was no other load against the server at that time. After a while server starts throwing error: TooManyLogicalSessions.

# Script start
Fri Jul 10 11:45:59 IST 2020
{ "count" : 3 }
Fri Jul 10 11:47:59 IST 2020
{ "count" : 4 }
Fri Jul 10 11:49:59 IST 2020
{ "count" : 5 }
Fri Jul 10 11:51:59 IST 2020
{ "count" : 7 }
Fri Jul 10 11:53:59 IST 2020
{ "count" : 8 }
Fri Jul 10 11:55:59 IST 2020
{ "count" : 322 }
Fri Jul 10 11:57:59 IST 2020
{ "count" : 2688 }
Fri Jul 10 11:59:59 IST 2020
{ "count" : 10729 }
Fri Jul 10 12:01:59 IST 2020
{ "count" : 19412 }
Fri Jul 10 12:03:59 IST 2020
{ "count" : 28088 }
Fri Jul 10 12:06:00 IST 2020
{ "count" : 36773 }
Fri Jul 10 12:08:00 IST 2020
{ "count" : 45433 }
Fri Jul 10 12:10:00 IST 2020
{ "count" : 54092 }
[...]
[...]
[...]
Fri Jul 10 12:34:03 IST 2020
{ "count" : 157638 }
Fri Jul 10 12:36:03 IST 2020
{ "count" : 166269 }
Fri Jul 10 12:38:03 IST 2020
{ "count" : 174879 }
Fri Jul 10 12:40:03 IST 2020
{ "count" : 183501 }
Fri Jul 10 12:42:04 IST 2020
{ "count" : 192108 }
Fri Jul 10 12:44:04 IST 2020
{ "count" : 200712 }
Fri Jul 10 12:46:04 IST 2020
{ "count" : 209331 }
Fri Jul 10 12:48:05 IST 2020
{ "count" : 217954 }
Fri Jul 10 12:50:05 IST 2020
{ "count" : 226577 }
[...]
[...]
[...]
Fri Jul 10 15:25:01 IST 2020
{ "count" : 882393 }
Fri Jul 10 15:27:02 IST 2020
{ "count" : 890995 }
Fri Jul 10 15:29:03 IST 2020
{ "count" : 899578 }
Fri Jul 10 15:31:04 IST 2020
{ "count" : 908120 }
Fri Jul 10 15:33:05 IST 2020
{ "count" : 916720 }
Fri Jul 10 15:35:06 IST 2020
{ "count" : 925311 }
Fri Jul 10 15:37:08 IST 2020
{ "count" : 933923 }
Fri Jul 10 15:39:09 IST 2020
{ "count" : 942535 }
Fri Jul 10 15:41:10 IST 2020
{ "count" : 951136 }
Fri Jul 10 15:43:11 IST 2020
{ "count" : 959716 }
Fri Jul 10 15:45:12 IST 2020
{ "count" : 968262 }
Fri Jul 10 15:47:13 IST 2020
{ "count" : 976875 }
Fri Jul 10 15:49:15 IST 2020
{ "count" : 985498 }
Fri Jul 10 15:51:16 IST 2020
{ "count" : 993970 }
Fri Jul 10 15:53:17 IST 2020
Fri Jul 10 15:55:17 IST 2020
# At this point server crashed with TooManyLogicalSessions

Comment by Joydip Datta [ 10/Jul/20 ]

Drivers:

mongo-java-driver 3.12.1

    <!-- https://mvnrepository.com/artifact/org.mongodb/mongo-java-driver -->
    <dependency>
      <groupId>org.mongodb</groupId>
      <artifactId>mongo-java-driver</artifactId>
      <version>3.12.1</version>
    </dependency>

mongodb-driver-async 3.12.1

    <!-- https://mvnrepository.com/artifact/org.mongodb/mongodb-driver-async -->
    <dependency>
        <groupId>org.mongodb</groupId>
        <artifactId>mongodb-driver-async</artifactId>
        <version>3.12.1</version>

Comment by Joydip Datta [ 10/Jul/20 ]

I have uploaded the requested files. Please check.

Comment by Dmitry Agranat [ 09/Jul/20 ]

Hi jdatta@imanisdata.com,

Would you please archive (tar or zip) the mongod.log files and the $dbpath/diagnostic.data directory (the contents are described here) and upload them to this support uploader location?

Files uploaded to this portal are visible only to MongoDB employees and are routinely deleted after some time.

Also, please note what driver type/version you use.

Thanks,
Dima

Comment by Joydip Datta [ 09/Jul/20 ]

This could be similar to: https://jira.mongodb.org/browse/SERVER-39044

Generated at Thu Feb 08 05:19:43 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.