[JAVA-2987] Change Stream startAtOperationTime MongoCommandException Created: 24/Sep/18  Updated: 28/Oct/23  Resolved: 27/Sep/18

Status: Closed
Project: Java Driver
Component/s: Command Operations, Query Operations
Affects Version/s: 3.8.2
Fix Version/s: 3.9.0

Type: Bug Priority: Major - P3
Reporter: victor carvalho Assignee: Ross Lawley
Resolution: Fixed Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment:

Mongo 4.0.2-xenial (Docker)
3 node replica set


Case:

 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.

 



 Comments   
Comment by victor carvalho [ 27/Sep/18 ]

Thank you @Ross!

 

Comment by Ross Lawley [ 27/Sep/18 ]

Hi victorcarvalho,

This fixed will be released in the next release. There is no eta for that release yet but in the meantime snapshots can be found here: https://oss.sonatype.org/content/repositories/snapshots/org/mongodb/mongo-java-driver/3.8.3-SNAPSHOT/

Ross

Comment by Githook User [ 26/Sep/18 ]

Author:

{'name': 'Ross Lawley', 'email': 'ross.lawley@gmail.com', 'username': 'rozza'}

Message: Fix bug retrying changestreams when a startAtOperationTime was set

JAVA-2987
Branch: 3.8.x
https://github.com/mongodb/mongo-java-driver/commit/e58d5b5388b94fab53fccdfd8e1ce3a181596def

Comment by Githook User [ 26/Sep/18 ]

Author:

{'name': 'Ross Lawley', 'email': 'ross.lawley@gmail.com', 'username': 'rozza'}

Message: Fix bug retrying changestreams when a startAtOperationTime was set

JAVA-2987
Branch: master
https://github.com/mongodb/mongo-java-driver/commit/7dd0779b166089dd611dfbd9ca1f357c049e2ee9

Comment by victor carvalho [ 25/Sep/18 ]

Thank you @Ross Lawley for such fast support and fix.

I feel glad for helping

 

When can I expect it to be released?

 

Victor

 

Comment by Ross Lawley [ 25/Sep/18 ]

Hi victorcarvalho,

Thanks again, the cause has been found and a fix is in code review. When the operation fails (due to the invalid cursor) it is automatically retried and as you correctly summarized both the resumeToken and startAtOperationTime are set causing the exception.

Ross

Comment by Ross Lawley [ 25/Sep/18 ]

Hi victorcarvalho,

Many thanks for the ticket and detailed report. I'll update the ticket once the issue has been replicated and / or the cause found.

Ross

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