-
Type:
New Feature
-
Resolution: Fixed
-
Priority:
Major - P3
-
Affects Version/s: None
-
Component/s: Monitoring
-
None
The driver currently logs:
Sending command {find : BsonString{value='mycollection'}} to database mydb on connection [connectionId{localValue:13, serverValue:361425}] to server myserver:27017
Command execution completed
Relying on the logging framework to print the timestamps
2017-12-06T19:05:17.780+0000 DEBUG : loggerName="org.mongodb.driver.protocol.command" threadName="qtp1848125895-70" txnId="f04394d3-cb7b-44e0-8381-49216e218103" Sending command {find : BsonString{value='mycollection'}} to database mydb on connection [connectionId{localValue:13, serverValue:361425}] to server myserver:27017
2017-12-06T19:05:17.789+0000 DEBUG : loggerName="org.mongodb.driver.protocol.command" threadName="qtp1848125895-70" txnId="f04394d3-cb7b-44e0-8381-49216e218103" Command execution completed
and making forensics more difficult since scripts have to find the two related log messages and diff the timestamps.
The driver could make this easier by logging the elapsed time itself:
Sending command {find : BsonString{value='mycollection'}} to database mydb on connection [connectionId{localValue:13, serverValue:361425}] to server myserver:27017
Command execution completed in xxx ms
It's also relying on the logging configuration to log the thread id, which is necessary to correlation the two log messages. Logging a unique request id could fix that:
Sending command {find : BsonString{value='mycollection'}} to database mydb on connection [connectionId{localValue:13, serverValue:361425}] with request id 101 to server myserver:27017
Command execution with request id 101 completed in xxx ms
This would also allow correlation of asynchronous command execution, where it's not possible to correlate these messages by thread id.
As part of this work, the driver will also log exceptions that occur as part of the command execution.
