[fix][broker] Fix intermittent issue where leader broker information is lost and causes lookup issues by lhotari · Pull Request #17254 · apache/pulsar

lhotari · 2022-08-24T07:21:46Z

Motivation

Fixes issue where leader broker information isn't available and this warning gets logged:
WARN org.apache.pulsar.broker.namespace.NamespaceService - The information about the current leader broker wasn't available. Handling load manager decisions in a decentralized way.

Modifications

use LeaderElectionService's readCurrentLeader method instead of getCurrentLeader method. This ensures that the leader broker information is refreshed if it happens to be missing.
refactor existing code so that the asynchronous readCurrentLeader method can be used.

eolivelli

Are we adding load on the metadata service ?
With this patch during a restart of the whole cluster we are going to perform ad additional read from zk for every topic lookup in order to find the leader broker. is this correct ?

lhotari · 2022-08-24T07:29:33Z

Are we adding load on the metadata service ? With this patch during a restart of the whole cluster we are going to perform ad additional read from zk for every topic lookup in order to find the leader broker. is this correct ?

no. LeaderElectionService caches lookups. There won't be any additional load.

eolivelli

LGTM

this is a very long standing issue

lhotari · 2022-08-24T08:24:16Z

LGTM

this is a very long standing issue

I think I'll need to add some tests to ensure that the logic works. I did notice from the implementation that readCurrentLeader isn't a sufficient solution for resolving this issue. I added another commit to retry looking up the leader broker if there's no leader at the moment. I'll evolve this solution based on review feedback.

lhotari · 2022-08-24T08:54:13Z

I marked this as draft since the tests are still missing

eolivelli · 2022-08-24T13:33:37Z

+                .handle((leaderBroker, t) -> {
+                    CompletableFuture<Optional<LeaderBroker>> retval;
+                    if ((t != null || !leaderBroker.isPresent()) && retries.getAndIncrement() < 3) {
+                        // retry after a delay of 5 seconds


tracking this delay with a debugger or with a jstack dump is very hard.
maybe we should log something at INFO level
otherwise lookup operations will hang without any observable sign

I'll add some logging

eolivelli · 2022-08-24T13:34:20Z

+                        // retry after a delay of 5 seconds
+                        retval =
+                                CompletableFuture.supplyAsync(() -> null,
+                                                CompletableFuture.delayedExecutor(5, SECONDS))


which thread pool will run this execution ? (I guess it would be the system common pool)
should we use a well-known thread pool ?

it's not really a problem to use the system's pool for delayed executor. However, delayed executor isn't available in Java 8 and using this will make backporting harder. I'll use Pulsar's existing scheduler for this purpose so that backporting will be easier.

eolivelli · 2022-08-24T13:34:44Z

+                    }
+                    return retval;
+                })
+                .thenCompose(Function.identity());


why do we need this step ?

when using .handle that returns a CompletableFuture, it's necessary to "flatten" it with .thenCompose(Function.identity()).
This is a known gap in CompletableFuture API that there is no handleCompose method directly. (an stackoverflow answer explaining details, contains links to other answers) . Java 12+ contains .exceptionallyCompose, but no .handleCompose which is unfortunate.

…is lost and causes lookup issues - Fixes issue where leader broker information isn't available and this warning gets logged: "WARN org.apache.pulsar.broker.namespace.NamespaceService - The information about the current leader broker wasn't available. Handling load manager decisions in a decentralized way."

KannarFr · 2022-08-31T12:07:41Z

To be sure, could this issue result in 502 during topic creation? I just had this problem.

I had these logs on brokers:

Aug 31 07:30:40 test-pulsar-c2-n1 pulsar-broker[1956320]: 07:30:40.055 [pulsar-web-34-3] INFO org.eclipse.jetty.server.RequestLog - 192.168.11.6 - - [31/Aug/2022:07:30:40 +0000] "PUT /admin/v2/persistent/customtenant/customns/customtopic?authoritative=false HTTP/1.1" 307 0 "-" "Jetty/9.4.44.v20210927" 5
Aug 31 07:30:40 test-pulsar-c2-n1 pulsar-broker[1956320]: 07:30:40.066 [pulsar-2-4] WARN org.apache.pulsar.broker.namespace.NamespaceService - The information about the current leader broker wasn't available. Handling load manager decisions in a decentralized way. NamespaceBundle[customtenant/customns/0xc0000000_0xffffffff]
Aug 31 07:30:40 test-pulsar-c2-n1 pulsar-broker[1956320]: 07:30:40.068 [pulsar-web-34-9] INFO org.eclipse.jetty.server.RequestLog - 192.168.11.6 - - [31/Aug/2022:07:30:40 +0000] "PUT /admin/v2/persistent/customtenant/customns/customtopic?authoritative=false HTTP/1.1" 307 0 "-" "Jetty/9.4.44.v20210927" 4
Aug 31 07:30:40 test-pulsar-c2-n1 pulsar-broker[1956320]: 07:30:40.079 [pulsar-2-5] WARN org.apache.pulsar.broker.namespace.NamespaceService - The information about the current leader broker wasn't available. Handling load manager decisions in a decentralized way. NamespaceBundle[customtenant/customns/0xc0000000_0xffffffff]
Aug 31 07:30:40 test-pulsar-c2-n1 pulsar-broker[1956320]: 07:30:40.080 [pulsar-web-34-3] INFO org.eclipse.jetty.server.RequestLog - 192.168.11.6 - - [31/Aug/2022:07:30:40 +0000] "PUT /admin/v2/persistent/customtenant/customns/customtopic?authoritative=false HTTP/1.1" 307 0 "-" "Jetty/9.4.44.v20210927" 4
Aug 31 07:30:40 test-pulsar-c2-n1 pulsar-broker[1956320]: 07:30:40.090 [pulsar-2-13] WARN org.apache.pulsar.broker.namespace.NamespaceService - The information about the current leader broker wasn't available. Handling load manager decisions in a decentralized way. NamespaceBundle[customtenant/customns/0xc0000000_0xffffffff]
Aug 31 07:30:40 test-pulsar-c2-n1 pulsar-broker[1956320]: 07:30:40.092 [pulsar-web-34-9] INFO org.eclipse.jetty.server.RequestLog - 192.168.11.6 - - [31/Aug/2022:07:30:40 +0000] "PUT /admin/v2/persistent/customtenant/customns/customtopic?authoritative=false HTTP/1.1" 307 0 "-" "Jetty/9.4.44.v20210927" 4

Then nothing related to this customtopic even on another broker. And the response was HTTP 502.

lhotari · 2022-09-05T11:37:38Z

closing this in favour of #17401

lhotari added type/bug The PR fixed a bug or issue reported a bug area/broker doc-not-needed Your PR changes do not impact docs labels Aug 24, 2022

lhotari requested review from codelipenghui, eolivelli, merlimat and michaeljmarshall August 24, 2022 07:21

lhotari self-assigned this Aug 24, 2022

eolivelli reviewed Aug 24, 2022

View reviewed changes

eolivelli approved these changes Aug 24, 2022

View reviewed changes

lhotari marked this pull request as draft August 24, 2022 08:53

eolivelli requested changes Aug 24, 2022

View reviewed changes

lhotari added 5 commits August 25, 2022 12:24

Retry looking up current leader if it's missing

f7eeed7

Exponential backoff

af713da

Improve check - make sure that leader broker is active too

f4eab41

Checkstyle

b771d96

lhotari force-pushed the lh-fix-leaderbroker-missing-issue branch from 878c09b to b771d96 Compare August 25, 2022 11:20

lhotari mentioned this pull request Sep 1, 2022

[fix][broker] Fix issue where leader broker information isn't available after 10 minutes #17401

Merged

1 task

lhotari closed this Sep 5, 2022

congbobo184 mentioned this pull request Nov 9, 2022

[cherry-pick][branch-2.9] Fix issue where leader broker information isn't available after 10 minutes #18393

Closed

1 task

Uh oh!

Conversation

lhotari commented Aug 24, 2022

Motivation

Modifications

Uh oh!

eolivelli left a comment

Choose a reason for hiding this comment

Uh oh!

lhotari commented Aug 24, 2022

Uh oh!

eolivelli left a comment

Choose a reason for hiding this comment

Uh oh!

lhotari commented Aug 24, 2022

Uh oh!

lhotari commented Aug 24, 2022

Uh oh!

eolivelli Aug 24, 2022

Choose a reason for hiding this comment

Uh oh!

lhotari Aug 25, 2022

Choose a reason for hiding this comment

Uh oh!

eolivelli Aug 24, 2022

Choose a reason for hiding this comment

Uh oh!

lhotari Aug 25, 2022

Choose a reason for hiding this comment

Uh oh!

eolivelli Aug 24, 2022

Choose a reason for hiding this comment

Uh oh!

lhotari Aug 25, 2022

Choose a reason for hiding this comment

Uh oh!

KannarFr commented Aug 31, 2022

Uh oh!

lhotari commented Sep 5, 2022

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

3 participants