search

apache / pulsar

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

Persistent topic is always temporarily unavailable #5284

Open codelipenghui opened 5 years ago

codelipenghui commented 5 years ago

Describe the bug Here is the error log at broker side:

 23:29:38.178 [pulsar-io-22-19] WARN  org.apache.pulsar.broker.service.ServerCnx - [/10.1.1.101:54749][persistent://swap_okex_prod/order_event/66][SUB_PP_EXCHANGE] Failed to create consumer: Topic is temporarily unavailable
java.util.concurrent.CompletionException: org.apache.pulsar.broker.service.BrokerServiceException$TopicFencedException: Topic is temporarily unavailable
        at java.util.concurrent.CompletableFuture.encodeRelay(CompletableFuture.java:326) ~[?:1.8.0_121]
        at java.util.concurrent.CompletableFuture.uniComposeStage(CompletableFuture.java:984) ~[?:1.8.0_121]
        at java.util.concurrent.CompletableFuture.thenCompose(CompletableFuture.java:2124) ~[?:1.8.0_121]
        at org.apache.pulsar.broker.service.ServerCnx.lambda$null$13(ServerCnx.java:680) ~[org.apache.pulsar-pulsar-broker-2.4.1.jar:2.4.1]
        at java.util.concurrent.CompletableFuture.uniApply(CompletableFuture.java:602) ~[?:1.8.0_121]
        at java.util.concurrent.CompletableFuture.uniApplyStage(CompletableFuture.java:614) ~[?:1.8.0_121]
        at java.util.concurrent.CompletableFuture.thenApply(CompletableFuture.java:1983) ~[?:1.8.0_121]
        at org.apache.pulsar.broker.service.ServerCnx.lambda$handleSubscribe$15(ServerCnx.java:633) ~[org.apache.pulsar-pulsar-broker-2.4.1.jar:2.4.1]
        at java.util.concurrent.CompletableFuture.uniApply(CompletableFuture.java:602) [?:1.8.0_121]
        at java.util.concurrent.CompletableFuture.uniApplyStage(CompletableFuture.java:614) [?:1.8.0_121]
        at java.util.concurrent.CompletableFuture.thenApply(CompletableFuture.java:1983) [?:1.8.0_121]
        at org.apache.pulsar.broker.service.ServerCnx.handleSubscribe(ServerCnx.java:622) [org.apache.pulsar-pulsar-broker-2.4.1.jar:2.4.1]
        at org.apache.pulsar.common.protocol.PulsarDecoder.channelRead(PulsarDecoder.java:199) [org.apache.pulsar-pulsar-common-2.4.1.jar:2.4.1]
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362) [io.netty-netty-all-4.1.32.Final.jar:4.1.32.Final]
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348) [io.netty-netty-all-4.1.32.Final.jar:4.1.32.Final]
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:340) [io.netty-netty-all-4.1.32.Final.jar:4.1.32.Final]
        at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:323) [io.netty-netty-all-4.1.32.Final.jar:4.1.32.Final]
        at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:297) [io.netty-netty-all-4.1.32.Final.jar:4.1.32.Final]

 23:29:48.235 [ForkJoinPool.commonPool-worker-7] WARN  org.apache.pulsar.broker.service.persistent.PersistentTopic - [persistent://swap_okex_prod/order_event/66] Attempting to add producer to a fenced topic
23:29:48.235 [ForkJoinPool.commonPool-worker-7] ERROR org.apache.pulsar.broker.service.ServerCnx - [/10.1.1.97:39705] Failed to add producer to topic persistent://swap_okex_prod/order_event/66: Topic is temporarily unavailable

To Reproduce Difficult to reproduce

aahmed-se commented 5 years ago

is this for a new consumer ?

codelipenghui commented 5 years ago

@aahmed-se

is this for a new consumer ?

both new producer and new consumer, and lasted for a few minutes, restart the broker can resolve.

TC-oKozlov commented 4 years ago

We are getting a similar issue from our custom client code when running a load test from 10 concurrent producer processes. In our setup we create a new producer before sending each message, send message, and close producer. We start getting "topic temporarily unavailable" after about 8000 producers / messages were created. This is runs through Pulsar Proxy ->Broker deployed on kubernetes. It seems like Pulsar starts having an issue when too many producers are created over a short period of time. With our load test we are able to reproduce it pretty consistently:

Re reproducing: 1) start several processes in parallel (in our case 10) 2) for each process: create producer send message, close producer We started 100k messages per process (1mil total), but started getting this error only after about 8k msgs were sent.

tuteng commented 4 years ago

Can you give me a test code? It seems that it is difficult for me to reproduce this problem locally. including some configurations of the cluster. @TC-oKozlov

jiazhai commented 4 years ago

Looks like bundle unload/load happened in the middle.

frankjkelly commented 3 years ago

Same issue for me - seemed to occur during a Topic Unload

13:58:55.615 [ForkJoinPool.commonPool-worker-5] ERROR org.apache.pulsar.broker.service.ServerCnx - [/127.0.0.1:54178] Failed to add producer to topic persistent://cogito-dialog/wav/080e684b-a1ef-44d4-a845-974886ff24f9: Topic is temporarily unavailable
.
.
.
13:58:55.616 [pulsar-web-42-11] INFO  org.apache.pulsar.broker.namespace.OwnedBundle - Unloading cogito-dialog/wav/0x2c000000_0x2e000000 namespace-bundle with 2168 topics completed in 731.0 ms
.
.
.
13:58:55.616 [pulsar-web-42-11] INFO  org.apache.pulsar.broker.admin.impl.NamespacesBase - [null] Successfully unloaded namespace bundle cogito-dialog/wav/0x2c000000_0x2e000000

UPDATE: FYI I was using Pulsar 2.6.1

frankjkelly commented 3 years ago

@addisonj @sijie Is there anything we can do to mitigate this? (We are currently using Pulsar 2.6.1)

JohnMops commented 3 years ago

Same here "Failed to create producer: Topic is temporarily unavailable" , getting this intermittently

JohnMops commented 3 years ago

Hi, Is this issue fixed after 2.7.x?

tomjohn9 commented 2 years ago

Hello, we had have the same issue. We could not even delete the topic which was affected by command ./pulsar-admin topics delete /tenant/space/topic -f

response:

 [AsyncHttpClient-7-1] WARN  org.apache.pulsar.client.admin.internal.BaseResource - [http://localhost:8080/admin/v2/persistent/tenant/space/topic?force=true&deleteSchema=false] Failed to perform http delete request: javax.ws.rs.InternalServerErrorException: HTTP 500 Internal Server Error
HTTP 500 Internal Server ErrorReason: HTTP 500 Internal Server Errorjava.io.ByteArrayInputStream@5d32b342

also reponse for same command after all brokeres were restarted:

[AsyncHttpClient-7-1] WARN  org.apache.pulsar.client.admin.internal.BaseResource - [http://localhost:8080/admin/v2/persistent/tenant/space/topic?force=true&deleteSchema=false] Failed to perform http delete request: java.util.concurrent.CompletionException: org.apache.pulsar.client.admin.internal.http.AsyncHttpConnector$RetryException: Could not complete the operation. Number of retries has been exhausted. Failed reason: test-pulsar-broker-2.test-pulsar-broker.str-test.svc.cluster.local
nullReason: java.util.concurrent.CompletionException: org.apache.pulsar.client.admin.internal.http.AsyncHttpConnector$RetryException: Could not complete the operation. Number of retries has been exhausted. Failed reason: test-pulsar-broker-2.test-pulsar-broker.str-test.svc.cluster.local

On server side was observed

[pulsar-web-42-1] ERROR org.apache.pulsar.broker.admin.impl.PersistentTopicsBase - [null] Failed to delete topic forcefully persistent://tenant/space/topic2022-01-12T10:12:22.112578917Z java.util.concurrent.ExecutionException: org.apache.pulsar.broker.service.BrokerServiceException$TopicFencedException: Topic is already fenced2022-01-12T10:12:22.112584692Z at java.util.concurrent.CompletableFuture.reportGet(CompletableFuture.java:357) ~[?:1.8.0_312]2022-01-12T10:12:22.112589692Z at java.util.concurrent.CompletableFuture.get(CompletableFuture.java:1908) ~[?:1.8.0_312]2022-01-12T10:12:22.112594023Z at org.apache.pulsar.broker.admin.impl.PersistentTopicsBase.internalDeleteTopicForcefully(PersistentTopicsBase.java:381) ~[org.apache.pulsar-pulsar-broker-2.7.4.jar:2.7.4]2022-01-12T10:12:22.112597842Z at org.apache.pulsar.broker.admin.impl.PersistentTopicsBase.internalDeleteTopic(PersistentTopicsBase.java:928) ~[org.apache.pulsar-pulsar-broker-2.7.4.jar:2.7.4]2022-01-12T10:12:22.112602209Z at org.apache.pulsar.broker.admin.v2.PersistentTopics.deleteTopic(PersistentTopics.java:895) ~[org.apache.pulsar-pulsar-broker-2.7.4.jar:2.7.4]2022-01-12T10:12:22.112606269Z at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:1.8.0_312]2022-01-12T10:12:22.112610533Z at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:1.8.0_312]2022-01-12T10:12:22.112614725Z at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_312]2022-01-12T10:12:22.112618793Z at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_312]2022-01-12T10:12:22.112624879Z at org.glassfish.jersey.server.model.internal.ResourceMethodInvocationHandlerFactory.lambda$static$0(ResourceMethodInvocationHandlerFactory.java:52) ~[org.glassfish.jersey.core-jersey-server-2.31.jar:?]2022-01-12T10:12:22.112628946Z at org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher$1.run(AbstractJavaResourceMethodDispatcher.java:124) ~[org.glassfish.jersey.core-jersey-server-2.31.jar:?]2022-01-12T10:12:22.112632798Z at org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher.invoke(AbstractJavaResourceMethodDispatcher.java:167) ~[org.glassfish.jersey.core-jersey-server-2.31.jar:?]2022-01-12T10:12:22.112637722Z at org.glassfish.jersey.server.model.internal.JavaResourceMethodDispatcherProvider$VoidOutInvoker.doDispatch(JavaResourceMethodDispatcherProvider.java:159) ~[org.glassfish.jersey.core-jersey-server-2.31.jar:?]2022-01-12T10:12:22.112643032Z at org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher.dispatch(AbstractJavaResourceMethodDispatcher.java:79) ~[org.glassfish.jersey.core-jersey-server-2.31.jar:?]2022-01-12T10:12:22.112647454Z at org.glassfish.jersey.server.model.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:469) ~[org.glassfish.jersey.core-jersey-server-2.31.jar:?]2022-01-12T10:12:22.112651631Z at org.glassfish.jersey.server.model.ResourceMethodInvoker.apply(ResourceMethodInvoker.java:391) ~[org.glassfish.jersey.core-jersey-server-2.31.jar:?]2022-01-12T10:12:22.112663041Z at org.glassfish.jersey.server.model.ResourceMethodInvoker.apply(ResourceMethodInvoker.java:80) ~[org.glassfish.jersey.core-jersey-server-2.31.jar:?]2022-01-12T10:12:22.112668516Z at org.glassfish.jersey.server.ServerRuntime$1.run(ServerRuntime.java:253) ~[org.glassfish.jersey.core-jersey-server-2.31.jar:?]2022-01-12T10:12:22.112672817Z at org.glassfish.jersey.internal.Errors$1.call(Errors.java:248) ~[org.glassfish.jersey.core-jersey-common-2.31.jar:?]2022-01-12T10:12:22.112677321Z at org.glassfish.jersey.internal.Errors$1.call(Errors.java:244) ~[org.glassfish.jersey.core-jersey-common-2.31.jar:?]2022-01-12T10:12:22.112681470Z at org.glassfish.jersey.internal.Errors.process(Errors.java:292) ~[org.glassfish.jersey.core-jersey-common-2.31.jar:?]2022-01-12T10:12:22.112685407Z at org.glassfish.jersey.internal.Errors.process(Errors.java:274) ~[org.glassfish.jersey.core-jersey-common-2.31.jar:?]2022-01-12T10:12:22.112689357Z at org.glassfish.jersey.internal.Errors.process(Errors.java:244) ~[org.glassfish.jersey.core-jersey-common-2.31.jar:?]2022-01-12T10:12:22.112693780Z at org.glassfish.jersey.process.internal.RequestScope.runInScope(RequestScope.java:265) ~[org.glassfish.jersey.core-jersey-common-2.31.jar:?]2022-01-12T10:12:22.112698117Z at org.glassfish.jersey.server.ServerRuntime.process(ServerRuntime.java:232) ~[org.glassfish.jersey.core-jersey-server-2.31.jar:?]2022-01-12T10:12:22.112702566Z at org.glassfish.jersey.server.ApplicationHandler.handle(ApplicationHandler.java:680) ~[org.glassfish.jersey.core-jersey-server-2.31.jar:?]2022-01-12T10:12:22.112706866Z at org.glassfish.jersey.servlet.WebComponent.serviceImpl(WebComponent.java:394) ~[org.glassfish.jersey.containers-jersey-container-servlet-core-2.31.jar:?]2022-01-12T10:12:22.112711807Z at org.glassfish.jersey.servlet.WebComponent.service(WebComponent.java:346) ~[org.glassfish.jersey.containers-jersey-container-servlet-core-2.31.jar:?]2022-01-12T10:12:22.112717009Z at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:366) ~[org.glassfish.jersey.containers-jersey-container-servlet-core-2.31.jar:?]2022-01-12T10:12:22.112721814Z at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:319) ~[org.glassfish.jersey.containers-jersey-container-servlet-core-2.31.jar:?]2022-01-12T10:12:22.112726179Z at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:205) ~[org.glassfish.jersey.containers-jersey-container-servlet-core-2.31.jar:?]2022-01-12T10:12:22.112730612Z at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:799) ~[org.eclipse.jetty-jetty-servlet-9.4.43.v20210629.jar:9.4.43.v20210629]2022-01-12T10:12:22.112735081Z 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]2022-01-12T10:12:22.112740008Z at org.apache.pulsar.broker.web.ResponseHandlerFilter.doFilter(ResponseHandlerFilter.java:66) ~[org.apache.pulsar-pulsar-broker-2.7.4.jar:2.7.4]2022-01-12T10:12:22.112744543Z at org.eclipse.jetty.servlet.FilterHolder.doFilter(FilterHolder.java:193) ~[org.eclipse.jetty-jetty-servlet-9.4.43.v20210629.jar:9.4.43.v20210629]2022-01-12T10:12:22.112751573Z 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]2022-01-12T10:12:22.112756057Z at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:548) ~[org.eclipse.jetty-jetty-servlet-9.4.43.v20210629.jar:9.4.43.v20210629]2022-01-12T10:12:22.112760477Z 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]2022-01-12T10:12:22.112764961Z 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]2022-01-12T10:12:22.112769449Z 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]2022-01-12T10:12:22.112774433Z 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]2022-01-12T10:12:22.112778917Z 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]2022-01-12T10:12:22.112783064Z at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:501) ~[org.eclipse.jetty-jetty-servlet-9.4.43.v20210629.jar:9.4.43.v20210629]2022-01-12T10:12:22.112787539Z 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]2022-01-12T10:12:22.112792091Z 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]2022-01-12T10:12:22.112796477Z 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]2022-01-12T10:12:22.112801031Z 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]2022-01-12T10:12:22.112805373Z 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]2022-01-12T10:12:22.112809970Z 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]2022-01-12T10:12:22.112814470Z 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]2022-01-12T10:12:22.112818967Z at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127) ~[org.eclipse.jetty-jetty-server-9.4.43.v20210629.jar:9.4.43.v20210629]2022-01-12T10:12:22.112823499Z at org.eclipse.jetty.server.Server.handle(Server.java:516) ~[org.eclipse.jetty-jetty-server-9.4.43.v20210629.jar:9.4.43.v20210629]2022-01-12T10:12:22.112829936Z 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]2022-01-12T10:12:22.112834628Z at org.eclipse.jetty.server.HttpChannel.dispatch(HttpChannel.java:633) [org.eclipse.jetty-jetty-server-9.4.43.v20210629.jar:9.4.43.v20210629]2022-01-12T10:12:22.112839081Z at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:380) [org.eclipse.jetty-jetty-server-9.4.43.v20210629.jar:9.4.43.v20210629]2022-01-12T10:12:22.112843388Z at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:277) [org.eclipse.jetty-jetty-server-9.4.43.v20210629.jar:9.4.43.v20210629]2022-01-12T10:12:22.112847845Z 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]2022-01-12T10:12:22.112852292Z at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:105) [org.eclipse.jetty-jetty-io-9.4.43.v20210629.jar:9.4.43.v20210629]2022-01-12T10:12:22.112856722Z 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]2022-01-12T10:12:22.112861022Z 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]2022-01-12T10:12:22.112865495Z 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]2022-01-12T10:12:22.112870070Z 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]2022-01-12T10:12:22.112875082Z 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]2022-01-12T10:12:22.112879486Z 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]2022-01-12T10:12:22.112883891Z at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_312]2022-01-12T10:12:22.112887551Z at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_312]2022-01-12T10:12:22.112891123Z at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) [io.netty-netty-common-4.1.68.Final.jar:4.1.68.Final]2022-01-12T10:12:22.112894872Z at java.lang.Thread.run(Thread.java:748) [?:1.8.0_312]2022-01-12T10:12:22.112898812Z Caused by: org.apache.pulsar.broker.service.BrokerServiceException$TopicFencedException: Topic is already fenced2022-01-12T10:12:22.112902802Z at org.apache.pulsar.broker.service.persistent.PersistentTopic.delete(PersistentTopic.java:937) ~[org.apache.pulsar-pulsar-broker-2.7.4.jar:2.7.4]2022-01-12T10:12:22.112906464Z at org.apache.pulsar.broker.service.persistent.PersistentTopic.deleteForcefully(PersistentTopic.java:908) ~[org.apache.pulsar-pulsar-broker-2.7.4.jar:2.7.4]2022-01-12T10:12:22.112910144Z at org.apache.pulsar.broker.service.BrokerService.deleteTopic(BrokerService.java:831) ~[org.apache.pulsar-pulsar-broker-2.7.4.jar:2.7.4]2022-01-12T10:12:22.112915645Z ... 66 more

As solution we had to perform removing item from zookeeper by zookeeper shell command and restart all brokers deleteall /managed-ledgers/tenant/namespace/persistent/topic

Is there any better workaround for it?

dragonls commented 2 years ago

We had exactly the same issue in 2.7.2. It happens that when unloading the topic, the topic becomes fenced, and then new producer and new consumer having error Topic is temporarily unavailable. After restarting the broker, the issue resolved.

The broker log:

// unload
16:11:11.603 [pulsar-web-42-4] INFO  org.apache.pulsar.broker.admin.impl.PersistentTopicsBase - [admin] Unloading topic persistent://sec/app/mid_291476475-partition-1

// disconnecting producers
16:11:11.603 [pulsar-web-42-4] INFO  org.apache.pulsar.broker.service.Producer - Disconnecting producer: Producer{topic=PersistentTopic{topic=persistent://sec/app/mid_291476475-partition-1}, client=/9.165.193.134:55508, producerName=pulsar-bi-1406-4093, producerId=73}
16:11:11.603 [pulsar-web-42-4] INFO  org.apache.pulsar.broker.service.Producer - Disconnecting producer: Producer{topic=PersistentTopic{topic=persistent://sec/app/mid_291476475-partition-1}, client=/9.165.243.144:44908, producerName=pulsar-bi-1406-4533, producerId=99}
...

// disconnecting consumer
16:11:11.607 [pulsar-web-42-4] INFO  org.apache.pulsar.broker.service.Consumer - Disconnecting consumer: Consumer{subscription=PersistentSubscription{topic=persistent://sec/app/mid_291476475-partition-1, name=mmdcfisherimport-mid_291476475-dw_safe-ods_safe_topic_291476475-669}, consumerId=1, consumerName=mmdcfisherimport-mid_291476475-dw_safe-ods_safe_topic_291476475-669, address=/9.165.226.119:33722}
16:11:11.607 [pulsar-web-42-4] INFO  org.apache.pulsar.broker.service.persistent.PersistentDispatcherMultipleConsumers - Removed consumer Consumer{subscription=PersistentSubscription{topic=persistent://sec/app/mid_291476475-partition-1, name=mmdcfisherimport-mid_291476475-dw_safe-ods_safe_topic_291476475-669}, consumerId=1, consumerName=mmdcfisherimport-mid_291476475-dw_safe-ods_safe_topic_291476475-669, address=/9.165.226.119:33722} with pending 0 acks
...

16:11:11.712 [ForkJoinPool.commonPool-worker-15] WARN  org.apache.pulsar.broker.service.AbstractTopic - [persistent://sec/app/mid_291476475-partition-1] Attempting to add producer to a fenced topic
16:11:11.712 [pulsar-io-24-33] INFO  org.apache.pulsar.broker.service.ServerCnx - [/9.165.217.148:59240][persistent://sec/app/mid_291476475-partition-1] Creating producer. producerId=45
16:11:11.712 [pulsar-io-24-22] INFO  org.apache.pulsar.broker.service.ServerCnx - [/9.165.193.122:40556][persistent://sec/app/mid_291476475-partition-1] Creating producer. producerId=33
16:11:11.712 [ForkJoinPool.commonPool-worker-15] ERROR org.apache.pulsar.broker.service.ServerCnx - [/9.165.193.228:45852] Failed to add producer to topic persistent://sec/app/mid_291476475-partition-1: Topic is temporarily unavailable

16:11:11.774 [pulsar-io-24-22] INFO  org.apache.pulsar.broker.service.ServerCnx - [/9.165.221.85:40652] Subscribing on topic persistent://sec/app/mid_291476475-partition-1 / mmdcfisherimport-mid_291476475-dw_safe-ods_safe_topic_291476475-669
16:11:11.774 [pulsar-io-24-22] WARN  org.apache.pulsar.broker.service.persistent.PersistentTopic - [persistent://sec/app/mid_291476475-partition-1] Attempting to subscribe to a fenced topic
16:11:11.774 [pulsar-io-24-22] WARN  org.apache.pulsar.broker.service.ServerCnx - [/9.165.221.85:40652][persistent://sec/app/mid_291476475-partition-1][mmdcfisherimport-mid_291476475-dw_safe-ods_safe_topic_291476475-669] Failed to create consumer: consumerId=1, Topic is temporarily unavailable

// secondly unload the topic
16:12:00.672 [pulsar-web-42-8] INFO  org.apache.pulsar.broker.admin.impl.PersistentTopicsBase - [admin] Unloading topic persistent://sec/app/mid_291476475-partition-1
16:12:00.673 [pulsar-web-42-8] WARN  org.apache.pulsar.broker.service.persistent.PersistentTopic - [persistent://sec/app/mid_291476475-partition-1] Topic is already being closed or deleted
16:12:00.673 [pulsar-web-42-8] ERROR org.apache.pulsar.broker.admin.impl.PersistentTopicsBase - [admin] Failed to unload topic persistent://sec/app/mid_291476475-partition-1, Topic is already fenced
org.apache.pulsar.broker.service.BrokerServiceException$TopicFencedException: Topic is already fenced
    at org.apache.pulsar.broker.service.persistent.PersistentTopic.close(PersistentTopic.java:1043) ~[org.apache.pulsar-pulsar-broker-2.7.3-SNAPHOT.jar:2.7.3-SNAPHOT]
    at org.apache.pulsar.broker.admin.impl.PersistentTopicsBase.internalUnloadNonPartitionedTopic(PersistentTopicsBase.java:951) ~[org.apache.pulsar-pulsar-broker-2.7.3-SNAPHOT.jar:2.7.3-SNAPHOT]
    at org.apache.pulsar.broker.admin.impl.PersistentTopicsBase.internalUnloadTopic(PersistentTopicsBase.java:763) ~[org.apache.pulsar-pulsar-broker-2.7.3-SNAPHOT.jar:2.7.3-SNAPHOT]
    at org.apache.pulsar.broker.admin.v2.PersistentTopics.unloadTopic(PersistentTopics.java:857) ~[org.apache.pulsar-pulsar-broker-2.7.3-SNAPHOT.jar:2.7.3-SNAPHOT]
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:1.8.0_312]
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:1.8.0_312]
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_312]
    at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_312]
    at org.glassfish.jersey.server.model.internal.ResourceMethodInvocationHandlerFactory.lambda$static$0(ResourceMethodInvocationHandlerFactory.java:52) ~[org.glassfish.jersey.core-jersey-server-2.31.jar:?]
    at org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher$1.run(AbstractJavaResourceMethodDispatcher.java:124) ~[org.glassfish.jersey.core-jersey-server-2.31.jar:?]
    at org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher.invoke(AbstractJavaResourceMethodDispatcher.java:167) ~[org.glassfish.jersey.core-jersey-server-2.31.jar:?]
    at org.glassfish.jersey.server.model.internal.JavaResourceMethodDispatcherProvider$VoidOutInvoker.doDispatch(JavaResourceMethodDispatcherProvider.java:159) ~[org.glassfish.jersey.core-jersey-server-2.31.jar:?]
    at org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher.dispatch(AbstractJavaResourceMethodDispatcher.java:79) ~[org.glassfish.jersey.core-jersey-server-2.31.jar:?]
    at org.glassfish.jersey.server.model.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:469) ~[org.glassfish.jersey.core-jersey-server-2.31.jar:?]
    at org.glassfish.jersey.server.model.ResourceMethodInvoker.apply(ResourceMethodInvoker.java:391) ~[org.glassfish.jersey.core-jersey-server-2.31.jar:?]
    at org.glassfish.jersey.server.model.ResourceMethodInvoker.apply(ResourceMethodInvoker.java:80) ~[org.glassfish.jersey.core-jersey-server-2.31.jar:?]
    at org.glassfish.jersey.server.ServerRuntime$1.run(ServerRuntime.java:253) ~[org.glassfish.jersey.core-jersey-server-2.31.jar:?]
    at org.glassfish.jersey.internal.Errors$1.call(Errors.java:248) ~[org.glassfish.jersey.core-jersey-common-2.31.jar:?]
    at org.glassfish.jersey.internal.Errors$1.call(Errors.java:244) ~[org.glassfish.jersey.core-jersey-common-2.31.jar:?]
    at org.glassfish.jersey.internal.Errors.process(Errors.java:292) ~[org.glassfish.jersey.core-jersey-common-2.31.jar:?]
    at org.glassfish.jersey.internal.Errors.process(Errors.java:274) ~[org.glassfish.jersey.core-jersey-common-2.31.jar:?]
    at org.glassfish.jersey.internal.Errors.process(Errors.java:244) ~[org.glassfish.jersey.core-jersey-common-2.31.jar:?]
    at org.glassfish.jersey.process.internal.RequestScope.runInScope(RequestScope.java:265) ~[org.glassfish.jersey.core-jersey-common-2.31.jar:?]
    at org.glassfish.jersey.server.ServerRuntime.process(ServerRuntime.java:232) ~[org.glassfish.jersey.core-jersey-server-2.31.jar:?]
    at org.glassfish.jersey.server.ApplicationHandler.handle(ApplicationHandler.java:680) ~[org.glassfish.jersey.core-jersey-server-2.31.jar:?]
    at org.glassfish.jersey.servlet.WebComponent.serviceImpl(WebComponent.java:394) ~[org.glassfish.jersey.containers-jersey-container-servlet-core-2.31.jar:?]
    at org.glassfish.jersey.servlet.WebComponent.service(WebComponent.java:346) ~[org.glassfish.jersey.containers-jersey-container-servlet-core-2.31.jar:?]
    at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:366) ~[org.glassfish.jersey.containers-jersey-container-servlet-core-2.31.jar:?]
    at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:319) ~[org.glassfish.jersey.containers-jersey-container-servlet-core-2.31.jar:?]
    at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:205) ~[org.glassfish.jersey.containers-jersey-container-servlet-core-2.31.jar:?]
    at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:799) ~[org.eclipse.jetty-jetty-servlet-9.4.42.v20210604.jar:9.4.42.v20210604]
    at org.eclipse.jetty.servlet.ServletHandler$ChainEnd.doFilter(ServletHandler.java:1626) ~[org.eclipse.jetty-jetty-servlet-9.4.42.v20210604.jar:9.4.42.v20210604]
    at org.apache.pulsar.broker.web.ResponseHandlerFilter.doFilter(ResponseHandlerFilter.java:66) ~[org.apache.pulsar-pulsar-broker-2.7.3-SNAPHOT.jar:2.7.3-SNAPHOT]
    at org.eclipse.jetty.servlet.FilterHolder.doFilter(FilterHolder.java:193) ~[org.eclipse.jetty-jetty-servlet-9.4.42.v20210604.jar:9.4.42.v20210604]
    at org.eclipse.jetty.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1601) ~[org.eclipse.jetty-jetty-servlet-9.4.42.v20210604.jar:9.4.42.v20210604]
    at org.apache.pulsar.broker.web.AuthenticationFilter.doFilter(AuthenticationFilter.java:82) ~[org.apache.pulsar-pulsar-broker-common-2.7.3-SNAPHOT.jar:2.7.3-SNAPHOT]
    at org.eclipse.jetty.servlet.FilterHolder.doFilter(FilterHolder.java:193) ~[org.eclipse.jetty-jetty-servlet-9.4.42.v20210604.jar:9.4.42.v20210604]
    at org.eclipse.jetty.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1601) ~[org.eclipse.jetty-jetty-servlet-9.4.42.v20210604.jar:9.4.42.v20210604]
    at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:548) ~[org.eclipse.jetty-jetty-servlet-9.4.42.v20210604.jar:9.4.42.v20210604]
    at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:233) ~[org.eclipse.jetty-jetty-server-9.4.42.v20210604.jar:9.4.42.v20210604]
    at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1624) ~[org.eclipse.jetty-jetty-server-9.4.42.v20210604.jar:9.4.42.v20210604]
    at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:233) ~[org.eclipse.jetty-jetty-server-9.4.42.v20210604.jar:9.4.42.v20210604]
    at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1435) ~[org.eclipse.jetty-jetty-server-9.4.42.v20210604.jar:9.4.42.v20210604]
    at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:188) ~[org.eclipse.jetty-jetty-server-9.4.42.v20210604.jar:9.4.42.v20210604]
    at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:501) ~[org.eclipse.jetty-jetty-servlet-9.4.42.v20210604.jar:9.4.42.v20210604]
    at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1594) ~[org.eclipse.jetty-jetty-server-9.4.42.v20210604.jar:9.4.42.v20210604]
    at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:186) ~[org.eclipse.jetty-jetty-server-9.4.42.v20210604.jar:9.4.42.v20210604]
    at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1350) ~[org.eclipse.jetty-jetty-server-9.4.42.v20210604.jar:9.4.42.v20210604]
    at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141) ~[org.eclipse.jetty-jetty-server-9.4.42.v20210604.jar:9.4.42.v20210604]
    at org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:234) ~[org.eclipse.jetty-jetty-server-9.4.42.v20210604.jar:9.4.42.v20210604]
    at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:146) ~[org.eclipse.jetty-jetty-server-9.4.42.v20210604.jar:9.4.42.v20210604]
    at org.eclipse.jetty.server.handler.StatisticsHandler.handle(StatisticsHandler.java:179) ~[org.eclipse.jetty-jetty-server-9.4.42.v20210604.jar:9.4.42.v20210604]
    at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127) ~[org.eclipse.jetty-jetty-server-9.4.42.v20210604.jar:9.4.42.v20210604]
    at org.eclipse.jetty.server.Server.handle(Server.java:516) ~[org.eclipse.jetty-jetty-server-9.4.42.v20210604.jar:9.4.42.v20210604]
    at org.eclipse.jetty.server.HttpChannel.lambda$handle$1(HttpChannel.java:388) ~[org.eclipse.jetty-jetty-server-9.4.42.v20210604.jar:9.4.42.v20210604]
    at org.eclipse.jetty.server.HttpChannel.dispatch(HttpChannel.java:633) [org.eclipse.jetty-jetty-server-9.4.42.v20210604.jar:9.4.42.v20210604]
    at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:380) [org.eclipse.jetty-jetty-server-9.4.42.v20210604.jar:9.4.42.v20210604]
    at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:277) [org.eclipse.jetty-jetty-server-9.4.42.v20210604.jar:9.4.42.v20210604]
    at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311) [org.eclipse.jetty-jetty-io-9.4.42.v20210604.jar:9.4.42.v20210604]
    at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:105) [org.eclipse.jetty-jetty-io-9.4.42.v20210604.jar:9.4.42.v20210604]
    at org.eclipse.jetty.io.ChannelEndPoint$1.run(ChannelEndPoint.java:104) [org.eclipse.jetty-jetty-io-9.4.42.v20210604.jar:9.4.42.v20210604]
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:338) [org.eclipse.jetty-jetty-util-9.4.42.v20210604.jar:9.4.42.v20210604]
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:315) [org.eclipse.jetty-jetty-util-9.4.42.v20210604.jar:9.4.42.v20210604]
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:173) [org.eclipse.jetty-jetty-util-9.4.42.v20210604.jar:9.4.42.v20210604]
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:131) [org.eclipse.jetty-jetty-util-9.4.42.v20210604.jar:9.4.42.v20210604]
    at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:383) [org.eclipse.jetty-jetty-util-9.4.42.v20210604.jar:9.4.42.v20210604]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_312]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_312]
    at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) [io.netty-netty-common-4.1.60.Final.jar:4.1.60.Final]
    at java.lang.Thread.run(Thread.java:748) [?:1.8.0_312]

There are no logs shows like Failed to unload topic or Successfully unloaded topic of the first unload operation, which means that the unload operation is stuck somewhere.

xiaofan-luan commented 2 years ago

hi there @codelipenghui, any progress on the issue? we are also blocking on #5284 for our release? Or anything we could do the temporary work around?

codelipenghui commented 2 years ago

@xiaofan-luan

This PR https://github.com/apache/pulsar/pull/11737 is related to this issue.

Which version you are using?

xiaofan-luan commented 2 years ago

Thanks for replying @codelipenghui We are using 2.8.2 and seems the error is still there, seems that it should be fixed in 2.8.1?