Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[Messaging] Fix delay message block #10078

Merged
merged 6 commits into from
Apr 9, 2021

Conversation

gaoran10
Copy link
Contributor

@gaoran10 gaoran10 commented Mar 29, 2021

Based on the PR #10077

Motivation

Currently, in the docker environment, if the consumer enables the retry feature and sets the retry topic in DeadLetterPolicy, the consumer will be blocked after receive retry messages many times.

The delay TimerTask may run before reaching the timeout, we could find out that the last log Timer triggered run after the log Start timer in 4958 millis but we cloud compute the duration between these two logs is 4936, it's less than 4958, so the hasMessageAvailable check is false, if there are no more messages to read the delay messages reading will be blocked. Please check logs below.

test environment

Macos 11.2.3 (20D91)
Docker image apachepulsar/pulsar:2.7.1, run standalone mode use default configuration.

13:29:10.220 [ForkJoinPool.commonPool-worker-2] INFO  org.apache.pulsar.broker.service.ServerCnx - [/172.17.0.1:56868] Created new producer: Producer{topic=PersistentTopic{topic=persistent://public/default/demo-RETRY}, client=/172.17.0.1:56868, producerName=standalone-1-1, producerId=1}
13:29:10.258 [bookkeeper-ml-workers-OrderedExecutor-2-0] DEBUG org.apache.pulsar.broker.service.persistent.PersistentDispatcherMultipleConsumers - [persistent://public/default/demo-RETRY / test] Distributing 1 messages to 1 consumers
13:29:10.265 [bookkeeper-ml-workers-OrderedExecutor-2-0] DEBUG org.apache.pulsar.broker.delayed.InMemoryDelayedDeliveryTracker - [persistent://public/default/demo-RETRY / test] Add message 21:0 -- Delivery in 4979 ms
13:29:10.267 [bookkeeper-ml-workers-OrderedExecutor-2-0] DEBUG org.apache.pulsar.broker.delayed.InMemoryDelayedDeliveryTracker - [persistent://public/default/demo-RETRY / test] Start timer in 4978 millis
13:29:10.271 [bookkeeper-ml-workers-OrderedExecutor-2-0] DEBUG org.apache.pulsar.broker.service.persistent.PersistentDispatcherMultipleConsumers - [persistent://public/default/demo-RETRY / test] Schedule read of 100 messages for 1 consumers
13:29:15.251 [pulsar-delayed-delivery-59-1] DEBUG org.apache.pulsar.broker.delayed.InMemoryDelayedDeliveryTracker - [persistent://public/default/demo-RETRY / test] Timer triggered
13:29:15.253 [pulsar-delayed-delivery-59-1] DEBUG org.apache.pulsar.broker.delayed.InMemoryDelayedDeliveryTracker - [persistent://public/default/demo-RETRY / test] Get scheduled messages - found 1
13:29:15.254 [pulsar-delayed-delivery-59-1] DEBUG org.apache.pulsar.broker.service.persistent.PersistentDispatcherMultipleConsumers - [persistent://public/default/demo-RETRY / test] Schedule replay of 1 messages for 1 consumers
13:29:15.272 [bookkeeper-ml-workers-OrderedExecutor-2-0] DEBUG org.apache.pulsar.broker.service.persistent.PersistentDispatcherMultipleConsumers - [persistent://public/default/demo-RETRY / test] Distributing 1 messages to 1 consumers
13:29:15.274 [bookkeeper-ml-workers-OrderedExecutor-2-0] DEBUG org.apache.pulsar.broker.delayed.InMemoryDelayedDeliveryTracker - [persistent://public/default/demo-RETRY / test] Add message 21:0 -- Delivery in -30 ms
13:29:15.275 [bookkeeper-ml-workers-OrderedExecutor-2-0] DEBUG org.apache.pulsar.broker.service.persistent.PersistentDispatcherMultipleConsumers - [persistent://public/default/demo-RETRY / test] Cannot schedule next read until previous one is done
13:29:15.328 [pulsar-io-50-1] INFO  org.apache.pulsar.broker.service.ServerCnx - [/172.17.0.1:56868][persistent://public/default/demo-RETRY] Creating producer. producerId=2
13:29:15.332 [ForkJoinPool.commonPool-worker-3] INFO  org.apache.pulsar.broker.service.ServerCnx - [/172.17.0.1:56868] persistent://public/default/demo-RETRY configured with schema false
13:29:15.334 [ForkJoinPool.commonPool-worker-3] INFO  org.apache.pulsar.broker.service.ServerCnx - [/172.17.0.1:56868] Created new producer: Producer{topic=PersistentTopic{topic=persistent://public/default/demo-RETRY}, client=/172.17.0.1:56868, producerName=standalone-1-2, producerId=2}
13:29:15.356 [bookkeeper-ml-workers-OrderedExecutor-2-0] DEBUG org.apache.pulsar.broker.service.persistent.PersistentDispatcherMultipleConsumers - [persistent://public/default/demo-RETRY / test] Distributing 1 messages to 1 consumers
13:29:15.356 [bookkeeper-ml-workers-OrderedExecutor-2-0] DEBUG org.apache.pulsar.broker.delayed.InMemoryDelayedDeliveryTracker - [persistent://public/default/demo-RETRY / test] Add message 21:1 -- Delivery in 4978 ms
13:29:15.357 [bookkeeper-ml-workers-OrderedExecutor-2-0] DEBUG org.apache.pulsar.broker.delayed.InMemoryDelayedDeliveryTracker - [persistent://public/default/demo-RETRY / test] Start timer in 4977 millis
13:29:15.359 [bookkeeper-ml-workers-OrderedExecutor-2-0] DEBUG org.apache.pulsar.broker.service.persistent.PersistentDispatcherMultipleConsumers - [persistent://public/default/demo-RETRY / test] Schedule read of 99 messages for 1 consumers
13:29:20.342 [pulsar-delayed-delivery-59-1] DEBUG org.apache.pulsar.broker.delayed.InMemoryDelayedDeliveryTracker - [persistent://public/default/demo-RETRY / test] Timer triggered
13:29:20.342 [pulsar-delayed-delivery-59-1] DEBUG org.apache.pulsar.broker.delayed.InMemoryDelayedDeliveryTracker - [persistent://public/default/demo-RETRY / test] Get scheduled messages - found 1
13:29:20.343 [pulsar-delayed-delivery-59-1] DEBUG org.apache.pulsar.broker.service.persistent.PersistentDispatcherMultipleConsumers - [persistent://public/default/demo-RETRY / test] Schedule replay of 1 messages for 1 consumers
13:29:20.348 [bookkeeper-ml-workers-OrderedExecutor-2-0] DEBUG org.apache.pulsar.broker.service.persistent.PersistentDispatcherMultipleConsumers - [persistent://public/default/demo-RETRY / test] Distributing 1 messages to 1 consumers
13:29:20.349 [bookkeeper-ml-workers-OrderedExecutor-2-0] DEBUG org.apache.pulsar.broker.delayed.InMemoryDelayedDeliveryTracker - [persistent://public/default/demo-RETRY / test] Add message 21:1 -- Delivery in -15 ms
13:29:20.349 [bookkeeper-ml-workers-OrderedExecutor-2-0] DEBUG org.apache.pulsar.broker.service.persistent.PersistentDispatcherMultipleConsumers - [persistent://public/default/demo-RETRY / test] Cannot schedule next read until previous one is done
13:29:20.376 [bookkeeper-ml-workers-OrderedExecutor-2-0] DEBUG org.apache.pulsar.broker.service.persistent.PersistentDispatcherMultipleConsumers - [persistent://public/default/demo-RETRY / test] Distributing 1 messages to 1 consumers
13:29:20.377 [bookkeeper-ml-workers-OrderedExecutor-2-0] DEBUG org.apache.pulsar.broker.delayed.InMemoryDelayedDeliveryTracker - [persistent://public/default/demo-RETRY / test] Add message 21:2 -- Delivery in 4965 ms
13:29:20.377 [bookkeeper-ml-workers-OrderedExecutor-2-0] DEBUG org.apache.pulsar.broker.delayed.InMemoryDelayedDeliveryTracker - [persistent://public/default/demo-RETRY / test] Start timer in 4965 millis
13:29:20.377 [bookkeeper-ml-workers-OrderedExecutor-2-0] DEBUG org.apache.pulsar.broker.service.persistent.PersistentDispatcherMultipleConsumers - [persistent://public/default/demo-RETRY / test] Schedule read of 98 messages for 1 consumers
13:29:24.155 [pulsar-web-68-3] INFO  org.eclipse.jetty.server.RequestLog - 127.0.0.1 - - [29/Mar/2021:13:29:24 +0000] "GET /admin/v2/persistent/public/functions/coordinate/stats?getPreciseBacklog=false&subscriptionBacklogSize=false HTTP/1.1" 200 1677 "-" "Pulsar-Java-v2.7.1" 4
13:29:25.351 [pulsar-delayed-delivery-59-1] DEBUG org.apache.pulsar.broker.delayed.InMemoryDelayedDeliveryTracker - [persistent://public/default/demo-RETRY / test] Timer triggered
13:29:25.351 [pulsar-delayed-delivery-59-1] DEBUG org.apache.pulsar.broker.delayed.InMemoryDelayedDeliveryTracker - [persistent://public/default/demo-RETRY / test] Get scheduled messages - found 1
13:29:25.351 [pulsar-delayed-delivery-59-1] DEBUG org.apache.pulsar.broker.service.persistent.PersistentDispatcherMultipleConsumers - [persistent://public/default/demo-RETRY / test] Schedule replay of 1 messages for 1 consumers
13:29:25.357 [bookkeeper-ml-workers-OrderedExecutor-2-0] DEBUG org.apache.pulsar.broker.service.persistent.PersistentDispatcherMultipleConsumers - [persistent://public/default/demo-RETRY / test] Distributing 1 messages to 1 consumers
13:29:25.358 [bookkeeper-ml-workers-OrderedExecutor-2-0] DEBUG org.apache.pulsar.broker.delayed.InMemoryDelayedDeliveryTracker - [persistent://public/default/demo-RETRY / test] Add message 21:2 -- Delivery in -16 ms
13:29:25.358 [bookkeeper-ml-workers-OrderedExecutor-2-0] DEBUG org.apache.pulsar.broker.service.persistent.PersistentDispatcherMultipleConsumers - [persistent://public/default/demo-RETRY / test] Cannot schedule next read until previous one is done
13:29:25.384 [bookkeeper-ml-workers-OrderedExecutor-2-0] DEBUG org.apache.pulsar.broker.service.persistent.PersistentDispatcherMultipleConsumers - [persistent://public/default/demo-RETRY / test] Distributing 1 messages to 1 consumers
13:29:25.385 [bookkeeper-ml-workers-OrderedExecutor-2-0] DEBUG org.apache.pulsar.broker.delayed.InMemoryDelayedDeliveryTracker - [persistent://public/default/demo-RETRY / test] Add message 21:3 -- Delivery in 4959 ms
13:29:25.385 [bookkeeper-ml-workers-OrderedExecutor-2-0] DEBUG org.apache.pulsar.broker.delayed.InMemoryDelayedDeliveryTracker - [persistent://public/default/demo-RETRY / test] Start timer in 4959 millis
13:29:25.385 [bookkeeper-ml-workers-OrderedExecutor-2-0] DEBUG org.apache.pulsar.broker.service.persistent.PersistentDispatcherMultipleConsumers - [persistent://public/default/demo-RETRY / test] Schedule read of 97 messages for 1 consumers
13:29:30.351 [pulsar-delayed-delivery-59-1] DEBUG org.apache.pulsar.broker.delayed.InMemoryDelayedDeliveryTracker - [persistent://public/default/demo-RETRY / test] Timer triggered
13:29:30.352 [pulsar-delayed-delivery-59-1] DEBUG org.apache.pulsar.broker.delayed.InMemoryDelayedDeliveryTracker - [persistent://public/default/demo-RETRY / test] Get scheduled messages - found 1
13:29:30.352 [pulsar-delayed-delivery-59-1] DEBUG org.apache.pulsar.broker.service.persistent.PersistentDispatcherMultipleConsumers - [persistent://public/default/demo-RETRY / test] Schedule replay of 1 messages for 1 consumers
13:29:30.356 [bookkeeper-ml-workers-OrderedExecutor-2-0] DEBUG org.apache.pulsar.broker.service.persistent.PersistentDispatcherMultipleConsumers - [persistent://public/default/demo-RETRY / test] Distributing 1 messages to 1 consumers
13:29:30.357 [bookkeeper-ml-workers-OrderedExecutor-2-0] DEBUG org.apache.pulsar.broker.delayed.InMemoryDelayedDeliveryTracker - [persistent://public/default/demo-RETRY / test] Add message 21:3 -- Delivery in -13 ms
13:29:30.357 [bookkeeper-ml-workers-OrderedExecutor-2-0] DEBUG org.apache.pulsar.broker.service.persistent.PersistentDispatcherMultipleConsumers - [persistent://public/default/demo-RETRY / test] Cannot schedule next read until previous one is done
13:29:30.371 [bookkeeper-ml-workers-OrderedExecutor-2-0] DEBUG org.apache.pulsar.broker.service.persistent.PersistentDispatcherMultipleConsumers - [persistent://public/default/demo-RETRY / test] Distributing 1 messages to 1 consumers
13:29:30.372 [bookkeeper-ml-workers-OrderedExecutor-2-0] DEBUG org.apache.pulsar.broker.delayed.InMemoryDelayedDeliveryTracker - [persistent://public/default/demo-RETRY / test] Add message 21:4 -- Delivery in 4966 ms
13:29:30.372 [bookkeeper-ml-workers-OrderedExecutor-2-0] DEBUG org.apache.pulsar.broker.delayed.InMemoryDelayedDeliveryTracker - [persistent://public/default/demo-RETRY / test] Start timer in 4966 millis
13:29:30.372 [bookkeeper-ml-workers-OrderedExecutor-2-0] DEBUG org.apache.pulsar.broker.service.persistent.PersistentDispatcherMultipleConsumers - [persistent://public/default/demo-RETRY / test] Schedule read of 96 messages for 1 consumers
13:29:32.696 [SessionTracker] INFO  org.apache.zookeeper.server.ZooKeeperServer - Expiring session 0x10014b5c5930004, timeout of 60000ms exceeded
13:29:32.706 [Curator-LeaderSelector-0] INFO  org.apache.bookkeeper.stream.storage.impl.cluster.ClusterControllerLeaderImpl - Become controller leader to monitor servers for assigning storage containers.
13:29:32.715 [main-EventThread] INFO  org.apache.bookkeeper.discover.ZKRegistrationClient - Update BookieInfoCache (writable bookie) 172.17.0.2:4181 -> BookieServiceInfo{properties={}, endpoints=[EndpointInfo{id=172.17.0.2:4181, port=4181, host=172.17.0.2, protocol=bookie-rpc, auth=[], extensions=[]}]}
13:29:32.716 [registration-service-provider-scheduler] INFO  org.apache.bookkeeper.stream.storage.impl.cluster.ClusterControllerLeaderImpl - Cluster topology is changed - new cluster : Versioned(value=[172.17.0.2:4181], version=3)
13:29:35.341 [pulsar-delayed-delivery-59-1] DEBUG org.apache.pulsar.broker.delayed.InMemoryDelayedDeliveryTracker - [persistent://public/default/demo-RETRY / test] Timer triggered
13:29:35.342 [pulsar-delayed-delivery-59-1] DEBUG org.apache.pulsar.broker.delayed.InMemoryDelayedDeliveryTracker - [persistent://public/default/demo-RETRY / test] Get scheduled messages - found 1
13:29:35.342 [pulsar-delayed-delivery-59-1] DEBUG org.apache.pulsar.broker.service.persistent.PersistentDispatcherMultipleConsumers - [persistent://public/default/demo-RETRY / test] Schedule replay of 1 messages for 1 consumers
13:29:35.347 [bookkeeper-ml-workers-OrderedExecutor-2-0] DEBUG org.apache.pulsar.broker.service.persistent.PersistentDispatcherMultipleConsumers - [persistent://public/default/demo-RETRY / test] Distributing 1 messages to 1 consumers
13:29:35.348 [bookkeeper-ml-workers-OrderedExecutor-2-0] DEBUG org.apache.pulsar.broker.delayed.InMemoryDelayedDeliveryTracker - [persistent://public/default/demo-RETRY / test] Add message 21:4 -- Delivery in -10 ms
13:29:35.348 [bookkeeper-ml-workers-OrderedExecutor-2-0] DEBUG org.apache.pulsar.broker.service.persistent.PersistentDispatcherMultipleConsumers - [persistent://public/default/demo-RETRY / test] Cannot schedule next read until previous one is done
13:29:35.363 [bookkeeper-ml-workers-OrderedExecutor-2-0] DEBUG org.apache.pulsar.broker.service.persistent.PersistentDispatcherMultipleConsumers - [persistent://public/default/demo-RETRY / test] Distributing 1 messages to 1 consumers
13:29:35.364 [bookkeeper-ml-workers-OrderedExecutor-2-0] DEBUG org.apache.pulsar.broker.delayed.InMemoryDelayedDeliveryTracker - [persistent://public/default/demo-RETRY / test] Add message 21:5 -- Delivery in 4959 ms
13:29:35.365 [bookkeeper-ml-workers-OrderedExecutor-2-0] DEBUG org.apache.pulsar.broker.delayed.InMemoryDelayedDeliveryTracker - [persistent://public/default/demo-RETRY / test] Start timer in 4958 millis
13:29:35.366 [bookkeeper-ml-workers-OrderedExecutor-2-0] DEBUG org.apache.pulsar.broker.service.persistent.PersistentDispatcherMultipleConsumers - [persistent://public/default/demo-RETRY / test] Schedule read of 95 messages for 1 consumers
13:29:40.301 [pulsar-delayed-delivery-59-1] DEBUG org.apache.pulsar.broker.delayed.InMemoryDelayedDeliveryTracker - [persistent://public/default/demo-RETRY / test] Timer triggered
13:29:40.301 [pulsar-delayed-delivery-59-1] DEBUG org.apache.pulsar.broker.service.persistent.PersistentDispatcherMultipleConsumers - [persistent://public/default/demo-RETRY / test] Cannot schedule next read until previous one is done
13:29:54.127 [pulsar-web-68-8] INFO  org.eclipse.jetty.server.RequestLog - 127.0.0.1 - - [29/Mar/2021:13:29:54 +0000] "GET /admin/v2/persistent/public/functions/coordinate/stats?getPreciseBacklog=false&subscriptionBacklogSize=false HTTP/1.1" 200 1677 "-" "Pulsar-Java-v2.7.1" 4
13:30:24.094 [pulsar-web-68-4] INFO  org.eclipse.jetty.server.RequestLog - 127.0.0.1 - - [29/Mar/2021:13:30:24 +0000] "GET /admin/v2/persistent/public/functions/coordinate/stats?getPreciseBacklog=false&subscriptionBacklogSize=false HTTP/1.1" 200 1677 "-" "Pulsar-Java-v2.7.1" 8
13:30:54.054 [pulsar-web-68-5] INFO  org.eclipse.jetty.server.RequestLog - 127.0.0.1 - - [29/Mar/2021:13:30:54 +0000] "GET /admin/v2/persistent/public/functions/coordinate/stats?getPreciseBacklog=false&subscriptionBacklogSize=false HTTP/1.1" 200 1677 "-" "Pulsar-Java-v2.7.1" 4

filter related logs ▽ ▽ ▽

09:31:48.546 [bookkeeper-ml-workers-OrderedExecutor-2-0] DEBUG org.apache.pulsar.broker.delayed.InMemoryDelayedDeliveryTracker - [persistent://public/default/demo-RETRY / test] Add message 12:0 -- Delivery in 9959 ms
09:31:48.547 [bookkeeper-ml-workers-OrderedExecutor-2-0] DEBUG org.apache.pulsar.broker.delayed.InMemoryDelayedDeliveryTracker - [persistent://public/default/demo-RETRY / test] Start timer in 9958 millis
09:31:58.549 [pulsar-delayed-delivery-59-1] DEBUG org.apache.pulsar.broker.delayed.InMemoryDelayedDeliveryTracker - [persistent://public/default/demo-RETRY / test] Timer triggered
09:31:58.551 [pulsar-delayed-delivery-59-1] DEBUG org.apache.pulsar.broker.delayed.InMemoryDelayedDeliveryTracker - [persistent://public/default/demo-RETRY / test] Get scheduled messages - found 1
09:31:58.602 [bookkeeper-ml-workers-OrderedExecutor-2-0] DEBUG org.apache.pulsar.broker.delayed.InMemoryDelayedDeliveryTracker - [persistent://public/default/demo-RETRY / test] Add message 12:0 -- Delivery in -97 ms


09:31:58.766 [bookkeeper-ml-workers-OrderedExecutor-2-0] DEBUG org.apache.pulsar.broker.delayed.InMemoryDelayedDeliveryTracker - [persistent://public/default/demo-RETRY / test] Add message 12:1 -- Delivery in 9914 ms
09:31:58.767 [bookkeeper-ml-workers-OrderedExecutor-2-0] DEBUG org.apache.pulsar.broker.delayed.InMemoryDelayedDeliveryTracker - [persistent://public/default/demo-RETRY / test] Start timer in 9913 millis
09:32:09.549 [pulsar-delayed-delivery-59-1] DEBUG org.apache.pulsar.broker.delayed.InMemoryDelayedDeliveryTracker - [persistent://public/default/demo-RETRY / test] Timer triggered
09:32:09.549 [pulsar-delayed-delivery-59-1] DEBUG org.apache.pulsar.broker.delayed.InMemoryDelayedDeliveryTracker - [persistent://public/default/demo-RETRY / test] Get scheduled messages - found 1
09:32:09.591 [bookkeeper-ml-workers-OrderedExecutor-2-0] DEBUG org.apache.pulsar.broker.delayed.InMemoryDelayedDeliveryTracker - [persistent://public/default/demo-RETRY / test] Add message 12:1 -- Delivery in -911 ms


09:32:09.611 [bookkeeper-ml-workers-OrderedExecutor-2-0] DEBUG org.apache.pulsar.broker.delayed.InMemoryDelayedDeliveryTracker - [persistent://public/default/demo-RETRY / test] Add message 12:2 -- Delivery in 9959 ms
09:32:09.612 [bookkeeper-ml-workers-OrderedExecutor-2-0] DEBUG org.apache.pulsar.broker.delayed.InMemoryDelayedDeliveryTracker - [persistent://public/default/demo-RETRY / test] Start timer in 9959 millis
09:32:20.515 [pulsar-delayed-delivery-59-1] DEBUG org.apache.pulsar.broker.delayed.InMemoryDelayedDeliveryTracker - [persistent://public/default/demo-RETRY / test] Timer triggered
09:32:20.516 [pulsar-delayed-delivery-59-1] DEBUG org.apache.pulsar.broker.delayed.InMemoryDelayedDeliveryTracker - [persistent://public/default/demo-RETRY / test] Get scheduled messages - found 1
09:32:20.541 [bookkeeper-ml-workers-OrderedExecutor-2-0] DEBUG org.apache.pulsar.broker.delayed.InMemoryDelayedDeliveryTracker - [persistent://public/default/demo-RETRY / test] Add message 12:2 -- Delivery in -971 ms


09:32:20.597 [bookkeeper-ml-workers-OrderedExecutor-2-0] DEBUG org.apache.pulsar.broker.delayed.InMemoryDelayedDeliveryTracker - [persistent://public/default/demo-RETRY / test] Add message 12:3 -- Delivery in 9954 ms
09:32:20.597 [bookkeeper-ml-workers-OrderedExecutor-2-0] DEBUG org.apache.pulsar.broker.delayed.InMemoryDelayedDeliveryTracker - [persistent://public/default/demo-RETRY / test] Start timer in 9954 millis
09:32:31.515 [pulsar-delayed-delivery-59-1] DEBUG org.apache.pulsar.broker.delayed.InMemoryDelayedDeliveryTracker - [persistent://public/default/demo-RETRY / test] Timer triggered
09:32:31.516 [pulsar-delayed-delivery-59-1] DEBUG org.apache.pulsar.broker.delayed.InMemoryDelayedDeliveryTracker - [persistent://public/default/demo-RETRY / test] Get scheduled messages - found 1
09:32:31.539 [bookkeeper-ml-workers-OrderedExecutor-2-0] DEBUG org.apache.pulsar.broker.delayed.InMemoryDelayedDeliveryTracker - [persistent://public/default/demo-RETRY / test] Add message 12:3 -- Delivery in -988 ms


09:32:31.618 [bookkeeper-ml-workers-OrderedExecutor-2-0] DEBUG org.apache.pulsar.broker.delayed.InMemoryDelayedDeliveryTracker - [persistent://public/default/demo-RETRY / test] Add message 12:4 -- Delivery in 9930 ms
09:32:31.627 [bookkeeper-ml-workers-OrderedExecutor-2-0] DEBUG org.apache.pulsar.broker.delayed.InMemoryDelayedDeliveryTracker - [persistent://public/default/demo-RETRY / test] Start timer in 9922 millis
09:32:42.515 [pulsar-delayed-delivery-59-1] DEBUG org.apache.pulsar.broker.delayed.InMemoryDelayedDeliveryTracker - [persistent://public/default/demo-RETRY / test] Timer triggered
09:32:42.516 [pulsar-delayed-delivery-59-1] DEBUG org.apache.pulsar.broker.delayed.InMemoryDelayedDeliveryTracker - [persistent://public/default/demo-RETRY / test] Get scheduled messages - found 1
09:32:42.523 [bookkeeper-ml-workers-OrderedExecutor-2-0] DEBUG org.apache.pulsar.broker.delayed.InMemoryDelayedDeliveryTracker - [persistent://public/default/demo-RETRY / test] Add message 12:4 -- Delivery in -975 ms


09:32:42.548 [bookkeeper-ml-workers-OrderedExecutor-2-0] DEBUG org.apache.pulsar.broker.delayed.InMemoryDelayedDeliveryTracker - [persistent://public/default/demo-RETRY / test] Add message 12:5 -- Delivery in 9956 ms
09:32:42.549 [bookkeeper-ml-workers-OrderedExecutor-2-0] DEBUG org.apache.pulsar.broker.delayed.InMemoryDelayedDeliveryTracker - [persistent://public/default/demo-RETRY / test] Start timer in 9955 millis
09:32:52.480 [pulsar-delayed-delivery-59-1] DEBUG org.apache.pulsar.broker.delayed.InMemoryDelayedDeliveryTracker - [persistent://public/default/demo-RETRY / test] Timer triggered

Modifications

change the hasMessageAvailable check for delay messages

Verifying this change

Add an integration test.

Does this pull request potentially affect one of the following parts:

If yes was chosen, please highlight the changes

  • Dependencies (does it add or upgrade a dependency): (no)
  • The public API: (no)
  • The schema: (no)
  • The default values of configurations: (no)
  • The wire protocol: (no)
  • The rest endpoints: (no)
  • The admin cli options: (no)
  • Anything that affects deployment: (no)

@gaoran10
Copy link
Contributor Author

This PR based on the PR #10077.

.subscriptionName("test")
.subscribe();

message = dltConsumer.receive(10, TimeUnit.SECONDS);
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

is there a way to not rely on this timeout ?
I am afraid we are going to add a new flaky test

cc @lhotari

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Normally, we could receive messages from the dead letter topic.

.create();

final int redeliverCnt = 10;
final int delayTimeSeconds = 10;
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Now that the integration test has been taking a long time, can we reduce the time here?

Later receive message at first time will use more than 100 seconds

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I reduce the delay timeout to 5, thanks.

@codelipenghui codelipenghui added this to the 2.8.0 milestone Mar 31, 2021
@codelipenghui codelipenghui added release/2.7.2 type/bug The PR fixed a bug or issue reported a bug labels Mar 31, 2021
@gaoran10
Copy link
Contributor Author

gaoran10 commented Apr 1, 2021

/pulsarbot run-failure-checks

1 similar comment
@gaoran10
Copy link
Contributor Author

gaoran10 commented Apr 2, 2021

/pulsarbot run-failure-checks

@gaoran10
Copy link
Contributor Author

gaoran10 commented Apr 9, 2021

/pulsarbot run-failure-checks

@codelipenghui codelipenghui merged commit 31f8315 into apache:master Apr 9, 2021
@gaoran10 gaoran10 deleted the fix-delay-message-block branch April 9, 2021 09:38
zymap pushed a commit that referenced this pull request Apr 14, 2021
Currently, in the docker environment, if the consumer enables the retry feature and sets the retry topic in DeadLetterPolicy, the consumer will be blocked after receive retry messages many times.

The delay TimerTask may run before reaching the timeout, we could find out that the last log `Timer triggered` run after the log `Start timer in 4958 millis` but we cloud compute the duration between these two logs is `4936`, it's less than `4958`, so the hasMessageAvailable check is false, if there are no more messages to read the delay messages reading will be blocked. Please check logs below.

(cherry picked from commit 31f8315)
@zymap zymap added the cherry-picked/branch-2.7 Archived: 2.7 is end of life label Apr 14, 2021
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
cherry-picked/branch-2.7 Archived: 2.7 is end of life release/2.7.2 type/bug The PR fixed a bug or issue reported a bug
Projects
None yet
Development

Successfully merging this pull request may close these issues.

None yet

5 participants