Uploaded image for project: 'Couchbase Server'
  1. Couchbase Server
  2. MB-42967

cbrestore fails to restore backups with mid transaction data

    XMLWordPrintable

    Details

    • Triage:
      Untriaged
    • Story Points:
      1
    • Is this a Regression?:
      Unknown

      Description

      If a backup with more than 10 elements that has mid transactions documents is restored with cbrestore the restore is likely to fail (it may pass if all the mid transaction documents fall in the last batch of messages to be processed).

      It will fail with the message

      2020-11-26 12:36:04,934: s0 error: async operation: error: opaque mismatch: 2 3 on sink: http://localhost:8091(b'demo-bucket'@b'127.0.0.1:8091')
      

      Steps to reproduce

      1. Stand up a cluster and create a bucket
      2. Load 100 documents to the bucket
      3. Add some mid-transaction documents see the attachment for a script that does this (the run.sh)
      4. Load another 100 documets to the bucket
      5. Do a backup with cbbackup
      6. Do a restore with cbrestore

        Attachments

          Issue Links

          No reviews matched the request. Check your Options in the drop-down menu of this sections header.

            Activity

            Hide
            build-team Couchbase Build Team added a comment -

            Build couchbase-server-7.0.0-4252 contains couchbase-cli commit 3210cf8 with commit message:
            MB-42967 Fix opaque verification when TXNs are filtered

            Show
            build-team Couchbase Build Team added a comment - Build couchbase-server-7.0.0-4252 contains couchbase-cli commit 3210cf8 with commit message: MB-42967 Fix opaque verification when TXNs are filtered
            Hide
            arunkumar Arunkumar Senthilnathan added a comment -

            Verified in 6.5.2-662:

            Jan 27, 2021 1:06:07 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info
            INFO: [com.couchbase.core][CoreCreatedEvent] {"clientVersion":"3.0.0-alpha.7","clientGitHash":"6caa093c","coreVersion":"2.0.0-alpha.7","coreGitHash":"6caa093c","userAgent":"couchbase-java/3.0.0-alpha.7 (Mac OS X 10.14.6 x86_64; Java HotSpot(TM) 64-Bit Server VM 1.8.0_221-b11)","seedNodes":[{"address":"10.112.194.101"}],"ioEnvironment":{"nativeIoEnabled":true,"eventLoopGroups":["KQueueEventLoopGroup"]},"ioConfig":{"allowedSaslMechs":["PLAIN","CRAM_MD5","SCRAM_SHA1","SCRAM_SHA256","SCRAM_SHA512"],"captureTraffic":[],"mutationTokensEnabled":true,"networkResolution":"auto","dnsSrvEnabled":false,"configPollIntervalMillis":2500,"kvCircuitBreakerConfig":"disabled","queryCircuitBreakerConfig":"disabled","viewCircuitBreakerConfig":"disabled","searchCircuitBreakerConfig":"disabled","analyticsCircuitBreakerConfig":"disabled","managerCircuitBreakerConfig":"disabled"},"compressionConfig":{"enabled":true,"minRatio":0.83,"minSize":32},"securityConfig":{"tlsEnabled":false,"nativeTlsEnabled":true,"certAuthEnabled":false,"hasTrustCertificates":false,"trustManagerFactory":null},"timeoutConfig":{"kvMs":2500,"managementMs":75000,"queryMs":75000,"viewMs":75000,"searchMs":75000,"analyticsMs":75000,"connectMs":10000,"disconnectMs":10000},"serviceConfig":{"kv":{"min":1,"max":1,"idleTimeMs":0},"query":{"min":0,"max":12,"idleTimeMs":300000},"view":{"min":0,"max":12,"idleTimeMs":300000},"search":{"min":0,"max":12,"idleTimeMs":300000},"analytics":{"min":0,"max":12,"idleTimeMs":300000}},"loggerConfig":{"customLogger":null,"fallbackToConsole":false,"disableSlf4j":false,"loggerName":"CouchbaseLogger","diagnosticContextEnabled":false},"credentials":"UsernameAndPassword","retryStrategy":"BestEffortRetryStrategy"} {"coreId":1}
            Jan 27, 2021 1:06:07 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info
            INFO: [com.couchbase.node][NodeConnectedEvent] Node connected {"coreId":1,"managerPort":"8091","remote":"10.112.194.101"}
            Jan 27, 2021 1:06:07 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info
            INFO: [com.couchbase.core][BucketOpenedEvent][60483µs] Opened bucket "people" {"coreId":1}
            Jan 27, 2021 1:06:07 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info
            INFO: [com.couchbase.transactions.cleanup][TransactionLogEvent] Cleanup settings; regular cleanup thread enabled=true, lost cleanup thread enabled=true
            Jan 27, 2021 1:06:07 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info
            INFO: [com.couchbase.transactions.cleanup.regular][TransactionLogEvent] Starting background cleanup thread to find transactions from this client
            Jan 27, 2021 1:06:07 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info
            INFO: [com.couchbase.transactions][TransactionsStarted] Transactions successfully started, regular cleanup enabled=true, lost cleanup enabled=true
            Jan 27, 2021 1:06:07 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info
            INFO: [com.couchbase.core][BucketOpenedEvent][4477µs] Opened bucket "people" {"coreId":1}
            Jan 27, 2021 1:06:07 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info
            INFO: [com.couchbase.transactions.cleanup.lost][TransactionLogEvent] Client 3c8dd people/_default creating thread to handle lost transactions
            Transaction failed:
            13:06:07.810 1/main/978fb starting attempt 0/978fb572-c82d-44ac-b7d9-6e3e3978bb1b/4e1938f9-c4fb-4d70-b0c7-d40967bf11c4
            13:06:07.811 1/main/978fb config: atrs=1024, expiry=5000msecs durability=null per-txn config: durability=Optional.empty
            13:06:07.814 1/main/978fb/4e193 First mutated doc in txn is 'insert:arun' on vbucket 621, so using atr _txn:atr-621-#1b88
            13:06:07.816 1/main/978fb/4e193 about to set ATR people/_default/_txn:atr-621-#1b88 to Pending
            13:06:07.818 1/main/978fb/4e193 set ATR people/_default/_txn:atr-621-#1b88 to Pending in 1ms, got CAS (start time) 1611781567809912832
            13:06:07.821 1/main/978fb/4e193 about to insert staged doc insert:arun
            13:06:07.825 1/main/978fb/4e193 inserted doc insert:arun got cas 1611781567814565888, in 3ms
            13:06:07.825 1/main/978fb/4e193 doing implicit commit
            13:06:07.826 1/main/978fb/4e193 commit AttemptContextReactive{id=4e193,state=PENDING,isDone=false,atr=_default/_txn:atr-621-#1b88,staged=[INSERT insert:arun]}
            13:06:07.830 1/main/978fb/4e193 about to set ATR people/_default/_txn:atr-621-#1b88 to Committed
            13:06:07.833 1/main/978fb/4e193 error com.couchbase.transactions.error.internal.AbortedAsRequestedNoRollbackNoCleanup: Faking that txn fails at stage afterCommit while setting ATR people/_default/_txn:atr-621-#1b88 to Committed
            13:06:07.834 1/main/978fb/<> hit error com.couchbase.transactions.error.internal.AbortedAsRequestedNoRollbackNoCleanup: Faking that txn fails at stage afterCommit
            13:06:07.834 1/main/978fb/<> received non-TransactionException error AbortedAsRequestedNoRollbackNoCleanup, unable to rollback as don't have context
            13:06:07.834 1/main/978fb/<> caught error com.couchbase.transactions.error.internal.AbortedAsRequestedNoRollbackNoCleanup: Faking that txn fails at stage afterCommit, wrapping in TransactionFailed
             
            BUILD SUCCESSFUL in 1s
            2 actionable tasks: 1 executed, 1 up-to-date
            > Task :Main.main()
            Jan 27, 2021 1:07:04 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info
            INFO: [com.couchbase.core][CoreCreatedEvent] {"clientVersion":"3.0.0-alpha.7","clientGitHash":"6caa093c","coreVersion":"2.0.0-alpha.7","coreGitHash":"6caa093c","userAgent":"couchbase-java/3.0.0-alpha.7 (Mac OS X 10.14.6 x86_64; Java HotSpot(TM) 64-Bit Server VM 1.8.0_221-b11)","seedNodes":[{"address":"10.112.194.101"}],"ioEnvironment":{"nativeIoEnabled":true,"eventLoopGroups":["KQueueEventLoopGroup"]},"ioConfig":{"allowedSaslMechs":["PLAIN","CRAM_MD5","SCRAM_SHA1","SCRAM_SHA256","SCRAM_SHA512"],"captureTraffic":[],"mutationTokensEnabled":true,"networkResolution":"auto","dnsSrvEnabled":false,"configPollIntervalMillis":2500,"kvCircuitBreakerConfig":"disabled","queryCircuitBreakerConfig":"disabled","viewCircuitBreakerConfig":"disabled","searchCircuitBreakerConfig":"disabled","analyticsCircuitBreakerConfig":"disabled","managerCircuitBreakerConfig":"disabled"},"compressionConfig":{"enabled":true,"minRatio":0.83,"minSize":32},"securityConfig":{"tlsEnabled":false,"nativeTlsEnabled":true,"certAuthEnabled":false,"hasTrustCertificates":false,"trustManagerFactory":null},"timeoutConfig":{"kvMs":2500,"managementMs":75000,"queryMs":75000,"viewMs":75000,"searchMs":75000,"analyticsMs":75000,"connectMs":10000,"disconnectMs":10000},"serviceConfig":{"kv":{"min":1,"max":1,"idleTimeMs":0},"query":{"min":0,"max":12,"idleTimeMs":300000},"view":{"min":0,"max":12,"idleTimeMs":300000},"search":{"min":0,"max":12,"idleTimeMs":300000},"analytics":{"min":0,"max":12,"idleTimeMs":300000}},"loggerConfig":{"customLogger":null,"fallbackToConsole":false,"disableSlf4j":false,"loggerName":"CouchbaseLogger","diagnosticContextEnabled":false},"credentials":"UsernameAndPassword","retryStrategy":"BestEffortRetryStrategy"} {"coreId":1}
            Jan 27, 2021 1:07:04 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info
            INFO: [com.couchbase.node][NodeConnectedEvent] Node connected {"coreId":1,"managerPort":"8091","remote":"10.112.194.101"}
            Jan 27, 2021 1:07:04 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info
            INFO: [com.couchbase.core][BucketOpenedEvent][57188µs] Opened bucket "people" {"coreId":1}
            Jan 27, 2021 1:07:04 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info
            INFO: [com.couchbase.transactions.cleanup][TransactionLogEvent] Cleanup settings; regular cleanup thread enabled=true, lost cleanup thread enabled=true
            Jan 27, 2021 1:07:04 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info
            INFO: [com.couchbase.transactions.cleanup.regular][TransactionLogEvent] Starting background cleanup thread to find transactions from this client
            Jan 27, 2021 1:07:04 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info
            INFO: [com.couchbase.transactions][TransactionsStarted] Transactions successfully started, regular cleanup enabled=true, lost cleanup enabled=true
            Jan 27, 2021 1:07:04 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info
            INFO: [com.couchbase.core][BucketOpenedEvent][3862µs] Opened bucket "people" {"coreId":1}
            Jan 27, 2021 1:07:04 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info
            INFO: [com.couchbase.transactions.cleanup.lost][TransactionLogEvent] Client 8b7ae people/_default creating thread to handle lost transactions
            Transaction failed:
            13:07:04.835 1/main/d0d20 starting attempt 0/d0d20635-f086-4bd8-a44a-2b32a12420e2/d06249be-6aef-4b65-87c2-9559673de588
            13:07:04.835 1/main/d0d20 config: atrs=1024, expiry=5000msecs durability=null per-txn config: durability=Optional.empty
            13:07:04.842 1/main/d0d20/d0624 getting doc xattrs:arun
            13:07:04.846 1/main/d0d20/d0624 completed get of TransactionGetResult{id=xattrs:arun,cas=1611781624846352384,status=NORMAL,bucket=people,coll=_default,links=TransactionLinks{atr=none,atrBkt=none,atrColl=none,txnId=none,attemptId=none,op=none,restore={none,none,-1}}} in 3ms
            13:07:04.847 1/main/d0d20/d0624 replace doc TransactionGetResult{id=xattrs:arun,cas=1611781624846352384,status=NORMAL,bucket=people,coll=_default,links=TransactionLinks{atr=none,atrBkt=none,atrColl=none,txnId=none,attemptId=none,op=none,restore={none,none,-1}}}
            13:07:04.848 1/main/d0d20/d0624 First mutated doc in txn is 'xattrs:arun' on vbucket 363, so using atr _txn:atr-363-#203
            13:07:04.850 1/main/d0d20/d0624 about to set ATR people/_default/_txn:atr-363-#203 to Pending
            13:07:04.851 1/main/d0d20/d0624 set ATR people/_default/_txn:atr-363-#203 to Pending in 1ms, got CAS (start time) 1611781624842616832
            13:07:04.854 1/main/d0d20/d0624 about to replace doc xattrs:arun with cas 1611781624807096320
            13:07:04.855 1/main/d0d20/d0624 replaced doc xattrs:arun got new cas 1611781624846352384, in 1ms
            13:07:04.857 1/main/d0d20/d0624 doing implicit commit
            13:07:04.857 1/main/d0d20/d0624 commit AttemptContextReactive{id=d0624,state=PENDING,isDone=false,atr=_default/_txn:atr-363-#203,staged=[REPLACE xattrs:arun]}
            13:07:04.862 1/main/d0d20/d0624 about to set ATR people/_default/_txn:atr-363-#203 to Committed
            13:07:04.865 1/main/d0d20/d0624 error com.couchbase.transactions.error.internal.AbortedAsRequestedNoRollbackNoCleanup: Faking that txn fails at stage afterCommit while setting ATR people/_default/_txn:atr-363-#203 to Committed
            13:07:04.867 1/main/d0d20/<> hit error com.couchbase.transactions.error.internal.AbortedAsRequestedNoRollbackNoCleanup: Faking that txn fails at stage afterCommit
            13:07:04.867 1/main/d0d20/<> received non-TransactionException error AbortedAsRequestedNoRollbackNoCleanup, unable to rollback as don't have context
            13:07:04.867 1/main/d0d20/<> caught error com.couchbase.transactions.error.internal.AbortedAsRequestedNoRollbackNoCleanup: Faking that txn fails at stage afterCommit, wrapping in TransactionFailed
             
            BUILD SUCCESSFUL in 1s
            2 actionable tasks: 1 executed, 1 up-to-date
            13:07:05: Task execution finished 'Main.main()'.
            > Task :Main.main()
            Jan 27, 2021 1:09:47 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info
            INFO: [com.couchbase.core][CoreCreatedEvent] {"clientVersion":"3.0.0-alpha.7","clientGitHash":"6caa093c","coreVersion":"2.0.0-alpha.7","coreGitHash":"6caa093c","userAgent":"couchbase-java/3.0.0-alpha.7 (Mac OS X 10.14.6 x86_64; Java HotSpot(TM) 64-Bit Server VM 1.8.0_221-b11)","seedNodes":[{"address":"10.112.194.101"}],"ioEnvironment":{"nativeIoEnabled":true,"eventLoopGroups":["KQueueEventLoopGroup"]},"ioConfig":{"allowedSaslMechs":["PLAIN","CRAM_MD5","SCRAM_SHA1","SCRAM_SHA256","SCRAM_SHA512"],"captureTraffic":[],"mutationTokensEnabled":true,"networkResolution":"auto","dnsSrvEnabled":false,"configPollIntervalMillis":2500,"kvCircuitBreakerConfig":"disabled","queryCircuitBreakerConfig":"disabled","viewCircuitBreakerConfig":"disabled","searchCircuitBreakerConfig":"disabled","analyticsCircuitBreakerConfig":"disabled","managerCircuitBreakerConfig":"disabled"},"compressionConfig":{"enabled":true,"minRatio":0.83,"minSize":32},"securityConfig":{"tlsEnabled":false,"nativeTlsEnabled":true,"certAuthEnabled":false,"hasTrustCertificates":false,"trustManagerFactory":null},"timeoutConfig":{"kvMs":2500,"managementMs":75000,"queryMs":75000,"viewMs":75000,"searchMs":75000,"analyticsMs":75000,"connectMs":10000,"disconnectMs":10000},"serviceConfig":{"kv":{"min":1,"max":1,"idleTimeMs":0},"query":{"min":0,"max":12,"idleTimeMs":300000},"view":{"min":0,"max":12,"idleTimeMs":300000},"search":{"min":0,"max":12,"idleTimeMs":300000},"analytics":{"min":0,"max":12,"idleTimeMs":300000}},"loggerConfig":{"customLogger":null,"fallbackToConsole":false,"disableSlf4j":false,"loggerName":"CouchbaseLogger","diagnosticContextEnabled":false},"credentials":"UsernameAndPassword","retryStrategy":"BestEffortRetryStrategy"} {"coreId":1}
            Jan 27, 2021 1:09:47 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info
            INFO: [com.couchbase.node][NodeConnectedEvent] Node connected {"coreId":1,"managerPort":"8091","remote":"10.112.194.101"}
            Jan 27, 2021 1:09:47 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info
            INFO: [com.couchbase.core][BucketOpenedEvent][63356µs] Opened bucket "people" {"coreId":1}
            Jan 27, 2021 1:09:47 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info
            INFO: [com.couchbase.transactions.cleanup][TransactionLogEvent] Cleanup settings; regular cleanup thread enabled=true, lost cleanup thread enabled=true
            Jan 27, 2021 1:09:47 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info
            INFO: [com.couchbase.transactions.cleanup.regular][TransactionLogEvent] Starting background cleanup thread to find transactions from this client
            Jan 27, 2021 1:09:47 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info
            INFO: [com.couchbase.transactions][TransactionsStarted] Transactions successfully started, regular cleanup enabled=true, lost cleanup enabled=true
            Jan 27, 2021 1:09:47 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info
            INFO: [com.couchbase.core][BucketOpenedEvent][4477µs] Opened bucket "people" {"coreId":1}
            Jan 27, 2021 1:09:47 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info
            INFO: [com.couchbase.transactions.cleanup.lost][TransactionLogEvent] Client 2580e people/_default creating thread to handle lost transactions
            Transaction failed:
            13:09:47.849 1/main/8fb0e starting attempt 0/8fb0e5e1-d6e3-4503-839a-b00b731ee2d0/4c1a4511-658b-416d-8b70-2d9bb1b2f9d6
            13:09:47.849 1/main/8fb0e config: atrs=1024, expiry=5000msecs durability=null per-txn config: durability=Optional.empty
            13:09:47.855 1/main/8fb0e/4c1a4 getting doc replace:arun
            13:09:47.860 1/main/8fb0e/4c1a4 completed get of TransactionGetResult{id=replace:arun,cas=1611781787856928768,status=NORMAL,bucket=people,coll=_default,links=TransactionLinks{atr=none,atrBkt=none,atrColl=none,txnId=none,attemptId=none,op=none,restore={none,none,-1}}} in 4ms
            13:09:47.861 1/main/8fb0e/4c1a4 replace doc TransactionGetResult{id=replace:arun,cas=1611781787856928768,status=NORMAL,bucket=people,coll=_default,links=TransactionLinks{atr=none,atrBkt=none,atrColl=none,txnId=none,attemptId=none,op=none,restore={none,none,-1}}}
            13:09:47.862 1/main/8fb0e/4c1a4 First mutated doc in txn is 'replace:arun' on vbucket 803, so using atr _txn:atr-803-#80a
            13:09:47.863 1/main/8fb0e/4c1a4 about to set ATR people/_default/_txn:atr-803-#80a to Pending
            13:09:47.865 1/main/8fb0e/4c1a4 set ATR people/_default/_txn:atr-803-#80a to Pending in 1ms, got CAS (start time) 1611781787853717504
            13:09:47.867 1/main/8fb0e/4c1a4 about to replace doc replace:arun with cas 1611781787803648000
            13:09:47.868 1/main/8fb0e/4c1a4 replaced doc replace:arun got new cas 1611781787856928768, in 1ms
            13:09:47.869 1/main/8fb0e/4c1a4 doing implicit commit
            13:09:47.870 1/main/8fb0e/4c1a4 commit AttemptContextReactive{id=4c1a4,state=PENDING,isDone=false,atr=_default/_txn:atr-803-#80a,staged=[REPLACE replace:arun]}
            13:09:47.874 1/main/8fb0e/4c1a4 about to set ATR people/_default/_txn:atr-803-#80a to Committed
            13:09:47.878 1/main/8fb0e/4c1a4 error com.couchbase.transactions.error.internal.AbortedAsRequestedNoRollbackNoCleanup: Faking that txn fails at stage afterCommit while setting ATR people/_default/_txn:atr-803-#80a to Committed
            13:09:47.879 1/main/8fb0e/<> hit error com.couchbase.transactions.error.internal.AbortedAsRequestedNoRollbackNoCleanup: Faking that txn fails at stage afterCommit
            13:09:47.879 1/main/8fb0e/<> received non-TransactionException error AbortedAsRequestedNoRollbackNoCleanup, unable to rollback as don't have context
            13:09:47.879 1/main/8fb0e/<> caught error com.couchbase.transactions.error.internal.AbortedAsRequestedNoRollbackNoCleanup: Faking that txn fails at stage afterCommit, wrapping in TransactionFailed
             
            BUILD SUCCESSFUL in 1s
            2 actionable tasks: 1 executed, 1 up-to-date
            13:09:48: Task execution finished 'Main.main()'.
            > Task :Main.main()
            Jan 27, 2021 1:13:07 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info
            INFO: [com.couchbase.core][CoreCreatedEvent] {"clientVersion":"3.0.0-alpha.7","clientGitHash":"6caa093c","coreVersion":"2.0.0-alpha.7","coreGitHash":"6caa093c","userAgent":"couchbase-java/3.0.0-alpha.7 (Mac OS X 10.14.6 x86_64; Java HotSpot(TM) 64-Bit Server VM 1.8.0_221-b11)","seedNodes":[{"address":"10.112.194.101"}],"ioEnvironment":{"nativeIoEnabled":true,"eventLoopGroups":["KQueueEventLoopGroup"]},"ioConfig":{"allowedSaslMechs":["PLAIN","CRAM_MD5","SCRAM_SHA1","SCRAM_SHA256","SCRAM_SHA512"],"captureTraffic":[],"mutationTokensEnabled":true,"networkResolution":"auto","dnsSrvEnabled":false,"configPollIntervalMillis":2500,"kvCircuitBreakerConfig":"disabled","queryCircuitBreakerConfig":"disabled","viewCircuitBreakerConfig":"disabled","searchCircuitBreakerConfig":"disabled","analyticsCircuitBreakerConfig":"disabled","managerCircuitBreakerConfig":"disabled"},"compressionConfig":{"enabled":true,"minRatio":0.83,"minSize":32},"securityConfig":{"tlsEnabled":false,"nativeTlsEnabled":true,"certAuthEnabled":false,"hasTrustCertificates":false,"trustManagerFactory":null},"timeoutConfig":{"kvMs":2500,"managementMs":75000,"queryMs":75000,"viewMs":75000,"searchMs":75000,"analyticsMs":75000,"connectMs":10000,"disconnectMs":10000},"serviceConfig":{"kv":{"min":1,"max":1,"idleTimeMs":0},"query":{"min":0,"max":12,"idleTimeMs":300000},"view":{"min":0,"max":12,"idleTimeMs":300000},"search":{"min":0,"max":12,"idleTimeMs":300000},"analytics":{"min":0,"max":12,"idleTimeMs":300000}},"loggerConfig":{"customLogger":null,"fallbackToConsole":false,"disableSlf4j":false,"loggerName":"CouchbaseLogger","diagnosticContextEnabled":false},"credentials":"UsernameAndPassword","retryStrategy":"BestEffortRetryStrategy"} {"coreId":1}
            Jan 27, 2021 1:13:07 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info
            INFO: [com.couchbase.node][NodeConnectedEvent] Node connected {"coreId":1,"managerPort":"8091","remote":"10.112.194.101"}
            Jan 27, 2021 1:13:07 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info
            INFO: [com.couchbase.core][BucketOpenedEvent][60498µs] Opened bucket "people" {"coreId":1}
            Jan 27, 2021 1:13:07 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info
            INFO: [com.couchbase.transactions.cleanup][TransactionLogEvent] Cleanup settings; regular cleanup thread enabled=true, lost cleanup thread enabled=true
            Jan 27, 2021 1:13:07 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info
            INFO: [com.couchbase.transactions.cleanup.regular][TransactionLogEvent] Starting background cleanup thread to find transactions from this client
            Jan 27, 2021 1:13:07 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info
            INFO: [com.couchbase.transactions][TransactionsStarted] Transactions successfully started, regular cleanup enabled=true, lost cleanup enabled=true
            Jan 27, 2021 1:13:07 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info
            INFO: [com.couchbase.core][BucketOpenedEvent][3736µs] Opened bucket "people" {"coreId":1}
            Jan 27, 2021 1:13:07 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info
            INFO: [com.couchbase.transactions.cleanup.lost][TransactionLogEvent] Client 9867a people/_default creating thread to handle lost transactions
            Transaction failed:
            13:13:07.859 1/main/627fd starting attempt 0/627fdcd8-295c-4952-987b-faa9cb06cb3c/3478ff1f-5d4e-4c53-8309-01bbb93cef63
            13:13:07.859 1/main/627fd config: atrs=1024, expiry=5000msecs durability=null per-txn config: durability=Optional.empty
            13:13:07.866 1/main/627fd/3478f getting doc remove:arun
            13:13:07.870 1/main/627fd/3478f completed get of TransactionGetResult{id=remove:arun,cas=1611781987863625728,status=NORMAL,bucket=people,coll=_default,links=TransactionLinks{atr=none,atrBkt=none,atrColl=none,txnId=none,attemptId=none,op=none,restore={none,none,-1}}} in 3ms
            13:13:07.872 1/main/627fd/3478f remove doc remove:arun
            13:13:07.872 1/main/627fd/3478f First mutated doc in txn is 'remove:arun' on vbucket 605, so using atr _txn:atr-605-#b29
            13:13:07.873 1/main/627fd/3478f about to set ATR people/_default/_txn:atr-605-#b29 to Pending
            13:13:07.875 1/main/627fd/3478f set ATR people/_default/_txn:atr-605-#b29 to Pending in 1ms, got CAS (start time) 1611781987860807680
            13:13:07.876 1/main/627fd/3478f about to remove doc remove:arun with cas 1611781987812769792
            13:13:07.878 1/main/627fd/3478f staged remove of doc remove:arun got cas 1611781987863625728, in 1ms
            13:13:07.878 1/main/627fd/3478f doing implicit commit
            13:13:07.879 1/main/627fd/3478f commit AttemptContextReactive{id=3478f,state=PENDING,isDone=false,atr=_default/_txn:atr-605-#b29,staged=[REMOVE remove:arun]}
            13:13:07.883 1/main/627fd/3478f about to set ATR people/_default/_txn:atr-605-#b29 to Committed
            13:13:07.886 1/main/627fd/3478f error com.couchbase.transactions.error.internal.AbortedAsRequestedNoRollbackNoCleanup: Faking that txn fails at stage afterCommit while setting ATR people/_default/_txn:atr-605-#b29 to Committed
            13:13:07.887 1/main/627fd/<> hit error com.couchbase.transactions.error.internal.AbortedAsRequestedNoRollbackNoCleanup: Faking that txn fails at stage afterCommit
            13:13:07.887 1/main/627fd/<> received non-TransactionException error AbortedAsRequestedNoRollbackNoCleanup, unable to rollback as don't have context
            13:13:07.888 1/main/627fd/<> caught error com.couchbase.transactions.error.internal.AbortedAsRequestedNoRollbackNoCleanup: Faking that txn fails at stage afterCommit, wrapping in TransactionFailed
             
            BUILD SUCCESSFUL in 1s
            2 actionable tasks: 1 executed, 1 up-to-date
            13:13:08: Task execution finished 'Main.main()'.
            

            [root@node1-mad-hatter-testing-centos7 bin]# ./cbbackup -u Administrator -p password http://10.112.194.101:8091 /backup
              [####################] 100.0% (116/estimated 116 msgs)
            bucket: people, msgs transferred...
                   :                total |       last |    per sec
             byte  :                10143 |      10143 |    13704.1
            2021-01-27 13:17:22,094: mt (0, None)
            done
            [root@node1-mad-hatter-testing-centos7 bin]#
             
            [root@node1-mad-hatter-testing-centos7 bin]# ./cbrestore /backup/ http://10.112.194.101:8091 --bucket-source people -u Administrator -p password
            Mid-transaction data have being rolled backed and restored, but transactional atomicity cannot be guaranteed.
              [####################] 100.0% (116/estimated 116 msgs)
            bucket: b'people', msgs transferred...
                   :                total |       last |    per sec
             byte  :                10143 |      10143 |   161921.1
            done
            [root@node1-mad-hatter-testing-centos7 bin]#
            

            Show
            arunkumar Arunkumar Senthilnathan added a comment - Verified in 6.5.2-662: Jan 27, 2021 1:06:07 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info INFO: [com.couchbase.core][CoreCreatedEvent] {"clientVersion":"3.0.0-alpha.7","clientGitHash":"6caa093c","coreVersion":"2.0.0-alpha.7","coreGitHash":"6caa093c","userAgent":"couchbase-java/3.0.0-alpha.7 (Mac OS X 10.14.6 x86_64; Java HotSpot(TM) 64-Bit Server VM 1.8.0_221-b11)","seedNodes":[{"address":"10.112.194.101"}],"ioEnvironment":{"nativeIoEnabled":true,"eventLoopGroups":["KQueueEventLoopGroup"]},"ioConfig":{"allowedSaslMechs":["PLAIN","CRAM_MD5","SCRAM_SHA1","SCRAM_SHA256","SCRAM_SHA512"],"captureTraffic":[],"mutationTokensEnabled":true,"networkResolution":"auto","dnsSrvEnabled":false,"configPollIntervalMillis":2500,"kvCircuitBreakerConfig":"disabled","queryCircuitBreakerConfig":"disabled","viewCircuitBreakerConfig":"disabled","searchCircuitBreakerConfig":"disabled","analyticsCircuitBreakerConfig":"disabled","managerCircuitBreakerConfig":"disabled"},"compressionConfig":{"enabled":true,"minRatio":0.83,"minSize":32},"securityConfig":{"tlsEnabled":false,"nativeTlsEnabled":true,"certAuthEnabled":false,"hasTrustCertificates":false,"trustManagerFactory":null},"timeoutConfig":{"kvMs":2500,"managementMs":75000,"queryMs":75000,"viewMs":75000,"searchMs":75000,"analyticsMs":75000,"connectMs":10000,"disconnectMs":10000},"serviceConfig":{"kv":{"min":1,"max":1,"idleTimeMs":0},"query":{"min":0,"max":12,"idleTimeMs":300000},"view":{"min":0,"max":12,"idleTimeMs":300000},"search":{"min":0,"max":12,"idleTimeMs":300000},"analytics":{"min":0,"max":12,"idleTimeMs":300000}},"loggerConfig":{"customLogger":null,"fallbackToConsole":false,"disableSlf4j":false,"loggerName":"CouchbaseLogger","diagnosticContextEnabled":false},"credentials":"UsernameAndPassword","retryStrategy":"BestEffortRetryStrategy"} {"coreId":1} Jan 27, 2021 1:06:07 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info INFO: [com.couchbase.node][NodeConnectedEvent] Node connected {"coreId":1,"managerPort":"8091","remote":"10.112.194.101"} Jan 27, 2021 1:06:07 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info INFO: [com.couchbase.core][BucketOpenedEvent][60483µs] Opened bucket "people" {"coreId":1} Jan 27, 2021 1:06:07 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info INFO: [com.couchbase.transactions.cleanup][TransactionLogEvent] Cleanup settings; regular cleanup thread enabled=true, lost cleanup thread enabled=true Jan 27, 2021 1:06:07 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info INFO: [com.couchbase.transactions.cleanup.regular][TransactionLogEvent] Starting background cleanup thread to find transactions from this client Jan 27, 2021 1:06:07 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info INFO: [com.couchbase.transactions][TransactionsStarted] Transactions successfully started, regular cleanup enabled=true, lost cleanup enabled=true Jan 27, 2021 1:06:07 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info INFO: [com.couchbase.core][BucketOpenedEvent][4477µs] Opened bucket "people" {"coreId":1} Jan 27, 2021 1:06:07 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info INFO: [com.couchbase.transactions.cleanup.lost][TransactionLogEvent] Client 3c8dd people/_default creating thread to handle lost transactions Transaction failed: 13:06:07.810 1/main/978fb starting attempt 0/978fb572-c82d-44ac-b7d9-6e3e3978bb1b/4e1938f9-c4fb-4d70-b0c7-d40967bf11c4 13:06:07.811 1/main/978fb config: atrs=1024, expiry=5000msecs durability=null per-txn config: durability=Optional.empty 13:06:07.814 1/main/978fb/4e193 First mutated doc in txn is 'insert:arun' on vbucket 621, so using atr _txn:atr-621-#1b88 13:06:07.816 1/main/978fb/4e193 about to set ATR people/_default/_txn:atr-621-#1b88 to Pending 13:06:07.818 1/main/978fb/4e193 set ATR people/_default/_txn:atr-621-#1b88 to Pending in 1ms, got CAS (start time) 1611781567809912832 13:06:07.821 1/main/978fb/4e193 about to insert staged doc insert:arun 13:06:07.825 1/main/978fb/4e193 inserted doc insert:arun got cas 1611781567814565888, in 3ms 13:06:07.825 1/main/978fb/4e193 doing implicit commit 13:06:07.826 1/main/978fb/4e193 commit AttemptContextReactive{id=4e193,state=PENDING,isDone=false,atr=_default/_txn:atr-621-#1b88,staged=[INSERT insert:arun]} 13:06:07.830 1/main/978fb/4e193 about to set ATR people/_default/_txn:atr-621-#1b88 to Committed 13:06:07.833 1/main/978fb/4e193 error com.couchbase.transactions.error.internal.AbortedAsRequestedNoRollbackNoCleanup: Faking that txn fails at stage afterCommit while setting ATR people/_default/_txn:atr-621-#1b88 to Committed 13:06:07.834 1/main/978fb/<> hit error com.couchbase.transactions.error.internal.AbortedAsRequestedNoRollbackNoCleanup: Faking that txn fails at stage afterCommit 13:06:07.834 1/main/978fb/<> received non-TransactionException error AbortedAsRequestedNoRollbackNoCleanup, unable to rollback as don't have context 13:06:07.834 1/main/978fb/<> caught error com.couchbase.transactions.error.internal.AbortedAsRequestedNoRollbackNoCleanup: Faking that txn fails at stage afterCommit, wrapping in TransactionFailed   BUILD SUCCESSFUL in 1s 2 actionable tasks: 1 executed, 1 up-to-date > Task :Main.main() Jan 27, 2021 1:07:04 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info INFO: [com.couchbase.core][CoreCreatedEvent] {"clientVersion":"3.0.0-alpha.7","clientGitHash":"6caa093c","coreVersion":"2.0.0-alpha.7","coreGitHash":"6caa093c","userAgent":"couchbase-java/3.0.0-alpha.7 (Mac OS X 10.14.6 x86_64; Java HotSpot(TM) 64-Bit Server VM 1.8.0_221-b11)","seedNodes":[{"address":"10.112.194.101"}],"ioEnvironment":{"nativeIoEnabled":true,"eventLoopGroups":["KQueueEventLoopGroup"]},"ioConfig":{"allowedSaslMechs":["PLAIN","CRAM_MD5","SCRAM_SHA1","SCRAM_SHA256","SCRAM_SHA512"],"captureTraffic":[],"mutationTokensEnabled":true,"networkResolution":"auto","dnsSrvEnabled":false,"configPollIntervalMillis":2500,"kvCircuitBreakerConfig":"disabled","queryCircuitBreakerConfig":"disabled","viewCircuitBreakerConfig":"disabled","searchCircuitBreakerConfig":"disabled","analyticsCircuitBreakerConfig":"disabled","managerCircuitBreakerConfig":"disabled"},"compressionConfig":{"enabled":true,"minRatio":0.83,"minSize":32},"securityConfig":{"tlsEnabled":false,"nativeTlsEnabled":true,"certAuthEnabled":false,"hasTrustCertificates":false,"trustManagerFactory":null},"timeoutConfig":{"kvMs":2500,"managementMs":75000,"queryMs":75000,"viewMs":75000,"searchMs":75000,"analyticsMs":75000,"connectMs":10000,"disconnectMs":10000},"serviceConfig":{"kv":{"min":1,"max":1,"idleTimeMs":0},"query":{"min":0,"max":12,"idleTimeMs":300000},"view":{"min":0,"max":12,"idleTimeMs":300000},"search":{"min":0,"max":12,"idleTimeMs":300000},"analytics":{"min":0,"max":12,"idleTimeMs":300000}},"loggerConfig":{"customLogger":null,"fallbackToConsole":false,"disableSlf4j":false,"loggerName":"CouchbaseLogger","diagnosticContextEnabled":false},"credentials":"UsernameAndPassword","retryStrategy":"BestEffortRetryStrategy"} {"coreId":1} Jan 27, 2021 1:07:04 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info INFO: [com.couchbase.node][NodeConnectedEvent] Node connected {"coreId":1,"managerPort":"8091","remote":"10.112.194.101"} Jan 27, 2021 1:07:04 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info INFO: [com.couchbase.core][BucketOpenedEvent][57188µs] Opened bucket "people" {"coreId":1} Jan 27, 2021 1:07:04 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info INFO: [com.couchbase.transactions.cleanup][TransactionLogEvent] Cleanup settings; regular cleanup thread enabled=true, lost cleanup thread enabled=true Jan 27, 2021 1:07:04 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info INFO: [com.couchbase.transactions.cleanup.regular][TransactionLogEvent] Starting background cleanup thread to find transactions from this client Jan 27, 2021 1:07:04 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info INFO: [com.couchbase.transactions][TransactionsStarted] Transactions successfully started, regular cleanup enabled=true, lost cleanup enabled=true Jan 27, 2021 1:07:04 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info INFO: [com.couchbase.core][BucketOpenedEvent][3862µs] Opened bucket "people" {"coreId":1} Jan 27, 2021 1:07:04 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info INFO: [com.couchbase.transactions.cleanup.lost][TransactionLogEvent] Client 8b7ae people/_default creating thread to handle lost transactions Transaction failed: 13:07:04.835 1/main/d0d20 starting attempt 0/d0d20635-f086-4bd8-a44a-2b32a12420e2/d06249be-6aef-4b65-87c2-9559673de588 13:07:04.835 1/main/d0d20 config: atrs=1024, expiry=5000msecs durability=null per-txn config: durability=Optional.empty 13:07:04.842 1/main/d0d20/d0624 getting doc xattrs:arun 13:07:04.846 1/main/d0d20/d0624 completed get of TransactionGetResult{id=xattrs:arun,cas=1611781624846352384,status=NORMAL,bucket=people,coll=_default,links=TransactionLinks{atr=none,atrBkt=none,atrColl=none,txnId=none,attemptId=none,op=none,restore={none,none,-1}}} in 3ms 13:07:04.847 1/main/d0d20/d0624 replace doc TransactionGetResult{id=xattrs:arun,cas=1611781624846352384,status=NORMAL,bucket=people,coll=_default,links=TransactionLinks{atr=none,atrBkt=none,atrColl=none,txnId=none,attemptId=none,op=none,restore={none,none,-1}}} 13:07:04.848 1/main/d0d20/d0624 First mutated doc in txn is 'xattrs:arun' on vbucket 363, so using atr _txn:atr-363-#203 13:07:04.850 1/main/d0d20/d0624 about to set ATR people/_default/_txn:atr-363-#203 to Pending 13:07:04.851 1/main/d0d20/d0624 set ATR people/_default/_txn:atr-363-#203 to Pending in 1ms, got CAS (start time) 1611781624842616832 13:07:04.854 1/main/d0d20/d0624 about to replace doc xattrs:arun with cas 1611781624807096320 13:07:04.855 1/main/d0d20/d0624 replaced doc xattrs:arun got new cas 1611781624846352384, in 1ms 13:07:04.857 1/main/d0d20/d0624 doing implicit commit 13:07:04.857 1/main/d0d20/d0624 commit AttemptContextReactive{id=d0624,state=PENDING,isDone=false,atr=_default/_txn:atr-363-#203,staged=[REPLACE xattrs:arun]} 13:07:04.862 1/main/d0d20/d0624 about to set ATR people/_default/_txn:atr-363-#203 to Committed 13:07:04.865 1/main/d0d20/d0624 error com.couchbase.transactions.error.internal.AbortedAsRequestedNoRollbackNoCleanup: Faking that txn fails at stage afterCommit while setting ATR people/_default/_txn:atr-363-#203 to Committed 13:07:04.867 1/main/d0d20/<> hit error com.couchbase.transactions.error.internal.AbortedAsRequestedNoRollbackNoCleanup: Faking that txn fails at stage afterCommit 13:07:04.867 1/main/d0d20/<> received non-TransactionException error AbortedAsRequestedNoRollbackNoCleanup, unable to rollback as don't have context 13:07:04.867 1/main/d0d20/<> caught error com.couchbase.transactions.error.internal.AbortedAsRequestedNoRollbackNoCleanup: Faking that txn fails at stage afterCommit, wrapping in TransactionFailed   BUILD SUCCESSFUL in 1s 2 actionable tasks: 1 executed, 1 up-to-date 13:07:05: Task execution finished 'Main.main()'. > Task :Main.main() Jan 27, 2021 1:09:47 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info INFO: [com.couchbase.core][CoreCreatedEvent] {"clientVersion":"3.0.0-alpha.7","clientGitHash":"6caa093c","coreVersion":"2.0.0-alpha.7","coreGitHash":"6caa093c","userAgent":"couchbase-java/3.0.0-alpha.7 (Mac OS X 10.14.6 x86_64; Java HotSpot(TM) 64-Bit Server VM 1.8.0_221-b11)","seedNodes":[{"address":"10.112.194.101"}],"ioEnvironment":{"nativeIoEnabled":true,"eventLoopGroups":["KQueueEventLoopGroup"]},"ioConfig":{"allowedSaslMechs":["PLAIN","CRAM_MD5","SCRAM_SHA1","SCRAM_SHA256","SCRAM_SHA512"],"captureTraffic":[],"mutationTokensEnabled":true,"networkResolution":"auto","dnsSrvEnabled":false,"configPollIntervalMillis":2500,"kvCircuitBreakerConfig":"disabled","queryCircuitBreakerConfig":"disabled","viewCircuitBreakerConfig":"disabled","searchCircuitBreakerConfig":"disabled","analyticsCircuitBreakerConfig":"disabled","managerCircuitBreakerConfig":"disabled"},"compressionConfig":{"enabled":true,"minRatio":0.83,"minSize":32},"securityConfig":{"tlsEnabled":false,"nativeTlsEnabled":true,"certAuthEnabled":false,"hasTrustCertificates":false,"trustManagerFactory":null},"timeoutConfig":{"kvMs":2500,"managementMs":75000,"queryMs":75000,"viewMs":75000,"searchMs":75000,"analyticsMs":75000,"connectMs":10000,"disconnectMs":10000},"serviceConfig":{"kv":{"min":1,"max":1,"idleTimeMs":0},"query":{"min":0,"max":12,"idleTimeMs":300000},"view":{"min":0,"max":12,"idleTimeMs":300000},"search":{"min":0,"max":12,"idleTimeMs":300000},"analytics":{"min":0,"max":12,"idleTimeMs":300000}},"loggerConfig":{"customLogger":null,"fallbackToConsole":false,"disableSlf4j":false,"loggerName":"CouchbaseLogger","diagnosticContextEnabled":false},"credentials":"UsernameAndPassword","retryStrategy":"BestEffortRetryStrategy"} {"coreId":1} Jan 27, 2021 1:09:47 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info INFO: [com.couchbase.node][NodeConnectedEvent] Node connected {"coreId":1,"managerPort":"8091","remote":"10.112.194.101"} Jan 27, 2021 1:09:47 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info INFO: [com.couchbase.core][BucketOpenedEvent][63356µs] Opened bucket "people" {"coreId":1} Jan 27, 2021 1:09:47 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info INFO: [com.couchbase.transactions.cleanup][TransactionLogEvent] Cleanup settings; regular cleanup thread enabled=true, lost cleanup thread enabled=true Jan 27, 2021 1:09:47 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info INFO: [com.couchbase.transactions.cleanup.regular][TransactionLogEvent] Starting background cleanup thread to find transactions from this client Jan 27, 2021 1:09:47 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info INFO: [com.couchbase.transactions][TransactionsStarted] Transactions successfully started, regular cleanup enabled=true, lost cleanup enabled=true Jan 27, 2021 1:09:47 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info INFO: [com.couchbase.core][BucketOpenedEvent][4477µs] Opened bucket "people" {"coreId":1} Jan 27, 2021 1:09:47 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info INFO: [com.couchbase.transactions.cleanup.lost][TransactionLogEvent] Client 2580e people/_default creating thread to handle lost transactions Transaction failed: 13:09:47.849 1/main/8fb0e starting attempt 0/8fb0e5e1-d6e3-4503-839a-b00b731ee2d0/4c1a4511-658b-416d-8b70-2d9bb1b2f9d6 13:09:47.849 1/main/8fb0e config: atrs=1024, expiry=5000msecs durability=null per-txn config: durability=Optional.empty 13:09:47.855 1/main/8fb0e/4c1a4 getting doc replace:arun 13:09:47.860 1/main/8fb0e/4c1a4 completed get of TransactionGetResult{id=replace:arun,cas=1611781787856928768,status=NORMAL,bucket=people,coll=_default,links=TransactionLinks{atr=none,atrBkt=none,atrColl=none,txnId=none,attemptId=none,op=none,restore={none,none,-1}}} in 4ms 13:09:47.861 1/main/8fb0e/4c1a4 replace doc TransactionGetResult{id=replace:arun,cas=1611781787856928768,status=NORMAL,bucket=people,coll=_default,links=TransactionLinks{atr=none,atrBkt=none,atrColl=none,txnId=none,attemptId=none,op=none,restore={none,none,-1}}} 13:09:47.862 1/main/8fb0e/4c1a4 First mutated doc in txn is 'replace:arun' on vbucket 803, so using atr _txn:atr-803-#80a 13:09:47.863 1/main/8fb0e/4c1a4 about to set ATR people/_default/_txn:atr-803-#80a to Pending 13:09:47.865 1/main/8fb0e/4c1a4 set ATR people/_default/_txn:atr-803-#80a to Pending in 1ms, got CAS (start time) 1611781787853717504 13:09:47.867 1/main/8fb0e/4c1a4 about to replace doc replace:arun with cas 1611781787803648000 13:09:47.868 1/main/8fb0e/4c1a4 replaced doc replace:arun got new cas 1611781787856928768, in 1ms 13:09:47.869 1/main/8fb0e/4c1a4 doing implicit commit 13:09:47.870 1/main/8fb0e/4c1a4 commit AttemptContextReactive{id=4c1a4,state=PENDING,isDone=false,atr=_default/_txn:atr-803-#80a,staged=[REPLACE replace:arun]} 13:09:47.874 1/main/8fb0e/4c1a4 about to set ATR people/_default/_txn:atr-803-#80a to Committed 13:09:47.878 1/main/8fb0e/4c1a4 error com.couchbase.transactions.error.internal.AbortedAsRequestedNoRollbackNoCleanup: Faking that txn fails at stage afterCommit while setting ATR people/_default/_txn:atr-803-#80a to Committed 13:09:47.879 1/main/8fb0e/<> hit error com.couchbase.transactions.error.internal.AbortedAsRequestedNoRollbackNoCleanup: Faking that txn fails at stage afterCommit 13:09:47.879 1/main/8fb0e/<> received non-TransactionException error AbortedAsRequestedNoRollbackNoCleanup, unable to rollback as don't have context 13:09:47.879 1/main/8fb0e/<> caught error com.couchbase.transactions.error.internal.AbortedAsRequestedNoRollbackNoCleanup: Faking that txn fails at stage afterCommit, wrapping in TransactionFailed   BUILD SUCCESSFUL in 1s 2 actionable tasks: 1 executed, 1 up-to-date 13:09:48: Task execution finished 'Main.main()'. > Task :Main.main() Jan 27, 2021 1:13:07 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info INFO: [com.couchbase.core][CoreCreatedEvent] {"clientVersion":"3.0.0-alpha.7","clientGitHash":"6caa093c","coreVersion":"2.0.0-alpha.7","coreGitHash":"6caa093c","userAgent":"couchbase-java/3.0.0-alpha.7 (Mac OS X 10.14.6 x86_64; Java HotSpot(TM) 64-Bit Server VM 1.8.0_221-b11)","seedNodes":[{"address":"10.112.194.101"}],"ioEnvironment":{"nativeIoEnabled":true,"eventLoopGroups":["KQueueEventLoopGroup"]},"ioConfig":{"allowedSaslMechs":["PLAIN","CRAM_MD5","SCRAM_SHA1","SCRAM_SHA256","SCRAM_SHA512"],"captureTraffic":[],"mutationTokensEnabled":true,"networkResolution":"auto","dnsSrvEnabled":false,"configPollIntervalMillis":2500,"kvCircuitBreakerConfig":"disabled","queryCircuitBreakerConfig":"disabled","viewCircuitBreakerConfig":"disabled","searchCircuitBreakerConfig":"disabled","analyticsCircuitBreakerConfig":"disabled","managerCircuitBreakerConfig":"disabled"},"compressionConfig":{"enabled":true,"minRatio":0.83,"minSize":32},"securityConfig":{"tlsEnabled":false,"nativeTlsEnabled":true,"certAuthEnabled":false,"hasTrustCertificates":false,"trustManagerFactory":null},"timeoutConfig":{"kvMs":2500,"managementMs":75000,"queryMs":75000,"viewMs":75000,"searchMs":75000,"analyticsMs":75000,"connectMs":10000,"disconnectMs":10000},"serviceConfig":{"kv":{"min":1,"max":1,"idleTimeMs":0},"query":{"min":0,"max":12,"idleTimeMs":300000},"view":{"min":0,"max":12,"idleTimeMs":300000},"search":{"min":0,"max":12,"idleTimeMs":300000},"analytics":{"min":0,"max":12,"idleTimeMs":300000}},"loggerConfig":{"customLogger":null,"fallbackToConsole":false,"disableSlf4j":false,"loggerName":"CouchbaseLogger","diagnosticContextEnabled":false},"credentials":"UsernameAndPassword","retryStrategy":"BestEffortRetryStrategy"} {"coreId":1} Jan 27, 2021 1:13:07 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info INFO: [com.couchbase.node][NodeConnectedEvent] Node connected {"coreId":1,"managerPort":"8091","remote":"10.112.194.101"} Jan 27, 2021 1:13:07 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info INFO: [com.couchbase.core][BucketOpenedEvent][60498µs] Opened bucket "people" {"coreId":1} Jan 27, 2021 1:13:07 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info INFO: [com.couchbase.transactions.cleanup][TransactionLogEvent] Cleanup settings; regular cleanup thread enabled=true, lost cleanup thread enabled=true Jan 27, 2021 1:13:07 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info INFO: [com.couchbase.transactions.cleanup.regular][TransactionLogEvent] Starting background cleanup thread to find transactions from this client Jan 27, 2021 1:13:07 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info INFO: [com.couchbase.transactions][TransactionsStarted] Transactions successfully started, regular cleanup enabled=true, lost cleanup enabled=true Jan 27, 2021 1:13:07 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info INFO: [com.couchbase.core][BucketOpenedEvent][3736µs] Opened bucket "people" {"coreId":1} Jan 27, 2021 1:13:07 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info INFO: [com.couchbase.transactions.cleanup.lost][TransactionLogEvent] Client 9867a people/_default creating thread to handle lost transactions Transaction failed: 13:13:07.859 1/main/627fd starting attempt 0/627fdcd8-295c-4952-987b-faa9cb06cb3c/3478ff1f-5d4e-4c53-8309-01bbb93cef63 13:13:07.859 1/main/627fd config: atrs=1024, expiry=5000msecs durability=null per-txn config: durability=Optional.empty 13:13:07.866 1/main/627fd/3478f getting doc remove:arun 13:13:07.870 1/main/627fd/3478f completed get of TransactionGetResult{id=remove:arun,cas=1611781987863625728,status=NORMAL,bucket=people,coll=_default,links=TransactionLinks{atr=none,atrBkt=none,atrColl=none,txnId=none,attemptId=none,op=none,restore={none,none,-1}}} in 3ms 13:13:07.872 1/main/627fd/3478f remove doc remove:arun 13:13:07.872 1/main/627fd/3478f First mutated doc in txn is 'remove:arun' on vbucket 605, so using atr _txn:atr-605-#b29 13:13:07.873 1/main/627fd/3478f about to set ATR people/_default/_txn:atr-605-#b29 to Pending 13:13:07.875 1/main/627fd/3478f set ATR people/_default/_txn:atr-605-#b29 to Pending in 1ms, got CAS (start time) 1611781987860807680 13:13:07.876 1/main/627fd/3478f about to remove doc remove:arun with cas 1611781987812769792 13:13:07.878 1/main/627fd/3478f staged remove of doc remove:arun got cas 1611781987863625728, in 1ms 13:13:07.878 1/main/627fd/3478f doing implicit commit 13:13:07.879 1/main/627fd/3478f commit AttemptContextReactive{id=3478f,state=PENDING,isDone=false,atr=_default/_txn:atr-605-#b29,staged=[REMOVE remove:arun]} 13:13:07.883 1/main/627fd/3478f about to set ATR people/_default/_txn:atr-605-#b29 to Committed 13:13:07.886 1/main/627fd/3478f error com.couchbase.transactions.error.internal.AbortedAsRequestedNoRollbackNoCleanup: Faking that txn fails at stage afterCommit while setting ATR people/_default/_txn:atr-605-#b29 to Committed 13:13:07.887 1/main/627fd/<> hit error com.couchbase.transactions.error.internal.AbortedAsRequestedNoRollbackNoCleanup: Faking that txn fails at stage afterCommit 13:13:07.887 1/main/627fd/<> received non-TransactionException error AbortedAsRequestedNoRollbackNoCleanup, unable to rollback as don't have context 13:13:07.888 1/main/627fd/<> caught error com.couchbase.transactions.error.internal.AbortedAsRequestedNoRollbackNoCleanup: Faking that txn fails at stage afterCommit, wrapping in TransactionFailed   BUILD SUCCESSFUL in 1s 2 actionable tasks: 1 executed, 1 up-to-date 13:13:08: Task execution finished 'Main.main()'. [root@node1-mad-hatter-testing-centos7 bin]# ./cbbackup -u Administrator -p password http://10.112.194.101:8091 /backup [####################] 100.0% (116/estimated 116 msgs) bucket: people, msgs transferred... : total | last | per sec byte : 10143 | 10143 | 13704.1 2021-01-27 13:17:22,094: mt (0, None) done [root@node1-mad-hatter-testing-centos7 bin]#   [root@node1-mad-hatter-testing-centos7 bin]# ./cbrestore /backup/ http://10.112.194.101:8091 --bucket-source people -u Administrator -p password Mid-transaction data have being rolled backed and restored, but transactional atomicity cannot be guaranteed. [####################] 100.0% (116/estimated 116 msgs) bucket: b'people', msgs transferred... : total | last | per sec byte : 10143 | 10143 | 161921.1 done [root@node1-mad-hatter-testing-centos7 bin]#
            Hide
            arunkumar Arunkumar Senthilnathan added a comment -

            Verified in 6.6.2-9458:

            > Task :Main.main()
            Jan 27, 2021 3:40:49 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info
            INFO: [com.couchbase.core][CoreCreatedEvent] {"clientVersion":"3.0.0-alpha.7","clientGitHash":"6caa093c","coreVersion":"2.0.0-alpha.7","coreGitHash":"6caa093c","userAgent":"couchbase-java/3.0.0-alpha.7 (Mac OS X 10.14.6 x86_64; Java HotSpot(TM) 64-Bit Server VM 1.8.0_221-b11)","seedNodes":[{"address":"10.112.194.101"}],"ioEnvironment":{"nativeIoEnabled":true,"eventLoopGroups":["KQueueEventLoopGroup"]},"ioConfig":{"allowedSaslMechs":["PLAIN","CRAM_MD5","SCRAM_SHA1","SCRAM_SHA256","SCRAM_SHA512"],"captureTraffic":[],"mutationTokensEnabled":true,"networkResolution":"auto","dnsSrvEnabled":false,"configPollIntervalMillis":2500,"kvCircuitBreakerConfig":"disabled","queryCircuitBreakerConfig":"disabled","viewCircuitBreakerConfig":"disabled","searchCircuitBreakerConfig":"disabled","analyticsCircuitBreakerConfig":"disabled","managerCircuitBreakerConfig":"disabled"},"compressionConfig":{"enabled":true,"minRatio":0.83,"minSize":32},"securityConfig":{"tlsEnabled":false,"nativeTlsEnabled":true,"certAuthEnabled":false,"hasTrustCertificates":false,"trustManagerFactory":null},"timeoutConfig":{"kvMs":2500,"managementMs":75000,"queryMs":75000,"viewMs":75000,"searchMs":75000,"analyticsMs":75000,"connectMs":10000,"disconnectMs":10000},"serviceConfig":{"kv":{"min":1,"max":1,"idleTimeMs":0},"query":{"min":0,"max":12,"idleTimeMs":300000},"view":{"min":0,"max":12,"idleTimeMs":300000},"search":{"min":0,"max":12,"idleTimeMs":300000},"analytics":{"min":0,"max":12,"idleTimeMs":300000}},"loggerConfig":{"customLogger":null,"fallbackToConsole":false,"disableSlf4j":false,"loggerName":"CouchbaseLogger","diagnosticContextEnabled":false},"credentials":"UsernameAndPassword","retryStrategy":"BestEffortRetryStrategy"} {"coreId":1}
            Jan 27, 2021 3:40:49 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info
            INFO: [com.couchbase.node][NodeConnectedEvent] Node connected {"coreId":1,"managerPort":"8091","remote":"10.112.194.101"}
            Jan 27, 2021 3:40:50 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info
            INFO: [com.couchbase.core][BucketOpenedEvent][162319µs] Opened bucket "people" {"coreId":1}
            Jan 27, 2021 3:40:50 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info
            INFO: [com.couchbase.transactions.cleanup][TransactionLogEvent] Cleanup settings; regular cleanup thread enabled=true, lost cleanup thread enabled=true
            Jan 27, 2021 3:40:50 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info
            INFO: [com.couchbase.transactions.cleanup.regular][TransactionLogEvent] Starting background cleanup thread to find transactions from this client
            Jan 27, 2021 3:40:50 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info
            INFO: [com.couchbase.transactions][TransactionsStarted] Transactions successfully started, regular cleanup enabled=true, lost cleanup enabled=true
            Jan 27, 2021 3:40:50 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info
            INFO: [com.couchbase.core][BucketOpenedEvent][3709µs] Opened bucket "people" {"coreId":1}
            Jan 27, 2021 3:40:50 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info
            INFO: [com.couchbase.transactions.cleanup.lost][TransactionLogEvent] Client d5bc0 people/_default creating thread to handle lost transactions
            Transaction failed:
            15:40:50.224 1/main/e4394 starting attempt 0/e4394006-ca16-428e-8076-7c356727836a/01331a6e-75bf-4cd8-ac61-6da639c5d8cc
            15:40:50.224 1/main/e4394 config: atrs=1024, expiry=5000msecs durability=null per-txn config: durability=Optional.empty
            15:40:50.233 1/main/e4394/01331 First mutated doc in txn is 'insert:arun' on vbucket 621, so using atr _txn:atr-621-#1b88
            15:40:50.235 1/main/e4394/01331 about to set ATR people/_default/_txn:atr-621-#1b88 to Pending
            15:40:50.237 1/main/e4394/01331 set ATR people/_default/_txn:atr-621-#1b88 to Pending in 2ms, got CAS (start time) 1611790850223112192
            15:40:50.240 1/main/e4394/01331 about to insert staged doc insert:arun
            15:40:50.242 1/main/e4394/01331 inserted doc insert:arun got cas 1611790850226913280, in 2ms
            15:40:50.242 1/main/e4394/01331 doing implicit commit
            15:40:50.243 1/main/e4394/01331 commit AttemptContextReactive{id=01331,state=PENDING,isDone=false,atr=_default/_txn:atr-621-#1b88,staged=[INSERT insert:arun]}
            15:40:50.247 1/main/e4394/01331 about to set ATR people/_default/_txn:atr-621-#1b88 to Committed
            15:40:50.249 1/main/e4394/01331 error com.couchbase.transactions.error.internal.AbortedAsRequestedNoRollbackNoCleanup: Faking that txn fails at stage afterCommit while setting ATR people/_default/_txn:atr-621-#1b88 to Committed
            15:40:50.250 1/main/e4394/<> hit error com.couchbase.transactions.error.internal.AbortedAsRequestedNoRollbackNoCleanup: Faking that txn fails at stage afterCommit
            15:40:50.250 1/main/e4394/<> received non-TransactionException error AbortedAsRequestedNoRollbackNoCleanup, unable to rollback as don't have context
            15:40:50.251 1/main/e4394/<> caught error com.couchbase.transactions.error.internal.AbortedAsRequestedNoRollbackNoCleanup: Faking that txn fails at stage afterCommit, wrapping in TransactionFailed
             
            BUILD SUCCESSFUL in 1s
            2 actionable tasks: 1 executed, 1 up-to-date
            15:40:50: Task execution finished 'Main.main()'.
            > Task :Main.main()
            Jan 27, 2021 3:42:51 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info
            INFO: [com.couchbase.core][CoreCreatedEvent] {"clientVersion":"3.0.0-alpha.7","clientGitHash":"6caa093c","coreVersion":"2.0.0-alpha.7","coreGitHash":"6caa093c","userAgent":"couchbase-java/3.0.0-alpha.7 (Mac OS X 10.14.6 x86_64; Java HotSpot(TM) 64-Bit Server VM 1.8.0_221-b11)","seedNodes":[{"address":"10.112.194.101"}],"ioEnvironment":{"nativeIoEnabled":true,"eventLoopGroups":["KQueueEventLoopGroup"]},"ioConfig":{"allowedSaslMechs":["PLAIN","CRAM_MD5","SCRAM_SHA1","SCRAM_SHA256","SCRAM_SHA512"],"captureTraffic":[],"mutationTokensEnabled":true,"networkResolution":"auto","dnsSrvEnabled":false,"configPollIntervalMillis":2500,"kvCircuitBreakerConfig":"disabled","queryCircuitBreakerConfig":"disabled","viewCircuitBreakerConfig":"disabled","searchCircuitBreakerConfig":"disabled","analyticsCircuitBreakerConfig":"disabled","managerCircuitBreakerConfig":"disabled"},"compressionConfig":{"enabled":true,"minRatio":0.83,"minSize":32},"securityConfig":{"tlsEnabled":false,"nativeTlsEnabled":true,"certAuthEnabled":false,"hasTrustCertificates":false,"trustManagerFactory":null},"timeoutConfig":{"kvMs":2500,"managementMs":75000,"queryMs":75000,"viewMs":75000,"searchMs":75000,"analyticsMs":75000,"connectMs":10000,"disconnectMs":10000},"serviceConfig":{"kv":{"min":1,"max":1,"idleTimeMs":0},"query":{"min":0,"max":12,"idleTimeMs":300000},"view":{"min":0,"max":12,"idleTimeMs":300000},"search":{"min":0,"max":12,"idleTimeMs":300000},"analytics":{"min":0,"max":12,"idleTimeMs":300000}},"loggerConfig":{"customLogger":null,"fallbackToConsole":false,"disableSlf4j":false,"loggerName":"CouchbaseLogger","diagnosticContextEnabled":false},"credentials":"UsernameAndPassword","retryStrategy":"BestEffortRetryStrategy"} {"coreId":1}
            Jan 27, 2021 3:42:51 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info
            INFO: [com.couchbase.node][NodeConnectedEvent] Node connected {"coreId":1,"managerPort":"8091","remote":"10.112.194.101"}
            Jan 27, 2021 3:42:51 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info
            INFO: [com.couchbase.core][BucketOpenedEvent][65557µs] Opened bucket "people" {"coreId":1}
            Jan 27, 2021 3:42:51 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info
            INFO: [com.couchbase.transactions.cleanup][TransactionLogEvent] Cleanup settings; regular cleanup thread enabled=true, lost cleanup thread enabled=true
            Jan 27, 2021 3:42:51 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info
            INFO: [com.couchbase.transactions.cleanup.regular][TransactionLogEvent] Starting background cleanup thread to find transactions from this client
            Jan 27, 2021 3:42:51 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info
            INFO: [com.couchbase.transactions][TransactionsStarted] Transactions successfully started, regular cleanup enabled=true, lost cleanup enabled=true
            Jan 27, 2021 3:42:51 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info
            INFO: [com.couchbase.core][BucketOpenedEvent][3817µs] Opened bucket "people" {"coreId":1}
            Jan 27, 2021 3:42:51 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info
            INFO: [com.couchbase.transactions.cleanup.lost][TransactionLogEvent] Client 55593 people/_default creating thread to handle lost transactions
            Transaction failed:
            15:42:51.832 1/main/5701c starting attempt 0/5701cc82-2976-4d17-b3dc-fb9fce046f03/74670108-3ad5-4fec-9947-44510bdf6adb
            15:42:51.832 1/main/5701c config: atrs=1024, expiry=5000msecs durability=null per-txn config: durability=Optional.empty
            15:42:51.840 1/main/5701c/74670 getting doc xattrs:arun
            15:42:51.843 1/main/5701c/74670 completed get of TransactionGetResult{id=xattrs:arun,cas=1611790971836366848,status=NORMAL,bucket=people,coll=_default,links=TransactionLinks{atr=none,atrBkt=none,atrColl=none,txnId=none,attemptId=none,op=none,restore={none,none,-1}}} in 3ms
            15:42:51.844 1/main/5701c/74670 replace doc TransactionGetResult{id=xattrs:arun,cas=1611790971836366848,status=NORMAL,bucket=people,coll=_default,links=TransactionLinks{atr=none,atrBkt=none,atrColl=none,txnId=none,attemptId=none,op=none,restore={none,none,-1}}}
            15:42:51.845 1/main/5701c/74670 First mutated doc in txn is 'xattrs:arun' on vbucket 363, so using atr _txn:atr-363-#203
            15:42:51.847 1/main/5701c/74670 about to set ATR people/_default/_txn:atr-363-#203 to Pending
            15:42:51.848 1/main/5701c/74670 set ATR people/_default/_txn:atr-363-#203 to Pending in 1ms, got CAS (start time) 1611790971832762368
            15:42:51.851 1/main/5701c/74670 about to replace doc xattrs:arun with cas 1611790971798683648
            15:42:51.853 1/main/5701c/74670 replaced doc xattrs:arun got new cas 1611790971836366848, in 1ms
            15:42:51.854 1/main/5701c/74670 doing implicit commit
            15:42:51.855 1/main/5701c/74670 commit AttemptContextReactive{id=74670,state=PENDING,isDone=false,atr=_default/_txn:atr-363-#203,staged=[REPLACE xattrs:arun]}
            15:42:51.859 1/main/5701c/74670 about to set ATR people/_default/_txn:atr-363-#203 to Committed
            15:42:51.862 1/main/5701c/74670 error com.couchbase.transactions.error.internal.AbortedAsRequestedNoRollbackNoCleanup: Faking that txn fails at stage afterCommit while setting ATR people/_default/_txn:atr-363-#203 to Committed
            15:42:51.863 1/main/5701c/<> hit error com.couchbase.transactions.error.internal.AbortedAsRequestedNoRollbackNoCleanup: Faking that txn fails at stage afterCommit
            15:42:51.863 1/main/5701c/<> received non-TransactionException error AbortedAsRequestedNoRollbackNoCleanup, unable to rollback as don't have context
            15:42:51.863 1/main/5701c/<> caught error com.couchbase.transactions.error.internal.AbortedAsRequestedNoRollbackNoCleanup: Faking that txn fails at stage afterCommit, wrapping in TransactionFailed
             
            BUILD SUCCESSFUL in 1s
            2 actionable tasks: 1 executed, 1 up-to-date
            15:42:52: Task execution finished 'Main.main()'.
            > Task :Main.main()
            Jan 27, 2021 3:43:26 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info
            INFO: [com.couchbase.core][CoreCreatedEvent] {"clientVersion":"3.0.0-alpha.7","clientGitHash":"6caa093c","coreVersion":"2.0.0-alpha.7","coreGitHash":"6caa093c","userAgent":"couchbase-java/3.0.0-alpha.7 (Mac OS X 10.14.6 x86_64; Java HotSpot(TM) 64-Bit Server VM 1.8.0_221-b11)","seedNodes":[{"address":"10.112.194.101"}],"ioEnvironment":{"nativeIoEnabled":true,"eventLoopGroups":["KQueueEventLoopGroup"]},"ioConfig":{"allowedSaslMechs":["PLAIN","CRAM_MD5","SCRAM_SHA1","SCRAM_SHA256","SCRAM_SHA512"],"captureTraffic":[],"mutationTokensEnabled":true,"networkResolution":"auto","dnsSrvEnabled":false,"configPollIntervalMillis":2500,"kvCircuitBreakerConfig":"disabled","queryCircuitBreakerConfig":"disabled","viewCircuitBreakerConfig":"disabled","searchCircuitBreakerConfig":"disabled","analyticsCircuitBreakerConfig":"disabled","managerCircuitBreakerConfig":"disabled"},"compressionConfig":{"enabled":true,"minRatio":0.83,"minSize":32},"securityConfig":{"tlsEnabled":false,"nativeTlsEnabled":true,"certAuthEnabled":false,"hasTrustCertificates":false,"trustManagerFactory":null},"timeoutConfig":{"kvMs":2500,"managementMs":75000,"queryMs":75000,"viewMs":75000,"searchMs":75000,"analyticsMs":75000,"connectMs":10000,"disconnectMs":10000},"serviceConfig":{"kv":{"min":1,"max":1,"idleTimeMs":0},"query":{"min":0,"max":12,"idleTimeMs":300000},"view":{"min":0,"max":12,"idleTimeMs":300000},"search":{"min":0,"max":12,"idleTimeMs":300000},"analytics":{"min":0,"max":12,"idleTimeMs":300000}},"loggerConfig":{"customLogger":null,"fallbackToConsole":false,"disableSlf4j":false,"loggerName":"CouchbaseLogger","diagnosticContextEnabled":false},"credentials":"UsernameAndPassword","retryStrategy":"BestEffortRetryStrategy"} {"coreId":1}
            Jan 27, 2021 3:43:26 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info
            INFO: [com.couchbase.node][NodeConnectedEvent] Node connected {"coreId":1,"managerPort":"8091","remote":"10.112.194.101"}
            Jan 27, 2021 3:43:26 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info
            INFO: [com.couchbase.core][BucketOpenedEvent][61582µs] Opened bucket "people" {"coreId":1}
            Jan 27, 2021 3:43:26 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info
            INFO: [com.couchbase.transactions.cleanup][TransactionLogEvent] Cleanup settings; regular cleanup thread enabled=true, lost cleanup thread enabled=true
            Jan 27, 2021 3:43:26 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info
            INFO: [com.couchbase.transactions.cleanup.regular][TransactionLogEvent] Starting background cleanup thread to find transactions from this client
            Jan 27, 2021 3:43:26 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info
            INFO: [com.couchbase.transactions][TransactionsStarted] Transactions successfully started, regular cleanup enabled=true, lost cleanup enabled=true
            Jan 27, 2021 3:43:26 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info
            INFO: [com.couchbase.core][BucketOpenedEvent][3920µs] Opened bucket "people" {"coreId":1}
            Jan 27, 2021 3:43:26 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info
            INFO: [com.couchbase.transactions.cleanup.lost][TransactionLogEvent] Client 995bd people/_default creating thread to handle lost transactions
            Transaction failed:
            15:43:26.978 1/main/984f8 starting attempt 0/984f8759-b4b3-42b9-8eaf-78c662b711d1/63d0e5a5-4cc9-4f4d-8d1c-8e3d416d0e46
            15:43:26.978 1/main/984f8 config: atrs=1024, expiry=5000msecs durability=null per-txn config: durability=Optional.empty
            15:43:26.984 1/main/984f8/63d0e getting doc replace:arun
            15:43:26.987 1/main/984f8/63d0e completed get of TransactionGetResult{id=replace:arun,cas=1611791006979063808,status=NORMAL,bucket=people,coll=_default,links=TransactionLinks{atr=none,atrBkt=none,atrColl=none,txnId=none,attemptId=none,op=none,restore={none,none,-1}}} in 3ms
            15:43:26.989 1/main/984f8/63d0e replace doc TransactionGetResult{id=replace:arun,cas=1611791006979063808,status=NORMAL,bucket=people,coll=_default,links=TransactionLinks{atr=none,atrBkt=none,atrColl=none,txnId=none,attemptId=none,op=none,restore={none,none,-1}}}
            15:43:26.989 1/main/984f8/63d0e First mutated doc in txn is 'replace:arun' on vbucket 803, so using atr _txn:atr-803-#80a
            15:43:26.991 1/main/984f8/63d0e about to set ATR people/_default/_txn:atr-803-#80a to Pending
            15:43:26.992 1/main/984f8/63d0e set ATR people/_default/_txn:atr-803-#80a to Pending in 1ms, got CAS (start time) 1611791006975721472
            15:43:26.994 1/main/984f8/63d0e about to replace doc replace:arun with cas 1611791006914838528
            15:43:26.996 1/main/984f8/63d0e replaced doc replace:arun got new cas 1611791006979063808, in 2ms
            15:43:26.997 1/main/984f8/63d0e doing implicit commit
            15:43:26.998 1/main/984f8/63d0e commit AttemptContextReactive{id=63d0e,state=PENDING,isDone=false,atr=_default/_txn:atr-803-#80a,staged=[REPLACE replace:arun]}
            15:43:27.002 1/main/984f8/63d0e about to set ATR people/_default/_txn:atr-803-#80a to Committed
            15:43:27.006 1/main/984f8/63d0e error com.couchbase.transactions.error.internal.AbortedAsRequestedNoRollbackNoCleanup: Faking that txn fails at stage afterCommit while setting ATR people/_default/_txn:atr-803-#80a to Committed
            15:43:27.006 1/main/984f8/<> hit error com.couchbase.transactions.error.internal.AbortedAsRequestedNoRollbackNoCleanup: Faking that txn fails at stage afterCommit
            15:43:27.006 1/main/984f8/<> received non-TransactionException error AbortedAsRequestedNoRollbackNoCleanup, unable to rollback as don't have context
            15:43:27.007 1/main/984f8/<> caught error com.couchbase.transactions.error.internal.AbortedAsRequestedNoRollbackNoCleanup: Faking that txn fails at stage afterCommit, wrapping in TransactionFailed
             
            BUILD SUCCESSFUL in 1s
            2 actionable tasks: 1 executed, 1 up-to-date
            > Task :Main.main()
            Jan 27, 2021 3:44:15 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info
            INFO: [com.couchbase.core][CoreCreatedEvent] {"clientVersion":"3.0.0-alpha.7","clientGitHash":"6caa093c","coreVersion":"2.0.0-alpha.7","coreGitHash":"6caa093c","userAgent":"couchbase-java/3.0.0-alpha.7 (Mac OS X 10.14.6 x86_64; Java HotSpot(TM) 64-Bit Server VM 1.8.0_221-b11)","seedNodes":[{"address":"10.112.194.101"}],"ioEnvironment":{"nativeIoEnabled":true,"eventLoopGroups":["KQueueEventLoopGroup"]},"ioConfig":{"allowedSaslMechs":["PLAIN","CRAM_MD5","SCRAM_SHA1","SCRAM_SHA256","SCRAM_SHA512"],"captureTraffic":[],"mutationTokensEnabled":true,"networkResolution":"auto","dnsSrvEnabled":false,"configPollIntervalMillis":2500,"kvCircuitBreakerConfig":"disabled","queryCircuitBreakerConfig":"disabled","viewCircuitBreakerConfig":"disabled","searchCircuitBreakerConfig":"disabled","analyticsCircuitBreakerConfig":"disabled","managerCircuitBreakerConfig":"disabled"},"compressionConfig":{"enabled":true,"minRatio":0.83,"minSize":32},"securityConfig":{"tlsEnabled":false,"nativeTlsEnabled":true,"certAuthEnabled":false,"hasTrustCertificates":false,"trustManagerFactory":null},"timeoutConfig":{"kvMs":2500,"managementMs":75000,"queryMs":75000,"viewMs":75000,"searchMs":75000,"analyticsMs":75000,"connectMs":10000,"disconnectMs":10000},"serviceConfig":{"kv":{"min":1,"max":1,"idleTimeMs":0},"query":{"min":0,"max":12,"idleTimeMs":300000},"view":{"min":0,"max":12,"idleTimeMs":300000},"search":{"min":0,"max":12,"idleTimeMs":300000},"analytics":{"min":0,"max":12,"idleTimeMs":300000}},"loggerConfig":{"customLogger":null,"fallbackToConsole":false,"disableSlf4j":false,"loggerName":"CouchbaseLogger","diagnosticContextEnabled":false},"credentials":"UsernameAndPassword","retryStrategy":"BestEffortRetryStrategy"} {"coreId":1}
            Jan 27, 2021 3:44:15 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info
            INFO: [com.couchbase.node][NodeConnectedEvent] Node connected {"coreId":1,"managerPort":"8091","remote":"10.112.194.101"}
            Jan 27, 2021 3:44:15 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info
            INFO: [com.couchbase.core][BucketOpenedEvent][60653µs] Opened bucket "people" {"coreId":1}
            Jan 27, 2021 3:44:15 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info
            INFO: [com.couchbase.transactions.cleanup][TransactionLogEvent] Cleanup settings; regular cleanup thread enabled=true, lost cleanup thread enabled=true
            Jan 27, 2021 3:44:15 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info
            INFO: [com.couchbase.transactions.cleanup.regular][TransactionLogEvent] Starting background cleanup thread to find transactions from this client
            Jan 27, 2021 3:44:15 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info
            INFO: [com.couchbase.transactions][TransactionsStarted] Transactions successfully started, regular cleanup enabled=true, lost cleanup enabled=true
            Jan 27, 2021 3:44:15 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info
            INFO: [com.couchbase.core][BucketOpenedEvent][3974µs] Opened bucket "people" {"coreId":1}
            Jan 27, 2021 3:44:15 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info
            INFO: [com.couchbase.transactions.cleanup.lost][TransactionLogEvent] Client 84ec7 people/_default creating thread to handle lost transactions
            Transaction failed:
            15:44:15.619 1/main/d67f8 starting attempt 0/d67f8561-5425-44cd-b13d-940f542912d3/e0d0e6b0-a5a1-4078-8b30-297cfd803760
            15:44:15.619 1/main/d67f8 config: atrs=1024, expiry=5000msecs durability=null per-txn config: durability=Optional.empty
            15:44:15.626 1/main/d67f8/e0d0e getting doc remove:arun
            15:44:15.629 1/main/d67f8/e0d0e completed get of TransactionGetResult{id=remove:arun,cas=1611791055636922368,status=NORMAL,bucket=people,coll=_default,links=TransactionLinks{atr=none,atrBkt=none,atrColl=none,txnId=none,attemptId=none,op=none,restore={none,none,-1}}} in 3ms
            15:44:15.631 1/main/d67f8/e0d0e remove doc remove:arun
            15:44:15.631 1/main/d67f8/e0d0e First mutated doc in txn is 'remove:arun' on vbucket 605, so using atr _txn:atr-605-#b29
            15:44:15.633 1/main/d67f8/e0d0e about to set ATR people/_default/_txn:atr-605-#b29 to Pending
            15:44:15.634 1/main/d67f8/e0d0e set ATR people/_default/_txn:atr-605-#b29 to Pending in 1ms, got CAS (start time) 1611791055632924672
            15:44:15.636 1/main/d67f8/e0d0e about to remove doc remove:arun with cas 1611791055572172800
            15:44:15.637 1/main/d67f8/e0d0e staged remove of doc remove:arun got cas 1611791055636922368, in 1ms
            15:44:15.638 1/main/d67f8/e0d0e doing implicit commit
            15:44:15.639 1/main/d67f8/e0d0e commit AttemptContextReactive{id=e0d0e,state=PENDING,isDone=false,atr=_default/_txn:atr-605-#b29,staged=[REMOVE remove:arun]}
            15:44:15.642 1/main/d67f8/e0d0e about to set ATR people/_default/_txn:atr-605-#b29 to Committed
            15:44:15.645 1/main/d67f8/e0d0e error com.couchbase.transactions.error.internal.AbortedAsRequestedNoRollbackNoCleanup: Faking that txn fails at stage afterCommit while setting ATR people/_default/_txn:atr-605-#b29 to Committed
            15:44:15.646 1/main/d67f8/<> hit error com.couchbase.transactions.error.internal.AbortedAsRequestedNoRollbackNoCleanup: Faking that txn fails at stage afterCommit
            15:44:15.646 1/main/d67f8/<> received non-TransactionException error AbortedAsRequestedNoRollbackNoCleanup, unable to rollback as don't have context
            15:44:15.647 1/main/d67f8/<> caught error com.couchbase.transactions.error.internal.AbortedAsRequestedNoRollbackNoCleanup: Faking that txn fails at stage afterCommit, wrapping in TransactionFailed
             
            BUILD SUCCESSFUL in 1s
            2 actionable tasks: 1 executed, 1 up-to-date
            

            [root@node1-mad-hatter-testing-centos7 ~]# cd /opt/couchbase/bin/
            [root@node1-mad-hatter-testing-centos7 bin]# ./cbbackup -u Administrator -p password http://10.112.194.101:8091 /backup
              [####################] 100.0% (114/estimated 114 msgs)
            bucket: people, msgs transferred...
                   :                total |       last |    per sec
             byte  :                 9749 |       9749 |    13393.3
            2021-01-27 15:45:43,621: mt (0, None)
            done
            [root@node1-mad-hatter-testing-centos7 bin]# ./cbrestore /backup/ http://10.112.194.101:8091 --bucket-source people -u Administrator -p password
            Mid-transaction data have being rolled backed and restored, but transactional atomicity cannot be guaranteed.
              [####################] 100.0% (114/estimated 114 msgs)
            bucket: b'people', msgs transferred...
                   :                total |       last |    per sec
             byte  :                 9749 |       9749 |   156529.8
            done
            [root@node1-mad-hatter-testing-centos7 bin]#
            

            Show
            arunkumar Arunkumar Senthilnathan added a comment - Verified in 6.6.2-9458: > Task :Main.main() Jan 27, 2021 3:40:49 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info INFO: [com.couchbase.core][CoreCreatedEvent] {"clientVersion":"3.0.0-alpha.7","clientGitHash":"6caa093c","coreVersion":"2.0.0-alpha.7","coreGitHash":"6caa093c","userAgent":"couchbase-java/3.0.0-alpha.7 (Mac OS X 10.14.6 x86_64; Java HotSpot(TM) 64-Bit Server VM 1.8.0_221-b11)","seedNodes":[{"address":"10.112.194.101"}],"ioEnvironment":{"nativeIoEnabled":true,"eventLoopGroups":["KQueueEventLoopGroup"]},"ioConfig":{"allowedSaslMechs":["PLAIN","CRAM_MD5","SCRAM_SHA1","SCRAM_SHA256","SCRAM_SHA512"],"captureTraffic":[],"mutationTokensEnabled":true,"networkResolution":"auto","dnsSrvEnabled":false,"configPollIntervalMillis":2500,"kvCircuitBreakerConfig":"disabled","queryCircuitBreakerConfig":"disabled","viewCircuitBreakerConfig":"disabled","searchCircuitBreakerConfig":"disabled","analyticsCircuitBreakerConfig":"disabled","managerCircuitBreakerConfig":"disabled"},"compressionConfig":{"enabled":true,"minRatio":0.83,"minSize":32},"securityConfig":{"tlsEnabled":false,"nativeTlsEnabled":true,"certAuthEnabled":false,"hasTrustCertificates":false,"trustManagerFactory":null},"timeoutConfig":{"kvMs":2500,"managementMs":75000,"queryMs":75000,"viewMs":75000,"searchMs":75000,"analyticsMs":75000,"connectMs":10000,"disconnectMs":10000},"serviceConfig":{"kv":{"min":1,"max":1,"idleTimeMs":0},"query":{"min":0,"max":12,"idleTimeMs":300000},"view":{"min":0,"max":12,"idleTimeMs":300000},"search":{"min":0,"max":12,"idleTimeMs":300000},"analytics":{"min":0,"max":12,"idleTimeMs":300000}},"loggerConfig":{"customLogger":null,"fallbackToConsole":false,"disableSlf4j":false,"loggerName":"CouchbaseLogger","diagnosticContextEnabled":false},"credentials":"UsernameAndPassword","retryStrategy":"BestEffortRetryStrategy"} {"coreId":1} Jan 27, 2021 3:40:49 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info INFO: [com.couchbase.node][NodeConnectedEvent] Node connected {"coreId":1,"managerPort":"8091","remote":"10.112.194.101"} Jan 27, 2021 3:40:50 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info INFO: [com.couchbase.core][BucketOpenedEvent][162319µs] Opened bucket "people" {"coreId":1} Jan 27, 2021 3:40:50 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info INFO: [com.couchbase.transactions.cleanup][TransactionLogEvent] Cleanup settings; regular cleanup thread enabled=true, lost cleanup thread enabled=true Jan 27, 2021 3:40:50 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info INFO: [com.couchbase.transactions.cleanup.regular][TransactionLogEvent] Starting background cleanup thread to find transactions from this client Jan 27, 2021 3:40:50 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info INFO: [com.couchbase.transactions][TransactionsStarted] Transactions successfully started, regular cleanup enabled=true, lost cleanup enabled=true Jan 27, 2021 3:40:50 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info INFO: [com.couchbase.core][BucketOpenedEvent][3709µs] Opened bucket "people" {"coreId":1} Jan 27, 2021 3:40:50 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info INFO: [com.couchbase.transactions.cleanup.lost][TransactionLogEvent] Client d5bc0 people/_default creating thread to handle lost transactions Transaction failed: 15:40:50.224 1/main/e4394 starting attempt 0/e4394006-ca16-428e-8076-7c356727836a/01331a6e-75bf-4cd8-ac61-6da639c5d8cc 15:40:50.224 1/main/e4394 config: atrs=1024, expiry=5000msecs durability=null per-txn config: durability=Optional.empty 15:40:50.233 1/main/e4394/01331 First mutated doc in txn is 'insert:arun' on vbucket 621, so using atr _txn:atr-621-#1b88 15:40:50.235 1/main/e4394/01331 about to set ATR people/_default/_txn:atr-621-#1b88 to Pending 15:40:50.237 1/main/e4394/01331 set ATR people/_default/_txn:atr-621-#1b88 to Pending in 2ms, got CAS (start time) 1611790850223112192 15:40:50.240 1/main/e4394/01331 about to insert staged doc insert:arun 15:40:50.242 1/main/e4394/01331 inserted doc insert:arun got cas 1611790850226913280, in 2ms 15:40:50.242 1/main/e4394/01331 doing implicit commit 15:40:50.243 1/main/e4394/01331 commit AttemptContextReactive{id=01331,state=PENDING,isDone=false,atr=_default/_txn:atr-621-#1b88,staged=[INSERT insert:arun]} 15:40:50.247 1/main/e4394/01331 about to set ATR people/_default/_txn:atr-621-#1b88 to Committed 15:40:50.249 1/main/e4394/01331 error com.couchbase.transactions.error.internal.AbortedAsRequestedNoRollbackNoCleanup: Faking that txn fails at stage afterCommit while setting ATR people/_default/_txn:atr-621-#1b88 to Committed 15:40:50.250 1/main/e4394/<> hit error com.couchbase.transactions.error.internal.AbortedAsRequestedNoRollbackNoCleanup: Faking that txn fails at stage afterCommit 15:40:50.250 1/main/e4394/<> received non-TransactionException error AbortedAsRequestedNoRollbackNoCleanup, unable to rollback as don't have context 15:40:50.251 1/main/e4394/<> caught error com.couchbase.transactions.error.internal.AbortedAsRequestedNoRollbackNoCleanup: Faking that txn fails at stage afterCommit, wrapping in TransactionFailed   BUILD SUCCESSFUL in 1s 2 actionable tasks: 1 executed, 1 up-to-date 15:40:50: Task execution finished 'Main.main()'. > Task :Main.main() Jan 27, 2021 3:42:51 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info INFO: [com.couchbase.core][CoreCreatedEvent] {"clientVersion":"3.0.0-alpha.7","clientGitHash":"6caa093c","coreVersion":"2.0.0-alpha.7","coreGitHash":"6caa093c","userAgent":"couchbase-java/3.0.0-alpha.7 (Mac OS X 10.14.6 x86_64; Java HotSpot(TM) 64-Bit Server VM 1.8.0_221-b11)","seedNodes":[{"address":"10.112.194.101"}],"ioEnvironment":{"nativeIoEnabled":true,"eventLoopGroups":["KQueueEventLoopGroup"]},"ioConfig":{"allowedSaslMechs":["PLAIN","CRAM_MD5","SCRAM_SHA1","SCRAM_SHA256","SCRAM_SHA512"],"captureTraffic":[],"mutationTokensEnabled":true,"networkResolution":"auto","dnsSrvEnabled":false,"configPollIntervalMillis":2500,"kvCircuitBreakerConfig":"disabled","queryCircuitBreakerConfig":"disabled","viewCircuitBreakerConfig":"disabled","searchCircuitBreakerConfig":"disabled","analyticsCircuitBreakerConfig":"disabled","managerCircuitBreakerConfig":"disabled"},"compressionConfig":{"enabled":true,"minRatio":0.83,"minSize":32},"securityConfig":{"tlsEnabled":false,"nativeTlsEnabled":true,"certAuthEnabled":false,"hasTrustCertificates":false,"trustManagerFactory":null},"timeoutConfig":{"kvMs":2500,"managementMs":75000,"queryMs":75000,"viewMs":75000,"searchMs":75000,"analyticsMs":75000,"connectMs":10000,"disconnectMs":10000},"serviceConfig":{"kv":{"min":1,"max":1,"idleTimeMs":0},"query":{"min":0,"max":12,"idleTimeMs":300000},"view":{"min":0,"max":12,"idleTimeMs":300000},"search":{"min":0,"max":12,"idleTimeMs":300000},"analytics":{"min":0,"max":12,"idleTimeMs":300000}},"loggerConfig":{"customLogger":null,"fallbackToConsole":false,"disableSlf4j":false,"loggerName":"CouchbaseLogger","diagnosticContextEnabled":false},"credentials":"UsernameAndPassword","retryStrategy":"BestEffortRetryStrategy"} {"coreId":1} Jan 27, 2021 3:42:51 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info INFO: [com.couchbase.node][NodeConnectedEvent] Node connected {"coreId":1,"managerPort":"8091","remote":"10.112.194.101"} Jan 27, 2021 3:42:51 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info INFO: [com.couchbase.core][BucketOpenedEvent][65557µs] Opened bucket "people" {"coreId":1} Jan 27, 2021 3:42:51 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info INFO: [com.couchbase.transactions.cleanup][TransactionLogEvent] Cleanup settings; regular cleanup thread enabled=true, lost cleanup thread enabled=true Jan 27, 2021 3:42:51 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info INFO: [com.couchbase.transactions.cleanup.regular][TransactionLogEvent] Starting background cleanup thread to find transactions from this client Jan 27, 2021 3:42:51 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info INFO: [com.couchbase.transactions][TransactionsStarted] Transactions successfully started, regular cleanup enabled=true, lost cleanup enabled=true Jan 27, 2021 3:42:51 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info INFO: [com.couchbase.core][BucketOpenedEvent][3817µs] Opened bucket "people" {"coreId":1} Jan 27, 2021 3:42:51 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info INFO: [com.couchbase.transactions.cleanup.lost][TransactionLogEvent] Client 55593 people/_default creating thread to handle lost transactions Transaction failed: 15:42:51.832 1/main/5701c starting attempt 0/5701cc82-2976-4d17-b3dc-fb9fce046f03/74670108-3ad5-4fec-9947-44510bdf6adb 15:42:51.832 1/main/5701c config: atrs=1024, expiry=5000msecs durability=null per-txn config: durability=Optional.empty 15:42:51.840 1/main/5701c/74670 getting doc xattrs:arun 15:42:51.843 1/main/5701c/74670 completed get of TransactionGetResult{id=xattrs:arun,cas=1611790971836366848,status=NORMAL,bucket=people,coll=_default,links=TransactionLinks{atr=none,atrBkt=none,atrColl=none,txnId=none,attemptId=none,op=none,restore={none,none,-1}}} in 3ms 15:42:51.844 1/main/5701c/74670 replace doc TransactionGetResult{id=xattrs:arun,cas=1611790971836366848,status=NORMAL,bucket=people,coll=_default,links=TransactionLinks{atr=none,atrBkt=none,atrColl=none,txnId=none,attemptId=none,op=none,restore={none,none,-1}}} 15:42:51.845 1/main/5701c/74670 First mutated doc in txn is 'xattrs:arun' on vbucket 363, so using atr _txn:atr-363-#203 15:42:51.847 1/main/5701c/74670 about to set ATR people/_default/_txn:atr-363-#203 to Pending 15:42:51.848 1/main/5701c/74670 set ATR people/_default/_txn:atr-363-#203 to Pending in 1ms, got CAS (start time) 1611790971832762368 15:42:51.851 1/main/5701c/74670 about to replace doc xattrs:arun with cas 1611790971798683648 15:42:51.853 1/main/5701c/74670 replaced doc xattrs:arun got new cas 1611790971836366848, in 1ms 15:42:51.854 1/main/5701c/74670 doing implicit commit 15:42:51.855 1/main/5701c/74670 commit AttemptContextReactive{id=74670,state=PENDING,isDone=false,atr=_default/_txn:atr-363-#203,staged=[REPLACE xattrs:arun]} 15:42:51.859 1/main/5701c/74670 about to set ATR people/_default/_txn:atr-363-#203 to Committed 15:42:51.862 1/main/5701c/74670 error com.couchbase.transactions.error.internal.AbortedAsRequestedNoRollbackNoCleanup: Faking that txn fails at stage afterCommit while setting ATR people/_default/_txn:atr-363-#203 to Committed 15:42:51.863 1/main/5701c/<> hit error com.couchbase.transactions.error.internal.AbortedAsRequestedNoRollbackNoCleanup: Faking that txn fails at stage afterCommit 15:42:51.863 1/main/5701c/<> received non-TransactionException error AbortedAsRequestedNoRollbackNoCleanup, unable to rollback as don't have context 15:42:51.863 1/main/5701c/<> caught error com.couchbase.transactions.error.internal.AbortedAsRequestedNoRollbackNoCleanup: Faking that txn fails at stage afterCommit, wrapping in TransactionFailed   BUILD SUCCESSFUL in 1s 2 actionable tasks: 1 executed, 1 up-to-date 15:42:52: Task execution finished 'Main.main()'. > Task :Main.main() Jan 27, 2021 3:43:26 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info INFO: [com.couchbase.core][CoreCreatedEvent] {"clientVersion":"3.0.0-alpha.7","clientGitHash":"6caa093c","coreVersion":"2.0.0-alpha.7","coreGitHash":"6caa093c","userAgent":"couchbase-java/3.0.0-alpha.7 (Mac OS X 10.14.6 x86_64; Java HotSpot(TM) 64-Bit Server VM 1.8.0_221-b11)","seedNodes":[{"address":"10.112.194.101"}],"ioEnvironment":{"nativeIoEnabled":true,"eventLoopGroups":["KQueueEventLoopGroup"]},"ioConfig":{"allowedSaslMechs":["PLAIN","CRAM_MD5","SCRAM_SHA1","SCRAM_SHA256","SCRAM_SHA512"],"captureTraffic":[],"mutationTokensEnabled":true,"networkResolution":"auto","dnsSrvEnabled":false,"configPollIntervalMillis":2500,"kvCircuitBreakerConfig":"disabled","queryCircuitBreakerConfig":"disabled","viewCircuitBreakerConfig":"disabled","searchCircuitBreakerConfig":"disabled","analyticsCircuitBreakerConfig":"disabled","managerCircuitBreakerConfig":"disabled"},"compressionConfig":{"enabled":true,"minRatio":0.83,"minSize":32},"securityConfig":{"tlsEnabled":false,"nativeTlsEnabled":true,"certAuthEnabled":false,"hasTrustCertificates":false,"trustManagerFactory":null},"timeoutConfig":{"kvMs":2500,"managementMs":75000,"queryMs":75000,"viewMs":75000,"searchMs":75000,"analyticsMs":75000,"connectMs":10000,"disconnectMs":10000},"serviceConfig":{"kv":{"min":1,"max":1,"idleTimeMs":0},"query":{"min":0,"max":12,"idleTimeMs":300000},"view":{"min":0,"max":12,"idleTimeMs":300000},"search":{"min":0,"max":12,"idleTimeMs":300000},"analytics":{"min":0,"max":12,"idleTimeMs":300000}},"loggerConfig":{"customLogger":null,"fallbackToConsole":false,"disableSlf4j":false,"loggerName":"CouchbaseLogger","diagnosticContextEnabled":false},"credentials":"UsernameAndPassword","retryStrategy":"BestEffortRetryStrategy"} {"coreId":1} Jan 27, 2021 3:43:26 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info INFO: [com.couchbase.node][NodeConnectedEvent] Node connected {"coreId":1,"managerPort":"8091","remote":"10.112.194.101"} Jan 27, 2021 3:43:26 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info INFO: [com.couchbase.core][BucketOpenedEvent][61582µs] Opened bucket "people" {"coreId":1} Jan 27, 2021 3:43:26 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info INFO: [com.couchbase.transactions.cleanup][TransactionLogEvent] Cleanup settings; regular cleanup thread enabled=true, lost cleanup thread enabled=true Jan 27, 2021 3:43:26 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info INFO: [com.couchbase.transactions.cleanup.regular][TransactionLogEvent] Starting background cleanup thread to find transactions from this client Jan 27, 2021 3:43:26 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info INFO: [com.couchbase.transactions][TransactionsStarted] Transactions successfully started, regular cleanup enabled=true, lost cleanup enabled=true Jan 27, 2021 3:43:26 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info INFO: [com.couchbase.core][BucketOpenedEvent][3920µs] Opened bucket "people" {"coreId":1} Jan 27, 2021 3:43:26 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info INFO: [com.couchbase.transactions.cleanup.lost][TransactionLogEvent] Client 995bd people/_default creating thread to handle lost transactions Transaction failed: 15:43:26.978 1/main/984f8 starting attempt 0/984f8759-b4b3-42b9-8eaf-78c662b711d1/63d0e5a5-4cc9-4f4d-8d1c-8e3d416d0e46 15:43:26.978 1/main/984f8 config: atrs=1024, expiry=5000msecs durability=null per-txn config: durability=Optional.empty 15:43:26.984 1/main/984f8/63d0e getting doc replace:arun 15:43:26.987 1/main/984f8/63d0e completed get of TransactionGetResult{id=replace:arun,cas=1611791006979063808,status=NORMAL,bucket=people,coll=_default,links=TransactionLinks{atr=none,atrBkt=none,atrColl=none,txnId=none,attemptId=none,op=none,restore={none,none,-1}}} in 3ms 15:43:26.989 1/main/984f8/63d0e replace doc TransactionGetResult{id=replace:arun,cas=1611791006979063808,status=NORMAL,bucket=people,coll=_default,links=TransactionLinks{atr=none,atrBkt=none,atrColl=none,txnId=none,attemptId=none,op=none,restore={none,none,-1}}} 15:43:26.989 1/main/984f8/63d0e First mutated doc in txn is 'replace:arun' on vbucket 803, so using atr _txn:atr-803-#80a 15:43:26.991 1/main/984f8/63d0e about to set ATR people/_default/_txn:atr-803-#80a to Pending 15:43:26.992 1/main/984f8/63d0e set ATR people/_default/_txn:atr-803-#80a to Pending in 1ms, got CAS (start time) 1611791006975721472 15:43:26.994 1/main/984f8/63d0e about to replace doc replace:arun with cas 1611791006914838528 15:43:26.996 1/main/984f8/63d0e replaced doc replace:arun got new cas 1611791006979063808, in 2ms 15:43:26.997 1/main/984f8/63d0e doing implicit commit 15:43:26.998 1/main/984f8/63d0e commit AttemptContextReactive{id=63d0e,state=PENDING,isDone=false,atr=_default/_txn:atr-803-#80a,staged=[REPLACE replace:arun]} 15:43:27.002 1/main/984f8/63d0e about to set ATR people/_default/_txn:atr-803-#80a to Committed 15:43:27.006 1/main/984f8/63d0e error com.couchbase.transactions.error.internal.AbortedAsRequestedNoRollbackNoCleanup: Faking that txn fails at stage afterCommit while setting ATR people/_default/_txn:atr-803-#80a to Committed 15:43:27.006 1/main/984f8/<> hit error com.couchbase.transactions.error.internal.AbortedAsRequestedNoRollbackNoCleanup: Faking that txn fails at stage afterCommit 15:43:27.006 1/main/984f8/<> received non-TransactionException error AbortedAsRequestedNoRollbackNoCleanup, unable to rollback as don't have context 15:43:27.007 1/main/984f8/<> caught error com.couchbase.transactions.error.internal.AbortedAsRequestedNoRollbackNoCleanup: Faking that txn fails at stage afterCommit, wrapping in TransactionFailed   BUILD SUCCESSFUL in 1s 2 actionable tasks: 1 executed, 1 up-to-date > Task :Main.main() Jan 27, 2021 3:44:15 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info INFO: [com.couchbase.core][CoreCreatedEvent] {"clientVersion":"3.0.0-alpha.7","clientGitHash":"6caa093c","coreVersion":"2.0.0-alpha.7","coreGitHash":"6caa093c","userAgent":"couchbase-java/3.0.0-alpha.7 (Mac OS X 10.14.6 x86_64; Java HotSpot(TM) 64-Bit Server VM 1.8.0_221-b11)","seedNodes":[{"address":"10.112.194.101"}],"ioEnvironment":{"nativeIoEnabled":true,"eventLoopGroups":["KQueueEventLoopGroup"]},"ioConfig":{"allowedSaslMechs":["PLAIN","CRAM_MD5","SCRAM_SHA1","SCRAM_SHA256","SCRAM_SHA512"],"captureTraffic":[],"mutationTokensEnabled":true,"networkResolution":"auto","dnsSrvEnabled":false,"configPollIntervalMillis":2500,"kvCircuitBreakerConfig":"disabled","queryCircuitBreakerConfig":"disabled","viewCircuitBreakerConfig":"disabled","searchCircuitBreakerConfig":"disabled","analyticsCircuitBreakerConfig":"disabled","managerCircuitBreakerConfig":"disabled"},"compressionConfig":{"enabled":true,"minRatio":0.83,"minSize":32},"securityConfig":{"tlsEnabled":false,"nativeTlsEnabled":true,"certAuthEnabled":false,"hasTrustCertificates":false,"trustManagerFactory":null},"timeoutConfig":{"kvMs":2500,"managementMs":75000,"queryMs":75000,"viewMs":75000,"searchMs":75000,"analyticsMs":75000,"connectMs":10000,"disconnectMs":10000},"serviceConfig":{"kv":{"min":1,"max":1,"idleTimeMs":0},"query":{"min":0,"max":12,"idleTimeMs":300000},"view":{"min":0,"max":12,"idleTimeMs":300000},"search":{"min":0,"max":12,"idleTimeMs":300000},"analytics":{"min":0,"max":12,"idleTimeMs":300000}},"loggerConfig":{"customLogger":null,"fallbackToConsole":false,"disableSlf4j":false,"loggerName":"CouchbaseLogger","diagnosticContextEnabled":false},"credentials":"UsernameAndPassword","retryStrategy":"BestEffortRetryStrategy"} {"coreId":1} Jan 27, 2021 3:44:15 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info INFO: [com.couchbase.node][NodeConnectedEvent] Node connected {"coreId":1,"managerPort":"8091","remote":"10.112.194.101"} Jan 27, 2021 3:44:15 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info INFO: [com.couchbase.core][BucketOpenedEvent][60653µs] Opened bucket "people" {"coreId":1} Jan 27, 2021 3:44:15 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info INFO: [com.couchbase.transactions.cleanup][TransactionLogEvent] Cleanup settings; regular cleanup thread enabled=true, lost cleanup thread enabled=true Jan 27, 2021 3:44:15 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info INFO: [com.couchbase.transactions.cleanup.regular][TransactionLogEvent] Starting background cleanup thread to find transactions from this client Jan 27, 2021 3:44:15 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info INFO: [com.couchbase.transactions][TransactionsStarted] Transactions successfully started, regular cleanup enabled=true, lost cleanup enabled=true Jan 27, 2021 3:44:15 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info INFO: [com.couchbase.core][BucketOpenedEvent][3974µs] Opened bucket "people" {"coreId":1} Jan 27, 2021 3:44:15 PM com.couchbase.client.core.cnc.LoggingEventConsumer$JdkLogger info INFO: [com.couchbase.transactions.cleanup.lost][TransactionLogEvent] Client 84ec7 people/_default creating thread to handle lost transactions Transaction failed: 15:44:15.619 1/main/d67f8 starting attempt 0/d67f8561-5425-44cd-b13d-940f542912d3/e0d0e6b0-a5a1-4078-8b30-297cfd803760 15:44:15.619 1/main/d67f8 config: atrs=1024, expiry=5000msecs durability=null per-txn config: durability=Optional.empty 15:44:15.626 1/main/d67f8/e0d0e getting doc remove:arun 15:44:15.629 1/main/d67f8/e0d0e completed get of TransactionGetResult{id=remove:arun,cas=1611791055636922368,status=NORMAL,bucket=people,coll=_default,links=TransactionLinks{atr=none,atrBkt=none,atrColl=none,txnId=none,attemptId=none,op=none,restore={none,none,-1}}} in 3ms 15:44:15.631 1/main/d67f8/e0d0e remove doc remove:arun 15:44:15.631 1/main/d67f8/e0d0e First mutated doc in txn is 'remove:arun' on vbucket 605, so using atr _txn:atr-605-#b29 15:44:15.633 1/main/d67f8/e0d0e about to set ATR people/_default/_txn:atr-605-#b29 to Pending 15:44:15.634 1/main/d67f8/e0d0e set ATR people/_default/_txn:atr-605-#b29 to Pending in 1ms, got CAS (start time) 1611791055632924672 15:44:15.636 1/main/d67f8/e0d0e about to remove doc remove:arun with cas 1611791055572172800 15:44:15.637 1/main/d67f8/e0d0e staged remove of doc remove:arun got cas 1611791055636922368, in 1ms 15:44:15.638 1/main/d67f8/e0d0e doing implicit commit 15:44:15.639 1/main/d67f8/e0d0e commit AttemptContextReactive{id=e0d0e,state=PENDING,isDone=false,atr=_default/_txn:atr-605-#b29,staged=[REMOVE remove:arun]} 15:44:15.642 1/main/d67f8/e0d0e about to set ATR people/_default/_txn:atr-605-#b29 to Committed 15:44:15.645 1/main/d67f8/e0d0e error com.couchbase.transactions.error.internal.AbortedAsRequestedNoRollbackNoCleanup: Faking that txn fails at stage afterCommit while setting ATR people/_default/_txn:atr-605-#b29 to Committed 15:44:15.646 1/main/d67f8/<> hit error com.couchbase.transactions.error.internal.AbortedAsRequestedNoRollbackNoCleanup: Faking that txn fails at stage afterCommit 15:44:15.646 1/main/d67f8/<> received non-TransactionException error AbortedAsRequestedNoRollbackNoCleanup, unable to rollback as don't have context 15:44:15.647 1/main/d67f8/<> caught error com.couchbase.transactions.error.internal.AbortedAsRequestedNoRollbackNoCleanup: Faking that txn fails at stage afterCommit, wrapping in TransactionFailed   BUILD SUCCESSFUL in 1s 2 actionable tasks: 1 executed, 1 up-to-date [root@node1-mad-hatter-testing-centos7 ~]# cd /opt/couchbase/bin/ [root@node1-mad-hatter-testing-centos7 bin]# ./cbbackup -u Administrator -p password http://10.112.194.101:8091 /backup [####################] 100.0% (114/estimated 114 msgs) bucket: people, msgs transferred... : total | last | per sec byte : 9749 | 9749 | 13393.3 2021-01-27 15:45:43,621: mt (0, None) done [root@node1-mad-hatter-testing-centos7 bin]# ./cbrestore /backup/ http://10.112.194.101:8091 --bucket-source people -u Administrator -p password Mid-transaction data have being rolled backed and restored, but transactional atomicity cannot be guaranteed. [####################] 100.0% (114/estimated 114 msgs) bucket: b'people', msgs transferred... : total | last | per sec byte : 9749 | 9749 | 156529.8 done [root@node1-mad-hatter-testing-centos7 bin]#
            Hide
            owend Daniel Owen added a comment -

            Hi Carlos Gonzalez Betancort Could you add a release note? thanks

            Show
            owend Daniel Owen added a comment - Hi Carlos Gonzalez Betancort Could you add a release note? thanks
            Hide
            carlos.gonzalez Carlos Gonzalez Betancort added a comment - - edited

            Description for release notes:
            Summary: Fix an edge case where restore would fail when transactions were being used.

            Show
            carlos.gonzalez Carlos Gonzalez Betancort added a comment - - edited Description for release notes: Summary: Fix an edge case where restore would fail when transactions were being used.

              People

              Assignee:
              carlos.gonzalez Carlos Gonzalez Betancort
              Reporter:
              carlos.gonzalez Carlos Gonzalez Betancort
              Votes:
              0 Vote for this issue
              Watchers:
              5 Start watching this issue

                Dates

                Created:
                Updated:
                Resolved:

                  Gerrit Reviews

                  There are no open Gerrit changes

                    PagerDuty