[FTS] Indexing stuck following failover(hard) and add back in delta recovery (of the only fts node)

Test Input params:

{'logs_folder': '/data/workspace/cen006-p0-fts-vset02-00-moving-topology/logs/testrunner-16-Apr-01_00-53-53/test_18', 'GROUP': 'P0', 'items': '30000', 'conf_file': 'conf/fts/py-fts-movingtopology.conf', 'num_nodes': 5, 'cluster_name': 'INI_FILE', 'cluster': 'D,D+F', 'stop-on-failure': 'False', 'ini': 'INI_FILE.ini', 'case_number': 18, 'get-logs': 'False', 'get-cbcollect-info': 'True', 'index_retry': '10', 'spec': 'py-fts-movingtopology'}

[2016-04-01 03:44:15,939] - [fts_base:1913] INFO - ==== FTSbasetests setup is started for test #18 hard_failover_and_delta_recovery_during_index_building ====

[2016-04-01 03:44:15,965] - [rest_client:1618] INFO - Node 172.23.105.190 not part of cluster inactiveFailed

[2016-04-01 03:44:15,966] - [fts_base:902] INFO - removing nodes from cluster ...

[2016-04-01 03:44:15,990] - [fts_base:904] INFO - cleanup [ip:172.23.105.96 port:8091 ssh_username:root]

[2016-04-01 03:44:16,023] - [bucket_helper:137] INFO - deleting existing buckets [u'default'] on 172.23.105.96

[2016-04-01 03:44:16,023] - [bucket_helper:139] INFO - remove bucket default ...

[2016-04-01 03:44:18,139] - [bucket_helper:153] INFO - deleted bucket : default from 172.23.105.96

[2016-04-01 03:44:18,139] - [bucket_helper:226] INFO - waiting for bucket deletion to complete....

[2016-04-01 03:44:18,144] - [rest_client:127] INFO - node 172.23.105.96 existing buckets : []

[2016-04-01 03:44:18,177] - [cluster_helper:255] INFO - rebalancing all nodes in order to remove nodes

[2016-04-01 03:44:18,181] - [rest_client:1206] INFO - rebalance params : password=password&ejectedNodes=ns_1%40172.23.105.190&user=Administrator&knownNodes=ns_1%40172.23.105.96%2Cns_1%40172.23.105.190

[2016-04-01 03:44:18,188] - [rest_client:1210] INFO - rebalance operation started

[2016-04-01 03:44:18,222] - [rest_client:1338] INFO - rebalance percentage : 0.00 %

[2016-04-01 03:44:28,250] - [rest_client:1293] INFO - rebalance progress took 10.0611629486 seconds 

[2016-04-01 03:44:28,250] - [rest_client:1294] INFO - sleep for 10 seconds after rebalance...

[2016-04-01 03:44:38,273] - [cluster_helper:295] INFO - removed all the nodes from cluster associated with ip:172.23.105.96 port:8091 ssh_username:root ? [(u'ns_1@172.23.105.190', 8091)]

[2016-04-01 03:44:38,282] - [cluster_helper:78] INFO - waiting for ns_server @ 172.23.105.96:8091

[2016-04-01 03:44:38,288] - [cluster_helper:80] INFO - ns_server @ 172.23.105.96:8091 is running

[2016-04-01 03:44:38,289] - [fts_base:852] INFO - Initializing Cluster ...

[2016-04-01 03:44:38,984] - [rest_client:811] INFO - pools/default params : memoryQuota=2069

[2016-04-01 03:44:38,995] - [rest_client:830] INFO - settings/indexes params : storageMode=forestdb

[2016-04-01 03:44:39,007] - [rest_client:774] INFO - settings/web params on 172.23.105.96:8091:username=Administrator&password=password&port=8091

[2016-04-01 03:44:39,031] - [fts_base:868] INFO - 172.23.105.190 will be configured with services kv,fts

[2016-04-01 03:44:40,032] - [task:404] INFO - adding node 172.23.105.190:8091 to cluster

[2016-04-01 03:44:40,033] - [rest_client:988] INFO - adding remote node @172.23.105.190:8091 to this cluster @172.23.105.96:8091

[2016-04-01 03:44:45,395] - [rest_client:1206] INFO - rebalance params : password=password&ejectedNodes=&user=Administrator&knownNodes=ns_1%40172.23.105.96%2Cns_1%40172.23.105.190

[2016-04-01 03:44:45,408] - [rest_client:1210] INFO - rebalance operation started

[2016-04-01 03:44:45,423] - [rest_client:1338] INFO - rebalance percentage : 0.00 %

[2016-04-01 03:44:55,446] - [task:520] INFO - rebalancing was completed with progress: 100% in 10.0373678207 sec

[2016-04-01 03:44:56,677] - [rest_client:1772] INFO - http://172.23.105.96:8091/pools/default/buckets with param: bucketType=membase&evictionPolicy=valueOnly&threadsNumber=3&ramQuotaMB=1569&proxyPort=11211&authType=sasl&name=default&flushEnabled=1&replicaNumber=1&replicaIndex=1&saslPassword=None

[2016-04-01 03:44:56,690] - [rest_client:1794] INFO - 0.01 seconds to create bucket default

[2016-04-01 03:44:56,691] - [bucket_helper:305] INFO - waiting for memcached bucket : default in 172.23.105.96 to accept set ops

[2016-04-01 03:44:57,928] - [data_helper:295] INFO - creating direct client 172.23.105.190:11210 default

[2016-04-01 03:44:58,051] - [data_helper:295] INFO - creating direct client 172.23.105.96:11210 default

[2016-04-01 03:44:58,238] - [data_helper:295] INFO - creating direct client 172.23.105.190:11210 default

[2016-04-01 03:44:58,924] - [data_helper:295] INFO - creating direct client 172.23.105.96:11210 default

[2016-04-01 03:45:00,367] - [task:288] INFO - bucket 'default' was created with per node RAM quota: 1569

[2016-04-01 03:45:00,388] - [rest_client:1222] INFO - /diag/eval status on 172.23.105.96:8091: True content: "/opt/couchbase/var/lib/couchbase/logs" command: filename:absname(element(2, application:get_env(ns_server,error_logger_mf_dir))).

[2016-04-01 03:45:00,389] - [remote_util:168] INFO - connecting to 172.23.105.96 with username : root password : couchbase ssh_key: 

[2016-04-01 03:45:00,633] - [remote_util:201] INFO - Connected to 172.23.105.96

[2016-04-01 03:45:01,208] - [remote_util:2279] INFO - running command.raw on 172.23.105.96: zgrep "panic:" "/opt/couchbase/var/lib/couchbase/logs"/fts.log* | wc -l

[2016-04-01 03:45:01,311] - [remote_util:2316] INFO - command executed successfully

[2016-04-01 03:45:01,313] - [fts_base:2349] INFO - 0

[2016-04-01 03:45:01,313] - [remote_util:2279] INFO - running command.raw on 172.23.105.96: zgrep "SIGABRT: abort" "/opt/couchbase/var/lib/couchbase/logs"/fts.log* | wc -l

[2016-04-01 03:45:01,426] - [remote_util:2316] INFO - command executed successfully

[2016-04-01 03:45:01,427] - [fts_base:2349] INFO - 0

[2016-04-01 03:45:01,542] - [remote_util:168] INFO - connecting to 172.23.105.190 with username : root password : couchbase ssh_key: 

[2016-04-01 03:45:01,822] - [remote_util:201] INFO - Connected to 172.23.105.190

[2016-04-01 03:45:02,517] - [remote_util:2279] INFO - running command.raw on 172.23.105.190: zgrep "panic:" "/opt/couchbase/var/lib/couchbase/logs"/fts.log* | wc -l

[2016-04-01 03:45:02,624] - [remote_util:2316] INFO - command executed successfully

[2016-04-01 03:45:02,625] - [fts_base:2349] INFO - 0

[2016-04-01 03:45:02,625] - [remote_util:2279] INFO - running command.raw on 172.23.105.190: zgrep "SIGABRT: abort" "/opt/couchbase/var/lib/couchbase/logs"/fts.log* | wc -l

[2016-04-01 03:45:02,771] - [remote_util:2316] INFO - command executed successfully

[2016-04-01 03:45:02,772] - [fts_base:2349] INFO - 0

[2016-04-01 03:45:02,887] - [remote_util:168] INFO - connecting to 172.23.106.66 with username : root password : couchbase ssh_key: 

[2016-04-01 03:45:03,134] - [remote_util:201] INFO - Connected to 172.23.106.66

[2016-04-01 03:45:03,706] - [remote_util:2279] INFO - running command.raw on 172.23.106.66: zgrep "panic:" "/opt/couchbase/var/lib/couchbase/logs"/fts.log* | wc -l

[2016-04-01 03:45:03,853] - [remote_util:2316] INFO - command executed successfully

[2016-04-01 03:45:03,854] - [fts_base:2349] INFO - 0

[2016-04-01 03:45:03,854] - [remote_util:2279] INFO - running command.raw on 172.23.106.66: zgrep "SIGABRT: abort" "/opt/couchbase/var/lib/couchbase/logs"/fts.log* | wc -l

[2016-04-01 03:45:03,992] - [remote_util:2316] INFO - command executed successfully

[2016-04-01 03:45:03,993] - [fts_base:2349] INFO - 0

[2016-04-01 03:45:04,108] - [remote_util:168] INFO - connecting to 172.23.105.69 with username : root password : couchbase ssh_key: 

[2016-04-01 03:45:04,352] - [remote_util:201] INFO - Connected to 172.23.105.69

[2016-04-01 03:45:04,956] - [remote_util:2279] INFO - running command.raw on 172.23.105.69: zgrep "panic:" "/opt/couchbase/var/lib/couchbase/logs"/fts.log* | wc -l

[2016-04-01 03:45:05,070] - [remote_util:2316] INFO - command executed successfully

[2016-04-01 03:45:05,071] - [fts_base:2349] INFO - 0

[2016-04-01 03:45:05,072] - [remote_util:2279] INFO - running command.raw on 172.23.105.69: zgrep "SIGABRT: abort" "/opt/couchbase/var/lib/couchbase/logs"/fts.log* | wc -l

[2016-04-01 03:45:05,185] - [remote_util:2316] INFO - command executed successfully

[2016-04-01 03:45:05,185] - [fts_base:2349] INFO - 0

[2016-04-01 03:45:05,188] - [remote_util:168] INFO - connecting to 172.23.105.54 with username : root password : couchbase ssh_key: 

[2016-04-01 03:45:05,412] - [remote_util:201] INFO - Connected to 172.23.105.54

[2016-04-01 03:45:05,994] - [remote_util:2279] INFO - running command.raw on 172.23.105.54: zgrep "panic:" "/opt/couchbase/var/lib/couchbase/logs"/fts.log* | wc -l

[2016-04-01 03:45:06,119] - [remote_util:2316] INFO - command executed successfully

[2016-04-01 03:45:06,120] - [fts_base:2349] INFO - 0

[2016-04-01 03:45:06,121] - [remote_util:2279] INFO - running command.raw on 172.23.105.54: zgrep "SIGABRT: abort" "/opt/couchbase/var/lib/couchbase/logs"/fts.log* | wc -l

[2016-04-01 03:45:06,243] - [remote_util:2316] INFO - command executed successfully

[2016-04-01 03:45:06,244] - [fts_base:2349] INFO - 0

[2016-04-01 03:45:06,358] - [fts_base:2121] INFO - {'172.23.105.190': {'SIGABRT: abort': 0, 'panic:': 0}, '172.23.106.66': {'SIGABRT: abort': 0, 'panic:': 0}, '172.23.105.69': {'SIGABRT: abort': 0, 'panic:': 0}, '172.23.105.54': {'SIGABRT: abort': 0, 'panic:': 0}, '172.23.105.96': {'SIGABRT: abort': 0, 'panic:': 0}}

[2016-04-01 03:45:06,359] - [fts_base:1922] INFO - ==== FTSbasetests setup is finished for test #18 hard_failover_and_delta_recovery_during_index_building ====

[2016-04-01 03:45:12,377] - [data_helper:295] INFO - creating direct client 172.23.105.190:11210 default

[2016-04-01 03:45:12,485] - [data_helper:295] INFO - creating direct client 172.23.105.96:11210 default

[2016-04-01 03:45:26,854] - [fts_base:2698] INFO - Loading phase complete!

[2016-04-01 03:45:26,892] - [fts_base:607] INFO - Checking if index already exists ...

[2016-04-01 03:45:26,938] - [fts_base:615] INFO - Creating fulltext-index default_index_1 on 172.23.105.190

[2016-04-01 03:45:26,938] - [rest_client:2074] INFO - {"params": {}, "name": "default_index_1", "planParams": {"hierarchyRules": null, "nodePlanParams": null, "numReplicas": 1, "planFrozen": false, "maxPartitionsPerPIndex": 32}, "sourceName": "default", "sourceUUID": "", "sourceType": "couchbase", "type": "fulltext-index", "sourceParams": {"authUser": "default", "dataManagerSleepMaxMS": 20000, "authSaslUser": "", "clusterManagerSleepMaxMS": 20000, "authSaslPassword": "", "clusterManagerSleepInitMS": 0, "dataManagerBackoffFactor": 0, "authPassword": "", "dataManagerSleepInitMS": 0, "feedBufferAckThreshold": 0, "feedBufferSizeBytes": 0, "clusterManagerBackoffFactor": 0}, "uuid": ""}

[2016-04-01 03:45:26,995] - [rest_client:2083] INFO - Index default_index_1 created

[2016-04-01 03:45:28,078] - [fts_base:2476] INFO - Validated: Number of PIndexes = 32

[2016-04-01 03:45:28,093] - [fts_base:2487] INFO - Validated: Every pIndex serves 32 partitions or lesser

[2016-04-01 03:45:28,093] - [fts_base:2503] INFO - Validated: pIndexes are distributed across [u'ca5c64829de3d9e4630662c3b383bee5'] 

[2016-04-01 03:45:28,093] - [fts_base:2509] INFO - Expecting num of partitions in each node in range 992-1024

[2016-04-01 03:45:28,094] - [fts_base:2524] INFO - Validated: Node ca5c64829de3d9e4630662c3b383bee5 houses 32 pindexes which serve 1024 partitions

[2016-04-01 03:45:28,094] - [fts_base:2370] INFO - sleep for 10 secs.  ...

[2016-04-01 03:45:38,104] - [moving_topology_fts:176] INFO - Index building has begun...

[2016-04-01 03:45:38,234] - [moving_topology_fts:179] INFO - Index count for default_index_1: 2033

[2016-04-01 03:45:38,235] - [fts_base:1733] INFO - Starting failover for nodes:[ip:172.23.105.190 port:8091 ssh_username:root] at C1 cluster 172.23.105.96

[2016-04-01 03:45:38,893] - [task:3183] INFO - Failing over 172.23.105.190:8091 with graceful=False

[2016-04-01 03:45:39,658] - [rest_client:1151] INFO - fail_over node ns_1@172.23.105.190 successful

[2016-04-01 03:45:39,658] - [task:3163] INFO - 0 seconds sleep after failover, for nodes to go pending....

[2016-04-01 03:45:39,685] - [rest_client:1184] INFO - add_back_node ns_1@172.23.105.190 successful

[2016-04-01 03:45:39,686] - [rest_client:1158] INFO - Going to set recoveryType=delta for node :: ns_1@172.23.105.190

[2016-04-01 03:45:39,692] - [rest_client:1170] INFO - recoveryType for node ns_1@172.23.105.190 set successful

[2016-04-01 03:45:40,679] - [rest_client:1206] INFO - rebalance params : password=password&ejectedNodes=&user=Administrator&knownNodes=ns_1%40172.23.105.96%2Cns_1%40172.23.105.190

[2016-04-01 03:45:40,713] - [rest_client:1210] INFO - rebalance operation started

[2016-04-01 03:45:40,732] - [rest_client:1338] INFO - rebalance percentage : 0.00 %

[2016-04-01 03:45:50,751] - [rest_client:1338] INFO - rebalance percentage : 9.08 %

[2016-04-01 03:46:00,770] - [rest_client:1338] INFO - rebalance percentage : 34.28 %

[2016-04-01 03:46:10,788] - [rest_client:1338] INFO - rebalance percentage : 58.30 %

[2016-04-01 03:46:20,806] - [task:520] INFO - rebalancing was completed with progress: 100% in 40.0920901299 sec

[2016-04-01 03:46:20,897] - [fts_base:2476] INFO - Validated: Number of PIndexes = 32

[2016-04-01 03:46:20,909] - [fts_base:2487] INFO - Validated: Every pIndex serves 32 partitions or lesser

[2016-04-01 03:46:20,909] - [fts_base:2503] INFO - Validated: pIndexes are distributed across [u'ca5c64829de3d9e4630662c3b383bee5'] 

[2016-04-01 03:46:20,910] - [fts_base:2509] INFO - Expecting num of partitions in each node in range 992-1024

[2016-04-01 03:46:20,910] - [fts_base:2524] INFO - Validated: Node ca5c64829de3d9e4630662c3b383bee5 houses 32 pindexes which serve 1024 partitions

[2016-04-01 03:46:21,087] - [fts_base:2392] INFO - Docs in bucket = 30000, docs in FTS index 'default_index_1': 8561

[2016-04-01 03:46:31,250] - [fts_base:2392] INFO - Docs in bucket = 30000, docs in FTS index 'default_index_1': 10785

[2016-04-01 03:46:41,408] - [fts_base:2392] INFO - Docs in bucket = 30000, docs in FTS index 'default_index_1': 12826

[2016-04-01 03:46:51,547] - [fts_base:2392] INFO - Docs in bucket = 30000, docs in FTS index 'default_index_1': 15030

[2016-04-01 03:47:01,735] - [fts_base:2392] INFO - Docs in bucket = 30000, docs in FTS index 'default_index_1': 17176

[2016-04-01 03:47:12,092] - [fts_base:2392] INFO - Docs in bucket = 30000, docs in FTS index 'default_index_1': 19541

[2016-04-01 03:47:22,306] - [fts_base:2392] INFO - Docs in bucket = 30000, docs in FTS index 'default_index_1': 22043

[2016-04-01 03:47:32,564] - [fts_base:2392] INFO - Docs in bucket = 30000, docs in FTS index 'default_index_1': 24363

[2016-04-01 03:47:42,690] - [fts_base:2392] INFO - Docs in bucket = 30000, docs in FTS index 'default_index_1': 26710

[2016-04-01 03:47:52,819] - [fts_base:2392] INFO - Docs in bucket = 30000, docs in FTS index 'default_index_1': 28527

[2016-04-01 03:48:02,993] - [fts_base:2392] INFO - Docs in bucket = 30000, docs in FTS index 'default_index_1': 28527

[2016-04-01 03:48:13,231] - [fts_base:2392] INFO - Docs in bucket = 30000, docs in FTS index 'default_index_1': 28527

[2016-04-01 03:48:23,412] - [fts_base:2392] INFO - Docs in bucket = 30000, docs in FTS index 'default_index_1': 28527

[2016-04-01 03:48:33,561] - [fts_base:2392] INFO - Docs in bucket = 30000, docs in FTS index 'default_index_1': 28527

[2016-04-01 03:48:43,722] - [fts_base:2392] INFO - Docs in bucket = 30000, docs in FTS index 'default_index_1': 28527

[2016-04-01 03:48:53,850] - [fts_base:2392] INFO - Docs in bucket = 30000, docs in FTS index 'default_index_1': 28527

[2016-04-01 03:49:04,020] - [fts_base:2392] INFO - Docs in bucket = 30000, docs in FTS index 'default_index_1': 28527

[2016-04-01 03:49:14,173] - [fts_base:2392] INFO - Docs in bucket = 30000, docs in FTS index 'default_index_1': 28527

[2016-04-01 03:49:24,338] - [fts_base:2392] INFO - Docs in bucket = 30000, docs in FTS index 'default_index_1': 28527

[2016-04-01 03:49:34,650] - [fts_base:2392] INFO - Docs in bucket = 30000, docs in FTS index 'default_index_1': 28527

[2016-04-01 03:49:44,660] - [fts_base:2412] INFO - FTS indexed 28527 docs in 3.4 mins

[2016-04-01 03:49:44,806] - [fts_base:2618] INFO - Docs in index default_index_1=28527, bucket docs=30000

FAIL