Uploaded image for project: 'Java Driver'
  1. Java Driver
  2. JAVA-2697

Include elapsed time and request id when logging command execution

    XMLWordPrintable

    Details

    • Type: New Feature
    • Status: Closed
    • Priority: Major - P3
    • Resolution: Fixed
    • Affects Version/s: None
    • Fix Version/s: 3.7.0
    • Component/s: Monitoring
    • Labels:
      None

      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.

        Attachments

          Issue Links

            Activity

              People

              • Votes:
                0 Vote for this issue
                Watchers:
                1 Start watching this issue

                Dates

                • Created:
                  Updated:
                  Resolved: