Skip to content

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

Merged
lhotari merged 7 commits into
apache:masterfrom
lhotari:lh-leaderelection-should-not-expire
Sep 8, 2022
Merged

[fix][broker] Fix issue where leader broker information isn't available after 10 minutes#17401
lhotari merged 7 commits into
apache:masterfrom
lhotari:lh-leaderelection-should-not-expire

Conversation

@lhotari

@lhotari lhotari commented Sep 1, 2022

Copy link
Copy Markdown
Member

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.

  • Possibly fixing:

The root cause of the problem is that currently leader election cache entries expire in 10 minutes. Entries are refreshed when there's a cache hit between 5 to 10 minutes after the entry was added to the cache or refreshed the last time. This expiration behavior cannot be configured currently in MetadataCache.

Modifications

Since leader election cache expiration leads to problems, it is better to disable expiration completely for leader election entries. The cache entry refreshing is not changed so a missed Zookeeper change notification won't cause the cache to serve stale values.

  • change MetadataStore
    • add support passing cache configuration for a MetadataCache so that expiration can be disabled for leader election cache
  • revisit expiration logic in LeaderElectionImpl. Use cache.refresh instead of removing entries from the cache.
  • schedule a call to refresh the cached entry to mitigate possible stale values

Additional context

- cache expiration leads to problems and it is better to serve a stale entry than to ever expire the
  entry
- MetadataStore didn't support passing cache configuration for a MetadataCache, it
  was necessary to modify the interface to support that.

@eolivelli eolivelli left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

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

LGTM

I have left one question, but I don't think we can change the code in spite of any answers to my question

@github-actions

github-actions Bot commented Sep 1, 2022

Copy link
Copy Markdown

@lhotari Please provide a correct documentation label for your PR.
Instructions see Pulsar Documentation Label Guide.

@nicoloboschi nicoloboschi left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

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

LGTM, just a comment

@dlg99 dlg99 left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

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

LGTM (no explicit approval as I am not familiar with this enough).
I think the PR could benefit from a test case that reproes the problem to catch regressions.

@lhotari lhotari changed the title [fix][broker] Fix issue where leader broker information isn't available after 10 minutes of idling [fix][broker] Fix issue where leader broker information isn't available after 10 minutes Sep 5, 2022
@github-actions github-actions Bot added doc-not-needed Your PR changes do not impact docs and removed doc-label-missing labels Sep 5, 2022

@michaeljmarshall michaeljmarshall left a comment

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

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

Overall, LGTM.

I agree that in the steady state, it makes sense not to expire the leader broker value from the cache given that the leader should not change all that frequently. The refreshAfter logic will ensure that a broker eventually gets the current value, in the case where notifications are somehow missed.

In reviewing your PR, I am seeing additional complexity for leader election that I'd like to discuss. I see two cases where a broker needs to go through the leader election logic.

  1. Broker is starting up and there is no value for /loadbalance/leader in the metadata store.
  2. The node for /loadbalance/leader is deleted and the broker gets a notification. (With ZK, this happens any time the leader broker's session terminates.)

In both cases, the real value for /loadbalance/leader is temporarily None and therefore it is likely a legitimate time for decentralized load balancing decisions. In case 1, the cached value is None so there is no other option. In case 2, the cached value is the previous leader broker, which likely just crashed or shutdown. Serving the stale value in case 2 could lead to connection related issues because the client will get a redirect to a broker that is likely no longer running. As such, it seems like we might want to consider invalidating the cache when the leader's node is deleted.

If our goal is to prevent decentralized load balancing decisions, we could consider queuing requests during leader election and then either respond with the leader once elected or time out. The biggest issue with queuing these requests is that a broker that is slow to get the ZK update could increase the overall latency for topic discovery. Queuing these requests also adds more complexity and increases the latency for loading topics. Also, it's not clear to me that a new leader will make a "better" load balancing decision than the local broker, which would be the whole reason to wait for the new leader.

On the other hand, we could accept that it's valid to make decentralized decisions during leader election, and then we just need to make sure that certain race conditions are gracefully handled. As long as we make sure that a broker failing to acquire the lock on a bundle is not a fatal error sent back to a client, the risk of "bad" decentralized load balancing decisions is much lower.

My preference is the latter.

Comment on lines +90 to +92
updateCachedValueFuture = executor.scheduleWithFixedDelay(SafeRunnable.safeRun(this::getLeaderValue),
metadataCacheConfig.getRefreshAfterWriteMillis() / 2,
metadataCacheConfig.getRefreshAfterWriteMillis(), TimeUnit.MILLISECONDS);

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

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

A call to getLeaderValueIfPresent will asynchronously trigger the refreshAfter logic in the loading cache. Is there a reason it is insufficient to rely on those calls?

Copy link
Copy Markdown
Member Author

Choose a reason for hiding this comment

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

yes, since with refreshAfter, the first call gets a stale value. This prevents that. I made this changed based on the Pulsar community meeting discussion where Matteo was explaining the reasons for the previous expiration logic.

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

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

My main thought is that with this loop, it's technically not necessary to remove the expiration logic from the cache because we're artificially keeping the value in the cache here. It's going to run pretty infrequently, so I don't think it's necessary to change it, but it does seem like an indirect way to handle the potential for "missed zk notifications".

Comment on lines -210 to -214
// We force the invalidation of the cache entry. Since we received a BadVersion error, we
// already know that the entry is out of date. If we don't invalidate, we'd be retrying the
// leader election many times until we finally receive the notification that invalidates the
// cache.
cache.invalidate(path);

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

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

If we don't invalidate the value here, I think we are at risk of recursively retrying to acquire the lock just as the comment indicates because when the cached value is None and the actual value is another broker, this broker will keep getting BadVersionException without completing any of the result objects.

This might be a place where the implementation in #17254 is better because an empty cache results in a read to the metadata store. I am wondering if its worth using both PRs in order to decrease certain edge cases during leader election where the current broker doesn't know the real leader.

Copy link
Copy Markdown
Member Author

Choose a reason for hiding this comment

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

This is taken care of in elect method. It uses store.get and by-passes the cache. There's cache.refresh(path); to invalidate the stale value.

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

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

The elect() method only calls cache.refresh(path); after a callback from this method (handleExistingLeaderValue()) is completed, and if we don't invalidate the cache, I think we'll recursively call handleExistingLeaderValue() as the comment indicates because store.get(path) will return a non empty result.

Copy link
Copy Markdown
Member Author

Choose a reason for hiding this comment

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

It's sufficient to call cache.refresh(path) after the election has been completed.
The cached value is not used in any away in the leader election code path. That's why I don't think it would make any difference. cache.get is currently called in tryToBecomeLeader, but that seems unnecessary and should be removed.

@lhotari
lhotari merged commit 774c50b into apache:master Sep 8, 2022
lhotari added a commit to datastax/pulsar that referenced this pull request Sep 9, 2022
…le after 10 minutes (apache#17401)

* [fix][broker] Leader election cache should not invalidate entries

- cache expiration leads to problems and it is better to serve a stale entry than to ever expire the
  entry
- MetadataStore didn't support passing cache configuration for a MetadataCache, it
  was necessary to modify the interface to support that.

* Add test case

* Prevent stale values in leader election cache

Co-authored-by: Enrico Olivelli <eolivelli@apache.org>
(cherry picked from commit 774c50b)
@mattisonchao

Copy link
Copy Markdown
Member

Hello @lhotari
It looks like we got many conflicts when cherry-picking it to branch-2.9.
Would you mind helping cherry-pick to branch-2.9? (To avoid cherry-picking involving bugs)

lhotari added a commit that referenced this pull request Oct 18, 2022
…le after 10 minutes (#17401)

* [fix][broker] Leader election cache should not invalidate entries

- cache expiration leads to problems and it is better to serve a stale entry than to ever expire the
  entry
- MetadataStore didn't support passing cache configuration for a MetadataCache, it
  was necessary to modify the interface to support that.

* Add test case

* Prevent stale values in leader election cache

Co-authored-by: Enrico Olivelli <eolivelli@apache.org>
(cherry picked from commit 774c50b)
lhotari added a commit that referenced this pull request Oct 18, 2022
…le after 10 minutes (#17401)

* [fix][broker] Leader election cache should not invalidate entries

- cache expiration leads to problems and it is better to serve a stale entry than to ever expire the
  entry
- MetadataStore didn't support passing cache configuration for a MetadataCache, it
  was necessary to modify the interface to support that.

* Add test case

* Prevent stale values in leader election cache

Co-authored-by: Enrico Olivelli <eolivelli@apache.org>
(cherry picked from commit 774c50b)
@srivatsav

Copy link
Copy Markdown

@lhotari here are the stack traces of both the errors

Pulsar Version - 2.9.2

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.


2022-11-08T09:54:38,651+0000 [pulsar-web-38-4] WARN  org.apache.pulsar.broker.admin.impl.NamespacesBase - [null] Failed to create namespace ALGRUS/JobSync - already exists
2022-11-08T09:54:38,651+0000 [bookkeeper-ml-scheduler-OrderedScheduler-0-0] INFO  org.apache.pulsar.broker.service.persistent.PersistentSubscription - [persistent://TQL1US/JobSync/jobevents-ack-partition-0][flink-pulsar-dd2186ba-8355-4536-aaa2-056d7bae6dda] Successfully disconnected consumers from subscription, proceeding with cursor reset
2022-11-08T09:54:38,651+0000 [bookkeeper-ml-scheduler-OrderedScheduler-0-0] INFO  org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl - [TQL1US/JobSync/persistent/jobevents-ack-partition-0] Opened new cursor: ManagedCursorImpl{ledger=TQL1US/JobSync/persistent/jobevents-ack-partition-0, name=flink-pulsar-dd2186ba-8355-4536-aaa2-056d7bae6dda, ackPos=3504667:-1, readPos=3504667:0}
2022-11-08T09:54:38,651+0000 [bookkeeper-ml-scheduler-OrderedScheduler-0-0] INFO  org.apache.bookkeeper.mledger.impl.ManagedCursorImpl - [TQL1US/JobSync/persistent/jobevents-ack-partition-0] Updated cursor flink-pulsar-dd2186ba-8355-4536-aaa2-056d7bae6dda with ledger id 3509778 md-position=3504667:-1 rd-position=3504667:0
2022-11-08T09:54:38,649+0000 [pulsar-2-1] 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[ASCAUS/JobSync/0x00000000_0x40000000]
2022-11-08T09:54:38,649+0000 [pulsar-2-2] 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[AEROUS/JobSync/0xc0000000_0xffffffff]

WARN Failed to acquire ownership for namespace bundle

	... 7 more
	at java.util.concurrent.CompletableFuture$UniCompose.tryFire(CompletableFuture.java:1072) ~[?:?]
	at org.apache.pulsar.metadata.coordination.impl.ResourceLockImpl.lambda$doRevalidate$20(ResourceLockImpl.java:297) ~[org.apache.pulsar-pulsar-metadata-2.9.2.jar:2.9.2]
Caused by: org.apache.pulsar.metadata.api.MetadataStoreException$LockBusyException: Resource at /namespace/CACIGLOBAL/JobSync/0x00000000_0x40000000 is already locked
	... 17 more
	at java.util.concurrent.CompletableFuture$UniApply.tryFire(CompletableFuture.java:632) ~[?:?]
	at java.util.concurrent.CompletableFuture.completeThrowable(CompletableFuture.java:346) ~[?:?]
	at java.util.concurrent.CompletableFuture.encodeThrowable(CompletableFuture.java:331) ~[?:?]
Caused by: java.util.concurrent.CompletionException: org.apache.pulsar.metadata.api.MetadataStoreException$LockBusyException: Resource at /namespace/CACIGLOBAL/JobSync/0x00000000_0x40000000 is already locked
	... 20 more
Caused by: org.apache.pulsar.broker.PulsarServerException: Failed to acquire ownership for namespace bundle CACIGLOBAL/JobSync/0x00000000_0x40000000
	at java.lang.Thread.run(Thread.java:829) [?:?]
	at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) [io.netty-netty-common-4.1.74.Final.jar:4.1.74.Final]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
	at org.apache.pulsar.metadata.impl.ZKMetadataStore.lambda$get$7(ZKMetadataStore.java:139) ~[org.apache.pulsar-pulsar-metadata-2.9.2.jar:2.9.2]
	at java.util.concurrent.CompletableFuture.complete(CompletableFuture.java:2073) ~[?:?]
	at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:506) ~[?:?]
	at java.util.concurrent.CompletableFuture$UniExceptionally.tryFire(CompletableFuture.java:970) ~[?:?]
	at java.util.concurrent.CompletableFuture.uniExceptionally(CompletableFuture.java:986) ~[?:?]
	at org.apache.pulsar.metadata.coordination.impl.ResourceLockImpl.lambda$acquire$4(ResourceLockImpl.java:134) ~[org.apache.pulsar-pulsar-metadata-2.9.2.jar:2.9.2]
	at java.util.concurrent.CompletableFuture.completeExceptionally(CompletableFuture.java:2088) ~[?:?]
	at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:506) ~[?:?]
	at java.util.concurrent.CompletableFuture$UniExceptionally.tryFire(CompletableFuture.java:970) ~[?:?]
	at java.util.concurrent.CompletableFuture.uniExceptionally(CompletableFuture.java:986) ~[?:?]
	at org.apache.pulsar.metadata.coordination.impl.LockManagerImpl.lambda$acquireLock$2(LockManagerImpl.java:111) ~[org.apache.pulsar-pulsar-metadata-2.9.2.jar:2.9.2]
	at java.util.concurrent.CompletableFuture.completeExceptionally(CompletableFuture.java:2088) ~[?:?]
	at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:506) ~[?:?]
	at java.util.concurrent.CompletableFuture$UniExceptionally.tryFire(CompletableFuture.java:970) ~[?:?]
	at java.util.concurrent.CompletableFuture.uniExceptionally(CompletableFuture.java:986) ~[?:?]
	at org.apache.pulsar.broker.namespace.NamespaceService.lambda$searchForCandidateBroker$15(NamespaceService.java:578) ~[org.apache.pulsar-pulsar-broker-2.9.2.jar:2.9.2]
	at java.util.concurrent.CompletableFuture.completeExceptionally(CompletableFuture.java:2088) ~[?:?]
	at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:506) ~[?:?]
	at java.util.concurrent.CompletableFuture$UniRelay.tryFire(CompletableFuture.java:1019) ~[?:?]
	at java.util.concurrent.CompletableFuture.completeRelay(CompletableFuture.java:376) ~[?:?]
	at java.util.concurrent.CompletableFuture.encodeRelay(CompletableFuture.java:367) ~[?:?]
java.util.concurrent.CompletionException: org.apache.pulsar.broker.PulsarServerException: Failed to acquire ownership for namespace bundle CACIGLOBAL/JobSync/0x00000000_0x40000000

congbobo184 pushed a commit to congbobo184/pulsar that referenced this pull request Nov 9, 2022
lhotari added a commit that referenced this pull request Nov 9, 2022
…le after 10 minutes (#17401)

* [fix][broker] Leader election cache should not invalidate entries

- cache expiration leads to problems and it is better to serve a stale entry than to ever expire the
  entry
- MetadataStore didn't support passing cache configuration for a MetadataCache, it
  was necessary to modify the interface to support that.

* Add test case

* Prevent stale values in leader election cache

Co-authored-by: Enrico Olivelli <eolivelli@apache.org>
(cherry picked from commit 774c50b)

# Conflicts:
#	pulsar-metadata/src/main/java/org/apache/pulsar/metadata/cache/impl/MetadataCacheImpl.java
#	pulsar-metadata/src/main/java/org/apache/pulsar/metadata/coordination/impl/LeaderElectionImpl.java
#	pulsar-metadata/src/main/java/org/apache/pulsar/metadata/impl/AbstractMetadataStore.java
(cherry picked from commit cd731f451cb80e21cadf732ad3e39ee98b87bd45)
@lhotari lhotari added the cherry-picked/branch-2.9 Archived: 2.9 is end of life label Nov 9, 2022
congbobo184 pushed a commit that referenced this pull request Nov 30, 2022
…le after 10 minutes (#17401)

* [fix][broker] Leader election cache should not invalidate entries

- cache expiration leads to problems and it is better to serve a stale entry than to ever expire the
  entry
- MetadataStore didn't support passing cache configuration for a MetadataCache, it
  was necessary to modify the interface to support that.

* Add test case

* Prevent stale values in leader election cache

Co-authored-by: Enrico Olivelli <eolivelli@apache.org>
(cherry picked from commit 774c50b)
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Projects

None yet

Development

Successfully merging this pull request may close these issues.

7 participants