Details
Description
Build
5.5.0-2155
Testcase
./testrunner -i /tmp/testexec.11676.ini get-cbcollect-info=True,get-logs=False,stop-on-failure=False,GROUP=P1 -t fts.moving_topology_fts.MovingTopFTS.swap_rebalance_during_querying,items=10000,cluster=D,F,replicas=0,num_queries=100,compare_es=True,num_queries=100,GROUP=P1
/data/workspace/centos-p0-fts-vset00-00-moving-topology-P1/logs/testrunner-18-Mar-14_23-39-41/test_7, slave 172.23.105.89
Steps:
1. D, F(.103) cluster
2. Create default index on default bucket with 10k docs, wait for indexing to complete
3. Start swap rebalance .103 with .122
4. Fire queries immediately, the logs below indicate that for 4s, pools/default rest api does not return any fts nodes in the cluster.
[2018-03-14 23:55:19,319] - [fts_base:876] INFO - Creating fulltext-index default_index on 172.23.104.103 |
[2018-03-14 23:55:19,320] - [rest_client:2667] INFO - {"params": {"store": {"mossStoreOptions": {}, "kvStoreName": "mossStore"}}, "name": "default_index", "planParams": {"numReplicas": 0, "maxPartitionsPerPIndex": 171}, "sourceName": "default", "sourceUUID": "", "sourceType": "couchbase", "type": "fulltext-index", "uuid": ""} |
[2018-03-14 23:55:19,344] - [rest_client:2674] INFO - Index default_index created |
[2018-03-14 23:55:19,345] - [fts_base:3515] INFO - Validating index distribution for default_index ... |
[2018-03-14 23:55:19,454] - [fts_base:3533] INFO - Validated: Number of PIndexes = 6 |
[2018-03-14 23:55:19,478] - [fts_base:3545] INFO - Validated: Every pIndex serves 171 partitions or lesser |
[2018-03-14 23:55:19,478] - [fts_base:3569] INFO - Expecting num of partitions in each node in range 853-1024 |
[2018-03-14 23:55:19,478] - [fts_base:3584] INFO - Validated: Node 6d04de90b6afba3267aace1e5f000193 houses 6 pindexes which serve 1024 partitions |
[2018-03-14 23:55:20,951] - [task:1228] INFO - Starting operation 'create' on Elastic Search ... |
[2018-03-14 23:55:21,529] - [data_helper:295] INFO - creating direct client 172.23.104.100:11210 default |
[2018-03-14 23:55:24,407] - [task:1262] INFO - 5000 documents bulk loaded into ES |
[2018-03-14 23:55:26,809] - [task:1262] INFO - 10000 documents bulk loaded into ES |
[2018-03-14 23:55:26,959] - [task:1267] INFO - ES index count for 'es_index': 10000 |
[2018-03-14 23:55:27,314] - [fts_base:3920] INFO - Loading phase complete! |
[2018-03-14 23:55:27,394] - [rest_client:1896] INFO - http://172.23.104.100:8091/pools/default/buckets/default/stats?zoom=minute |
[2018-03-14 23:55:27,418] - [fts_base:3433] INFO - Docs in bucket = 5000, docs in FTS index 'default_index': 5609, docs in ES index: 10000 |
[2018-03-14 23:55:33,472] - [rest_client:1896] INFO - http://172.23.104.100:8091/pools/default/buckets/default/stats?zoom=minute |
[2018-03-14 23:55:33,504] - [fts_base:3433] INFO - Docs in bucket = 10000, docs in FTS index 'default_index': 10000, docs in ES index: 10000 |
[2018-03-14 23:55:33,581] - [fts_base:2572] INFO - Starting swap-rebalance [remove_node:[ip:172.23.104.103 port:8091 ssh_username:root]] -> [add_node:[ip:172.23.105.122 port:8091 ssh_username:root]] at C1 cluster 172.23.104.100 |
[2018-03-14 23:55:34,164] - [rest_client:1997] INFO - Node versions in cluster [u'5.5.0-2155-enterprise', u'5.5.0-2155-enterprise'] |
[2018-03-14 23:55:34,197] - [task:437] INFO - adding node 172.23.105.122:8091 to cluster |
[2018-03-14 23:55:34,197] - [rest_client:1215] INFO - adding remote node @172.23.105.122:8091 to this cluster @172.23.104.100:8091 |
[2018-03-14 23:55:36,131] - [rest_client:1433] INFO - rebalance params : {'password': 'password', 'ejectedNodes': u'ns_1@172.23.104.103', 'user': 'Administrator', 'knownNodes': u'ns_1@172.23.104.100,ns_1@172.23.104.103,ns_1@172.23.105.122'} |
[2018-03-14 23:55:36,142] - [rest_client:1438] INFO - rebalance operation started |
[2018-03-14 23:55:36,143] - [task:1296] INFO - ----------------------------------------------------- Query # 1 ---------------------------------------------------- |
[2018-03-14 23:55:36,167] - [rest_client:1971] INFO - Node 172.23.105.122 not part of cluster inactiveAdded |
[2018-03-14 23:55:36,168] - [fts_base:1075] ERROR - Error running query: No node in the cluster has 'fts' service enabled |
[2018-03-14 23:55:36,168] - [task:1300] INFO - Status: {} |
[2018-03-14 23:55:36,168] - [task:1324] INFO - FTS hits for query: {"field": "manages.reports", "match": "Hanna Drucilla"} is -1 (took 0.0ms) |
[2018-03-14 23:55:36,248] - [task:1334] INFO - ES hits for query: {"query": {"match": {"manages.reports": "Hanna Drucilla"}}} on es_index is 929 (took 25ms) |
[2018-03-14 23:55:36,248] - [task:1296] INFO - ----------------------------------------------------- Query # 2 ---------------------------------------------------- |
[2018-03-14 23:55:36,268] - [rest_client:1971] INFO - Node 172.23.105.122 not part of cluster inactiveAdded |
[2018-03-14 23:55:36,269] - [fts_base:1075] ERROR - Error running query: No node in the cluster has 'fts' service enabled |
[2018-03-14 23:55:36,269] - [task:1300] INFO - Status: {} |
[2018-03-14 23:55:36,270] - [task:1324] INFO - FTS hits for query: {"field": "manages.reports", "match": "Solita Hanna Cytheria"} is -1 (took 0.0ms) |
[2018-03-14 23:55:36,374] - [task:1334] INFO - ES hits for query: {"query": {"match": {"manages.reports": "Solita Hanna Cytheria"}}} on es_index is 1349 (took 33ms) |
[2018-03-14 23:55:36,374] - [task:1296] INFO - ----------------------------------------------------- Query # 3 ---------------------------------------------------- |
[2018-03-14 23:55:36,389] - [rest_client:1971] INFO - Node 172.23.105.122 not part of cluster inactiveAdded |
[2018-03-14 23:55:36,389] - [fts_base:1075] ERROR - Error running query: No node in the cluster has 'fts' service enabled |
[2018-03-14 23:55:36,390] - [task:1300] INFO - Status: {} |
[2018-03-14 23:55:36,390] - [task:1324] INFO - FTS hits for query: {"field": "dept", "match": "Training"} is -1 (took 0.0ms) |
[2018-03-14 23:55:36,463] - [task:1334] INFO - ES hits for query: {"query": {"match": {"dept": "Training"}}} on es_index is 947 (took 26ms) |
[2018-03-14 23:55:36,464] - [task:1296] INFO - ----------------------------------------------------- Query # 4 ---------------------------------------------------- |
[2018-03-14 23:55:36,483] - [rest_client:1971] INFO - Node 172.23.105.122 not part of cluster inactiveAdded |
[2018-03-14 23:55:36,483] - [fts_base:1075] ERROR - Error running query: No node in the cluster has 'fts' service enabled |
[2018-03-14 23:55:36,483] - [task:1300] INFO - Status: {} |
[2018-03-14 23:55:36,484] - [task:1324] INFO - FTS hits for query: {"field": "type", "match": "wiki"} is -1 (took 0.0ms) |
[2018-03-14 23:55:36,488] - [task:1334] INFO - ES hits for query: {"query": {"match": {"type": "wiki"}}} on es_index is 0 (took 1ms) |
[2018-03-14 23:55:36,489] - [task:1296] INFO - ----------------------------------------------------- Query # 5 ---------------------------------------------------- |
[2018-03-14 23:55:36,503] - [rest_client:1971] INFO - Node 172.23.105.122 not part of cluster inactiveAdded |
[2018-03-14 23:55:36,503] - [fts_base:1075] ERROR - Error running query: No node in the cluster has 'fts' service enabled |
[2018-03-14 23:55:36,503] - [task:1300] INFO - Status: {} |
[2018-03-14 23:55:36,504] - [task:1324] INFO - FTS hits for query: {"field": "email", "match": "fuscienne@mcdiabetes.com"} is -1 (took 0.0ms) |
[2018-03-14 23:55:37,115] - [task:1334] INFO - ES hits for query: {"query": {"match": {"email": "fuscienne@mcdiabetes.com"}}} on es_index is 10000 (took 206ms) |
[2018-03-14 23:55:37,117] - [task:1296] INFO - ----------------------------------------------------- Query # 6 ---------------------------------------------------- |
[2018-03-14 23:55:37,131] - [rest_client:1971] INFO - Node 172.23.105.122 not part of cluster inactiveAdded |
[2018-03-14 23:55:37,132] - [fts_base:1075] ERROR - Error running query: No node in the cluster has 'fts' service enabled |
[2018-03-14 23:55:37,132] - [task:1300] INFO - Status: {} |
[2018-03-14 23:55:37,132] - [task:1324] INFO - FTS hits for query: {"field": "languages_known", "match": "Portuguese"} is -1 (took 0.0ms) |
[2018-03-14 23:55:37,244] - [task:1334] INFO - ES hits for query: {"query": {"match": {"languages_known": "Portuguese"}}} on es_index is 1388 (took 49ms) |
[2018-03-14 23:55:37,246] - [task:1296] INFO - ----------------------------------------------------- Query # 7 ---------------------------------------------------- |
[2018-03-14 23:55:37,272] - [rest_client:1971] INFO - Node 172.23.105.122 not part of cluster inactiveAdded |
[2018-03-14 23:55:37,273] - [fts_base:1075] ERROR - Error running query: No node in the cluster has 'fts' service enabled |
[2018-03-14 23:55:37,273] - [task:1300] INFO - Status: {} |
[2018-03-14 23:55:37,273] - [task:1324] INFO - FTS hits for query: {"field": "type", "match": "wiki"} is -1 (took 0.0ms) |
[2018-03-14 23:55:37,279] - [task:1334] INFO - ES hits for query: {"query": {"match": {"type": "wiki"}}} on es_index is 0 (took 1ms) |
[2018-03-14 23:55:37,280] - [task:1296] INFO - ----------------------------------------------------- Query # 8 ---------------------------------------------------- |
[2018-03-14 23:55:37,299] - [rest_client:1971] INFO - Node 172.23.105.122 not part of cluster inactiveAdded |
[2018-03-14 23:55:37,300] - [fts_base:1075] ERROR - Error running query: No node in the cluster has 'fts' service enabled |
[2018-03-14 23:55:37,300] - [task:1300] INFO - Status: {} |
[2018-03-14 23:55:37,301] - [task:1324] INFO - FTS hits for query: {"field": "name", "match": "Richardson IX"} is -1 (took 0.0ms) |
[2018-03-14 23:55:37,321] - [task:1334] INFO - ES hits for query: {"query": {"match": {"name": "Richardson IX"}}} on es_index is 158 (took 7ms) |
[2018-03-14 23:55:37,322] - [task:1296] INFO - ----------------------------------------------------- Query # 9 ---------------------------------------------------- |
[2018-03-14 23:55:37,349] - [rest_client:1971] INFO - Node 172.23.105.122 not part of cluster inactiveAdded |
[2018-03-14 23:55:37,350] - [fts_base:1075] ERROR - Error running query: No node in the cluster has 'fts' service enabled |
[2018-03-14 23:55:37,350] - [task:1300] INFO - Status: {} |
[2018-03-14 23:55:37,351] - [task:1324] INFO - FTS hits for query: {"field": "languages_known", "match": "Japanese"} is -1 (took 0.0ms) |
[2018-03-14 23:55:37,449] - [task:1334] INFO - ES hits for query: {"query": {"match": {"languages_known": "Japanese"}}} on es_index is 1434 (took 43ms) |
[2018-03-14 23:55:37,449] - [task:1296] INFO - ----------------------------------------------------- Query # 10 ---------------------------------------------------- |
[2018-03-14 23:55:37,471] - [fts_base:1991] INFO - Running query {"indexName": "default_index", "from": 0, "fields": [], "explain": false, "ctl": {"timeout": 60000, "consistency": {"vectors": {}, "level": ""}}, "query": {"field": "email", "match": "kory@mcdiabetes.com"}, "size": 10000000} on node: 172.23.105.122: |
[2018-03-14 23:55:37,481] - [rest_client:816] ERROR - socket error while connecting to http://172.23.105.122:8094/api/index/default_index/query error [Errno 111] Connection refused |
[2018-03-14 23:55:40,888] - [task:1300] INFO - Status: {u'successful': 6, u'failed': 0, u'total': 6, u'errors': {}} |
[2018-03-14 23:55:40,889] - [task:1324] INFO - FTS hits for query: {"field": "email", "match": "kory@mcdiabetes.com"} is 10000 (took 46.370653ms) |
[2018-03-14 23:55:41,441] - [task:1334] INFO - ES hits for query: {"query": {"match": {"email": "kory@mcdiabetes.com"}}} on es_index is 10000 (took 195ms) |
[2018-03-14 23:55:41,450] - [task:1343] INFO - SUCCESS: Docs returned by FTS = docs returned by ES, doc_ids verified |
[2018-03-14 23:55:41,455] - [task:1296] INFO - ----------------------------------------------------- Query # 11 ---------------------------------------------------- |
[2018-03-14 23:55:41,482] - [fts_base:1991] INFO - Running query {"indexName": "default_index", "from": 0, "fields": [], "explain": false, "ctl": {"timeout": 60000, "consistency": {"vectors": {}, "level": ""}}, "query": {"field": "dept", "match": "Accounts"}, "size": 10000000} on node: 172.23.105.122: |
[2018-03-14 23:55:41,519] - [task:1300] INFO - Status: {u'successful': 6, u'failed': 0, u'total': 6, u'errors': {}} |
[2018-03-14 23:55:41,520] - [task:1324] INFO - FTS hits for query: {"field": "dept", "match": "Accounts"} is 883 (took 4.469432ms) |
[2018-03-14 23:55:41,594] - [task:1334] INFO - ES hits for query: {"query": {"match": {"dept": "Accounts"}}} on es_index is 883 (took 23ms) |
[2018-03-14 23:55:41,595] - [task:1343] INFO - SUCCESS: Docs returned by FTS = docs returned by ES, doc_ids verified |