[CX] Intermittent failure in ClusterRebalanceIT rebalance_MB-27650

2021-01-28T17:01:44.678-08:00 WARN TestMethodTracer [main] ### test[ClusterRebalanceIT 9: rebalance: rebalance_MB-27650] START

2021-01-28T17:01:44.701-08:00 INFO TestExecutor [main] Starting [TEST]: rebalance/rebalance_MB-27650 ... 

2021-01-28T17:01:44.701-08:00 INFO ClusterExecutionITBase [main] starting cluster_run

2021-01-28T17:01:57.227-08:00 INFO ClusterExecutionITBase [main] Running cli: ip-family -c 172.18.0.3:9000 -u couchbase -p couchbase --get

2021-01-28T17:01:57.425-08:00 INFO ClusterExecutionITBase [main+] >> Cluster using ipv4

2021-01-28T17:01:57.447-08:00 INFO ClusterExecutionITBase [main] requested address family IPV4 already configured for cluster at 172.18.0.3:9000

2021-01-28T17:01:57.449-08:00 INFO ClusterExecutionITBase [pool] +http://172.18.0.3:9000/node/controller/rename

2021-01-28T17:01:57.655-08:00 INFO ClusterExecutionITBase [main] cluster is running

2021-01-28T17:01:57.655-08:00 INFO ClusterExecutionITBase [pool] configuring cluster with services: [DATA]

2021-01-28T17:01:57.656-08:00 INFO ClusterExecutionITBase [pool] Running cli: node-init -c 172.18.0.3:9000 -u couchbase -p couchbase --node-init-data-path /home/couchbase/jenkins/workspace/cbas-cbcluster-test2/ns_server/data/n_0/datadir --node-init-index-path /home/couchbase/jenkins/workspace/cbas-cbcluster-test2/ns_server/data/n_0/datadir --ipv4 --node-init-analytics-path /home/couchbase/jenkins/workspace/cbas-cbcluster-test2/ns_server/data/n_0/datadir --node-init-hostname 172.18.0.3

2021-01-28T17:01:57.942-08:00 INFO ClusterExecutionITBase [pool+] >> SUCCESS: Node initialized

2021-01-28T17:01:57.972-08:00 INFO ClusterExecutionITBase [pool] Running cli: cluster-init --cluster-username couchbase --cluster-password couchbase -c 172.18.0.3:9000 --services data --cluster-analytics-ramsize 3072 --cluster-ramsize 3072

2021-01-28T17:01:58.342-08:00 INFO ClusterExecutionITBase [pool+] >> SUCCESS: Cluster initialized

2021-01-28T17:01:58.380-08:00 INFO ClusterExecutionITBase [main] state: [0], nodes: {{DATA},{},{},{}}, cbas node count: 0

2021-01-28T17:01:58.416-08:00 INFO ClusterExecutionITBase [main] Updating node name for n_0 to 0ac2c75b5e666c2912aa8512f71fbea6

2021-01-28T17:01:58.417-08:00 INFO KvStoreHttpHelper [main] installing sample(s): [beer-sample] on 172.18.0.3:9000

2021-01-28T17:02:04.503-08:00 INFO ClusterExecutionITBase [main] Rebalancing from [0] to [0]

2021-01-28T17:02:04.512-08:00 INFO ClusterExecutionITBase [main] Nothing to do, requested topology already in place: [0]

2021-01-28T17:02:04.512-08:00 INFO ClusterExecutionITBase [main] Rebalancing from [0] to [0, 1, 2, 3]

2021-01-28T17:02:04.518-08:00 INFO ClusterExecutionITBase [main] ensuring joining nodes ([[1, 2, 3]]) are fully removed

2021-01-28T17:02:04.526-08:00 INFO ClusterExecutionITBase [main] ensured joining nodes are fully removed (failures: [])

2021-01-28T17:02:04.526-08:00 INFO ClusterExecutionITBase [main]   adding node(s) [1, 2, 3] with service(s): [ANALYTICS]

2021-01-28T17:02:04.527-08:00 INFO ClusterExecutionITBase [main -> init n_2] Running cli: node-init -c 172.18.0.3:9002 -u couchbase -p couchbase --node-init-data-path /home/couchbase/jenkins/workspace/cbas-cbcluster-test2/ns_server/data/n_2/datadir --node-init-index-path /home/couchbase/jenkins/workspace/cbas-cbcluster-test2/ns_server/data/n_2/datadir --ipv4 --node-init-hostname 172.18.0.3 --node-init-analytics-path /home/couchbase/jenkins/workspace/cbas-cbcluster-test2/ns_server/data/n_2/datadir

2021-01-28T17:02:04.527-08:00 INFO ClusterExecutionITBase [main -> init n_1] Running cli: node-init -c 172.18.0.3:9001 -u couchbase -p couchbase --node-init-data-path /home/couchbase/jenkins/workspace/cbas-cbcluster-test2/ns_server/data/n_1/datadir --node-init-index-path /home/couchbase/jenkins/workspace/cbas-cbcluster-test2/ns_server/data/n_1/datadir --ipv4 --node-init-hostname 172.18.0.3 --node-init-analytics-path /home/couchbase/jenkins/workspace/cbas-cbcluster-test2/ns_server/data/n_1/datadir

2021-01-28T17:02:04.527-08:00 INFO ClusterExecutionITBase [main -> init n_3] Running cli: node-init -c 172.18.0.3:9003 -u couchbase -p couchbase --node-init-data-path /home/couchbase/jenkins/workspace/cbas-cbcluster-test2/ns_server/data/n_3/datadir --node-init-index-path /home/couchbase/jenkins/workspace/cbas-cbcluster-test2/ns_server/data/n_3/datadir --ipv4 --node-init-hostname 172.18.0.3 --node-init-analytics-path /home/couchbase/jenkins/workspace/cbas-cbcluster-test2/ns_server/data/n_3/datadir

2021-01-28T17:02:05.341-08:00 INFO ClusterExecutionITBase [main -> init n_3+] >> SUCCESS: Node initialized

2021-01-28T17:02:05.456-08:00 INFO ClusterExecutionITBase [main -> init n_1+] >> SUCCESS: Node initialized

2021-01-28T17:02:05.549-08:00 INFO ClusterExecutionITBase [main -> init n_2+] >> SUCCESS: Node initialized

2021-01-28T17:02:05.634-08:00 INFO ClusterExecutionITBase [main] Running cli: server-add -c 172.18.0.3:9000 -u couchbase -p couchbase --server-add http://172.18.0.3:9003,http://172.18.0.3:9001,http://172.18.0.3:9002 --server-add-username couchbase --server-add-password couchbase --services analytics

2021-01-28T17:02:17.456-08:00 INFO ClusterExecutionITBase [main+] >> SUCCESS: Server added

2021-01-28T17:02:17.489-08:00 INFO ClusterExecutionITBase [main] Updating node name for n_1 to 1c5d5951c1c16daf80f65792c8337139

2021-01-28T17:02:17.489-08:00 INFO ClusterExecutionITBase [main] Updating node name for n_2 to 050e1dbb72a88b68aa95daed6e474b40

2021-01-28T17:02:17.489-08:00 INFO ClusterExecutionITBase [main] Updating node name for n_3 to 05859c709af2d46da91f1c6f8c9d0022

2021-01-28T17:02:17.490-08:00 INFO ClusterExecutionITBase [main]   calling rebalance with following args: [rebalance, -c, 172.18.0.3:9000, -u, couchbase, -p, couchbase]

2021-01-28T17:02:17.490-08:00 INFO ClusterExecutionITBase [main] Running cli: rebalance -c 172.18.0.3:9000 -u couchbase -p couchbase

2021-01-28T17:02:19.857-08:00 INFO ClusterExecutionITBase [main+] >> Unable to display progress bar on this os

2021-01-28T17:02:19.858-08:00 INFO ClusterExecutionITBase [main+] >> SUCCESS: Rebalance complete

2021-01-28T17:02:19.897-08:00 INFO ClusterExecutionITBase [main] state: [0, 1, 2, 3], nodes: {{DATA},{ANALYTICS},{ANALYTICS},{ANALYTICS}}, cbas node count: 3

2021-01-28T17:02:19.897-08:00 INFO ClusterExecutionITBase [assertCbasNodesActive-36-172.18.0.3:9630] Waiting for NCs == 3 & Cluster state in {ACTIVE} for up to 120s...

2021-01-28T17:02:19.898-08:00 INFO ClusterExecutionITBase [assertCbasNodesActive-36-172.18.0.3:9615] Waiting for NCs == 3 & Cluster state in {ACTIVE} for up to 120s...

2021-01-28T17:02:19.898-08:00 INFO ClusterExecutionITBase [assertCbasNodesActive-36-172.18.0.3:9645] Waiting for NCs == 3 & Cluster state in {ACTIVE} for up to 120s...

2021-01-28T17:02:34.753-08:00 INFO TestExecutor [main] Executing test file: rebalance_MB-27650.2.ddl.sqlpp 

2021-01-28T17:02:40.079-08:00 INFO TestExecutor [main] Executing test file: rebalance_MB-27650.3.update.sqlpp 

2021-01-28T17:02:41.548-08:00 INFO TestExecutor [pool-209-thread-1] Expected results file: src/test/resources/runtimets/results/rebalance/rebalance_MB-27650/rebalance_MB-27650.3.adm 

2021-01-28T17:02:41.549-08:00 INFO TestExecutor [pool-209-thread-1] Actual results file: target/rttest/results/rebalance/rebalance_MB-27650/rebalance_MB-27650.3.adm

2021-01-28T17:02:41.549-08:00 INFO TestExecutor [main] Comparison failure on poll: Result for src/test/resources/runtimets/queries/rebalance/rebalance_MB-27650/rebalance_MB-27650.4.pollquery.sqlpp changed at line 1:

expected < { "count": 5891 }

actual   > { "count": 0 }

2021-01-28T17:02:43.241-08:00 INFO TestExecutor [pool-209-thread-1] Expected results file: src/test/resources/runtimets/results/rebalance/rebalance_MB-27650/rebalance_MB-27650.3.adm 

2021-01-28T17:02:43.241-08:00 INFO TestExecutor [pool-209-thread-1] Actual results file: target/rttest/results/rebalance/rebalance_MB-27650/rebalance_MB-27650.3.adm

2021-01-28T17:02:43.241-08:00 INFO TestExecutor [main] Comparison failure on poll: Result for src/test/resources/runtimets/queries/rebalance/rebalance_MB-27650/rebalance_MB-27650.4.pollquery.sqlpp changed at line 1:

expected < { "count": 5891 }

actual   > { "count": 0 }

2021-01-28T17:02:44.461-08:00 INFO TestExecutor [pool-209-thread-1] Expected results file: src/test/resources/runtimets/results/rebalance/rebalance_MB-27650/rebalance_MB-27650.3.adm 

2021-01-28T17:02:44.461-08:00 INFO TestExecutor [pool-209-thread-1] Actual results file: target/rttest/results/rebalance/rebalance_MB-27650/rebalance_MB-27650.3.adm

2021-01-28T17:02:44.462-08:00 INFO TestExecutor [main] Comparison failure on poll: Result for src/test/resources/runtimets/queries/rebalance/rebalance_MB-27650/rebalance_MB-27650.4.pollquery.sqlpp changed at line 1:

expected < { "count": 5891 }

actual   > { "count": 0 }

2021-01-28T17:02:45.637-08:00 INFO TestExecutor [pool-209-thread-1] Expected results file: src/test/resources/runtimets/results/rebalance/rebalance_MB-27650/rebalance_MB-27650.3.adm 

2021-01-28T17:02:45.637-08:00 INFO TestExecutor [pool-209-thread-1] Actual results file: target/rttest/results/rebalance/rebalance_MB-27650/rebalance_MB-27650.3.adm

2021-01-28T17:02:45.638-08:00 INFO TestExecutor [main] Comparison failure on poll: Result for src/test/resources/runtimets/queries/rebalance/rebalance_MB-27650/rebalance_MB-27650.4.pollquery.sqlpp changed at line 1:

expected < { "count": 5891 }

actual   > { "count": 0 }