michaeljmarshall commented on issue #20376: URL: https://github.com/apache/pulsar/issues/20376#issuecomment-1561585239
Here is the rest of my error log file: [org.apache.pulsar.broker.admin.AdminApi2Test-output.txt](https://github.com/apache/pulsar/files/11557017/org.apache.pulsar.broker.admin.AdminApi2Test-output.txt) With additional inspection, it seems like part of the problem could easily be system topics. I see issues related to `__change-events` topic: ``` xyz2/ns1/persistent/__change_events-partition-11, ackPos=66:-1, readPos=66:0}] 2023-05-24T15:30:44,862 - INFO - [PulsarTestContext-executor-OrderedExecutor-0-0:PersistentSubscription@312] - [persistent://prop-xyz2/ns1/__change_events-partition-11][multiTopicsReader-1b06c712cc] Successfully closed dispatcher for reader 2023-05-24T15:30:44,862 - ERROR - [PulsarTestContext-executor-OrderedExecutor-0-0:PersistentTopic@948] - [persistent://prop-xyz2/ns1/__change_events-partition-11] Failed to create subscription: multiTopicsReader-1b06c712cc java.util.concurrent.CompletionException: org.apache.pulsar.broker.service.BrokerServiceException: Connection was closed while the opening the cursor at java.util.concurrent.CompletableFuture.encodeRelay(CompletableFuture.java:368) ~[?:?] at java.util.concurrent.CompletableFuture.uniComposeStage(CompletableFuture.java:1189) ~[?:?] at java.util.concurrent.CompletableFuture.thenCompose(CompletableFuture.java:2309) ~[?:?] at org.apache.pulsar.broker.service.persistent.PersistentTopic.lambda$internalSubscribe$20(PersistentTopic.java:890) ~[classes/:?] at java.util.concurrent.CompletableFuture.uniComposeStage(CompletableFuture.java:1187) ~[?:?] at java.util.concurrent.CompletableFuture.thenCompose(CompletableFuture.java:2309) ~[?:?] at org.apache.pulsar.broker.service.persistent.PersistentTopic.lambda$internalSubscribe$22(PersistentTopic.java:885) ~[classes/:?] at java.util.concurrent.CompletableFuture.uniComposeStage(CompletableFuture.java:1187) ~[?:?] at java.util.concurrent.CompletableFuture.thenCompose(CompletableFuture.java:2309) ~[?:?] at org.apache.pulsar.broker.service.persistent.PersistentTopic.internalSubscribe(PersistentTopic.java:806) ~[classes/:?] at org.apache.pulsar.broker.service.persistent.PersistentTopic.subscribe(PersistentTopic.java:780) ~[classes/:?] at org.apache.pulsar.broker.service.ServerCnx.lambda$handleSubscribe$14(ServerCnx.java:1239) ~[classes/:?] at java.util.concurrent.CompletableFuture$UniCompose.tryFire(CompletableFuture.java:1150) ~[?:?] at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:510) ~[?:?] at java.util.concurrent.CompletableFuture.complete(CompletableFuture.java:2147) ~[?:?] at org.apache.pulsar.broker.service.schema.BookkeeperSchemaStorage.lambda$closeLedger$42(BookkeeperSchemaStorage.java:619) ~[classes/:?] at org.apache.bookkeeper.client.PulsarMockLedgerHandle.lambda$asyncClose$1(PulsarMockLedgerHandle.java:96) ~[testmocks-3.1.0-SNAPSHOT.jar:4.16.1] at java.util.concurrent.CompletableFuture.uniWhenComplete(CompletableFuture.java:863) ~[?:?] at java.util.concurrent.CompletableFuture$UniWhenComplete.tryFire(CompletableFuture.java:841) ~[?:?] at java.util.concurrent.CompletableFuture$Completion.run(CompletableFuture.java:482) ~[?:?] at org.apache.bookkeeper.common.util.SingleThreadExecutor.safeRunTask(SingleThreadExecutor.java:137) ~[bookkeeper-common-4.16.1.jar:4.16.1] at org.apache.bookkeeper.common.util.SingleThreadExecutor.run(SingleThreadExecutor.java:107) ~[bookkeeper-common-4.16.1.jar:4.16.1] at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) ~[netty-common-4.1.89.Final.jar:4.1.89.Final] at java.lang.Thread.run(Thread.java:833) ~[?:?] Caused by: org.apache.pulsar.broker.service.BrokerServiceException: Connection was closed while the opening the cursor at org.apache.pulsar.broker.service.persistent.PersistentTopic.lambda$internalSubscribe$19(PersistentTopic.java:914) ~[classes/:?] at java.util.concurrent.CompletableFuture.uniComposeStage(CompletableFuture.java:1187) ~[?:?] ... 22 more 2023-05-24T15:30:44,864 - WARN - [PulsarTestContext-executor-OrderedExecutor-0-0:ServerCnx@1282] - [/127.0.0.1:57364][persistent://prop-xyz2/ns1/__change_events-partition-11][multiTopicsReader-1b06c712cc] Failed to create consumer: consumerId=11, Connection was closed while the opening the cursor 2023-05-24T15:30:44,864 - INFO - [PulsarTestContext-executor-OrderedExecutor-0-0:PersistentTopic@1033] - [persistent://prop-xyz2/ns1/__change_events-partition-4][multiTopicsReader-1b06c712cc] Creating non-durable subscription at msg id -1:-1:-1:-1 - {} 2023-05-24T15:30:44,864 - INFO - [PulsarTestContext-executor-OrderedExecutor-0-0:NonDurableCursorImpl@66] - [prop-xyz2/ns1/persistent/__change_events-partition-4] Created non-durable cursor read-position=67:0 mark-delete-position=67:-1 2023-05-24T15:30:44,864 - INFO - [PulsarTestContext-executor-OrderedExecutor-0-0:ManagedLedgerImpl@1130] - [prop-xyz2/ns1/persistent/__change_events-partition-4] Opened new cursor: NonDurableCursorImpl{ledger=prop-xyz2/ns1/persistent/__change_events-partition-4, ackPos=67:-1, readPos=67:0} 2023-05-24T15:30:44,865 - INFO - [PulsarTestContext-executor-OrderedExecutor-0-0:AbstractDispatcherSingleActiveConsumer@211] - Removing consumer Consumer{subscription=PersistentSubscription{topic=persistent://prop-xyz2/ns1/__change_events-partition-4, name=multiTopicsReader-1b06c712cc}, consumerId=4, consumerName=ae38e, address=/127.0.0.1:57364} 2023-05-24T15:30:44,865 - INFO - [PulsarTestContext-executor-OrderedExecutor-0-0:PersistentSubscription@880] - [persistent://prop-xyz2/ns1/__change_events-partition-4][multiTopicsReader-1b06c712cc] Successfully closed subscription [NonDurableCursorImpl{ledger=prop-xyz2/ns1/persistent/__change_events-partition-4, ackPos=67:-1, readPos=67:0}] 2023-05-24T15:30:44,865 - INFO - [PulsarTestContext-executor-OrderedExecutor-0-0:PersistentSubscription@312] - [persistent://prop-xyz2/ns1/__change_events-partition-4][multiTopicsReader-1b06c712cc] Successfully closed dispatcher for reader 2023-05-24T15:30:44,865 - ERROR - [PulsarTestContext-executor-OrderedExecutor-0-0:PersistentTopic@948] - [persistent://prop-xyz2/ns1/__change_events-partition-4] Failed to create subscription: multiTopicsReader-1b06c712cc java.util.concurrent.CompletionException: org.apache.pulsar.broker.service.BrokerServiceException: Connection was closed while the opening the cursor at java.util.concurrent.CompletableFuture.encodeRelay(CompletableFuture.java:368) ~[?:?] at java.util.concurrent.CompletableFuture.uniComposeStage(CompletableFuture.java:1189) ~[?:?] at java.util.concurrent.CompletableFuture.thenCompose(CompletableFuture.java:2309) ~[?:?] at org.apache.pulsar.broker.service.persistent.PersistentTopic.lambda$internalSubscribe$20(PersistentTopic.java:890) ~[classes/:?] at java.util.concurrent.CompletableFuture.uniComposeStage(CompletableFuture.java:1187) ~[?:?] at java.util.concurrent.CompletableFuture.thenCompose(CompletableFuture.java:2309) ~[?:?] at org.apache.pulsar.broker.service.persistent.PersistentTopic.lambda$internalSubscribe$22(PersistentTopic.java:885) ~[classes/:?] at java.util.concurrent.CompletableFuture.uniComposeStage(CompletableFuture.java:1187) ~[?:?] at java.util.concurrent.CompletableFuture.thenCompose(CompletableFuture.java:2309) ~[?:?] at org.apache.pulsar.broker.service.persistent.PersistentTopic.internalSubscribe(PersistentTopic.java:806) ~[classes/:?] at org.apache.pulsar.broker.service.persistent.PersistentTopic.subscribe(PersistentTopic.java:780) ~[classes/:?] at org.apache.pulsar.broker.service.ServerCnx.lambda$handleSubscribe$14(ServerCnx.java:1239) ~[classes/:?] at java.util.concurrent.CompletableFuture$UniCompose.tryFire(CompletableFuture.java:1150) ~[?:?] at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:510) ~[?:?] at java.util.concurrent.CompletableFuture.complete(CompletableFuture.java:2147) ~[?:?] at org.apache.pulsar.broker.service.schema.BookkeeperSchemaStorage.lambda$closeLedger$42(BookkeeperSchemaStorage.java:619) ~[classes/:?] at org.apache.bookkeeper.client.PulsarMockLedgerHandle.lambda$asyncClose$1(PulsarMockLedgerHandle.java:96) ~[testmocks-3.1.0-SNAPSHOT.jar:4.16.1] at java.util.concurrent.CompletableFuture.uniWhenComplete(CompletableFuture.java:863) ~[?:?] at java.util.concurrent.CompletableFuture$UniWhenComplete.tryFire(CompletableFuture.java:841) ~[?:?] at java.util.concurrent.CompletableFuture$Completion.run(CompletableFuture.java:482) ~[?:?] at org.apache.bookkeeper.common.util.SingleThreadExecutor.safeRunTask(SingleThreadExecutor.java:137) ~[bookkeeper-common-4.16.1.jar:4.16.1] at org.apache.bookkeeper.common.util.SingleThreadExecutor.run(SingleThreadExecutor.java:107) ~[bookkeeper-common-4.16.1.jar:4.16.1] at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) ~[netty-common-4.1.89.Final.jar:4.1.89.Final] at java.lang.Thread.run(Thread.java:833) ~[?:?] Caused by: org.apache.pulsar.broker.service.BrokerServiceException: Connection was closed while the opening the cursor at org.apache.pulsar.broker.service.persistent.PersistentTopic.lambda$internalSubscribe$19(PersistentTopic.java:914) ~[classes/:?] at java.util.concurrent.CompletableFuture.uniComposeStage(CompletableFuture.java:1187) ~[?:?] ... 22 more 2023-05-24T15:30:44,866 - WARN - [PulsarTestContext-executor-OrderedExecutor-0-0:ServerCnx@1282] - [/127.0.0.1:57364][persistent://prop-xyz2/ns1/__change_events-partition-4][multiTopicsReader-1b06c712cc] Failed to create consumer: consumerId=4, Connection was closed while the opening the cursor 2023-05-24T15:30:44,922 - INFO - [broker-client-shared-timer-2719-1:ConnectionHandler@124] - [persistent://prop-xyz2/ns1/__change_events-partition-19] [multiTopicsReader-1b06c712cc] Reconnecting after connection was closed 2023-05-24T15:30:44,922 - INFO - [broker-client-shared-timer-2719-1:ConnectionHandler@68] - [persistent://prop-xyz2/ns1/__change_events-partition-19] [multiTopicsReader-1b06c712cc] Ignoring reconnection request (state: Closed) 2023-05-24T15:30:44,923 - INFO - [broker-client-shared-timer-2719-1:ConnectionHandler@124] - [persistent://prop-xyz2/ns1/__change_events-partition-17] [multiTopicsReader-1b06c712cc] Reconnecting after connection was closed 2023-05-24T15:30:44,923 - INFO - [broker-client-shared-timer-2719-1:ConnectionHandler@68] - [persistent://prop-xyz2/ns1/__change_events-partition-17] [multiTopicsReader-1b06c712cc] Ignoring reconnection request (state: Closed) ``` I wonder if the issue is related to how system topics are deleted? -- This is an automated message from the Apache Git Service. To respond to the message, please log on to GitHub and use the URL above to go to the specific comment. To unsubscribe, e-mail: [email protected] For queries about this service, please contact Infrastructure at: [email protected]
