Incorrect range filter results: Querying `time:>=T` yields documents with `time < T`!

[judnich]

Bug Summary

Searching "query": "time:>=T" returns documents with time < T, where:

• T is a numeric literal containing a valid integer nanosecond unix timestamp where T % 1000 > 0
• Indexed document(s) exist with nanoseconds timestamp x where T-N < x < T for "small N" (*)
• Field time in the index is configured with fast_precision: nanoseconds and output_format: unix_timestamp_nanos.

(*) Black-box behavior probing gives the impression that timestamps are being erroneously rounded down to lower precisions internally at some point during query execution, but further probing shows that the "boundary" points (the smallest U>T for which time:>=U stops returning documents at time T) are very unusual and don't seem to obviously correspond to either the integer microsecond or floating point nanosecond rounding error boundaries we'd expect. See "Example Repro" section below for more details.

Repro Steps

1. Ingest some data with nanosecond precision timestamps (reference index configuration is provided below)
2. Select some sample timestamp T from any document, as long as the last 3 decimal digits of T are not 999. It's fine if the last 3 digits are all 000.
3. Use the REST API to search "query": "time:>={T+1}", "sort_by":"-time", "max_hits":1" where T the sample timestamp selected above.
4. You will find that the document at time T is incorrectly included in the result!
5. Optional: Experiment with different time offsets (incorrect behavior repros with offsets much larger than 1 nano, though exactly what offset ahead of T stops incorrectly returning the document at time T seems unusual and doesn't align with most normal precision rounding boundaries one would expect).

Example Repro

❯ curl -X POST "http://127.0.0.1:7280/api/v1/fluentbit-logs/search" \
    -H "Content-Type: application/json" \
    -d '{"max_hits":1,"query":"time:>=1751128201918247001","sort_by":"-time"}'

{
  "num_hits": 7354717336,
  "hits": [
    {
      "time": 1751128201918247000
      /* ... */
    }
  ],
  "elapsed_time_micros": 291577,
  "errors": []
}

Bisecting this "time:>=T+N" query to find when Quickwit stops returning the document at time T found this:

❯ curl -X POST "http://127.0.0.1:7280/api/v1/fluentbit-logs/search" \
    -H "Content-Type: application/json" \
    -d '{"max_hits":1,"query":"time:>=1751128201918247595","sort_by":"-time"}'
...
      "time": 1751128201918247000

❯ curl -X POST "http://127.0.0.1:7280/api/v1/fluentbit-logs/search" \
    -H "Content-Type: application/json" \
      -d '{"max_hits":1,"query":"time:>=1751128201918247596","sort_by":"-time"}'
...
      "time": 1751128201918249000

Notice how the query for time:>= (T + 595) still incorrectly returns the document at time T, while querying time:>=(T + 596) finally got it to move on to the (presumably) next document >= T.

Expected behavior

Quickwit should NOT have returned a "hit" document with "time": 1751128201918247000 in response to a query for time:>=1751128201918247595, since 1751128201918247000 < 1751128201918247595 (equivalently 000 < 595).

In general:

• Querying time:>=T should never return documents with time < T.
• Querying field:>=X should never return documents with field < X.

Some black-box brainstorming

This odd boundary at least suggests that whatever the issue is internally, it's not as simple as integer nanoseconds being rounded down to integer microseconds, and probably not even nanoseconds being simply rounded to a IEEE-753 64-bit float!

If the timestamps were just being rounded into f64, then we'd expect the boundary point to be N > 40, rather than the observed boundary of N > 595 (since (1751128201918247000.0 >= 1751128201918247040.0) == true and (1751128201918247000.0 >= 1751128201918247041.0) == false).

Configuration

> quickwit --version
Quickwit 0.8.2 (x86_64-unknown-linux-gnu 2024-09-03T11:26:51Z 0f28194)

index.yaml

version: 0.8

index_id: fluentbit-logs

doc_mapping:
  mode: lenient

  field_mappings:
    - name: time
      type: datetime
      input_formats:
        - iso8601
      output_format: unix_timestamp_nanos
      fast_precision: nanoseconds
      fast: true
    # ...

  timestamp_field: time

# ...

[rdettai]

Thanks for this detailed report.

First, the build you are referring to (commit 0f28194) is a bit of an "in-between". Not sure how you ended up with it 😄 .

Regardless of that, it looks like a plausible bug on boundaries, but I cannot reproduce. I tried this test scenario on both main and 0.8.2 and it works just fine:

• I think I used your example datapoints, did I get something wrong?
• Otherwise, it means that you bug only happens when there is more data / more splits / more ???.

I know writing this issue must have been quite time consuming already, but could you come up with a sharable (minimal?) dataset that reproduces the issue?

[judnich]

Thank you for the reply! Yes I’ll try to come up with a shareable dataset to repro soon. It’s 100% reproducible in our large production deployment, and as you can imagine, this makes paging a pain to do correctly (since it requires essentially dilating the queried range then post-filtering — which in addition to being a hacky workaround, only works up to a certain level of docs/time density for any given query being paginated).

[judnich]

As for the odd in-between build -- this is just the build from docker, e.g.:

❯ docker run --rm --platform linux/amd64 quickwit/quickwit --version
Quickwit 0.8.2 (x86_64-unknown-linux-gnu 2024-09-03T11:26:51Z 0f28194)

[judnich]

Some additional observations for now (until I can get you a repro dataset):

1. Same bugs occur when using microsecond precision timestamps configured in the Quickwit index.
2. Same bugs occur when I try query expressions using RFC3339 timestamps instead of numeric literals.
3. In addition to the >= issue mentioned above, searching for > time (with ascending time sort order) often skips over several of the next entries above time, which should have been returned first if the sorting and range bound was applied correctly.
4. Ascending sort order is apparently specified via a "-" prefix (vs "+" for descending) to the "sort_by" API field? Seems like an odd inversion of convention, but it's fine if this is intentional (weird though it may be). I only mention it in case it is not intentional.

(3) is particularly damaging to any ability to correctly paginate large queries, using a Elasticsearch-style search_after approach to paging where you make subsequent queries with search_after { previous page's last item's timestamp (+ other sort keys) }.

FWIW I also tried the Elasticsearch compatibility API to even less avail! There is also a different bug there, where the timestamps in the last entry JSON's "sort" field are rounded to a much lower resolution (seconds, IIRC) than the timestamp field or what was queried via "search_after". So the end result is that you could query Elasticsearch compatibility API with "search_after" with timestamp 123456789, and the result would contain entries where the last hit's "sort" field contains a truncated timestamp like "123456" (not real timestamps, but you get the idea). This bug makes "search_after" paging useless / dangerous, since the whole point of the "sort" field attached to hits from Elasticsearch API is that you can take the last hit's "sort" property value, and pass it in directly to the next query via "search_after", to get the next page correctly. But due to this incorrect aggressive rounding, typical Elasticsearch search_after style paging will infinite loop using the Quickwit Elasticsearch compatibility API.

I didn't file a bug on the Elasticsearch compatibility API only in the interest of time and prioritization -- I don't need Elasticsearch compatibility, I just need to be able to do paging correctly (ideally without having to work around "fuzzy" range bounds).

[rdettai-sk]

@judnich I think I stumbled on the same problem as you and #6201 should solve it 😉