poulhenriksen opened a new issue #6451: Doing negative ack after ack timeout breaks redelivery in strange ways URL: https://github.com/apache/pulsar/issues/6451 **Describe the bug** When consuming a message, and the processing takes longer than `ackTimeout` and the result of the processing is to send a `negativeAcknowledge`, it somehow breaks redelivery. **To Reproduce** Steps to reproduce the behavior: 1. Set a fairly low `ackTimeout`, say 1001ms. 2. Set DLQ `maxRedeliverCount` to 10. 3. Take longer than `ackTimeout` to process the message (1200ms), and when done processing, do a `negativeAcknowledge`. 4. Then the consumer seems to only get the first 2-3 delivery retries 5. When killing the consumer, and starting the same again consumer again, it will start receiving the message again with `redeliveryCount` initially set 0, but the `redeliveryCount` will after that skip some counts, and also never reach maxRedeliverCount. For example: ```[20-Mar-02 08:40:13:248] [INFO] [PulsarRedeliverBug:83] - time: 0 msg: 2020-03-02T07:39:51.004681Z, receivedCount: 1, redeliverCount: 0 [20-Mar-02 08:40:14:321] [WARN] [UnAckedMessageTracker:132] - [ConsumerBase{subscription='failing-subscription', consumerName='failing-consumer', topic='persistent://public/default/redeliver-topic'}] 1 messages have timed-out [20-Mar-02 08:40:14:454] [INFO] [PulsarRedeliverBug:83] - time: 1205 msg: 2020-03-02T07:40:13.235867Z, receivedCount: 2, redeliverCount: 0 [20-Mar-02 08:40:15:549] [WARN] [UnAckedMessageTracker:132] - [ConsumerBase{subscription='failing-subscription', consumerName='failing-consumer', topic='persistent://public/default/redeliver-topic'}] 1 messages have timed-out [20-Mar-02 08:40:15:658] [INFO] [PulsarRedeliverBug:83] - time: 2410 msg: 2020-03-02T07:39:51.004681Z, receivedCount: 3, redeliverCount: 1 [20-Mar-02 08:40:16:775] [WARN] [UnAckedMessageTracker:132] - [ConsumerBase{subscription='failing-subscription', consumerName='failing-consumer', topic='persistent://public/default/redeliver-topic'}] 1 messages have timed-out [20-Mar-02 08:40:16:863] [INFO] [PulsarRedeliverBug:83] - time: 3615 msg: 2020-03-02T07:39:51.004681Z, receivedCount: 4, redeliverCount: 2 [20-Mar-02 08:40:17:902] [WARN] [UnAckedMessageTracker:132] - [ConsumerBase{subscription='failing-subscription', consumerName='failing-consumer', topic='persistent://public/default/redeliver-topic'}] 1 messages have timed-out [20-Mar-02 08:40:18:064] [INFO] [PulsarRedeliverBug:83] - time: 4815 msg: 2020-03-02T07:40:13.235867Z, receivedCount: 5, redeliverCount: 2 [20-Mar-02 08:40:19:128] [WARN] [UnAckedMessageTracker:132] - [ConsumerBase{subscription='failing-subscription', consumerName='failing-consumer', topic='persistent://public/default/redeliver-topic'}] 1 messages have timed-out [20-Mar-02 08:40:19:269] [INFO] [PulsarRedeliverBug:83] - time: 6021 msg: 2020-03-02T07:39:51.004681Z, receivedCount: 6, redeliverCount: 3 [20-Mar-02 08:40:20:352] [WARN] [UnAckedMessageTracker:132] - [ConsumerBase{subscription='failing-subscription', consumerName='failing-consumer', topic='persistent://public/default/redeliver-topic'}] 1 messages have timed-out [20-Mar-02 08:40:20:474] [INFO] [PulsarRedeliverBug:83] - time: 7226 msg: 2020-03-02T07:39:51.004681Z, receivedCount: 7, redeliverCount: 4 [20-Mar-02 08:40:21:578] [WARN] [UnAckedMessageTracker:132] - [ConsumerBase{subscription='failing-subscription', consumerName='failing-consumer', topic='persistent://public/default/redeliver-topic'}] 1 messages have timed-out [20-Mar-02 08:40:21:679] [INFO] [PulsarRedeliverBug:83] - time: 8431 msg: 2020-03-02T07:40:13.235867Z, receivedCount: 8, redeliverCount: 4 [20-Mar-02 08:40:22:704] [WARN] [UnAckedMessageTracker:132] - [ConsumerBase{subscription='failing-subscription', consumerName='failing-consumer', topic='persistent://public/default/redeliver-topic'}] 1 messages have timed-out [20-Mar-02 08:40:22:884] [INFO] [PulsarRedeliverBug:83] - time: 9636 msg: 2020-03-02T07:39:51.004681Z, receivedCount: 9, redeliverCount: 7 [20-Mar-02 08:40:23:931] [WARN] [UnAckedMessageTracker:132] - [ConsumerBase{subscription='failing-subscription', consumerName='failing-consumer', ``` **Expected behavior** Doing a `negativeAcknowledge` after having processed for more than `ackTimeout` should have no effect on the behaviour. The message should be redelivered until `maxRedeliverCount` is reached and then put in the DLQ. **Additional context** Tested locally against 2.5.0 standalone docker. Using partitioned topics. Test program to reproduce the issue: [pulsarbug.zip](https://github.com/apache/pulsar/files/4274114/pulsarbug.zip) Sample log output showing how it breaks: ``` [20-Mar-02 09:00:12:746] [INFO] [PulsarRedeliverBug:26] - *** FIRST RUN [20-Mar-02 09:00:12:750] [INFO] [PulsarRedeliverBug:40] - maxRedeliverCount: 10, negAckRedeliveryDelayMs: 300, ackTimeoutMs: 1001, consumerProcessingTimeMs: 1200 [20-Mar-02 09:00:13:643] [INFO] [ConnectionPool:156] - [[id: 0x2e956f78, L:/127.0.0.1:60947 - R:localhost/127.0.0.1:14002]] Connected to server [20-Mar-02 09:00:15:480] [INFO] [ProducerStatsRecorderImpl:101] - Starting Pulsar producer perf with config: { "topicName" : "persistent://public/default/redeliver-topic", "producerName" : null, "sendTimeoutMs" : 30000, "blockIfQueueFull" : false, "maxPendingMessages" : 1000, "maxPendingMessagesAcrossPartitions" : 50000, "messageRoutingMode" : "RoundRobinPartition", "hashingScheme" : "JavaStringHash", "cryptoFailureAction" : "FAIL", "batchingMaxPublishDelayMicros" : 1000, "batchingPartitionSwitchFrequencyByPublishDelay" : 10, "batchingMaxMessages" : 1000, "batchingMaxBytes" : 131072, "batchingEnabled" : true, "compressionType" : "NONE", "initialSequenceId" : null, "autoUpdatePartitions" : true, "multiSchema" : true, "properties" : { } } [20-Mar-02 09:00:15:485] [INFO] [ProducerStatsRecorderImpl:102] - Pulsar client config: { "serviceUrl" : "pulsar://localhost:14002", "authPluginClassName" : null, "authParams" : null, "operationTimeoutMs" : 30000, "statsIntervalSeconds" : 60, "numIoThreads" : 1, "numListenerThreads" : 1, "connectionsPerBroker" : 1, "useTcpNoDelay" : true, "useTls" : false, "tlsTrustCertsFilePath" : "", "tlsAllowInsecureConnection" : false, "tlsHostnameVerificationEnable" : false, "concurrentLookupRequest" : 5000, "maxLookupRequest" : 50000, "maxNumberOfRejectedRequestPerConnection" : 50, "keepAliveIntervalSeconds" : 30, "connectionTimeoutMs" : 10000, "requestTimeoutMs" : 60000, "initialBackoffIntervalNanos" : 100000000, "maxBackoffIntervalNanos" : 60000000000 } [20-Mar-02 09:00:15:504] [INFO] [ConnectionPool:156] - [[id: 0xa750bd44, L:/127.0.0.1:60948 - R:localhost/127.0.0.1:14002]] Connected to server [20-Mar-02 09:00:15:504] [INFO] [ClientCnx:195] - [id: 0xa750bd44, L:/127.0.0.1:60948 - R:localhost/127.0.0.1:14002] Connected through proxy to target broker at localhost:6650 [20-Mar-02 09:00:15:511] [INFO] [ProducerImpl:1059] - [persistent://public/default/redeliver-topic-partition-0] [null] Creating producer on cnx [id: 0xa750bd44, L:/127.0.0.1:60948 - R:localhost/127.0.0.1:14002] [20-Mar-02 09:00:15:535] [INFO] [ProducerImpl:1109] - [persistent://public/default/redeliver-topic-partition-0] [standalone-9-106] Created producer on cnx [id: 0xa750bd44, L:/127.0.0.1:60948 - R:localhost/127.0.0.1:14002] [20-Mar-02 09:00:15:558] [INFO] [PartitionedProducerImpl:145] - [persistent://public/default/redeliver-topic] Created partitioned producer [20-Mar-02 09:00:15:634] [INFO] [ConsumerStatsRecorderImpl:108] - Starting Pulsar consumer status recorder with config: { "topicNames" : [ ], "topicsPattern" : null, "subscriptionName" : "failing-subscription", "subscriptionType" : "Shared", "receiverQueueSize" : 1000, "acknowledgementsGroupTimeMicros" : 100000, "negativeAckRedeliveryDelayMicros" : 300000, "maxTotalReceiverQueueSizeAcrossPartitions" : 50000, "consumerName" : "failing-consumer", "ackTimeoutMillis" : 1001, "tickDurationMillis" : 101, "priorityLevel" : 0, "cryptoFailureAction" : "FAIL", "properties" : { }, "readCompacted" : false, "subscriptionInitialPosition" : "Latest", "patternAutoDiscoveryPeriod" : 1, "regexSubscriptionMode" : "PersistentOnly", "deadLetterPolicy" : { "maxRedeliverCount" : 10, "deadLetterTopic" : null }, "autoUpdatePartitions" : true, "replicateSubscriptionState" : false, "resetIncludeHead" : false, "keySharedPolicy" : null } [20-Mar-02 09:00:15:638] [INFO] [ConsumerStatsRecorderImpl:109] - Pulsar client config: { "serviceUrl" : "pulsar://localhost:14002", "authPluginClassName" : null, "authParams" : null, "operationTimeoutMs" : 30000, "statsIntervalSeconds" : 60, "numIoThreads" : 1, "numListenerThreads" : 1, "connectionsPerBroker" : 1, "useTcpNoDelay" : true, "useTls" : false, "tlsTrustCertsFilePath" : "", "tlsAllowInsecureConnection" : false, "tlsHostnameVerificationEnable" : false, "concurrentLookupRequest" : 5000, "maxLookupRequest" : 50000, "maxNumberOfRejectedRequestPerConnection" : 50, "keepAliveIntervalSeconds" : 30, "connectionTimeoutMs" : 10000, "requestTimeoutMs" : 60000, "initialBackoffIntervalNanos" : 100000000, "maxBackoffIntervalNanos" : 60000000000 } [20-Mar-02 09:00:15:647] [INFO] [ConsumerImpl:544] - [persistent://public/default/redeliver-topic-partition-0][failing-subscription] Subscribing to topic on cnx [id: 0xa750bd44, L:/127.0.0.1:60948 - R:localhost/127.0.0.1:14002] [20-Mar-02 09:00:15:671] [INFO] [ConsumerImpl:656] - [persistent://public/default/redeliver-topic-partition-0][failing-subscription] Subscribed to topic on localhost/127.0.0.1:14002 -- consumer: 0 [20-Mar-02 09:00:15:677] [INFO] [MultiTopicsConsumerImpl:883] - [persistent://public/default/redeliver-topic] [failing-subscription] Success subscribe new topic persistent://public/default/redeliver-topic in topics consumer, partitions: 1, allTopicPartitionsNumber: 1 [20-Mar-02 09:00:15:699] [WARN] [Crc32cIntChecksum:44] - Failed to load Circe JNI library. Falling back to Java based CRC32c provider [20-Mar-02 09:00:15:734] [INFO] [PulsarRedeliverBug:83] - time: 0 msg: 2020-03-02T08:00:15.679538Z, receivedCount: 1, redeliverCount: 0 [20-Mar-02 09:00:16:833] [WARN] [UnAckedMessageTracker:132] - [ConsumerBase{subscription='failing-subscription', consumerName='failing-consumer', topic='persistent://public/default/redeliver-topic'}] 1 messages have timed-out [20-Mar-02 09:00:16:940] [INFO] [PulsarRedeliverBug:83] - time: 1207 msg: 2020-03-02T08:00:15.679538Z, receivedCount: 2, redeliverCount: 1 [20-Mar-02 09:00:17:995] [WARN] [UnAckedMessageTracker:132] - [ConsumerBase{subscription='failing-subscription', consumerName='failing-consumer', topic='persistent://public/default/redeliver-topic'}] 1 messages have timed-out [20-Mar-02 09:00:18:145] [INFO] [PulsarRedeliverBug:83] - time: 2412 msg: 2020-03-02T08:00:15.679538Z, receivedCount: 3, redeliverCount: 2 [20-Mar-02 09:00:19:220] [WARN] [UnAckedMessageTracker:132] - [ConsumerBase{subscription='failing-subscription', consumerName='failing-consumer', topic='persistent://public/default/redeliver-topic'}] 1 messages have timed-out [20-Mar-02 09:00:35:803] [INFO] [ConsumerImpl:761] - [persistent://public/default/redeliver-topic-partition-0] [failing-subscription] Closed consumer [20-Mar-02 09:00:35:804] [INFO] [MultiTopicsConsumerImpl:538] - [persistent://public/default/redeliver-topic] [failing-subscription] Closed Topics Consumer [20-Mar-02 09:00:35:833] [INFO] [ProducerImpl:755] - [persistent://public/default/redeliver-topic-partition-0] [standalone-9-106] Closed Producer [20-Mar-02 09:00:35:834] [INFO] [PartitionedProducerImpl:229] - [persistent://public/default/redeliver-topic] Closed Partitioned Producer [20-Mar-02 09:00:35:836] [INFO] [PulsarClientImpl:538] - Client closing. URL: pulsar://localhost:14002 [20-Mar-02 09:00:35:853] [INFO] [ClientCnx:225] - [id: 0xa750bd44, L:/127.0.0.1:60948 ! R:localhost/127.0.0.1:14002] Disconnected [20-Mar-02 09:00:35:882] [INFO] [ClientCnx:225] - [id: 0x2e956f78, L:/127.0.0.1:60947 ! R:localhost/127.0.0.1:14002] Disconnected [20-Mar-02 09:00:35:895] [WARN] [MultiTopicsConsumerImpl:299] - [persistent://public/default/redeliver-topic] [failing-subscription] Failed to dequeue the message for listener org.apache.pulsar.client.api.PulsarClientException: java.lang.InterruptedException at org.apache.pulsar.client.api.PulsarClientException.unwrap(PulsarClientException.java:656) ~[pulsar-client-api-2.5.0.jar:2.5.0] at org.apache.pulsar.client.impl.MultiTopicsConsumerImpl.internalReceive(MultiTopicsConsumerImpl.java:354) ~[pulsar-client-2.5.0.jar:2.5.0] at org.apache.pulsar.client.impl.MultiTopicsConsumerImpl.lambda$messageReceived$9(MultiTopicsConsumerImpl.java:297) ~[pulsar-client-2.5.0.jar:2.5.0] at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) [?:?] at java.util.concurrent.FutureTask.run(FutureTask.java:264) [?:?] at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) [?:?] at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?] at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?] at org.apache.pulsar.shade.io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) [pulsar-client-2.5.0.jar:2.5.0] at java.lang.Thread.run(Thread.java:834) [?:?] Caused by: java.lang.InterruptedException at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.reportInterruptAfterWait(AbstractQueuedSynchronizer.java:2056) ~[?:?] at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2090) ~[?:?] at org.apache.pulsar.common.util.collections.GrowableArrayBlockingQueue.take(GrowableArrayBlockingQueue.java:176) ~[pulsar-client-2.5.0.jar:2.5.0] at org.apache.pulsar.client.impl.MultiTopicsConsumerImpl.internalReceive(MultiTopicsConsumerImpl.java:347) ~[pulsar-client-2.5.0.jar:2.5.0] ... 8 more [20-Mar-02 09:00:37:900] [INFO] [PulsarRedeliverBug:29] - *** SECOND RUN [20-Mar-02 09:00:37:900] [INFO] [PulsarRedeliverBug:40] - maxRedeliverCount: 10, negAckRedeliveryDelayMs: 300, ackTimeoutMs: 1001, consumerProcessingTimeMs: 1200 [20-Mar-02 09:00:37:905] [INFO] [ConnectionPool:156] - [[id: 0xb9c6f5ed, L:/127.0.0.1:60959 - R:localhost/127.0.0.1:14002]] Connected to server [20-Mar-02 09:00:37:925] [INFO] [ProducerStatsRecorderImpl:101] - Starting Pulsar producer perf with config: { "topicName" : "persistent://public/default/redeliver-topic", "producerName" : null, "sendTimeoutMs" : 30000, "blockIfQueueFull" : false, "maxPendingMessages" : 1000, "maxPendingMessagesAcrossPartitions" : 50000, "messageRoutingMode" : "RoundRobinPartition", "hashingScheme" : "JavaStringHash", "cryptoFailureAction" : "FAIL", "batchingMaxPublishDelayMicros" : 1000, "batchingPartitionSwitchFrequencyByPublishDelay" : 10, "batchingMaxMessages" : 1000, "batchingMaxBytes" : 131072, "batchingEnabled" : true, "compressionType" : "NONE", "initialSequenceId" : null, "autoUpdatePartitions" : true, "multiSchema" : true, "properties" : { } } [20-Mar-02 09:00:37:928] [INFO] [ProducerStatsRecorderImpl:102] - Pulsar client config: { "serviceUrl" : "pulsar://localhost:14002", "authPluginClassName" : null, "authParams" : null, "operationTimeoutMs" : 30000, "statsIntervalSeconds" : 60, "numIoThreads" : 1, "numListenerThreads" : 1, "connectionsPerBroker" : 1, "useTcpNoDelay" : true, "useTls" : false, "tlsTrustCertsFilePath" : "", "tlsAllowInsecureConnection" : false, "tlsHostnameVerificationEnable" : false, "concurrentLookupRequest" : 5000, "maxLookupRequest" : 50000, "maxNumberOfRejectedRequestPerConnection" : 50, "keepAliveIntervalSeconds" : 30, "connectionTimeoutMs" : 10000, "requestTimeoutMs" : 60000, "initialBackoffIntervalNanos" : 100000000, "maxBackoffIntervalNanos" : 60000000000 } [20-Mar-02 09:00:37:935] [INFO] [ConnectionPool:156] - [[id: 0x36418be6, L:/127.0.0.1:60960 - R:localhost/127.0.0.1:14002]] Connected to server [20-Mar-02 09:00:37:935] [INFO] [ClientCnx:195] - [id: 0x36418be6, L:/127.0.0.1:60960 - R:localhost/127.0.0.1:14002] Connected through proxy to target broker at localhost:6650 [20-Mar-02 09:00:37:943] [INFO] [ProducerImpl:1059] - [persistent://public/default/redeliver-topic-partition-0] [null] Creating producer on cnx [id: 0x36418be6, L:/127.0.0.1:60960 - R:localhost/127.0.0.1:14002] [20-Mar-02 09:00:37:952] [INFO] [ProducerImpl:1109] - [persistent://public/default/redeliver-topic-partition-0] [standalone-9-107] Created producer on cnx [id: 0x36418be6, L:/127.0.0.1:60960 - R:localhost/127.0.0.1:14002] [20-Mar-02 09:00:37:953] [INFO] [PartitionedProducerImpl:145] - [persistent://public/default/redeliver-topic] Created partitioned producer [20-Mar-02 09:00:37:980] [INFO] [ConsumerStatsRecorderImpl:108] - Starting Pulsar consumer status recorder with config: { "topicNames" : [ ], "topicsPattern" : null, "subscriptionName" : "failing-subscription", "subscriptionType" : "Shared", "receiverQueueSize" : 1000, "acknowledgementsGroupTimeMicros" : 100000, "negativeAckRedeliveryDelayMicros" : 300000, "maxTotalReceiverQueueSizeAcrossPartitions" : 50000, "consumerName" : "failing-consumer", "ackTimeoutMillis" : 1001, "tickDurationMillis" : 101, "priorityLevel" : 0, "cryptoFailureAction" : "FAIL", "properties" : { }, "readCompacted" : false, "subscriptionInitialPosition" : "Latest", "patternAutoDiscoveryPeriod" : 1, "regexSubscriptionMode" : "PersistentOnly", "deadLetterPolicy" : { "maxRedeliverCount" : 10, "deadLetterTopic" : null }, "autoUpdatePartitions" : true, "replicateSubscriptionState" : false, "resetIncludeHead" : false, "keySharedPolicy" : null } [20-Mar-02 09:00:37:984] [INFO] [ConsumerStatsRecorderImpl:109] - Pulsar client config: { "serviceUrl" : "pulsar://localhost:14002", "authPluginClassName" : null, "authParams" : null, "operationTimeoutMs" : 30000, "statsIntervalSeconds" : 60, "numIoThreads" : 1, "numListenerThreads" : 1, "connectionsPerBroker" : 1, "useTcpNoDelay" : true, "useTls" : false, "tlsTrustCertsFilePath" : "", "tlsAllowInsecureConnection" : false, "tlsHostnameVerificationEnable" : false, "concurrentLookupRequest" : 5000, "maxLookupRequest" : 50000, "maxNumberOfRejectedRequestPerConnection" : 50, "keepAliveIntervalSeconds" : 30, "connectionTimeoutMs" : 10000, "requestTimeoutMs" : 60000, "initialBackoffIntervalNanos" : 100000000, "maxBackoffIntervalNanos" : 60000000000 } [20-Mar-02 09:00:37:990] [INFO] [ConsumerImpl:544] - [persistent://public/default/redeliver-topic-partition-0][failing-subscription] Subscribing to topic on cnx [id: 0x36418be6, L:/127.0.0.1:60960 - R:localhost/127.0.0.1:14002] [20-Mar-02 09:00:38:033] [INFO] [ConsumerImpl:656] - [persistent://public/default/redeliver-topic-partition-0][failing-subscription] Subscribed to topic on localhost/127.0.0.1:14002 -- consumer: 0 [20-Mar-02 09:00:38:034] [INFO] [MultiTopicsConsumerImpl:883] - [persistent://public/default/redeliver-topic] [failing-subscription] Success subscribe new topic persistent://public/default/redeliver-topic in topics consumer, partitions: 1, allTopicPartitionsNumber: 1 [20-Mar-02 09:00:38:061] [INFO] [PulsarRedeliverBug:83] - time: 0 msg: 2020-03-02T08:00:15.679538Z, receivedCount: 1, redeliverCount: 0 [20-Mar-02 09:00:39:093] [WARN] [UnAckedMessageTracker:132] - [ConsumerBase{subscription='failing-subscription', consumerName='failing-consumer', topic='persistent://public/default/redeliver-topic'}] 1 messages have timed-out [20-Mar-02 09:00:39:266] [INFO] [PulsarRedeliverBug:83] - time: 1205 msg: 2020-03-02T08:00:38.035792Z, receivedCount: 2, redeliverCount: 0 [20-Mar-02 09:00:40:323] [WARN] [UnAckedMessageTracker:132] - [ConsumerBase{subscription='failing-subscription', consumerName='failing-consumer', topic='persistent://public/default/redeliver-topic'}] 1 messages have timed-out [20-Mar-02 09:00:40:471] [INFO] [PulsarRedeliverBug:83] - time: 2410 msg: 2020-03-02T08:00:15.679538Z, receivedCount: 3, redeliverCount: 1 [20-Mar-02 09:00:41:549] [WARN] [UnAckedMessageTracker:132] - [ConsumerBase{subscription='failing-subscription', consumerName='failing-consumer', topic='persistent://public/default/redeliver-topic'}] 1 messages have timed-out [20-Mar-02 09:00:41:676] [INFO] [PulsarRedeliverBug:83] - time: 3615 msg: 2020-03-02T08:00:15.679538Z, receivedCount: 4, redeliverCount: 2 [20-Mar-02 09:00:42:778] [WARN] [UnAckedMessageTracker:132] - [ConsumerBase{subscription='failing-subscription', consumerName='failing-consumer', topic='persistent://public/default/redeliver-topic'}] 1 messages have timed-out [20-Mar-02 09:00:42:882] [INFO] [PulsarRedeliverBug:83] - time: 4821 msg: 2020-03-02T08:00:38.035792Z, receivedCount: 5, redeliverCount: 2 [20-Mar-02 09:00:44:004] [WARN] [UnAckedMessageTracker:132] - [ConsumerBase{subscription='failing-subscription', consumerName='failing-consumer', topic='persistent://public/default/redeliver-topic'}] 1 messages have timed-out [20-Mar-02 09:00:44:088] [INFO] [PulsarRedeliverBug:83] - time: 6026 msg: 2020-03-02T08:00:15.679538Z, receivedCount: 6, redeliverCount: 3 [20-Mar-02 09:00:45:130] [WARN] [UnAckedMessageTracker:132] - [ConsumerBase{subscription='failing-subscription', consumerName='failing-consumer', topic='persistent://public/default/redeliver-topic'}] 1 messages have timed-out [20-Mar-02 09:00:45:293] [INFO] [PulsarRedeliverBug:83] - time: 7232 msg: 2020-03-02T08:00:15.679538Z, receivedCount: 7, redeliverCount: 4 [20-Mar-02 09:00:46:358] [WARN] [UnAckedMessageTracker:132] - [ConsumerBase{subscription='failing-subscription', consumerName='failing-consumer', topic='persistent://public/default/redeliver-topic'}] 1 messages have timed-out [20-Mar-02 09:00:46:498] [INFO] [PulsarRedeliverBug:83] - time: 8437 msg: 2020-03-02T08:00:38.035792Z, receivedCount: 8, redeliverCount: 4 [20-Mar-02 09:00:47:588] [WARN] [UnAckedMessageTracker:132] - [ConsumerBase{subscription='failing-subscription', consumerName='failing-consumer', topic='persistent://public/default/redeliver-topic'}] 1 messages have timed-out [20-Mar-02 09:00:47:721] [INFO] [PulsarRedeliverBug:83] - time: 9660 msg: 2020-03-02T08:00:15.679538Z, receivedCount: 9, redeliverCount: 7 [20-Mar-02 09:00:48:816] [WARN] [UnAckedMessageTracker:132] - [ConsumerBase{subscription='failing-subscription', consumerName='failing-consumer', topic='persistent://public/default/redeliver-topic'}] 1 messages have timed-out [20-Mar-02 09:00:48:817] [WARN] [TopicName:279] - Could not get the partition index from the topic persistent://public/default/redeliver-topic-partition-0-failing-subscription-DLQ [20-Mar-02 09:00:48:826] [INFO] [ProducerStatsRecorderImpl:101] - Starting Pulsar producer perf with config: { "topicName" : "persistent://public/default/redeliver-topic-partition-0-failing-subscription-DLQ", "producerName" : null, "sendTimeoutMs" : 30000, "blockIfQueueFull" : false, "maxPendingMessages" : 1000, "maxPendingMessagesAcrossPartitions" : 50000, "messageRoutingMode" : "RoundRobinPartition", "hashingScheme" : "JavaStringHash", "cryptoFailureAction" : "FAIL", "batchingMaxPublishDelayMicros" : 1000, "batchingPartitionSwitchFrequencyByPublishDelay" : 10, "batchingMaxMessages" : 1000, "batchingMaxBytes" : 131072, "batchingEnabled" : true, "compressionType" : "NONE", "initialSequenceId" : null, "autoUpdatePartitions" : true, "multiSchema" : true, "properties" : { } } [20-Mar-02 09:00:48:829] [INFO] [ProducerStatsRecorderImpl:102] - Pulsar client config: { "serviceUrl" : "pulsar://localhost:14002", "authPluginClassName" : null, "authParams" : null, "operationTimeoutMs" : 30000, "statsIntervalSeconds" : 60, "numIoThreads" : 1, "numListenerThreads" : 1, "connectionsPerBroker" : 1, "useTcpNoDelay" : true, "useTls" : false, "tlsTrustCertsFilePath" : "", "tlsAllowInsecureConnection" : false, "tlsHostnameVerificationEnable" : false, "concurrentLookupRequest" : 5000, "maxLookupRequest" : 50000, "maxNumberOfRejectedRequestPerConnection" : 50, "keepAliveIntervalSeconds" : 30, "connectionTimeoutMs" : 10000, "requestTimeoutMs" : 60000, "initialBackoffIntervalNanos" : 100000000, "maxBackoffIntervalNanos" : 60000000000 } [20-Mar-02 09:00:48:834] [INFO] [ProducerImpl:1059] - [persistent://public/default/redeliver-topic-partition-0-failing-subscription-DLQ] [null] Creating producer on cnx [id: 0x36418be6, L:/127.0.0.1:60960 - R:localhost/127.0.0.1:14002] [20-Mar-02 09:00:48:870] [INFO] [ProducerImpl:1109] - [persistent://public/default/redeliver-topic-partition-0-failing-subscription-DLQ] [standalone-9-108] Created producer on cnx [id: 0x36418be6, L:/127.0.0.1:60960 - R:localhost/127.0.0.1:14002] [20-Mar-02 09:00:48:871] [INFO] [PartitionedProducerImpl:145] - [persistent://public/default/redeliver-topic-partition-0-failing-subscription-DLQ] Created partitioned producer [20-Mar-02 09:00:58:136] [INFO] [ConsumerImpl:761] - [persistent://public/default/redeliver-topic-partition-0] [failing-subscription] Closed consumer [20-Mar-02 09:00:58:137] [INFO] [MultiTopicsConsumerImpl:538] - [persistent://public/default/redeliver-topic] [failing-subscription] Closed Topics Consumer [20-Mar-02 09:00:58:143] [INFO] [ProducerImpl:755] - [persistent://public/default/redeliver-topic-partition-0] [standalone-9-107] Closed Producer [20-Mar-02 09:00:58:143] [INFO] [PartitionedProducerImpl:229] - [persistent://public/default/redeliver-topic] Closed Partitioned Producer [20-Mar-02 09:00:58:143] [INFO] [PulsarClientImpl:538] - Client closing. URL: pulsar://localhost:14002 [20-Mar-02 09:00:58:148] [INFO] [ProducerImpl:755] - [persistent://public/default/redeliver-topic-partition-0-failing-subscription-DLQ] [standalone-9-108] Closed Producer [20-Mar-02 09:00:58:149] [INFO] [PartitionedProducerImpl:229] - [persistent://public/default/redeliver-topic-partition-0-failing-subscription-DLQ] Closed Partitioned Producer [20-Mar-02 09:00:58:151] [INFO] [ClientCnx:225] - [id: 0x36418be6, L:/127.0.0.1:60960 ! R:localhost/127.0.0.1:14002] Disconnected [20-Mar-02 09:00:58:151] [INFO] [ClientCnx:225] - [id: 0xb9c6f5ed, L:/127.0.0.1:60959 ! R:localhost/127.0.0.1:14002] Disconnected [20-Mar-02 09:00:58:159] [WARN] [MultiTopicsConsumerImpl:299] - [persistent://public/default/redeliver-topic] [failing-subscription] Failed to dequeue the message for listener org.apache.pulsar.client.api.PulsarClientException: java.lang.InterruptedException at org.apache.pulsar.client.api.PulsarClientException.unwrap(PulsarClientException.java:656) ~[pulsar-client-api-2.5.0.jar:2.5.0] at org.apache.pulsar.client.impl.MultiTopicsConsumerImpl.internalReceive(MultiTopicsConsumerImpl.java:354) ~[pulsar-client-2.5.0.jar:2.5.0] at org.apache.pulsar.client.impl.MultiTopicsConsumerImpl.lambda$messageReceived$9(MultiTopicsConsumerImpl.java:297) ~[pulsar-client-2.5.0.jar:2.5.0] at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) [?:?] at java.util.concurrent.FutureTask.run(FutureTask.java:264) [?:?] at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) [?:?] at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?] at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?] at org.apache.pulsar.shade.io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) [pulsar-client-2.5.0.jar:2.5.0] at java.lang.Thread.run(Thread.java:834) [?:?] Caused by: java.lang.InterruptedException at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.reportInterruptAfterWait(AbstractQueuedSynchronizer.java:2056) ~[?:?] at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2090) ~[?:?] at org.apache.pulsar.common.util.collections.GrowableArrayBlockingQueue.take(GrowableArrayBlockingQueue.java:176) ~[pulsar-client-2.5.0.jar:2.5.0] at org.apache.pulsar.client.impl.MultiTopicsConsumerImpl.internalReceive(MultiTopicsConsumerImpl.java:347) ~[pulsar-client-2.5.0.jar:2.5.0] ... 8 more ```
---------------------------------------------------------------- This is an automated message from the Apache Git Service. To respond to the message, please log on to GitHub and use the URL above to go to the specific comment. For queries about this service, please contact Infrastructure at: [email protected] With regards, Apache Git Services
