Couchbase Server

Rebalance fails with error "wait_for_memcached_failed,"bucket3" on issuing a rebalance after reboot of master node.

Details

  • Type: Bug Bug
  • Status: Closed Closed
  • Priority: Major Major
  • Resolution: Won't Fix
  • Affects Version/s: 1.8.1
  • Fix Version/s: 2.0-beta
  • Component/s: ns_server
  • Security Level: Public
  • Labels:
    None
  • Environment:
    Large Cluster - Centos, - 16 node cluster
    Build 181-916rel
    3 buckets - bucket1(3G), bucket2(2.8G), bucket3(200M)

Description


Setup:
1.Setup a 16 node cluster. Enable Auto-failover
2.Load data on all 3 buckets [around 3M, 2M, 367k] items.
3. Continue loading data..
4. Reboot orchestrator node [84]
5. Issue rebalance on this cluster.

Output
1. Node 84 goes down, and is auto-failed over - Expected.
2. Rebalance operation shows - No ejected Nodes on the rebalance params. [ Note: There was no explicit remove server action done on this]
3. Rebalance operation fails withe error" Wait for memcached" fails. Rebalance params -
4. Node 107 is failed over.

Likely the rebalance command was a faulty one? Should we disallow anyone to issue rebalance in-this manner?

The live cluster is accessible at http://10.3.2.89:8091/index.html#sec=log
Output from web-logs
2012-06-15 11:35:46.448 ns_orchestrator:4:info:message(ns_1@10.3.121.126) - Starting rebalance, KeepNodes = ['ns_1@10.3.2.84','ns_1@10.3.2.85',
                                 'ns_1@10.3.2.86','ns_1@10.3.2.87',
                                 'ns_1@10.3.2.88','ns_1@10.3.2.89',
                                 'ns_1@10.3.2.104','ns_1@10.3.2.105',
                                 'ns_1@10.3.2.106','ns_1@10.3.2.109',
                                 'ns_1@10.3.2.110','ns_1@10.3.2.112',
                                 'ns_1@10.3.2.113','ns_1@10.3.2.114',
                                 'ns_1@10.3.121.126','ns_1@10.3.121.127',
                                 'ns_1@10.3.2.107'], EjectNodes = []

2012-06-15 11:35:46.668 ns_rebalancer:0:info:message(ns_1@10.3.121.126) - Started rebalancing bucket bucket3
2012-06-15 11:35:49.335 ns_memcached:1:info:message(ns_1@10.3.2.107) - Bucket "bucket3" loaded on node 'ns_1@10.3.2.107' in 0 seconds.
2012-06-15 11:35:59.030 ns_orchestrator:2:info:message(ns_1@10.3.121.126) - Rebalance exited with reason {wait_for_memcached_failed,"bucket3",
                                 ['ns_1@10.3.2.84']}


2012-06-15 11:36:03.901 ns_memcached:1:info:message(ns_1@10.3.2.84) - Bucket "bucket3" loaded on node 'ns_1@10.3.2.84' in 25 seconds.
2012-06-15 11:36:19.566 auto_failover:3:info:message(ns_1@10.3.121.126) - Could not auto-failover node ('ns_1@10.3.2.107'). There was at least another node down.

2012-06-15 11:36:19.566 auto_failover:3:info:message(ns_1@10.3.121.126) - Could not auto-failover node ('ns_1@10.3.2.84'). There was at least another node down.

Attached are the log file at : https://s3.amazonaws.com/bugdb/jira/bug-rebalance-largecluster/bug1.tar

Activity

Ascending order - Click to sort in descending order
Hide
Permalink
Aleksey Kondratenko added a comment -
Logs reveal slightly different picture:

2012-06-15 11:35:32.325 ns_node_disco:4:info:node up(ns_1@10.3.2.107) - Node 'ns_1@10.3.2.107' saw that node 'ns_1@10.3.2.86' came up.
2012-06-15 11:35:32.354 ns_node_disco:4:info:node up(ns_1@10.3.2.84) - Node 'ns_1@10.3.2.84' saw that node 'ns_1@10.3.2.107' came up.
2012-06-15 11:35:46.448 ns_orchestrator:4:info:message(ns_1@10.3.121.126) - Starting rebalance, KeepNodes = ['ns_1@10.3.2.84','ns_1@10.3.2.85',
                                 'ns_1@10.3.2.86','ns_1@10.3.2.87',
                                 'ns_1@10.3.2.88','ns_1@10.3.2.89',
                                 'ns_1@10.3.2.104','ns_1@10.3.2.105',
                                 'ns_1@10.3.2.106','ns_1@10.3.2.109',
                                 'ns_1@10.3.2.110','ns_1@10.3.2.112',
                                 'ns_1@10.3.2.113','ns_1@10.3.2.114',
                                 'ns_1@10.3.121.126','ns_1@10.3.121.127',
                                 'ns_1@10.3.2.107'], EjectNodes = []

2012-06-15 11:35:46.668 ns_rebalancer:0:info:message(ns_1@10.3.121.126) - Started rebalancing bucket bucket3
2012-06-15 11:35:49.335 ns_memcached:1:info:message(ns_1@10.3.2.107) - Bucket "bucket3" loaded on node 'ns_1@10.3.2.107' in 0 seconds.
2012-06-15 11:35:59.030 ns_orchestrator:2:info:message(ns_1@10.3.121.126) - Rebalance exited with reason {wait_for_memcached_failed,"bucket3",
                                 ['ns_1@10.3.2.84']}

2012-06-15 11:36:03.901 ns_memcached:1:info:message(ns_1@10.3.2.84) - Bucket "bucket3" loaded on node 'ns_1@10.3.2.84' in 25 seconds.
2012-06-15 11:36:19.566 auto_failover:3:info:message(ns_1@10.3.121.126) - Could not auto-failover node ('ns_1@10.3.2.107'). There was at least another node down.

2012-06-15 11:36:19.566 auto_failover:3:info:message(ns_1@10.3.121.126) - Could not auto-failover node ('ns_1@10.3.2.84'). There was at least another node down.

2012-06-15 11:38:23.406 ns_memcached:1:info:message(ns_1@10.3.2.84) - Bucket "bucket2" loaded on node 'ns_1@10.3.2.84' in 164 seconds.
2012-06-15 11:39:26.403 ns_memcached:1:info:message(ns_1@10.3.2.84) - Bucket "bucket1" loaded on node 'ns_1@10.3.2.84' in 227 seconds.
2012-06-15 11:39:34.578 ns_orchestrator:0:info:message(ns_1@10.3.121.126) - Starting failing over 'ns_1@10.3.2.107'
2012-06-15 11:39:35.011 ns_orchestrator:6:info:message(ns_1@10.3.121.126) - Failed over 'ns_1@10.3.2.107': ok
2012-06-15 11:39:35.021 auto_failover:1:info:message(ns_1@10.3.121.126) - Node ('ns_1@10.3.2.107') was automatically failovered.

So we're seeing that .84 gets rebooted and starts warmup. .107 is 'down' at same time. Perhaps rebooted as well or memcached crash. It's technically up but bucket(s) are not ready.

So rebalance fails because .84 is still warming up data and clearly not yet ready.

At this point neither .84 nor .107 were failed over.

After rebalance fails .84 completes it's warmup and now we have only one node left that's unheatlhy - .107. And it's now automatically failed over.

Show
Aleksey Kondratenko added a comment - Logs reveal slightly different picture: 2012-06-15 11:35:32.325 ns_node_disco:4:info:node up( ns_1@10.3.2.107 ) - Node ' ns_1@10.3.2.107 ' saw that node ' ns_1@10.3.2.86 ' came up. 2012-06-15 11:35:32.354 ns_node_disco:4:info:node up( ns_1@10.3.2.84 ) - Node ' ns_1@10.3.2.84 ' saw that node ' ns_1@10.3.2.107 ' came up. 2012-06-15 11:35:46.448 ns_orchestrator:4:info:message( ns_1@10.3.121.126 ) - Starting rebalance, KeepNodes = [' ns_1@10.3.2.84 ',' ns_1@10.3.2.85 ',                                  ' ns_1@10.3.2.86 ',' ns_1@10.3.2.87 ',                                  ' ns_1@10.3.2.88 ',' ns_1@10.3.2.89 ',                                  ' ns_1@10.3.2.104 ',' ns_1@10.3.2.105 ',                                  ' ns_1@10.3.2.106 ',' ns_1@10.3.2.109 ',                                  ' ns_1@10.3.2.110 ',' ns_1@10.3.2.112 ',                                  ' ns_1@10.3.2.113 ',' ns_1@10.3.2.114 ',                                  ' ns_1@10.3.121.126 ',' ns_1@10.3.121.127 ',                                  ' ns_1@10.3.2.107 '], EjectNodes = [] 2012-06-15 11:35:46.668 ns_rebalancer:0:info:message( ns_1@10.3.121.126 ) - Started rebalancing bucket bucket3 2012-06-15 11:35:49.335 ns_memcached:1:info:message( ns_1@10.3.2.107 ) - Bucket "bucket3" loaded on node ' ns_1@10.3.2.107 ' in 0 seconds. 2012-06-15 11:35:59.030 ns_orchestrator:2:info:message( ns_1@10.3.121.126 ) - Rebalance exited with reason {wait_for_memcached_failed,"bucket3",                                  [' ns_1@10.3.2.84 ']} 2012-06-15 11:36:03.901 ns_memcached:1:info:message( ns_1@10.3.2.84 ) - Bucket "bucket3" loaded on node ' ns_1@10.3.2.84 ' in 25 seconds. 2012-06-15 11:36:19.566 auto_failover:3:info:message( ns_1@10.3.121.126 ) - Could not auto-failover node (' ns_1@10.3.2.107 '). There was at least another node down. 2012-06-15 11:36:19.566 auto_failover:3:info:message( ns_1@10.3.121.126 ) - Could not auto-failover node (' ns_1@10.3.2.84 '). There was at least another node down. 2012-06-15 11:38:23.406 ns_memcached:1:info:message( ns_1@10.3.2.84 ) - Bucket "bucket2" loaded on node ' ns_1@10.3.2.84 ' in 164 seconds. 2012-06-15 11:39:26.403 ns_memcached:1:info:message( ns_1@10.3.2.84 ) - Bucket "bucket1" loaded on node ' ns_1@10.3.2.84 ' in 227 seconds. 2012-06-15 11:39:34.578 ns_orchestrator:0:info:message( ns_1@10.3.121.126 ) - Starting failing over ' ns_1@10.3.2.107 ' 2012-06-15 11:39:35.011 ns_orchestrator:6:info:message( ns_1@10.3.121.126 ) - Failed over ' ns_1@10.3.2.107 ': ok 2012-06-15 11:39:35.021 auto_failover:1:info:message( ns_1@10.3.121.126 ) - Node (' ns_1@10.3.2.107 ') was automatically failovered. So we're seeing that .84 gets rebooted and starts warmup. .107 is 'down' at same time. Perhaps rebooted as well or memcached crash. It's technically up but bucket(s) are not ready. So rebalance fails because .84 is still warming up data and clearly not yet ready. At this point neither .84 nor .107 were failed over. After rebalance fails .84 completes it's warmup and now we have only one node left that's unheatlhy - .107. And it's now automatically failed over.
Hide
Permalink
Ketaki Gangal added a comment -
Ok checked on the cluster. Node 107 was added to the cluster and rebalance issued. Likely as you mentioned 84 was still warming-up, but was not complete. Which put this operation of rebalance with an inconsistent start-state. But we should not allow rebalance to start until the node is up and has all the items?
Show
Ketaki Gangal added a comment - Ok checked on the cluster. Node 107 was added to the cluster and rebalance issued. Likely as you mentioned 84 was still warming-up, but was not complete. Which put this operation of rebalance with an inconsistent start-state. But we should not allow rebalance to start until the node is up and has all the items?
Hide
Permalink
Ketaki Gangal added a comment -
On re-issue rebalance succeeds
Show
Ketaki Gangal added a comment - On re-issue rebalance succeeds
Hide
Permalink
Farshid Ghods added a comment -
rebalance is expected to fail when one or multiple nodes are not ready or warming up.

given that this is actually seen more and more often in the field and customers are not aware of warm up right now ( yellow in the UI could be warm up or stats not responding for few seconds) , can we disllow rebalance operation if one or multiple nodes are warming up ?
Show
Farshid Ghods added a comment - rebalance is expected to fail when one or multiple nodes are not ready or warming up. given that this is actually seen more and more often in the field and customers are not aware of warm up right now ( yellow in the UI could be warm up or stats not responding for few seconds) , can we disllow rebalance operation if one or multiple nodes are warming up ?
Hide
Permalink
Farshid Ghods added a comment -
assigning to Dipti
Show
Farshid Ghods added a comment - assigning to Dipti
Hide
Permalink
Dipti Borkar added a comment -
behavior is acceptable . warmup can be seen was a special case. rebalance failing is not a bad thing.
closing as no plan to fix.
Show
Dipti Borkar added a comment - behavior is acceptable . warmup can be seen was a special case. rebalance failing is not a bad thing. closing as no plan to fix.

People

  • Assignee:
    Dipti Borkar
    Reporter:
    Ketaki Gangal
Vote (0)
Watch (1)

Dates

  • Created:
    Updated:
    Resolved: