pulsar icon indicating copy to clipboard operation
pulsar copied to clipboard
verified publisher icon apache

[Bug] trying reader on __change_events while NS is deleted

Open KannarFr opened this issue 1 year ago • 6 comments

Search before asking

  • [X] I searched in the issues and found nothing similar.

Version

3.2.0

Minimal reproduce step

/

What did you expect to see?

Nothing

What did you see instead?

Broker is trying to read

Feb 01 12:34:28 yo-pulsar-broker-c3-n3 pulsar[3989552]: java.util.concurrent.CompletionException: org.apache.pulsar.client.api.PulsarClientException$TopicDoesNotExistException: {"errorMsg":"Topic persistent://orga_da381d49-a6b5-42eb-97cc-d59effbc6e46/logs/__change_events-partition-0 does not exist","reqId":3207262734360353657, "remote":"yo-pulsar-broker-c3-n5/192.168.2.5:6650", "local":"/192.168.2.3:42438"}
Feb 01 12:34:28 yo-pulsar-broker-c3-n3 pulsar[3989552]:        at java.util.concurrent.CompletableFuture.encodeThrowable(CompletableFuture.java:332) ~[?:?]
Feb 01 12:34:28 yo-pulsar-broker-c3-n3 pulsar[3989552]:        at java.util.concurrent.CompletableFuture.completeThrowable(CompletableFuture.java:347) ~[?:?]
Feb 01 12:34:28 yo-pulsar-broker-c3-n3 pulsar[3989552]:        at java.util.concurrent.CompletableFuture$UniRun.tryFire(CompletableFuture.java:781) ~[?:?]
Feb 01 12:34:28 yo-pulsar-broker-c3-n3 pulsar[3989552]:        at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:510) ~[?:?]
Feb 01 12:34:28 yo-pulsar-broker-c3-n3 pulsar[3989552]:        at java.util.concurrent.CompletableFuture.completeExceptionally(CompletableFuture.java:2162) ~[?:?]
Feb 01 12:34:28 yo-pulsar-broker-c3-n3 pulsar[3989552]:        at org.apache.pulsar.client.impl.ClientCnx.handleError(ClientCnx.java:794) ~[org.apache.pulsar-pulsar-client-original-3.3.0-SNAPSHOT.jar:3.3.0-SNAPSHOT]
Feb 01 12:34:28 yo-pulsar-broker-c3-n3 pulsar[3989552]:        at org.apache.pulsar.common.protocol.PulsarDecoder.channelRead(PulsarDecoder.java:192) ~[org.apache.pulsar-pulsar-common-3.3.0-SNAPSHOT.jar:3.3.0-SNAPSHOT]
Feb 01 12:34:28 yo-pulsar-broker-c3-n3 pulsar[3989552]:        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:444) ~[io.netty-netty-transport-4.1.105.Final.jar:4.1.105.Final]
Feb 01 12:34:28 yo-pulsar-broker-c3-n3 pulsar[3989552]:        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420) ~[io.netty-netty-transport-4.1.105.Final.jar:4.1.105.Final]
Feb 01 12:34:28 yo-pulsar-broker-c3-n3 pulsar[3989552]:        at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412) ~[io.netty-netty-transport-4.1.105.Final.jar:4.1.105.Final]
Feb 01 12:34:28 yo-pulsar-broker-c3-n3 pulsar[3989552]:        at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:346) ~[io.netty-netty-codec-4.1.105.Final.jar:4.1.105.Final]
Feb 01 12:34:28 yo-pulsar-broker-c3-n3 pulsar[3989552]:        at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:318) ~[io.netty-netty-codec-4.1.105.Final.jar:4.1.105.Final]
Feb 01 12:34:28 yo-pulsar-broker-c3-n3 pulsar[3989552]:        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:444) ~[io.netty-netty-transport-4.1.105.Final.jar:4.1.105.Final]
Feb 01 12:34:28 yo-pulsar-broker-c3-n3 pulsar[3989552]:        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420) ~[io.netty-netty-transport-4.1.105.Final.jar:4.1.105.Final]
Feb 01 12:34:28 yo-pulsar-broker-c3-n3 pulsar[3989552]:        at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412) ~[io.netty-netty-transport-4.1.105.Final.jar:4.1.105.Final]
Feb 01 12:34:28 yo-pulsar-broker-c3-n3 pulsar[3989552]:        at io.netty.handler.flush.FlushConsolidationHandler.channelRead(FlushConsolidationHandler.java:152) ~[io.netty-netty-handler-4.1.105.Final.jar:4.1.105.Final]
Feb 01 12:34:28 yo-pulsar-broker-c3-n3 pulsar[3989552]:        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:442) ~[io.netty-netty-transport-4.1.105.Final.jar:4.1.105.Final]
Feb 01 12:34:28 yo-pulsar-broker-c3-n3 pulsar[3989552]:        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420) ~[io.netty-netty-transport-4.1.105.Final.jar:4.1.105.Final]
Feb 01 12:34:28 yo-pulsar-broker-c3-n3 pulsar[3989552]:        at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412) ~[io.netty-netty-transport-4.1.105.Final.jar:4.1.105.Final]
Feb 01 12:34:28 yo-pulsar-broker-c3-n3 pulsar[3989552]:        at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410) ~[io.netty-netty-transport-4.1.105.Final.jar:4.1.105.Final]
Feb 01 12:34:28 yo-pulsar-broker-c3-n3 pulsar[3989552]:        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:440) ~[io.netty-netty-transport-4.1.105.Final.jar:4.1.105.Final]
Feb 01 12:34:28 yo-pulsar-broker-c3-n3 pulsar[3989552]:        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420) ~[io.netty-netty-transport-4.1.105.Final.jar:4.1.105.Final]
Feb 01 12:34:28 yo-pulsar-broker-c3-n3 pulsar[3989552]:        at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919) ~[io.netty-netty-transport-4.1.105.Final.jar:4.1.105.Final]
Feb 01 12:34:28 yo-pulsar-broker-c3-n3 pulsar[3989552]:        at io.netty.channel.epoll.AbstractEpollStreamChannel$EpollStreamUnsafe.epollInReady(AbstractEpollStreamChannel.java:800) ~[io.netty-netty-transport-classes-epoll-4.1.105.Final.jar:4.1.105.Final]
Feb 01 12:34:28 yo-pulsar-broker-c3-n3 pulsar[3989552]:        at io.netty.channel.epoll.EpollEventLoop.processReady(EpollEventLoop.java:509) ~[io.netty-netty-transport-classes-epoll-4.1.105.Final.jar:4.1.105.Final]
Feb 01 12:34:28 yo-pulsar-broker-c3-n3 pulsar[3989552]:        at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:407) ~[io.netty-netty-transport-classes-epoll-4.1.105.Final.jar:4.1.105.Final]
Feb 01 12:34:28 yo-pulsar-broker-c3-n3 pulsar[3989552]:        at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997) ~[io.netty-netty-common-4.1.105.Final.jar:4.1.105.Final]
Feb 01 12:34:28 yo-pulsar-broker-c3-n3 pulsar[3989552]:        at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) ~[io.netty-netty-common-4.1.105.Final.jar:4.1.105.Final]
Feb 01 12:34:28 yo-pulsar-broker-c3-n3 pulsar[3989552]:        at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) ~[io.netty-netty-common-4.1.105.Final.jar:4.1.105.Final]
Feb 01 12:34:28 yo-pulsar-broker-c3-n3 pulsar[3989552]:        at java.lang.Thread.run(Thread.java:840) ~[?:?]
Feb 01 12:34:28 yo-pulsar-broker-c3-n3 pulsar[3989552]: Caused by: org.apache.pulsar.client.api.PulsarClientException$TopicDoesNotExistException: {"errorMsg":"Topic persistent://orga_da381d49-a6b5-42eb-97cc-d59effbc6e46/logs/__change_events-partition-0 does not exist","reqId":3207262734360353657, "remote":"yo-pulsar-broker-c3-n5/192.168.2.5:6650", "local":"/192.168.2.3:42438"}
Feb 01 12:34:28 yo-pulsar-broker-c3-n3 pulsar[3989552]:        at org.apache.pulsar.client.impl.ClientCnx.getPulsarClientException(ClientCnx.java:1338) ~[org.apache.pulsar-pulsar-client-original-3.3.0-SNAPSHOT.jar:3.3.0-SNAPSHOT]
Feb 01 12:34:28 yo-pulsar-broker-c3-n3 pulsar[3989552]:        at org.apache.pulsar.client.impl.ClientCnx.handleError(ClientCnx.java:795) ~[org.apache.pulsar-pulsar-client-original-3.3.0-SNAPSHOT.jar:3.3.0-SNAPSHOT]
Feb 01 12:34:28 yo-pulsar-broker-c3-n3 pulsar[3989552]:        ... 24 more

but the namespace has been deleted.

Anything else?

No response

Are you willing to submit a PR?

  • [ ] I'm willing to submit a PR!

KannarFr avatar Feb 01 '24 12:02 KannarFr

How do you occur this issue or do you have the reproduce steps?

Technoboy- avatar Feb 01 '24 14:02 Technoboy-

I don't know, it appears on some topics (majority of __change_events-partition-0) but it appears randomly on our production cluster which runs 3.2.0 (due to fixes we wanted to apply for fenced topics issues) on proxies/brokers as suggested by @lhotari . Maybe we need to also bump the BK?

KannarFr avatar Feb 01 '24 18:02 KannarFr

I don't know, it appears on some topics (majority of __change_events-partition-0) but it appears randomly on our production cluster which runs 3.2.0 (due to fixes we wanted to apply for fenced topics issues) on proxies/brokers as suggested by @lhotari . Maybe we need to also bump the BK?

Does the log print continuously?

Technoboy- avatar Feb 02 '24 02:02 Technoboy-

Yes.

KannarFr avatar Feb 02 '24 14:02 KannarFr

Yes.

Do you have more logs related to this topic ?

Technoboy- avatar Feb 04 '24 16:02 Technoboy- 

Feb 05 14:14:27 yo-pulsar-broker-c3-n3 pulsar[3989552]: 2024-02-05T14:14:27,524+0000 [pulsar-io-3-11] WARN  org.apache.pulsar.broker.service.ServerCnx - [/192.168.2.3:57332][persistent://orga_69da42d8-1a82-4160-809d-cba92c2c9655/logs/__change_events-partition-0][multiTopicsReader-4e137a97f1] Failed to create consumer: consumerId=14543, No such ledger exists on Metadata Server -  ledger=16317 - operation=Failed to open ledger
Feb 05 14:14:27 yo-pulsar-broker-c3-n3 pulsar[3989552]: 2024-02-05T14:14:27,524+0000 [pulsar-io-3-10] WARN  org.apache.pulsar.client.impl.ClientCnx - [id: 0xebb46184, L:/192.168.2.3:57332 - R:yo-pulsar-broker-c3-n3/192.168.2.3:6650] Received error from server: No such ledger exists on Metadata Server -  ledger=16317 - operation=Failed to open ledger
Feb 05 14:14:27 yo-pulsar-broker-c3-n3 pulsar[3989552]: 2024-02-05T14:14:27,524+0000 [pulsar-io-3-10] WARN  org.apache.pulsar.client.impl.ConsumerImpl - [persistent://orga_69da42d8-1a82-4160-809d-cba92c2c9655/logs/__change_events-partition-0][multiTopicsReader-4e137a97f1] Failed to subscribe to topic on yo-pulsar-broker-c3-n3/192.168.2.3:6650
Feb 05 14:14:27 yo-pulsar-broker-c3-n3 pulsar[3989552]: 2024-02-05T14:14:27,524+0000 [pulsar-io-3-10] WARN  org.apache.pulsar.client.impl.ConnectionHandler - [persistent://orga_69da42d8-1a82-4160-809d-cba92c2c9655/logs/__change_events-partition-0] [multiTopicsReader-4e137a97f1] Error connecting to broker: org.apache.pulsar.client.api.PulsarClientException: {"errorMsg":"No such ledger exists on Metadata Server -  ledger=16317 - operation=Failed to open ledger","reqId":3207262734372488948, "remote":"yo-pulsar-broker-c3-n3/192.168.2.3:6650", "local":"/192.168.2.3:57332"}
Feb 05 14:14:27 yo-pulsar-broker-c3-n3 pulsar[3989552]: 2024-02-05T14:14:27,524+0000 [pulsar-io-3-10] WARN  org.apache.pulsar.client.impl.ConnectionHandler - [persistent://orga_69da42d8-1a82-4160-809d-cba92c2c9655/logs/__change_events-partition-0] [multiTopicsReader-4e137a97f1] Could not get connection to broker: org.apache.pulsar.client.api.PulsarClientException: {"errorMsg":"No such ledger exists on Metadata Server -  ledger=16317 - operation=Failed to open ledger","reqId":3207262734372488948, "remote":"yo-pulsar-broker-c3-n3/192.168.2.3:6650", "local":"/192.168.2.3:57332"} -- Will try again in 25.445 s

KannarFr avatar Feb 05 '24 14:02 KannarFr

The issue has disappeared since we applied 3.2.0 on each component. Closing.

KannarFr avatar Feb 22 '24 12:02 KannarFr