Details
-
Bug
-
Status: Closed
-
Major
-
Resolution: Fixed
-
6.5.0, Cheshire-Cat, 6.5.1, 6.6.1
-
Untriaged
-
1
-
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
- Stand up a cluster and create a bucket
- Load 100 documents to the bucket
- Add some mid-transaction documents see the attachment for a script that does this (the run.sh)
- Load another 100 documets to the bucket
- Do a backup with cbbackup
- Do a restore with cbrestore
Attachments
Issue Links
- is caused by
-
-
- Closed
-
Activity
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]#
|
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]#
|
Description for release notes:
Summary: Fix an edge case where restore would fail when transactions were being used.
Build couchbase-server-7.0.0-4252 contains couchbase-cli commit 3210cf8 with commit message:
MB-42967Fix opaque verification when TXNs are filtered