apache / apache/pulsar

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

Open
#17,891 4 comments 0 reactions 0 assignees View on GitHub
Stale type/bug
Dominant language
Java
Stars
15.3k
Forks
3.8k
Avg merge
1d 14h
Merged PRs (30d)
160

Description

### Search before asking

- [ ] I searched in the [issues](https://github.com/apache/pulsar/issues) and found nothing similar.

### 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);`
6. produce and send message for all 100 topics
produce and send messages like this: `sendResult = producer.send((T) sendMessage);`
8. wait for 10mins
9. 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?

- [x] I'm willing to submit a PR!

Contributor guide

Open the contributing guide

Research direction

Start with PersistentTopic.java around internalDeleteTopicForcefully and asyncDeleteCursor, then trace the corresponding failure in ManagedLedgerImpl.java. Reproduce forceful deletion of the reported topic on Pulsar 2.10.0 and inspect how the missing reader cursor is handled. Done means topic deletion no longer fails with CursorNotFoundException and the behavior is covered by an appropriate regression test.

Written by the indexing model from the issue text.

Assessment

Tech stack
java
Domain
backend, distributed-systems
Issue type
Bug
Difficulty
4/5
Estimated time
3-5 days
Activity status
Stale
Clarity
Needs clarification
Newbie friendliness
25/100

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.