1 / 1
Jul 2024

We’re using MongoDB 6.0.6 cluster with 3 nodes.

We’ve started noticing strange warning & info messages in our logs, saying that the query has timed out (error.code = 50). It was strange, because our app does not set maxTimeMS for the queries and we cannot see application errors (which should be caused by query timeout, set by client.

{ "t": { "$date": "2024-07-25T22:58:53.488+01:00" }, "s": "I", "c": "NETWORK", "id": 51800, "ctx": "conn101739", "msg": "client metadata", "attr": { "remote": "10.x.x.x:34148", "client": "conn101739", "doc": { "driver": { "name": "NetworkInterfaceTL-MirrorMaestro", "version": "6.0.6" }, "os": { "type": "Linux", "name": "...", "architecture": "x86_64", "version": "..." } } } } { "t": { "$date": "2024-07-25T22:58:53.488+01:00" }, "s": "I", "c": "ACCESS", "id": 5286202, "ctx": "conn101739", "msg": "Different user name was supplied to saslSupportedMechs", "attr": { "error": { "code": 17, "codeName": "ProtocolError", "errmsg": "Attempt to switch database target during SASL authentication from __system@local to @$external" } } } { "t": { "$date": "2024-07-25T22:58:53.488+01:00" }, "s": "I", "c": "ACCESS", "id": 20429, "ctx": "conn101739", "msg": "Successfully authenticated", "attr": { "client": "10.x.x.x:34148", "mechanism": "MONGODB-X509", "user": "...", "db": "$external" } } { "t": { "$date": "2024-07-25T23:00:37.364+01:00" }, "s": "W", "c": "QUERY", "id": 23798, "ctx": "conn101739", "msg": "Plan executor error during find command", "attr": { "error": { "code": 50, "codeName": "MaxTimeMSExpired", "errmsg": "operation exceeded time limit" }, "stats": { /*...*/ }, "cmd": { /*...*/ "limit": 100, "batchSize": 1, "singleBatch": true, "maxTimeMS": 1000, "$readPreference": { "mode": "secondaryPreferred" }, "readConcern": { "level": "local" }, "$db": "the-database" } } } { "t": { "$date": "2024-07-25T23:00:37.364+01:00" }, "s": "W", "c": "COMMAND", "id": 20525, "ctx": "conn101739", "msg": "Failed to gather storage statistics for slow operation", "attr": { "opId": 116221767, "error": "lock acquire timeout" } } { "t": { "$date": "2024-07-25T23:00:37.364+01:00" }, "s": "I", "c": "COMMAND", "id": 51803, "ctx": "conn101739", "msg": "Slow query", "attr": { "type": "command", "ns": "the-database.the-collection", "command": { /*...*/ "limit": 100, "batchSize": 1, "singleBatch": true, "maxTimeMS": 1000, "$readPreference": { "mode": "secondaryPreferred" }, "readConcern": { "level": "local" }, "$db": "the-database" }, "planSummary": "IXSCAN { ... }", "numYields": 47, "queryHash": "557C0B81", "planCacheKey": "FDECA18C", "queryFramework": "classic", "ok": 0, "errMsg": "Executor error during find command :: caused by :: operation exceeded time limit", "errName": "MaxTimeMSExpired", "errCode": 50, "locks": { "FeatureCompatibilityVersion": { "acquireCount": { "r": 48 } }, "Global": { "acquireCount": { "r": 48 } }, "Mutex": { "acquireCount": { "r": 1 } } }, "readConcern": { "level": "local", "provenance": "clientSupplied" }, "remote": "10.x.x.x:34148", "protocol": "op_msg", "durationMillis": 1012 } }

After more detailed look into the logs we noted that these are internal MongoDB queries, produced by NetworkInterfaceTL-MirrorMaestro client (even though the queries look very much like the queries coming from our app).

So, I have the following questions:

  • are these warnings harmful? can they affect data mirroring?
  • what exactly does mongo try to do by imitating our app queries?
  • can I silence these kind of warnings down?
  • I can see that intermediate results (for example, nReturned from IXSCAN) from that queries, which can be seen in the explanation of MaxTimeMSExpired log entry differs from the explanation which I get when I am trying to reproduce this query manualy. Can this be the case (maybe I am missing something in our app logic) and what is the reason for that?