MongoDB replicaset | version: 4.4 | "Dropping all pooled connections" to secondaries

Ops and Admin Replication
1

Hello everyone,

In a 3 node MongoDB Replicaset, the below error messages occur repeatedly only on the Primary node (master). The error messages show up twice/thrice every hour.

{"t":{"$date":"2021-08-02T21:29:52.720+00:00"},"s":"I",  "c":"CONNPOOL", "id":22572,   "ctx":"MirrorMaestro","msg":"Dropping all pooled connections","attr":{"hostAndPort":"mongo02.abc.com:27017","error":"ShutdownInProgress: Pool for mongo02.abc.com:27017 has expired."}}
{"t":{"$date":"2021-08-02Txx:xx:xx.720+00:00"},"s":"I",  "c":"CONNPOOL", "id":22572,   "ctx":"MirrorMaestro","msg":"Dropping all pooled connections","attr":{"hostAndPort":"mongo03.abc.com:27017","error":"ShutdownInProgress: Pool for mongo03.abc.com:27017 has expired."}}

I tried checking the logs of mongo02 and mongo03. But, there are no error messages there.

This is a normal replicaset with default configuration. No arbiters etc. This issue happens on all clusters that we have.

I googled this error message and read that… this may be because of glibc versions >= 2.27. We are using CentOS and glibc version is 2.17. So, this may not be the cause.

The replicasets are on top of VMs in Azure and they talk internally via private IPs and the VMs are in same subnet. So, no firewall or security rule issue here.

If anyone faced similar issue in the past, please provide your inputs. Thanks in advance !!

3 Likes
2

bring this topic to the top for visibility

3

Is everyone getting the error Dropping all pooled connections recurrently in your MongoDB replicaset configurations ?

If so, can I ignore this error ?

I am not sure about the root cause of this error. But, I have enabled log-level of 5 and found the below information. For some reason, the connection pool used by mongo01 VM to connect to mongo02 and mongo03 expire and this is causing the above error message.

{"t":{"$date":"2021-08-06T11:34:22.860+00:00"},"s":"D4", "c":"CONNPOOL", "id":22578,   "ctx":"MirrorMaestro","msg":"Updating pool controller","attr":{"hostAndPort":"mongo02.abc.com:27017","poolState":"{ requests: 0, ready: 1, pending: 0, active: 0, isExpired: true }"}}
{"t":{"$date":"2021-08-06T11:34:22.860+00:00"},"s":"D2", "c":"CONNPOOL", "id":22571,   "ctx":"MirrorMaestro","msg":"Delistinng connection pool","attr":{"hostAndPort":"mongo02.abc.com:27017"}}
{"t":{"$date":"2021-08-06T11:34:22.860+00:00"},"s":"I",  "c":"CONNPOOL", "id":22572,   "ctx":"MirrorMaestro","msg":"Dropping all pooled connections","attr":{"hostAndPort":"mongo02.abc.com:27017","error":"ShutdownInProgress: Pool for mongo02.abc.com:27017 has expired."}}
{"t":{"$date":"2021-08-06T11:34:22.869+00:00"},"s":"D4", "c":"CONNPOOL", "id":22570,   "ctx":"MirrorMaestro","msg":"Triggered refresh timeout","attr":{"hostAndPort":"mongo02.abc.com:27017"}}
{"t":{"$date":"2021-08-06T11:34:22.869+00:00"},"s":"D4", "c":"CONNPOOL", "id":22579,   "ctx":"MirrorMaestro","msg":"Pool is dead","attr":{"hostAndPort":"mongo02.abc.com:27017"}}
{"t":{"$date":"2021-08-06T11:34:22.933+00:00"},"s":"D4", "c":"CONNPOOL", "id":22578,   "ctx":"ReplNetwork","msg":"Updating pool controller","attr":{"hostAndPort":"mongo03.abc.com:27017","poolState":"{ requests: 0, ready: 1, pending: 0, active: 0, isExpired: false }"}}
{"t":{"$date":"2021-08-06T11:34:22.933+00:00"},"s":"D4", "c":"CONNPOOL", "id":22575,   "ctx":"ReplNetwork","msg":"Comparing connection state to controls","attr":{"hostAndPort":"mongo03.abc.com:27017","poolControls":"{ maxPending: 2, target: 1, }"}}
{"t":{"$date":"2021-08-06T11:34:22.933+00:00"},"s":"D4", "c":"CONNPOOL", "id":22578,   "ctx":"ReplNetwork","msg":"Updating pool controller","attr":{"hostAndPort":"mongo02.abc.com:27017","poolState":"{ requests: 0, ready: 1, pending: 0, active: 0, isExpired: false }"}}
{"t":{"$date":"2021-08-06T11:34:22.933+00:00"},"s":"D4", "c":"CONNPOOL", "id":22575,   "ctx":"ReplNetwork","msg":"Comparing connection state to controls","attr":{"hostAndPort":"mongo02.abc.com:27017","poolControls":"{ maxPending: 2, target: 1, }"}}

{"t":{"$date":"2021-08-06T12:03:14.953+00:00"},"s":"D4", "c":"CONNPOOL", "id":22578,   "ctx":"ReplNetwork","msg":"Updating pool controller","attr":{"hostAndPort":"mongo02.abc.com:27017","poolState":"{ requests: 0, ready: 1, pending: 0, active: 0, isExpired: false }"}}
{"t":{"$date":"2021-08-06T12:03:14.953+00:00"},"s":"D4", "c":"CONNPOOL", "id":22575,   "ctx":"ReplNetwork","msg":"Comparing connection state to controls","attr":{"hostAndPort":"mongo02.abc.com:27017","poolControls":"{ maxPending: 2, target: 1, }"}}
{"t":{"$date":"2021-08-06T12:03:14.953+00:00"},"s":"D4", "c":"CONNPOOL", "id":22578,   "ctx":"ReplNetwork","msg":"Updating pool controller","attr":{"hostAndPort":"mongo03.abc.com:27017","poolState":"{ requests: 0, ready: 1, pending: 0, active: 0, isExpired: false }"}}
{"t":{"$date":"2021-08-06T12:03:14.953+00:00"},"s":"D4", "c":"CONNPOOL", "id":22575,   "ctx":"ReplNetwork","msg":"Comparing connection state to controls","attr":{"hostAndPort":"mongo03.abc.com:27017","poolControls":"{ maxPending: 2, target: 1, }"}}
{"t":{"$date":"2021-08-06T12:03:15.061+00:00"},"s":"D4", "c":"CONNPOOL", "id":22559,   "ctx":"ReplCoord-99839","msg":"Using existing idle connection","attr":{"hostAndPort":"mongo02.abc.com:27017"}}
{"t":{"$date":"2021-08-06T12:03:15.061+00:00"},"s":"D2", "c":"ASIO",     "id":4646300, "ctx":"ReplCoord-99839","msg":"Sending request","attr":{"requestId":17203576,"target":"mongo02.abc.com:27017"}}
{"t":{"$date":"2021-08-06T12:03:15.061+00:00"},"s":"D2", "c":"ASIO",     "id":4630601, "ctx":"ReplCoord-99839","msg":"Request acquired a connection","attr":{"requestId":17203576,"target":"mongo02.abc.com:27017"}}
{"t":{"$date":"2021-08-06T12:03:15.061+00:00"},"s":"D4", "c":"CONNPOOL", "id":22578,   "ctx":"ReplNetwork","msg":"Updating pool controller","attr":{"hostAndPort":"mongo02.abc.com:27017","poolState":"{ requests: 0, ready: 0, pending: 0, active: 1, isExpired: false }"}}
{"t":{"$date":"2021-08-06T12:03:15.061+00:00"},"s":"D3", "c":"NETWORK",  "id":22925,   "ctx":"ReplCoord-99839","msg":"Compressing message","attr":{"compressor":"snappy"}}
{"t":{"$date":"2021-08-06T12:03:15.061+00:00"},"s":"D4", "c":"CONNPOOL", "id":22575,   "ctx":"ReplNetwork","msg":"Comparing connection state to controls","attr":{"hostAndPort":"mongo02.abc.com:27017","poolControls":"{ maxPending: 2, target: 1, }"}}
{"t":{"$date":"2021-08-06T12:03:15.061+00:00"},"s":"D3", "c":"EXECUTOR", "id":23107,   "ctx":"ReplCoord-99839","msg":"Not reaping this thread","attr":{"nextThreadRetirementDate":{"$date":"2021-08-06T12:03:32.799Z"}}}
{"t":{"$date":"2021-08-06T12:03:15.063+00:00"},"s":"D3", "c":"REPL",     "id":21296,   "ctx":"WTJournalFlusher","msg":"Setting oplog truncate after point","attr":{"oplogTruncateAfterPoint":{"":{"$timestamp":{"t":1628251392,"i":1}}}}}
{"t":{"$date":"2021-08-06T12:03:15.063+00:00"},"s":"D3", "c":"STORAGE",  "id":22414,   "ctx":"WTJournalFlusher","msg":"WT begin_transaction","attr":{"snapshotId":868767029,"readSource":"kUnset"}}
{"t":{"$date":"2021-08-06T12:03:15.063+00:00"},"s":"D3", "c":"STORAGE",  "id":22413,   "ctx":"WTJournalFlusher","msg":"WT rollback_transaction for snapshot id {getSnapshotId_toNumber}","attr":{"getSnapshotId_toNumber":868767035}}
{"t":{"$date":"2021-08-06T12:03:15.063+00:00"},"s":"D3", "c":"STORAGE",  "id":22414,   "ctx":"WTJournalFlusher","msg":"WT begin_transaction","attr":{"snapshotId":868767035,"readSource":"kUnset"}}
{"t":{"$date":"2021-08-06T12:03:15.063+00:00"},"s":"D3", "c":"STORAGE",  "id":22413,   "ctx":"WTJournalFlusher","msg":"WT rollback_transaction for snapshot id {getSnapshotId_toNumber}","attr":{"getSnapshotId_toNumber":868767036}}
{"t":{"$date":"2021-08-06T12:03:15.063+00:00"},"s":"D4", "c":"STORAGE",  "id":22419,   "ctx":"WTJournalFlusher","msg":"flushed journal"}
{"t":{"$date":"2021-08-06T12:03:15.063+00:00"},"s":"D3", "c":"NETWORK",  "id":22927,   "ctx":"ReplNetwork","msg":"Decompressing message","attr":{"compressor":"snappy"}}
{"t":{"$date":"2021-08-06T12:03:15.063+00:00"},"s":"D4", "c":"CONNPOOL", "id":22569,   "ctx":"ReplNetwork","msg":"Returning ready connection","attr":{"hostAndPort":"mongo02.abc.com:27017"}}
4

I’m seeing it too on a 3 node system. Version 4.4.6. Doesn’t seem to be causing any problems. Replication is fine.

{"t":{"$date":"2021-09-22T14:31:27.530-04:00"},"s":"I",  "c":"CONNPOOL", "id":22576,   "ctx":"MirrorMaestro","msg":"Connecting","attr":{"hostAndPort":"my_replicate_mongo_server:27017"}}
.... other log entries ...
{"t":{"$date":"2021-09-22T14:36:27.643-04:00"},"s":"I",  "c":"CONNPOOL", "id":22572,   "ctx":"MirrorMaestro","msg":"Dropping all pooled connections","attr":{"hostAndPort":"my_replicate_mongo_server:27017","error":"ShutdownInProgress: Pool for my_replicate_mongo_server:27017 has expired."}}
5

I know its been a while since this was posted, but I am facing exact same issue. Getting connection pool expired error when a write operation is attempted on the primary node. Was anyone able to resolve this issue? @Benjamin_Slade @Manu

6

I’m facing the same issue, did you manage to fix it ?

7

Also wondering if this is solved?
Seeing ConnectionPoolExpired error message looking like this.

“c”:“CONNPOOL”, “id”:22572, “ctx”:“MirrorMaestro”,“msg”:“Dropping all pooled connections”,“attr”:{“hostAndPort”:“mysecondaryhost:myport”,“error”:“ConnectionPoolExpired: Pool for mysecondaryhost:myport has expired.”}}

8

MirrorMaestro is resposible for Mirrored Reads which warms the cache on Secondary Members of a replica set.

https://www.mongodb.com/docs/manual/replication/#enable-disable-support-for-mirrored-reads

This is an Information level log ("s":"I") not an error and is part of the lifecycle of the ConnectionPool. The ConnectionPool has not seen any queries within the maxIdle time and is clearing the pool.

2 Likes
9

Hi i had this error and iI’ve found what was causing it. I share it here if anybody is in my situation.

In fact the problem does not come from my database neither from my network … but from my client server.

Sometimes my client server get its CPU overloaded, all cores going to 100%. In those cases i guess it can’t handle in time its mongoDB requests which leads to this MongoPoolClearedError.

Anyone having this error should check on client side if the server is not overloaded.

10

Thank you Chris. Turning off the mirrored Reads by setting samplingRate to zero got rid of the “informational” errors showing in our PRIMARY’s log files.
I used the command that was in the link you sent.
db.adminCommand( {setParameter: 1,mirrorReads: { samplingRate: 0.0 }} )

11

I’m sure you read it but for anyone who happens upon the topic: disabling mirrored reads could have a performance impact. Mirrored reads warm the cache of secondaries, so they are better prepared to service queries after a change in primary.

Verbatim from the manual.

Mirrored reads reduce the impact of primary elections following an outage or planned maintenance. After a failover in a replica set, the secondary that takes over as the new primary updates its cache as new queries come in. While the cache is warming up performance can be impacted.

12

Hi Chris -
Is there a way to set the mirrorReads samplingRate in the config file?
Or startup command? I could not get get the syntax to work.
And it reverts to 0.1 on restart.

Also, how do I determine a useful value other than default 0.01?
thanks,
Linda

13

Hi @lbesecker

The correct syntax is:

#example to set mirrored read sampling ratemirr
setParameter:
  mirrorReads: "{samplingRate: 0.1}"

And command line:
--setParameter "mirrorReads={samplingRate: 0.1}"

If your application is particularly sensitive to a cold-cache (like after a primary step down/failure) then increasing the sampling rate will reduce that impact.