Skip to content

Broker often shutdown after using KoP #16140

New issue
New issue
Closed as not planned
Closed as not planned
Broker often shutdown after using KoP#16140
Labels
Staletype/bugThe PR fixed a bug or issue reported a bug
@zbye

Description

@zbye
zbye
opened on Jun 20, 2022

Describe the bug

One Broker shutdown with the following logs :

2022-06-17T13:27:16,824+0800 [main-SendThread(10.187.128.229:2181)] WARN org.apache.pulsar.broker.service.persistent.PersistentTopic - [persistent://gmtp_cffex/SF_test/bar] Failed to persist msg in store: Error while using ZooKeeper
2022-06-17T13:27:16,824+0800 [main-SendThread(10.187.128.229:2181)] WARN org.apache.pulsar.broker.service.persistent.PersistentTopic - [persistent://gmtp_cffex/SF_test/bar] Failed to persist msg in store: Error while using ZooKeeper
2022-06-17T13:27:16,824+0800 [main-SendThread(10.187.128.229:2181)] WARN org.apache.pulsar.broker.service.persistent.PersistentTopic - [persistent://gmtp_cffex/SF_test/bar] Failed to persist msg in store: Error while using ZooKeeper
2022-06-17T13:27:16,824+0800 [main-SendThread(10.187.128.229:2181)] WARN org.apache.pulsar.broker.service.persistent.PersistentTopic - [persistent://gmtp_cffex/SF_test/bar] Failed to persist msg in store: Error while using ZooKeeper
2022-06-17T13:27:16,824+0800 [main-SendThread(10.187.128.229:2181)] WARN org.apache.pulsar.broker.service.persistent.PersistentTopic - [persistent://gmtp_cffex/SF_test/bar] Failed to persist msg in store: Error while using ZooKeeper
2022-06-17T13:27:16,824+0800 [main-SendThread(10.187.128.229:2181)] WARN org.apache.pulsar.broker.service.persistent.PersistentTopic - [persistent://gmtp_cffex/SF_test/bar] Failed to persist msg in store: Error while using ZooKeeper
2022-06-17T13:27:16,824+0800 [main-SendThread(10.187.128.229:2181)] WARN org.apache.pulsar.broker.service.persistent.PersistentTopic - [persistent://gmtp_cffex/SF_test/bar] Failed to persist msg in store: Error while using ZooKeeper
2022-06-17T13:27:16,824+0800 [main-SendThread(10.187.128.229:2181)] WARN org.apache.pulsar.broker.service.persistent.PersistentTopic - [persistent://gmtp_cffex/SF_test/bar] Failed to persist msg in store: Error while using ZooKeeper
2022-06-17T13:27:16,824+0800 [main-SendThread(10.187.128.229:2181)] WARN org.apache.pulsar.broker.service.persistent.PersistentTopic - [persistent://gmtp_cffex/SF_test/bar] Failed to persist msg in store: Error while using ZooKeeper
2022-06-17T13:27:16,824+0800 [main-SendThread(10.187.128.229:2181)] WARN org.apache.pulsar.broker.service.persistent.PersistentTopic - [persistent://gmtp_cffex/SF_test/bar] Failed to persist msg in store: Error while using ZooKeeper
2022-06-17T13:27:16,824+0800 [main-SendThread(10.187.128.229:2181)] WARN org.apache.pulsar.broker.service.persistent.PersistentTopic - [persistent://gmtp_cffex/SF_test/bar] Failed to persist msg in store: Error while using ZooKeeper
2022-06-17T13:27:16,824+0800 [main-SendThread(10.187.128.229:2181)] WARN org.apache.pulsar.broker.service.persistent.PersistentTopic - [persistent://gmtp_cffex/SF_test/bar] Failed to persist msg in store: Error while using ZooKeeper
2022-06-17T13:27:16,824+0800 [main-SendThread(10.187.128.229:2181)] WARN org.apache.pulsar.broker.service.persistent.PersistentTopic - [persistent://gmtp_cffex/SF_test/bar] Failed to persist msg in store: Error while using ZooKeeper
2022-06-17T13:27:16,824+0800 [main-SendThread(10.187.128.229:2181)] WARN org.apache.pulsar.broker.service.persistent.PersistentTopic - [persistent://gmtp_cffex/SF_test/bar] Failed to persist msg in store: Error while using ZooKeeper
2022-06-17T13:27:16,824+0800 [main-SendThread(10.187.128.229:2181)] WARN org.apache.pulsar.broker.service.persistent.PersistentTopic - [persistent://gmtp_cffex/SF_test/bar] Failed to persist msg in store: Error while using ZooKeeper
2022-06-17T13:27:16,824+0800 [main-SendThread(10.187.128.229:2181)] WARN org.apache.pulsar.broker.service.persistent.PersistentTopic - [persistent://gmtp_cffex/SF_test/bar] Failed to persist msg in store: Error while using ZooKeeper
2022-06-17T13:27:16,824+0800 [main-SendThread(10.187.128.229:2181)] WARN org.apache.pulsar.broker.service.persistent.PersistentTopic - [persistent://gmtp_cffex/SF_test/bar] Failed to persist msg in store: Error while using ZooKeeper
2022-06-17T13:27:16,824+0800 [main-SendThread(10.187.128.229:2181)] WARN org.apache.pulsar.broker.service.persistent.PersistentTopic - [persistent://gmtp_cffex/SF_test/bar] Failed to persist msg in store: Error while using ZooKeeper
2022-06-17T13:27:16,824+0800 [main-SendThread(10.187.128.229:2181)] WARN org.apache.pulsar.broker.service.persistent.PersistentTopic - [persistent://gmtp_cffex/SF_test/bar] Failed to persist msg in store: Error while using ZooKeeper
2022-06-17T13:27:16,824+0800 [main-SendThread(10.187.128.229:2181)] WARN org.apache.pulsar.broker.service.persistent.PersistentTopic - [persistent://gmtp_cffex/SF_test/bar] Failed to persist msg in store: Error while using ZooKeeper
2022-06-17T13:27:16,824+0800 [main-SendThread(10.187.128.229:2181)] WARN org.apache.pulsar.broker.service.persistent.PersistentTopic - [persistent://gmtp_cffex/SF_test/bar] Failed to persist msg in store: Error while using ZooKeeper
2022-06-17T13:27:16,824+0800 [main-SendThread(10.187.128.229:2181)] WARN org.apache.pulsar.broker.service.persistent.PersistentTopic - [persistent://gmtp_cffex/SF_test/bar] Failed to persist msg in store: Error while using ZooKeeper
2022-06-17T13:27:16,824+0800 [main-SendThread(10.187.128.229:2181)] WARN org.apache.pulsar.broker.service.persistent.PersistentTopic - [persistent://gmtp_cffex/SF_test/bar] Failed to persist msg in store: Error while using ZooKeeper
2022-06-17T13:27:16,824+0800 [main-SendThread(10.187.128.229:2181)] WARN org.apache.pulsar.broker.service.persistent.PersistentTopic - [persistent://gmtp_cffex/SF_test/bar] Failed to persist msg in store: Error while using ZooKeeper
2022-06-17T13:27:16,824+0800 [main-SendThread(10.187.128.229:2181)] WARN org.apache.pulsar.broker.service.persistent.PersistentTopic - [persistent://gmtp_cffex/SF_test/bar] Failed to persist msg in store: Error while using ZooKeeper
2022-06-17T13:27:16,824+0800 [main-SendThread(10.187.128.229:2181)] WARN org.apache.pulsar.broker.service.persistent.PersistentTopic - [persistent://gmtp_cffex/SF_test/bar] Failed to persist msg in store: Error while using ZooKeeper
2022-06-17T13:27:16,824+0800 [main-SendThread(10.187.128.229:2181)] INFO org.apache.pulsar.broker.service.persistent.PersistentTopic - [persistent://gmtp_cffex/SF_test/bar] Un-fencing topic...
2022-06-17T13:27:16,824+0800 [main-SendThread(10.187.128.229:2181)] INFO org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl - [gmtp_cffex/SF_test/persistent/bar] Managed ledger is now ready to accept writes again
2022-06-17T13:27:16,824+0800 [main-SendThread(10.187.128.229:2181)] WARN org.apache.pulsar.broker.service.persistent.PersistentTopic - [persistent://gmtp_cffex/SF_test/bar] Failed to persist msg in store: Error while using ZooKeeper
2022-06-17T13:27:16,825+0800 [main-SendThread(10.187.128.229:2181)] WARN org.apache.bookkeeper.meta.AbstractZkLedgerManager - Conditional update ledger metadata failed: SESSIONEXPIRED
2022-06-17T13:27:16,825+0800 [main-SendThread(10.187.128.229:2181)] ERROR org.apache.bookkeeper.client.MetadataUpdateLoop - UpdateLoop(ledgerId=135600,loopId=4f19d4e3) Error writing metadata to store
org.apache.bookkeeper.client.BKException$ZKException: Error while using ZooKeeper
at org.apache.bookkeeper.meta.AbstractZkLedgerManager$4.processResult(AbstractZkLedgerManager.java:509) [org.apache.bookkeeper-bookkeeper-server-4.14.4.jar:4.14.4]
at org.apache.bookkeeper.zookeeper.ZooKeeperClient$22$1.processResult(ZooKeeperClient.java:1094) [org.apache.bookkeeper-bookkeeper-server-4.14.4.jar:4.14.4]
at org.apache.zookeeper.ClientCnxn$EventThread.processEvent(ClientCnxn.java:638) [org.apache.zookeeper-zookeeper-3.6.3.jar:3.6.3]
at org.apache.zookeeper.ClientCnxn$EventThread.queuePacket(ClientCnxn.java:541) [org.apache.zookeeper-zookeeper-3.6.3.jar:3.6.3]
at org.apache.zookeeper.ClientCnxn.finishPacket(ClientCnxn.java:781) [org.apache.zookeeper-zookeeper-3.6.3.jar:3.6.3]
at org.apache.zookeeper.ClientCnxn.conLossPacket(ClientCnxn.java:818) [org.apache.zookeeper-zookeeper-3.6.3.jar:3.6.3]
at org.apache.zookeeper.ClientCnxn.access$2600(ClientCnxn.java:106) [org.apache.zookeeper-zookeeper-3.6.3.jar:3.6.3]
at org.apache.zookeeper.ClientCnxn$SendThread.cleanup(ClientCnxn.java:1403) [org.apache.zookeeper-zookeeper-3.6.3.jar:3.6.3]
at org.apache.zookeeper.ClientCnxn$SendThread.cleanAndNotifyState(ClientCnxn.java:1331) [org.apache.zookeeper-zookeeper-3.6.3.jar:3.6.3]
at org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:1309) [org.apache.zookeeper-zookeeper-3.6.3.jar:3.6.3]
Caused by: org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /ledgers/00/0013/L5600
at org.apache.zookeeper.KeeperException.create(KeeperException.java:134) ~[org.apache.zookeeper-zookeeper-3.6.3.jar:3.6.3]
at org.apache.zookeeper.KeeperException.create(KeeperException.java:54) ~[org.apache.zookeeper-zookeeper-3.6.3.jar:3.6.3]
... 10 more
2022-06-17T13:27:16,825+0800 [main-SendThread(10.187.128.229:2181)] WARN org.apache.bookkeeper.client.LedgerHandle - Close failed: ZKException: Error while using ZooKeeper
2022-06-17T13:27:16,988+0800 [ZKC-connect-executor-0-EventThread] INFO org.apache.bookkeeper.discover.ZKRegistrationClient - Update BookieInfoCache (writable bookie) 10.187.128.232:3181 -> BookieServiceInfo{properties={}, endpoints=[EndpointInfo{id=bookie, port=3181, host=10.187.128.232, protocol=bookie-rpc, auth=[], extensions=[]}]}
2022-06-17T13:27:16,988+0800 [ZKC-connect-executor-0-EventThread] INFO org.apache.bookkeeper.discover.ZKRegistrationClient - Update BookieInfoCache (writable bookie) 10.187.128.231:3181 -> BookieServiceInfo{properties={}, endpoints=[EndpointInfo{id=bookie, port=3181, host=10.187.128.231, protocol=bookie-rpc, auth=[], extensions=[]}]}
2022-06-17T13:27:16,989+0800 [ZKC-connect-executor-0-EventThread] INFO org.apache.bookkeeper.discover.ZKRegistrationClient - Update BookieInfoCache (writable bookie) 10.187.128.230:3181 -> BookieServiceInfo{properties={}, endpoints=[EndpointInfo{id=bookie, port=3181, host=10.187.128.230, protocol=bookie-rpc, auth=[], extensions=[]}]}
2022-06-17T13:27:17,015+0800 [main-SendThread(10.187.128.227:2181)] INFO org.apache.zookeeper.ClientCnxn - Opening socket connection to server 10.187.128.227/10.187.128.227:2181.
2022-06-17T13:27:17,015+0800 [main-SendThread(10.187.128.227:2181)] INFO org.apache.zookeeper.ClientCnxn - SASL config status: Will not attempt to authenticate using SASL (unknown error)
2022-06-17T13:27:17,015+0800 [main-SendThread(10.187.128.227:2181)] INFO org.apache.zookeeper.ClientCnxn - Socket connection established, initiating session, client: /10.187.128.226:49916, server: 10.187.128.227/10.187.128.227:2181
2022-06-17T13:27:17,020+0800 [main-SendThread(10.187.128.227:2181)] WARN org.apache.zookeeper.ClientCnxn - Unable to reconnect to ZooKeeper service, session 0x304454ce5fc006e has expired
2022-06-17T13:27:17,020+0800 [main-SendThread(10.187.128.227:2181)] WARN org.apache.zookeeper.ClientCnxn - Session 0x304454ce5fc006e for sever 10.187.128.227/10.187.128.227:2181, Closing socket connection. Attempting reconnect except it is a SessionExpiredException.
org.apache.zookeeper.ClientCnxn$SessionExpiredException: Unable to reconnect to ZooKeeper service, session 0x304454ce5fc006e has expired
at org.apache.zookeeper.ClientCnxn$SendThread.onConnected(ClientCnxn.java:1434) ~[org.apache.zookeeper-zookeeper-3.6.3.jar:3.6.3]
at org.apache.zookeeper.ClientCnxnSocket.readConnectResult(ClientCnxnSocket.java:154) ~[org.apache.zookeeper-zookeeper-3.6.3.jar:3.6.3]
at org.apache.zookeeper.ClientCnxnSocketNIO.doIO(ClientCnxnSocketNIO.java:86) ~[org.apache.zookeeper-zookeeper-3.6.3.jar:3.6.3]
at org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(ClientCnxnSocketNIO.java:350) ~[org.apache.zookeeper-zookeeper-3.6.3.jar:3.6.3]
at org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:1290) [org.apache.zookeeper-zookeeper-3.6.3.jar:3.6.3]
2022-06-17T13:27:17,331+0800 [pulsar-timer-52-1] INFO org.apache.pulsar.client.impl.ConnectionHandler - [public/__kafka/__consumer_offsets-partition-48] [pulsar-cluster-test-148-18] Reconnecting after connection was closed
2022-06-17T13:27:17,591+0800 [BookKeeperClientWorker-OrderedExecutor-2-0] INFO org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl - [gmtp_cffex/SF_test/persistent/bar] Creating a new ledger
2022-06-17T13:27:17,592+0800 [BookKeeperClientWorker-OrderedExecutor-2-0] INFO org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl - [gmtp_cffex/SF_test/persistent/bar] Creating ledger, metadata: {component=[109, 97, 110, 97, 103, 101, 100, 45, 108, 101, 100, 103, 101, 114], pulsar/managed-ledger=[103, 109, 116, 112, 95, 99, 102, 102, 101, 120, 47, 83, 70, 95, 116, 101, 115, 116, 47, 112, 101, 114, 115, 105, 115, 116, 101, 110, 116, 47, 98, 97, 114], application=[112, 117, 108, 115, 97, 114]} - metadata ops timeout : 60 seconds
2022-06-17T13:27:17,592+0800 [BookKeeperClientWorker-OrderedExecutor-2-0] WARN org.apache.bookkeeper.client.RackawareEnsemblePlacementPolicyImpl - Failed to find 2 bookies : excludeBookies [Bookie:10.187.128.232:3181, Bookie:10.187.128.231:3181, Bookie:10.187.128.230:3181], allBookies [Bookie:10.187.128.232:3181, Bookie:10.187.128.230:3181, Bookie:10.187.128.231:3181].
2022-06-17T13:27:17,592+0800 [BookKeeperClientWorker-OrderedExecutor-2-0] WARN org.apache.bookkeeper.client.BookieWatcherImpl - New ensemble: [10.187.128.232:3181, 10.187.128.231:3181] is not adhering to Placement Policy
2022-06-17T13:27:17,599+0800 [ZKC-connect-executor-0-EventThread] INFO org.apache.bookkeeper.client.LedgerCreateOp - Ensemble: [10.187.128.232:3181, 10.187.128.231:3181] for ledger: 135693
2022-06-17T13:27:17,600+0800 [ZKC-connect-executor-0-EventThread] INFO org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl - [gmtp_cffex/SF_test/persistent/bar] Created new ledger 135693
2022-06-17T13:27:18,053+0800 [metadata-store-zk-session-watcher-7-1] WARN org.apache.pulsar.metadata.impl.ZKSessionWatcher - ZooKeeper client is disconnected. Waiting to reconnect, time remaining = 22.988 seconds
2022-06-17T13:27:19,189+0800 [pulsar-web-37-7] INFO org.eclipse.jetty.server.RequestLog - 10.187.98.151 - - [17/Jun/2022:13:27:19 +0800] "GET /metrics?format=prometheus HTTP/1.1" 302 0 "-" "Prometheus/2.16.0" 0
2022-06-17T13:27:19,248+0800 [prometheus-stats-38-1] INFO org.eclipse.jetty.server.RequestLog - 10.187.98.151 - - [17/Jun/2022:13:27:19 +0800] "GET /metrics/?format=prometheus HTTP/1.1" 200 625724 "http://10.187.128.226:8080/metrics?format=prometheus" "Prometheus/2.16.0" 58
2022-06-17T13:27:19,622+0800 [pulsar-timer-52-1] INFO org.apache.pulsar.client.impl.ConnectionHandler - [public/__kafka/__consumer_offsets-partition-40] [pulsar-cluster-test-148-8] Reconnecting after connection was closed
2022-06-17T13:27:20,054+0800 [metadata-store-zk-session-watcher-7-1] WARN org.apache.pulsar.metadata.impl.ZKSessionWatcher - ZooKeeper client is disconnected. Waiting to reconnect, time remaining = 20.987 seconds
2022-06-17T13:27:21,966+0800 [pulsar-timer-52-1] INFO org.apache.pulsar.client.impl.ConnectionHandler - [public/__kafka/__consumer_offsets-partition-35] [pulsar-cluster-test-148-9] Reconnecting after connection was closed
2022-06-17T13:27:22,054+0800 [metadata-store-zk-session-watcher-7-1] WARN org.apache.pulsar.metadata.impl.ZKSessionWatcher - ZooKeeper client is disconnected. Waiting to reconnect, time remaining = 18.987 seconds
2022-06-17T13:27:23,011+0800 [pulsar-timer-52-1] INFO org.apache.pulsar.client.impl.ConnectionHandler - [public/__kafka/__consumer_offsets-partition-25] [reader-fc21d8c429] Reconnecting after connection was closed
2022-06-17T13:27:24,054+0800 [metadata-store-zk-session-watcher-7-1] WARN org.apache.pulsar.metadata.impl.ZKSessionWatcher - ZooKeeper client is disconnected. Waiting to reconnect, time remaining = 16.987 seconds
2022-06-17T13:27:24,189+0800 [pulsar-web-37-19] INFO org.eclipse.jetty.server.RequestLog - 10.187.98.151 - - [17/Jun/2022:13:27:24 +0800] "GET /metrics?format=prometheus HTTP/1.1" 302 0 "-" "Prometheus/2.16.0" 0
2022-06-17T13:27:24,257+0800 [prometheus-stats-38-1] INFO org.eclipse.jetty.server.RequestLog - 10.187.98.151 - - [17/Jun/2022:13:27:24 +0800] "GET /metrics/?format=prometheus HTTP/1.1" 200 625723 "http://10.187.128.226:8080/metrics?format=prometheus" "Prometheus/2.16.0" 68
2022-06-17T13:27:25,455+0800 [pulsar-timer-52-1] INFO org.apache.pulsar.client.impl.ConnectionHandler - [public/__kafka/__consumer_offsets-partition-15] [reader-cf54e565f4] Reconnecting after connection was closed
2022-06-17T13:27:26,055+0800 [metadata-store-zk-session-watcher-7-1] WARN org.apache.pulsar.metadata.impl.ZKSessionWatcher - ZooKeeper client is disconnected. Waiting to reconnect, time remaining = 14.986 seconds
2022-06-17T13:27:28,055+0800 [metadata-store-zk-session-watcher-7-1] WARN org.apache.pulsar.metadata.impl.ZKSessionWatcher - ZooKeeper client is disconnected. Waiting to reconnect, time remaining = 12.986 seconds
2022-06-17T13:27:29,189+0800 [pulsar-web-37-7] INFO org.eclipse.jetty.server.RequestLog - 10.187.98.151 - - [17/Jun/2022:13:27:29 +0800] "GET /metrics?format=prometheus HTTP/1.1" 302 0 "-" "Prometheus/2.16.0" 1
2022-06-17T13:27:29,239+0800 [pulsar-timer-52-1] INFO org.apache.pulsar.client.impl.ConnectionHandler - [public/__kafka/__consume

To Reproduce
This happens occasionally.

Desktop (please complete the following information):
CentOS Linux release 7.4.1708

Additional context
Pulsar 2.9.2
KoP 2.9.2.20

Metadata

Metadata

Assignees

No one assigned

    Labels

    Staletype/bugThe PR fixed a bug or issue reported a bug

    Type

    No type

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions