Reliable replica building during rebalance sometimes fails to work resulting in larger data loss window and duplicate backfill

Aleksey Kondratenko added a comment - 23/Apr/12 10:25 PM I've found proposed ns_server-side workaround very ugly. Because ns_memcached does not support get_last_closed_checkpoint operation natively we are forced to establish new memcached connections from master node to all other nodes. Error handling and cleanup becomes a lot of code. I've found one potential cause of issue happening in practice inside ep-engine and uploaded patch. http://review.couchbase.org/15119 I think with that patch we should not see this problem in practice. Hopefully for 1.8.2 we'll have some native ep-engine's support for replica building. Like new tap option similar to tap_dump. I've stashed my ugly attempt to work around this issue on ns_server side hoping we won't needed, but testing is needed to confirm that.

Aleksey Kondratenko added a comment - 24/Apr/12 10:02 AM My previous comment is not quite correct. Sadly old versions still have that issue with more probable "backfill_completed = true, but no open_checkpoint message sent yet" situation. So will have to proceed with original plan.

Thuan Nguyen added a comment - 25/Apr/12 2:47 AM Integrated in github-ns-server-2-0 #337 (See [ http://qa.hq.northscale.net/job/github-ns-server-2-0/337/ ])     in replica building wait until destination has checkpoint. MB-5136 (Revision f9a9cdf24efe3ec97d3568db54cd28ff1dec6526)      Result = SUCCESS Aliaksey Kandratsenka : Files : * src/ns_replicas_builder.erl * src/ns_memcached.erl

Aleksey Kondratenko added a comment - 25/Apr/12 12:13 PM http://review.couchbase.org/15186

Thuan Nguyen added a comment - 26/Apr/12 7:54 PM Integrated in github-ep-engine-2-0 #262 (See [ http://qa.hq.northscale.net/job/github-ep-engine-2-0/262/ ])      MB-5136 Don't sleep if there are any new pending notifications. (Revision 06b090ec6374435733e0af75830efaa335a3dcea)      Result = SUCCESS Aliaksey Kandratsenka : Files : * tapconnmap.hh * tapconnmap.cc * configuration.json * ep_engine.cc

Karan Kumar added a comment - 14/May/12 6:59 PM Reopening this based on discussion with Chiyoung. " We might be doing duplicate backfills.." .. Attaching the diags from the cluster where we see the issue..

Karan Kumar added a comment - 14/May/12 7:01 PM See http://www.couchbase.com/issues/browse/MB-5297 for more details

Aleksey Kondratenko added a comment - 14/May/12 8:39 PM I believe that ns_server is doing the right thing. Here's some relevant logs: [ns_server:info] [2012-05-14 12:23:43] [ ns_1@10.1.3.80 :<0.4211.0>:ns_port_server:log:161] memcached<0.4211.0>: TAP (Producer) eq_tapq:replication_building_55_' ns_1@10.1.3.74 ' - Backfill is completed with VBuckets 55, memcached<0.4211.0>: TAP (Producer) eq_tapq:replication_building_55_' ns_1@10.1.3.78 ' - Backfill is completed with VBuckets 55, [ns_server:debug] [2012-05-14 12:23:44] [ ns_1@10.1.3.80 :ns_config_log:ns_config_log:log_common:111] config change: buckets -> [{configs,[{"bucket-0",             [{map,[]},              {fastForwardMap,[]},              {num_replicas,2},              {ram_quota,736100352},              {auth_type,sasl},              {sasl_password,"password"},              {type,membase},              {num_vbuckets,64},              {servers,[' ns_1@10.1.3.75 ',' ns_1@10.1.3.80 ',' ns_1@10.1.3.79 ',                        ' ns_1@10.1.3.76 ']}]},            {"bucket-1",             [{map,[{55,                     [' ns_1@10.1.3.80 ',' ns_1@10.1.3.79 ',' ns_1@10.1.3.76 '],                     [' ns_1@10.1.3.80 ',' ns_1@10.1.3.74 ',' ns_1@10.1.3.78 ']}]},              {fastForwardMap,[]},              {num_replicas,2},              {ram_quota,736100352},              {auth_type,sasl},              {sasl_password,"password"},              {type,membase},              {num_vbuckets,64},              {servers,[' ns_1@10.1.3.75 ',' ns_1@10.1.3.78 ',' ns_1@10.1.3.77 ',                        ' ns_1@10.1.3.80 ',' ns_1@10.1.3.79 ',' ns_1@10.1.3.76 ',                        ' ns_1@10.1.3.74 ']}]}]}] [rebalance:info] [2012-05-14 12:23:44] [ ns_1@10.1.3.80 :<0.10036.0>:ebucketmigrator_srv:init:223] Starting tap stream: [{vbuckets,",57"},  {checkpoints,[{44,0},{53,0},{55,0}]},  {name," replication_ns_1@10.1.3.74 "},  {takeover,false}] {{"10.1.3.80",11209},  {"10.1.3.74",11209},  [{username,"bucket-1"},   {password,"password"},   {vbuckets,",57"},   {takeover,false},   {suffix," ns_1@10.1.3.74 "},   {passed_downstream_retriever,#Fun<ns_vbm_sup.11.117070107>}]} [rebalance:debug] [2012-05-14 12:23:44] [ ns_1@10.1.3.80 :<0.10036.0>:ebucketmigrator_srv:init:245] upstream_sender pid: <0.10041.0> [rebalance:info] [2012-05-14 12:23:44] [ ns_1@10.1.3.80 :<0.10036.0>:ebucketmigrator_srv:process_upstream:446] Initial stream for vbucket 55 And I have evidence that I am doing what we're decided to do (polling for open checkpoint id on destination):                    {ns_server_stats,                     [{replica_builder_sleep_amount,36800},                      {ebucketmigrator_backfill_starts,403},                      {replica_builder_sleeps,368},                      {ebucketmigrator_not_ready_times,25},                      {ebucketmigrator_not_ready_vbuckets,31},                      {replicas_builder_checkpoint_sleeps,6},                      {replicas_builder_backfill_sleeps,362}]}, replicas_builder_checkpoint_sleeps being non-zero means that at last sometimes we've made that extra sleep for open checkpoint after we've found backfill to be done Either what we've decided to do is not enough or there's some other bug

Aleksey Kondratenko added a comment - 14/May/12 10:53 PM I've added more ns_server logging and hopefully that will help

Chiyoung Seo added a comment - 14/May/12 11:56 PM Thanks Alk for your help. From the logs that you posted above, it seems to me that the VB 55 backfill from 10.1.3.80 to 10.1.3.74 was still performed on the normal replication stream even after building the replica vbucket 55 on 10.1.3.74: [rebalance:info] [2012-05-14 12:23:44] [ ns_1@10.1.3.80 :<0.10036.0>:ebucketmigrator_srv:process_upstream:446] Initial stream for vbucket 55 I know that the ep-engine should not cause any data loss even with duplicate backfills, which I'm also investigating separately.

Aleksey Kondratenko added a comment - 15/May/12 11:30 AM My point was: Yes I see that. And I see that ns_server is doing seemingly the right thing. We wait until backfill_completed becomes true, _then_ we wait until we observe non-zero open checkpoint on destination. And only then we proceed with takeover (if it's needed, and in that particular case master node remains same). After which we shutdown star replication and set up chain. And in this case we've observed unpexpected backfill from master (.80) to first replica (.74). Is that possible that our new polling sequence is still incorrect/raceful ?

Chiyoung Seo added a comment - 15/May/12 12:52 PM Well, I know and believe that the ns_server does the right thing. My one question here is that "why the closed checkpoint ids are all zero when the regular replication is established after building the initial replicas? {checkpoints,[{44,0},{53,0},{55,0}]}, I also observed that even if the open checkpoint id >= 2, the closed checkpoint 0 is still passed to the the source node after building the initial replica, which caused the backfill to be scheduled on the source node again.

Aleksey Kondratenko added a comment - 15/May/12 1:25 PM - edited I have same question. We haven't changed code that queries destination checkpoint at the beginning of rebalance. We don't know but it is either ns_server is not doing the right thing (either because of some implementation bug or because polling sequence is incorrect) or it's some sort of ep-engine bug.

Chiyoung Seo added a comment - 18/May/12 5:09 PM http://review.couchbase.org/#change,16201