Transaction rollback did not happen on error

Hi,

I am using couchbase for first-time. I have a use-case of inserting new documents to couchbase ( all or none). On exception in transaction block, rollback of already inserted documents did not happen. Can you please guide me on resolving this issue.

INFO: [com.couchbase.transactions][TransactionsStarted] Transactions successfully started, regular cleanup enabled=true, lost cleanup enabled=true
Transaction f41309d3-7495-4d9b-9a12-6d79f4213cb7 failed
19:14:24.941 1/main/f4130 starting attempt 0/f41309d3-7495-4d9b-9a12-6d79f4213cb7/b3575448-1ff6-4d22-a593-fbf97805e214
19:14:24.941 1/main/f4130 config: atrs=1024, expiry=15000msecs durability=MAJORITY per-txn config: durability=Optional.empty
19:14:25.006 1/main/f4130/b3575 caught exception ‘com.couchbase.client.core.error.DocumentExistsException: Document with the given id already exists {“completed”:true,“coreId”:“0x148bf9af00000003”,“idempotent”:false,“lastChannelId”:“148BF9AF00000003/000000002CD6B508”,“lastDispatchedFrom”:“127.0.0.1:62332”,“lastDispatchedTo”:“localhost:11210”,“requestId”:10,“requestType”:“InsertRequest”,“retried”:0,“service”:{“bucket”:“payments-metadata-dev”,“collection”:"_default",“documentId”:“osn3”,“opaque”:“0x23”,“scope”:"_default",“syncDurability”:{“empty”:true,“present”:false},“type”:“kv”},“status”:“EXISTS”,“timeoutMs”:2500,“timings”:{“dispatchMicros”:2248,“encodingMicros”:143,“totalMicros”:3308,“serverMicros”:0}}’ in runBlocking, rethrowing
19:14:25.007 1/main/f4130/b3575 com.couchbase.client.java.AsyncUtils.block(AsyncUtils.java:51)
19:14:25.007 1/main/f4130/b3575 com.couchbase.client.java.Collection.insert(Collection.java:381)
19:14:25.007 1/main/f4130/b3575 pymts_batch.cb3_0_1.cb3.lambda$0(cb3.java:2148)
19:14:25.007 1/main/f4130/b3575 com.couchbase.transactions.TransactionsReactive.lambda$null$26(TransactionsReactive.java:521)
19:14:25.007 1/main/f4130/b3575 reactor.core.publisher.MonoRunnable.call(MonoRunnable.java:73)
19:14:25.007 1/main/f4130/b3575 reactor.core.publisher.MonoRunnable.call(MonoRunnable.java:32)
19:14:25.007 1/main/f4130/b3575 reactor.core.publisher.FluxSubscribeOnCallable$CallableSubscribeOnSubscription.run(FluxSubscribeOnCallable.java:225)
19:14:25.007 1/main/f4130/b3575 reactor.core.scheduler.SchedulerTask.call(SchedulerTask.java:68)
19:14:25.007 1/main/f4130/b3575 reactor.core.scheduler.SchedulerTask.call(SchedulerTask.java:28)
19:14:25.007 1/main/f4130/b3575 java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
19:14:25.007 1/main/f4130/b3575 java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304)
19:14:25.007 1/main/f4130/b3575 java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
19:14:25.007 1/main/f4130/b3575 java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
Jun 07, 2020 7:14:25 PM com.couchbase.client.core.cnc.LoggingEventConsumer$Slf4JLogger info
INFO: [com.couchbase.transactions.cleanup.lost][TransactionLogEvent] new cluster config with 1 buckets
Jun 07, 2020 7:14:25 PM com.couchbase.client.core.cnc.LoggingEventConsumer$Slf4JLogger info
INFO: [com.couchbase.transactions.cleanup.lost][TransactionLogEvent] will start cleaning lost transactions on bucket payments-metadata-dev
19:14:25.007 1/main/f4130/b3575 java.base/java.lang.Thread.run(Thread.java:834)
Jun 07, 2020 7:14:25 PM com.couchbase.client.core.cnc.LoggingEventConsumer$Slf4JLogger info
INFO: [com.couchbase.core][BucketOpenedEvent][138ms] Opened bucket “payments-metadata-dev” {“coreId”:“0x148bf9af00000003”}
19:14:25.012 1/main/f4130/b3575 exception DocumentExistsException should not be retried, wrapping in AttemptWrappedExceptionNoRetry, rollback=true
19:14:25.012 1/main/f4130/<> hit error com.couchbase.transactions.error.internal.AttemptWrappedExceptionNoRetry: com.couchbase.client.core.error.DocumentExistsException: Document with the given id already exists {“completed”:true,“coreId”:“0x148bf9af00000003”,“idempotent”:false,“lastChannelId”:“148BF9AF00000003/000000002CD6B508”,“lastDispatchedFrom”:“127.0.0.1:62332”,“lastDispatchedTo”:“localhost:11210”,“requestId”:10,“requestType”:“InsertRequest”,“retried”:0,“service”:{“bucket”:“payments-metadata-dev”,“collection”:"_default",“documentId”:“osn3”,“opaque”:“0x23”,“scope”:"_default",“syncDurability”:{“empty”:true,“present”:false},“type”:“kv”},“status”:“EXISTS”,“timeoutMs”:2500,“timings”:{“dispatchMicros”:2248,“encodingMicros”:143,“totalMicros”:3308,“serverMicros”:0}}
19:14:25.012 1/main/f4130/b3575 rolling back on error
19:14:25.013 1/main/f4130/b3575 Skipping cleanup request as no ATR entry to remove (due to no mutations)
19:14:25.018 1/main/f4130/b3575 added attempt TransactionAttempt{id=b3575,state=NOT_STARTED,atr=/} after error
19:14:25.018 1/main/f4130/b3575 rollback AttemptContextReactive{id=b3575,state=ROLLED_BACK,isDone=true,atr=/,staged=} expiryOvertimeMode=false
19:14:25.019 1/main/f4130/b3575 Calling rollback when it’s had no mutations, so nothing to do
19:14:25.021 1/main/f4130/b3575 AttemptWrappedExceptionNoRetry raised, wrapping original exception ‘com.couchbase.client.core.error.DocumentExistsException: Document with the given id already exists {“completed”:true,“coreId”:“0x148bf9af00000003”,“idempotent”:false,“lastChannelId”:“148BF9AF00000003/000000002CD6B508”,“lastDispatchedFrom”:“127.0.0.1:62332”,“lastDispatchedTo”:“localhost:11210”,“requestId”:10,“requestType”:“InsertRequest”,“retried”:0,“service”:{“bucket”:“payments-metadata-dev”,“collection”:"_default",“documentId”:“osn3”,“opaque”:“0x23”,“scope”:"_default",“syncDurability”:{“empty”:true,“present”:false},“type”:“kv”},“status”:“EXISTS”,“timeoutMs”:2500,“timings”:{“dispatchMicros”:2248,“encodingMicros”:143,“totalMicros”:3308,“serverMicros”:0}}’ in TransactionFailed
[statistics] disconnected

Here is my Java code:

Cluster cluster = Cluster.connect(“localhost”, “XXX”, “XXX”);
Bucket bucket = cluster.bucket(“XXX”);
Collection collection = bucket.defaultCollection();
Transactions transactions = Transactions.create(cluster, TransactionConfigBuilder.create().build());
try {
transactions.run((ctx) -> {

	try{
		File file1 = FileUtils.getFile("/Users/309399/apps/test/osn.txt");
		LineIterator it = FileUtils.lineIterator(file1, "UTF-8");
		while (it.hasNext()) {
			String line = it.nextLine();
			String documentId = line.split(",")[0];
			String osnPayload = line.split(",")[1];
			JsonObject content = JsonObject.create().put("payload", osnPayload);
			MutationResult insertResult = collection.insert(documentId, content);
		}
		}  catch(IOException ex){
      ex.printStackTrace();
    }
});

} catch (TransactionFailed e) {
System.err.println(“Transaction " + e.result().transactionId() + " failed”);

for (LogDefer err : e.result().log().logs()) {
    System.err.println(err.toString());
}

}

Hi,
The issue is happening as you are performing ‘normal’ inserts inside the transaction block, and not using the transaction AttemptContext “ctx” to perform your inserts, here:

    MutationResult insertResult = collection.insert(documentId, content);

Instead use something like this: ctx.insert(collection, documentId, content);

Hope this helps,
Will

1 Like

Thanks Will, it worked as expected.

11:16:11.670 1/main/3a356/<> hit error com.couchbase.transactions.error.internal.AttemptWrappedExceptionNoRetry: com.couchbase.client.core.error.DocumentExistsException: Document with the given id already exists {“documentId”:“osn3”}

11:16:11.670 1/main/3a356/5ec3c rolling back on error

11:16:11.671 1/main/3a356/5ec3c Adding cleanup request for _default/_txn:atr-636-#35 to run in 15000 msecs

11:16:11.674 1/main/3a356/5ec3c added attempt TransactionAttempt{id=5ec3c,state=PENDING,atrColl=com.couchbase.client.java.ReactiveCollection@3ecedf21/_txn:atr-636-#35} after error

11:16:11.674 1/main/3a356/5ec3c rollback AttemptContextReactive{id=5ec3c,state=ROLLED_BACK,isDone=true,atr=_default/_txn:atr-636-#35,staged=[INSERT osn4, INSERT osn5]} expiryOvertimeMode=false

11:16:11.678 1/main/3a356/5ec3c aborting AttemptContextReactive{id=5ec3c,state=ROLLED_BACK,isDone=true,atr=_default/_txn:atr-636-#35,staged=[INSERT osn4, INSERT osn5]}, expiryOvertimeMode=false

11:16:11.690 1/main/3a356/5ec3c got ATR payments-metadata-dev/_default/_txn:atr-636-#35 ATREntry{atr=payments-metadata-dev/_txn:atr-636-#35,attemptId=5ec3c0c0-c2ac-4194-a5a9-75ae0fbee621,state=PENDING,expires=Optional[15000]ms,[age=0ms,cas=1591640171626496000ns/1591640171626ms]<-Only Accurate If ATR Updated,inserted=Optional.empty,replaced=Optional.empty,removed=Optional.empty,start=Optional[1591640171626]ms}

11:16:11.690 1/main/3a356/5ec3c aborting ATR payments-metadata-dev/_default/_txn:atr-636-#35

11:16:11.700 1/main/3a356/5ec3c aborted ATR payments-metadata-dev/_default/_txn:atr-636-#35

11:16:11.702 1/main/3a356/5ec3c deleting inserted doc osn4

11:16:11.710 1/main/3a356/5ec3c deleted inserted doc osn4, mt Optional[mt{vbID=636, vbUUID=217152030880143, seqno=9, bucket=payments-metadata-dev}]

11:16:11.711 1/main/3a356/5ec3c deleting inserted doc osn5

11:16:11.726 1/main/3a356/5ec3c deleted inserted doc osn5, mt Optional[mt{vbID=379, vbUUID=90127317062542, seqno=5, bucket=payments-metadata-dev}]

11:16:11.726 1/main/3a356/5ec3c marking ATR payments-metadata-dev/_default/_txn:atr-636-#35 as rollback complete

11:16:11.750 1/main/3a356/5ec3c rollback - atr rolled back

That’s good to hear! No problem.