curr_items_tot & vb_replica_curr_items mismatch when rebalancing new 1.8.1 and 2.0.1 nodes at once to 1.8.1 cluster that was rebooted before

Andrei Baranouski added a comment - 01/Feb/13 6:25 AM - edited https://s3.amazonaws.com/bugdb/jira/MB-7660/10.3.3.91-212013-234-diag.zip https://s3.amazonaws.com/bugdb/jira/MB-7660/10.3.3.92-212013-231-diag.zip https://s3.amazonaws.com/bugdb/jira/MB-7660/10.3.3.93-212013-233-diag.zip https://s3.amazonaws.com/bugdb/jira/MB-7660/10.3.3.99-212013-232-diag.zip

Chiyoung Seo added a comment - 01/Feb/13 11:58 AM I saw some deletions coming through TAP replication: The following stats are from the memcached layer: .91 node tap_delete_received: 15 .93 node tap_delete_received: 381 .94 node stats.log were truncated unfortunately. .99 node tap_delete_received: 100 I'm a little confused with this test. You mentioned that there are four nodes (.92, .91, .93, and .99) But, the logs attached don't include .92 node, but instead has .94 node.

Chiyoung Seo added a comment - 01/Feb/13 8:48 PM Please see my comment above.

Andrei Baranouski added a comment - 04/Feb/13 3:05 AM Please, see 92 logs instead of 94 logs

Chiyoung Seo added a comment - 04/Feb/13 4:11 PM As mentioned earlier, there are some deletions that were replicated to some replica vbuckets through TAP: .node 91: tap_delete_received: 150 .node 92: tap_delete_received: 189 tap_delete_sent: 481 .node 93: tap_delete_received: 381 tap_delete_sent: 339 .node 99: tap_delete_received: 100 I couldn't figure out where those deletions came from. Those nodes belong to a single cluster only?

Andrei Baranouski added a comment - 05/Feb/13 10:58 AM Chiyoгng, these vms are used only for the job http://qa.hq.northscale.net/view/2.0.1/job/centos-64-2.0-new-rebalance-mixed-cluster/28/console - run only the separate test on build 148, it failed again if you need you can take this environment to debug/investigate or try it manually: 1) echo "[global] username:root password:password port:8091 [10.3.3.92] [10.3.3.93] [10.3.3.99] [10.3.3.82] [10.3.3.91] [10.3.3.97] [10.3.3.94] [servers] 1:10.3.3.92 2:10.3.3.93 3:10.3.3.99 4:10.3.3.82 5:10.3.3.91 6:10.3.3.97 7:10.3.3.94 [membase] rest_username:Administrator rest_password:password" > /tmp/rebalance_in.ini 2) echo "[global] username:root password:password port:8091 [10.3.3.92] [10.3.3.93] [10.3.3.94] [servers] 1:10.3.3.92 2:10.3.3.93 3:10.3.3.94 [membase] rest_username:Administrator rest_password:password" > /tmp/rebalance_in_1_8_1.ini 3) echo "[global] username:root password:password port:8091 [10.3.3.99] [10.3.3.82] [10.3.3.91] [10.3.3.97] [servers] 1:10.3.3.99 2:10.3.3.82 3:10.3.3.91 4:10.3.3.97 [membase] rest_username:Administrator rest_password:password" > /tmp/rebalance_in_2_0.ini 4) python scripts/install.py -i /tmp/rebalance_in_1_8_1.ini -p version=1.8.1-937-rel,product=cb,parallel=True,get-logs=True,vbuckets=1024 5) python scripts/install.py -i /tmp/rebalance_in_2_0.ini -p version=2.0.1-148-rel,product=cb,parallel=True,get-logs=True,vbuckets=1024 6) python testrunner -i /tmp/rebalance_in.ini -t rebalance.rebalancein.RebalanceInTests.rebalance_in_with_warming_up,nodes_in=3,items=100000,replicas=2,get-logs=True,wait_timeout=180,get-cbcollect-info=True,skip_cleanup=True test always passed on non mixed cluster( 2.0.0/2.0.1) test don't use any ops during rebalance with warmup node:     def rebalance_in_with_warming_up(self):         servs_in = self.servers[self.nodes_init:self.nodes_init + self.nodes_in]         servs_init = self.servers[:self.nodes_init]         warmup_node = servs_init[-1]         shell = RemoteMachineShellConnection(warmup_node)         shell.stop_couchbase()         self.sleep(20)         shell.start_couchbase()         shell.disconnect()         try:             rebalance = self.cluster.async_rebalance(servs_init, servs_in, [])             rebalance.result()         except RebalanceFailedException:             self.log.info("rebalance was failed as expected")             self.assertTrue(ClusterOperationHelper._wait_warmup_completed(self, [warmup_node], \                             self.default_bucket_name, wait_time=self.wait_timeout * 10))             self.log.info("second attempt to rebalance")             rebalance = self.cluster.async_rebalance(servs_init + servs_in, [], [])             rebalance.result()         self.verify_cluster_stats(self.servers[:self.nodes_in + self.nodes_init])

Andrei Baranouski added a comment - 07/Feb/13 6:24 AM The same failure of the test with 1*1.8.1 node, rebalance in 2 2.0.1-151-rel nodes http://qa.hq.northscale.net/view/2.0.1/job/centos-64-2.0-new-rebalance-mixed-cluster/31/consoleFull

Chiyoung Seo added a comment - 15/Feb/13 7:06 PM Just for the bug distributions in the engine team

Xiaoqin Ma added a comment - 21/Feb/13 3:57 PM @andrei, Can you confirm that there are no client traffic in setup? Do you set up the item expiration time while running the test? As @Chiyoung has pointed out, there are tap deletion ops that we could not explain yet.

Andrei Baranouski added a comment - 22/Feb/13 2:15 AM - edited The test doesn't contains any operations in the test. all docs are loaded in setup: 1. [2013-02-20 04:18:11,460] - [data_helper:289] INFO - creating direct client 10.3.3.92:11210 default [2013-02-20 04:18:12,146] - [task:543] INFO - Batch create documents done #: 0 with exp:0 [2013-02-20 04:19:32,864] - [task:543] INFO - Batch create documents done #: 50000 with exp:0 [2013-02-20 04:20:55,499] - [task:543] INFO - Batch create documents done #: 100000 with exp:0 2. then we restart 10.3.3.92 and perform rebalance: [2013-02-20 04:21:32,633] - [rest_client:804] INFO - rebalance params : password=password&ejectedNodes=&user=Administrator&knownNodes=ns_1%4010.3.3.92%2Cns_1%4010.3.3.82%2Cns_1%4010.3.3.99%2Cns_1%4010.3.3.93 3. wait while all items are drained and check all 100K items: [2013-02-20 04:27:56,497] - [task:309] INFO - rebalancing was completed with progress: 100% in 371.912900925 sec [2013-02-20 04:27:57,535] - [data_helper:289] INFO - creating direct client 10.3.3.92:11210 default [2013-02-20 04:27:58,021] - [task:361] INFO - Saw ep_queue_size 0 == 0 expected on '10.3.3.92:8091' [2013-02-20 04:27:58,051] - [data_helper:289] INFO - creating direct client 10.3.3.92:11210 default [2013-02-20 04:27:58,576] - [task:361] INFO - Saw ep_flusher_todo 0 == 0 expected on '10.3.3.92:8091' [2013-02-20 04:27:58,611] - [data_helper:289] INFO - creating direct client 10.3.3.93:11210 default [2013-02-20 04:27:59,111] - [task:361] INFO - Saw ep_queue_size 0 == 0 expected on '10.3.3.93:8091' [2013-02-20 04:27:59,159] - [data_helper:289] INFO - creating direct client 10.3.3.93:11210 default [2013-02-20 04:27:59,604] - [task:361] INFO - Saw ep_flusher_todo 0 == 0 expected on '10.3.3.93:8091' [2013-02-20 04:27:59,707] - [data_helper:289] INFO - creating direct client 10.3.3.99:11210 default [2013-02-20 04:28:00,032] - [task:361] INFO - Saw ep_queue_size 0 == 0 expected on '10.3.3.99:8091' [2013-02-20 04:28:00,106] - [data_helper:289] INFO - creating direct client 10.3.3.99:11210 default [2013-02-20 04:28:00,271] - [task:361] INFO - Saw ep_flusher_todo 0 == 0 expected on '10.3.3.99:8091' [2013-02-20 04:28:00,361] - [data_helper:289] INFO - creating direct client 10.3.3.82:11210 default [2013-02-20 04:28:00,558] - [task:361] INFO - Saw ep_queue_size 0 == 0 expected on '10.3.3.82:8091' [2013-02-20 04:28:00,657] - [data_helper:289] INFO - creating direct client 10.3.3.82:11210 default [2013-02-20 04:28:00,892] - [task:361] INFO - Saw ep_flusher_todo 0 == 0 expected on '10.3.3.82:8091' [2013-02-20 04:28:01,569] - [data_helper:289] INFO - creating direct client 10.3.3.82:11210 default [2013-02-20 04:28:01,998] - [data_helper:289] INFO - creating direct client 10.3.3.92:11210 default [2013-02-20 04:28:02,795] - [data_helper:289] INFO - creating direct client 10.3.3.93:11210 default [2013-02-20 04:28:03,651] - [data_helper:289] INFO - creating direct client 10.3.3.99:11210 default [2013-02-20 04:28:04,205] - [task:830] INFO - 100000 items will be verified on default bucket [2013-02-20 04:28:04,905] - [task:839] INFO - 0 items were verified ... [2013-02-20 04:29:28,297] - [task:839] INFO - 100000 items were verified [2013-02-20 04:29:28,298] - [task:843] INFO - 100000 items were verified in 84.0928199291 sec.the average number of ops - 1189.16213694 per second 4. check curr_items, vb_active_curr_items( that are fine), but vb_replica_curr_items and curr_items_tot don't match with expected [2013-02-20 04:29:31,112] - [task:361] INFO - Saw curr_items 100000 == 100000 expected on '10.3.3.92:8091''10.3.3.93:8091''10.3.3.99:8091''10.3.3.82:8091' [2013-02-20 04:29:31,159] - [data_helper:289] INFO - creating direct client 10.3.3.92:11210 default [2013-02-20 04:29:31,893] - [data_helper:289] INFO - creating direct client 10.3.3.93:11210 default [2013-02-20 04:29:32,633] - [data_helper:289] INFO - creating direct client 10.3.3.99:11210 default [2013-02-20 04:29:32,953] - [data_helper:289] INFO - creating direct client 10.3.3.82:11210 default [2013-02-20 04:29:33,159] - [task:361] INFO - Saw vb_active_curr_items 100000 == 100000 expected on '10.3.3.92:8091''10.3.3.93:8091''10.3.3.99:8091''10.3.3.82:8091' [2013-02-20 04:29:33,205] - [data_helper:289] INFO - creating direct client 10.3.3.92:11210 default [2013-02-20 04:29:33,848] - [data_helper:289] INFO - creating direct client 10.3.3.93:11210 default [2013-02-20 04:29:34,654] - [data_helper:289] INFO - creating direct client 10.3.3.99:11210 default [2013-02-20 04:29:34,889] - [data_helper:289] INFO - creating direct client 10.3.3.82:11210 default [2013-02-20 04:29:35,076] - [task:357] WARNING - Not Ready: vb_replica_curr_items 199315 == 200000 expected on '10.3.3.92:8091''10.3.3.93:8091''10.3.3.99:8091''10.3.3.82:8091' [2013-02-20 04:29:35,110] - [data_helper:289] INFO - creating direct client 10.3.3.92:11210 default [2013-02-20 04:29:35,665] - [data_helper:289] INFO - creating direct client 10.3.3.93:11210 default [2013-02-20 04:29:36,418] - [data_helper:289] INFO - creating direct client 10.3.3.99:11210 default [2013-02-20 04:29:36,766] - [data_helper:289] INFO - creating direct client 10.3.3.82:11210 default [2013-02-20 04:29:36,983] - [task:357] WARNING - Not Ready: curr_items_tot 299315 == 300000 expected on '10.3.3.92:8091''10.3.3.93:8091''10.3.3.99:8091''10.3.3.82:8091' [2013-02-20 04:29:41,278] - [task:357] WARNING - Not Ready: vb_replica_curr_items 199315 == 200000 expected on '10.3.3.92:8091''10.3.3.93:8091''10.3.3.99:8091''10.3.3.82:8091' .... logs from http://qa.hq.northscale.net/job/centos-64-2.0-new-rebalance-mixed-cluster/44/consoleFull 1.8.1-937-rel and 2.0.1-161-rel mixed cluster

Xiaoqin Ma added a comment - 22/Feb/13 4:54 PM Thanks for the info. I would like to do live debug on these system. Can I use the centos-64-2.0-new-rebalance-mixed-cluster build on jenkins to run the test? What the parameters should I set while building it? Also, I could not log on to the nodes, 10.3.3.X. Let me know the login information by email.

Andrei Baranouski added a comment - 24/Feb/13 4:54 AM yes, sure 1. you can stop all runs 2. in http://qa.hq.northscale.net/job/centos-64-2.0-new-rebalance-mixed-cluster/configure modify 'Execute shell' not to perform all the tests, but only one:comment out the first line and uncomment the second one. Should be ''' #/opt/python2.7/bin/python testrunner -i ${resource} -c ${testcase2} -p get-logs=True,wait_timeout=180,GROUP=${priority},EXCLUDE_GROUP=FROM_2_0,get-cbcollect-info=True /opt/python2.7/bin/python testrunner -i ${resource} -t rebalance.rebalancein.RebalanceInTests.rebalance_in_with_warming_up,nodes_in=2,items=100000,replicas=2,get-logs=True,wait_timeout=180,get-cbcollect-info=True,skip_cleanup=True ''' Then Apply, Save 3. Build Now and modify only version_number, for instance: 2.0.1-164-rel That's all

Xiaoqin Ma added a comment - 25/Feb/13 2:15 PM Thanks. I can reproduce it on my VMs. I dont need your setting any more. I tried with all nodes with 1.8.1-937-rel, it has items lost too. With all node in 2.0.1 release, it doesn't have data loss.

Xiaoqin Ma added a comment - 25/Feb/13 4:22 PM with all nodes in 1.8.1-937: curr_items_tot 299510 == 300000 vb_replica_curr_items 199510 == 200000 tap log from all nodes: [ root@centos-63-x64 ~]# /opt/couchbase/bin/cbstats localhost:11210 all | grep "tap"  ep_tap_bg_fetch_requeued: 0  ep_tap_bg_fetched: 0  ep_tap_keepalive: 300  tap_checkpoint_start_received: 64  tap_checkpoint_start_sent: 468  tap_connect_received: 449  tap_delete_received: 4217  tap_delete_sent: 7895  tap_mutation_received: 62171  tap_mutation_sent: 366302  tap_opaque_received: 361  tap_opaque_sent: 1858  tap_vbucket_set_sent: 192 [ root@centos-63-x64 ~]# [ root@centos-63-x64 ~]# /opt/couchbase/bin/cbstats localhost:11210 all | grep "tap"  ep_tap_bg_fetch_requeued: 0  ep_tap_bg_fetched: 0  ep_tap_keepalive: 300  tap_checkpoint_start_received: 223  tap_checkpoint_start_sent: 74  tap_connect_received: 64  tap_delete_received: 8453  tap_delete_sent: 585  tap_mutation_received: 179887  tap_mutation_sent: 82341  tap_opaque_received: 1030  tap_opaque_sent: 340  tap_vbucket_set_received: 64 [ root@centos-63-x64 ~]# [ root@tahoe-1103 ~]# /opt/couchbase/bin/cbstats localhost:11210 all | grep "tap"  ep_tap_bg_fetch_requeued: 0  ep_tap_bg_fetched: 0  ep_tap_keepalive: 300  tap_checkpoint_start_received: 192  tap_checkpoint_start_sent: 84  tap_connect_received: 65  tap_delete_received: 1510  tap_delete_sent: 490  tap_mutation_received: 158597  tap_mutation_sent: 65110  tap_opaque_received: 949  tap_opaque_sent: 320  tap_vbucket_set_received: 64 [ root@tahoe-1103 ~]# [ root@tahoe-1104 ~]# /opt/couchbase/bin/cbstats localhost:11210 all | grep "tap"  ep_tap_bg_fetch_requeued: 0  ep_tap_bg_fetched: 0  ep_tap_keepalive: 300  tap_checkpoint_start_received: 222  tap_checkpoint_start_sent: 75  tap_connect_received: 63  tap_delete_received: 1075  tap_delete_sent: 6285  tap_mutation_received: 180249  tap_mutation_sent: 67151  tap_opaque_received: 1028  tap_opaque_sent: 316  tap_vbucket_set_received: 64 [ root@tahoe-1104 ~]#

Xiaoqin Ma added a comment - 25/Feb/13 4:45 PM Hi Andrei, Can you try with all nodes with 1.8.1 release? As I observed that if all nodes in 1.8.1 releases, it already has the issue. Try again with all nodes in 2.0.1 release. So if it is the problem in 1.8.1 even all nodes in 1.8.1, we don't plan to fix it.

Andrei Baranouski added a comment - 26/Feb/13 10:32 AM Hi Xiaoqin, yes, it was reproduced on clean 1.8.1 cluster http://qa.hq.northscale.net/view/2.0.1/job/centos-64-2.0-new-rebalance-mixed-cluster/47/console and passed on 2.0.1 builds http://qa.hq.northscale.net/view/2.0.1/job/ubuntu-64-2.0-new-rebalance-tests-P0 please close the ticket if we don't plan to fix it

Xiaoqin Ma added a comment - 26/Feb/13 12:09 PM As this happens even with all nodes with 1.8.1 release, we will not fix it.

Andrei Baranouski added a comment - 23/Apr/13 6:46 AM only as additional information to the bug. similar happened in test ./testrunner -i /tmp/rebalance_in.ini wait_timeout=180,GROUP=P0,EXCLUDE_GROUP=FROM_2_0,get-cbcollect-info=True -t rebalance.rebalanceout.RebalanceOutTests.rebalance_out_with_warming_up,nodes_out=3,items=500000,replicas=2,max_verify=100000,value_size=1024,GROUP=OUT;P0 http://qa.hq.northscale.net/job/centos-64-2.0-new-rebalance-mixed-cluster/64/consoleFull [2013-04-22 04:58:25,029] - [task:323] INFO - rebalancing was completed with progress: 100.0% in 336.652933121 sec [2013-04-22 04:58:25,072] - [data_helper:289] INFO - creating direct client 10.3.3.92:11210 default [2013-04-22 04:58:25,546] - [task:375] INFO - Saw ep_queue_size 0 == 0 expected on '10.3.3.92:8091',default bucket [2013-04-22 04:58:25,585] - [data_helper:289] INFO - creating direct client 10.3.3.92:11210 default [2013-04-22 04:58:25,691] - [task:375] INFO - Saw ep_flusher_todo 0 == 0 expected on '10.3.3.92:8091',default bucket [2013-04-22 04:58:25,741] - [data_helper:289] INFO - creating direct client 10.3.3.93:11210 default [2013-04-22 04:58:25,855] - [task:375] INFO - Saw ep_queue_size 0 == 0 expected on '10.3.3.93:8091',default bucket [2013-04-22 04:58:25,895] - [data_helper:289] INFO - creating direct client 10.3.3.93:11210 default [2013-04-22 04:58:26,018] - [task:375] INFO - Saw ep_flusher_todo 0 == 0 expected on '10.3.3.93:8091',default bucket [2013-04-22 04:58:26,116] - [data_helper:289] INFO - creating direct client 10.3.3.99:11210 default [2013-04-22 04:58:26,329] - [task:375] INFO - Saw ep_queue_size 0 == 0 expected on '10.3.3.99:8091',default bucket [2013-04-22 04:58:26,407] - [data_helper:289] INFO - creating direct client 10.3.3.99:11210 default [2013-04-22 04:58:26,602] - [task:375] INFO - Saw ep_flusher_todo 0 == 0 expected on '10.3.3.99:8091',default bucket [2013-04-22 04:58:26,694] - [data_helper:289] INFO - creating direct client 10.3.3.82:11210 default [2013-04-22 04:58:26,860] - [task:371] WARNING - Not Ready: ep_queue_size 1 == 0 expected on '10.3.3.82:8091', default bucket [2013-04-22 04:58:26,951] - [data_helper:289] INFO - creating direct client 10.3.3.82:11210 default [2013-04-22 04:58:27,129] - [task:375] INFO - Saw ep_flusher_todo 0 == 0 expected on '10.3.3.82:8091',default bucket [2013-04-22 04:58:32,145] - [task:371] WARNING - Not Ready: ep_queue_size 1 == 0 expected on '10.3.3.82:8091', default bucket [2013-04-22 04:58:37,160] - [task:371] WARNING - Not Ready: ep_queue_size 1 == 0 expected on '10.3.3.82:8091', default bucket [2013-04-22 04:58:42,177] - [task:371] WARNING - Not Ready: ep_queue_size 1 == 0 expected on '10.3.3.82:8091', default bucket [2013-04-22 04:58:47,193] - [task:371] WARNING - Not Ready: ep_queue_size 1 == 0 expected on '10.3.3.82:8091', default bucket [2013-04-22 04:58:52,208] - [task:371] WARNING - Not Ready: ep_queue_size 1 == 0 expected on '10.3.3.82:8091', default bucket [2013-04-22 04:58:57,223] - [task:371] WARNING - Not Ready: ep_queue_size 1 == 0 expected on '10.3.3.82:8091', default bucket [2013-04-22 04:59:02,238] - [task:371] WARNING - Not Ready: ep_queue_size 1 == 0 expected on '10.3.3.82:8091', default bucket [2013-04-22 04:59:07,253] - [task:371] WARNING - Not Ready: ep_queue_size 1 == 0 expected on '10.3.3.82:8091', default bucket [2013-04-22 04:59:12,268] - [task:371] WARNING - Not Ready: ep_queue_size 1 == 0 expected on '10.3.3.82:8091', default bucket [2013-04-22 04:59:17,284] - [task:371] WARNING - Not Ready: ep_queue_size 1 == 0 expected on '10.3.3.82:8091', default bucket [2013-04-22 04:59:22,300] - [task:371] WARNING - Not Ready: ep_queue_size 1 == 0 expected on '10.3.3.82:8091', default bucket [2013-04-22 04:59:27,316] - [task:371] WARNING - Not Ready: ep_queue_size 1 == 0 expected on '10.3.3.82:8091', default bucket [2013-04-22 04:59:32,331] - [task:371] WARNING - Not Ready: ep_queue_size 1 == 0 expected on '10.3.3.82:8091', default bucket [2013-04-22 04:59:37,347] - [task:371] WARNING - Not Ready: ep_queue_size 1 == 0 expected on '10.3.3.82:8091', default bucket [2013-04-22 04:59:42,369] - [task:371] WARNING - Not Ready: ep_queue_size 1 == 0 expected on '10.3.3.82:8091', default bucket [2013-04-22 04:59:47,388] - [task:371] WARNING - Not Ready: ep_queue_size 1 == 0 expected on '10.3.3.82:8091', default bucket [2013-04-22 04:59:52,406] - [task:371] WARNING - Not Ready: ep_queue_size 1 == 0 expected on '10.3.3.82:8091', default bucket [2013-04-22 04:59:57,422] - [task:371] WARNING - Not Ready: ep_queue_size 1 == 0 expected on '10.3.3.82:8091', default bucket [2013-04-22 05:00:02,437] - [task:371] WARNING - Not Ready: ep_queue_size 1 == 0 expected on '10.3.3.82:8091', default bucket [2013-04-22 05:00:07,453] - [task:371] WARNING - Not Ready: ep_queue_size 1 == 0 expected on '10.3.3.82:8091', default bucket [2013-04-22 05:00:12,469] - [task:371] WARNING - Not Ready: ep_queue_size 1 == 0 expected on '10.3.3.82:8091', default bucket [2013-04-22 05:00:17,484] - [task:371] WARNING - Not Ready: ep_queue_size 1 == 0 expected on '10.3.3.82:8091', default bucket [2013-04-22 05:00:22,499] - [task:371] WARNING - Not Ready: ep_queue_size 1 == 0 expected on '10.3.3.82:8091', default bucket