Upgrade Mongo 4.2 to Mongo 4.4 : regression on some heavy transaction

Olivier_Boudet · December 15, 2020, 5:18pm

Hello,

I have a Spring Boot Application (version 2.4.0 with mongo-driver 4.4.1) with a pretty heavy task which do the following in a transaction :

remove 20 522 docs from a collection
insert 20 522 docs in this same collection (in my tests, all these docs are same)
insert 1 doc in a different collection

I am running this on a MongoDB 4.2.1 replicaset with one node on my laptop. It works very well.
Then I upgrade my replicaset to MongoDB 4.4.2 and run same test. It fails with this error :


org.springframework.transaction.TransactionSystemException: Could not commit Mongo transaction for session [ClientSessionImpl@61cd23f8 id = {"id": {"$binary": {"base64": "OLTFzpcTQaqZRecyjnQbSg==", "subType": "04"}}}, causallyConsistent = true, txActive = false, txNumber = 1, error = d != java.lang.Boolean].; nested exception is com.mongodb.MongoCommandException: Command failed with error 112 (WriteConflict): 'WriteConflict error: this operation conflicted with another operation. Please retry your operation or multi-document transaction.' on server localhost:27017. The full response is {"errorLabels": ["TransientTransactionError"], "operationTime": {"$timestamp": {"t": 1608049752, "i": 1}}, "ok": 0.0, "errmsg": "WriteConflict error: this operation conflicted with another operation. Please retry your operation or multi-document transaction.", "code": 112, "codeName": "WriteConflict", "$clusterTime": {"clusterTime": {"$timestamp": {"t": 1608049757, "i": 41045}}, "signature": {"hash": {"$binary": {"base64": "AAAAAAAAAAAAAAAAAAAAAAAAAAA=", "subType": "00"}}, "keyId": 0}}}
	at org.springframework.data.mongodb.MongoTransactionManager.doCommit(MongoTransactionManager.java:203)
	at org.springframework.transaction.support.AbstractPlatformTransactionManager.processCommit(AbstractPlatformTransactionManager.java:743)
	at org.springframework.transaction.support.AbstractPlatformTransactionManager.commit(AbstractPlatformTransactionManager.java:711)
	at org.springframework.transaction.interceptor.TransactionAspectSupport.commitTransactionAfterReturning(TransactionAspectSupport.java:654)
	at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:407)
	at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:119)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
	at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:749)
	at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:691)
	at com.xxx.RapportBuildServiceImpl$$EnhancerBySpringCGLIB$$8542fe9b.buildSingleReport(<generated>)
	at com.xxx.BuildPoller.processQueue(BuildPoller.java:67)
	at com.xxx.BuildPoller.lambda$init$0(BuildPoller.java:43)
	at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
	at java.base/java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305)
	at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
	at java.base/java.lang.Thread.run(Thread.java:834)
Caused by: com.mongodb.MongoCommandException: Command failed with error 112 (WriteConflict): 'WriteConflict error: this operation conflicted with another operation. Please retry your operation or multi-document transaction.' on server localhost:27017. The full response is {"errorLabels": ["TransientTransactionError"], "operationTime": {"$timestamp": {"t": 1608049752, "i": 1}}, "ok": 0.0, "errmsg": "WriteConflict error: this operation conflicted with another operation. Please retry your operation or multi-document transaction.", "code": 112, "codeName": "WriteConflict", "$clusterTime": {"clusterTime": {"$timestamp": {"t": 1608049757, "i": 41045}}, "signature": {"hash": {"$binary": {"base64": "AAAAAAAAAAAAAAAAAAAAAAAAAAA=", "subType": "00"}}, "keyId": 0}}}
	at com.mongodb.internal.connection.ProtocolHelper.getCommandFailureException(ProtocolHelper.java:175)
	at com.mongodb.internal.connection.InternalStreamConnection.receiveCommandMessageResponse(InternalStreamConnection.java:359)
	at com.mongodb.internal.connection.InternalStreamConnection.sendAndReceive(InternalStreamConnection.java:280)
	at com.mongodb.internal.connection.UsageTrackingInternalConnection.sendAndReceive(UsageTrackingInternalConnection.java:100)
	at com.mongodb.internal.connection.DefaultConnectionPool$PooledConnection.sendAndReceive(DefaultConnectionPool.java:490)
	at com.mongodb.internal.connection.CommandProtocolImpl.execute(CommandProtocolImpl.java:71)
	at com.mongodb.internal.connection.DefaultServer$DefaultServerProtocolExecutor.execute(DefaultServer.java:255)
	at com.mongodb.internal.connection.DefaultServerConnection.executeProtocol(DefaultServerConnection.java:202)
	at com.mongodb.internal.connection.DefaultServerConnection.command(DefaultServerConnection.java:118)
	at com.mongodb.internal.connection.DefaultServerConnection.command(DefaultServerConnection.java:110)
	at com.mongodb.internal.operation.CommandOperationHelper$13.call(CommandOperationHelper.java:712)
	at com.mongodb.internal.operation.OperationHelper.withReleasableConnection(OperationHelper.java:620)
	at com.mongodb.internal.operation.CommandOperationHelper.executeRetryableCommand(CommandOperationHelper.java:705)
	at com.mongodb.internal.operation.TransactionOperation.execute(TransactionOperation.java:69)
	at com.mongodb.internal.operation.CommitTransactionOperation.execute(CommitTransactionOperation.java:133)
	at com.mongodb.internal.operation.CommitTransactionOperation.execute(CommitTransactionOperation.java:54)
	at com.mongodb.client.internal.MongoClientDelegate$DelegateOperationExecutor.execute(MongoClientDelegate.java:195)
	at com.mongodb.client.internal.ClientSessionImpl.commitTransaction(ClientSessionImpl.java:129)
	at org.springframework.data.mongodb.MongoTransactionManager$MongoTransactionObject.commitTransaction(MongoTransactionManager.java:469)
	at org.springframework.data.mongodb.MongoTransactionManager.doCommit(MongoTransactionManager.java:236)
	at org.springframework.data.mongodb.MongoTransactionManager.doCommit(MongoTransactionManager.java:200)
	... 17 common frames omitted

I am running this on my laptop, nothing is using my application in parallel of my test. Is there something chaned in 4.4 which can explain this new behavior ?
I have activated profiling (level 2) and I can confirm that no other query is running during my test. This is always reproducible.

Thanks

Olivier_Boudet · December 16, 2020, 10:04am

Hello,
it seems to be linked to the number of documents (writes ?) in the transactions.
The same test with 11000 deletes & 11000 inserts successfully pass.

If I raise the limit to 12000 deletes & 12000 inserts, the WriteConflict error appears.

Olivier_Boudet · December 16, 2020, 10:04am

I wrote a simple unit test which do the following :

init the collection outside the transaction with 20 000 docs (with 2 properties, id and string with 1000 chars)
in a transaction, removes all the 20 000 docs and re-insert 20 000 similar docs

This test passes with mongo 4.2.1 but fails with 4.4.2.

@RunWith(SpringRunner.class)
@ActiveProfiles(value = "test-mongo44")
@Import(
        {MongoAutoConfiguration.class, MongoDataAutoConfiguration.class}
)
@SpringBootTest()
public class Mongo44Test {
    @Autowired
    private MongoTemplate mongoTemplate;

    @Autowired
    private MongoTransactionManager mongoTransactionManager;

    @Test
    public void test1() {

        // init the collection with 20 000 docs with a 1000 chars length string
        Collection<Document> elements = new ArrayList<Document>();
        IntStream.range(0,20000).forEach(i -> {
            Document doc = new Document();
            doc.put("id", "site");
            doc.put("string", RandomStringUtils.random(1000, true, true));
            elements.add(doc);
        });
        mongoTemplate.insert(elements, "mongo44");

        TransactionTemplate transactionTemplate = new TransactionTemplate(mongoTransactionManager);
        transactionTemplate.execute(new TransactionCallbackWithoutResult() {

            @Override
            protected void doInTransactionWithoutResult(TransactionStatus status) {

                // remove all docs in transaction
                mongoTemplate.remove(Query.query(Criteria.where("id").is("site")), "mongo44");

                elements.clear();
                // and re-insert 20 000 docs with a 1000 chars length string in the transaction
                IntStream.range(0,20000).forEach(i -> {
                    Document doc = new Document();
                    doc.put("id", "site");
                    doc.put("string", RandomStringUtils.random(1000, true, true));
                    elements.add(doc);
                });
                mongoTemplate.insert(elements, "mongo44");
            };
        });

    }
}

Olivier_Boudet · December 22, 2020, 10:08am

For those concerned by this issue, I opened a ticket : https://jira.mongodb.org/browse/SERVER-53464

Stennie_X · December 22, 2020, 10:20am

Hi @Olivier_Boudet,

Thanks for sharing a unit test and link to the Jira issue for others to follow!

Regards,
Stennie