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.05k stars 1.42k forks source link

AckFloor is ahead of the NAK'ed message sequence id [v2.10.17] #5727

Open TheCheshireFox opened 4 months ago

TheCheshireFox commented 4 months ago

Observed behavior

So far, for unknown reasons, the stream and ack floor sequence goes further away than the message sequence. This leads to some messages not being delivered.

In the same time we have this lines in logs:

[3924] 2024/07/25 09:39:20.399780 [WRN] Internal subscription on "$JS.API.STREAM.PURGE.ResolvedStream" took too long: 2.8518496s [3924] 2024/07/25 09:39:20.399780 [WRN] Internal subscription on "$JS.API.STREAM.PURGE.ResolvedStream" took too long: 2.8518496s [3924] 2024/07/25 09:39:20.399780 [WRN] [fe80::1e08:e369:ec28:43ff%Ethernet]:62197 - cid:139 - Readloop processing time: 2.8518496s [3924] 2024/07/25 09:58:46.644653 [WRN] Internal subscription on "$JS.API.STREAM.PURGE.ResolvedStream" took too long: 2.7806246s [3924] 2024/07/25 09:58:46.645165 [WRN] Internal subscription on "$JS.API.STREAM.PURGE.ResolvedStream" took too long: 2.7811366s [3924] 2024/07/25 09:58:46.645165 [WRN] Internal subscription on "$JS.API.STREAM.PURGE.ResolvedStream" took too long: 2.7811366s [3924] 2024/07/25 09:58:46.645165 [WRN] [fe80::1e08:e369:ec28:43ff%Ethernet]:62197 - cid:139 - Readloop processing time: 2.7811366s [3924] 2024/07/25 11:48:44.800632 [WRN] Internal subscription on "$JS.API.STREAM.PURGE.SessionEventsStream" took too long: 19.7930954s [3924] 2024/07/25 11:48:44.800632 [WRN] Internal subscription on "$JS.API.STREAM.PURGE.SessionEventsStream" took too long: 19.7930954s [3924] 2024/07/25 11:48:44.800632 [WRN] Internal subscription on "$JS.API.STREAM.PURGE.SessionEventsStream" took too long: 19.7930954s [3924] 2024/07/25 11:48:44.800632 [WRN] [fe80::1e08:e369:ec28:43ff%Ethernet]:62255 - cid:142 - Readloop processing time: 19.7930954s [3924] 2024/07/25 12:06:30.730378 [WRN] Consumer '$G > ProcessingStream > ProcessorService_ProcessingStream_Consumer_b7995ccd001f4c7aa2a33473006cb572_High' error on write store state from purge: bad pending entry, sequence [410203] out of range [3924] 2024/07/25 12:06:55.687925 [WRN] Consumer '$G > ProcessingStream > ProcessorService_ProcessingStream_Consumer_b7995ccd001f4c7aa2a33473006cb572_High' error on write store state from purge: bad pending entry, sequence [410203] out of range [3924] 2024/07/25 12:07:18.684606 [WRN] Consumer '$G > ProcessingStream > ProcessorService_ProcessingStream_Consumer_b7995ccd001f4c7aa2a33473006cb572_High' error on write store state from purge: bad pending entry, sequence [410369] out of range [3924] 2024/07/25 12:08:58.826814 [WRN] Consumer '$G > ProcessingStream > ProcessorService_ProcessingStream_Consumer_b7995ccd001f4c7aa2a33473006cb572_High' error on write store state from purge: bad pending entry, sequence [410369] out of range [3924] 2024/07/25 12:09:22.349081 [WRN] Consumer '$G > ProcessingStream > ProcessorService_ProcessingStream_Consumer_b7995ccd001f4c7aa2a33473006cb572_High' error on write store state from purge: bad pending entry, sequence [410203] out of range [3924] 2024/07/25 12:09:41.269744 [WRN] Consumer '$G > ProcessingStream > ProcessorService_ProcessingStream_Consumer_b7995ccd001f4c7aa2a33473006cb572_High' error on write store state from purge: bad pending entry, sequence [410203] out of range [3924] 2024/07/25 12:09:55.141511 [WRN] Consumer '$G > ProcessingStream > ProcessorService_ProcessingStream_Consumer_b7995ccd001f4c7aa2a33473006cb572_High' error on write store state from purge: bad pending entry, sequence [410369] out of range [3924] 2024/07/25 12:09:55.173560 [WRN] Consumer '$G > ProcessingStream > ProcessorService_ProcessingStream_Consumer_b7995ccd001f4c7aa2a33473006cb572_High' error on write store state from purge: bad pending entry, sequence [410203] out of range [3924] 2024/07/25 12:09:55.191331 [WRN] Consumer '$G > ProcessingStream > ProcessorService_ProcessingStream_Consumer_b7995ccd001f4c7aa2a33473006cb572_High' error on write store state from purge: bad pending entry, sequence [410200] out of range [3924] 2024/07/25 12:09:55.208208 [WRN] Consumer '$G > ProcessingStream > ProcessorService_ProcessingStream_Consumer_b7995ccd001f4c7aa2a33473006cb572_High' error on write store state from purge: bad pending entry, sequence [410200] out of range [3924] 2024/07/25 12:09:59.205579 [WRN] Consumer '$G > ProcessingStream > ProcessorService_ProcessingStream_Consumer_b7995ccd001f4c7aa2a33473006cb572_High' error on write store state from purge: bad pending entry, sequence [410203] out of range [3924] 2024/07/25 12:09:59.219878 [WRN] Consumer '$G > ProcessingStream > ProcessorService_ProcessingStream_Consumer_b7995ccd001f4c7aa2a33473006cb572_High' error on write store state from purge: bad pending entry, sequence [410369] out of range [3924] 2024/07/25 12:09:59.234684 [WRN] Consumer '$G > ProcessingStream > ProcessorService_ProcessingStream_Consumer_b7995ccd001f4c7aa2a33473006cb572_High' error on write store state from purge: bad pending entry, sequence [410369] out of range [3924] 2024/07/25 12:09:59.245033 [WRN] Consumer '$G > ProcessingStream > ProcessorService_ProcessingStream_Consumer_b7995ccd001f4c7aa2a33473006cb572_High' error on write store state from purge: bad pending entry, sequence [410200] out of range [3924] 2024/07/25 12:09:59.257238 [WRN] Consumer '$G > ProcessingStream > ProcessorService_ProcessingStream_Consumer_b7995ccd001f4c7aa2a33473006cb572_High' error on write store state from purge: bad pending entry, sequence [410200] out of range [3924] 2024/07/25 12:09:59.269476 [WRN] Consumer '$G > ProcessingStream > ProcessorService_ProcessingStream_Consumer_b7995ccd001f4c7aa2a33473006cb572_High' error on write store state from purge: bad pending entry, sequence [410369] out of range [3924] 2024/07/25 12:09:59.280122 [WRN] Consumer '$G > ProcessingStream > ProcessorService_ProcessingStream_Consumer_b7995ccd001f4c7aa2a33473006cb572_High' error on write store state from purge: bad pending entry, sequence [410200] out of range [3924] 2024/07/25 12:09:59.288702 [WRN] Consumer '$G > ProcessingStream > ProcessorService_ProcessingStream_Consumer_b7995ccd001f4c7aa2a33473006cb572_High' error on write store state from purge: bad pending entry, sequence [410203] out of range [3924] 2024/07/25 12:09:59.298228 [WRN] Consumer '$G > ProcessingStream > ProcessorService_ProcessingStream_Consumer_b7995ccd001f4c7aa2a33473006cb572_High' error on write store state from purge: bad pending entry, sequence [410203] out of range [3924] 2024/07/25 12:09:59.311782 [WRN] Consumer '$G > ProcessingStream > ProcessorService_ProcessingStream_Consumer_b7995ccd001f4c7aa2a33473006cb572_High' error on write store state from purge: bad pending entry, sequence [410203] out of range [3924] 2024/07/25 12:09:59.341952 [WRN] Consumer '$G > ProcessingStream > ProcessorService_ProcessingStream_Consumer_b7995ccd001f4c7aa2a33473006cb572_High' error on write store state from purge: bad pending entry, sequence [410369] out of range [3924] 2024/07/25 12:09:59.366353 [WRN] Consumer '$G > ProcessingStream > ProcessorService_ProcessingStream_Consumer_b7995ccd001f4c7aa2a33473006cb572_High' error on write store state from purge: bad pending entry, sequence [410203] out of range [3924] 2024/07/25 12:09:59.389319 [WRN] Consumer '$G > ProcessingStream > ProcessorService_ProcessingStream_Consumer_b7995ccd001f4c7aa2a33473006cb572_High' error on write store state from purge: bad pending entry, sequence [410203] out of range [3924] 2024/07/25 12:09:59.429338 [WRN] Consumer '$G > ProcessingStream > ProcessorService_ProcessingStream_Consumer_b7995ccd001f4c7aa2a33473006cb572_High' error on write store state from purge: bad pending entry, sequence [410200] out of range [3924] 2024/07/25 12:09:59.447628 [WRN] Consumer '$G > ProcessingStream > ProcessorService_ProcessingStream_Consumer_b7995ccd001f4c7aa2a33473006cb572_High' error on write store state from purge: bad pending entry, sequence [410384] out of range [3924] 2024/07/25 12:09:59.476263 [WRN] Consumer '$G > ProcessingStream > ProcessorService_ProcessingStream_Consumer_b7995ccd001f4c7aa2a33473006cb572_High' error on write store state from purge: bad pending entry, sequence [410203] out of range [3924] 2024/07/25 12:09:59.602504 [WRN] Consumer '$G > ProcessingStream > ProcessorService_ProcessingStream_Consumer_b7995ccd001f4c7aa2a33473006cb572_High' error on write store state from purge: bad pending entry, sequence [410203] out of range [3924] 2024/07/25 12:09:59.620547 [WRN] Consumer '$G > ProcessingStream > ProcessorService_ProcessingStream_Consumer_b7995ccd001f4c7aa2a33473006cb572_High' error on write store state from purge: bad pending entry, sequence [410369] out of range [3924] 2024/07/25 12:09:59.634582 [WRN] Consumer '$G > ProcessingStream > ProcessorService_ProcessingStream_Consumer_b7995ccd001f4c7aa2a33473006cb572_High' error on write store state from purge: bad pending entry, sequence [410203] out of range [3924] 2024/07/25 12:09:59.644213 [WRN] Consumer '$G > ProcessingStream > ProcessorService_ProcessingStream_Consumer_b7995ccd001f4c7aa2a33473006cb572_High' error on write store state from purge: bad pending entry, sequence [410203] out of range [3924] 2024/07/25 12:09:59.658049 [WRN] Consumer '$G > ProcessingStream > ProcessorService_ProcessingStream_Consumer_b7995ccd001f4c7aa2a33473006cb572_High' error on write store state from purge: bad pending entry, sequence [410203] out of range [3924] 2024/07/25 12:09:59.667945 [WRN] Consumer '$G > ProcessingStream > ProcessorService_ProcessingStream_Consumer_b7995ccd001f4c7aa2a33473006cb572_High' error on write store state from purge: bad pending entry, sequence [410203] out of range [3924] 2024/07/25 12:09:59.678536 [WRN] Consumer '$G > ProcessingStream > ProcessorService_ProcessingStream_Consumer_b7995ccd001f4c7aa2a33473006cb572_High' error on write store state from purge: bad pending entry, sequence [410203] out of range [3924] 2024/07/25 12:09:59.696812 [WRN] Consumer '$G > ProcessingStream > ProcessorService_ProcessingStream_Consumer_b7995ccd001f4c7aa2a33473006cb572_High' error on write store state from purge: bad pending entry, sequence [410203] out of range [3924] 2024/07/25 12:09:59.709234 [WRN] Consumer '$G > ProcessingStream > ProcessorService_ProcessingStream_Consumer_b7995ccd001f4c7aa2a33473006cb572_High' error on write store state from purge: bad pending entry, sequence [410203] out of range [3924] 2024/07/25 12:09:59.728542 [WRN] Consumer '$G > ProcessingStream > ProcessorService_ProcessingStream_Consumer_b7995ccd001f4c7aa2a33473006cb572_High' error on write store state from purge: bad pending entry, sequence [410200] out of range [3924] 2024/07/25 12:09:59.739676 [WRN] Consumer '$G > ProcessingStream > ProcessorService_ProcessingStream_Consumer_b7995ccd001f4c7aa2a33473006cb572_High' error on write store state from purge: bad pending entry, sequence [410203] out of range [3924] 2024/07/25 12:09:59.752390 [WRN] Consumer '$G > ProcessingStream > ProcessorService_ProcessingStream_Consumer_b7995ccd001f4c7aa2a33473006cb572_High' error on write store state from purge: bad pending entry, sequence [410203] out of range [3924] 2024/07/25 12:09:59.766410 [WRN] Consumer '$G > ProcessingStream > ProcessorService_ProcessingStream_Consumer_b7995ccd001f4c7aa2a33473006cb572_High' error on write store state from purge: bad pending entry, sequence [410203] out of range [3924] 2024/07/25 12:09:59.791476 [WRN] Consumer '$G > ProcessingStream > ProcessorService_ProcessingStream_Consumer_b7995ccd001f4c7aa2a33473006cb572_High' error on write store state from purge: bad pending entry, sequence [410203] out of range [3924] 2024/07/25 12:09:59.804872 [WRN] Consumer '$G > ProcessingStream > ProcessorService_ProcessingStream_Consumer_b7995ccd001f4c7aa2a33473006cb572_High' error on write store state from purge: bad pending entry, sequence [410200] out of range [3924] 2024/07/25 12:09:59.820241 [WRN] Consumer '$G > ProcessingStream > ProcessorService_ProcessingStream_Consumer_b7995ccd001f4c7aa2a33473006cb572_High' error on write store state from purge: bad pending entry, sequence [410203] out of range [3924] 2024/07/25 12:09:59.834459 [WRN] Consumer '$G > ProcessingStream > ProcessorService_ProcessingStream_Consumer_b7995ccd001f4c7aa2a33473006cb572_High' error on write store state from purge: bad pending entry, sequence [410203] out of range [3924] 2024/07/25 12:09:59.851933 [WRN] Consumer '$G > ProcessingStream > ProcessorService_ProcessingStream_Consumer_b7995ccd001f4c7aa2a33473006cb572_High' error on write store state from purge: bad pending entry, sequence [410200] out of range [3924] 2024/07/25 12:09:59.901653 [WRN] Consumer '$G > ProcessingStream > ProcessorService_ProcessingStream_Consumer_b7995ccd001f4c7aa2a33473006cb572_High' error on write store state from purge: bad pending entry, sequence [410203] out of range [3924] 2024/07/25 12:10:02.197363 [WRN] Consumer '$G > ProcessingStream > ProcessorService_ProcessingStream_Consumer_b7995ccd001f4c7aa2a33473006cb572_High' error on write store state from purge: bad pending entry, sequence [410200] out of range [3924] 2024/07/25 12:10:29.738856 [WRN] Consumer '$G > ProcessingStream > ProcessorService_ProcessingStream_Consumer_b7995ccd001f4c7aa2a33473006cb572_High' error on write store state from purge: bad pending entry, sequence [410200] out of range [3924] 2024/07/25 12:10:30.277279 [WRN] Consumer '$G > ProcessingStream > ProcessorService_ProcessingStream_Consumer_b7995ccd001f4c7aa2a33473006cb572_High' error on write store state from purge: bad pending entry, sequence [410203] out of range [3924] 2024/07/25 12:10:30.926567 [WRN] Consumer '$G > ProcessingStream > ProcessorService_ProcessingStream_Consumer_b7995ccd001f4c7aa2a33473006cb572_High' error on write store state from purge: bad pending entry, sequence [410200] out of range [3924] 2024/07/25 12:10:32.068136 [WRN] Consumer '$G > ProcessingStream > ProcessorService_ProcessingStream_Consumer_b7995ccd001f4c7aa2a33473006cb572_High' error on write store state from purge: bad pending entry, sequence [410200] out of range [3924] 2024/07/25 12:10:33.121954 [WRN] Consumer '$G > ProcessingStream > ProcessorService_ProcessingStream_Consumer_b7995ccd001f4c7aa2a33473006cb572_High' error on write store state from purge: bad pending entry, sequence [410369] out of range [3924] 2024/07/25 12:10:33.147361 [WRN] Consumer '$G > ProcessingStream > ProcessorService_ProcessingStream_Consumer_b7995ccd001f4c7aa2a33473006cb572_High' error on write store state from purge: bad pending entry, sequence [410369] out of range [3924] 2024/07/25 12:10:33.166727 [WRN] Consumer '$G > ProcessingStream > ProcessorService_ProcessingStream_Consumer_b7995ccd001f4c7aa2a33473006cb572_High' error on write store state from purge: bad pending entry, sequence [410203] out of range [3924] 2024/07/25 12:10:37.984535 [WRN] Consumer '$G > ProcessingStream > ProcessorService_ProcessingStream_Consumer_b7995ccd001f4c7aa2a33473006cb572_High' error on write store state from purge: bad pending entry, sequence [410384] out of range [3924] 2024/07/25 12:10:38.006142 [WRN] Consumer '$G > ProcessingStream > ProcessorService_ProcessingStream_Consumer_b7995ccd001f4c7aa2a33473006cb572_High' error on write store state from purge: bad pending entry, sequence [410200] out of range [3924] 2024/07/25 12:10:38.046319 [WRN] Consumer '$G > ProcessingStream > ProcessorService_ProcessingStream_Consumer_b7995ccd001f4c7aa2a33473006cb572_High' error on write store state from purge: bad pending entry, sequence [410203] out of range [3924] 2024/07/25 12:10:38.440940 [WRN] Consumer '$G > ProcessingStream > ProcessorService_ProcessingStream_Consumer_b7995ccd001f4c7aa2a33473006cb572_High' error on write store state from purge: bad pending entry, sequence [410203] out of range [3924] 2024/07/25 12:10:38.570226 [WRN] Consumer '$G > ProcessingStream > ProcessorService_ProcessingStream_Consumer_b7995ccd001f4c7aa2a33473006cb572_High' error on write store state from purge: bad pending entry, sequence [410203] out of range [3924] 2024/07/25 12:10:38.599436 [WRN] Consumer '$G > ProcessingStream > ProcessorService_ProcessingStream_Consumer_b7995ccd001f4c7aa2a33473006cb572_High' error on write store state from purge: bad pending entry, sequence [410369] out of range [3924] 2024/07/25 12:43:14.688611 [WRN] Internal subscription on "$JS.API.STREAM.PURGE.SessionEventsStream" took too long: 12.385257s [3924] 2024/07/25 12:43:14.688611 [WRN] Internal subscription on "$JS.API.STREAM.PURGE.SessionEventsStream" took too long: 12.385257s [3924] 2024/07/25 12:43:14.688611 [WRN] Internal subscription on "$JS.API.STREAM.PURGE.SessionEventsStream" took too long: 12.385257s [3924] 2024/07/25 12:43:14.688611 [WRN] [fe80::1e08:e369:ec28:43ff%Ethernet]:62255 - cid:142 - Readloop processing time: 12.385257s

Expected behavior

All messages in a stream must be delivered.

Server and client version

nats-server: v2.10.17 dotnet nats-client: 1.0.4

Host environment

os: Windows Server 2019 Standard arch: x64 ram: 6 Gb

Steps to reproduce

I'm not sure what the steps to reproduce are, but we got such a problem for the message we NAK on the stream we actively purging.

wallyqs commented 4 months ago

@TheCheshireFox could you share an example of how you are purging the stream?

TheCheshireFox commented 4 months ago

Sure. We use this method:

public ulong PurgeStream(string streamName, string subject, CancellationToken cancellationToken)
{
    var optionsBuilder = new PurgeOptions.PurgeOptionsBuilder();
    optionsBuilder.WithSubject(subject);
    var response = JetStreamManagement.PurgeStream(streamName, optionsBuilder.Build()); // JetStreamManagement has a type IJetStreamManagement
    return response.Purged;
}
TheCheshireFox commented 3 months ago

@wallyqs, any news? Maybe I can provide more information?