venasolutions / bosk

Apache License 2.0
11 stars 4 forks source link

WriteConflict errors #86

Closed prdoyle closed 10 months ago

prdoyle commented 10 months ago

Looks like I need my own retry loop for multi-document transactions. Example here.

MongoDriverSpecialTest > hookRegisteredDuringNetworkOutage_works() > [2] {parameters=MongoDriverResiliencyTest_150_PandoFormat} STANDARD_OUT
    2024-01-17 14:53:40,163 ERROR [ChangeReceiver [Hanoi4]] [Hanoi4] io.vena.bosk.Bosk: Bosk hook terminated with an exception, which usually indicates a bug. State updates may have been lost
    java.lang.IllegalStateException: Unable to call hook "discMoved"
        at io.vena.bosk.HookRegistrar.lambda$registerHooks$4(HookRegistrar.java:68)
        at io.vena.bosk.Bosk$LocalDriver.lambda$triggerQueueingOfHooks$0(Bosk.java:377)
        at io.vena.bosk.Bosk$LocalDriver.drainQueueIfAllowed(Bosk.java:419)
        at io.vena.bosk.Bosk$LocalDriver.submitReplacement(Bosk.java:195)
        at io.vena.bosk.drivers.mongo.MainDriver$Listener.onConnectionSucceeded(MainDriver.java:357)
        at io.vena.bosk.drivers.mongo.ChangeReceiver.connectionLoop(ChangeReceiver.java:100)
        at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539)
        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:1136)
        at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
        at java.base/java.lang.Thread.run(Thread.java:840)
    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:32803. The full response is {"errorLabels": ["TransientTransactionError"], "operationTime": {"$timestamp": {"t": 1705503220, "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": 1705503220, "i": 1}}, "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.operation.MixedBulkWriteOperation.executeCommand(MixedBulkWriteOperation.java:431)
        at com.mongodb.internal.operation.MixedBulkWriteOperation.executeBulkWriteBatch(MixedBulkWriteOperation.java:251)
        at com.mongodb.internal.operation.MixedBulkWriteOperation.access$700(MixedBulkWriteOperation.java:76)
        at com.mongodb.internal.operation.MixedBulkWriteOperation$1.call(MixedBulkWriteOperation.java:194)
        at com.mongodb.internal.operation.MixedBulkWriteOperation$1.call(MixedBulkWriteOperation.java:185)
        at com.mongodb.internal.operation.OperationHelper.withReleasableConnection(OperationHelper.java:620)
        at com.mongodb.internal.operation.MixedBulkWriteOperation.execute(MixedBulkWriteOperation.java:185)
        at com.mongodb.internal.operation.MixedBulkWriteOperation.execute(MixedBulkWriteOperation.java:76)
        at com.mongodb.client.internal.MongoClientDelegate$DelegateOperationExecutor.execute(MongoClientDelegate.java:195)
        at com.mongodb.client.internal.MongoCollectionImpl.executeSingleWriteRequest(MongoCollectionImpl.java:1009)
        at com.mongodb.client.internal.MongoCollectionImpl.executeUpdate(MongoCollectionImpl.java:993)
        at com.mongodb.client.internal.MongoCollectionImpl.updateOne(MongoCollectionImpl.java:590)
        at com.mongodb.client.internal.MongoCollectionImpl.updateOne(MongoCollectionImpl.java:583)
        at io.vena.bosk.drivers.mongo.TransactionalCollection.updateOne(TransactionalCollection.java:474)
        at io.vena.bosk.drivers.mongo.PandoFormatDriver.doUpdate(PandoFormatDriver.java:750)
        at io.vena.bosk.drivers.mongo.PandoFormatDriver.doDelete(PandoFormatDriver.java:583)
        at io.vena.bosk.drivers.mongo.PandoFormatDriver.submitDeletion(PandoFormatDriver.java:141)
        at io.vena.bosk.drivers.mongo.MainDriver.lambda$submitDeletion$4(MainDriver.java:252)
        at io.vena.bosk.drivers.mongo.MainDriver.lambda$doRetryableDriverOperation$7(MainDriver.java:[500](https://github.com/venasolutions/bosk/actions/runs/7557449747/job/20576702477#step:5:501))
        at io.vena.bosk.drivers.mongo.MainDriver.doRetryableDriverOperation(MainDriver.java:[509](https://github.com/venasolutions/bosk/actions/runs/7557449747/job/20576702477#step:5:510))
        at io.vena.bosk.drivers.mongo.MainDriver.submitDeletion(MainDriver.java:251)
        at io.vena.bosk.drivers.HanoiTest.submitMove(HanoiTest.java:180)
        at io.vena.bosk.drivers.HanoiTest.discMoved(HanoiTest.java:170)
        at java.base/java.lang.invoke.MethodHandle.invokeWithArguments(MethodHandle.java:732)
        at java.base/java.lang.invoke.MethodHandle.invokeWithArguments(MethodHandle.java:757)
        at io.vena.bosk.HookRegistrar.lambda$registerHooks$4(HookRegistrar.java:66)
        ... 11 common frames omitted
prdoyle commented 10 months ago

Sticking the logs here so they don't disappear after the 90-day retention period. It was run against commit 8189594e323b9c38de2b6112dc7e3590210c28aa. logs_336.zip

prdoyle commented 10 months ago

Since we're not using the callback API for transactions (should we?) we need to have our own retry logic as described here.

I'm having a hard time thinking of a way to test this retry logic reliably. 🤔