@PulsarListener ackTimeoutMillis conflicting with redelivery policy

[Programmer-yyds]

@PulsarListener configured ackTimeoutMillis code to be re-delivered only twice after execution timeout, but my policy configured re-delivery for 10 times, and it was not delivered to the dead letter queue.

In the current code, the consumeString method is configured with timeout of 1000 and code dormancy of 30*1000. Under normal circumstances, timeout retry should be triggered, but it was only retried twice, while my policy was configured with 10 redeliveries, and it was not delivered to the dead letter queue topic-1-dlq-topic.

code segment：
`
@RestController
public class TaskAsyncController {
private static final DateTimeFormatter sdf = DateTimeFormatter.ofPattern("yyyyMMdd HH:mm:ss");
private static final Logger log = LoggerFactory.getLogger(TaskAsyncController.class);
static Pattern pattern = Pattern.compile("\.([a-zA-Z0-9]+)(?:\?|$)");
@resource
private PulsarTemplate strProducer;

@PostMapping(value = "/task/test")
public Result<String> test() {
    LocalDateTime now = LocalDateTime.now();
    String format = sdf.format(now);
    strProducer.send("topic-1", "date:" + format);
    return Result.success("");
}

@PulsarListener(topics = "topic-1", ackMode = AckMode.RECORD,
        subscriptionType = SubscriptionType.Shared, schemaType = SchemaType.STRING,
        ackTimeoutRedeliveryBackoff = "testAckTimeoutRedeliveryBackoff",
        negativeAckRedeliveryBackoff = "testAckTimeoutRedeliveryBackoff",
        deadLetterPolicy = "deadLetterPolicy", properties = {"ackTimeoutMillis=1000"})
public void consumeString(String message) throws InterruptedException {
    log.info("date:" + sdf.format(LocalDateTime.now()));
    log.info("enter_sleep");
    Thread.sleep(30 * 1000);
    log.info("awaken");
}

@PulsarListener(topics = "topic-1-dlq-topic", ackMode = AckMode.RECORD,
        subscriptionType = SubscriptionType.Shared, schemaType = SchemaType.STRING)
public void consumeStringD(String message) {
    log.info("dead_letter_received_message_in_the_column,date:" + sdf.format(LocalDateTime.now()));
}
@Bean("testAckTimeoutRedeliveryBackoff")
RedeliveryBackoff ackTimeoutRedeliveryBackoff() {
    return MultiplierRedeliveryBackoff.builder()
            .minDelayMs(1000)
            .maxDelayMs(2 * 1000)
            .multiplier(2)
            .build();
}
@Bean
DeadLetterPolicy deadLetterPolicy() {
    return DeadLetterPolicy.builder()
            .maxRedeliverCount(10)
            .deadLetterTopic("topic-1-dlq-topic")
            .build();
}

}
`

log:

[onobc]

Hi @Programmer-yyds ,
The team has been busy and has not got around to this issue yet. However, it is on our radar and we should get to it in the next 24-48hrs. Thanks for your patience.

• chris

[Programmer-yyds]

Hello, has this problem been fixed in version 1.2.2?

[onobc]

Hi @Programmer-yyds , unfortunately we have been busy and have not had a chance to get to this issue. That being said, the 1.2.3 release is tomorrow and I am have a few hours today to hopefully solve this in time for the release tomorrow. 🤞🏻

[onobc]

Hi @Programmer-yyds ,

The issue here is that once the listener awakes from its sleep it does in fact ack the message. This in turn takes the message out of the next redelivery as the message was in fact handled.

The reason that you are seeing only 1 message go through the listener method is because the default concurrency of the listener is 1 so any subsequent delivery will block until it awakes (and acks the message it slept/blocked with). If you instead set concurrency on the listener to 10 you will see the behavior you expect.

[Programmer-yyds]

According to your prompt, the set code is as follows (I set ackTimeoutMillis for 2 s, hibernation for 300 s, and concurrency for 10):
@PulsarListener(topics = "topic-1", ackMode = AckMode.RECORD,
subscriptionType = SubscriptionType.Shared, schemaType = SchemaType.STRING,
ackTimeoutRedeliveryBackoff = "testAckTimeoutRedeliveryBackoff",
negativeAckRedeliveryBackoff = "testAckTimeoutRedeliveryBackoff",
deadLetterPolicy = "deadLetterPolicy", properties = {"ackTimeoutMillis=2000"}, concurrency = "10")
public void consumeString(String message) throws InterruptedException {
log.info("date:" + sdf.format(LocalDateTime.now()));
log.info("enter_sleep");
Thread.sleep(300 * 1000);
log.info("awaken");
}

Problem: Check the log (the log is as follows). The message has been repeatedly consumed for 10 times, but the message has not been delivered to the dead letter queue after 10 times of consumption.

2025-02-18 09:51:41.839 [pulsar-client-io-1-3] INFO o.a.pulsar.client.impl.ProducerStatsRecorderImpl [,] - Starting Pulsar producer perf with config: {"topicName":"persistent://sample/ns1/topic-1","producerName":null,"sendTimeoutMs":30000,"blockIfQueueFull":false,"maxPendingMessages":0,"maxPendingMessagesAcrossPartitions":0,"messageRoutingMode":"RoundRobinPartition","hashingScheme":"JavaStringHash","cryptoFailureAction":"FAIL","batchingMaxPublishDelayMicros":1000,"batchingPartitionSwitchFrequencyByPublishDelay":10,"batchingMaxMessages":1000,"batchingMaxBytes":131072,"batchingEnabled":true,"chunkingEnabled":false,"chunkMaxMessageSize":-1,"encryptionKeys":[],"compressionType":"NONE","initialSequenceId":null,"autoUpdatePartitions":true,"autoUpdatePartitionsIntervalSeconds":60,"multiSchema":true,"accessMode":"Shared","lazyStartPartitionedProducers":false,"properties":{},"initialSubscriptionName":null,"nonPartitionedTopicExpected":false}
2025-02-18 09:51:41.839 [pulsar-client-io-1-3] INFO o.a.pulsar.client.impl.ProducerStatsRecorderImpl [,] - Pulsar client config: {"serviceUrl":"pulsar://10.8.15.75:6650","authPluginClassName":null,"authParams":null,"authParamMap":null,"operationTimeoutMs":30000,"lookupTimeoutMs":30000,"statsIntervalSeconds":60,"numIoThreads":12,"numListenerThreads":12,"connectionsPerBroker":1,"connectionMaxIdleSeconds":60,"useTcpNoDelay":true,"useTls":false,"tlsKeyFilePath":null,"tlsCertificateFilePath":null,"tlsTrustCertsFilePath":null,"tlsAllowInsecureConnection":false,"tlsHostnameVerificationEnable":false,"concurrentLookupRequest":5000,"maxLookupRequest":50000,"maxLookupRedirects":20,"maxNumberOfRejectedRequestPerConnection":50,"keepAliveIntervalSeconds":30,"connectionTimeoutMs":10000,"requestTimeoutMs":60000,"readTimeoutMs":60000,"autoCertRefreshSeconds":300,"initialBackoffIntervalNanos":100000000,"maxBackoffIntervalNanos":60000000000,"enableBusyWait":false,"listenerName":null,"useKeyStoreTls":false,"sslProvider":null,"tlsKeyStoreType":"JKS","tlsKeyStorePath":null,"tlsKeyStorePassword":null,"tlsTrustStoreType":"JKS","tlsTrustStorePath":null,"tlsTrustStorePassword":null,"tlsCiphers":[],"tlsProtocols":[],"memoryLimitBytes":67108864,"proxyServiceUrl":null,"proxyProtocol":null,"enableTransaction":false,"dnsLookupBindAddress":null,"dnsLookupBindPort":0,"dnsServerAddresses":[],"socks5ProxyAddress":null,"socks5ProxyUsername":null,"socks5ProxyPassword":null,"description":null,"openTelemetry":null}
2025-02-18 09:51:41.859 [pulsar-client-io-1-6] INFO org.apache.pulsar.client.impl.ProducerImpl [,] - [persistent://sample/ns1/topic-1] [null] Creating producer on cnx [id: 0xeddddaa5, L:/10.8.88.242:50064 - R:/10.8.15.75:6650]
2025-02-18 09:51:41.887 [pulsar-client-io-1-6] INFO org.apache.pulsar.client.impl.ProducerImpl [,] - [persistent://sample/ns1/topic-1] [standalone-0-91] Created producer on cnx [id: 0xeddddaa5, L:/10.8.88.242:50064 - R:/10.8.15.75:6650]
2025-02-18 09:51:41.983 [org.springframework.Pulsar.PulsarListenerEndpointContainer#0-0-C-3] INFO c.aspire.crcp.pdf.controller.TaskAsyncController1 [,] - date:20250218 09:51:41
2025-02-18 09:51:41.983 [org.springframework.Pulsar.PulsarListenerEndpointContainer#0-0-C-3] INFO c.aspire.crcp.pdf.controller.TaskAsyncController1 [,] - enter_sleep
2025-02-18 09:51:45.781 [pulsar-timer-40-1] INFO o.a.p.client.impl.UnAckedMessageRedeliveryTracker [,] - [ConsumerBase{subscription='office-to-pdf', consumerName='UMtCu', topic='persistent://sample/ns1/topic-1'}] 1 messages will be re-delivered
2025-02-18 09:51:45.829 [org.springframework.Pulsar.PulsarListenerEndpointContainer#0-0-C-4] INFO c.aspire.crcp.pdf.controller.TaskAsyncController1 [,] - date:20250218 09:51:45
2025-02-18 09:51:45.829 [org.springframework.Pulsar.PulsarListenerEndpointContainer#0-0-C-4] INFO c.aspire.crcp.pdf.controller.TaskAsyncController1 [,] - enter_sleep
2025-02-18 09:51:50.801 [pulsar-timer-40-1] INFO o.a.p.client.impl.UnAckedMessageRedeliveryTracker [,] - [ConsumerBase{subscription='office-to-pdf', consumerName='nPCk4', topic='persistent://sample/ns1/topic-1'}] 1 messages will be re-delivered
2025-02-18 09:51:50.891 [org.springframework.Pulsar.PulsarListenerEndpointContainer#0-0-C-5] INFO c.aspire.crcp.pdf.controller.TaskAsyncController1 [,] - date:20250218 09:51:50
2025-02-18 09:51:50.892 [org.springframework.Pulsar.PulsarListenerEndpointContainer#0-0-C-5] INFO c.aspire.crcp.pdf.controller.TaskAsyncController1 [,] - enter_sleep
2025-02-18 09:51:55.808 [pulsar-timer-40-1] INFO o.a.p.client.impl.UnAckedMessageRedeliveryTracker [,] - [ConsumerBase{subscription='office-to-pdf', consumerName='Vg0Q9', topic='persistent://sample/ns1/topic-1'}] 1 messages will be re-delivered
2025-02-18 09:51:55.852 [org.springframework.Pulsar.PulsarListenerEndpointContainer#0-0-C-6] INFO c.aspire.crcp.pdf.controller.TaskAsyncController1 [,] - date:20250218 09:51:55
2025-02-18 09:51:55.852 [org.springframework.Pulsar.PulsarListenerEndpointContainer#0-0-C-6] INFO c.aspire.crcp.pdf.controller.TaskAsyncController1 [,] - enter_sleep
2025-02-18 09:52:00.815 [pulsar-timer-40-1] INFO o.a.p.client.impl.UnAckedMessageRedeliveryTracker [,] - [ConsumerBase{subscription='office-to-pdf', consumerName='P6VDy', topic='persistent://sample/ns1/topic-1'}] 1 messages will be re-delivered
2025-02-18 09:52:00.919 [org.springframework.Pulsar.PulsarListenerEndpointContainer#0-0-C-7] INFO c.aspire.crcp.pdf.controller.TaskAsyncController1 [,] - date:20250218 09:52:00
2025-02-18 09:52:00.919 [org.springframework.Pulsar.PulsarListenerEndpointContainer#0-0-C-7] INFO c.aspire.crcp.pdf.controller.TaskAsyncController1 [,] - enter_sleep
2025-02-18 09:52:05.822 [pulsar-timer-40-1] INFO o.a.p.client.impl.UnAckedMessageRedeliveryTracker [,] - [ConsumerBase{subscription='office-to-pdf', consumerName='Eo3Xr', topic='persistent://sample/ns1/topic-1'}] 1 messages will be re-delivered
2025-02-18 09:52:05.883 [org.springframework.Pulsar.PulsarListenerEndpointContainer#0-0-C-8] INFO c.aspire.crcp.pdf.controller.TaskAsyncController1 [,] - date:20250218 09:52:05
2025-02-18 09:52:05.883 [org.springframework.Pulsar.PulsarListenerEndpointContainer#0-0-C-8] INFO c.aspire.crcp.pdf.controller.TaskAsyncController1 [,] - enter_sleep
2025-02-18 09:52:10.828 [pulsar-timer-40-1] INFO o.a.p.client.impl.UnAckedMessageRedeliveryTracker [,] - [ConsumerBase{subscription='office-to-pdf', consumerName='t8Xpv', topic='persistent://sample/ns1/topic-1'}] 1 messages will be re-delivered
2025-02-18 09:52:10.844 [org.springframework.Pulsar.PulsarListenerEndpointContainer#0-0-C-9] INFO c.aspire.crcp.pdf.controller.TaskAsyncController1 [,] - date:20250218 09:52:10
2025-02-18 09:52:10.844 [org.springframework.Pulsar.PulsarListenerEndpointContainer#0-0-C-9] INFO c.aspire.crcp.pdf.controller.TaskAsyncController1 [,] - enter_sleep
2025-02-18 09:52:15.835 [pulsar-timer-40-1] INFO o.a.p.client.impl.UnAckedMessageRedeliveryTracker [,] - [ConsumerBase{subscription='office-to-pdf', consumerName='ocUqo', topic='persistent://sample/ns1/topic-1'}] 1 messages will be re-delivered
2025-02-18 09:52:15.901 [org.springframework.Pulsar.PulsarListenerEndpointContainer#0-0-C-10] INFO c.aspire.crcp.pdf.controller.TaskAsyncController1 [,] - date:20250218 09:52:15
2025-02-18 09:52:15.901 [org.springframework.Pulsar.PulsarListenerEndpointContainer#0-0-C-10] INFO c.aspire.crcp.pdf.controller.TaskAsyncController1 [,] - enter_sleep
2025-02-18 09:52:20.841 [pulsar-timer-40-1] INFO o.a.p.client.impl.UnAckedMessageRedeliveryTracker [,] - [ConsumerBase{subscription='office-to-pdf', consumerName='ukrPz', topic='persistent://sample/ns1/topic-1'}] 1 messages will be re-delivered
2025-02-18 09:52:20.867 [org.springframework.Pulsar.PulsarListenerEndpointContainer#0-0-C-1] INFO c.aspire.crcp.pdf.controller.TaskAsyncController1 [,] - date:20250218 09:52:20
2025-02-18 09:52:20.867 [org.springframework.Pulsar.PulsarListenerEndpointContainer#0-0-C-1] INFO c.aspire.crcp.pdf.controller.TaskAsyncController1 [,] - enter_sleep
2025-02-18 09:52:25.849 [pulsar-timer-40-1] INFO o.a.p.client.impl.UnAckedMessageRedeliveryTracker [,] - [ConsumerBase{subscription='office-to-pdf', consumerName='BoE62', topic='persistent://sample/ns1/topic-1'}] 1 messages will be re-delivered
2025-02-18 09:52:25.935 [org.springframework.Pulsar.PulsarListenerEndpointContainer#0-0-C-2] INFO c.aspire.crcp.pdf.controller.TaskAsyncController1 [,] - date:20250218 09:52:25
2025-02-18 09:52:25.935 [org.springframework.Pulsar.PulsarListenerEndpointContainer#0-0-C-2] INFO c.aspire.crcp.pdf.controller.TaskAsyncController1 [,] - enter_sleep
2025-02-18 09:52:28.843 [pulsar-timer-40-1] INFO o.a.pulsar.client.impl.ConsumerStatsRecorderImpl [,] - [persistent://sample/ns1/topic-1] [office-to-pdf] [BoE62] Prefetched messages: 0 --- Consume throughput received: 0.02 msgs/s --- 0.00 Mbit/s --- Ack sent rate: 0.00 ack/s --- Failed messages: 0 --- batch messages: 0 ---Failed acks: 0
2025-02-18 09:52:28.878 [pulsar-timer-40-1] INFO o.a.pulsar.client.impl.ConsumerStatsRecorderImpl [,] - [persistent://sample/ns1/topic-1] [office-to-pdf] [TWtpo] Prefetched messages: 0 --- Consume throughput received: 0.02 msgs/s --- 0.00 Mbit/s --- Ack sent rate: 0.00 ack/s --- Failed messages: 0 --- batch messages: 0 ---Failed acks: 0
2025-02-18 09:52:28.959 [pulsar-timer-40-1] INFO o.a.pulsar.client.impl.ConsumerStatsRecorderImpl [,] - [persistent://sample/ns1/topic-1] [office-to-pdf] [UMtCu] Prefetched messages: 0 --- Consume throughput received: 0.02 msgs/s --- 0.00 Mbit/s --- Ack sent rate: 0.00 ack/s --- Failed messages: 0 --- batch messages: 0 ---Failed acks: 0
2025-02-18 09:52:29.004 [pulsar-timer-40-1] INFO o.a.pulsar.client.impl.ConsumerStatsRecorderImpl [,] - [persistent://sample/ns1/topic-1] [office-to-pdf] [nPCk4] Prefetched messages: 0 --- Consume throughput received: 0.02 msgs/s --- 0.00 Mbit/s --- Ack sent rate: 0.00 ack/s --- Failed messages: 0 --- batch messages: 0 ---Failed acks: 0
2025-02-18 09:52:29.060 [pulsar-timer-40-1] INFO o.a.pulsar.client.impl.ConsumerStatsRecorderImpl [,] - [persistent://sample/ns1/topic-1] [office-to-pdf] [Vg0Q9] Prefetched messages: 0 --- Consume throughput received: 0.02 msgs/s --- 0.00 Mbit/s --- Ack sent rate: 0.00 ack/s --- Failed messages: 0 --- batch messages: 0 ---Failed acks: 0
2025-02-18 09:52:29.091 [pulsar-timer-40-1] INFO o.a.pulsar.client.impl.ConsumerStatsRecorderImpl [,] - [persistent://sample/ns1/topic-1] [office-to-pdf] [P6VDy] Prefetched messages: 0 --- Consume throughput received: 0.02 msgs/s --- 0.00 Mbit/s --- Ack sent rate: 0.00 ack/s --- Failed messages: 0 --- batch messages: 0 ---Failed acks: 0
2025-02-18 09:52:29.147 [pulsar-timer-40-1] INFO o.a.pulsar.client.impl.ConsumerStatsRecorderImpl [,] - [persistent://sample/ns1/topic-1] [office-to-pdf] [Eo3Xr] Prefetched messages: 0 --- Consume throughput received: 0.02 msgs/s --- 0.00 Mbit/s --- Ack sent rate: 0.00 ack/s --- Failed messages: 0 --- batch messages: 0 ---Failed acks: 0
2025-02-18 09:52:29.173 [pulsar-timer-40-1] INFO o.a.pulsar.client.impl.ConsumerStatsRecorderImpl [,] - [persistent://sample/ns1/topic-1] [office-to-pdf] [t8Xpv] Prefetched messages: 0 --- Consume throughput received: 0.02 msgs/s --- 0.00 Mbit/s --- Ack sent rate: 0.00 ack/s --- Failed messages: 0 --- batch messages: 0 ---Failed acks: 0
2025-02-18 09:52:29.199 [pulsar-timer-40-1] INFO o.a.pulsar.client.impl.ConsumerStatsRecorderImpl [,] - [persistent://sample/ns1/topic-1] [office-to-pdf] [ocUqo] Prefetched messages: 0 --- Consume throughput received: 0.02 msgs/s --- 0.00 Mbit/s --- Ack sent rate: 0.00 ack/s --- Failed messages: 0 --- batch messages: 0 ---Failed acks: 0
2025-02-18 09:52:29.226 [pulsar-timer-40-1] INFO o.a.pulsar.client.impl.ConsumerStatsRecorderImpl [,] - [persistent://sample/ns1/topic-1] [office-to-pdf] [ukrPz] Prefetched messages: 0 --- Consume throughput received: 0.02 msgs/s --- 0.00 Mbit/s --- Ack sent rate: 0.00 ack/s --- Failed messages: 0 --- batch messages: 0 ---Failed acks: 0
2025-02-18 09:52:30.855 [pulsar-timer-40-1] INFO o.a.p.client.impl.UnAckedMessageRedeliveryTracker [,] - [ConsumerBase{subscription='office-to-pdf', consumerName='TWtpo', topic='persistent://sample/ns1/topic-1'}] 1 messages will be re-delivered
2025-02-18 09:52:41.843 [pulsar-timer-40-1] INFO o.a.pulsar.client.impl.ProducerStatsRecorderImpl [,] - [persistent://sample/ns1/topic-1] [standalone-0-91] --- Publish throughput: 0.02 msg/s --- 0.00 Mbit/s --- Latency: med: 51.000 ms - 95pct: 51.000 ms - 99pct: 51.000 ms - 99.9pct: 51.000 ms - max: 51.000 ms --- BatchSize: med: 1.000 - 95pct: 1.000 - 99pct: 1.000 - 99.9pct: 1.000 - max: 1.000 --- MsgSize: med: 22.000 bytes - 95pct: 22.000 bytes - 99pct: 22.000 bytes - 99.9pct: 22.000 bytes - max: 22.000 bytes --- Ack received rate: 0.02 ack/s --- Failed messages: 0 --- Pending messages: 0
2025-02-18 09:52:41.908 [pulsar-client-io-1-6] INFO org.apache.pulsar.client.impl.ProducerImpl [,] - [persistent://sample/ns1/topic-1] [standalone-0-91] Closed Producer
2025-02-18 09:53:26.955 [pulsar-client-io-1-3] INFO org.apache.pulsar.client.impl.ClientCnx [,] - [id: 0xfea20e9a, L:/10.8.88.242:50063 ! R:/10.8.15.75:6650] Disconnected
2025-02-18 09:56:41.991 [org.springframework.Pulsar.PulsarListenerEndpointContainer#0-0-C-3] INFO c.aspire.crcp.pdf.controller.TaskAsyncController1 [,] - awaken
2025-02-18 09:56:42.096 [org.springframework.Pulsar.PulsarListenerEndpointContainer#0-0-C-3] INFO c.aspire.crcp.pdf.controller.TaskAsyncController1 [,] - date:20250218 09:56:42
2025-02-18 09:56:42.096 [org.springframework.Pulsar.PulsarListenerEndpointContainer#0-0-C-3] INFO c.aspire.crcp.pdf.controller.TaskAsyncController1 [,] - enter_sleep
2025-02-18 09:56:45.833 [org.springframework.Pulsar.PulsarListenerEndpointContainer#0-0-C-4] INFO c.aspire.crcp.pdf.controller.TaskAsyncController1 [,] - awaken
2025-02-18 09:56:46.162 [pulsar-timer-40-1] INFO o.a.p.client.impl.UnAckedMessageRedeliveryTracker [,] - [ConsumerBase{subscription='office-to-pdf', consumerName='UMtCu', topic='persistent://sample/ns1/topic-1'}] 1 messages will be re-delivered
2025-02-18 09:56:50.898 [org.springframework.Pulsar.PulsarListenerEndpointContainer#0-0-C-5] INFO c.aspire.crcp.pdf.controller.TaskAsyncController1 [,] - awaken
2025-02-18 09:56:55.859 [org.springframework.Pulsar.PulsarListenerEndpointContainer#0-0-C-6] INFO c.aspire.crcp.pdf.controller.TaskAsyncController1 [,] - awaken
2025-02-18 09:57:00.927 [org.springframework.Pulsar.PulsarListenerEndpointContainer#0-0-C-7] INFO c.aspire.crcp.pdf.controller.TaskAsyncController1 [,] - awaken
2025-02-18 09:57:05.886 [org.springframework.Pulsar.PulsarListenerEndpointContainer#0-0-C-8] INFO c.aspire.crcp.pdf.controller.TaskAsyncController1 [,] - awaken
2025-02-18 09:57:10.849 [org.springframework.Pulsar.PulsarListenerEndpointContainer#0-0-C-9] INFO c.aspire.crcp.pdf.controller.TaskAsyncController1 [,] - awaken
2025-02-18 09:57:15.909 [org.springframework.Pulsar.PulsarListenerEndpointContainer#0-0-C-10] INFO c.aspire.crcp.pdf.controller.TaskAsyncController1 [,] - awaken
2025-02-18 09:57:20.875 [org.springframework.Pulsar.PulsarListenerEndpointContainer#0-0-C-1] INFO c.aspire.crcp.pdf.controller.TaskAsyncController1 [,] - awaken
2025-02-18 09:57:25.944 [org.springframework.Pulsar.PulsarListenerEndpointContainer#0-0-C-2] INFO c.aspire.crcp.pdf.controller.TaskAsyncController1 [,] - awaken
2025-02-18 09:57:28.852 [pulsar-timer-40-1] INFO o.a.pulsar.client.impl.ConsumerStatsRecorderImpl [,] - [persistent://sample/ns1/topic-1] [office-to-pdf] [BoE62] Prefetched messages: 0 --- Consume throughput received: 0.00 msgs/s --- 0.00 Mbit/s --- Ack sent rate: 0.02 ack/s --- Failed messages: 0 --- batch messages: 0 ---Failed acks: 0
2025-02-18 09:57:28.887 [pulsar-timer-40-1] INFO o.a.pulsar.client.impl.ConsumerStatsRecorderImpl [,] - [persistent://sample/ns1/topic-1] [office-to-pdf] [TWtpo] Prefetched messages: 0 --- Consume throughput received: 0.00 msgs/s --- 0.00 Mbit/s --- Ack sent rate: 0.02 ack/s --- Failed messages: 0 --- batch messages: 0 ---Failed acks: 0
2025-02-18 09:57:28.969 [pulsar-timer-40-1] INFO o.a.pulsar.client.impl.ConsumerStatsRecorderImpl [,] - [persistent://sample/ns1/topic-1] [office-to-pdf] [UMtCu] Prefetched messages: 0 --- Consume throughput received: 0.02 msgs/s --- 0.00 Mbit/s --- Ack sent rate: 0.02 ack/s --- Failed messages: 0 --- batch messages: 0 ---Failed acks: 0
2025-02-18 09:57:29.012 [pulsar-timer-40-1] INFO o.a.pulsar.client.impl.ConsumerStatsRecorderImpl [,] - [persistent://sample/ns1/topic-1] [office-to-pdf] [nPCk4] Prefetched messages: 0 --- Consume throughput received: 0.00 msgs/s --- 0.00 Mbit/s --- Ack sent rate: 0.02 ack/s --- Failed messages: 0 --- batch messages: 0 ---Failed acks: 0
2025-02-18 09:57:29.070 [pulsar-timer-40-1] INFO o.a.pulsar.client.impl.ConsumerStatsRecorderImpl [,] - [persistent://sample/ns1/topic-1] [office-to-pdf] [Vg0Q9] Prefetched messages: 0 --- Consume throughput received: 0.00 msgs/s --- 0.00 Mbit/s --- Ack sent rate: 0.02 ack/s --- Failed messages: 0 --- batch messages: 0 ---Failed acks: 0
2025-02-18 09:57:29.101 [pulsar-timer-40-1] INFO o.a.pulsar.client.impl.ConsumerStatsRecorderImpl [,] - [persistent://sample/ns1/topic-1] [office-to-pdf] [P6VDy] Prefetched messages: 0 --- Consume throughput received: 0.00 msgs/s --- 0.00 Mbit/s --- Ack sent rate: 0.02 ack/s --- Failed messages: 0 --- batch messages: 0 ---Failed acks: 0
2025-02-18 09:57:29.156 [pulsar-timer-40-1] INFO o.a.pulsar.client.impl.ConsumerStatsRecorderImpl [,] - [persistent://sample/ns1/topic-1] [office-to-pdf] [Eo3Xr] Prefetched messages: 0 --- Consume throughput received: 0.00 msgs/s --- 0.00 Mbit/s --- Ack sent rate: 0.02 ack/s --- Failed messages: 0 --- batch messages: 0 ---Failed acks: 0
2025-02-18 09:57:29.182 [pulsar-timer-40-1] INFO o.a.pulsar.client.impl.ConsumerStatsRecorderImpl [,] - [persistent://sample/ns1/topic-1] [office-to-pdf] [t8Xpv] Prefetched messages: 0 --- Consume throughput received: 0.00 msgs/s --- 0.00 Mbit/s --- Ack sent rate: 0.02 ack/s --- Failed messages: 0 --- batch messages: 0 ---Failed acks: 0
2025-02-18 09:57:29.209 [pulsar-timer-40-1] INFO o.a.pulsar.client.impl.ConsumerStatsRecorderImpl [,] - [persistent://sample/ns1/topic-1] [office-to-pdf] [ocUqo] Prefetched messages: 0 --- Consume throughput received: 0.00 msgs/s --- 0.00 Mbit/s --- Ack sent rate: 0.02 ack/s --- Failed messages: 0 --- batch messages: 0 ---Failed acks: 0
2025-02-18 09:57:29.235 [pulsar-timer-40-1] INFO o.a.pulsar.client.impl.ConsumerStatsRecorderImpl [,] - [persistent://sample/ns1/topic-1] [office-to-pdf] [ukrPz] Prefetched messages: 0 --- Consume throughput received: 0.00 msgs/s --- 0.00 Mbit/s --- Ack sent rate: 0.02 ack/s --- Failed messages: 0 --- batch messages: 0 ---Failed acks: 0

[onobc]

In the case of a long running listener, there has to be enough concurrency in order to process the max amount of redeliveries, otherwise, the broker does not think anyone has processed the last retried message.

Let's step through your example.

concurrency = 10
max-retries = 10

t0  send msg1 listener1 gets and blocks for 5min...
t1  resend msg1 listener2 gets and blocks for 5min...
t2  resend msg1 listener3 gets and blocks for 5min...
t3  resend msg1 listener4 gets and blocks for 5min...
t4  resend msg1 listener5 gets and blocks for 5min...
t5  resend msg1 listener6 gets and blocks for 5min...
t6  resend msg1 listener7 gets and blocks for 5min...
t7  resend msg1 listener8 gets and blocks for 5min...
t8  resend msg1 listener9 gets and blocks for 5min...
t9  resend msg1 listener10 gets and blocks for 5min...

// At this point there are 9 retries - need 1 more but
// we have no more listeners - msg just sitting on topic.
// 
// After the 5min block though it will ack it before it
// gets the retried from the topic.
//
// Will never get to the redeliver below.

t10 resend msg1 listener11 gets and blocks for 5min...
AckTimeoutTracker sees it has been >= 10 retries and sends to DLT

Now if we bump the concurrency to 11 it will look as follows:

concurrency = 11
max-retries = 10

t0  send msg1 listener1 gets and blocks for 5min...
t1  resend msg1 listener2 gets and blocks for 5min...
t2  resend msg1 listener3 gets and blocks for 5min...
t3  resend msg1 listener4 gets and blocks for 5min...
t4  resend msg1 listener5 gets and blocks for 5min...
t5  resend msg1 listener6 gets and blocks for 5min...
t6  resend msg1 listener7 gets and blocks for 5min...
t7  resend msg1 listener8 gets and blocks for 5min...
t8  resend msg1 listener9 gets and blocks for 5min...
t9  resend msg1 listener10 gets and blocks for 5min...
t10 resend msg1 listener11 gets and blocks for 5min...
AckTimeoutTracker sees it has been >= 10 retries and sends to DLT