[JAVA-2697] Include elapsed time and request id when logging command execution Created: 08/Dec/17  Updated: 28/Oct/23  Resolved: 09/Jan/18

Status: Closed
Project: Java Driver
Component/s: Monitoring
Affects Version/s: None
Fix Version/s: 3.7.0

Type: New Feature Priority: Major - P3
Reporter: Jeffrey Yemin Assignee: Jeffrey Yemin
Resolution: Fixed Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Duplicate
is duplicated by JAVA-1322 Log command line friendly queries and... Closed
Related
related to JAVA-2698 Include more of the command document ... Closed

 Description   

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.



 Comments   
Comment by Githook User [ 09/Jan/18 ]

Author:

{'name': 'Jeff Yemin', 'username': 'jyemin', 'email': 'jeff.yemin@10gen.com'}

Message: JAVA-2697, JAVA-2698: Log successful and failed command events, including elapsed time, request id, and truncated (at 1000 characters) JSON representation of the command. Logs now look like this (against a 3.6 server)

10:37:29.099 [cluster-ClusterId

{value='5a466138741fc252712a6d71', description='null'}-127.0.0.1:27017] DEBUG org.mongodb.driver.protocol.command - Sending command '{ "ismaster" : 1, "$db" : "admin" } ...' with request id 4 to database admin on connection [connectionId{localValue:1, serverValue:1958}] to server 127.0.0.1:27017
10:37:29.104 [cluster-ClusterId{value='5a466138741fc252712a6d71', description='null'}

-127.0.0.1:27017] DEBUG org.mongodb.driver.protocol.command - Execution of command with request id 4 completed successfully in 22.44 ms on connection [connectionId

{localValue:1, serverValue:1958}

] to server 127.0.0.1:27017
10:37:29.154 [main] DEBUG org.mongodb.driver.protocol.command - Sending command '{ "insert" : "test", "ordered" : true, "writeConcern" :

{ "w" : 0 }

, "$db" : "test", "documents" : [{ "_id" :

{ "$oid" : "5a466139741fc252712a6d72" }

, "bytes" : { "$binary" : { "base64" : "AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA ...' with request id 8 to database test on connection [connectionId

{localValue:2, serverValue:1959}

] to server 127.0.0.1:27017
10:37:29.154 [main] DEBUG org.mongodb.driver.protocol.command - Execution of one-way command with request id 8 completed successfully in 24.02 ms on connection [connectionId

{localValue:2, serverValue:1959}

] to server 127.0.0.1:27017
10:37:29.161 [main] DEBUG org.mongodb.driver.protocol.command - Sending command '{ "ping" : 1, "$db" : "admin", "lsid" : { "id" : { "$binary" :

{ "base64" : "1VaSnyegTCy9yXzgsmP0FQ==", "subType" : "04" }

} } } ...' with request id 9 to database admin on connection [connectionId

{localValue:2, serverValue:1959}

] to server 127.0.0.1:27017
10:37:29.162 [main] DEBUG org.mongodb.driver.protocol.command - Execution of command with request id 9 completed successfully in 1.46 ms on connection [connectionId

{localValue:2, serverValue:1959}

] to server 127.0.0.1:27017
10:37:29.163 [main] DEBUG org.mongodb.driver.protocol.command - Sending command '{ "unknown" : 1, "$db" : "admin", "lsid" : { "id" : { "$binary" :

{ "base64" : "1VaSnyegTCy9yXzgsmP0FQ==", "subType" : "04" }

} } } ...' with request id 10 to database admin on connection [connectionId

{localValue:2, serverValue:1959}

] to server 127.0.0.1:27017
10:37:29.175 [main] DEBUG org.mongodb.driver.protocol.command - Execution of command with request id 10 failed to complete successfully in 5.34 ms on connection [connectionId

{localValue:2, serverValue:1959}

] to server 127.0.0.1:27017
com.mongodb.MongoCommandException: Command failed with error 59: 'no such command: 'unknown', bad cmd: '{ unknown: 1, $db: "admin", lsid:

{ id: UUID("d556929f-27a0-4c2c-bdc9-7ce0b263f415") }

}'' on server 127.0.0.1:27017. The full response is { "operationTime" : { "$timestamp" :

{ "t" : 1514556771, "i" : 1 }

}, "ok" : 0.0, "errmsg" : "no such command: 'unknown', bad cmd: '{ unknown: 1, $db: \"admin\", lsid:

{ id: UUID(\"d556929f-27a0-4c2c-bdc9-7ce0b263f415\") }

}'", "code" : 59, "codeName" : "CommandNotFound" }
at com.mongodb.connection.ProtocolHelper.getCommandFailureException(ProtocolHelper.java:164)
Branch: master
https://github.com/mongodb/mongo-java-driver/commit/a93299f7a9a18e9febabfd8445a24af0f8a8c194

Generated at Thu Feb 08 08:57:51 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.