https://pulsar.apache.org/ logo
Join Slack
Powered by
Hi Guys, My once working cluster, deployed on GKE ...
# general
t
Hi Guys, My once working cluster, deployed on GKE using the helm chart, has stopped working completely. All of the topics cannot be produced to nor consumed from. Through the 
pulsar-shell
I can 
admin topic stats my-topic
, but for example when I try to delete the topic (I'd like to avoid that), I get the following error: • (This is a similar error to when I try to create producer/consumer from the Java clients)
Copy code
org.apache.pulsar.broker.service.schema.exceptions.SchemaException: Error while reading ledger -  ledger=391 - operation=Failed to read entry - entry=0
	at org.apache.pulsar.broker.service.schema.BookkeeperSchemaStorage.bkException(BookkeeperSchemaStorage.java:711)
	at org.apache.pulsar.broker.service.schema.BookkeeperSchemaStorage$Functions.lambda$getLedgerEntry$0(BookkeeperSchemaStorage.java:655)
	at org.apache.bookkeeper.client.LedgerHandle$4.onFailure(LedgerHandle.java:818)
	at org.apache.bookkeeper.common.concurrent.FutureEventListener.accept(FutureEventListener.java:38)
	at org.apache.bookkeeper.common.concurrent.FutureEventListener.accept(FutureEventListener.java:26)
	at java.base/java.util.concurrent.CompletableFuture.uniWhenComplete(CompletableFuture.java:863)
	at java.base/java.util.concurrent.CompletableFuture$UniWhenComplete.tryFire(CompletableFuture.java:841)
	at java.base/java.util.concurrent.CompletableFuture$Completion.run(CompletableFuture.java:482)
	at org.apache.bookkeeper.common.util.SingleThreadExecutor.safeRunTask(SingleThreadExecutor.java:137)
	at org.apache.bookkeeper.common.util.SingleThreadExecutor.run(SingleThreadExecutor.java:107)
	at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
	at java.base/java.lang.Thread.run(Thread.java:840)
The Bookies and Brokers have no Error logs. The Recovery Pod has many errors, below are some log entries:
Copy code
data-pulsar-recovery 2024-03-17T17:11:09,481+0000 [BookKeeperClientWorker-OrderedExecutor-1-0] ERROR org.apache.bookkeeper.replication.ReplicationWorker - Received error: -1 while trying to read entry: 5218 of ledger: 418 in ReplicationWorker
data-pulsar-recovery 2024-03-17T17:11:09,481+0000 [BookKeeperClientWorker-OrderedExecutor-1-0] ERROR org.apache.bookkeeper.proto.PerChannelBookieClient - Read for failed on bookie data-pulsar-bookie-0.data-pulsar-bookie.data.svc.cluster.local:3181 code EIO
data-pulsar-recovery 2024-03-17T17:11:09,481+0000 [BookKeeperClientWorker-OrderedExecutor-1-0] INFO  org.apache.bookkeeper.client.PendingReadOp - Error: Error while reading ledger while reading L418 E5219 from bookie: data-pulsar-bookie-0.data-pulsar-bookie.data.svc.cluster.local:3181
data-pulsar-recovery 2024-03-17T17:11:09,481+0000 [BookKeeperClientWorker-OrderedExecutor-1-0] ERROR org.apache.bookkeeper.client.PendingReadOp - Read of ledger entry failed: L418 E5219-E5219, Sent to [data-pulsar-bookie-0.data-pulsar-bookie.data.svc.cluster.local:3181], Heard from ] : bitset = {}, Error = 'Error while reading ledger'. First unread entry is (-1, rc = null)
data-pulsar-recovery 2024-03-17T17:11:09,481+0000 [BookKeeperClientWorker-OrderedExecutor-1-0] ERROR org.apache.bookkeeper.proto.PerChannelBookieClient - Read for failed on bookie data-pulsar-bookie-0.data-pulsar-bookie.data.svc.cluster.local:3181 code EIO
data-pulsar-recovery 2024-03-17T17:11:09,481+0000 [BookKeeperClientWorker-OrderedExecutor-1-0] ERROR org.apache.bookkeeper.replication.ReplicationWorker - Received error: -1 while trying to read entry: 5219 of ledger: 418 in ReplicationWorker
data-pulsar-recovery 2024-03-17T17:11:09,481+0000 [BookKeeperClientWorker-OrderedExecutor-1-0] ERROR org.apache.bookkeeper.proto.PerChannelBookieClient - Read for failed on bookie data-pulsar-bookie-0.data-pulsar-bookie.data.svc.cluster.local:3181 code EIO
data-pulsar-recovery 2024-03-17T17:11:09,481+0000 [ReplicationWorker] ERROR org.apache.bookkeeper.replication.ReplicationWorker - ReplicationWorker failed to replicate Ledger : 418 for 3 number of times, so deferring the ledger lock release by 75000 msecs
Can you please point me to the reason for this? I am not sure how to further debug this. My assumption is that maybe there isn't sufficient ledger storage space? Can the assumption verified somehow? Can it be resized online using the chart? (the storage class should support this) EDIT: I am not sure if this is the correct channel. If it isn't i'll move this elsewhere. Thanks!
d
The first step is determining if your bookie pods are up and running. Both the error logs indicate a failure to read from BookKeeper, so I suspect a connectivity issue of some sort is the culprit.
Try exec-ing into one of the bookie pods and, confirming that the bookie is up and running, and listening on port 3181. Ensure your metadata store has the correct network addresses for the bookies. IIRC, you can use the bookkeeper shell for this
t
Hi @David K, thank you for the response. I see that (all of the 4) Bookie Pods are running, and as far as I understand their logs contain no information indicating an error. As you suggested, I exec-ed into one of them, in it I ran 
/pulsar/bin/bookkeeper shell bookiesanity
which did not yield any error (Attached the output below). The output of the bookiesanity command:
Copy code
2024-03-19T12:11:09,177+0000 [main] INFO  org.apache.zookeeper.ZooKeeper - Initiating client connection, connectString=data-pulsar-zookeeper:2181 sessionTimeout=30000 watcher=org.apache.bookkeeper.zookeeper.ZooKeeperWatcherBase@8a589a2
2024-03-19T12:11:09,181+0000 [main] INFO  org.apache.zookeeper.common.X509Util - Setting -D jdk.tls.rejectClientInitiatedRenegotiation=true to disable client-initiated TLS renegotiation
2024-03-19T12:11:09,187+0000 [main] INFO  org.apache.zookeeper.ClientCnxnSocket - jute.maxbuffer value is 1048575 Bytes
2024-03-19T12:11:09,196+0000 [main] INFO  org.apache.zookeeper.ClientCnxn - zookeeper.request.timeout value is 0. feature enabled=false
2024-03-19T12:11:09,211+0000 [main-SendThread(data-pulsar-zookeeper:2181)] INFO  org.apache.zookeeper.ClientCnxn - Opening socket connection to server data-pulsar-zookeeper/10.4.0.33:2181.
2024-03-19T12:11:09,211+0000 [main-SendThread(data-pulsar-zookeeper:2181)] INFO  org.apache.zookeeper.ClientCnxn - SASL config status: Will not attempt to authenticate using SASL (unknown error)
2024-03-19T12:11:09,220+0000 [main-SendThread(data-pulsar-zookeeper:2181)] INFO  org.apache.zookeeper.ClientCnxn - Socket connection established, initiating session, client: /10.4.0.9:42680, server: data-pulsar-zookeeper/10.4.0.33:2181
2024-03-19T12:11:09,228+0000 [main-SendThread(data-pulsar-zookeeper:2181)] INFO  org.apache.zookeeper.ClientCnxn - Session establishment complete on server data-pulsar-zookeeper/10.4.0.33:2181, session id = 0x100068784bb000e, negotiated timeout = 30000
2024-03-19T12:11:09,232+0000 [main-EventThread] INFO  org.apache.bookkeeper.zookeeper.ZooKeeperWatcherBase - ZooKeeper client is connected now.
2024-03-19T12:11:09,372+0000 [main] INFO  org.apache.bookkeeper.client.BookKeeper - Weighted ledger placement is not enabled
2024-03-19T12:11:09,462+0000 [main-EventThread] INFO  org.apache.bookkeeper.discover.ZKRegistrationClient - Update BookieInfoCache (writable bookie) data-pulsar-bookie-0.data-pulsar-bookie.data.svc.cluster.local:3181 -> BookieServiceInfo{properties={}, endpoints=[EndpointInfo{id=httpserver, port=8000, host=0.0.0.0, protocol=http, auth=[], extensions=[]}, EndpointInfo{id=bookie, port=3181, host=data-pulsar-bookie-0.data-pulsar-bookie.data.svc.cluster.local, protocol=bookie-rpc, auth=[], extensions=[]}]}
2024-03-19T12:11:09,462+0000 [main-EventThread] INFO  org.apache.bookkeeper.discover.ZKRegistrationClient - Update BookieInfoCache (writable bookie) data-pulsar-bookie-2.data-pulsar-bookie.data.svc.cluster.local:3181 -> BookieServiceInfo{properties={}, endpoints=[EndpointInfo{id=httpserver, port=8000, host=0.0.0.0, protocol=http, auth=[], extensions=[]}, EndpointInfo{id=bookie, port=3181, host=data-pulsar-bookie-2.data-pulsar-bookie.data.svc.cluster.local, protocol=bookie-rpc, auth=[], extensions=[]}]}
2024-03-19T12:11:09,463+0000 [main-EventThread] INFO  org.apache.bookkeeper.discover.ZKRegistrationClient - Update BookieInfoCache (writable bookie) data-pulsar-bookie-3.data-pulsar-bookie.data.svc.cluster.local:3181 -> BookieServiceInfo{properties={}, endpoints=[EndpointInfo{id=httpserver, port=8000, host=0.0.0.0, protocol=http, auth=[], extensions=[]}, EndpointInfo{id=bookie, port=3181, host=data-pulsar-bookie-3.data-pulsar-bookie.data.svc.cluster.local, protocol=bookie-rpc, auth=[], extensions=[]}]}
2024-03-19T12:11:09,463+0000 [main-EventThread] INFO  org.apache.bookkeeper.discover.ZKRegistrationClient - Update BookieInfoCache (writable bookie) data-pulsar-bookie-1.data-pulsar-bookie.data.svc.cluster.local:3181 -> BookieServiceInfo{properties={}, endpoints=[EndpointInfo{id=httpserver, port=8000, host=0.0.0.0, protocol=http, auth=[], extensions=[]}, EndpointInfo{id=bookie, port=3181, host=data-pulsar-bookie-1.data-pulsar-bookie.data.svc.cluster.local, protocol=bookie-rpc, auth=[], extensions=[]}]}
2024-03-19T12:11:09,540+0000 [main-EventThread] INFO  org.apache.bookkeeper.client.LedgerCreateOp - Ensemble: [data-pulsar-bookie-0.data-pulsar-bookie.data.svc.cluster.local:3181] for ledger: 580
2024-03-19T12:11:09,542+0000 [main] INFO  org.apache.bookkeeper.tools.cli.commands.bookie.SanityTestCommand - Create ledger 580
2024-03-19T12:11:09,677+0000 [bookkeeper-io-3-1] INFO  org.apache.bookkeeper.proto.PerChannelBookieClient - Successfully connected to bookie: data-pulsar-bookie-0.data-pulsar-bookie.data.svc.cluster.local:3181 [id: 0xc90c63c9, L:/10.4.0.9:37948 - R:data-pulsar-bookie-0.data-pulsar-bookie.data.svc.cluster.local/10.4.0.9:3181]
2024-03-19T12:11:09,693+0000 [bookkeeper-io-3-1] INFO  org.apache.bookkeeper.proto.PerChannelBookieClient - connection [id: 0xc90c63c9, L:/10.4.0.9:37948 - R:data-pulsar-bookie-0.data-pulsar-bookie.data.svc.cluster.local/10.4.0.9:3181] authenticated as BookKeeperPrincipal{ANONYMOUS}
2024-03-19T12:11:09,740+0000 [main] INFO  org.apache.bookkeeper.tools.cli.commands.bookie.SanityTestCommand - Written 10 entries in ledger 580
2024-03-19T12:11:09,777+0000 [BookKeeperClientWorker-OrderedExecutor-2-0] INFO  org.apache.bookkeeper.client.ReadOnlyLedgerHandle - Closing recovered ledger 580 at entry 9
2024-03-19T12:11:09,796+0000 [main] INFO  org.apache.bookkeeper.tools.cli.commands.bookie.SanityTestCommand - Read 10 entries from ledger 580
2024-03-19T12:11:09,805+0000 [main] INFO  org.apache.bookkeeper.tools.cli.commands.bookie.SanityTestCommand - Deleted ledger 580
2024-03-19T12:11:09,805+0000 [main] INFO  org.apache.bookkeeper.proto.PerChannelBookieClient - Closing the per channel bookie client for data-pulsar-bookie-0.data-pulsar-bookie.data.svc.cluster.local:3181
2024-03-19T12:11:09,808+0000 [main] INFO  org.apache.bookkeeper.proto.PerChannelBookieClient - Closing the per channel bookie client for data-pulsar-bookie-0.data-pulsar-bookie.data.svc.cluster.local:3181
2024-03-19T12:11:09,809+0000 [bookkeeper-io-3-1] INFO  org.apache.bookkeeper.proto.PerChannelBookieClient - Disconnected from bookie channel [id: 0xc90c63c9, L:/10.4.0.9:37948 ! R:data-pulsar-bookie-0.data-pulsar-bookie.data.svc.cluster.local/10.4.0.9:3181]
2024-03-19T12:11:11,789+0000 [main] WARN  org.apache.bookkeeper.client.BookKeeper - The mainWorkerPool did not shutdown cleanly
2024-03-19T12:11:11,898+0000 [main] INFO  org.apache.zookeeper.ZooKeeper - Session: 0x100068784bb000e closed
2024-03-19T12:11:11,899+0000 [main] INFO  org.apache.bookkeeper.tools.cli.commands.bookie.SanityTestCommand - Bookie sanity test succeeded
2024-03-19T12:11:11,899+0000 [main-EventThread] INFO  org.apache.zookeeper.ClientCnxn - EventThread shut down for session: 0x100068784bb000e
Ah, but when running autorecovery, I get in the log an error:
Copy code
2024-03-19T12:13:49,378+0000 [ReplicationWorker] ERROR org.apache.bookkeeper.proto.PerChannelBookieClient - Cannot connect to data-pulsar-bookie-2.data-pulsar-bookie.data.svc.cluster.local:3181 as endpoint resolution failed (probably bookie is down) err org.apache.bookkeeper.proto.BookieAddressResolver$BookieIdNotResolvedException: Cannot resolve bookieId data-pulsar-bookie-2.data-pulsar-bookie.data.svc.cluster.local:3181, bookie does not exist or it is not running
Which might indicate name resolution issue
Open in Slack
PreviousNext
Powered by