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

Change Stream startAtOperationTime MongoCommandException

    XMLWordPrintable

    Details

    • Type: Bug
    • Status: Closed
    • Priority: Major - P3
    • Resolution: Fixed
    • Affects Version/s: 3.8.2
    • Fix Version/s: 3.9.0
    • Labels:
      None
    • Environment:
      Mongo 4.0.2-xenial (Docker)
      3 node replica set

      Description

      This exception happens everytime I use ChangeStreamIterable.startAtOperationTime():

      com.mongodb.MongoCommandException: Command failed with error 40674 (Location40674): 'Only one type of resume option is allowed, but multiple were found.'
      

      Code I'm using for changestream (simplified):

      ChangeStreamIterable cs = this.inputCollection.watch(this.makePipeline()).fullDocument(FullDocument.UPDATE_LOOKUP);
      cs = cs.startAtOperationTime(new BsonTimestamp(6604821705883910145L));
       
      try (MongoCursor<ChangeStreamDocument> csCursor = cs.iterator()) {
          while (csCursor.hasNext()) {
              ChangeStreamDocument<Document> changeDocument = csCursor.next();
              Document newDocument = changeDocument.getFullDocument();
              System.out.println(newDocument);
          }
      } catch (MongoCommandException e) {
          log.error("Exception in run: " + e.getLocalizedMessage(), e);
      }
      

      The stream is resumed to the correct point and documents are retrieved.
      However, after some time idle in MongoCursor.hasNext(), I can see some in debug logs the following Exception:

      com.mongodb.MongoCommandException: Command failed with error 43 (CursorNotFound): 'cursor id 8186839281604374805 not found' on server 105.103.15.107:30002. The full response is { "operationTime" : { "$timestamp" : { "t" : 1537818089, "i" : 1 } }, "ok" : 0.0, "errmsg" : "cursor id 8186839281604374805 not found", "code" : 43, "codeName" : "CursorNotFound", "$clusterTime" : { "clusterTime" : { "$timestamp" : { "t" : 1537818089, "i" : 1 } }, "signature" : { "hash" : { "$binary" : "AAAAAAAAAAAAAAAAAAAAAAAAAAA=", "$type" : "00" }, "keyId" : { "$numberLong" : "0" } } } }
         at com.mongodb.internal.connection.ProtocolHelper.getCommandFailureException(ProtocolHelper.java:179)
         at com.mongodb.internal.connection.InternalStreamConnection.receiveCommandMessageResponse(InternalStreamConnection.java:293)
         at com.mongodb.internal.connection.InternalStreamConnection.sendAndReceive(InternalStreamConnection.java:255)
         at com.mongodb.internal.connection.UsageTrackingInternalConnection.sendAndReceive(UsageTrackingInternalConnection.java:99)
         at com.mongodb.internal.connection.DefaultConnectionPool$PooledConnection.sendAndReceive(DefaultConnectionPool.java:444)
         at com.mongodb.internal.connection.CommandProtocolImpl.execute(CommandProtocolImpl.java:72)
         at com.mongodb.internal.connection.DefaultServer$DefaultServerProtocolExecutor.execute(DefaultServer.java:200)
         at com.mongodb.internal.connection.DefaultServerConnection.executeProtocol(DefaultServerConnection.java:269)
         at com.mongodb.internal.connection.DefaultServerConnection.command(DefaultServerConnection.java:131)
         at com.mongodb.internal.connection.DefaultServerConnection.command(DefaultServerConnection.java:123)
         at com.mongodb.operation.QueryBatchCursor.getMore(QueryBatchCursor.java:222)
         at com.mongodb.operation.QueryBatchCursor.hasNext(QueryBatchCursor.java:115)
         at com.mongodb.operation.ChangeStreamBatchCursor$1.apply(ChangeStreamBatchCursor.java:59)
         at com.mongodb.operation.ChangeStreamBatchCursor$1.apply(ChangeStreamBatchCursor.java:56)
         at com.mongodb.operation.ChangeStreamBatchCursor.resumeableOperation(ChangeStreamBatchCursor.java:133)
         at com.mongodb.operation.ChangeStreamBatchCursor.hasNext(ChangeStreamBatchCursor.java:56)
         at com.mongodb.client.internal.MongoBatchCursorAdapter.hasNext(MongoBatchCursorAdapter.java:54)
         at com.victor.changestream.Main.run(Main.java:63)
      
      

      Looks like this is treated internally by Mongo driver reopening the Cursor, what causes the MongoCommandException in my application:

      com.mongodb.MongoCommandException: Command failed with error 40674 (Location40674): 'Only one type of resume option is allowed, but multiple were found.' on server 105.103.15.107:30002. The full response is { "operationTime" : { "$timestamp" : { "t" : 1537815472, "i" : 1 } }, "ok" : 0.0, "errmsg" : "Only one type of resume option is allowed, but multiple were found.", "code" : 40674, "codeName" : "Location40674", "$clusterTime" : { "clusterTime" : { "$timestamp" : { "t" : 1537815472, "i" : 1 } }, "signature" : { "hash" : { "$binary" : "AAAAAAAAAAAAAAAAAAAAAAAAAAA=", "$type" : "00" }, "keyId" : { "$numberLong" : "0" } } } }
         at com.mongodb.internal.connection.ProtocolHelper.getCommandFailureException(ProtocolHelper.java:179)
         at com.mongodb.internal.connection.InternalStreamConnection.receiveCommandMessageResponse(InternalStreamConnection.java:293)
         at com.mongodb.internal.connection.InternalStreamConnection.sendAndReceive(InternalStreamConnection.java:255)
         at com.mongodb.internal.connection.UsageTrackingInternalConnection.sendAndReceive(UsageTrackingInternalConnection.java:99)
         at com.mongodb.internal.connection.DefaultConnectionPool$PooledConnection.sendAndReceive(DefaultConnectionPool.java:444)
         at com.mongodb.internal.connection.CommandProtocolImpl.execute(CommandProtocolImpl.java:72)
         at com.mongodb.internal.connection.DefaultServer$DefaultServerProtocolExecutor.execute(DefaultServer.java:200)
         at com.mongodb.internal.connection.DefaultServerConnection.executeProtocol(DefaultServerConnection.java:269)
         at com.mongodb.internal.connection.DefaultServerConnection.command(DefaultServerConnection.java:131)
         at com.mongodb.internal.connection.DefaultServerConnection.command(DefaultServerConnection.java:123)
         at com.mongodb.operation.CommandOperationHelper.executeWrappedCommandProtocol(CommandOperationHelper.java:242)
         at com.mongodb.operation.CommandOperationHelper.executeWrappedCommandProtocol(CommandOperationHelper.java:233)
         at com.mongodb.operation.CommandOperationHelper.executeWrappedCommandProtocol(CommandOperationHelper.java:136)
         at com.mongodb.operation.AggregateOperationImpl$1.call(AggregateOperationImpl.java:193)
         at com.mongodb.operation.AggregateOperationImpl$1.call(AggregateOperationImpl.java:189)
         at com.mongodb.operation.OperationHelper.withConnectionSource(OperationHelper.java:462)
         at com.mongodb.operation.OperationHelper.withConnection(OperationHelper.java:406)
         at com.mongodb.operation.AggregateOperationImpl.execute(AggregateOperationImpl.java:189)
         at com.mongodb.operation.ChangeStreamOperation.execute(ChangeStreamOperation.java:264)
         at com.mongodb.operation.ChangeStreamBatchCursor.resumeableOperation(ChangeStreamBatchCursor.java:145)
         at com.mongodb.operation.ChangeStreamBatchCursor.hasNext(ChangeStreamBatchCursor.java:56)
         at com.mongodb.client.internal.MongoBatchCursorAdapter.hasNext(MongoBatchCursorAdapter.java:54)
         at com.victor.changestream.Main.run(Main.java:63)
      

      So it will end up failing in MongoDb assert code 40674 (https://github.com/mongodb/mongo/blob/master/src/mongo/db/pipeline/document_source_change_stream.cpp#L362).

      According to this test and Mongo documentation, resume token can't be used at the same time than startAtOperationTime. Even though I'm only using startAtOperationTime, Java Mongo Driver uses resume token internally.

      When it sets the resume token, in ChangeStreamBatchCursor.resumeableOperation(), startOperationTimeForResume is set to null. However, startOperationTime keeps the value I set in the beggining. It causes the final BSON, in ChangeStreamOperation.getPipelineCreator(), to be:

      [{ "$changeStream" : { "fullDocument" : "updateLookup", "resumeAfter" : { "_data" : "825BA9277D0000000129295A1004987F22483C7947C4A201F540EF03C40646645F696400645BA9277D951C97282609B8CA0004" }, "startAtOperationTime" : { "$timestamp" : { "t" : 1537804889, "i" : 1 } } } }, { "$match" : { "operationType" : "insert" } }]
      

      It seems to be a bug related to startOperationTime  and startOperationTimeForResume  in the driver.

       

        Attachments

          Activity

            People

            Assignee:
            ross.lawley Ross Lawley
            Reporter:
            victorcarvalho victor carvalho
            Participants:
            Votes:
            0 Vote for this issue
            Watchers:
            2 Start watching this issue

              Dates

              Created:
              Updated:
              Resolved: