Loki: Query `start` is not always inclusive

[jgehrcke]

By design, the start query parameter is supposed to be inclusive (a log entry with precisely this timestamp is supposed to be returned by a corresponding query) whereas the end parameter is supposed to be exclusive (a log entry with this timestamp is expected to _not_ be returned by the query).

This largely seems to hold true.

However, as part of synthetic workload testing we have found that in rare cases the query start parameter did not behave inclusive.

This appeared to be reproducible for the very same query (at least for a small number of repetitions < 10).

Example: query with start=1590396230133000000 (Python w/ requests):

>>> import requests
>>> qparams = {
...   "query": "{streamname=\"looker-1590396228-YPd0cySxXQ-00101-XW7MH-0001\",  <snip>}",
...   "direction": "FORWARD",
...   "regexp": "",
...   "limit": "60000",
...   "start": "1590396230133000000",
...   "end": "1590396230193000000"
... }
>>> data = requests.get("https://<snip>/api/prom/query", params=qparams, verify=False).json()
>>> data['streams'][0]['entries'][0]
{'ts': '2020-05-25T08:43:50.133001Z', 'line': '1590396230133001000:<snip>'}
>>> 

The response does not contain a log entry with the timestamp 1590396230133000000.

Next query however shows that this log entry exists:

>>> qparamsfine = {
...   "query": "{streamname=\"looker-1590396228-YPd0cySxXQ-00101-XW7MH-0001\", <snip>}",
...   "direction": "FORWARD",
...   "regexp": "",
...   "limit": "60000",
...   "start": "1590396230132997000",
...   "end": "1590396230133003000"
... }
>>> datafine = requests.get("https://<snip>/api/prom/query", params=qparamsfine, verify=False).json()
>>> datafine['streams'][0]['entries'][3]
{'ts': '2020-05-25T08:43:50.133Z', 'line': '1590396230133000000:<snip>''}

Observed with Loki version 1.4.1.

[cyriltovena]

By design, the start query parameter is supposed to be inclusive (a log entry with precisely this timestamp is supposed to be returned by a corresponding query) whereas the end parameter is supposed to be exclusive (a log entry with this timestamp is expected to not be returned by the query).

Where did you find this in the documentation ?

From the code it looks like this hasn't change for a while, not sure where this is happening yet.

I'll try to reproduce it.

[jgehrcke]

Where did you find this in the documentation ?

I think I at some point found conversations here in the issue tracker confirming that. Looking.

More importantly, we tested this ourselves and this has been the behavior for quite a while.

[jgehrcke]

I think I also at some point found conversations here in the issue tracker confirming that. Looking.

Funny, @cyriltovena this was you:

@hugohaggmark yes this is normal, the end is exclusive but the start is inclusive. You don't have to feel like a newb this is not documented properly.

https://github.com/grafana/loki/issues/597#issuecomment-506408980

You also opened https://github.com/grafana/loki/issues/1570 a while ago :). Clearly related, if not even a "duplicate".

We should have the start inclusive and end exclusive for log query requests and also add this as part of the API documentation. The precision should be nanoseconds.

[cyriltovena]

Do you remember when it was working which version you were using ? Also you're saying the issue doesn't happen all the time ?

[cyriltovena]

I'm having hard time to reproduce this issue. It must be a specific code path being activated.

[jgehrcke]

Do you remember when it was working which version you were using ?

I think when we first set out to test empirically which of both parameters is inclusive and which is exclusive we were using Loki version 1.2.0.

[jgehrcke]

I'm having hard time to reproduce this issue

Note that we do a _lot_ of querying with this synthetic workload.

I have an interesting number for us: the probability for a query to be affected in our test is about 1/1000 (order of magnitude).

In other words: for every query affected by this problem about ~1000 queries work as expected (with start being inclusive).

I can't see a conceptual difference between the queries that fail in the described way and the queries that return data as expected.

[cyriltovena]

There's a stats property in the response could you share one of the failing one ? This would help me see if this is only from the store or ingesters.

Are you querying across multiple streams ? Can you increase the max_chunk_batch_size
https://github.com/grafana/loki/tree/master/docs/configuration to 200 I'm wondering if it's chunk overlaping causing this, increasing could make it so it happens less, I'm looking for informations to reduce my search to find where this is happening :)

Any chance you could share the chunk that contains this missing line so I could inspect it too ?

[jgehrcke]

There's a stats property in the response could you share one of the failing one ?

OK, that was easy for me. This is the stats property in a query response of a query that yielded 59999 entries instead of the expected 60000:

{
  "summary": {
    "bytesProcessedPerSeconds": 55134952,
    "linesProcessedPerSeconds": 249479,
    "totalBytesProcessed": 14172730,
    "totalLinesProcessed": 64130,
    "execTime": 0.257055268
  },
  "store": {
    "totalChunksRef": 3,
    "totalChunksDownloaded": 3,
    "chunksDownloadTime": 0.06060643,
    "headChunkBytes": 0,
    "headChunkLines": 0,
    "decompressedBytes": 12803635,
    "decompressedLines": 57935,
    "compressedBytes": 4675989,
    "totalDuplicates": 4128
  },
  "ingester": {
    "totalReached": 7,
    "totalChunksMatched": 3,
    "totalBatches": 51,
    "totalLinesSent": 6192,
    "headChunkBytes": 0,
    "headChunkLines": 0,
    "decompressedBytes": 1369095,
    "decompressedLines": 6195,
    "compressedBytes": 631752,
    "totalDuplicates": 0
  }
}

[jgehrcke]

Any chance you could share the chunk that contains this missing line so I could inspect it too ?

This is tough as I don't quite know how to do this.

[jgehrcke]

Are you querying across multiple streams ? Can you increase the max_chunk_batch_size
https://github.com/grafana/loki/tree/master/docs/configuration to 200

We could certainly try do that but not quite immediately. Will note this down for one of the next deployments.

I'm looking for informations to reduce my search to find where this is happening :)

Yes, thanks for your initiative here!

[cyriltovena]

No need to test the new max_chunk_batch_size it seems that it happens with only 3 chunks.

[cyriltovena]

If you supplied the same query again long after (say 2hours) do you still see the entry missing ? (trying to know if this is because of ingesters which returns only recent data)

How do you deploy Loki ? with helm ? How does the config look like ?

[jgehrcke]

If you supplied the same query again long after (say 2hours) do you still see the entry missing ? (trying to know if this is because of ingesters which returns only recent data)

Yes, just reproduced with literally the same query as shown in the initial post above, still returning 59999 entries instead of 60000, still the first entry missing.

How do you deploy Loki ? with helm ?

Not with Helm, it's a custom deployment.

How does the config look like ?

Our cfg is so far for "playing with the system" (not yet a tuned config at all). Many default parameters.

non-default ingester config:

      chunk_retain_period: "5m"
      chunk_target_size: 2000000
      max_chunk_age: "2h"
      chunk_idle_period: "2h"

In this specific setup we use memcached for chunk_cache, write_dedupe_cache, index_queries_cache.

[cyriltovena]

Can you show the stats the second time ? I want to see if ingester are returning data ?

[jgehrcke]

Can you show the stats the second time ?

Yes. Still had the terminal running with the Python interpreter with which I ran the query mentioned in https://github.com/grafana/loki/issues/2124#issuecomment-633656059. stats object:

{
  "summary": {
    "bytesProcessedPerSeconds": 23565207,
    "linesProcessedPerSeconds": 106629,
    "totalBytesProcessed": 13260000,
    "totalLinesProcessed": 60000,
    "execTime": 0.562693962
  },
  "store": {
    "totalChunksRef": 4,
    "totalChunksDownloaded": 4,
    "chunksDownloadTime": 0.369945689,
    "headChunkBytes": 0,
    "headChunkLines": 0,
    "decompressedBytes": 13260000,
    "decompressedLines": 60000,
    "compressedBytes": 4886573,
    "totalDuplicates": 0
  },
  "ingester": {
    "totalReached": 7,
    "totalChunksMatched": 0,
    "totalBatches": 0,
    "totalLinesSent": 0,
    "headChunkBytes": 0,
    "headChunkLines": 0,
    "decompressedBytes": 0,
    "decompressedLines": 0,
    "compressedBytes": 0,
    "totalDuplicates": 0
  }
}

Does that make any sense at all?

[jgehrcke]

A third time. From right now.

>>> data = requests.get("https://<snip>/api/prom/query", params=qparams, verify=False).json()
>>> len(data['streams'][0]['entries'])
59999
>>> data['stats']
{'summary': {'bytesProcessedPerSeconds': 23503986, 'linesProcessedPerSeconds': 106352, 'totalBytesProcessed': 13260000, 'totalLinesProcessed': 60000, 'execTime': 0.564159624}, 'store': {'totalChunksRef': 4, 'totalChunksDownloaded': 4, 'chunksDownloadTime': 0.313126543, 'headChunkBytes': 0, 'headChunkLines': 0, 'decompressedBytes': 13260000, 'decompressedLines': 60000, 'compressedBytes': 4886573, 'totalDuplicates': 0}, 'ingester': {'totalReached': 7, 'totalChunksMatched': 0, 'totalBatches': 0, 'totalLinesSent': 0, 'headChunkBytes': 0, 'headChunkLines': 0, 'decompressedBytes': 0, 'decompressedLines': 0, 'compressedBytes': 0, 'totalDuplicates': 0}}

Interestingly, in those last two summaries (this comment, previous comment) we see four downloaded chunks and "totalLinesProcessed": 60000.

[cyriltovena]

One chunk was probably not flushed yet. But since it still happening it reduces where I have to search.

Thanks for this. Do you run query-frontend ? or do you query directly the querier ?

[jgehrcke]

@cyriltovena I could try to fetch the raw chunks (stored in GCS), if I just knew how to find out which objects these are exactly, i.e. guess I want to learn how to read the index (Bigtable). Any docs on that?

[jgehrcke]

Do you run query-frontend ? or do you query directly the querier ?

Directly to the querier, if I am not mistaken.

[cyriltovena]

The index is from Cortex, it's an inverted index with the label names and values. Not really easy for a human to read and not really documented. https://cortexmetrics.io/

I'm thinking.....

The logcli has a way to run against GCS/bigtable directly using the querier code. You could give a go to that and see if that does still happens. If it does then I could modify it a bit within a branch so that you can download those chunk and share them for repro.

WDYT ?

[cyriltovena]

logcli query
--from=2020-05-14T00:00:05.781889298Z
--to=2020-05-14T00:01:00Z
--limit=3
--forward
--store-config=/Users/ctovena/local-gcs.yaml
'{container_name="ingress-nginx"}'

my config look like this :

chunk_store_config:
  max_look_back_period: 2160h
  write_dedupe_cache_config:
distributor:
frontend:
frontend_worker:
ingester:
limits_config:
  enforce_metric_name: false
  ingestion_burst_size_mb: 20
  ingestion_rate_mb: 10
  ingestion_rate_strategy: global
  max_global_streams_per_user: 10000
  max_query_length: 12000h
  max_query_parallelism: 32
  max_streams_per_user: 0
  reject_old_samples: true
  reject_old_samples_max_age: 168h
querier:
  engine:
    timeout: 5m
  query_timeout: 5m
query_range:
schema_config:
  configs:
    - from: "2018-04-15"
      index:
        period: 168h
        prefix: loki_dev_index_
      object_store: gcs
      schema: v9
      row_shards: 16
      store: bigtable
    - from: "2019-10-30"
      index:
        period: 168h
        prefix: loki_dev_index_
      object_store: gcs
      schema: v11
      row_shards: 16
      store: bigtable
server:
  graceful_shutdown_timeout: 5s
  grpc_server_max_concurrent_streams: 1000
  grpc_server_max_recv_msg_size: 1.048576e+08
  grpc_server_max_send_msg_size: 1.048576e+08
  http_server_idle_timeout: 120s
  http_server_write_timeout: 1m
storage_config:
  bigtable:
    instance: dev-us-central1
    project: grafanalabs-dev
  gcs:
    bucket_name: dev-us-central1-loki-dev
  max_chunk_batch_size: 50
table_manager:
  retention_deletes_enabled: true
  retention_period: 2520h

[cyriltovena]

I could also build a branch of Loki that logs the chunk name before downloading it. but that requires you to deploy a new image while with logcli you don't really need to it will directly query GCS.

[jgehrcke]

Do you have a docker image for logcli? I quickly tried building locally, started to look like a rabbit hole to me (not having Go 1.13 set up, etc). https://hub.docker.com/r/grafana/logcli looks pretty empty!

Edit: checking out for today. Thanks for the effort, be back tmrw.

[cyriltovena]

I'll build one later !

[cyriltovena]

Not fully sure, I still need to prove it with tests.

But I think I have an idea of what's going on. I have a feeling that the timestamp is exactly the min timestamp of a chunk block. And it seems to be skipped.

If this is true writing some tests will be simple. Trying now. That would explain why you can repro at 100% with the same query and why it rare, e.g you would need a query that is exactly at the boundaries of a block.

FYI on what is a chunk.

A single chunk contains entries for the same streams.
Chunks contains 11 blocks (if full) and a header. The header contains position of each block and their max/min timestamp. Each block contains entries. Why blocks position ? it is to be able to skip through blocks, some sort of intermediary index within a chunk itself. That's a quick explanation but the header contains also the encoding, checksum and some magic bits.

[cyriltovena]

In the meantime here is the docker image for the CLI grafana/logcli:logci-docker-e6ce9fe-WIP

and this how I used it

docker run -v /Users/ctovena/local-gcs.yaml:/Users/ctovena/local-gcs.yaml  -v ~/.config:/root/.config grafana/logcli:logci-docker-e6ce9fe-WIP query --from="2020-05-14T00:00:05.781889298Z" --to="2020-05-14T00:10:00Z" \
--limit=100 \
--forward --org-id=3927 \
--store-config=/Users/ctovena/local-gcs.yaml \
'{container_name="ingress-nginx"}'

It will print first the amount of chunk found then the list of their external name which you can found in GCS see example:

11
3927/49ebe87920d33438:172107eee92:172107f15f3:f1728765
3927/52a4146eacc23d7a:172107eee93:172107f15ef:6b4eedbd
3927/7531e6c9fe474878:17210795b70:172107c1b77:4e05013a
3927/7531e6c9fe474878:172107c1be1:172108198fd:b7d23976
3927/7531e6c9fe474878:172108198fd:17210873e31:ca4ca7c7
3927/8361dcc9dd940c0b:172107eee94:172107f15ee:67f8673e
3927/a4f42e6e8f117909:1721077ad70:172107d154c:a7b94f65
3927/a4f42e6e8f117909:172107d154e:17210801d2d:9096d490
3927/a4f42e6e8f117909:17210801d49:172108598b7:1707b219
3927/bfbbd2790300704b:17210798d19:172107f3835:3f464791
3927/bfbbd2790300704b:172107f3836:1721084f0ff:8cbc6c7
log follow......

use fake as org-id if you're using single tenant mode and this -v ~/.config:/root/.config is to mount gcloud credentials.

I already shared above my config file to give you an idea you only need to replace the storage config.

storage_config:
  bigtable:
    instance: dev-us-central1
    project: grafanalabs-dev
  gcs:
    bucket_name: dev-us-central1-loki-dev

The rest is noise but required, you can use the same as me.

Thanks for the help, I usually give a lot of effort on issues where logs are missing !!!!!!! Thus why I'm verbose and trying to get the maximum intel from your setup.

[jgehrcke]

Thanks for providing logcli @cyriltovena. Got a super narrow repro with logcli, and I think a major finding that allows us to track down the off-by-one error (you had the right suspicion!).

Queried --from="2020-05-25T08:43:50.132997000Z" --to="2020-05-25T08:43:50.133006000Z":
(notice how close these two timestamps are!)

1
default/ff3d4552160465d5:1724b0099e9:1724b009a01:5a51dc30
2020-05-25T08:43:50Z {} 1590396230132997000:AFW8gSed4g/htlR/n79hyzvdnqYKKgUfbv8pjWI9D7DxOyd+HEr9ZNFer9rbFjpau+JFIxW0i62EjPKt3iLB0brD12aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa
2020-05-25T08:43:50Z {} 1590396230132998000:EQlBSSXqpP3BLTK6WND8e7ova+AfA6HRKHz9TiHfcu9nFgGW9jMkVFkIN0t5gHL8YEut8o4OhsW9AzerJHmKQI5aVuaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa
2020-05-25T08:43:50Z {} 1590396230132999000:byg1RTkBHwMQ9Oq+qutAUM+mNDCYCMNIzQUsiBRsv6zlQoNslh8rU0DwJfQJ8mwWrVipd7TRN3yR24oAHrZeLQ5Fk6aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa
2020-05-25T08:43:50Z {} 1590396230133000000:uqGRFGYSSoTiyZgIwVUC6VVCE3KnIVnOQkfFwj0F58XJU7jHdqXA4/r93cc7Nqya6ONVClTQpAFBoZo/bikS+JW+1Haaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa
2020-05-25T08:43:50Z {} 1590396230133001000:lU8Wnyll5EnBpc3XBe1RXzVuw27R+EJKTA5gNXicn1kzLMacHQclQzt3HtLChAeMEBfealCp5Efy4sb7mxk4ZpY/Tfaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa
2020-05-25T08:43:50Z {} 1590396230133002000:HIt2bmb884mV4cyzIjQ0G8yEaRHzxZYdlNyME3LZlqJEHxEPbA6KaVei2XFuZJxNQLVNnhvlmoVOx5TO+AoEm04ALPaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa
2020-05-25T08:43:50Z {} 1590396230133003000:KPrDyux/9jOz2l37QRzhRlT9gFm9vBu4FKNakkZTlSDuDSWp74XevKdL/78410UWp/6ghZml9WH3CTZ0z/3xCp0+BPaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa
2020-05-25T08:43:50Z {} 1590396230133004000:HSJOWh/hbhlWHv/ncOoZcRb/eK1wiZHFDxSa0e/HFuYgYQjpcRiTLQCoQltpPHmpAFn5MXbwxGpB04zsObhpIyyn7baaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa
2020-05-25T08:43:50Z {} 1590396230133005000:/biwL1XWrgvuvses41rXnP01aKM2nSc0av1CRNqOjigMu7wU1YA93AaTJ20qmDhV6PWKsyN6rruKkrZZSOuu+eHysbaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa

The entry in question is returned, position 4, timestamp 1590396230133000000.

Same query but with --from="2020-05-25T08:43:50.133000000Z" --to="2020-05-25T08:43:50.133006000Z" (entry in question used as start):

1
default/ff3d4552160465d5:1724b0099e9:1724b009a01:5a51dc30
2020-05-25T08:43:50Z {} 1590396230133001000:lU8Wnyll5EnBpc3XBe1RXzVuw27R+EJKTA5gNXicn1kzLMacHQclQzt3HtLChAeMEBfealCp5Efy4sb7mxk4ZpY/Tfaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa
2020-05-25T08:43:50Z {} 1590396230133002000:HIt2bmb884mV4cyzIjQ0G8yEaRHzxZYdlNyME3LZlqJEHxEPbA6KaVei2XFuZJxNQLVNnhvlmoVOx5TO+AoEm04ALPaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa
2020-05-25T08:43:50Z {} 1590396230133003000:KPrDyux/9jOz2l37QRzhRlT9gFm9vBu4FKNakkZTlSDuDSWp74XevKdL/78410UWp/6ghZml9WH3CTZ0z/3xCp0+BPaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa
2020-05-25T08:43:50Z {} 1590396230133004000:HSJOWh/hbhlWHv/ncOoZcRb/eK1wiZHFDxSa0e/HFuYgYQjpcRiTLQCoQltpPHmpAFn5MXbwxGpB04zsObhpIyyn7baaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa
2020-05-25T08:43:50Z {} 1590396230133005000:/biwL1XWrgvuvses41rXnP01aKM2nSc0av1CRNqOjigMu7wU1YA93AaTJ20qmDhV6PWKsyN6rruKkrZZSOuu+eHysbaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa

Entry (start boundary) not returned.

I downloaded chunk default/ff3d4552160465d5:1724b0099e9:1724b009a01:5a51dc30 and inspected it manually.

It has 17 gzip-encoded blocks (identified using the gzip start byte sequence 1f 8b 08):

$ cat default_ff3d4552160465d5_1724b0099e9_1724b009a01_5a51dc30 | hexdump -C | grep '1f 8b 08' | wc -l
17

The trailing entry in block 8 is the log entry missing in the query response:

$ cat default_ff3d4552160465d5_1724b0099e9_1724b009a01_5a51dc30 | tail -c +843092 | gunzip | hexdump -C | tail -n 25

gzip: stdin: decompression OK, trailing garbage ignored
000436c0  61 61 61 61 61 61 61 61  61 61 61 61 61 61 61 61  |aaaaaaaaaaaaaaaa|
*
00043700  61 61 61 61 61 61 61 61  61 61 61 61 b0 8d 95 d3  |aaaaaaaaaaaa....|
00043710  bd bc 9c 92 2c c9 01 31  35 39 30 33 39 36 32 33  |....,..159039623|
00043720  30 31 33 32 39 39 39 30  30 30 3a 62 79 67 31 52  |0132999000:byg1R|
00043730  54 6b 42 48 77 4d 51 39  4f 71 2b 71 75 74 41 55  |TkBHwMQ9Oq+qutAU|
00043740  4d 2b 6d 4e 44 43 59 43  4d 4e 49 7a 51 55 73 69  |M+mNDCYCMNIzQUsi|
00043750  42 52 73 76 36 7a 6c 51  6f 4e 73 6c 68 38 72 55  |BRsv6zlQoNslh8rU|
00043760  30 44 77 4a 66 51 4a 38  6d 77 57 72 56 69 70 64  |0DwJfQJ8mwWrVipd|
00043770  37 54 52 4e 33 79 52 32  34 6f 41 48 72 5a 65 4c  |7TRN3yR24oAHrZeL|
00043780  51 35 46 6b 36 61 61 61  61 61 61 61 61 61 61 61  |Q5Fk6aaaaaaaaaaa|
00043790  61 61 61 61 61 61 61 61  61 61 61 61 61 61 61 61  |aaaaaaaaaaaaaaaa|
*
000437e0  80 9d 95 d3 bd bc 9c 92  2c c9 01 31 35 39 30 33  |........,..15903|
000437f0  39 36 32 33 30 31 33 33  30 30 30 30 30 30 3a 75  |96230133000000:u|
00043800  71 47 52 46 47 59 53 53  6f 54 69 79 5a 67 49 77  |qGRFGYSSoTiyZgIw|
00043810  56 55 43 36 56 56 43 45  33 4b 6e 49 56 6e 4f 51  |VUC6VVCE3KnIVnOQ|
00043820  6b 66 46 77 6a 30 46 35  38 58 4a 55 37 6a 48 64  |kfFwj0F58XJU7jHd|
00043830  71 58 41 34 2f 72 39 33  63 63 37 4e 71 79 61 36  |qXA4/r93cc7Nqya6|
00043840  4f 4e 56 43 6c 54 51 70  41 46 42 6f 5a 6f 2f 62  |ONVClTQpAFBoZo/b|
00043850  69 6b 53 2b 4a 57 2b 31  48 61 61 61 61 61 61 61  |ikS+JW+1Haaaaaaa|
00043860  61 61 61 61 61 61 61 61  61 61 61 61 61 61 61 61  |aaaaaaaaaaaaaaaa|
*
000438b0  61 61 61 61                                       |aaaa|
000438b4

Clarification:

• The tail -c +843092 skips that many leading bytes of the chunk (I manually chose 843092 so that we gzip-decompress specifically block 8 of 17 in this chunk; tried others, too, via trial and error, looking for our log entry in question).
• gunzip fails upon the end of that block, i.e. the final | tail -n 25 indeed shows the _trailing_ part of the payload part of block 8.

This confirms that the start boundary of our query is at the boundary between two blocks encoded in this chunk, with the query start timestamp value corresponding to the trailing entry in a block.

[cyriltovena]

Wow ! You did a nice analysis, thank you so much. Really appreciate the effort, it would be so hard to find this one.

I'm going to open a PR soon, if you can take a look at it see if that makes sense. I found 2 issues and I have tests to prove them.

PS: Like always the famous off by one !

[jgehrcke]

I'm going to open a PR soon, if you can take a look at it see if that makes sense. I found 2 issues and I have tests to prove them.

Lovely. Looking forward to seeing these patches :-). Great collaboration!

[jgehrcke]

Thanks for the PR @cyriltovena!

I'm going to open a PR soon, if you can take a look at it see if that makes sense

I had a quick peek and it looks like you indeed found some booboos haha... just want to say that I will not have the time to review this. Additional tests of course go into the right direction! Big thanks!