Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Persistent topic is always temporarily unavailable #5284

Open
codelipenghui opened this issue Sep 26, 2019 · 14 comments
Open

Persistent topic is always temporarily unavailable #5284

codelipenghui opened this issue Sep 26, 2019 · 14 comments
Labels
lifecycle/stale type/bug The PR fixed a bug or issue reported a bug

Comments

@codelipenghui
Copy link
Contributor

codelipenghui commented Sep 26, 2019

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

@codelipenghui codelipenghui added the type/bug The PR fixed a bug or issue reported a bug label Sep 26, 2019
@codelipenghui codelipenghui changed the title Persistent topic fenced Persistent topic always fenced. Sep 26, 2019
@codelipenghui codelipenghui changed the title Persistent topic always fenced. Persistent topic is always temporarily unavailable Sep 26, 2019
@codelipenghui codelipenghui self-assigned this Sep 26, 2019
@codelipenghui codelipenghui added this to the 2.4.2 milestone Sep 26, 2019
@aahmed-se
Copy link
Contributor

is this for a new consumer ?

@codelipenghui
Copy link
Contributor Author

@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.

@wolfstudy wolfstudy modified the milestones: 2.4.2, 2.5.0 Oct 29, 2019
@TC-oKozlov
Copy link

TC-oKozlov commented Nov 22, 2019

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
Copy link
Member

tuteng commented Dec 27, 2019

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
Copy link
Member

jiazhai commented Jan 2, 2020

Looks like bundle unload/load happened in the middle.

@codelipenghui codelipenghui removed this from the 2.6.0 milestone May 19, 2020
@codelipenghui codelipenghui removed their assignment May 19, 2020
@frankjkelly
Copy link
Contributor

frankjkelly commented Jun 8, 2021

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
Copy link
Contributor

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

@JohnMops
Copy link

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

@JohnMops
Copy link

Hi, Is this issue fixed after 2.7.x?

@tomjohn9
Copy link

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
Copy link
Contributor

dragonls commented Mar 24, 2022

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
Copy link

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
Copy link
Contributor Author

@xiaofan-luan

This PR #11737
is related to this issue.

Which version you are using?

@xiaofan-luan
Copy link

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?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
lifecycle/stale type/bug The PR fixed a bug or issue reported a bug
Projects
None yet
Development

No branches or pull requests