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

Failure from 3.6 server when using DB command API with custom DBEncoder

    • Type: Icon: Bug Bug
    • Resolution: Fixed
    • Priority: Icon: Major - P3 Major - P3
    • 3.6.1
    • Affects Version/s: 3.6.0
    • Component/s: Codecs, Command Operations
    • Labels:
      None
    • Environment:
      * Java Driver 3.6.0
      * Oracle Hotspot JVM 8u141
      * MongoDB 3.6.0 mongod

      Issue comes from using this variant of DB.command API where you provider your own encoder:

      public CommandResult command(final DBObject command, final DBEncoder encoder)
      

      Example repro test case:

          @Test
          public void testCommandCustomEncoder() throws Exception {
              Logger root = (Logger)LoggerFactory.getLogger(Logger.ROOT_LOGGER_NAME);
              root.setLevel(Level.INFO);
      
              // localhost:5000 should be a 3.6 mongod
              try (final MongoClient client = new MongoClient("localhost:5000")) {
                  final DB database = client.getDB("admin");
      
                  CommandResult cmdResult = database.command(new BasicDBObject("isMaster", 1), DefaultDBEncoder.FACTORY.create()); // FAIL
      //            CommandResult cmdResult = database.command(new BasicDBObject("isMaster", 1)); // PASS
                  System.out.println(cmdResult);
                  cmdResult.throwOnError();
              }
          }
      

      Test case output:

      com.mongodb.MongoCommandException: Command failed with error 40571: 'OP_MSG requests require a $db argument' on server localhost:5000. The full response is { "operationTime" : { "$timestamp" : { "t" : 1513189160, "i" : 1 } }, "ok" : 0.0, "errmsg" : "OP_MSG requests require a $db argument", "code" : 40571, "codeName" : "Location40571", "$clusterTime" : { "clusterTime" : { "$timestamp" : { "t" : 1513189160, "i" : 1 } }, "signature" : { "hash" : { "$binary" : "AAAAAAAAAAAAAAAAAAAAAAAAAAA=", "$type" : "00" }, "keyId" : { "$numberLong" : "0" } } } }
      	at com.mongodb.CommandResult.getException(CommandResult.java:80)
      	at com.mongodb.CommandResult.throwOnError(CommandResult.java:94)
      	at foo.Sandbox.testCommandCustomEncoder(Sandbox.java:91)
      

      I've looked into this a little bit, and would appear the general cause is as follows:

      • This DB.command variant causes a DBEncoderAdapter to be used.
      • That adapter interacts with the BSON writer by using pipe()
      • Using pipe() means that the ElementExtendingBsonWriter is not called/hooked for the ElementExtendingBsonWriter.writeEndDocument() invocation
      • This in turn means the extra elements for $db and such that are required for communication with 3.6 mongod aren't written out to wire, causing the error.

      Additional tricky "gotcha" – note that the logging statements of the repro are required, and the log level impacts the triggering of the issue. Changing root.setLevel(Level.INFO) to DEBUG causes the test to then pass. The cause here as discovered by jeff.yemin is debug logging causes encoding of the command document outside of the adapter. This encoding then proceeds through the ElementExtendingBsonWriter and causes the extra elements to be added and written out, avoiding the issue. This appears to happen via com.mongodb.connection.CommandProtocolImpl#getCommandName, called from com.mongodb.connection.CommandProtocolImpl#execute for the debug logging.

            Assignee:
            jeff.yemin@mongodb.com Jeffrey Yemin
            Reporter:
            john.morales@mongodb.com John Morales (Inactive)
            Votes:
            0 Vote for this issue
            Watchers:
            3 Start watching this issue

              Created:
              Updated:
              Resolved: