Details
Description
./testrunner -i /tmp/ubuntu-64-2.0-cbrecovery-P1.ini get-cbcollect-info=True -t cbRecoverytests.cbrecovery.restart_cbrecover_multiple_failover_swapout_reb_routine,items=100000,rdirection=unidirection,ctopology=chain,failover=destination,fail_count=2,add_count=0,max_verify=10000,when_step=rebalance_when_recovering
http://qa.hq.northscale.net/job/ubuntu_x64--38_01--cbrecovery-P1/37/console
steps:
1) source rebalance params : password=password&ejectedNodes=&user=Administrator&knownNodes=ns_1%4010.3.3.233%2Cns_1%4010.3.5.46%2Cns_1%4010.1.3.72
destination rebalance params : password=password&ejectedNodes=&user=Administrator&knownNodes=ns_1%4010.1.4.31%2Cns_1%4010.3.3.141%2Cns_1%4010.1.3.71
2) Failing over 2 nodes on destination: 10.1.3.71:8091 & 10.1.4.31:8091
then we start recovery 10.3.3.233 -> 10.3.3.141
and during recovery try to rebalance failovered nodes on destination(rebalance failed as expected)
but recovery stuck
command was executed: '/opt/couchbase/bin/cbrecovery http://10.3.3.233:8091 http://10.3.3.141:8091 -b default -B default -u Administrator -p password -U Administrator -P password '
[2014-05-07 16:13:11,297] - [task:2875] INFO - cbrecovery strarted with progress: {u'code': u'ok', u'uuid': u'3d1b8a425881bb68fdad5787e78a5d32', u'recoveryMap': [
]}
[2014-05-07 16:13:11,298] - [task:2876] INFO - will not wait for the end of the cbrecovery
[2014-05-07 16:13:11,316] - [rest_client:1076] INFO - rebalance params : password=password&ejectedNodes=&user=Administrator&knownNodes=ns_1%4010.1.4.31%2Cns_1%4010.3.3.141%2Cns_1%4010.1.3.71
[2014-05-07 16:13:11,327] - [task:2894] INFO - cbrecovery progress: {u'code': u'ok', u'uuid': u'3d1b8a425881bb68fdad5787e78a5d32', u'recoveryMap': [
]}
[2014-05-07 16:13:11,336] - [rest_client:736] ERROR - http://10.3.3.141:8091/controller/rebalance error 503 reason: status: 503, content: Cluster is in recovery mode. Cluster is in recovery mode.
[2014-05-07 16:13:11,337] - [rest_client:1082] ERROR - rebalance operation failed: Cluster is in recovery mode.
[2014-05-07 16:13:11,337] - [cbRecoverytests:379] INFO - can't call rebalance during cbrecovery as expected
[2014-05-07 16:13:11,387] - [remote_util:136] INFO - connecting to 10.3.3.233 with username : root password : couchbase ssh_key:
[2014-05-07 16:13:11,827] - [remote_util:168] INFO - Connected to 10.3.3.233
[2014-05-07 16:13:13,118] - [remote_util:1449] INFO - running command.raw on 10.3.3.233: sudo cat /proc/cpuinfo
[2014-05-07 16:13:13,841] - [remote_util:1478] INFO - command executed successfully
[2014-05-07 16:13:13,848] - [remote_util:1449] INFO - running command.raw on 10.3.3.233: df -Th
[2014-05-07 16:13:14,338] - [remote_util:1478] INFO - command executed successfully
[2014-05-07 16:13:14,339] - [remote_util:1449] INFO - running command.raw on 10.3.3.233: sudo cat /proc/meminfo
[2014-05-07 16:13:14,473] - [remote_util:1478] INFO - command executed successfully
[2014-05-07 16:13:14,474] - [remote_util:1449] INFO - running command.raw on 10.3.3.233: hostname
[2014-05-07 16:13:14,578] - [remote_util:1478] INFO - command executed successfully
[2014-05-07 16:13:14,578] - [remote_util:1449] INFO - running command.raw on 10.3.3.233: hostname -d
[2014-05-07 16:13:14,877] - [remote_util:1478] INFO - command executed successfully
[2014-05-07 16:13:16,385] - [task:2861] INFO - command was executed: '/opt/couchbase/bin/cbrecovery http://10.3.3.233:8091 http://10.3.3.141:8091 -b default -B default -u Administrator -p password -U Administrator -P password '
[2014-05-07 16:13:36,722] - [task:2894] INFO - cbrecovery progress: {u'code': u'ok', u'uuid': u'3d1b8a425881bb68fdad5787e78a5d32', u'recoveryMap': [
]}
[2014-05-07 16:13:57,866] - [task:2894] INFO - cbrecovery progress: {u'code': u'ok', u'uuid': u'3d1b8a425881bb68fdad5787e78a5d32', u'recoveryMap': [
]}
[2014-05-07 16:14:18,451] - [task:2894] INFO - cbrecovery progress: {u'code': u'ok', u'uuid': u'3d1b8a425881bb68fdad5787e78a5d32', u'recoveryMap': [
]}
[2014-05-07 16:14:38,678] - [task:2894] INFO - cbrecovery progress: {u'code': u'ok', u'uuid': u'3d1b8a425881bb68fdad5787e78a5d32', u'recoveryMap': [
]}
[2014-05-07 16:14:59,203] - [task:2894] INFO - cbrecovery progress: {u'code': u'ok', u'uuid': u'3d1b8a425881bb68fdad5787e78a5d32', u'recoveryMap': [
]}
[2014-05-07 16:15:19,895] - [task:2894] INFO - cbrecovery progress: {u'code': u'ok', u'uuid': u'3d1b8a425881bb68fdad5787e78a5d32', u'recoveryMap': [
]}
[2014-05-07 16:15:40,145] - [task:2894] INFO - cbrecovery progress: {u'code': u'ok', u'uuid': u'3d1b8a425881bb68fdad5787e78a5d32', u'recoveryMap': [
]}
[2014-05-07 16:16:00,495] - [task:2881] WARNING - cbrecovery progress was not changed
[2014-05-07 16:16:20,759] - [task:2881] WARNING - cbrecovery progress was not changed
[2014-05-07 16:16:41,058] - [task:2881] WARNING - cbrecovery progress was not changed
[2014-05-07 16:17:02,395] - [task:2881] WARNING - cbrecovery progress was not changed
[2014-05-07 16:17:23,323] - [task:2881] WARNING - cbrecovery progress was not changed
[2014-05-07 16:17:43,796] - [task:2881] WARNING - cbrecovery progress was not changed
[2014-05-07 16:18:04,616] - [task:2881] WARNING - cbrecovery progress was not changed
[2014-05-07 16:18:25,578] - [task:2881] WARNING - cbrecovery progress was not changed
[2014-05-07 16:18:46,115] - [task:2881] WARNING - cbrecovery progress was not changed
[2014-05-07 16:19:06,814] - [task:2881] WARNING - cbrecovery progress was not changed
[2014-05-07 16:19:27,838] - [task:2881] WARNING - cbrecovery progress was not changed
[2014-05-07 16:19:48,881] - [task:2881] WARNING - cbrecovery progress was not changed
[2014-05-07 16:20:09,395] - [task:2881] WARNING - cbrecovery progress was not changed
[2014-05-07 16:20:30,377] - [task:2881] WARNING - cbrecovery progress was not changed
[2014-05-07 16:20:50,637] - [task:2881] WARNING - cbrecovery progress was not changed
[2014-05-07 16:21:11,301] - [task:2881] WARNING - cbrecovery progress was not changed
[2014-05-07 16:21:32,126] - [task:2881] WARNING - cbrecovery progress was not changed
[2014-05-07 16:21:52,668] - [task:2881] WARNING - cbrecovery progress was not changed
[2014-05-07 16:22:13,775] - [task:2881] WARNING - cbrecovery progress was not changed
[2014-05-07 16:22:34,986] - [task:2881] WARNING - cbrecovery progress was not changed
[2014-05-07 16:22:55,726] - [task:2881] WARNING - cbrecovery progress was not changed
[2014-05-07 16:23:16,546] - [task:2881] WARNING - cbrecovery progress was not changed
[2014-05-07 16:23:17,394] - [rest_client:1935] INFO - Latest logs from UI on 10.3.3.141:
[2014-05-07 16:23:17,395] - [rest_client:1936] ERROR -
[2014-05-07 16:23:17,396] - [rest_client:1936] ERROR -
{u'node': u'ns_1@10.1.4.31', u'code': 0, u'text': u'Shutting down bucket "default" on \'ns_1@10.1.4.31\' for deletion', u'shortText': u'message', u'serverTime': u'2014-05-07T16:12:11.384Z', u'module': u'ns_memcached', u'tstamp': 1399504331384, u'type': u'info'}[2014-05-07 16:23:17,397] - [rest_client:1936] ERROR -
{u'node': u'ns_1@10.3.3.141', u'code': 0, u'text': u"Failed over 'ns_1@10.1.4.31': ok", u'shortText': u'message', u'serverTime': u'2014-05-07T16:12:10.560Z', u'module': u'ns_rebalancer', u'tstamp': 1399504330560, u'type': u'info'}[2014-05-07 16:23:17,398] - [rest_client:1936] ERROR -
{u'node': u'ns_1@10.3.3.141', u'code': 1, u'text': u'Data has been lost for 33% of vbuckets in bucket "default".', u'shortText': u'message', u'serverTime': u'2014-05-07T16:12:10.365Z', u'module': u'ns_rebalancer', u'tstamp': 1399504330365, u'type': u'info'}[2014-05-07 16:23:17,403] - [rest_client:1936] ERROR -
{u'node': u'ns_1@10.3.3.141', u'code': 0, u'text': u'Lost data in "default" for [0,1,2,3,4,5,6,7,8,9,10,11,12,13,14,15,16,17,18,19,20,21,22,23,24,25,26,27,28,29,30,31,32,33,34,35,36,37,38,39,40,41,42,43,44,45,46,47,48,49,50,51,52,53,54,55,56,57,58,59,60,61,62,63,64,65,66,67,68,69,70,71,72,73,74,75,76,77,78,79,80,81,82,83,84,85,86,87,88,89,90,91,92,93,94,95,96,97,98,99,100,101,102,103,104,105,106,107,108,109,110,111,112,113,114,115,116,117,118,119,120,121,122,123,124,125,126,127,128,129,130,131,132,133,134,135,136,137,138,139,140,141,142,143,144,145,146,147,148,149,150,151,152,153,154,155,156,157,158,159,160,161,162,163,164,165,166,167,168,169,170,342,343,344,345,346,347,348,349,350,351,352,353,354,355,356,357,358,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,410,411,412,413,414,415,416,417,418,419,420,421,422,423,424,425,426,427,428,429,430,431,432,433,434,435,436,437,438,439,440,441,442,443,444,445,446,447,448,449,450,451,452,453,454,455,456,457,458,459,460,461,462,463,464,465,466,467,468,469,470,471,472,473,474,475,476,477,478,479,480,481,482,483,484,485,486,487,488,489,490,491,492,493,494,495,496,497,498,499,500,501,502,503,504,505,506,507,508,509,510,511,512]', u'shortText': u'message', u'serverTime': u'2014-05-07T16:12:10.364Z', u'module': u'ns_rebalancer', u'tstamp': 1399504330364, u'type': u'critical'}[2014-05-07 16:23:17,404] - [rest_client:1936] ERROR -
{u'node': u'ns_1@10.1.3.71', u'code': 0, u'text': u'Shutting down bucket "default" on \'ns_1@10.1.3.71\' for deletion', u'shortText': u'message', u'serverTime': u'2014-05-07T16:12:10.361Z', u'module': u'ns_memcached', u'tstamp': 1399504330361, u'type': u'info'}[2014-05-07 16:23:17,404] - [rest_client:1936] ERROR -
{u'node': u'ns_1@10.3.3.141', u'code': 0, u'text': u"Starting failing over 'ns_1@10.1.4.31'", u'shortText': u'message', u'serverTime': u'2014-05-07T16:12:10.361Z', u'module': u'ns_rebalancer', u'tstamp': 1399504330361, u'type': u'info'}[2014-05-07 16:23:17,405] - [rest_client:1936] ERROR -
{u'node': u'ns_1@10.3.3.141', u'code': 0, u'text': u"Failed over 'ns_1@10.1.3.71': ok", u'shortText': u'message', u'serverTime': u'2014-05-07T16:12:09.618Z', u'module': u'ns_rebalancer', u'tstamp': 1399504329618, u'type': u'info'}[2014-05-07 16:23:17,406] - [rest_client:1936] ERROR -
{u'node': u'ns_1@10.3.3.141', u'code': 0, u'text': u"Starting failing over 'ns_1@10.1.3.71'", u'shortText': u'message', u'serverTime': u'2014-05-07T16:12:09.353Z', u'module': u'ns_rebalancer', u'tstamp': 1399504329353, u'type': u'info'}[2014-05-07 16:23:17,406] - [rest_client:1936] ERROR -
{u'node': u'ns_1@10.1.3.71', u'code': 0, u'text': u'Bucket "default" loaded on node \'ns_1@10.1.3.71\' in 0 seconds.', u'shortText': u'message', u'serverTime': u'2014-05-07T16:01:47.873Z', u'module': u'ns_memcached', u'tstamp': 1399503707873, u'type': u'info'}[2014-05-07 16:23:17,426] - [task:2886] WARNING - ns_server_tasks: [
{u'commitVBucketURI': u'/pools/default/buckets/default/controller/commitVBucket?recovery_uuid=3d1b8a425881bb68fdad5787e78a5d32', u'uuid': u'3d1b8a425881bb68fdad5787e78a5d32', u'bucket': u'default', u'stopURI': u'/pools/default/buckets/default/controller/stopRecovery?recovery_uuid=3d1b8a425881bb68fdad5787e78a5d32', u'recoveryStatusURI': u'/pools/default/buckets/default/recoveryStatus?recovery_uuid=3d1b8a425881bb68fdad5787e78a5d32', u'recommendedRefreshPeriod': 10, u'type': u'recovery'},
{u'status': u'notRunning', u'type': u'rebalance'}]
[2014-05-07 16:23:17,444] - [task:2887] WARNING - cbrecovery progress: {u'code': u'ok', u'uuid': u'3d1b8a425881bb68fdad5787e78a5d32', u'recoveryMap': [
]}
ERROR
CBRecoveryFailedException: CBRecovery Failed: cbrecovery hangs