7.7.0 bug with _search and idle shards

[awick]

Elasticsearch version (bin/elasticsearch --version): Version: 7.7.0, Build: default/tar/81a1e9eda8e6183f5237786246f6dced26a10eaf/2020-05-12T02:01:37.602180Z, JVM: 14

Plugins installed: [] None

JVM version (java -version): Included

OS version (uname -a if on a Unix-like system): Linux moloches01 3.10.0-1062.12.1.el7.YAHOO.20200205.52.x86_64 #1 SMP Wed Feb 5 22:45:50 UTC 2020 x86_64 x86_64 x86_64 GNU/Linux

Description of the problem including expected versus actual behavior:

7.7.0 seems to no longer wait for idle shards to be refreshed before responding to a _search query. 7.6.2 and previous versions did not have this issue.

• So I have a index (dstats_v4) that I constantly overwrite documents in (1440 documents per moloch node, written every 5 seconds, wrapping around so always the same doc ids are used)
• It does NOT have a refresh_interval set, so it should be taking advantage of the idle shard feature (https://www.elastic.co/guide/en/elasticsearch/reference/7.7/index-modules.html#dynamic-index-settings)
• If we wait to search this index for a long period of time and then do a search, only some of the documents we know are there are returned. so if we a _search?q=molochnode:test we should ALWAYS get 1440 documents, but we randomly get around 600-800, it almost looks like every other document is returned so it is NOT just the documents written during the period of not searching. (I wondering if there is some idle + # of shards issue here, since we are using 2 shards)
• If we repeat the search several times eventually it will return all 1440 documents and then will keep working
• As a work around Mark had as set refresh_interval to 1s and that always works, even after wait a long period of time

Here is our _settings

      "dstats_v4" : {
        "settings" : {
          "index" : {
            "number_of_shards" : "2",
            "auto_expand_replicas" : "0-3",
            "provided_name" : "dstats_v4",
            "creation_date" : "1565358628829",
            "priority" : "50",
            "number_of_replicas" : "3",
            "uuid" : "muB0pZV4SYywXmxBcJEEGA",
            "version" : {
              "created" : "6080299",
              "upgraded" : "7040299"
            }
          }
        }
      }
    }```


**Steps to reproduce**:

Haven't been able to reproduce with standalone script yet

[dnhatn]

@awick Thank you for reporting the issue. Can you share the search query and the mapping of index.

[elasticmachine]

Pinging @elastic/es-search (:Search/Search)

[elasticmachine]

Pinging @elastic/es-distributed (:Distributed/Engine)

[awick]

_mapping

{"dstats_v4":{"mappings":{"dynamic":"true","dynamic_templates":[{"numeric":{"match_mapping_type":"long","mapping":{"index":false,"type":"long"}}},{"noindex":{"match":"*","mapping":{"index":false}}}],"properties":{"closeQueue":{"type":"long","index":false},"cpu":{"type":"long","index":false},"currentTime":{"type":"date","format":"epoch_second"},"deltaBytes":{"type":"long","index":false},"deltaDropped":{"type":"long","index":false},"deltaESDropped":{"type":"long","index":false},"deltaFragsDropped":{"type":"long","index":false},"deltaMS":{"type":"long","index":false},"deltaOverloadDropped":{"type":"long","index":false},"deltaPackets":{"type":"long","index":false},"deltaSessionBytes":{"type":"long","index":false},"deltaSessions":{"type":"long","index":false},"deltaUnwrittenBytes":{"type":"long","index":false},"deltaWrittenBytes":{"type":"long","index":false},"diskQueue":{"type":"long","index":false},"esHealthMS":{"type":"long","index":false},"esQueue":{"type":"long","index":false},"espSessions":{"type":"long","index":false},"frags":{"type":"long","index":false},"fragsQueue":{"type":"long","index":false},"freeSpaceM":{"type":"long","index":false},"freeSpaceP":{"type":"float","index":false},"hostname":{"type":"text","index":false},"icmpSessions":{"type":"long","index":false},"interval":{"type":"short"},"memory":{"type":"long","index":false},"memoryP":{"type":"float","index":false},"monitoring":{"type":"long","index":false},"needSave":{"type":"long","index":false},"nodeName":{"type":"keyword"},"otherSessions":{"type":"long","index":false},"packetQueue":{"type":"long","index":false},"sctpSessions":{"type":"long","index":false},"tcpSessions":{"type":"long","index":false},"totalDropped":{"type":"long","index":false},"totalK":{"type":"long","index":false},"totalPackets":{"type":"long","index":false},"totalSessions":{"type":"long","index":false},"udpSessions":{"type":"long","index":false},"usedSpaceM":{"type":"long","index":false},"ver":{"type":"text","index":false}}}}}

sample options as sent to old javascript api, notice we do use an alias of dstats -> dstats_v4

{
 "index": "dstats",
 "body": {
  "query": {
   "bool": {
    "filter": [
     {
      "range": {
       "currentTime": {
        "from": "1590050255",
        "to": "1590057455"
       }
      }
     },
     {
      "term": {
       "interval": "5"
      }
     },
     {
      "term": {
       "nodeName": "THENODENAME"
      }
     }
    ]
   }
  },
  "sort": {
   "currentTime": {
    "order": "desc"
   }
  },
  "size": 1440,
  "_source": [
   "deltaPackets",
   "deltaMS",
   "nodeName",
   "currentTime"
  ],
  "profile": false
 },
 "rest_total_hits_as_int": true,
 "filter_path": "_scroll_id,hits.total,hits.hits._source"
}

Sample response, 718 total while it should be ~1440

 "hits": {
  "total": 718,
  "hits": [
   {
    "_source": {
     "nodeName": "THENODENAME",
     "currentTime": 1590057454,
     "deltaPackets": 1336481,
     "deltaMS": 4636
    }
   },
   {
    "_source": {
     "nodeName": "THENODENAME",
     "currentTime": 1590057449,
     "deltaPackets": 1434213,
     "deltaMS": 5099
    }
   },
...

Here is a picture of how we noticed the problem. I hadn't viewed the page for at least 6 hours. Each line is a dstats query. The first 6 are messed up and the rest aren't. My assumption is only the first 6 are messed up because the browser does 6 at once and then waits before doing the next 6, by which time ES has "background refreshed". A reload of the page instantly fixes the first 6.

I did a bunch of _cat stuff before/after

/_cat/indices/dstats_v4?v - the deleted docs get cleaned up

health status index     uuid                   pri rep docs.count docs.deleted store.size pri.store.size
green  open   dstats_v4 muB0pZV4SYywXmxBcJEEGA   2   3      73440        11369    242.5mb         38.1mb (before)
green  open   dstats_v4 muB0pZV4SYywXmxBcJEEGA   2   3      73440            4    269.4mb         67.1mb (after)

/_cat/shards/dstats_v4?v

index     shard prirep state    docs  store
dstats_v4 0     p      STARTED 36818   18mb
dstats_v4 0     r      STARTED 36818 33.3mb
dstats_v4 1     r      STARTED 36622 33.8mb
dstats_v4 0     r      STARTED 36818 34.9mb
dstats_v4 1     r      STARTED 36622 33.2mb
dstats_v4 1     p      STARTED 36622 20.1mb
dstats_v4 1     r      STARTED 36622 34.7mb
dstats_v4 0     r      STARTED 36818 34.1mb

index     shard prirep state    docs  store
dstats_v4 0     p      STARTED 36818 33.6mb
dstats_v4 0     r      STARTED 36818 33.8mb
dstats_v4 1     r      STARTED 36622 33.5mb
dstats_v4 0     r      STARTED 36818 33.8mb
dstats_v4 1     r      STARTED 36622 33.6mb
dstats_v4 1     p      STARTED 36622 33.5mb
dstats_v4 1     r      STARTED 36622 33.6mb
dstats_v4 0     r      STARTED 36818 33.7mb

/_cat/segments/dstats_v4?v - here is before/after of just 1 of the primary shards, let me know if you want more

index     shard prirep ip            segment generation docs.count docs.deleted   size size.memory committed searchable version compound
dstats_v4 0     p               .153 _8xkm       416758      31112         5706  15.6mb        3788 true      true       8.5.1   false
dstats_v4 0     p               .153 _8xkn       416759          1            0  10.3kb           0 true      false      8.5.1   true
dstats_v4 0     p               .153 _8xl7       416779       5692            0   2.2mb        3612 false     true       8.5.1   false
dstats_v4 0     p               .153 _8xl8       416780          4            0  12.3kb        2908 false     true       8.5.1   true
dstats_v4 0     p               .153 _8xl9       416781          1            0  10.3kb        1516 false     true       8.5.1   true
dstats_v4 0     p               .153 _8xla       416782          3            0  11.7kb        2668 false     true       8.5.1   true
dstats_v4 0     p               .153 _8xlb       416783          1            0  10.3kb        1516 false     true       8.5.1   true
dstats_v4 0     p               .153 _8xlc       416784          1            0  10.3kb        1516 false     true       8.5.1   true
dstats_v4 0     p               .153 _8xld       416785          2            0  10.8kb        1516 false     true       8.5.1   true
dstats_v4 0     p               .153 _8xle       416786          2            0  10.8kb        1516 false     true       8.5.1   true


index     shard prirep ip            segment generation docs.count docs.deleted   size size.memory committed searchable version compound
dstats_v4 0     p               .153 _8xkm       416758      31112         5706 15.6mb        3788 false     true       8.5.1   false
dstats_v4 0     p               .153 _8xl7       416779       5692            0  2.2mb        3612 false     true       8.5.1   false
dstats_v4 0     p               .153 _8xl8       416780          4            0 12.3kb        2908 false     true       8.5.1   true
dstats_v4 0     p               .153 _8xl9       416781          1            0 10.3kb        1516 false     true       8.5.1   true
dstats_v4 0     p               .153 _8xla       416782          3            0 11.7kb        2668 false     true       8.5.1   true
dstats_v4 0     p               .153 _8xlb       416783          1            0 10.3kb        1516 false     true       8.5.1   true
dstats_v4 0     p               .153 _8xlc       416784          1            0 10.3kb        1516 false     true       8.5.1   true
dstats_v4 0     p               .153 _8xld       416785          2            0 10.8kb        1516 false     true       8.5.1   true
dstats_v4 0     p               .153 _8xle       416786          2            0 10.8kb        1516 false     true       8.5.1   true
dstats_v4 0     p               .153 _8xlj       416791      36818            0 15.6mb        3788 true      false      8.5.1   false

[awick]

To make sure this wasn't an issue with having start life as a 6.8 cluster, I tried with another cluster I'm running that started life as a 7.6.2, and having the same issues. This new cluster is also fairly lightly loaded so I don't think it is a load issue either.

{
  "dstats_v4" : {
    "settings" : {
      "index" : {
        "number_of_shards" : "2",
        "auto_expand_replicas" : "0-3",
        "provided_name" : "dstats_v4",
        "creation_date" : "1587125029032",
        "priority" : "50",
        "number_of_replicas" : "3",
        "uuid" : "_dayuNqkTs22yTyuPiWNBg",
        "version" : {
          "created" : "7060299",
          "upgraded" : "7070099"
        }
      }
    }
  }
}

[dnhatn]

@awick Is it also an issue on 7.6.2?

[awick]

No, there is only a problem with 7.7.0, 7.6.2 works fine. My comment above was only showing that an index that starts out as 7.6.2 -> 7.7.0 still has the same issue. My original bug report was for an index that started as 6.8.2 and gone thru multiple versions before reaching 7.7.0.

[dnhatn]

Thanks @awick. That's helpful. I will take a look. I think this issue was introduced in #49601 (/cc @jimczi).

[jimczi]

The issue was introduced with #53873, which sets the pre_filter_shard_size to 1 if the primary sort is on a field. This should be fixed by #55428 but you can explicitly set pre_filter_shard_size to a large value in the meantime as a workaround before the fix is released.

[jimczi]

We've decided to backport the fix for this bug in 7.7.1 so we can close the issue now. Thanks for reporting @awick.