search

apache / pulsar

Apache Pulsar - distributed pub-sub messaging system
https://pulsar.apache.org/
Apache License 2.0
14.18k stars 3.57k forks source link

[Bug]CursorNotFoundException: ManagedCursor not found: reader-1d0faf5700 #17891

Open zhanghang91 opened 2 years ago

zhanghang91 commented 2 years ago

Search before asking

Version

pulsar version: 2.10.0 I had the follow problem when I clear data

ERROR: 2022-09-29T18:16:30,763+0800 [bookkeeper-ml-scheduler-OrderedScheduler-3-0] INFO org.apache.bookkeeper.mledger.impl.MetaStoreImpl - [pulsar_test_kp/routingdata100/persistent/__transaction_buffer_snapshot] Remove consumer=__compaction 2022-09-29T18:16:30,768+0800 [bookkeeper-ml-scheduler-OrderedScheduler-1-0] INFO org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl - [pulsar_test_kp/routingdata100/persistent/__transaction_buffer_snapshot] [__compaction] Deleted cursor 2022-09-29T18:16:30,768+0800 [bookkeeper-ml-scheduler-OrderedScheduler-1-0] ERROR org.apache.pulsar.broker.service.persistent.PersistentTopic - [persistent://pulsar_test_kp/routingdata100/__transaction_buffer_snapshot] Error deleting topic java.util.concurrent.CompletionException: org.apache.pulsar.broker.service.BrokerServiceException$PersistenceException: org.apache.bookkeeper.mledger.ManagedLedgerException$CursorNotFoundException: ManagedCursor not found: reader-1d0faf5700 at java.util.concurrent.CompletableFuture.encodeThrowable(CompletableFuture.java:292) ~[?:1.8.0_232] at java.util.concurrent.CompletableFuture.completeThrowable(CompletableFuture.java:308) ~[?:1.8.0_232] at java.util.concurrent.CompletableFuture.biRelay(CompletableFuture.java:1298) ~[?:1.8.0_232] at java.util.concurrent.CompletableFuture$BiRelay.tryFire(CompletableFuture.java:1284) ~[?:1.8.0_232] at java.util.concurrent.CompletableFuture$CoCompletion.tryFire(CompletableFuture.java:1034) ~[?:1.8.0_232] at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:488) ~[?:1.8.0_232] at java.util.concurrent.CompletableFuture.completeExceptionally(CompletableFuture.java:1990) ~[?:1.8.0_232] at org.apache.pulsar.broker.service.persistent.PersistentTopic$5.deleteCursorFailed(PersistentTopic.java:1046) ~[org.apache.pulsar-pulsar-broker-2.10.0.jar:2.10.0] at org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl.asyncDeleteCursor(ManagedLedgerImpl.java:965) ~[org.apache.pulsar-managed-ledger-2.10.0.jar:2.10.0] at org.apache.pulsar.broker.service.persistent.PersistentTopic.asyncDeleteCursor(PersistentTopic.java:1024) ~[org.apache.pulsar-pulsar-broker-2.10.0.jar:2.10.0] at org.apache.pulsar.broker.service.persistent.PersistentTopic.access$600(PersistentTopic.java:167) ~[org.apache.pulsar-pulsar-broker-2.10.0.jar:2.10.0] at org.apache.pulsar.broker.service.persistent.PersistentTopic$4.deleteLedgerFailed(PersistentTopic.java:1007) ~[org.apache.pulsar-pulsar-broker-2.10.0.jar:2.10.0] at org.apache.bookkeeper.mledger.impl.ManagedLedgerFactoryImpl$9.getInfoFailed(ManagedLedgerFactoryImpl.java:876) ~[org.apache.pulsar-managed-ledger-2.10.0.jar:2.10.0] at org.apache.bookkeeper.mledger.impl.ManagedLedgerFactoryImpl$7.operationFailed(ManagedLedgerFactoryImpl.java:803) ~[org.apache.pulsar-managed-ledger-2.10.0.jar:2.10.0] at org.apache.bookkeeper.mledger.impl.MetaStoreImpl.lambda$getManagedLedgerInfo$3(MetaStoreImpl.java:125) ~[org.apache.pulsar-managed-ledger-2.10.0.jar:2.10.0] at java.util.concurrent.CompletableFuture.uniAccept(CompletableFuture.java:670) [?:1.8.0_232] at java.util.concurrent.CompletableFuture$UniAccept.tryFire(CompletableFuture.java:646) [?:1.8.0_232] at java.util.concurrent.CompletableFuture$Completion.run(CompletableFuture.java:456) [?:1.8.0_232] at org.apache.bookkeeper.common.util.OrderedExecutor$TimedRunnable.run(OrderedExecutor.java:203) [org.apache.bookkeeper-bookkeeper-common-4.14.4.jar:4.14.4] at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:1.8.0_232] at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_232] at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) [?:1.8.0_232] at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) [?:1.8.0_232] at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_232] at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_232] 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.lang.Thread.run(Thread.java:748) [?:1.8.0_232] Caused by: org.apache.pulsar.broker.service.BrokerServiceException$PersistenceException: org.apache.bookkeeper.mledger.ManagedLedgerException$CursorNotFoundException: ManagedCursor not found: reader-1d0faf5700 ... 20 more Caused by: org.apache.bookkeeper.mledger.ManagedLedgerException$CursorNotFoundException: ManagedCursor not found: reader-1d0faf5700 2022-09-29T18:16:30,777+0800 [BookKeeperClientWorker-OrderedExecutor-0-0] INFO org.apache.bookkeeper.mledger.impl.ManagedCursorImpl - [pulsar_test_kp/routingdata100/persistent/__transaction_buffer_snapshot][__compaction] Deleted cursor ledger 1964 2022-09-29T18:16:30,777+0800 [pulsar-web-37-8] ERROR org.apache.pulsar.broker.admin.impl.PersistentTopicsBase - [null] Failed to delete topic forcefully persistent://pulsar_test_kp/routingdata100/__transaction_buffer_snapshot java.util.concurrent.ExecutionException: org.apache.pulsar.broker.service.BrokerServiceException$PersistenceException: org.apache.bookkeeper.mledger.ManagedLedgerException$CursorNotFoundException: ManagedCursor not found: reader-1d0faf5700 at java.util.concurrent.CompletableFuture.reportGet(CompletableFuture.java:357) ~[?:1.8.0_232] at java.util.concurrent.CompletableFuture.get(CompletableFuture.java:1908) ~[?:1.8.0_232] at org.apache.pulsar.broker.admin.impl.PersistentTopicsBase.internalDeleteTopicForcefully(PersistentTopicsBase.java:312) ~[org.apache.pulsar-pulsar-broker-2.10.0.jar:2.10.0] at org.apache.pulsar.broker.admin.impl.PersistentTopicsBase.internalDeleteTopic(PersistentTopicsBase.java:1009) ~[org.apache.pulsar-pulsar-broker-2.10.0.jar:2.10.0] at org.apache.pulsar.broker.admin.v2.PersistentTopics.deleteTopic(PersistentTopics.java:961) ~[org.apache.pulsar-pulsar-broker-2.10.0.jar:2.10.0] at sun.reflect.GeneratedMethodAccessor104.invoke(Unknown Source) ~[?:?] at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_232] at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_232] at org.glassfish.jersey.server.model.internal.ResourceMethodInvocationHandlerFactory.lambda$static$0(ResourceMethodInvocationHandlerFactory.java:52) ~[org.glassfish.jersey.core-jersey-server-2.34.jar:?] at org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher$1.run(AbstractJavaResourceMethodDispatcher.java:124) ~[org.glassfish.jersey.core-jersey-server-2.34.jar:?] at org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher.invoke(AbstractJavaResourceMethodDispatcher.java:167) ~[org.glassfish.jersey.core-jersey-server-2.34.jar:?] at org.glassfish.jersey.server.model.internal.JavaResourceMethodDispatcherProvider$VoidOutInvoker.doDispatch(JavaResourceMethodDispatcherProvider.java:159) ~[org.glassfish.jersey.core-jersey-server-2.34.jar:?] at org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher.dispatch(AbstractJavaResourceMethodDispatcher.java:79) ~[org.glassfish.jersey.core-jersey-server-2.34.jar:?] at org.glassfish.jersey.server.model.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:475) ~[org.glassfish.jersey.core-jersey-server-2.34.jar:?] at org.glassfish.jersey.server.model.ResourceMethodInvoker.apply(ResourceMethodInvoker.java:397) ~[org.glassfish.jersey.core-jersey-server-2.34.jar:?] at org.glassfish.jersey.server.model.ResourceMethodInvoker.apply(ResourceMethodInvoker.java:81) ~[org.glassfish.jersey.core-jersey-server-2.34.jar:?] at org.glassfish.jersey.server.ServerRuntime$1.run(ServerRuntime.java:255) ~[org.glassfish.jersey.core-jersey-server-2.34.jar:?] at org.glassfish.jersey.internal.Errors$1.call(Errors.java:248) ~[org.glassfish.jersey.core-jersey-common-2.34.jar:?] at org.glassfish.jersey.internal.Errors$1.call(Errors.java:244) ~[org.glassfish.jersey.core-jersey-common-2.34.jar:?] at org.glassfish.jersey.internal.Errors.process(Errors.java:292) ~[org.glassfish.jersey.core-jersey-common-2.34.jar:?] at org.glassfish.jersey.internal.Errors.process(Errors.java:274) ~[org.glassfish.jersey.core-jersey-common-2.34.jar:?] at org.glassfish.jersey.internal.Errors.process(Errors.java:244) ~[org.glassfish.jersey.core-jersey-common-2.34.jar:?] at org.glassfish.jersey.process.internal.RequestScope.runInScope(RequestScope.java:265) ~[org.glassfish.jersey.core-jersey-common-2.34.jar:?] at org.glassfish.jersey.server.ServerRuntime.process(ServerRuntime.java:234) ~[org.glassfish.jersey.core-jersey-server-2.34.jar:?] at org.glassfish.jersey.server.ApplicationHandler.handle(ApplicationHandler.java:680) ~[org.glassfish.jersey.core-jersey-server-2.34.jar:?] at org.glassfish.jersey.servlet.WebComponent.serviceImpl(WebComponent.java:394) ~[org.glassfish.jersey.containers-jersey-container-servlet-core-2.34.jar:?] at org.glassfish.jersey.servlet.WebComponent.service(WebComponent.java:346) ~[org.glassfish.jersey.containers-jersey-container-servlet-core-2.34.jar:?] at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:366) ~[org.glassfish.jersey.containers-jersey-container-servlet-core-2.34.jar:?] at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:319) ~[org.glassfish.jersey.containers-jersey-container-servlet-core-2.34.jar:?] at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:205) ~[org.glassfish.jersey.containers-jersey-container-servlet-core-2.34.jar:?] at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:799) ~[org.eclipse.jetty-jetty-servlet-9.4.43.v20210629.jar:9.4.43.v20210629] at org.eclipse.jetty.servlet.ServletHandler$ChainEnd.doFilter(ServletHandler.java:1626) ~[org.eclipse.jetty-jetty-servlet-9.4.43.v20210629.jar:9.4.43.v20210629] at org.apache.pulsar.broker.web.ResponseHandlerFilter.doFilter(ResponseHandlerFilter.java:67) ~[org.apache.pulsar-pulsar-broker-2.10.0.jar:2.10.0] at org.eclipse.jetty.servlet.FilterHolder.doFilter(FilterHolder.java:193) ~[org.eclipse.jetty-jetty-servlet-9.4.43.v20210629.jar:9.4.43.v20210629] at org.eclipse.jetty.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1601) ~[org.eclipse.jetty-jetty-servlet-9.4.43.v20210629.jar:9.4.43.v20210629] at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:548) ~[org.eclipse.jetty-jetty-servlet-9.4.43.v20210629.jar:9.4.43.v20210629] at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:233) ~[org.eclipse.jetty-jetty-server-9.4.43.v20210629.jar:9.4.43.v20210629] at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1624) ~[org.eclipse.jetty-jetty-server-9.4.43.v20210629.jar:9.4.43.v20210629] at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:233) ~[org.eclipse.jetty-jetty-server-9.4.43.v20210629.jar:9.4.43.v20210629] at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1434) ~[org.eclipse.jetty-jetty-server-9.4.43.v20210629.jar:9.4.43.v20210629] at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:188) ~[org.eclipse.jetty-jetty-server-9.4.43.v20210629.jar:9.4.43.v20210629] at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:501) ~[org.eclipse.jetty-jetty-servlet-9.4.43.v20210629.jar:9.4.43.v20210629] at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1594) ~[org.eclipse.jetty-jetty-server-9.4.43.v20210629.jar:9.4.43.v20210629] at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:186) ~[org.eclipse.jetty-jetty-server-9.4.43.v20210629.jar:9.4.43.v20210629] at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1349) ~[org.eclipse.jetty-jetty-server-9.4.43.v20210629.jar:9.4.43.v20210629] at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141) ~[org.eclipse.jetty-jetty-server-9.4.43.v20210629.jar:9.4.43.v20210629] at org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:234) ~[org.eclipse.jetty-jetty-server-9.4.43.v20210629.jar:9.4.43.v20210629] at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:146) ~[org.eclipse.jetty-jetty-server-9.4.43.v20210629.jar:9.4.43.v20210629] at org.eclipse.jetty.server.handler.StatisticsHandler.handle(StatisticsHandler.java:179) ~[org.eclipse.jetty-jetty-server-9.4.43.v20210629.jar:9.4.43.v20210629] at org.eclipse.jetty.server.HttpChannel.lambda$handle$1(HttpChannel.java:388) ~[org.eclipse.jetty-jetty-server-9.4.43.v20210629.jar:9.4.43.v20210629] at org.eclipse.jetty.server.HttpChannel.dispatch(HttpChannel.java:633) [org.eclipse.jetty-jetty-server-9.4.43.v20210629.jar:9.4.43.v20210629] at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:380) [org.eclipse.jetty-jetty-server-9.4.43.v20210629.jar:9.4.43.v20210629] at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:277) [org.eclipse.jetty-jetty-server-9.4.43.v20210629.jar:9.4.43.v20210629] at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311) [org.eclipse.jetty-jetty-io-9.4.43.v20210629.jar:9.4.43.v20210629] at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:105) [org.eclipse.jetty-jetty-io-9.4.43.v20210629.jar:9.4.43.v20210629] at org.eclipse.jetty.io.ChannelEndPoint$1.run(ChannelEndPoint.java:104) [org.eclipse.jetty-jetty-io-9.4.43.v20210629.jar:9.4.43.v20210629] at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:338) [org.eclipse.jetty-jetty-util-9.4.43.v20210629.jar:9.4.43.v20210629] at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:315) [org.eclipse.jetty-jetty-util-9.4.43.v20210629.jar:9.4.43.v20210629] at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:173) [org.eclipse.jetty-jetty-util-9.4.43.v20210629.jar:9.4.43.v20210629] at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:131) [org.eclipse.jetty-jetty-util-9.4.43.v20210629.jar:9.4.43.v20210629] at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:386) [org.eclipse.jetty-jetty-util-9.4.43.v20210629.jar:9.4.43.v20210629] at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_232] at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_232] 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.lang.Thread.run(Thread.java:748) [?:1.8.0_232]

Minimal reproduce step

  1. open transaction
  2. create1 tenant (pulsar_test_kp)
  3. create 1 namespace (pulsar_test_kp/routingdata100)
  4. create 100 topics with random names (pulsar_test_kp/routingdata100/topic__100000XXXXX) create topics like this: pulsarAdmin.topics().createPartitionedTopic(topicName, partition);
  5. produce and send message for all 100 topics produce and send messages like this: sendResult = producer.send((T) sendMessage);
  6. wait for 10mins
  7. delete topics、namespace、tenant sequentially

I implement the above steps through the pulsar-client-admin-api-2.10.0.jar, and call the interface in it.

What did you expect to see?

the reason why I had this problem and the solved method

What did you see instead?

the reason why I had this problem and the solved method

Anything else?

No response

Are you willing to submit a PR?

zhanghang91 commented 2 years ago

when I delete namespace (routingdata100), then I got many many warnings as below, I want to know the reason why I met this.

2022-09-29T20:08:37,224+0800 [pulsar-io-8-8] WARN org.apache.pulsar.client.impl.BinaryProtoLookupService - [persistent://pulsar_test_kp/routingdata100/__transaction_buffer_snapshot] failed to send lookup request : {"errorMsg":"org.apache.pulsar.broker.web.RestException: Namespace not found","reqId":2386858287879233556, "remote":"172.31.225.175/172.31.225.175:6651", "local":"/172.31.225.175:49376"} 2022-09-29T20:08:37,224+0800 [pulsar-io-8-8] WARN org.apache.pulsar.client.impl.ConnectionHandler - [persistent://pulsar_test_kp/routingdata100/__transaction_buffer_snapshot] [reader-d8383e8a41] Error connecting to broker: org.apache.pulsar.client.api.PulsarClientException$BrokerMetadataException: {"errorMsg":"org.apache.pulsar.broker.web.RestException: Namespace not found","reqId":2386858287879233556, "remote":"172.31.225.175/172.31.225.175:6651", "local":"/172.31.225.175:49376"} 2022-09-29T20:08:37,224+0800 [pulsar-io-8-8] WARN org.apache.pulsar.client.impl.ConnectionHandler - [persistent://pulsar_test_kp/routingdata100/__transaction_buffer_snapshot] [reader-d8383e8a41] Could not get connection to broker: org.apache.pulsar.client.api.PulsarClientException$BrokerMetadataException: {"errorMsg":"org.apache.pulsar.broker.web.RestException: Namespace not found","reqId":2386858287879233556, "remote":"172.31.225.175/172.31.225.175:6651", "local":"/172.31.225.175:49376"} -- Will try again in 55.513 s 2022-09-29T20:08:37,464+0800 [pulsar-load-manager-1-1] WARN org.apache.pulsar.broker.loadbalance.impl.ThresholdShedder - average max resource usage is 0 2022-09-29T20:08:37,805+0800 [broker-client-shared-timer-12-1] INFO org.apache.pulsar.client.impl.ConnectionHandler - [persistent://pulsar_test_kp/routingdata100/__transaction_buffer_snapshot] [reader-11523ab60c] Reconnecting after connection was closed

github-actions[bot] commented 1 year ago

The issue had no activity for 30 days, mark with Stale label.

Hongten commented 1 year ago

hi @zhanghang91 , is there any deep research?

github-actions[bot] commented 1 year ago

The issue had no activity for 30 days, mark with Stale label.