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

Details

Type: Bug
Status: Resolved
Priority: Blocker
Resolution: Fixed
Affects Version/s: 1.8.1-release-candidate
Fix Version/s: 1.8.1
Component/s: couchbase-bucket, ns_server
Security Level: Public
Labels:
None

Description

As part of fixing ~~MB-5052~~ it's logs revealed that one of vbuckets we previously built using new code did not actually have closed checkpoint. So replica wasn't in fact built.

After discussion with Chiyoung I found that using 'backfill_completed' to find out when replica is mostly up-to-date is not correct. This stat becomes true when backfill is done, but there's also next message that opens next checkpoint. And we should be waiting for it instead. But we also found there are no producer-side stats we can use.

So we decided I'll have to additionally poll destinations for actually closed checkpoints on them before I'll stop replication building.

Options
- Sort By Name
- Sort By Date
- Ascending
- Descending
- Download All

Attachments

10.1.3.74-8091-diag.txt.gz

14/May/12 7:00 PM

1.10 MB

Karan Kumar
10.1.3.75-8091-diag.txt.gz

14/May/12 7:00 PM

1.17 MB

Karan Kumar
10.1.3.76-8091-diag.txt.gz

14/May/12 7:00 PM

1.16 MB

Karan Kumar
10.1.3.77-8091-diag.txt.gz

14/May/12 7:00 PM

1.08 MB

Karan Kumar
10.1.3.78-8091-diag.txt.gz

14/May/12 7:00 PM

1.08 MB

Karan Kumar
10.1.3.79-8091-diag.txt.gz

14/May/12 7:00 PM

1.16 MB

Karan Kumar
10.1.3.80-8091-diag.txt.gz

14/May/12 7:00 PM

1.27 MB

Karan Kumar

Activity

Ascending order - Click to sort in descending order

Hide

Permalink

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.

Show

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.

Hide

Permalink

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.

Show

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.

Hide

Permalink

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

Show

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

Hide

Permalink

Aleksey Kondratenko added a comment - 25/Apr/12 12:13 PM

http://review.couchbase.org/15186

Show

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

Hide

Permalink

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

Show

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

Hide

Permalink

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..

Show

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..

Hide

Permalink

Karan Kumar added a comment - 14/May/12 7:01 PM

See http://www.couchbase.com/issues/browse/MB-5297 for more details

Show

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

Hide

Permalink

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

Show

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

Hide

Permalink

Aleksey Kondratenko added a comment - 14/May/12 10:53 PM

I've added more ns_server logging and hopefully that will help

Show

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

Hide

Permalink

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.

Show

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.

Hide

Permalink

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 ?

Show

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 ?

Hide

Permalink

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.

Show

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.

Hide

Permalink

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.

Show

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.

Hide

Permalink

Chiyoung Seo added a comment - 18/May/12 5:09 PM

http://review.couchbase.org/#change,16201

Show

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

People

Assignee:

Chiyoung Seo

Reporter:

Aleksey Kondratenko

Vote (0)

Watch (2)

Dates

Created:

23/Apr/12 12:03 PM

Updated:

21/May/12 3:29 PM

Resolved:

18/May/12 5:09 PM

Agile

View on Board