Prepare join failed. Got HTTP status 500: initial call: ns_log:-start_link_crash_consumer/0-fun-0-/0 exception error: distribution_not_started

2.0.2-764-rel

http://qa.hq.northscale.net/view/2.0.1/job/ubuntu-32-2.0-swaprebalance-test-P0/49/consoleFull

./testrunner -i /tmp/swaprebalance-32.ini get-logs=True,GROUP=P0 -t swaprebalance.SwapRebalanceFailedTests.test_failed_swap_rebalance,replica=1,num-buckets=1,num-swap=3,percentage_progress=40,GROUP=P0

this is the first test after installation in suite

steps:
1.data loaded on cluster with 3 nodes: ns_1%4010.3.2.157%2Cns_1%4010.3.2.154%2Cns_1%4010.3.2.156
2.2013-04-14 07:14:20 | INFO | MainProcess | MainThread | [rest_client.add_node] adding remote node @10.3.2.158:8091 to this cluster @10.3.2.154:8091
2013-04-14 07:14:20 | ERROR | MainProcess | MainThread | [rest_client._http_request] http://10.3.2.154:8091/controller/addNode error 400 reason: unknown ["Prepare join failed. Got HTTP status 500 from REST call post to http://10.3.2.158:8091/engageCluster2. Body was: \"\\\"Unexpected server error, request logged.\\\"\""]
2013-04-14 07:14:20 | ERROR | MainProcess | MainThread | [rest_client.add_node] add_node error : ["Prepare join failed. Got HTTP status 500 from REST call post to http://10.3.2.158:8091/engageCluster2. Body was: \"\\\"Unexpected server error, request logged.\\\"\""]

logs on 154 node:
[cluster:debug,2013-04-14T7:27:14.698,ns_1@10.3.2.154:ns_cluster<0.280.0>:ns_cluster:handle_call:134]handling add_node("10.3.2.158", 8091, ..)

[cluster:debug,2013-04-14T7:27:14.708,ns_1@10.3.2.154:ns_cluster<0.280.0>:ns_cluster:do_add_node_with_connectivity:413]Posting node info to engage_cluster on

{"10.3.2.158",8091}:
{struct,
[{<<"requestedTargetNodeHostname">>,<<"10.3.2.158">>},
{availableStorage,
{struct,
[{hdd,
[{struct,
[{path,<<"/">>},
{sizeKBytes,50136788},
{usagePercent,8}]},
{struct,
[{path,<<"/dev">>},
{sizeKBytes,1544124},
{usagePercent,1}]},
{struct,
[{path,<<"/dev/shm">>},
{sizeKBytes,1548376},
{usagePercent,1}]},
{struct,
[{path,<<"/var/run">>},
{sizeKBytes,1548376},
{usagePercent,1}]},
{struct,
[{path,<<"/var/lock">>},
{sizeKBytes,1548376},
{usagePercent,0}]},
{struct,
[{path,<<"/lib/init/rw">>},
{sizeKBytes,1548376},
{usagePercent,0}]},
{struct,
[{path,<<"/var/lib/ureadahead/debugfs">>},
{sizeKBytes,50136788},
{usagePercent,8}]}]}]}},
{memoryQuota,1612},
{storageTotals,
{struct,
[{ram,
{struct,
[{total,3171074048},
{quotaTotal,1690304512},
{quotaUsed,1126170624},
{used,1452965888},
{usedByData,49892936}]}},
{hdd,
{struct,
[{total,51340070912},
{quotaTotal,51340070912},
{used,4107205672},
{usedByData,60938988},
{free,47232865240}]}}]}},
{storage,
{struct,
[{ssd,[]},
{hdd,
[{struct,
[{path,<<"/opt/couchbase/var/lib/couchbase/data">>},
{index_path, <<"/opt/couchbase/var/lib/couchbase/data">>},
{quotaMb,none},
{state,ok}]}]}]}},
{systemStats,
{struct,
[{cpu_utilization_rate,19.801980198019802},
{swap_total,1524621312},
{swap_used,37068800},
{minor_faults,5673},
{major_faults,0},
{page_faults,5673}]}},
{interestingStats,
{struct,
[{couch_docs_actual_disk_size,60938988},
{couch_docs_data_size,60846884},
{couch_views_actual_disk_size,0},
{couch_views_data_size,0},
{curr_items,32175},
{curr_items_tot,64465},
{mem_used,49892936},
{vb_replica_curr_items,32290}]}},
{uptime,<<"489">>},
{memoryTotal,3171074048},
{memoryFree,1718108160},
{mcdMemoryReserved,2419},
{mcdMemoryAllocated,2419},
{couchApiBase,<<"http://10.3.2.154:8092/">>},
{otpNode,<<"ns_1@10.3.2.154">>},
{otpCookie,<<"jjznjstrefpanrku">>},
{clusterMembership,<<"active">>},
{status,<<"healthy">>},
{thisNode,true},
{hostname,<<"10.3.2.154:8091">>},
{clusterCompatibility,131072},
{version,<<"2.0.2-764-rel-enterprise">>},
{os,<<"i686-pc-linux-gnu">>},
{ports,{struct,[{proxy,11211},{direct,11210}]}}]}

[cluster:debug,2013-04-14T7:27:14.817,ns_1@10.3.2.154:ns_cluster<0.280.0>:ns_cluster:do_add_node_with_connectivity:420]Reply from engage_cluster on {"10.3.2.158",8091}

:
{error,rest_error,
<<"Got HTTP status 500 from REST call post to http://10.3.2.158:8091/engageCluster2. Body was: \"\\\"Unexpected server error, request logged.\\\"\"">>,
{bad_status,500,<<"[\"Unexpected server error, request logged.\"]">>}}

[cluster:debug,2013-04-14T7:27:14.818,ns_1@10.3.2.154:ns_cluster<0.280.0>:ns_cluster:handle_call:136]add_node("10.3.2.158", 8091, ..) -> {error,engage_cluster,
<<"Prepare join failed. Got HTTP status 500 from REST call post to http://10.3.2.158:8091/engageCluster2. Body was: \"\\\"Unexpected server error, request logged.\\\"\"">>,
{error,rest_error,
<<"Got HTTP status 500 from REST call post to http://10.3.2.158:8091/engageCluster2. Body was: \"\\\"Unexpected server error, request logged.\\\"\"">>,

{bad_status,500, <<"[\"Unexpected server error, request logged.\"]">>}

}}

[user:info,2013-04-14T7:27:14.818,ns_1@10.3.2.154:<0.16197.1>:ns_cluster:add_node:75]Failed to add node 10.3.2.158:8091 to cluster. Prepare join failed. Got HTTP status 500 from REST call post to http://10.3.2.158:8091/engageCluster2. Body was: "[\"Unexpected server error, request logged.\"]"

on node 158

[ns_server:debug,2013-04-14T7:27:14.767,ns_1@10.3.2.158:<0.1846.0>:ns_node_disco:do_nodes_wanted_updated_fun:202]ns_node_disco: nodes_wanted updated: ['ns_1@10.3.2.158'], with cookie: uhyxemnvxinuuiul
[ns_server:debug,2013-04-14T7:27:14.767,ns_1@10.3.2.158:<0.1846.0>:ns_node_disco:do_nodes_wanted_updated_fun:208]ns_node_disco: nodes_wanted pong: ['ns_1@10.3.2.158'], with cookie: uhyxemnvxinuuiul
[ns_server:info,2013-04-14T7:27:14.767,ns_1@10.3.2.158:mb_master<0.338.0>:mb_master:terminate:302]Synchronously shutting down child mb_master_sup
[ns_server:debug,2013-04-14T7:27:14.769,ns_1@10.3.2.158:ns_config_log<0.290.0>:ns_config_log:log_common:111]config change:

{node,'ns_1@10.3.2.158',port_servers}

->
[{moxi,"/opt/couchbase/bin/moxi",
["-Z",

{"port_listen=~B,default_bucket_name=default,downstream_max=1024,downstream_conn_max=4,connect_max_errors=5,connect_retry_interval=30000,connect_timeout=400,auth_timeout=100,cycle=200,downstream_conn_queue_timeout=200,downstream_timeout=5000,wait_queue_timeout=200", [port]}

,
"-z",
{"url=http://127.0.0.1:~B/pools/default/saslBucketsStreaming",
[

{misc,this_node_rest_port,[]}

]},
"-p","0","-Y","y","-O","stderr",

{"~s",[verbosity]}],
[{env,[{"EVENT_NOSELECT","1"},
{"MOXI_SASL_PLAIN_USR",{"~s",[{ns_moxi_sup,rest_user,[]}]}},
{"MOXI_SASL_PLAIN_PWD",{"~s",[{ns_moxi_sup,rest_pass,[]}]}}]},
use_stdio,exit_status,port_server_send_eol,stderr_to_stdout,stream]},
{memcached,"/opt/couchbase/bin/memcached",
["-X","/opt/couchbase/lib/memcached/stdin_term_handler.so","-X",
{"/opt/couchbase/lib/memcached/file_logger.so,cyclesize=~B;sleeptime=~B;filename=~s/~s", [log_cyclesize,log_sleeptime,log_path,log_prefix]},
"-l",
{"0.0.0.0:~B,0.0.0.0:~B:1000",[port,dedicated_port]},
"-p",
{"~B",[port]},
"-E","/opt/couchbase/lib/memcached/bucket_engine.so","-B",
"binary","-r","-c","10000","-e",
{"admin=~s;default_bucket_name=default;auto_create=false", [admin_user]},
{"~s",[verbosity]}

],
[{env,[

{"EVENT_NOSELECT","1"}

,

{"MEMCACHED_TOP_KEYS","100"}

,
{"ISASL_PWFILE",{"~s",[

{isasl,path}

]}},

{"ISASL_DB_CHECK_TIME","1"}

]},
use_stdio,stderr_to_stdout,exit_status,port_server_send_eol,
stream]}]
[ns_server:debug,2013-04-14T7:27:14.770,ns_1@10.3.2.158:<0.333.0>:ns_pubsub:do_subscribe_link:136]Parent process of subscription

{ns_config_events,<0.332.0>}

exited with reason shutdown
[ns_server:debug,2013-04-14T7:27:14.770,ns_1@10.3.2.158:<0.339.0>:ns_pubsub:do_subscribe_link:136]Parent process of subscription

{ns_config_events,<0.338.0>}

exited with reason shutdown
[ns_server:debug,2013-04-14T7:27:14.771,ns_1@10.3.2.158:<0.418.0>:ns_pubsub:do_subscribe_link:136]Parent process of subscription

{ns_config_events,<0.417.0>}

exited with reason shutdown
[ns_server:debug,2013-04-14T7:27:14.771,ns_1@10.3.2.158:<0.414.0>:ns_pubsub:do_subscribe_link:136]Parent process of subscription

{ns_config_events,<0.413.0>}

exited with reason shutdown
[ns_server:debug,2013-04-14T7:27:14.771,ns_1@10.3.2.158:<0.416.0>:ns_pubsub:do_subscribe_link:136]Parent process of subscription

{ns_node_disco_events,<0.415.0>}

exited with reason shutdown
[ns_server:debug,2013-04-14T7:27:14.771,ns_1@10.3.2.158:ns_config_log<0.290.0>:ns_config_log:log_common:111]config change:

{node,'ns_1@10.3.2.158',ns_log}

->
[

{filename,"/opt/couchbase/var/lib/couchbase/data/ns_log"}

]
[ns_server:debug,2013-04-14T7:27:14.771,ns_1@10.3.2.158:ns_config_log<0.290.0>:ns_config_log:log_common:111]config change:

{node,'ns_1@10.3.2.158',moxi}

->
[

{port,11211}

,

{verbosity,[]}]
[ns_server:debug,2013-04-14T7:27:14.772,ns_1@10.3.2.158:ns_config_log<0.290.0>:ns_config_log:log_common:111]config change: {node,'ns_1@10.3.2.158',memcached} ->
[{mccouch_port,11213},
{engines,
[{membase,
[{engine,"/opt/couchbase/lib/memcached/ep.so"},
{static_config_string, "vb0=false;waitforwarmup=false;failpartialwarmup=false"}]},
{memcached,
[{engine,"/opt/couchbase/lib/memcached/default_engine.so"},
{static_config_string,"vb0=true"}]}]},
{log_path,"/opt/couchbase/var/lib/couchbase/logs"},
{log_prefix,"memcached.log"},
{log_generations,10},
{log_cyclesize,104857600},
{log_sleeptime,19},
{log_rotation_period,39003},
{dedicated_port,11209},
{bucket_engine,"/opt/couchbase/lib/memcached/bucket_engine.so"},
{port,11210},
{dedicated_port,11209},
{admin_user,"_admin"},
{admin_pass,"_admin"},
{verbosity,[]}

]
[ns_server:debug,2013-04-14T7:27:14.772,ns_1@10.3.2.158:ns_config_log<0.290.0>:ns_config_log:log_common:111]config change:

{node,'ns_1@10.3.2.158',membership}

->
active
[ns_server:debug,2013-04-14T7:27:14.772,ns_1@10.3.2.158:ns_config_log<0.290.0>:ns_config_log:log_common:111]config change:

{node,'ns_1@10.3.2.158',isasl}

->
[

{path,"/opt/couchbase/var/lib/couchbase/data/isasl.pw"}

]
[ns_server:debug,2013-04-14T7:27:14.772,ns_1@10.3.2.158:ns_config_log<0.290.0>:ns_config_log:log_common:111]config change:

{node,'ns_1@10.3.2.158',compaction_daemon}

->
[

{check_interval,30}

,

{min_file_size,131072}

]
[error_logger:error,2013-04-14T7:27:14.754,ns_1@10.3.2.158:error_logger<0.6.0>:ale_error_logger_handler:log_report:72]
=========================CRASH REPORT=========================
crasher:
initial call: ns_ports_setup:setup_body/0
pid: <0.1816.0>
registered_name: ns_ports_setup
exception error: no match of right hand side value false
in function ns_ports_setup:dynamic_children/0
in call from ns_ports_setup:setup_body/0
ancestors: [ns_server_sup,ns_server_cluster_sup,<0.59.0>]
messages: []
links: [<0.295.0>,<0.1836.0>]
dictionary: []
trap_exit: false
status: running
heap_size: 10946
stack_size: 24
reductions: 796
neighbours:

[error_logger:info,2013-04-14T7:27:14.777,ns_1@10.3.2.158:error_logger<0.6.0>:ale_error_logger_handler:log_report:72]
=========================PROGRESS REPORT=========================
supervisor:

{local,net_sup}
started: [{pid,<0.1838.0>},
{name,erl_epmd},
{mfargs,{erl_epmd,start_link,[]}},
{restart_type,permanent},
{shutdown,2000},
{child_type,worker}]

[error_logger:info,2013-04-14T7:27:14.777,ns_1@10.3.2.158:error_logger<0.6.0>:ale_error_logger_handler:log_report:72]
=========================PROGRESS REPORT=========================
supervisor: {local,net_sup}

started: [

{pid,<0.1839.0>}

,

{name,auth}

,
{mfargs,{auth,start_link,[]}},

{restart_type,permanent},
{shutdown,2000},
{child_type,worker}]

[error_logger:info,2013-04-14T7:27:14.778,ns_1@10.3.2.158:error_logger<0.6.0>:ale_error_logger_handler:log_report:72]
=========================PROGRESS REPORT=========================
supervisor: {local,net_sup}
started: [{pid,<0.1840.0>},
{name,net_kernel},
{mfargs,
{net_kernel,start_link,
[['ns_1@10.3.2.158',longnames]]}},
{restart_type,permanent}

,

{shutdown,2000}

,

{child_type,worker}]

[error_logger:info,2013-04-14T7:27:14.778,ns_1@10.3.2.158:error_logger<0.6.0>:ale_error_logger_handler:log_report:72]
=========================PROGRESS REPORT=========================
supervisor: {local,kernel_sup}
started: [{pid,<0.1837.0>},
{name,net_sup_dynamic},
{mfargs,
{erl_distribution,start_link,
[['ns_1@10.3.2.158',longnames]]}},
{restart_type,permanent},
{shutdown,1000},
{child_type,supervisor}]

[ns_server:debug,2013-04-14T7:27:14.777,ns_1@10.3.2.158:ns_config_log<0.290.0>:ns_config_log:log_common:111]config change: {node,'ns_1@10.3.2.158',capi_port} ->
8092
[ns_server:debug,2013-04-14T7:27:14.785,ns_1@10.3.2.158:ns_config_log<0.290.0>:ns_config_log:log_common:111]config change:
nodes_wanted ->
['ns_1@10.3.2.158']
[ns_server:debug,2013-04-14T7:27:14.785,ns_1@10.3.2.158:ns_config_log<0.290.0>:ns_config_log:log_common:111]config change: {node,'ns_1@10.3.2.158',config_version} -> {2,0}
[error_logger:info,2013-04-14T7:27:14.778,ns_1@10.3.2.158:error_logger<0.6.0>:ale_error_logger_handler:log_report:72]
=========================PROGRESS REPORT=========================
supervisor: {local,ns_server_sup}
started: [{pid,<0.1850.0>},
{name,ns_doctor},
{mfa,{ns_doctor,start_link,[]}},
{restart_type,permanent},
{shutdown,1000},
{child_type,worker}

]

[error_logger:error,2013-04-14T7:27:14.785,ns_1@10.3.2.158:error_logger<0.6.0>:ale_error_logger_handler:log_msg:76]** gen_event handler

{ns_pubsub,#Ref<0.0.0.1745>}

crashed.

• • Was installed in master_activity_events_ingress
  • Last event was: {submit_master_event,
    Unknown macro: {name_changed,'ns_1@10.3.2.158'}

    }

  • When handler state == {state,#Fun<master_activity_events.2.37655346>,[]}
  • Reason == {shutdown,
    Unknown macro: {gen_fsm,sync_send_all_state_event, [mb_master,master_node]}

    }

[error_logger:error,2013-04-14T7:27:14.786,ns_1@10.3.2.158:error_logger<0.6.0>:ale_error_logger_handler:log_report:72]
=========================CRASH REPORT=========================
crasher:
initial call: ns_pubsub:do_subscribe_link/4
pid: <0.359.0>
registered_name: []
exception exit: {handler_crashed,master_activity_events_ingress,
{'EXIT',
{shutdown,
{gen_fsm,sync_send_all_state_event,
[mb_master,master_node]}}}}
in function ns_pubsub:do_subscribe_link/4
ancestors: [ns_server_sup,ns_server_cluster_sup,<0.59.0>]
messages: []
links: [<0.295.0>,<0.358.0>]
dictionary: []
trap_exit: true
status: running
heap_size: 233
stack_size: 24
reductions: 113
neighbours:

[error_logger:error,2013-04-14T7:27:14.786,ns_1@10.3.2.158:error_logger<0.6.0>:ale_error_logger_handler:log_report:72]
=========================SUPERVISOR REPORT=========================
Supervisor:

{local,ns_server_sup}
Context: child_terminated
Reason: {handler_crashed,master_activity_events_ingress,
{'EXIT',
{shutdown,
{gen_fsm,sync_send_all_state_event,
[mb_master,master_node]}}}}
Offender: [{pid,<0.359.0>},
{name,master_activity_events_timestamper},
{mfa,{master_activity_events,start_link_timestamper,[]}},
{restart_type,permanent},
{shutdown,brutal_kill},
{child_type,worker}]


[error_logger:error,2013-04-14T7:27:14.787,ns_1@10.3.2.158:error_logger<0.6.0>:ale_error_logger_handler:log_report:72]
=========================SUPERVISOR REPORT=========================
Supervisor: {local,ns_server_sup}

Context: shutdown
Reason: reached_max_restart_intensity
Offender: [

{pid,<0.359.0>}

,

{name,master_activity_events_timestamper}

,
{mfa,{master_activity_events,start_link_timestamper,[]}},

{restart_type,permanent},
{shutdown,brutal_kill},
{child_type,worker}]


[ns_server:debug,2013-04-14T7:27:14.806,ns_1@10.3.2.158:<0.411.0>:ns_pubsub:do_subscribe_link:136]Parent process of subscription {ns_stats_event,<0.410.0>} exited with reason shutdown
[ns_server:debug,2013-04-14T7:27:14.807,ns_1@10.3.2.158:<0.407.0>:ns_pubsub:do_subscribe_link:136]Parent process of subscription {ns_config_events,<0.406.0>} exited with reason shutdown
[error_logger:error,2013-04-14T7:27:14.807,ns_1@10.3.2.158:error_logger<0.6.0>:ale_error_logger_handler:log_report:72]
=========================SUPERVISOR REPORT=========================
Supervisor: {local,ns_bucket_sup}
Context: shutdown_error
Reason: normal
Offender: [{pid,<0.407.0>},
{name,buckets_observing_subscription},
{mfargs,{ns_bucket_sup,subscribe_on_config_events,[]}},
{restart_type,permanent}

,

{shutdown,1000}

,

{child_type,worker}

]

[ns_server:debug,2013-04-14T7:27:14.808,ns_1@10.3.2.158:<0.394.0>:ns_pubsub:do_subscribe_link:136]Parent process of subscription

{ns_config_events,<0.389.0>}

exited with reason killed
[ns_server:debug,2013-04-14T7:27:14.809,ns_1@10.3.2.158:<0.331.0>:ns_pubsub:do_subscribe_link:136]Parent process of subscription

{buckets_events,<0.330.0>}

exited with reason shutdown
[ns_server:debug,2013-04-14T7:27:14.809,ns_1@10.3.2.158:<0.362.0>:ns_pubsub:do_subscribe_link:136]Parent process of subscription

{master_activity_events,<0.361.0>}

exited with reason killed
[ns_server:debug,2013-04-14T7:27:14.809,ns_1@10.3.2.158:<0.321.0>:ns_pubsub:do_subscribe_link:136]Parent process of subscription

{ns_config_events,<0.320.0>}

exited with reason killed
[ns_server:debug,2013-04-14T7:27:14.810,ns_1@10.3.2.158:<0.316.0>:ns_pubsub:do_subscribe_link:136]Parent process of subscription

{ns_config_events_local,<0.315.0>}

exited with reason shutdown
[ns_server:debug,2013-04-14T7:27:14.810,ns_1@10.3.2.158:<0.1851.0>:ns_pubsub:do_subscribe_link:136]Parent process of subscription

{ns_config_events,<0.1850.0>}

exited with reason shutdown
[ns_server:debug,2013-04-14T7:27:14.811,ns_1@10.3.2.158:<0.301.0>:ns_pubsub:do_subscribe_link:136]Parent process of subscription

{ns_config_events,<0.300.0>}

exited with reason killed
[ns_server:debug,2013-04-14T7:27:14.811,ns_1@10.3.2.158:<0.409.0>:ns_pubsub:do_subscribe_link:136]Parent process of subscription

{ns_tick_event,<0.408.0>}

exited with reason shutdown
[error_logger:error,2013-04-14T7:27:14.812,ns_1@10.3.2.158:error_logger<0.6.0>:ale_error_logger_handler:log_report:72]
=========================SUPERVISOR REPORT=========================
Supervisor:

{local,ns_server_cluster_sup}

Context: child_terminated
Reason: shutdown
Offender: [

{pid,<0.295.0>}

,

{name,ns_server_sup}

,
{mfargs,{ns_server_sup,start_link,[]}},

{restart_type,permanent}

,

{shutdown,infinity}

,

{child_type,supervisor}

]

[ns_server:info,2013-04-14T7:27:14.813,ns_1@10.3.2.158:ns_server_sup<0.1857.0>:dir_size:start_link:47]Starting quick version of dir_size with program name: i386-linux-godu
[menelaus:warn,2013-04-14T7:27:14.812,ns_1@10.3.2.158:<0.403.0>:menelaus_web:loop:441]Server error during processing: ["web request failed",

{path,"/engageCluster2"}

,

{type,exit}

,
{what,
{{shutdown,
{gen_server,call,
[ns_server_sup,

{restart_child,mb_master}

,
infinity]}},

The test does not kill couchbase on node 158 during execution