Couchbase Server

Rebalance 5->4 nodes is failed with reason not_all_nodes_are_ready_yet

Details

  • Type: Bug Bug
  • Status: Closed Closed
  • Priority: Blocker Blocker
  • Resolution: Fixed
  • Affects Version/s: None
  • Fix Version/s: 2.0-beta
  • Component/s: ns_server
  • Security Level: Public
  • Labels:
  • Environment:
    centOS, 64 -bit, 4 cores VMs, build #1620

Description

1.Rebalance in 1->5 nodes
2. Load data (1M), no views or ddocs are created,
   data doc is like: {{ "age": some_integer, "first_name": some_string }}
3. Start rebalance out
4. Created 2 ddocs, 3 view per ddoc, map function: 'function (doc) { emit(null, doc);}'
    ddoc_40->views0, views1,
    ddoc_41->views0, views1,
    ddoc_42->views0,views1
5. Rebalance is failed

2012-08-22 18:47:09.143 menelaus_sup:1:info:web start ok(ns_1@10.3.3.73) - Couchbase Server has started on web port 8091 on node 'ns_1@10.3.3.73'.
2012-08-22 18:47:09.143 ns_node_disco:4:info:node up(ns_1@10.3.3.73) - Node 'ns_1@10.3.3.73' saw that node 'ns_1@10.3.3.71' came up.
2012-08-22 18:47:09.214 ns_cluster:3:info:message(ns_1@10.3.3.73) - Node ns_1@10.3.3.73 joined cluster
2012-08-22 18:47:09.249 ns_orchestrator:4:info:message(ns_1@10.3.3.58) - Starting rebalance, KeepNodes = ['ns_1@10.3.3.73','ns_1@10.3.3.68',
                                 'ns_1@10.3.3.58','ns_1@10.3.3.71'], EjectNodes = ['ns_1@10.3.3.64']

2012-08-22 18:47:09.331 ns_rebalancer:0:info:message(ns_1@10.3.3.58) - Started rebalancing bucket default
2012-08-22 18:47:09.591 ns_memcached:2:info:message(ns_1@10.3.3.73) - Shutting down bucket "default" on 'ns_1@10.3.3.73' for server shutdown
2012-08-22 18:48:09.080 ns_memcached:2:info:message(ns_1@10.3.3.73) - Shutting down bucket "default" on 'ns_1@10.3.3.73' for server shutdown (repeated 1544 times)
2012-08-22 18:48:09.105 ns_memcached:2:info:message(ns_1@10.3.3.73) - Shutting down bucket "default" on 'ns_1@10.3.3.73' for server shutdown
2012-08-22 18:48:09.418 ns_orchestrator:2:info:message(ns_1@10.3.3.58) - Rebalance exited with reason {not_all_nodes_are_ready_yet,['ns_1@10.3.3.73']}
  1. GZip Archive
    10.3.3.58-8091-diag.txt.gz
    22/Aug/12 6:53 PM
    15.72 MB
    Iryna Mironava
  2. GZip Archive
    10.3.3.64-8091-diag.txt.gz
    22/Aug/12 6:53 PM
    6.19 MB
    Iryna Mironava
  3. GZip Archive
    10.3.3.68-8091-diag.txt.gz
    22/Aug/12 6:53 PM
    14.42 MB
    Iryna Mironava
  4. GZip Archive
    10.3.3.71-8091-diag.txt.gz
    22/Aug/12 6:53 PM
    5.83 MB
    Iryna Mironava
  5. GZip Archive
    10.3.3.73-8091-diag.txt.gz
    22/Aug/12 6:53 PM
    3.59 MB
    Iryna Mironava

Activity

Ascending order - Click to sort in descending order
Hide
Permalink
Aleksey Kondratenko added a comment -
Happens because of constant crashes in capi_set_view_manager on .73.

Starts happening with this and I don't understand how this is possible at all:


[ns_server:debug,2012-08-22T17:46:08.142,ns_1@10.3.3.73:'capi_ddoc_replication_srv-default':cb_generic_replication_srv:handle_cast:131]Writing replicated ddoc {doc,<<"_design/dev_ddoc41">>,
                             {1,<<"¡¾4ë">>},
                             <<"{\"views\":{\"views0\":{\"map\":\"function (doc) { emit(doc.age, doc.first_name);}\"}}}">>,
                             0,false,[]}
[couchdb:info,2012-08-22T17:46:08.149,ns_1@10.3.3.73:<0.4293.4>:couch_log:info:39]Native compactor output: Compacted /opt/couchbase/var/lib/couchbase/data/default/189.couch.23 -> /opt/cou
[couchdb:info,2012-08-22T17:46:08.149,ns_1@10.3.3.73:<0.4293.4>:couch_log:info:39]Native compactor output: chbase/var/lib/couchbase/data/default/189.couch.23.compact
[couchdb:info,2012-08-22T17:46:08.150,ns_1@10.3.3.73:<0.4293.4>:couch_log:info:39]Native initial compact succeeded for "default/189"
[couchdb:info,2012-08-22T17:46:08.150,ns_1@10.3.3.73:<0.19661.0>:couch_log:info:39]Database `default/master`, design document `_design/dev_ddoc41` updated (new revision: 1-a1be34eb, deleted: false)
[views:debug,2012-08-22T17:46:08.152,ns_1@10.3.3.73:<0.19667.0>:capi_set_view_manager:master_db_watcher:434]Got change in `_design/dev_ddoc41` design document. Initiating set view update
[ns_server:info,2012-08-22T17:46:08.152,ns_1@10.3.3.73:'capi_set_view_manager-default':capi_set_view_manager:handle_info:236]Processing update_ddoc _design/dev_ddoc41 (false)
[views:info,2012-08-22T17:46:08.152,ns_1@10.3.3.73:'capi_set_view_manager-default':capi_set_view_manager:maybe_define_group:300]
Calling couch_set_view:define_group([<<"default">>,<<"_design/dev_ddoc41">>,
                                     {set_view_params,1024,[],[],true}])
[couchdb:info,2012-08-22T17:46:08.153,ns_1@10.3.3.73:<0.20650.0>:couch_log:info:39]CouchDB swapping files /opt/couchbase/var/lib/couchbase/data/default/189.couch.24 and /opt/couchbase/var/lib/couchbase/data/default/189.couch.23.compact.
[couchdb:info,2012-08-22T17:46:08.156,ns_1@10.3.3.73:<0.20650.0>:couch_log:info:39]Compaction for db "default/189" completed.
[ns_server:info,2012-08-22T17:46:08.158,ns_1@10.3.3.73:<0.4313.4>:compaction_daemon:spawn_vbucket_compactor:640]Compacting <<"default/190">>
[couchdb:info,2012-08-22T17:46:08.158,ns_1@10.3.3.73:<0.20664.0>:couch_log:info:39]Starting compaction for db "default/190"
[couchdb:info,2012-08-22T17:46:08.160,ns_1@10.3.3.73:<0.4315.4>:couch_log:error:42]Error opening database set `default`: {db_open_error,<<"default/154">>,
                                       {not_found,no_db_file},
                                       <<"Couldn't open database `default/154`, reason: {not_found,no_db_file}">>}
initial partitions: [154,155,156,157,158,159,160,161,162,163,164,165,166,167,168,169,170,171,172,173,174,175,176,177,178,179,180,181,182,183,184,185,186,187,188,189,190,191,192,193,194,195,196,197,198,199,200,201,202,203,204,359,360,361,362,363,364,365,366,367,368,369,370,371,372,373,374,375,376,377,378,379,380,381,382,383,384,385,386,387,388,389,390,391,392,393,394,395,396,397,398,399,400,401,402,403,404,405,406,407,408,409,564,565,566,567,568,569,570,571,572,573,574,575,576,577,578,579,580,581,582,583,584,585,586,587,588,589,590,591,592,593,594,595,596,597,598,599,600,601,602,603,604,605,606,607,608,609,610,611,612,613,614,769,770,771,772,773,774,775,776,777,778,779,780,781,782,783,784,785,786,787,788,789,790,791,792,793,794,795,796,797,798,799,800,801,802,803,804,805,806,807,808,809,810,811,812,813,814,815,816,817,818,819]

[couchdb:info,2012-08-22T17:46:08.161,ns_1@10.3.3.73:<0.4308.4>:couch_log:error:42]couch_set_view_group error opening set view group `_design/dev_ddoc41`, signature `63cea0744ec01dbac6dc69cc22bc0376', from set `default`: {error,
                                                                                                                                           {db_open_error,
                                                                                                                                            <<"default/154">>,
                                                                                                                                            {not_found,
                                                                                                                                             no_db_file},
                                                                                                                                            <<"Couldn't open database `default/154`, reason: {not_found,no_db_file}">>}}
Show
Aleksey Kondratenko added a comment - Happens because of constant crashes in capi_set_view_manager on .73. Starts happening with this and I don't understand how this is possible at all: [ns_server:debug,2012-08-22T17:46:08.142, ns_1@10.3.3.73 :'capi_ddoc_replication_srv-default':cb_generic_replication_srv:handle_cast:131]Writing replicated ddoc {doc,<<"_design/dev_ddoc41">>,                              {1,<<"¡¾4ë">>},                              <<"{\"views\":{\"views0\":{\"map\":\"function (doc) { emit(doc.age, doc.first_name);}\"}}}">>,                              0,false,[]} [couchdb:info,2012-08-22T17:46:08.149, ns_1@10.3.3.73 :<0.4293.4>:couch_log:info:39]Native compactor output: Compacted /opt/couchbase/var/lib/couchbase/data/default/189.couch.23 -> /opt/cou [couchdb:info,2012-08-22T17:46:08.149, ns_1@10.3.3.73 :<0.4293.4>:couch_log:info:39]Native compactor output: chbase/var/lib/couchbase/data/default/189.couch.23.compact [couchdb:info,2012-08-22T17:46:08.150, ns_1@10.3.3.73 :<0.4293.4>:couch_log:info:39]Native initial compact succeeded for "default/189" [couchdb:info,2012-08-22T17:46:08.150, ns_1@10.3.3.73 :<0.19661.0>:couch_log:info:39]Database `default/master`, design document `_design/dev_ddoc41` updated (new revision: 1-a1be34eb, deleted: false) [views:debug,2012-08-22T17:46:08.152, ns_1@10.3.3.73 :<0.19667.0>:capi_set_view_manager:master_db_watcher:434]Got change in `_design/dev_ddoc41` design document. Initiating set view update [ns_server:info,2012-08-22T17:46:08.152, ns_1@10.3.3.73 :'capi_set_view_manager-default':capi_set_view_manager:handle_info:236]Processing update_ddoc _design/dev_ddoc41 (false) [views:info,2012-08-22T17:46:08.152, ns_1@10.3.3.73 :'capi_set_view_manager-default':capi_set_view_manager:maybe_define_group:300] Calling couch_set_view:define_group([<<"default">>,<<"_design/dev_ddoc41">>,                                      {set_view_params,1024,[],[],true}]) [couchdb:info,2012-08-22T17:46:08.153, ns_1@10.3.3.73 :<0.20650.0>:couch_log:info:39]CouchDB swapping files /opt/couchbase/var/lib/couchbase/data/default/189.couch.24 and /opt/couchbase/var/lib/couchbase/data/default/189.couch.23.compact. [couchdb:info,2012-08-22T17:46:08.156, ns_1@10.3.3.73 :<0.20650.0>:couch_log:info:39]Compaction for db "default/189" completed. [ns_server:info,2012-08-22T17:46:08.158, ns_1@10.3.3.73 :<0.4313.4>:compaction_daemon:spawn_vbucket_compactor:640]Compacting <<"default/190">> [couchdb:info,2012-08-22T17:46:08.158, ns_1@10.3.3.73 :<0.20664.0>:couch_log:info:39]Starting compaction for db "default/190" [couchdb:info,2012-08-22T17:46:08.160, ns_1@10.3.3.73 :<0.4315.4>:couch_log:error:42]Error opening database set `default`: {db_open_error,<<"default/154">>,                                        {not_found,no_db_file},                                        <<"Couldn't open database `default/154`, reason: {not_found,no_db_file}">>} initial partitions: [154,155,156,157,158,159,160,161,162,163,164,165,166,167,168,169,170,171,172,173,174,175,176,177,178,179,180,181,182,183,184,185,186,187,188,189,190,191,192,193,194,195,196,197,198,199,200,201,202,203,204,359,360,361,362,363,364,365,366,367,368,369,370,371,372,373,374,375,376,377,378,379,380,381,382,383,384,385,386,387,388,389,390,391,392,393,394,395,396,397,398,399,400,401,402,403,404,405,406,407,408,409,564,565,566,567,568,569,570,571,572,573,574,575,576,577,578,579,580,581,582,583,584,585,586,587,588,589,590,591,592,593,594,595,596,597,598,599,600,601,602,603,604,605,606,607,608,609,610,611,612,613,614,769,770,771,772,773,774,775,776,777,778,779,780,781,782,783,784,785,786,787,788,789,790,791,792,793,794,795,796,797,798,799,800,801,802,803,804,805,806,807,808,809,810,811,812,813,814,815,816,817,818,819] [couchdb:info,2012-08-22T17:46:08.161, ns_1@10.3.3.73 :<0.4308.4>:couch_log:error:42]couch_set_view_group error opening set view group `_design/dev_ddoc41`, signature `63cea0744ec01dbac6dc69cc22bc0376', from set `default`: {error,                                                                                                                                            {db_open_error,                                                                                                                                             <<"default/154">>,                                                                                                                                             {not_found,                                                                                                                                              no_db_file},                                                                                                                                             <<"Couldn't open database `default/154`, reason: {not_found,no_db_file}">>}}
Hide
Permalink
Filipe Manana added a comment -
Maybe there's an old index file left around. Was the bucket deleted and created, or something similar?
However the logs don't seem to show that.
Show
Filipe Manana added a comment - Maybe there's an old index file left around. Was the bucket deleted and created, or something similar? However the logs don't seem to show that.
Hide
Permalink
Iryna Mironava added a comment - - edited
yes, the bucket was deleted and created again when test was started
Show
Iryna Mironava added a comment - - edited yes, the bucket was deleted and created again when test was started
Hide
Permalink
Filipe Manana added a comment -
Then something went wrong in ns_server, didn't seem to cleanup everything.
Show
Filipe Manana added a comment - Then something went wrong in ns_server, didn't seem to cleanup everything.
Hide
Permalink
Aleksey Kondratenko added a comment -
I was thinking index files are automagically deleted when master vbucket is deleted. That's not the case ?
Show
Aleksey Kondratenko added a comment - I was thinking index files are automagically deleted when master vbucket is deleted. That's not the case ?
Hide
Permalink
Farshid Ghods added a comment -
regressions are marked as beta blockers
Show
Farshid Ghods added a comment - regressions are marked as beta blockers
Hide
Permalink
Filipe Manana added a comment -
Yep, if master database is deleted, and couch_set_view process is alive, it will delete index files.

What I see in the log of .73 is that the crash happens at line 194890:

[couchdb:info,2012-08-22T17:46:08.160,ns_1@10.3.3.73:<0.4315.4>:couch_log:error:42]Error opening database set `default`: {db_open_error,<<"default/154">>,
                                       {not_found,no_db_file},
                                       <<"Couldn't open database `default/154`, reason: {not_found,no_db_file}">>}

Before the crash several databases are deleted, but the master database is deleted only after the crash, at line 198096:

[couchdb:info,2012-08-22T17:46:19.251,ns_1@10.3.3.73:couch_server:couch_log:info:39]Deleting database default/master

Show
Filipe Manana added a comment - Yep, if master database is deleted, and couch_set_view process is alive, it will delete index files. What I see in the log of .73 is that the crash happens at line 194890: [couchdb:info,2012-08-22T17:46:08.160, ns_1@10.3.3.73 :<0.4315.4>:couch_log:error:42]Error opening database set `default`: {db_open_error,<<"default/154">>,                                        {not_found,no_db_file},                                        <<"Couldn't open database `default/154`, reason: {not_found,no_db_file}">>} Before the crash several databases are deleted, but the master database is deleted only after the crash, at line 198096: [couchdb:info,2012-08-22T17:46:19.251, ns_1@10.3.3.73 :couch_server:couch_log:info:39]Deleting database default/master
Hide
Permalink
Aleksey Kondratenko added a comment -
We merged fix we think
Show
Aleksey Kondratenko added a comment - We merged fix we think
Hide
Permalink
Thuan Nguyen added a comment -
Integrated in github-ns-server-2-0 #453 (See [http://qa.hq.northscale.net/job/github-ns-server-2-0/453/])
    MB-6385: delete remains of index files on bucket deletion (Revision aff9d82954b7accf1a8c4151889d29356ae2718b)

     Result = SUCCESS
Aliaksey Kandratsenka :
Files :
* src/ns_storage_conf.erl
Show
Thuan Nguyen added a comment - Integrated in github-ns-server-2-0 #453 (See [ http://qa.hq.northscale.net/job/github-ns-server-2-0/453/ ])      MB-6385 : delete remains of index files on bucket deletion (Revision aff9d82954b7accf1a8c4151889d29356ae2718b)      Result = SUCCESS Aliaksey Kandratsenka : Files : * src/ns_storage_conf.erl
Hide
Permalink
Ketaki Gangal added a comment -
Seeing this rebalance failure on build 1661, aug 30 on rebalancing nodes.
Show
Ketaki Gangal added a comment - Seeing this rebalance failure on build 1661, aug 30 on rebalancing nodes.
Hide
Permalink
Iryna Mironava added a comment -
verified
Show
Iryna Mironava added a comment - verified

People

  • Assignee:
    Iryna Mironava
    Reporter:
    Iryna Mironava
Vote (0)
Watch (3)

Dates

  • Created:
    Updated:
    Resolved: