[JAVA-1885] Bulk write can error when upserting across batches Created: 13/Jul/15  Updated: 01/Apr/16  Resolved: 14/Jul/15

Status: Closed
Project: Java Driver
Component/s: Write Operations
Affects Version/s: 3.0.2
Fix Version/s: 3.0.3, 2.13.3

Type: Bug Priority: Major - P3
Reporter: NIkhilesh Gargi Assignee: Ross Lawley
Resolution: Done Votes: 0
Labels: bulk_api
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Attachments: Zip Archive JAVA-1885.zip    

 Description   

The buggy behaviour comes into play for a bulk write operation when:

1) Number of bulk writes is greater than internal batch size + 1 (i.e. > 1000 + 1 = 1002 or above)
2) Writes are upsert operations. In our case we were using UpdateOneModel with $set and $setOnInsert with upsert = true
2) Bulk operations are interleaved operations of different types e.g. writes and delete e.g. alternate write and deletes (1002 each or 2004 in total)
3) Writes are unordered (we have not tested the ordered writes)

The problem does not occur if:
1) The documents being upserted are already there i.e. if you repeat the bulk write for same set of documents, then you will not see the issue.

The error thrown is MongoInternalException "no mapping found for index 0"

The error seems to be caused when com.mongodb.operation.MixedBulkWriteOperation.UnorderedRunGenerator -> iterator#next() adds a entry in Index map for second batch of upserts
run.add(writeRequest, curIndex);

Internally Index map converts the RangeBased map to HashBased map:

else

{ IndexMap hashBasedMap = new HashBased(startIndex, count); hashBasedMap.add(index, originalIndex); return hashBasedMap; }

But the initialization code in the constructor of HashBased() does not entet the for loop as the condition i <= count is not met.

for (int i = startIndex; i <= count; i++)

{ indexMap.put(i - startIndex, i); }

Thus the mapping for index 0 is not created



 Comments   
Comment by Ross Lawley [ 08/Sep/15 ]

Hi nikhilgargi, excellent news, thanks for getting back so quickly.

All the best,

Ross

Comment by NIkhilesh Gargi [ 08/Sep/15 ]

Yes, you are right. I missed updating the Java driver version. I had updated the mongo server version

Comment by Ross Lawley [ 08/Sep/15 ]

Hi nikhilgargi,

I'm confused becuase looking at the logs I see:

Exception in thread "main" com.mongodb.MongoInternalException: no mapping found for index 0
	at com.mongodb.internal.connection.IndexMap$HashBased.map(IndexMap.java:89)

The line number looks wrong because the exception is thrown line 89 and not the expected line 91 - as it was updated in 3.0.3.

See: 3.0.2 IndexMap compared to 3.0.3 IndexMap

Could you double check the installed driver version and I'll rerun the provided test case to check and confirm the fix.

All the best,

Ross

Comment by NIkhilesh Gargi [ 08/Sep/15 ]

I can still reproduce the issue in 3.0.3 and 3.0.5 using the test case attached earlier in the JIRA. Following are the error logs from both versions:

3.0.3 logs:

Sep 08, 2015 10:18:05 AM com.mongodb.diagnostics.logging.JULLogger log
INFO: Cluster created with settings {hosts=[127.0.0.1:27017], mode=SINGLE, requiredClusterType=UNKNOWN, serverSelectionTimeout='30000 ms', maxWaitQueueSize=500}
Sep 08, 2015 10:18:05 AM com.mongodb.diagnostics.logging.JULLogger log
INFO: No server chosen by PrimaryServerSelector from cluster description ClusterDescription{type=UNKNOWN, connectionMode=SINGLE, all=[ServerDescription{address=127.0.0.1:27017, type=UNKNOWN, state=CONNECTING}]}. Waiting for 30000 ms before timing out
Sep 08, 2015 10:18:05 AM com.mongodb.diagnostics.logging.JULLogger log
INFO: Opened connection [connectionId{localValue:1, serverValue:1}] to 127.0.0.1:27017
Sep 08, 2015 10:18:05 AM com.mongodb.diagnostics.logging.JULLogger log
INFO: Monitor thread successfully connected to server with description ServerDescription{address=127.0.0.1:27017, type=STANDALONE, state=CONNECTED, ok=true, version=ServerVersion{versionList=[3, 0, 3]}, minWireVersion=0, maxWireVersion=3, electionId=null, maxDocumentSize=16777216, roundTripTimeNanos=455810}
Sep 08, 2015 10:18:05 AM com.mongodb.diagnostics.logging.JULLogger log
INFO: Opened connection [connectionId{localValue:2, serverValue:2}] to 127.0.0.1:27017
Exception in thread "main" com.mongodb.MongoInternalException: no mapping found for index 0
	at com.mongodb.internal.connection.IndexMap$HashBased.map(IndexMap.java:89)
	at com.mongodb.connection.BulkWriteBatchCombiner.mergeUpserts(BulkWriteBatchCombiner.java:199)
	at com.mongodb.connection.BulkWriteBatchCombiner.addResult(BulkWriteBatchCombiner.java:91)
	at com.mongodb.operation.MixedBulkWriteOperation$1.call(MixedBulkWriteOperation.java:150)
	at com.mongodb.operation.MixedBulkWriteOperation$1.call(MixedBulkWriteOperation.java:141)
	at com.mongodb.operation.OperationHelper.withConnectionSource(OperationHelper.java:186)
	at com.mongodb.operation.OperationHelper.withConnection(OperationHelper.java:177)
	at com.mongodb.operation.MixedBulkWriteOperation.execute(MixedBulkWriteOperation.java:141)
	at com.mongodb.operation.MixedBulkWriteOperation.execute(MixedBulkWriteOperation.java:72)
	at com.mongodb.Mongo.execute(Mongo.java:747)
	at com.mongodb.Mongo$2.execute(Mongo.java:730)
	at com.mongodb.MongoCollectionImpl.bulkWrite(MongoCollectionImpl.java:268)
	at MongoBulkOperationBugDemo.main(MongoBulkOperationBugDemo.java:38)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:483)
	at com.intellij.rt.execution.application.AppMain.main(AppMain.java:140)

3.0.5 logs:

Sep 08, 2015 10:27:40 AM com.mongodb.diagnostics.logging.JULLogger log
INFO: Cluster created with settings {hosts=[127.0.0.1:27017], mode=SINGLE, requiredClusterType=UNKNOWN, serverSelectionTimeout='30000 ms', maxWaitQueueSize=500}
Sep 08, 2015 10:27:40 AM com.mongodb.diagnostics.logging.JULLogger log
INFO: No server chosen by PrimaryServerSelector from cluster description ClusterDescription{type=UNKNOWN, connectionMode=SINGLE, all=[ServerDescription{address=127.0.0.1:27017, type=UNKNOWN, state=CONNECTING}]}. Waiting for 30000 ms before timing out
Sep 08, 2015 10:27:40 AM com.mongodb.diagnostics.logging.JULLogger log
INFO: Opened connection [connectionId{localValue:1, serverValue:1}] to 127.0.0.1:27017
Sep 08, 2015 10:27:40 AM com.mongodb.diagnostics.logging.JULLogger log
INFO: Monitor thread successfully connected to server with description ServerDescription{address=127.0.0.1:27017, type=STANDALONE, state=CONNECTED, ok=true, version=ServerVersion{versionList=[3, 0, 5]}, minWireVersion=0, maxWireVersion=3, electionId=null, maxDocumentSize=16777216, roundTripTimeNanos=428865}
Sep 08, 2015 10:27:40 AM com.mongodb.diagnostics.logging.JULLogger log
INFO: Opened connection [connectionId{localValue:2, serverValue:2}] to 127.0.0.1:27017
Exception in thread "main" com.mongodb.MongoInternalException: no mapping found for index 0
	at com.mongodb.internal.connection.IndexMap$HashBased.map(IndexMap.java:89)
	at com.mongodb.connection.BulkWriteBatchCombiner.mergeUpserts(BulkWriteBatchCombiner.java:199)
	at com.mongodb.connection.BulkWriteBatchCombiner.addResult(BulkWriteBatchCombiner.java:91)
	at com.mongodb.operation.MixedBulkWriteOperation$1.call(MixedBulkWriteOperation.java:150)
	at com.mongodb.operation.MixedBulkWriteOperation$1.call(MixedBulkWriteOperation.java:141)
	at com.mongodb.operation.OperationHelper.withConnectionSource(OperationHelper.java:186)
	at com.mongodb.operation.OperationHelper.withConnection(OperationHelper.java:177)
	at com.mongodb.operation.MixedBulkWriteOperation.execute(MixedBulkWriteOperation.java:141)
	at com.mongodb.operation.MixedBulkWriteOperation.execute(MixedBulkWriteOperation.java:72)
	at com.mongodb.Mongo.execute(Mongo.java:747)
	at com.mongodb.Mongo$2.execute(Mongo.java:730)
	at com.mongodb.MongoCollectionImpl.bulkWrite(MongoCollectionImpl.java:268)
	at MongoBulkOperationBugDemo.main(MongoBulkOperationBugDemo.java:38)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:483)
	at com.intellij.rt.execution.application.AppMain.main(AppMain.java:140)

Comment by Jeffrey Yemin [ 16/Jul/15 ]

Fix is now available in the 3.0.3 release.

Comment by Ross Lawley [ 14/Jul/15 ]

Many thanks for the report, this issue has been fixed and will be released in 3.0.3

Also merged into 2.x, 2.13.x, 3.0.x, 3.x branches.

Comment by Githook User [ 14/Jul/15 ]

Author:

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

Message: IndexMap improvements

Fixed issue converting from Range to Hash based Index maps
Fixed negative key lookup on Range based Index maps
Added value assertions on creation of Index maps

JAVA-1885
Branch: 2.13.x
https://github.com/mongodb/mongo-java-driver/commit/8b336d3e76f2441f25f44ef28c4f893d029bb75f

Comment by Githook User [ 14/Jul/15 ]

Author:

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

Message: IndexMap improvements

Fixed issue converting from Range to Hash based Index maps
Fixed negative key lookup on Range based Index maps
Added value assertions on creation of Index maps

JAVA-1885
Branch: 2.x
https://github.com/mongodb/mongo-java-driver/commit/15f3d02244ef721530265a5fe275feeb65697e42

Comment by Githook User [ 14/Jul/15 ]

Author:

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

Message: IndexMap improvements

Fixed issue converting from Range to Hash based Index maps
Fixed negative key lookup on Range based Index maps
Added value assertions on creation of Index maps

JAVA-1885
Branch: 3.0.x
https://github.com/mongodb/mongo-java-driver/commit/dc02cc7e7ce3aae6b7de962677ccb7d48737a57b

Comment by Githook User [ 14/Jul/15 ]

Author:

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

Message: IndexMap improvements

Fixed issue converting from Range to Hash based Index maps
Fixed negative key lookup on Range based Index maps
Added value assertions on creation of Index maps

JAVA-1885
Branch: master
https://github.com/mongodb/mongo-java-driver/commit/c10bc6fac249999e71afbc734457a2dc4aada6fa

Comment by Ross Lawley [ 13/Jul/15 ]

Thanks nikhilgargi, great bug report. I hope to have a fix released in the near future.

Ross

Comment by NIkhilesh Gargi [ 13/Jul/15 ]

Title and priority need to be fixed. Fat fingered the JIRA creation. Unable to edit due to permissions.

Comment by NIkhilesh Gargi [ 13/Jul/15 ]

Sample code to reproduce the issue.

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