nats-server icon indicating copy to clipboard operation
nats-server copied to clipboard

Should I pay attention to "Delivery Terminated" advisory messages?

Open Kaarel opened this issue 1 year ago • 1 comments

I have a application subscribed to a durable consumer. When a message is consumed it is removed by the stream as per retention rules. The setup seems to be working as the stream message count stays at 0.

However when observing nats event --js-advisory results I noticed these every few minutes or so

...
[ More "Delivery Terminated" events ]
...

[15:57:24] [GG9sNLjwyDKp4JVxIfwp3v] Delivery Terminated

          Consumer: logs > logs-consumer
   Stream Sequence: 277535989
        Deliveries: 0

[16:00:00] [GG9sNLjwyDKp4JVxIfwp4c] Delivery Terminated

          Consumer: logs > logs-consumer
   Stream Sequence: 277536551
        Deliveries: 0

...
[ More "Delivery Terminated" events ]
...

Should I be concerned about the above? Sounds like delivery was terminated and something did not get the message? Why would Delivery Terminated be recorded for 2 messages but not for the rest? As far as application logic is concerned all messages (including these 2) should have been processed exactly the same way. There are also no errors in application logs. But the advisory log suggests something distinctly different happened to these 2 messages (and other "Delivery Terminated" messages).

nats stream info logs

Information for Stream logs created 2022-07-13 20:07:45

             Subjects: logs.>
             Replicas: 3
              Storage: File

Options:

            Retention: Interest
     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: 1.0 GiB
          Maximum Age: 5d0h0m0s
 Maximum Message Size: unlimited
    Maximum Consumers: unlimited


Cluster Information:

                 Name: nats-cluster
               Leader: nats2
              Replica: nats3, current, seen 0.23s ago
              Replica: nats1, current, seen 0.23s ago

State:

             Messages: 0
                Bytes: 0 B
             FirstSeq: 281,225,307
              LastSeq: 281,225,306 @ 2023-03-13T16:46:13 UTC
     Active Consumers: 2

nats consumer info logs logs-consumer

Information for Consumer logs > logs-consumer created 2023-02-09T08:34:06Z

Configuration:

        Durable Name: logs-consumer
    Delivery Subject: logs-consumer.logs
      Deliver Policy: All
 Deliver Queue Group: logs-consumer
          Ack Policy: Explicit
            Ack Wait: 30s
       Replay Policy: Instant
     Max Ack Pending: 1,000
        Flow Control: false

Cluster Information:

                Name: nats-cluster
              Leader: nats1
             Replica: nats3, current, seen 0.45s ago
             Replica: nats2, current, seen 0.45s ago

State:

   Last Delivered Message: Consumer sequence: 281,139,766 Stream sequence: 281,225,537 Last delivery: 0.45s ago
     Acknowledgment floor: Consumer sequence: 281,139,766 Stream sequence: 281,225,537 Last Ack: 0.45s ago
         Outstanding Acks: 0 out of maximum 1,000
     Redelivered Messages: 0
     Unprocessed Messages: 0
          Active Interest: Active using Queue Group logs-consumer

Is there reason for concern?

Kaarel avatar Mar 13 '23 16:03 Kaarel

I did some spelunking in the code and it seems these are generated - among others - when a limit is evicting a message that is still being processed (we have an outstanding ack).

Fair enough to get a notice about that, but I think the server needs to start adding reasons to these so they can be distinguished as now that isnt useful. (This is also mentioned in the comments in the code).

ripienaar avatar Mar 13 '23 16:03 ripienaar