Mirrored stream with deletions returns too old messages

[ahirner]

Observed behavior

We have one app source and created an app_replica.
mirror_with_deled_fails.json

$ nats s report
Obtaining Stream stats

╭──────────────────────────────────────────────────────────────────────────────────────────────────╮
│                                           Stream Report                                          │
├─────────────┬─────────┬───────────┬───────────┬───────────┬──────────┬──────┬─────────┬──────────┤
│ Stream      │ Storage │ Placement │ Consumers │ Messages  │ Bytes    │ Lost │ Deleted │ Replicas │
├─────────────┼─────────┼───────────┼───────────┼───────────┼──────────┼──────┼─────────┼──────────┤
│ app_replica │ Memory  │           │         0 │ 725,105   │ 425 MiB  │ 0    │  387018 │          │
│ app         │ File    │           │         0 │ 1,653,467 │ 1024 MiB │ 0    │ 5666872 │          │
╰─────────────┴─────────┴───────────┴───────────┴───────────┴──────────┴──────┴─────────┴──────────╯

╭────────────────────────────────────────────────────────────────────────────────────────────────────────╮
│                                           Replication Report                                           │
├─────────────┬────────┬────────────┬───────────────┬────────────────────────┬────────┬───────┬───────┬──┤
│ Stream      │ Kind   │ API Prefix │ Source Stream │ Filters and Transforms │ Active │ Lag   │ Error │  │
├─────────────┼────────┼────────────┼───────────────┼────────────────────────┼────────┼───────┼───────┼──┤
│ app_replica │ Mirror │            │ app           │                        │        │ 115ms │ 0     │  │
╰─────────────┴────────┴────────────┴───────────────┴────────────────────────┴────────┴───────┴───────┴──╯

The source returns messages starting at the correct time:

The mirror returns older messages than requested:

If the mirror is started from a sequence or time where 0 deletions happened yet, it returns messages starting at the correct time.

It doesn't matter if the mirror replica is file or memory based.

The extra messages returned amount roughly, but seemingly not exactly to the amount of Deleted messages in the replica.

Expected behavior

Messages older than requested are not included in the response.

Server and client version

server: 2.10.22 and 2.10.23-RC.4 (tried after reading #6076).
client: 0.1.5

Host environment

Mac OS x84 darwin, same on linux docker.

Steps to reproduce

I've yet to find a more minimal and reproducer. In other words, I expected this script to return older than requested messages, but it doesn't.
single_node_timestamp_problem.sh.txt
Any pointers appreciated. The defect may for example only happen, if the source stream is fragmented more than what is easy to reproduce or if the Deleted count and structure differs from source to mirror.

[ahirner]

Another interesting observation.
If I omit "opt_start_time": "2024-11-10T09:00:00Z", the mirror doesn't ever seem to catch up fully. There are no server errors.

$ nats s report
Obtaining Stream stats

╭──────────────────────────────────────────────────────────────────────────────────────────────────╮
│                                           Stream Report                                          │
├─────────────┬─────────┬───────────┬───────────┬───────────┬──────────┬──────┬─────────┬──────────┤
│ Stream      │ Storage │ Placement │ Consumers │ Messages  │ Bytes    │ Lost │ Deleted │ Replicas │
├─────────────┼─────────┼───────────┼───────────┼───────────┼──────────┼──────┼─────────┼──────────┤
│ app_replica │ Memory  │           │         0 │ 1,473,238 │ 891 MiB  │ 0    │ 5847046 │          │
│ app         │ File    │           │         0 │ 1,653,477 │ 1024 MiB │ 0    │ 5666537 │          │
╰─────────────┴─────────┴───────────┴───────────┴───────────┴──────────┴──────┴─────────┴──────────╯

╭────────────────────────────────────────────────────────────────────────────────────────────────────────╮
│                                           Replication Report                                           │
├─────────────┬────────┬────────────┬───────────────┬────────────────────────┬────────┬───────┬───────┬──┤
│ Stream      │ Kind   │ API Prefix │ Source Stream │ Filters and Transforms │ Active │ Lag   │ Error │  │
├─────────────┼────────┼────────────┼───────────────┼────────────────────────┼────────┼───────┼───────┼──┤
│ app_replica │ Mirror │            │ app           │                        │        │ 487ms │ 0     │  │
╰─────────────┴────────┴────────────┴───────────────┴────────────────────────┴────────┴───────┴───────┴──╯

Their State is inconsistent:

$ nats s info app |grep State -A 10
State:

              Messages: 1,653,479
                 Bytes: 1024 MiB
        First Sequence: 19,296,779 @ 2024-09-10 05:24:05
         Last Sequence: 26,616,794 @ 2024-11-24 07:53:23
      Deleted Messages: 5,666,537
      Active Consumers: 0
    Number of Subjects: 2,626

$ nats s info app_replica |grep State -A 10
State:

              Messages: 1,473,306
                 Bytes: 891 MiB
        First Sequence: 19,296,443 @ 2024-09-10 05:24:05
         Last Sequence: 26,616,794 @ 2024-11-24 07:53:23
      Deleted Messages: 5,847,046
      Active Consumers: 0
    Number of Subjects: 2,290

If I set opt_start_time to an early enough time, such that Deleted count is 0 in the mirror (but not in the source), there is no defect, as implied by the title.