search

nats-io / nats-server

High-Performance server for NATS.io, the cloud and edge native messaging system.
https://nats.io
Apache License 2.0
16.08k stars 1.42k forks source link

Stream FirstSeq is far behind all consumers Ack Floor [v2.9.15] #3996

Open ewirch opened 1 year ago

ewirch commented 1 year ago

Defect

Sorry, I can't provide an example to reproduce the case. I don't know how this happens. With a little help from you devs I might be able to collect enough information to understand the problem.

We have multiple streams, which report a FirstSeq ID, which is far behind any existing consumer "Ack Floor". Also the ID does not exist any more.

$ nats stream info api-delivery-email_transactional
Information for Stream api-delivery-email_transactional created 2022-04-27 15:59:58

             Subjects: api.delivery.email_transactional.*
             Replicas: 3
              Storage: File

Options:

            Retention: WorkQueue
     Acknowledgements: true
       Discard Policy: Old
     Duplicate Window: 2m0s
    Allows Msg Delete: true
         Allows Purge: true
       Allows Rollups: false

Limits:

     Maximum Messages: unlimited
  Maximum Per Subject: unlimited
        Maximum Bytes: unlimited
          Maximum Age: unlimited
 Maximum Message Size: unlimited
    Maximum Consumers: unlimited

Cluster Information:

                 Name: nats-prod-cluster
               Leader: nats-1
              Replica: nats-0, current, seen 0.14s ago
              Replica: nats-2, current, seen 0.14s ago

State:

             Messages: 0
                Bytes: 0 B
             FirstSeq: 45
              LastSeq: 235,189 @ 2023-03-27T22:37:24 UTC
     Deleted Messages: 235,145
     Active Consumers: 1

FirstSeq is 45. 

$ nats consumer report api-delivery-email_transactional
╭───────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────╮
│                               Consumer report for api-delivery-email_transactional with 1 consumers                               │
├────────────────────┬──────┬────────────┬──────────┬─────────────┬─────────────┬─────────────┬───────────┬─────────────────────────┤
│ Consumer           │ Mode │ Ack Policy │ Ack Wait │ Ack Pending │ Redelivered │ Unprocessed │ Ack Floor │ Cluster                 │
├────────────────────┼──────┼────────────┼──────────┼─────────────┼─────────────┼─────────────┼───────────┼─────────────────────────┤
│ delivery-service-1 │ Pull │ Explicit   │ 30.00s   │ 0           │ 0           │ 0           │ 235,189   │ nats-0*, nats-1, nats-2 │
╰────────────────────┴──────┴────────────┴──────────┴─────────────┴─────────────┴─────────────┴───────────┴─────────────────────────╯
$ nats consumer info api-delivery-email_transactional delivery-service-1
Information for Consumer api-delivery-email_transactional > delivery-service-1 created 2023-03-22T09:46:48+01:00

Configuration:

        Durable Name: delivery-service-1
           Pull Mode: true
      Filter Subject: api.delivery.email_transactional.*
      Deliver Policy: All
          Ack Policy: Explicit
            Ack Wait: 30s
       Replay Policy: Instant
     Max Ack Pending: 100
   Max Waiting Pulls: 512

Cluster Information:

                Name: nats-prod-cluster
              Leader: nats-0
             Replica: nats-1, current, seen 0.85s ago
             Replica: nats-2, current, seen 0.85s ago

State:

   Last Delivered Message: Consumer sequence: 235,144 Stream sequence: 235,189 Last delivery: 5h54m35s ago
     Acknowledgment floor: Consumer sequence: 235,144 Stream sequence: 235,189 Last Ack: 5h54m35s ago
         Outstanding Acks: 0 out of maximum 100
     Redelivered Messages: 0
     Unprocessed Messages: 0
            Waiting Pulls: 1 of maximum 512

Trying to retrieve the message fails:

$ nats stream get api-delivery-email_transactional 45
nats: error: could not retrieve api-delivery-email_transactional#45: no message found (10037)

nats-server -DV output

[INF] Starting nats-server
[INF]   Version:  2.9.15
[INF]   Git:      [b91fa85]
[DBG]   Go build: go1.19.6
[INF]   Name:     NCFCCTSZHOWPBOLPNQOEYE3NTEQ7WLTP6Q2REAOF6I4YT5G3T4XYF5CL
[INF]   ID:       NCFCCTSZHOWPBOLPNQOEYE3NTEQ7WLTP6Q2REAOF6I4YT5G3T4XYF5CL
[DBG] Created system account: "$SYS"
[FTL] Error listening on port: 0.0.0.0:4222, "listen tcp 0.0.0.0:4222: bind: address already in use"

Versions of nats-server and affected client libraries used:

nats-server: 2.9.15 (it is possible that the situation was created by an older version (2.8), but the update to 2.9.15 didn't solve it either)

OS/Container environment:

Google Kubernetes Engine 1.24.10-gke.1200

Expected result:

FirstSeq is moved to the oldest existing message, not yet acknowledged by at least one consumer.

Actual result:

FirstSeq is stale, pointing to a non-existing message.

derekcollison commented 1 year ago

We are aware of this issue and working on completing a fix that will roll out for 2.9.16.

stitchcula commented 6 months ago

I also encountered the same situation, where the issue reliably occurs when power off and restart. After restarting, all consumers are unable to self-recover and fail to receive messages. The related issue is https://github.com/nats-io/nats-server/issues/4566 . I believe this is a server-side problem and should not be circumvented by client-side operations like deleting and re-adding consumers.

I conducted power-off tests on the following versions, and all exhibited the issue:

I tested various sync time periods, including 'sync: always', but it doesn't seem to have much effect.

jetstream {
    store_dir: /userdata/nats
    max_mem: 100M
    max_file: 500M
    sync: always # 1s to 2min
}

The following information will appear in the logs:

[INF]   Starting restore for stream '$G > TEST_STREAM'
[1471] 2024/05/11 16:11:09.915294 [WRN] Filestore [TEST_STREAM] Stream state detected prior state, could not locate msg block 1244
[1471] 2024/05/11 16:11:09.936155 [INF]   Restored 0 messages for stream '$G > TEST_STREAM' in 77ms

and then:

[WRN] Detected consumer '$G > TEST_STREAM > test_consumer' ack floor 14084 is ahead of stream's last sequence 0

It appears that the blk index in index.db actually cannot be found on the disk.

This issue is beyond my ability to fix quickly. I earnestly seek assistance. @derekcollison @bruth

derekcollison commented 6 months ago

Can you describe a bit more on the details of your testing?

How do you perform power off? Is it for all servers or just some? How do you restart the servers / cluster?

stitchcula commented 6 months ago

Can you describe a bit more on the details of your testing?

How do you perform power off? Is it for all servers or just some? How do you restart the servers / cluster?

I conducted tests using a single-node NATS JetStream running on a standalone server, and the method of restarting was to directly cut off the server's power supply. After the restart, it was almost 100% likely to reproduce the situation described in the issue, where the consumer's ack floor is greater than the stream's last sequence, resulting in all consumers being unable to consume. I have used multiple servers for testing, and have tested with various file systems (xfs, ext4) and types of disks (nano flash, SSD, mechanical hard disk) to rule out the possibility of randomness. I can provide more logs and information when I come to work tomorrow.

derekcollison commented 6 months ago

Thanks that is helpful. Will try to recreate and see if we can improve.

stitchcula commented 6 months ago

Thanks that is helpful. Will try to recreate and see if we can improve.

Because there is a lot of information, I have reorganized it into a new issue https://github.com/nats-io/nats-server/issues/5412. This situation has occurred frequently in our production environment. I am seeking help, thank you very much.

derekcollison commented 6 months ago

Are you a Synadia customer?

derekcollison commented 6 months ago

@stitchcula could you try top of main?