Uploaded image for project: 'Couchbase Server'
  1. Couchbase Server
  2. MB-19361

[FTS] Querying during rebalance of fts node yields lesser num of hits

    XMLWordPrintable

Details

    • Bug
    • Resolution: Duplicate
    • Critical
    • 4.5.0
    • 4.5.0
    • cbft
    • None
    • Untriaged
    • No

    Description

      Build
      4.5.0-2151, 4.5.0-2363, 4.5.0-2383

      Another bug like MB-19342 that was hidden because of index_replicas =1

      Testcase
      ./testrunner -i INI_FILE.ini -t fts.moving_topology_fts.MovingTopFTS.rebalance_out_during_querying,items=10000,cluster=D,D+F,F,num_queries=100,compare_es=True,num_queries=100,GROUP=P1

      Consistently reproducible.

      2016-04-25 14:21:37 | INFO | MainProcess | test_thread | [fts_base.__async_rebalance_out] Starting rebalance-out nodes:[ip:172.23.106.176 port:8091 ssh_username:root] at C1 cluster 172.23.106.139
      2016-04-25 14:21:38 | INFO | MainProcess | Cluster_Thread | [rest_client.rebalance] rebalance params : password=password&ejectedNodes=ns_1%40172.23.106.176&user=Administrator&knownNodes=ns_1%40172.23.106.176%2Cns_1%40172.23.106.175%2Cns_1%40172.23.106.139
      2016-04-25 14:21:38 | INFO | MainProcess | Cluster_Thread | [rest_client.rebalance] rebalance operation started
      2016-04-25 14:21:38 | INFO | MainProcess | Cluster_Thread | [task.execute] ------------------------------------------------------------------ Query # 1 -----------------------------------------------------------------
      2016-04-25 14:21:38 | INFO | MainProcess | Cluster_Thread | [fts_base.run_fts_query] Running query {"from": 0, "indexName": "default_index", "fields": [], "explain": false, "ctl": {"timeout": 60000, "consistency": {"vectors": {}, "level": ""}}, "query": {"field": "manages.reports", "match": "Hanna Drucilla"}, "size": 10000000} on node: 172.23.106.175
      2016-04-25 14:21:38 | INFO | MainProcess | Cluster_Thread | [rest_client.run_fts_query] Status: {u'successful': 32, u'failed': 0, u'total': 32}
      2016-04-25 14:21:38 | INFO | MainProcess | Cluster_Thread | [task.execute] FTS hits for query: {"field": "manages.reports", "match": "Hanna Drucilla"} is 1009 (took 29.239389ms)
      2016-04-25 14:21:39 | INFO | MainProcess | Cluster_Thread | [task.execute] ES hits for query: {"match": {"manages.reports": "Hanna Drucilla"}} on es_index is 1009 (took 23ms)
      2016-04-25 14:21:39 | INFO | MainProcess | Cluster_Thread | [task.execute] SUCCESS: Docs returned by FTS = docs returned by ES, doc_ids verified
      2016-04-25 14:21:39 | INFO | MainProcess | Cluster_Thread | [task.execute] ------------------------------------------------------------------ Query # 2 -----------------------------------------------------------------
      2016-04-25 14:21:39 | INFO | MainProcess | Cluster_Thread | [fts_base.run_fts_query] Running query {"from": 0, "indexName": "default_index", "fields": [], "explain": false, "ctl": {"timeout": 60000, "consistency": {"vectors": {}, "level": ""}}, "query": {"field": "manages.reports", "match": "Solita Hanna Cytheria"}, "size": 10000000} on node: 172.23.106.139
      2016-04-25 14:21:39 | INFO | MainProcess | Cluster_Thread | [rest_client.run_fts_query] Status: {u'successful': 32, u'failed': 0, u'total': 32}
      2016-04-25 14:21:39 | INFO | MainProcess | Cluster_Thread | [task.execute] FTS hits for query: {"field": "manages.reports", "match": "Solita Hanna Cytheria"} is 1344 (took 55.585729ms)
      2016-04-25 14:21:40 | INFO | MainProcess | Cluster_Thread | [task.execute] ES hits for query: {"match": {"manages.reports": "Solita Hanna Cytheria"}} on es_index is 1402 (took 36ms)
      2016-04-25 14:21:40 | ERROR | MainProcess | Cluster_Thread | [task.execute] FAIL: FTS hits: 1344, while ES hits: 1402
      2016-04-25 14:21:40 | ERROR | MainProcess | Cluster_Thread | [task.execute] FAIL: Following 58 docs were not returned by FTS, but ES, printing 50: [u'emp10006763', u'emp10005085', u'emp10006055', u'emp10008491', u'emp10007104', u'emp10007221', u'emp10006192', u'emp10007907', u'emp10005515', u'emp10004360', u'emp10003955', u'emp10008112', u'emp10005551', u'emp10004457', u'emp10003545', u'emp10003083', u'emp10001502', u'emp10004445', u'emp10003673', u'emp10008955', u'emp10007541', u'emp10006844', u'emp10009414', u'emp10004980', u'emp10000997', u'emp10009597', u'emp10000814', u'emp10004802', u'emp10003946', u'emp10009196', u'emp10006771', u'emp10009375', u'emp10000777', u'emp10005916', u'emp10000332', u'emp10000333', u'emp10003556', u'emp10008673', u'emp10008083', u'emp10009804', u'emp10000984', u'emp10007621', u'emp10003090', u'emp10003091', u'emp10005230', u'emp10001510', u'emp10002007', u'emp10004760', u'emp10006857', u'emp10006727']
      2016-04-25 14:21:40 | INFO | MainProcess | Cluster_Thread | [task.execute] ------------------------------------------------------------------ Query # 3 -----------------------------------------------------------------
      2016-04-25 14:21:40 | INFO | MainProcess | Cluster_Thread | [fts_base.run_fts_query] Running query {"from": 0, "indexName": "default_index", "fields": [], "explain": false, "ctl": {"timeout": 60000, "consistency": {"vectors": {}, "level": ""}}, "query": {"field": "dept", "match": "Training"}, "size": 10000000} on node: 172.23.106.139
      2016-04-25 14:21:40 | INFO | MainProcess | Cluster_Thread | [rest_client.run_fts_query] Status: {u'successful': 32, u'failed': 0, u'total': 32}
      2016-04-25 14:21:40 | INFO | MainProcess | Cluster_Thread | [task.execute] FTS hits for query: {"field": "dept", "match": "Training"} is 912 (took 19.098899ms)
      2016-04-25 14:21:41 | INFO | MainProcess | Cluster_Thread | [task.execute] ES hits for query: {"match": {"dept": "Training"}} on es_index is 912 (took 27ms)
      2016-04-25 14:21:41 | INFO | MainProcess | Cluster_Thread | [task.execute] SUCCESS: Docs returned by FTS = docs returned by ES, doc_ids verified
      2016-04-25 14:21:41 | INFO | MainProcess | Cluster_Thread | [task.execute] ------------------------------------------------------------------ Query # 4 -----------------------------------------------------------------
      2016-04-25 14:21:41 | INFO | MainProcess | Cluster_Thread | [fts_base.run_fts_query] Running query {"from": 0, "indexName": "default_index", "fields": [], "explain": false, "ctl": {"timeout": 60000, "consistency": {"vectors": {}, "level": ""}}, "query": {"field": "type", "match": "wiki"}, "size": 10000000} on node: 172.23.106.175
      2016-04-25 14:21:41 | INFO | MainProcess | Cluster_Thread | [rest_client.run_fts_query] Status: {u'successful': 32, u'failed': 0, u'total': 32}
      2016-04-25 14:21:41 | INFO | MainProcess | Cluster_Thread | [task.execute] FTS hits for query: {"field": "type", "match": "wiki"} is 0 (took 22.54638ms)
      2016-04-25 14:21:41 | INFO | MainProcess | Cluster_Thread | [task.execute] ES hits for query: {"match": {"type": "wiki"}} on es_index is 0 (took 1ms)
      2016-04-25 14:21:41 | INFO | MainProcess | Cluster_Thread | [task.execute] SUCCESS: Docs returned by FTS = docs returned by ES, doc_ids verified
      2016-04-25 14:21:41 | INFO | MainProcess | Cluster_Thread | [task.execute] ------------------------------------------------------------------ Query # 5 -----------------------------------------------------------------
      2016-04-25 14:21:41 | INFO | MainProcess | Cluster_Thread | [fts_base.run_fts_query] Running query {"from": 0, "indexName": "default_index", "fields": [], "explain": false, "ctl": {"timeout": 60000, "consistency": {"vectors": {}, "level": ""}}, "query": {"field": "email", "match": "fuscienne@mcdiabetes.com"}, "size": 10000000} on node: 172.23.106.175
      2016-04-25 14:21:42 | INFO | MainProcess | Cluster_Thread | [rest_client.run_fts_query] Status: {u'successful': 32, u'failed': 0, u'total': 32}
      2016-04-25 14:21:42 | INFO | MainProcess | Cluster_Thread | [task.execute] FTS hits for query: {"field": "email", "match": "fuscienne@mcdiabetes.com"} is 10000 (took 170.224192ms)
      2016-04-25 14:21:44 | INFO | MainProcess | Cluster_Thread | [task.execute] ES hits for query: {"match": {"email": "fuscienne@mcdiabetes.com"}} on es_index is 10000 (took 157ms)
      2016-04-25 14:21:44 | INFO | MainProcess | Cluster_Thread | [task.execute] SUCCESS: Docs returned by FTS = docs returned by ES, doc_ids verified
      2016-04-25 14:21:44 | INFO | MainProcess | Cluster_Thread | [task.execute] ------------------------------------------------------------------ Query # 6 -----------------------------------------------------------------
      2016-04-25 14:21:44 | INFO | MainProcess | Cluster_Thread | [fts_base.run_fts_query] Running query {"from": 0, "indexName": "default_index", "fields": [], "explain": false, "ctl": {"timeout": 60000, "consistency": {"vectors": {}, "level": ""}}, "query": {"field": "languages_known", "match": "French"}, "size": 10000000} on node: 172.23.106.139
      2016-04-25 14:21:45 | INFO | MainProcess | Cluster_Thread | [rest_client.run_fts_query] Status: {u'successful': 32, u'failed': 0, u'total': 32}
      2016-04-25 14:21:45 | INFO | MainProcess | Cluster_Thread | [task.execute] FTS hits for query: {"field": "languages_known", "match": "French"} is 7922 (took 117.93372ms)
      2016-04-25 14:21:46 | INFO | MainProcess | Cluster_Thread | [task.execute] ES hits for query: {"match": {"languages_known": "French"}} on es_index is 7922 (took 138ms)
      2016-04-25 14:21:46 | INFO | MainProcess | Cluster_Thread | [task.execute] SUCCESS: Docs returned by FTS = docs returned by ES, doc_ids verified
      2016-04-25 14:21:46 | INFO | MainProcess | Cluster_Thread | [task.execute] ------------------------------------------------------------------ Query # 7 -----------------------------------------------------------------
      2016-04-25 14:21:47 | INFO | MainProcess | Cluster_Thread | [fts_base.run_fts_query] Running query {"from": 0, "indexName": "default_index", "fields": [], "explain": false, "ctl": {"timeout": 60000, "consistency": {"vectors": {}, "level": ""}}, "query": {"field": "languages_known", "match": "Malay Urdu"}, "size": 10000000} on node: 172.23.106.175
      2016-04-25 14:21:47 | INFO | MainProcess | Cluster_Thread | [rest_client.run_fts_query] Status: {u'successful': 32, u'failed': 0, u'total': 32}
      2016-04-25 14:21:47 | INFO | MainProcess | Cluster_Thread | [task.execute] FTS hits for query: {"field": "languages_known", "match": "Malay Urdu"} is 5260 (took 81.360204ms)
      2016-04-25 14:21:48 | INFO | MainProcess | Cluster_Thread | [task.execute] ES hits for query: {"match": {"languages_known": "Malay Urdu"}} on es_index is 5260 (took 121ms)
      2016-04-25 14:21:48 | INFO | MainProcess | Cluster_Thread | [task.execute] SUCCESS: Docs returned by FTS = docs returned by ES, doc_ids verified
      2016-04-25 14:21:48 | INFO | MainProcess | Cluster_Thread | [task.execute] ------------------------------------------------------------------ Query # 8 -----------------------------------------------------------------
      2016-04-25 14:21:48 | INFO | MainProcess | Cluster_Thread | [fts_base.run_fts_query] Running query {"from": 0, "indexName": "default_index", "fields": [], "explain": false, "ctl": {"timeout": 60000, "consistency": {"vectors": {}, "level": ""}}, "query": {"field": "manages.reports", "match": "Kimberly Adara Gallia Severin"}, "size": 10000000} on node: 172.23.106.139
      2016-04-25 14:21:49 | INFO | MainProcess | Cluster_Thread | [rest_client.run_fts_query] Status: {u'successful': 32, u'failed': 0, u'total': 32}
      2016-04-25 14:21:49 | INFO | MainProcess | Cluster_Thread | [task.execute] FTS hits for query: {"field": "manages.reports", "match": "Kimberly Adara Gallia Severin"} is 1339 (took 28.530021ms)
      2016-04-25 14:21:49 | INFO | MainProcess | Cluster_Thread | [task.execute] ES hits for query: {"match": {"manages.reports": "Kimberly Adara Gallia Severin"}} on es_index is 1339 (took 30ms)
      2016-04-25 14:21:49 | INFO | MainProcess | Cluster_Thread | [task.execute] SUCCESS: Docs returned by FTS = docs returned by ES, doc_ids verified
      2016-04-25 14:21:49 | INFO | MainProcess | Cluster_Thread | [task.execute] ------------------------------------------------------------------ Query # 9 -----------------------------------------------------------------
      2016-04-25 14:21:49 | INFO | MainProcess | Cluster_Thread | [fts_base.run_fts_query] Running query {"from": 0, "indexName": "default_index", "fields": [], "explain": false, "ctl": {"timeout": 60000, "consistency": {"vectors": {}, "level": ""}}, "query": {"field": "type", "match": "wiki"}, "size": 10000000} on node: 172.23.106.139
      2016-04-25 14:21:49 | INFO | MainProcess | Cluster_Thread | [rest_client.run_fts_query] Status: {u'successful': 32, u'failed': 0, u'total': 32}
      2016-04-25 14:21:49 | INFO | MainProcess | Cluster_Thread | [task.execute] FTS hits for query: {"field": "type", "match": "wiki"} is 0 (took 12.092555ms)
      2016-04-25 14:21:49 | INFO | MainProcess | Cluster_Thread | [task.execute] ES hits for query: {"match": {"type": "wiki"}} on es_index is 0 (took 1ms)
      2016-04-25 14:21:49 | INFO | MainProcess | Cluster_Thread | [task.execute] SUCCESS: Docs returned by FTS = docs returned by ES, doc_ids verified
      2016-04-25 14:21:49 | INFO | MainProcess | Cluster_Thread | [task.execute] ------------------------------------------------------------------ Query # 10 -----------------------------------------------------------------
      2016-04-25 14:21:49 | INFO | MainProcess | Cluster_Thread | [fts_base.run_fts_query] Running query {"from": 0, "indexName": "default_index", "fields": [], "explain": false, "ctl": {"timeout": 60000, "consistency": {"vectors": {}, "level": ""}}, "query": {"field": "type", "match": "emp"}, "size": 10000000} on node: 172.23.106.139
      2016-04-25 14:21:51 | INFO | MainProcess | Cluster_Thread | [rest_client.run_fts_query] Status: {u'successful': 32, u'failed': 0, u'total': 32}
      2016-04-25 14:21:51 | INFO | MainProcess | Cluster_Thread | [task.execute] FTS hits for query: {"field": "type", "match": "emp"} is 10000 (took 240.086845ms)
      2016-04-25 14:21:52 | INFO | MainProcess | Cluster_Thread | [task.execute] ES hits for query: {"match": {"type": "emp"}} on es_index is 10000 (took 160ms)
      2016-04-25 14:21:52 | INFO | MainProcess | Cluster_Thread | [task.execute] SUCCESS: Docs returned by FTS = docs returned by ES, doc_ids verified
      2016-04-25 14:21:52 | INFO | MainProcess | Cluster_Thread | [task.execute] ------------------------------------------------------------------ Query # 11 -----------------------------------------------------------------
      2016-04-25 14:21:53 | INFO | MainProcess | Cluster_Thread | [fts_base.run_fts_query] Running query {"from": 0, "indexName": "default_index", "fields": [], "explain": false, "ctl": {"timeout": 60000, "consistency": {"vectors": {}, "level": ""}}, "query": {"field": "dept", "match": "Finance"}, "size": 10000000} on node: 172.23.106.175
      2016-04-25 14:21:53 | INFO | MainProcess | Cluster_Thread | [rest_client.run_fts_query] Status: {u'successful': 32, u'failed': 0, u'total': 32}
      2016-04-25 14:21:53 | INFO | MainProcess | Cluster_Thread | [task.execute] FTS hits for query: {"field": "dept", "match": "Finance"} is 909 (took 29.126026ms)
      2016-04-25 14:21:54 | INFO | MainProcess | Cluster_Thread | [task.execute] ES hits for query: {"match": {"dept": "Finance"}} on es_index is 909 (took 25ms)
      2016-04-25 14:21:54 | INFO | MainProcess | Cluster_Thread | [task.execute] SUCCESS: Docs returned by FTS = docs returned by ES, doc_ids verified
      2016-04-25 14:21:54 | INFO | MainProcess | Cluster_Thread | [task.execute] ------------------------------------------------------------------ Query # 12 -----------------------------------------------------------------
      2016-04-25 14:21:54 | INFO | MainProcess | Cluster_Thread | [fts_base.run_fts_query] Running query {"from": 0, "indexName": "default_index", "fields": [], "explain": false, "ctl": {"timeout": 60000, "consistency": {"vectors": {}, "level": ""}}, "query": {"field": "languages_known", "match": "German"}, "size": 10000000} on node: 172.23.106.175
      2016-04-25 14:21:55 | INFO | MainProcess | Cluster_Thread | [rest_client.run_fts_query] Status: {u'successful': 32, u'failed': 0, u'total': 32}
      2016-04-25 14:21:55 | INFO | MainProcess | Cluster_Thread | [task.execute] FTS hits for query: {"field": "languages_known", "match": "German"} is 8953 (took 103.693646ms)
      2016-04-25 14:21:56 | INFO | MainProcess | Cluster_Thread | [task.execute] ES hits for query: {"match": {"languages_known": "German"}} on es_index is 8953 (took 151ms)
      2016-04-25 14:21:56 | INFO | MainProcess | Cluster_Thread | [task.execute] SUCCESS: Docs returned by FTS = docs returned by ES, doc_ids verified
      2016-04-25 14:21:56 | INFO | MainProcess | Cluster_Thread | [task.execute] ------------------------------------------------------------------ Query # 13 -----------------------------------------------------------------
      2016-04-25 14:21:56 | INFO | MainProcess | Cluster_Thread | [fts_base.run_fts_query] Running query {"from": 0, "indexName": "default_index", "fields": [], "explain": false, "ctl": {"timeout": 60000, "consistency": {"vectors": {}, "level": ""}}, "query": {"field": "dept", "match": "Accounts"}, "size": 10000000} on node: 172.23.106.175
      2016-04-25 14:21:57 | INFO | MainProcess | Cluster_Thread | [rest_client.run_fts_query] Status: {u'successful': 32, u'failed': 0, u'total': 32}
      2016-04-25 14:21:57 | INFO | MainProcess | Cluster_Thread | [task.execute] FTS hits for query: {"field": "dept", "match": "Accounts"} is 940 (took 29.139113ms)
      2016-04-25 14:21:57 | INFO | MainProcess | Cluster_Thread | [task.execute] ES hits for query: {"match": {"dept": "Accounts"}} on es_index is 940 (took 21ms)
      2016-04-25 14:21:57 | INFO | MainProcess | Cluster_Thread | [task.execute] SUCCESS: Docs returned by FTS = docs returned by ES, doc_ids verified
      2016-04-25 14:21:57 | INFO | MainProcess | Cluster_Thread | [task.execute] ------------------------------------------------------------------ Query # 14 -----------------------------------------------------------------
      2016-04-25 14:21:57 | INFO | MainProcess | Cluster_Thread | [fts_base.run_fts_query] Running query {"from": 0, "indexName": "default_index", "fields": [], "explain": false, "ctl": {"timeout": 60000, "consistency": {"vectors": {}, "level": ""}}, "query": {"field": "name", "match": "Mia"}, "size": 10000000} on node: 172.23.106.175
      2016-04-25 14:21:57 | INFO | MainProcess | Cluster_Thread | [rest_client.run_fts_query] Status: {u'successful': 32, u'failed': 0, u'total': 32}
      2016-04-25 14:21:57 | INFO | MainProcess | Cluster_Thread | [task.execute] FTS hits for query: {"field": "name", "match": "Mia"} is 149 (took 11.464992ms)
      2016-04-25 14:21:57 | INFO | MainProcess | Cluster_Thread | [task.execute] ES hits for query: {"match": {"name": "Mia"}} on es_index is 149 (took 7ms)
      2016-04-25 14:21:57 | INFO | MainProcess | Cluster_Thread | [task.execute] SUCCESS: Docs returned by FTS = docs returned by ES, doc_ids verified
      2016-04-25 14:21:57 | INFO | MainProcess | Cluster_Thread | [task.execute] ------------------------------------------------------------------ Query # 15 -----------------------------------------------------------------
      2016-04-25 14:21:57 | INFO | MainProcess | Cluster_Thread | [fts_base.run_fts_query] Running query {"from": 0, "indexName": "default_index", "fields": [], "explain": false, "ctl": {"timeout": 60000, "consistency": {"vectors": {}, "level": ""}}, "query": {"field": "dept", "match": "Support"}, "size": 10000000} on node: 172.23.106.175
      2016-04-25 14:21:58 | INFO | MainProcess | Cluster_Thread | [rest_client.run_fts_query] Status: {u'successful': 32, u'failed': 0, u'total': 32}
      2016-04-25 14:21:58 | INFO | MainProcess | Cluster_Thread | [task.execute] FTS hits for query: {"field": "dept", "match": "Support"} is 925 (took 21.725885ms)
      2016-04-25 14:21:58 | INFO | MainProcess | Cluster_Thread | [task.execute] ES hits for query: {"match": {"dept": "Support"}} on es_index is 925 (took 22ms)
      2016-04-25 14:21:58 | INFO | MainProcess | Cluster_Thread | [task.execute] SUCCESS: Docs returned by FTS = docs returned by ES, doc_ids verified
      2016-04-25 14:21:58 | INFO | MainProcess | Cluster_Thread | [task.execute] ------------------------------------------------------------------ Query # 16 -----------------------------------------------------------------
      2016-04-25 14:21:58 | INFO | MainProcess | Cluster_Thread | [fts_base.run_fts_query] Running query {"from": 0, "indexName": "default_index", "fields": [], "explain": false, "ctl": {"timeout": 60000, "consistency": {"vectors": {}, "level": ""}}, "query": {"field": "manages.reports", "match": "Mercedes"}, "size": 10000000} on node: 172.23.106.175
      2016-04-25 14:21:58 | INFO | MainProcess | Cluster_Thread | [rest_client.run_fts_query] Status: {u'successful': 32, u'failed': 0, u'total': 32}
      2016-04-25 14:21:58 | INFO | MainProcess | Cluster_Thread | [task.execute] FTS hits for query: {"field": "manages.reports", "match": "Mercedes"} is 531 (took 15.457107ms)
      2016-04-25 14:21:59 | INFO | MainProcess | Cluster_Thread | [task.execute] ES hits for query: {"match": {"manages.reports": "Mercedes"}} on es_index is 531 (took 13ms)
      2016-04-25 14:21:59 | INFO | MainProcess | Cluster_Thread | [task.execute] SUCCESS: Docs returned by FTS = docs returned by ES, doc_ids verified
      2016-04-25 14:21:59 | INFO | MainProcess | Cluster_Thread | [task.execute] ------------------------------------------------------------------ Query # 17 -----------------------------------------------------------------
      2016-04-25 14:21:59 | INFO | MainProcess | Cluster_Thread | [fts_base.run_fts_query] Running query {"from": 0, "indexName": "default_index", "fields": [], "explain": false, "ctl": {"timeout": 60000, "consistency": {"vectors": {}, "level": ""}}, "query": {"field": "type", "match": "emp"}, "size": 10000000} on node: 172.23.106.139
      2016-04-25 14:22:00 | INFO | MainProcess | Cluster_Thread | [rest_client.run_fts_query] Status: {u'successful': 32, u'failed': 0, u'total': 32}
      2016-04-25 14:22:00 | INFO | MainProcess | Cluster_Thread | [task.execute] FTS hits for query: {"field": "type", "match": "emp"} is 10000 (took 129.512485ms)
      2016-04-25 14:22:02 | INFO | MainProcess | Cluster_Thread | [task.execute] ES hits for query: {"match": {"type": "emp"}} on es_index is 10000 (took 160ms)
      2016-04-25 14:22:02 | INFO | MainProcess | Cluster_Thread | [task.execute] SUCCESS: Docs returned by FTS = docs returned by ES, doc_ids verified
      2016-04-25 14:22:02 | INFO | MainProcess | Cluster_Thread | [task.execute] ------------------------------------------------------------------ Query # 18 -----------------------------------------------------------------
      2016-04-25 14:22:02 | INFO | MainProcess | Cluster_Thread | [fts_base.run_fts_query] Running query {"from": 0, "indexName": "default_index", "fields": [], "explain": false, "ctl": {"timeout": 60000, "consistency": {"vectors": {}, "level": ""}}, "query": {"field": "manages.reports", "match": "Cynara Quella Salina"}, "size": 10000000} on node: 172.23.106.139
      2016-04-25 14:22:02 | INFO | MainProcess | Cluster_Thread | [rest_client.run_fts_query] Status: {u'successful': 32, u'failed': 0, u'total': 32}
      2016-04-25 14:22:02 | INFO | MainProcess | Cluster_Thread | [task.execute] FTS hits for query: {"field": "manages.reports", "match": "Cynara Quella Salina"} is 1404 (took 39.304608ms)
      2016-04-25 14:22:03 | INFO | MainProcess | Cluster_Thread | [task.execute] ES hits for query: {"match": {"manages.reports": "Cynara Quella Salina"}} on es_index is 1404 (took 30ms)
      2016-04-25 14:22:03 | INFO | MainProcess | Cluster_Thread | [task.execute] SUCCESS: Docs returned by FTS = docs returned by ES, doc_ids verified
      2016-04-25 14:22:03 | INFO | MainProcess | Cluster_Thread | [task.execute] ------------------------------------------------------------------ Query # 19 -----------------------------------------------------------------
      2016-04-25 14:22:03 | INFO | MainProcess | Cluster_Thread | [fts_base.run_fts_query] Running query {"from": 0, "indexName": "default_index", "fields": [], "explain": false, "ctl": {"timeout": 60000, "consistency": {"vectors": {}, "level": ""}}, "query": {"field": "type", "match": "emp"}, "size": 10000000} on node: 172.23.106.175
      2016-04-25 14:22:04 | INFO | MainProcess | Cluster_Thread | [rest_client.run_fts_query] Status: {u'successful': 32, u'failed': 0, u'total': 32}
      2016-04-25 14:22:04 | INFO | MainProcess | Cluster_Thread | [task.execute] FTS hits for query: {"field": "type", "match": "emp"} is 10000 (took 146.996297ms)
      2016-04-25 14:22:06 | INFO | MainProcess | Cluster_Thread | [task.execute] ES hits for query: {"match": {"type": "emp"}} on es_index is 10000 (took 172ms)
      2016-04-25 14:22:06 | INFO | MainProcess | Cluster_Thread | [task.execute] SUCCESS: Docs returned by FTS = docs returned by ES, doc_ids verified
      2016-04-25 14:22:06 | INFO | MainProcess | Cluster_Thread | [task.execute] ------------------------------------------------------------------ Query # 20 -----------------------------------------------------------------
      2016-04-25 14:22:06 | INFO | MainProcess | Cluster_Thread | [fts_base.run_fts_query] Running query {"from": 0, "indexName": "default_index", "fields": [], "explain": false, "ctl": {"timeout": 60000, "consistency": {"vectors": {}, "level": ""}}, "query": {"field": "type", "match": "emp"}, "size": 10000000} on node: 172.23.106.139
      2016-04-25 14:22:07 | INFO | MainProcess | Cluster_Thread | [rest_client.run_fts_query] Status: {u'successful': 32, u'failed': 0, u'total': 32}
      2016-04-25 14:22:07 | INFO | MainProcess | Cluster_Thread | [task.execute] FTS hits for query: {"field": "type", "match": "emp"} is 10000 (took 130.848008ms)
      2016-04-25 14:22:09 | INFO | MainProcess | Cluster_Thread | [task.execute] ES hits for query: {"match": {"type": "emp"}} on es_index is 10000 (took 177ms)
      2016-04-25 14:22:09 | INFO | MainProcess | Cluster_Thread | [task.execute] SUCCESS: Docs returned by FTS = docs returned by ES, doc_ids verified
      2016-04-25 14:22:09 | INFO | MainProcess | Cluster_Thread | [task.execute] ------------------------------------------------------------------ Query # 21 -----------------------------------------------------------------
      2016-04-25 14:22:09 | INFO | MainProcess | Cluster_Thread | [fts_base.run_fts_query] Running query {"from": 0, "indexName": "default_index", "fields": [], "explain": false, "ctl": {"timeout": 60000, "consistency": {"vectors": {}, "level": ""}}, "query": {"field": "languages_known", "match": "Quechua Chinese"}, "size": 10000000} on node: 172.23.106.175
      2016-04-25 14:22:10 | INFO | MainProcess | Cluster_Thread | [rest_client.run_fts_query] Status: {u'successful': 32, u'failed': 0, u'total': 32}
      2016-04-25 14:22:10 | INFO | MainProcess | Cluster_Thread | [task.execute] FTS hits for query: {"field": "languages_known", "match": "Quechua Chinese"} is 4232 (took 85.74682ms)
      2016-04-25 14:22:11 | INFO | MainProcess | Cluster_Thread | [task.execute] ES hits for query: {"match": {"languages_known": "Quechua Chinese"}} on es_index is 4232 (took 76ms)
      2016-04-25 14:22:11 | INFO | MainProcess | Cluster_Thread | [task.execute] SUCCESS: Docs returned by FTS = docs returned by ES, doc_ids verified
      2016-04-25 14:22:11 | INFO | MainProcess | Cluster_Thread | [task.execute] ------------------------------------------------------------------ Query # 22 -----------------------------------------------------------------
      2016-04-25 14:22:11 | INFO | MainProcess | Cluster_Thread | [fts_base.run_fts_query] Running query {"from": 0, "indexName": "default_index", "fields": [], "explain": false, "ctl": {"timeout": 60000, "consistency": {"vectors": {}, "level": ""}}, "query": {"field": "dept", "match": "Pre-sales"}, "size": 10000000} on node: 172.23.106.175
      2016-04-25 14:22:11 | INFO | MainProcess | Cluster_Thread | [rest_client.run_fts_query] Status: {u'successful': 32, u'failed': 0, u'total': 32}
      2016-04-25 14:22:11 | INFO | MainProcess | Cluster_Thread | [task.execute] FTS hits for query: {"field": "dept", "match": "Pre-sales"} is 1736 (took 50.499751ms)
      2016-04-25 14:22:12 | INFO | MainProcess | Cluster_Thread | [task.execute] ES hits for query: {"match": {"dept": "Pre-sales"}} on es_index is 1736 (took 31ms)
      2016-04-25 14:22:12 | INFO | MainProcess | Cluster_Thread | [task.execute] SUCCESS: Docs returned by FTS = docs returned by ES, doc_ids verified
      2016-04-25 14:22:12 | INFO | MainProcess | Cluster_Thread | [task.execute] ------------------------------------------------------------------ Query # 23 -----------------------------------------------------------------
      2016-04-25 14:22:12 | INFO | MainProcess | Cluster_Thread | [fts_base.run_fts_query] Running query {"from": 0, "indexName": "default_index", "fields": [], "explain": false, "ctl": {"timeout": 60000, "consistency": {"vectors": {}, "level": ""}}, "query": {"field": "manages.reports", "match": "Maura"}, "size": 10000000} on node: 172.23.106.139
      2016-04-25 14:22:12 | INFO | MainProcess | Cluster_Thread | [rest_client.run_fts_query] Status: {u'successful': 32, u'failed': 0, u'total': 32}
      2016-04-25 14:22:12 | INFO | MainProcess | Cluster_Thread | [task.execute] FTS hits for query: {"field": "manages.reports", "match": "Maura"} is 514 (took 23.019362ms)
      2016-04-25 14:22:13 | INFO | MainProcess | Cluster_Thread | [task.execute] ES hits for query: {"match": {"manages.reports": "Maura"}} on es_index is 529 (took 14ms)
      2016-04-25 14:22:13 | ERROR | MainProcess | Cluster_Thread | [task.execute] FAIL: FTS hits: 514, while ES hits: 529
      2016-04-25 14:22:13 | ERROR | MainProcess | Cluster_Thread | [task.execute] FAIL: Following 15 docs were not returned by FTS, but ES, printing 50: [u'emp10004006', u'emp10004185', u'emp10001516', u'emp10003507', u'emp10005156', u'emp10004407', u'emp10001729', u'emp10000770', u'emp10009001', u'emp10000455', u'emp10003542', u'emp10002802', u'emp10006586', u'emp10000763', u'emp10002508']
      2016-04-25 14:22:13 | INFO | MainProcess | Cluster_Thread | [task.execute] ------------------------------------------------------------------ Query # 24 -----------------------------------------------------------------
      2016-04-25 14:22:13 | INFO | MainProcess | Cluster_Thread | [fts_base.run_fts_query] Running query {"from": 0, "indexName": "default_index", "fields": [], "explain": false, "ctl": {"timeout": 60000, "consistency": {"vectors": {}, "level": ""}}, "query": {"field": "email", "match": "keelia@mcdiabetes.com"}, "size": 10000000} on node: 172.23.106.139
      2016-04-25 14:22:14 | INFO | MainProcess | Cluster_Thread | [rest_client.run_fts_query] Status: {u'successful': 32, u'failed': 0, u'total': 32}
      2016-04-25 14:22:14 | INFO | MainProcess | Cluster_Thread | [task.execute] FTS hits for query: {"field": "email", "match": "keelia@mcdiabetes.com"} is 9983 (took 218.341022ms)
      2016-04-25 14:22:16 | INFO | MainProcess | Cluster_Thread | [task.execute] ES hits for query: {"match": {"email": "keelia@mcdiabetes.com"}} on es_index is 10000 (took 152ms)
      2016-04-25 14:22:16 | ERROR | MainProcess | Cluster_Thread | [task.execute] FAIL: FTS hits: 9983, while ES hits: 10000
      2016-04-25 14:22:16 | ERROR | MainProcess | Cluster_Thread | [task.execute] FAIL: Following 17 docs were not returned by FTS, but ES, printing 50: [u'emp10003667', u'emp10006776', u'emp10007900', u'emp10003085', u'emp10005225', u'emp10009855', u'emp10008623', u'emp10002981', u'emp10000334', u'emp10007890', u'emp10008151', u'emp10006194', u'emp10006004', u'emp10000446', u'emp10002811', u'emp10005557', u'emp10003115']
      2016-04-25 14:22:16 | INFO | MainProcess | Cluster_Thread | [task.execute] ------------------------------------------------------------------ Query # 25 -----------------------------------------------------------------
      2016-04-25 14:22:16 | INFO | MainProcess | Cluster_Thread | [fts_base.run_fts_query] Running query {"from": 0, "indexName": "default_index", "fields": [], "explain": false, "ctl": {"timeout": 60000, "consistency": {"vectors": {}, "level": ""}}, "query": {"field": "name", "match": "Keelia Foster"}, "size": 10000000} on node: 172.23.106.175
      2016-04-25 14:22:16 | INFO | MainProcess | Cluster_Thread | [rest_client.run_fts_query] Status: {u'successful': 32, u'failed': 0, u'total': 32}
      2016-04-25 14:22:16 | INFO | MainProcess | Cluster_Thread | [task.execute] FTS hits for query: {"field": "name", "match": "Keelia Foster"} is 278 (took 15.744402ms)
      2016-04-25 14:22:16 | INFO | MainProcess | Cluster_Thread | [task.execute] ES hits for query: {"match": {"name": "Keelia Foster"}} on es_index is 278 (took 10ms)
      2016-04-25 14:22:16 | INFO | MainProcess | Cluster_Thread | [task.execute] SUCCESS: Docs returned by FTS = docs returned by ES, doc_ids verified
      

      Pls let me know if you would like logs for this issue, the testrunner command through cluster-run should work.

      Attachments

        Issue Links

          No reviews matched the request. Check your Options in the drop-down menu of this sections header.

          Activity

            People

              apiravi Aruna Piravi (Inactive)
              apiravi Aruna Piravi (Inactive)
              Votes:
              0 Vote for this issue
              Watchers:
              4 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved:

                Gerrit Reviews

                  There are no open Gerrit changes

                  PagerDuty