[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: |
|
||||||||||||||||
| Description |
|
The driver currently logs:
Relying on the logging framework to print the timestamps
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:
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:
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: 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:2701710: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 , "$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 ] to server 127.0.0.1:27017 } } } ...' with request id 9 to database admin on connection [connectionId {localValue:2, serverValue:1959}] to server 127.0.0.1:27017 ] to server 127.0.0.1:27017 } } } ...' with request id 10 to database admin on connection [connectionId {localValue:2, serverValue:1959}] to server 127.0.0.1:27017 ] to server 127.0.0.1:27017 }'' 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" } |