[fix][broker] Fix the broker shutdown issue after Zookeeper node crashed #17909
Conversation
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
### Motivation [fix][broker] Fix the broker shutdown issue after the Zookeeper node crashed ### Motivation The broker was shutdown unexpectedly after the Zookeeper node crashed. I have a test to kill the zookeeper node periodically, sometimes the following logs will appear ``` Sep 30 12:21:33 ip-10-0-0-160.us-west-2.compute.internal pulsar[21529]: 2022-09-30T12:21:33,214+0000 [metadata-store-zk-session-watcher-7-1] WARN org.apache.pulsar.metadata.impl.ZKSessionWatcher - ZooKeeper client is disconnected. Waiting to reconnect, time remaining = 22.245 seconds Sep 30 12:21:35 ip-10-0-0-160.us-west-2.compute.internal pulsar[21529]: 2022-09-30T12:21:35,214+0000 [metadata-store-zk-session-watcher-7-1] WARN org.apache.pulsar.metadata.impl.ZKSessionWatcher - ZooKeeper client is disconnected. Waiting to reconnect, time remaining = 20.245 seconds Sep 30 12:21:37 ip-10-0-0-160.us-west-2.compute.internal pulsar[21529]: 2022-09-30T12:21:37,214+0000 [metadata-store-zk-session-watcher-7-1] WARN org.apache.pulsar.metadata.impl.ZKSessionWatcher - ZooKeeper client is disconnected. Waiting to reconnect, time remaining = 18.244 seconds Sep 30 12:21:37 ip-10-0-0-160.us-west-2.compute.internal pulsar[21529]: 2022-09-30T12:21:37,523+0000 [pulsar-web-36-43] INFO org.eclipse.jetty.server.RequestLog - 10.0.0.54 - - [30/Sep/2022:12:21:37 +0000] "GET /metrics HTTP/1.1" 302 0 "-" "Prometheus/2.31.1" 0 Sep 30 12:21:37 ip-10-0-0-160.us-west-2.compute.internal pulsar[21529]: 2022-09-30T12:21:37,526+0000 [prometheus-stats-37-1] INFO org.eclipse.jetty.server.RequestLog - 10.0.0.54 - - [30/Sep/2022:12:21:37 +0000] "GET /metrics/ HTTP/1.1" 200 21383 "http://10.0.0.160:8080/metrics" "Prometheus/2.31.1" 2 Sep 30 12:21:39 ip-10-0-0-160.us-west-2.compute.internal pulsar[21529]: 2022-09-30T12:21:39,214+0000 [metadata-store-zk-session-watcher-7-1] WARN org.apache.pulsar.metadata.impl.ZKSessionWatcher - ZooKeeper client is disconnected. Waiting to reconnect, time remaining = 16.244 seconds Sep 30 12:21:41 ip-10-0-0-160.us-west-2.compute.internal pulsar[21529]: 2022-09-30T12:21:41,214+0000 [metadata-store-zk-session-watcher-7-1] WARN org.apache.pulsar.metadata.impl.ZKSessionWatcher - ZooKeeper client is disconnected. Waiting to reconnect, time remaining = 14.244 seconds Sep 30 12:21:43 ip-10-0-0-160.us-west-2.compute.internal pulsar[21529]: 2022-09-30T12:21:43,215+0000 [metadata-store-zk-session-watcher-7-1] WARN org.apache.pulsar.metadata.impl.ZKSessionWatcher - ZooKeeper client is disconnected. Waiting to reconnect, time remaining = 12.244 seconds Sep 30 12:21:45 ip-10-0-0-160.us-west-2.compute.internal pulsar[21529]: 2022-09-30T12:21:45,215+0000 [metadata-store-zk-session-watcher-7-1] WARN org.apache.pulsar.metadata.impl.ZKSessionWatcher - ZooKeeper client is disconnected. Waiting to reconnect, time remaining = 10.243 seconds Sep 30 12:21:47 ip-10-0-0-160.us-west-2.compute.internal pulsar[21529]: 2022-09-30T12:21:47,215+0000 [metadata-store-zk-session-watcher-7-1] WARN org.apache.pulsar.metadata.impl.ZKSessionWatcher - ZooKeeper client is disconnected. Waiting to reconnect, time remaining = 8.243 seconds Sep 30 12:21:47 ip-10-0-0-160.us-west-2.compute.internal pulsar[21529]: 2022-09-30T12:21:47,523+0000 [pulsar-web-36-43] INFO org.eclipse.jetty.server.RequestLog - 10.0.0.54 - - [30/Sep/2022:12:21:47 +0000] "GET /metrics HTTP/1.1" 302 0 "-" "Prometheus/2.31.1" 0 Sep 30 12:21:47 ip-10-0-0-160.us-west-2.compute.internal pulsar[21529]: 2022-09-30T12:21:47,526+0000 [prometheus-stats-37-1] INFO org.eclipse.jetty.server.RequestLog - 10.0.0.54 - - [30/Sep/2022:12:21:47 +0000] "GET /metrics/ HTTP/1.1" 200 21383 "http://10.0.0.160:8080/metrics" "Prometheus/2.31.1" 2 Sep 30 12:21:49 ip-10-0-0-160.us-west-2.compute.internal pulsar[21529]: 2022-09-30T12:21:49,215+0000 [metadata-store-zk-session-watcher-7-1] WARN org.apache.pulsar.metadata.impl.ZKSessionWatcher - ZooKeeper client is disconnected. Waiting to reconnect, time remaining = 6.243 seconds Sep 30 12:21:51 ip-10-0-0-160.us-west-2.compute.internal pulsar[21529]: 2022-09-30T12:21:51,216+0000 [metadata-store-zk-session-watcher-7-1] WARN org.apache.pulsar.metadata.impl.ZKSessionWatcher - ZooKeeper client is disconnected. Waiting to reconnect, time remaining = 4.243 seconds Sep 30 12:21:53 ip-10-0-0-160.us-west-2.compute.internal pulsar[21529]: 2022-09-30T12:21:53,216+0000 [metadata-store-zk-session-watcher-7-1] WARN org.apache.pulsar.metadata.impl.ZKSessionWatcher - ZooKeeper client is disconnected. Waiting to reconnect, time remaining = 2.243 seconds Sep 30 12:21:55 ip-10-0-0-160.us-west-2.compute.internal pulsar[21529]: 2022-09-30T12:21:55,216+0000 [metadata-store-zk-session-watcher-7-1] WARN org.apache.pulsar.metadata.impl.ZKSessionWatcher - ZooKeeper client is disconnected. Waiting to reconnect, time remaining = 0.242 seconds Sep 30 12:21:57 ip-10-0-0-160.us-west-2.compute.internal pulsar[21529]: 2022-09-30T12:21:57,216+0000 [metadata-store-zk-session-watcher-7-1] ERROR org.apache.pulsar.metadata.impl.ZKSessionWatcher - ZooKeeper session reconnection timeout. Notifying session is lost. Sep 30 12:21:57 ip-10-0-0-160.us-west-2.compute.internal pulsar[21529]: 2022-09-30T12:21:57,216+0000 [metadata-store-zk-session-watcher-7-1] INFO org.apache.pulsar.broker.PulsarService - Received metadata service session event: SessionLost Sep 30 12:21:57 ip-10-0-0-160.us-west-2.compute.internal pulsar[21529]: 2022-09-30T12:21:57,216+0000 [metadata-store-zk-session-watcher-7-1] WARN org.apache.pulsar.broker.PulsarService - The session with metadata service was lost. Shutting down. Sep 30 12:21:57 ip-10-0-0-160.us-west-2.compute.internal pulsar[21529]: 2022-09-30T12:21:57,216+0000 [metadata-store-zk-session-watcher-7-1] INFO org.apache.pulsar.broker.PulsarService - Invoking Pulsar service immediate shutdown Sep 30 12:21:57 ip-10-0-0-160.us-west-2.compute.internal pulsar[21529]: 2022-09-30T12:21:57,323+0000 [metadata-store-zk-session-watcher-7-1] INFO org.apache.zookeeper.ZooKeeper - Session: 0xcc55e0015 closed Sep 30 12:21:57 ip-10-0-0-160.us-west-2.compute.internal pulsar[21529]: 2022-09-30T12:21:57,324+0000 [metadata-store-zk-session-watcher-7-1] WARN org.apache.pulsar.broker.PulsarService - Failed to close metadata service session: null Sep 30 12:21:57 ip-10-0-0-160.us-west-2.compute.internal pulsar[21529]: 2022-09-30T12:21:57,324+0000 [metadata-store-zk-session-watcher-7-1] INFO org.apache.pulsar.PulsarBrokerStarter - Halting broker process with code -1 ``` Then I try to make the thread dump when the broker performing the `Waiting to reconnect` ``` ``` "main-EventThread" apache#27 daemon prio=5 os_prio=0 cpu=126.35ms elapsed=1369.57s tid=0x00007f453d65d1a0 nid=0x1c3df waiting for monitor entry [0x00007f429da8a000] java.lang.Thread.State: BLOCKED (on object monitor) at org.apache.pulsar.metadata.impl.ZKSessionWatcher.process(ZKSessionWatcher.java:123) - waiting to lock <0x0000100007c41a30> (a org.apache.pulsar.metadata.impl.ZKSessionWatcher) at org.apache.pulsar.metadata.impl.ZKMetadataStore.lambda$null$0(ZKMetadataStore.java:78) at org.apache.pulsar.metadata.impl.ZKMetadataStore$$Lambda$546/0x000000080111e888.accept(Unknown Source) at java.util.Optional.ifPresent([email protected]/Optional.java:178) at org.apache.pulsar.metadata.impl.ZKMetadataStore.lambda$new$1(ZKMetadataStore.java:78) at org.apache.pulsar.metadata.impl.ZKMetadataStore$$Lambda$124/0x0000000800e29478.process(Unknown Source) at org.apache.bookkeeper.zookeeper.ZooKeeperWatcherBase.notifyEvent(ZooKeeperWatcherBase.java:180) at org.apache.bookkeeper.zookeeper.ZooKeeperWatcherBase.process(ZooKeeperWatcherBase.java:146) at org.apache.zookeeper.ClientCnxn$EventThread.processEvent(ClientCnxn.java:588) at org.apache.zookeeper.ClientCnxn$EventThread.run(ClientCnxn.java:563) Locked ownable synchronizers: - None "metadata-store-zk-session-watcher-7-1" apache#28 prio=5 os_prio=0 cpu=36.92ms elapsed=1369.54s tid=0x00007f453d665b60 nid=0x1c3e0 waiting on condition [0x00007f429d786000] java.lang.Thread.State: TIMED_WAITING (parking) at jdk.internal.misc.Unsafe.park([email protected]/Native Method) - parking to wait for <0x0000100029e10418> (a java.util.concurrent.CompletableFuture$Signaller) at java.util.concurrent.locks.LockSupport.parkNanos([email protected]/LockSupport.java:252) at java.util.concurrent.CompletableFuture$Signaller.block([email protected]/CompletableFuture.java:1866) at java.util.concurrent.ForkJoinPool.unmanagedBlock([email protected]/ForkJoinPool.java:3463) at java.util.concurrent.ForkJoinPool.managedBlock([email protected]/ForkJoinPool.java:3434) at java.util.concurrent.CompletableFuture.timedGet([email protected]/CompletableFuture.java:1939) at java.util.concurrent.CompletableFuture.get([email protected]/CompletableFuture.java:2095) at org.apache.pulsar.metadata.impl.ZKSessionWatcher.checkConnectionStatus(ZKSessionWatcher.java:107) - locked <0x0000100007c41a30> (a org.apache.pulsar.metadata.impl.ZKSessionWatcher) at org.apache.pulsar.metadata.impl.ZKSessionWatcher$$Lambda$129/0x0000000800e36598.run(Unknown Source) at org.apache.pulsar.common.util.Runnables$CatchingAndLoggingRunnable.run(Runnables.java:53) at java.util.concurrent.Executors$RunnableAdapter.call([email protected]/Executors.java:539) at java.util.concurrent.FutureTask.runAndReset([email protected]/FutureTask.java:305) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run([email protected]/ScheduledThreadPoolExecutor.java:305) at java.util.concurrent.ThreadPoolExecutor.runWorker([email protected]/ThreadPoolExecutor.java:1136) at java.util.concurrent.ThreadPoolExecutor$Worker.run([email protected]/ThreadPoolExecutor.java:635) at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) at java.lang.Thread.run([email protected]/Unknown Source) ``` It's a deadlock issue happened on the broker side. ### Modification As apache#17638, process the session event in separated thread to avoid the deadlock ### Verification The test continues running 6 hours, I don't see the issue happens again. Without this fix, the problem will happen in 10 min during the test.
codelipenghui
added
type/bug
nodece
approved these changes
Oct 1, 2022
lhotari
approved these changes
Oct 1, 2022
merlimat
approved these changes
Oct 1, 2022
dlg99
pushed a commit
to dlg99/pulsar
that referenced
this pull request
Oct 3, 2022
…hed (apache#17909) (cherry picked from commit e26060a)
nicoloboschi
pushed a commit
to datastax/pulsar
that referenced
this pull request
Oct 4, 2022
…hed (apache#17909) (cherry picked from commit e26060a)
sajithsebastian
pushed a commit
to sajithsebastian/pulsar
that referenced
this pull request
Oct 30, 2022
…hed (apache#17909) (cherry picked from commit e26060a)
2 tasks
codelipenghui
added
cherry-picked/branch-2.9
SumangalaRao
pushed a commit
to SumangalaRao/pulsar
that referenced
this pull request
Aug 23, 2023
…hed (apache#17909) (cherry picked from commit e26060a)
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.
This suggestion is invalid because no changes were made to the code.
Suggestions cannot be applied while the pull request is closed.
Suggestions cannot be applied while viewing a subset of changes.
Only one suggestion per line can be applied in a batch.
Add this suggestion to a batch that can be applied as a single commit.
Applying suggestions on deleted lines is not supported.
You must change the existing code in this line in order to create a valid suggestion.
Outdated suggestions cannot be applied.
This suggestion has been applied or marked resolved.
Suggestions cannot be applied from pending reviews.
Suggestions cannot be applied on multi-line comments.
Suggestions cannot be applied while the pull request is queued to merge.
Suggestion cannot be applied right now. Please check back later.
Motivation
[fix][broker] Fix the broker shutdown issue after the Zookeeper node crashed
Motivation
The broker was shutdown unexpectedly after the Zookeeper node crashed. I have a test to kill the zookeeper node periodically, sometimes the following logs will appear
Then I try to make the thread dump when the broker performing the
Waiting to reconnectIt's a deadlock issue happened on the broker side.
Modification
As #17638, process the session event in separated thread to avoid the deadlock
Verification
The test continues running 6 hours, I don't see the issue happens again. Without this fix, the problem will happen in 10 min during the
test.
Does this pull request potentially affect one of the following parts:
If the box was checked, please highlight the changes
Documentation
doc-required(Your PR needs to update docs and you will update later)
doc-not-needed(Please explain why)
doc(Your PR contains doc changes)
doc-complete(Docs have been already added)
Matching PR in forked repository
PR in forked repository: codelipenghui#15