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?