-
Type:
Bug
-
Resolution: Fixed
-
Priority:
Major - P3
-
Affects Version/s: 3.8.2
-
Component/s: Command Operations, Query Operations
-
Labels:None
-
Environment:Mongo 4.0.2-xenial (Docker)
3 node replica set
-
(copied to CRM)
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.