rob-kvietkauskas-ign opened a new issue, #20722: URL: https://github.com/apache/pulsar/issues/20722
### Search before asking - [X] I searched in the [issues](https://github.com/apache/pulsar/issues) and found nothing similar. ### Version OS: Debian 5.10.162-1 (2023-01-21) x86_64 GNU/Linux Pulsar: 2.9.1 Pulsar Built-in File Source Connector: 2.9.1 Pulsar Built-in Debezium PostgreSQL Source Connector: 2.9.1 Java: openjdk 11.0.18 2023-01-17 ### Minimal reproduce step Steps described below were performed using Ansible in order to perform identical configuration on machines of same type. This was done in order to reduce human errors. 1. Deploy a (single) cluster (of 6 machines) on bare-metal: 3 machines for brokers + bookies (both run on each machine), 3 machines for zookeepers following given instructions: https://pulsar.apache.org/docs/2.9.x/deploy-bare-metal/ 2. Adjust firewall settings on each machine to allow incoming connections to ports used by Pulsar (including TCP 4181 on broker+bookie machines); 3. Initialize distributed log metadata; 4. Adjust following settings in broker.conf: - authenticationEnabled=true - authorizationEnabled=true - authenticationProviders=org.apache.pulsar.broker.authentication.AuthenticationProviderToken - brokerClientAuthenticationPlugin=org.apache.pulsar.client.impl.auth.AuthenticationToken - brokerClientAuthenticationParameters=token:generatedTokenGoesHere - superUserRoles=superUserRoleGoesHere - anonymousUserRole=anonymousRoleGoesHere - tokenSecretKey=file://path_to_secret_key 5. Adjust following settings in client.conf: - authPlugin=org.apache.pulsar.client.impl.auth.AuthenticationToken - authParams=token:generatedTokenGoesHere 6. Set namespace permissions for existing namespaces 7. Configure functions workers in following way: 1. Use Process runtime for function worker, as it is described here: https://pulsar.apache.org/docs/2.9.x/functions-runtime/#configure-process-runtime 2. Configure run-with-brokers, as it is described here: https://pulsar.apache.org/docs/2.9.x/functions-worker/#run-functions-worker-with-brokers (numFunctionPackageReplicas – 2; initializedDlogMetadata: false; workerId – set; workerHostname – set; wokerPort – 6750; wokerPortTls – 6751, download directory – /tmp/pulsar_functions; pulsarFunctionsNamespace – public/functions; pulsarFunctionsCluster – correct one; functionMetadataTopicName – metadata; clusterCoordinationTopicName – coordinate; useCompactedMetadataTopic – false; authenticateMetricsEndpoint – false; stateStorageServiceUrl: bk://one-of-the-zookeeper-machine-addres:4181; connectorsDirectory – ./connectors; functionsDirectory – ./functions) 3. Restart bookies and brokers 4. Ensure functions wokers work as expected by performing admin/v2/worker/cluster REST Admin API call; 5. Deploy connector (tried File Source, Debezium PostgreSQL source and custom CDC sink) and configuration of it to broker machines- (to `<pulsar directory>/connectors` and `<pulsar directory>/connectors/configuration` respectively); After setup is done, navigate to `<pulsar directory>/bin` directory and perform: ./pulsar-admin sources create --archive /opt/pulsar/apache-pulsar-2.9.1/connectors/pulsar-io-file-2.9.1.nar --name file-test --destination-topic-name pulsar-file-test --source-config-file /opt/pulsar/apache-pulsar-2.9.1/connectors/configuration/file-connector.yml In case of Built-in File Source connector, configuration of it is: ``` configs: inputDirectory: "/opt/pulsar" recurse: false keepFile: true fileFilter: "[^\\.].txt" ``` Broker machine has a.txt in `/opt/pulsar` directory (readable, permissions and ownership verified) ``` ~$ cat /opt/pulsar/a.txt test ``` To clarify: - `bookkeeper.conf` has `zkServers=<list_of_actual_addresses_of_zookeper_instances>`; - `broker.conf` has `zookeeperServers=<list_of_actual_addresses_of_zookeper_instances>`; - `broker.conf` has `configurationStoreServers=<list_of_actual_addresses_of_zookeper_instances>`; - `broker.conf` has `globalZookeeperServers=<list_of_actual_addresses_of_zookeper_instances>`; - `functions_woker.yml` has `configurationStoreServers` commented-out; The cluster works fine, without any errors while `StateStorageLifecycleComponent` is not enabled in `bookkeeper.conf` on servers containing Bookkeeper. After functions worker setup is done, connectors do work in `localrun` mode (this proves that configuration of connector is valid, both for File Source and Debezium PostgreSQL Source). After `StateStorageLifecycleComponent` gets enabled, following piece reoccurs in logs (if `initializedDlogMetadata: false` – in logs of Broker, if `initializedDlogMetadata: true` – in logs of Bookkeeper): ``` Jul 05 11:29:18 pulsar[797192]: 2023-07-05T11:29:18,297+0300 [io-write-scheduler-OrderedScheduler-1-0-SendThread(localhost:2181)] INFO org.apache.zookeeper.ClientCnxn - Opening socket connection to server localhost/127.0.0.1:2181. Jul 05 11:29:18 pulsar[797192]: 2023-07-05T11:29:18,297+0300 [io-write-scheduler-OrderedScheduler-1-0-SendThread(localhost:2181)] INFO org.apache.zookeeper.ClientCnxn - SASL config status: Will not attempt to authenticate using SASL (unknown error) Jul 05 11:29:18 pulsar[797192]: 2023-07-05T11:29:18,298+0300 [io-write-scheduler-OrderedScheduler-1-0-SendThread(localhost:2181)] WARN org.apache.zookeeper.ClientCnxn - Session 0x0 for sever localhost/127.0.0.1:2181, Closing socket connection. Attempting reconnect except it is a SessionExpiredException. Jul 05 11:29:18 pulsar[797192]: java.net.ConnectException: Connection refused Jul 05 11:29:18 pulsar[797192]: at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method) ~[?:?] Jul 05 11:29:18 pulsar[797192]: at sun.nio.ch.SocketChannelImpl.finishConnect(SocketChannelImpl.java:777) ~[?:?] Jul 05 11:29:18 pulsar[797192]: at org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(ClientCnxnSocketNIO.java:344) ~[org.apache.zookeeper-zookeeper-3.6.3.jar:3.6.3] Jul 05 11:29:18 pulsar[797192]: at org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:1290) [org.apache.zookeeper-zookeeper-3.6.3.jar:3.6.3] ``` What is more, this fragment reoccurs without connector-related pulsar-admin calls. ### What did you expect to see? Connector running (succesfully created and started). ### What did you see instead? Error on allocating ledger under /pulsar/functions/public/default/<connector name>/78b1ef8d-ab3c-4deb-8b60-0579ff0ba395-<connector filename>.nar/<default>/allocation Reason: HTTP 500 Internal Server Error ### Anything else? Also, after `StateStorageLifecycleComponent` gets enabled (and `initializedDlogMetadata` is set to `false`), following piece (stream paths change) reoccurs periodically in broker logs: ``` Jul 05 11:29:23 pulsar[797192]: 2023-07-05T11:29:23,907+0300 [io-write-scheduler-OrderedScheduler-1-0] ERROR org.apache.distributedlog.bk.SimpleLedgerAllocator - Error creating ledger for allocating /stream/storage/streams_000000000000000004_000000000000000001_000000000000000000/<default>/allocation : Jul 05 11:29:23 pulsar[797192]: org.apache.distributedlog.ZooKeeperClient$ZooKeeperConnectionException: Problem connecting to servers: localhost:2181 Jul 05 11:29:23 pulsar[797192]: at org.apache.distributedlog.ZooKeeperClient.buildZooKeeper(ZooKeeperClient.java:320) ~[org.apache.distributedlog-distributedlog-core-4.14.2.jar:4.14.2] Jul 05 11:29:23 pulsar[797192]: at org.apache.distributedlog.ZooKeeperClient.get(ZooKeeperClient.java:239) ~[org.apache.distributedlog-distributedlog-core-4.14.2.jar:4.14.2] Jul 05 11:29:23 pulsar[797192]: at org.apache.distributedlog.BookKeeperClient.commonInitialization(BookKeeperClient.java:115) ~[org.apache.distributedlog-distributedlog-core-4.14.2.jar:4.14.2] Jul 05 11:29:23 pulsar[797192]: at org.apache.distributedlog.BookKeeperClient.initialize(BookKeeperClient.java:172) ~[org.apache.distributedlog-distributedlog-core-4.14.2.jar:4.14.2] Jul 05 11:29:23 pulsar[797192]: at org.apache.distributedlog.BookKeeperClient.get(BookKeeperClient.java:199) ~[org.apache.distributedlog-distributedlog-core-4.14.2.jar:4.14.2] Jul 05 11:29:23 pulsar[797192]: at org.apache.distributedlog.BookKeeperClient.createLedger(BookKeeperClient.java:211) ~[org.apache.distributedlog-distributedlog-core-4.14.2.jar:4.14.2] Jul 05 11:29:23 pulsar[797192]: at org.apache.distributedlog.bk.SimpleLedgerAllocator.allocateLedger(SimpleLedgerAllocator.java:370) ~[org.apache.distributedlog-distributedlog-core-4.14.2.jar:4.14.2] Jul 05 11:29:23 pulsar[797192]: at org.apache.distributedlog.bk.SimpleLedgerAllocator.allocate(SimpleLedgerAllocator.java:271) ~[org.apache.distributedlog-distributedlog-core-4.14.2.jar:4.14.2] Jul 05 11:29:23 pulsar[797192]: at org.apache.distributedlog.bk.LedgerAllocatorDelegator.allocate(LedgerAllocatorDelegator.java:67) ~[org.apache.distributedlog-distributedlog-core-4.14.2.jar:4.14.2] Jul 05 11:29:23 pulsar[797192]: at org.apache.distributedlog.impl.logsegment.BKLogSegmentAllocator.allocate(BKLogSegmentAllocator.java:55) ~[org.apache.distributedlog-distributedlog-core-4.14.2.jar:4.14.2] Jul 05 11:29:23 pulsar[797192]: at org.apache.distributedlog.BKLogWriteHandler.doStartLogSegment(BKLogWriteHandler.java:571) ~[org.apache.distributedlog-distributedlog-core-4.14.2.jar:4.14.2] Jul 05 11:29:23 pulsar[797192]: at org.apache.distributedlog.BKLogWriteHandler$10.onSuccess(BKLogWriteHandler.java:538) ~[org.apache.distributedlog-distributedlog-core-4.14.2.jar:4.14.2] Jul 05 11:29:23 pulsar[797192]: at org.apache.distributedlog.BKLogWriteHandler$10.onSuccess(BKLogWriteHandler.java:530) ~[org.apache.distributedlog-distributedlog-core-4.14.2.jar:4.14.2] Jul 05 11:29:23 pulsar[797192]: at org.apache.bookkeeper.common.concurrent.FutureEventListener.accept(FutureEventListener.java:42) ~[org.apache.bookkeeper-bookkeeper-common-4.14.2.jar:4.14.2] Jul 05 11:29:23 pulsar[797192]: at org.apache.bookkeeper.common.concurrent.FutureEventListener.accept(FutureEventListener.java:26) ~[org.apache.bookkeeper-bookkeeper-common-4.14.2.jar:4.14.2] Jul 05 11:29:23 pulsar[797192]: at java.util.concurrent.CompletableFuture.uniWhenComplete(CompletableFuture.java:859) ~[?:?] Jul 05 11:29:23 pulsar[797192]: at java.util.concurrent.CompletableFuture.uniWhenCompleteStage(CompletableFuture.java:883) ~[?:?] Jul 05 11:29:23 pulsar[797192]: at java.util.concurrent.CompletableFuture.whenComplete(CompletableFuture.java:2251) ~[?:?] Jul 05 11:29:23 pulsar[797192]: at org.apache.distributedlog.BKLogWriteHandler.asyncStartLogSegment(BKLogWriteHandler.java:530) ~[org.apache.distributedlog-distributedlog-core-4.14.2.jar:4.14.2] Jul 05 11:29:23 pulsar[797192]: at org.apache.distributedlog.BKAbstractLogWriter.lambda$asyncStartNewLogSegment$1(BKAbstractLogWriter.java:379) ~[org.apache.distributedlog-distributedlog-core-4.14.2.jar:4.14.2] Jul 05 11:29:23 pulsar[797192]: at java.util.concurrent.CompletableFuture.uniComposeStage(CompletableFuture.java:1106) ~[?:?] Jul 05 11:29:23 pulsar[797192]: at java.util.concurrent.CompletableFuture.thenCompose(CompletableFuture.java:2235) ~[?:?] Jul 05 11:29:23 pulsar[797192]: at org.apache.distributedlog.BKAbstractLogWriter.asyncStartNewLogSegment(BKAbstractLogWriter.java:378) ~[org.apache.distributedlog-distributedlog-core-4.14.2.jar:4.14.2] Jul 05 11:29:23 pulsar[797192]: at org.apache.distributedlog.BKAbstractLogWriter.rollLogSegmentIfNecessary(BKAbstractLogWriter.java:517) ~[org.apache.distributedlog-distributedlog-core-4.14.2.jar:4.14.2] Jul 05 11:29:23 pulsar[797192]: at org.apache.distributedlog.BKAsyncLogWriter.doGetLogSegmentWriter(BKAsyncLogWriter.java:226) ~[org.apache.distributedlog-distributedlog-core-4.14.2.jar:4.14.2] Jul 05 11:29:23 pulsar[797192]: at org.apache.distributedlog.BKAsyncLogWriter.getLogSegmentWriter(BKAsyncLogWriter.java:211) ~[org.apache.distributedlog-distributedlog-core-4.14.2.jar:4.14.2] Jul 05 11:29:23 pulsar[797192]: at org.apache.distributedlog.BKAsyncLogWriter.getLogSegmentWriter(BKAsyncLogWriter.java:249) ~[org.apache.distributedlog-distributedlog-core-4.14.2.jar:4.14.2] Jul 05 11:29:23 pulsar[797192]: at org.apache.distributedlog.BKAsyncLogWriter.rollLogSegmentAndIssuePendingRequests(BKAsyncLogWriter.java:344) ~[org.apache.distributedlog-distributedlog-core-4.14.2.jar:4.14.2] Jul 05 11:29:23 pulsar[797192]: at org.apache.distributedlog.BKAsyncLogWriter.asyncWrite(BKAsyncLogWriter.java:302) ~[org.apache.distributedlog-distributedlog-core-4.14.2.jar:4.14.2] Jul 05 11:29:23 pulsar[797192]: at org.apache.distributedlog.BKAsyncLogWriter.write(BKAsyncLogWriter.java:420) ~[org.apache.distributedlog-distributedlog-core-4.14.2.jar:4.14.2] Jul 05 11:29:23 pulsar[797192]: at org.apache.bookkeeper.statelib.impl.journal.AbstractStateStoreWithJournal.writeCommandBuf(AbstractStateStoreWithJournal.java:550) ~[org.apache.bookkeeper-statelib-4.14.2.jar:4.14.2] Jul 05 11:29:23 pulsar[797192]: at org.apache.bookkeeper.statelib.impl.journal.AbstractStateStoreWithJournal.lambda$initializeJournalWriter$6(AbstractStateStoreWithJournal.java:248) ~[org.apache.bookkeeper-statelib-4.14.2.jar:4.14.2] Jul 05 11:29:23 pulsar[797192]: at java.util.concurrent.CompletableFuture$UniCompose.tryFire(CompletableFuture.java:1072) [?:?] Jul 05 11:29:23 pulsar[797192]: at java.util.concurrent.CompletableFuture$Completion.run(CompletableFuture.java:478) [?:?] Jul 05 11:29:23 pulsar[797192]: at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) [?:?] Jul 05 11:29:23 pulsar[797192]: at java.util.concurrent.FutureTask.run(FutureTask.java:264) [?:?] Jul 05 11:29:23 pulsar[797192]: at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) [?:?] Jul 05 11:29:23 pulsar[797192]: at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?] Jul 05 11:29:23 pulsar[797192]: at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?] Jul 05 11:29:23 pulsar[797192]: at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) [io.netty-netty-common-4.1.72.Final.jar:4.1.72.Final] Jul 05 11:29:23 pulsar[797192]: at java.lang.Thread.run(Thread.java:829) [?:?] Jul 05 11:29:23 pulsar[797192]: Caused by: org.apache.zookeeper.KeeperException$ConnectionLossException: KeeperErrorCode = ConnectionLoss Jul 05 11:29:23 pulsar[797192]: at org.apache.zookeeper.KeeperException.create(KeeperException.java:102) ~[org.apache.zookeeper-zookeeper-3.6.3.jar:3.6.3] Jul 05 11:29:23 pulsar[797192]: at org.apache.bookkeeper.zookeeper.ZooKeeperWatcherBase.waitForConnection(ZooKeeperWatcherBase.java:159) ~[org.apache.bookkeeper-bookkeeper-server-4.14.2.jar:4.14.2] Jul 05 11:29:23 pulsar[797192]: at org.apache.bookkeeper.zookeeper.ZooKeeperClient$Builder.build(ZooKeeperClient.java:260) ~[org.apache.bookkeeper-bookkeeper-server-4.14.2.jar:4.14.2] Jul 05 11:29:23 pulsar[797192]: at org.apache.distributedlog.ZooKeeperClient.buildZooKeeper(ZooKeeperClient.java:318) ~[org.apache.distributedlog-distributedlog-core-4.14.2.jar:4.14.2] Jul 05 11:29:23 pulsar[797192]: ... 40 more Jul 05 11:29:23 pulsar[797192]: 2023-07-05T11:29:23,908+0300 [io-write-scheduler-OrderedScheduler-1-0] INFO org.apache.distributedlog.bk.SimpleLedgerAllocator - Ledger allocator /stream/storage/streams_000000000000000004_000000000000000001_000000000000000000/<default>/allocation moved to phase ERROR : version = 0. Jul 05 11:29:23 pulsar[797192]: 2023-07-05T11:29:23,908+0300 [io-write-scheduler-OrderedScheduler-1-0-EventThread] INFO org.apache.zookeeper.ClientCnxn - EventThread shut down for session: 0x0 Jul 05 11:29:23 pulsar[797192]: 2023-07-05T11:29:23,908+0300 [io-write-scheduler-OrderedScheduler-1-0] INFO org.apache.bookkeeper.stream.storage.impl.store.MVCCStoreFactoryImpl - Clearing resources hold by stream(1)/range(0) at storage container (4) Jul 05 11:29:23 pulsar[797192]: 2023-07-05T11:29:23,908+0300 [io-write-scheduler-OrderedScheduler-1-0] WARN org.apache.bookkeeper.stream.storage.impl.sc.StorageContainerRegistryImpl - De-registered StorageContainer ('4') when failed to start Jul 05 11:29:23 pulsar[797192]: java.util.concurrent.CompletionException: org.apache.distributedlog.bk.SimpleLedgerAllocator$AllocationException: Error on allocating ledger under /stream/storage/streams_000000000000000004_000000000000000001_000000000000000000/<default>/allocation Jul 05 11:29:23 pulsar[797192]: at java.util.concurrent.CompletableFuture.encodeThrowable(CompletableFuture.java:331) ~[?:?] Jul 05 11:29:23 pulsar[797192]: at java.util.concurrent.CompletableFuture.uniApplyNow(CompletableFuture.java:670) ~[?:?] Jul 05 11:29:23 pulsar[797192]: at java.util.concurrent.CompletableFuture.uniApplyStage(CompletableFuture.java:658) [?:?] Jul 05 11:29:23 pulsar[797192]: at java.util.concurrent.CompletableFuture.thenApply(CompletableFuture.java:2094) [?:?] Jul 05 11:29:23 pulsar[797192]: at org.apache.distributedlog.BKAsyncLogWriter.asyncWrite(BKAsyncLogWriter.java:309) ~[org.apache.distributedlog-distributedlog-core-4.14.2.jar:4.14.2] Jul 05 11:29:23 pulsar[797192]: at org.apache.distributedlog.BKAsyncLogWriter.write(BKAsyncLogWriter.java:420) ~[org.apache.distributedlog-distributedlog-core-4.14.2.jar:4.14.2] Jul 05 11:29:23 pulsar[797192]: at org.apache.bookkeeper.statelib.impl.journal.AbstractStateStoreWithJournal.writeCommandBuf(AbstractStateStoreWithJournal.java:550) ~[org.apache.bookkeeper-statelib-4.14.2.jar:4.14.2] Jul 05 11:29:23 pulsar[797192]: at org.apache.bookkeeper.statelib.impl.journal.AbstractStateStoreWithJournal.lambda$initializeJournalWriter$6(AbstractStateStoreWithJournal.java:248) ~[org.apache.bookkeeper-statelib-4.14.2.jar:4.14.2] Jul 05 11:29:23 pulsar[797192]: at java.util.concurrent.CompletableFuture$UniCompose.tryFire(CompletableFuture.java:1072) [?:?] Jul 05 11:29:23 pulsar[797192]: at java.util.concurrent.CompletableFuture$Completion.run(CompletableFuture.java:478) [?:?] Jul 05 11:29:23 pulsar[797192]: at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) [?:?] Jul 05 11:29:23 pulsar[797192]: at java.util.concurrent.FutureTask.run(FutureTask.java:264) [?:?] Jul 05 11:29:23 pulsar[797192]: at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) [?:?] Jul 05 11:29:23 pulsar[797192]: at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?] Jul 05 11:29:23 pulsar[797192]: at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?] Jul 05 11:29:23 pulsar[797192]: at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) [io.netty-netty-common-4.1.72.Final.jar:4.1.72.Final] Jul 05 11:29:23 pulsar[797192]: at java.lang.Thread.run(Thread.java:829) [?:?] Jul 05 11:29:23 pulsar[797192]: Caused by: org.apache.distributedlog.bk.SimpleLedgerAllocator$AllocationException: Error on allocating ledger under /stream/storage/streams_000000000000000004_000000000000000001_000000000000000000/<default>/allocation Jul 05 11:29:23 pulsar[797192]: at org.apache.distributedlog.bk.SimpleLedgerAllocator.tryObtain(SimpleLedgerAllocator.java:279) ~[org.apache.distributedlog-distributedlog-core-4.14.2.jar:4.14.2] Jul 05 11:29:23 pulsar[797192]: at org.apache.distributedlog.bk.LedgerAllocatorDelegator.tryObtain(LedgerAllocatorDelegator.java:73) ~[org.apache.distributedlog-distributedlog-core-4.14.2.jar:4.14.2] Jul 05 11:29:23 pulsar[797192]: at org.apache.distributedlog.impl.logsegment.BKLogSegmentAllocator.tryObtain(BKLogSegmentAllocator.java:61) ~[org.apache.distributedlog-distributedlog-core-4.14.2.jar:4.14.2] Jul 05 11:29:23 pulsar[797192]: at org.apache.distributedlog.BKLogWriteHandler.doStartLogSegment(BKLogWriteHandler.java:589) ~[org.apache.distributedlog-distributedlog-core-4.14.2.jar:4.14.2] Jul 05 11:29:23 pulsar[797192]: at org.apache.distributedlog.BKLogWriteHandler$10.onSuccess(BKLogWriteHandler.java:538) ~[org.apache.distributedlog-distributedlog-core-4.14.2.jar:4.14.2] Jul 05 11:29:23 pulsar[797192]: at org.apache.distributedlog.BKLogWriteHandler$10.onSuccess(BKLogWriteHandler.java:530) ~[org.apache.distributedlog-distributedlog-core-4.14.2.jar:4.14.2] Jul 05 11:29:23 pulsar[797192]: at org.apache.bookkeeper.common.concurrent.FutureEventListener.accept(FutureEventListener.java:42) ~[org.apache.bookkeeper-bookkeeper-common-4.14.2.jar:4.14.2] Jul 05 11:29:23 pulsar[797192]: at org.apache.bookkeeper.common.concurrent.FutureEventListener.accept(FutureEventListener.java:26) ~[org.apache.bookkeeper-bookkeeper-common-4.14.2.jar:4.14.2] Jul 05 11:29:23 pulsar[797192]: at java.util.concurrent.CompletableFuture.uniWhenComplete(CompletableFuture.java:859) ~[?:?] Jul 05 11:29:23 pulsar[797192]: at java.util.concurrent.CompletableFuture.uniWhenCompleteStage(CompletableFuture.java:883) ~[?:?] Jul 05 11:29:23 pulsar[797192]: at java.util.concurrent.CompletableFuture.whenComplete(CompletableFuture.java:2251) ~[?:?] Jul 05 11:29:23 pulsar[797192]: at org.apache.distributedlog.BKLogWriteHandler.asyncStartLogSegment(BKLogWriteHandler.java:530) ~[org.apache.distributedlog-distributedlog-core-4.14.2.jar:4.14.2] Jul 05 11:29:23 pulsar[797192]: at org.apache.distributedlog.BKAbstractLogWriter.lambda$asyncStartNewLogSegment$1(BKAbstractLogWriter.java:379) ~[org.apache.distributedlog-distributedlog-core-4.14.2.jar:4.14.2] Jul 05 11:29:23 pulsar[797192]: at java.util.concurrent.CompletableFuture.uniComposeStage(CompletableFuture.java:1106) ~[?:?] Jul 05 11:29:23 pulsar[797192]: at java.util.concurrent.CompletableFuture.thenCompose(CompletableFuture.java:2235) ~[?:?] Jul 05 11:29:23 pulsar[797192]: at org.apache.distributedlog.BKAbstractLogWriter.asyncStartNewLogSegment(BKAbstractLogWriter.java:378) ~[org.apache.distributedlog-distributedlog-core-4.14.2.jar:4.14.2] Jul 05 11:29:23 pulsar[797192]: at org.apache.distributedlog.BKAbstractLogWriter.rollLogSegmentIfNecessary(BKAbstractLogWriter.java:517) ~[org.apache.distributedlog-distributedlog-core-4.14.2.jar:4.14.2] Jul 05 11:29:23 pulsar[797192]: at org.apache.distributedlog.BKAsyncLogWriter.doGetLogSegmentWriter(BKAsyncLogWriter.java:226) ~[org.apache.distributedlog-distributedlog-core-4.14.2.jar:4.14.2] Jul 05 11:29:23 pulsar[797192]: at org.apache.distributedlog.BKAsyncLogWriter.getLogSegmentWriter(BKAsyncLogWriter.java:211) ~[org.apache.distributedlog-distributedlog-core-4.14.2.jar:4.14.2] Jul 05 11:29:23 pulsar[797192]: at org.apache.distributedlog.BKAsyncLogWriter.getLogSegmentWriter(BKAsyncLogWriter.java:249) ~[org.apache.distributedlog-distributedlog-core-4.14.2.jar:4.14.2] Jul 05 11:29:23 pulsar[797192]: at org.apache.distributedlog.BKAsyncLogWriter.rollLogSegmentAndIssuePendingRequests(BKAsyncLogWriter.java:344) ~[org.apache.distributedlog-distributedlog-core-4.14.2.jar:4.14.2] Jul 05 11:29:23 pulsar[797192]: at org.apache.distributedlog.BKAsyncLogWriter.asyncWrite(BKAsyncLogWriter.java:302) ~[org.apache.distributedlog-distributedlog-core-4.14.2.jar:4.14.2] Jul 05 11:29:23 pulsar[797192]: ... 12 more Jul 05 11:29:23 pulsar[797192]: 2023-07-05T11:29:23,908+0300 [io-write-scheduler-OrderedScheduler-1-0] INFO org.apache.bookkeeper.stream.storage.impl.sc.StorageContainerRegistryImpl - Release resources hold by StorageContainer ('4') during de-register Jul 05 11:29:23 pulsar[797192]: 2023-07-05T11:29:23,908+0300 [io-write-scheduler-OrderedScheduler-1-0] INFO org.apache.bookkeeper.stream.storage.impl.sc.StorageContainerImpl - Stopping storage container (4) ... Jul 05 11:29:23 pulsar[797192]: 2023-07-05T11:29:23,909+0300 [DLM-/stream/storage-OrderedScheduler-0-0] INFO org.apache.zookeeper.ZooKeeper - Initiating client connection, connectString=localhost:2181 sessionTimeout=30000 watcher=org.apache.bookkeeper.zookeeper.ZooKeeperWatcherBase@27f4e436 Jul 05 11:29:23 pulsar[797192]: 2023-07-05T11:29:23,909+0300 [DLM-/stream/storage-OrderedScheduler-0-0] INFO org.apache.zookeeper.ClientCnxnSocket - jute.maxbuffer value is 10485760 Bytes Jul 05 11:29:23 pulsar[797192]: 2023-07-05T11:29:23,909+0300 [DLM-/stream/storage-OrderedScheduler-0-0] INFO org.apache.zookeeper.ClientCnxn - zookeeper.request.timeout value is 0. feature enabled=false Jul 05 11:29:23 pulsar[797192]: 2023-07-05T11:29:23,918+0300 [io-write-scheduler-OrderedScheduler-1-0] INFO org.apache.bookkeeper.stream.storage.impl.store.MVCCStoreFactoryImpl - scStores for 4 on store factory is null, return directly Jul 05 11:29:23 pulsar[797192]: 2023-07-05T11:29:23,918+0300 [io-write-scheduler-OrderedScheduler-1-0] INFO org.apache.bookkeeper.stream.storage.impl.sc.StorageContainerImpl - Successfully stopped storage container (4). Jul 05 11:29:23 pulsar[797192]: 2023-07-05T11:29:23,918+0300 [io-write-scheduler-OrderedScheduler-1-0] WARN org.apache.bookkeeper.stream.storage.impl.sc.ZkStorageContainerManager - Failed to start storage container (4) Jul 05 11:29:23 pulsar[797192]: java.util.concurrent.CompletionException: org.apache.distributedlog.bk.SimpleLedgerAllocator$AllocationException: Error on allocating ledger under /stream/storage/streams_000000000000000004_000000000000000001_000000000000000000/<default>/allocation Jul 05 11:29:23 pulsar[797192]: at java.util.concurrent.CompletableFuture.encodeThrowable(CompletableFuture.java:331) ~[?:?] Jul 05 11:29:23 pulsar[797192]: at java.util.concurrent.CompletableFuture.uniApplyNow(CompletableFuture.java:670) ~[?:?] Jul 05 11:29:23 pulsar[797192]: at java.util.concurrent.CompletableFuture.uniApplyStage(CompletableFuture.java:658) [?:?] Jul 05 11:29:23 pulsar[797192]: at java.util.concurrent.CompletableFuture.thenApply(CompletableFuture.java:2094) [?:?] Jul 05 11:29:23 pulsar[797192]: at org.apache.distributedlog.BKAsyncLogWriter.asyncWrite(BKAsyncLogWriter.java:309) ~[org.apache.distributedlog-distributedlog-core-4.14.2.jar:4.14.2] Jul 05 11:29:23 pulsar[797192]: at org.apache.distributedlog.BKAsyncLogWriter.write(BKAsyncLogWriter.java:420) ~[org.apache.distributedlog-distributedlog-core-4.14.2.jar:4.14.2] Jul 05 11:29:23 pulsar[797192]: at org.apache.bookkeeper.statelib.impl.journal.AbstractStateStoreWithJournal.writeCommandBuf(AbstractStateStoreWithJournal.java:550) ~[org.apache.bookkeeper-statelib-4.14.2.jar:4.14.2] Jul 05 11:29:23 pulsar[797192]: at org.apache.bookkeeper.statelib.impl.journal.AbstractStateStoreWithJournal.lambda$initializeJournalWriter$6(AbstractStateStoreWithJournal.java:248) ~[org.apache.bookkeeper-statelib-4.14.2.jar:4.14.2] Jul 05 11:29:23 pulsar[797192]: at java.util.concurrent.CompletableFuture$UniCompose.tryFire(CompletableFuture.java:1072) [?:?] Jul 05 11:29:23 pulsar[797192]: at java.util.concurrent.CompletableFuture$Completion.run(CompletableFuture.java:478) [?:?] Jul 05 11:29:23 pulsar[797192]: at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) [?:?] Jul 05 11:29:23 pulsar[797192]: at java.util.concurrent.FutureTask.run(FutureTask.java:264) [?:?] Jul 05 11:29:23 pulsar[797192]: at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) [?:?] Jul 05 11:29:23 pulsar[797192]: at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?] Jul 05 11:29:23 pulsar[797192]: at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?] Jul 05 11:29:23 pulsar[797192]: at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) [io.netty-netty-common-4.1.72.Final.jar:4.1.72.Final] Jul 05 11:29:23 pulsar[797192]: at java.lang.Thread.run(Thread.java:829) [?:?] Jul 05 11:29:23 pulsar[797192]: Caused by: org.apache.distributedlog.bk.SimpleLedgerAllocator$AllocationException: Error on allocating ledger under /stream/storage/streams_000000000000000004_000000000000000001_000000000000000000/<default>/allocation Jul 05 11:29:23 pulsar[797192]: at org.apache.distributedlog.bk.SimpleLedgerAllocator.tryObtain(SimpleLedgerAllocator.java:279) ~[org.apache.distributedlog-distributedlog-core-4.14.2.jar:4.14.2] Jul 05 11:29:23 pulsar[797192]: at org.apache.distributedlog.bk.LedgerAllocatorDelegator.tryObtain(LedgerAllocatorDelegator.java:73) ~[org.apache.distributedlog-distributedlog-core-4.14.2.jar:4.14.2] Jul 05 11:29:23 pulsar[797192]: at org.apache.distributedlog.impl.logsegment.BKLogSegmentAllocator.tryObtain(BKLogSegmentAllocator.java:61) ~[org.apache.distributedlog-distributedlog-core-4.14.2.jar:4.14.2] Jul 05 11:29:23 pulsar[797192]: at org.apache.distributedlog.BKLogWriteHandler.doStartLogSegment(BKLogWriteHandler.java:589) ~[org.apache.distributedlog-distributedlog-core-4.14.2.jar:4.14.2] Jul 05 11:29:23 pulsar[797192]: at org.apache.distributedlog.BKLogWriteHandler$10.onSuccess(BKLogWriteHandler.java:538) ~[org.apache.distributedlog-distributedlog-core-4.14.2.jar:4.14.2] Jul 05 11:29:23 pulsar[797192]: at org.apache.distributedlog.BKLogWriteHandler$10.onSuccess(BKLogWriteHandler.java:530) ~[org.apache.distributedlog-distributedlog-core-4.14.2.jar:4.14.2] Jul 05 11:29:23 pulsar[797192]: at org.apache.bookkeeper.common.concurrent.FutureEventListener.accept(FutureEventListener.java:42) ~[org.apache.bookkeeper-bookkeeper-common-4.14.2.jar:4.14.2] Jul 05 11:29:23 pulsar[797192]: at org.apache.bookkeeper.common.concurrent.FutureEventListener.accept(FutureEventListener.java:26) ~[org.apache.bookkeeper-bookkeeper-common-4.14.2.jar:4.14.2] Jul 05 11:29:23 pulsar[797192]: at java.util.concurrent.CompletableFuture.uniWhenComplete(CompletableFuture.java:859) ~[?:?] Jul 05 11:29:23 pulsar[797192]: at java.util.concurrent.CompletableFuture.uniWhenCompleteStage(CompletableFuture.java:883) ~[?:?] Jul 05 11:29:23 pulsar[797192]: at java.util.concurrent.CompletableFuture.whenComplete(CompletableFuture.java:2251) ~[?:?] Jul 05 11:29:23 pulsar[797192]: at org.apache.distributedlog.BKLogWriteHandler.asyncStartLogSegment(BKLogWriteHandler.java:530) ~[org.apache.distributedlog-distributedlog-core-4.14.2.jar:4.14.2] Jul 05 11:29:23 pulsar[797192]: at org.apache.distributedlog.BKAbstractLogWriter.lambda$asyncStartNewLogSegment$1(BKAbstractLogWriter.java:379) ~[org.apache.distributedlog-distributedlog-core-4.14.2.jar:4.14.2] Jul 05 11:29:23 pulsar[797192]: at java.util.concurrent.CompletableFuture.uniComposeStage(CompletableFuture.java:1106) ~[?:?] Jul 05 11:29:23 pulsar[797192]: at java.util.concurrent.CompletableFuture.thenCompose(CompletableFuture.java:2235) ~[?:?] Jul 05 11:29:23 pulsar[797192]: at org.apache.distributedlog.BKAbstractLogWriter.asyncStartNewLogSegment(BKAbstractLogWriter.java:378) ~[org.apache.distributedlog-distributedlog-core-4.14.2.jar:4.14.2] Jul 05 11:29:23 pulsar[797192]: at org.apache.distributedlog.BKAbstractLogWriter.rollLogSegmentIfNecessary(BKAbstractLogWriter.java:517) ~[org.apache.distributedlog-distributedlog-core-4.14.2.jar:4.14.2] Jul 05 11:29:23 pulsar[797192]: at org.apache.distributedlog.BKAsyncLogWriter.doGetLogSegmentWriter(BKAsyncLogWriter.java:226) ~[org.apache.distributedlog-distributedlog-core-4.14.2.jar:4.14.2] Jul 05 11:29:23 pulsar[797192]: at org.apache.distributedlog.BKAsyncLogWriter.getLogSegmentWriter(BKAsyncLogWriter.java:211) ~[org.apache.distributedlog-distributedlog-core-4.14.2.jar:4.14.2] Jul 05 11:29:23 pulsar[797192]: at org.apache.distributedlog.BKAsyncLogWriter.getLogSegmentWriter(BKAsyncLogWriter.java:249) ~[org.apache.distributedlog-distributedlog-core-4.14.2.jar:4.14.2] Jul 05 11:29:23 pulsar[797192]: at org.apache.distributedlog.BKAsyncLogWriter.rollLogSegmentAndIssuePendingRequests(BKAsyncLogWriter.java:344) ~[org.apache.distributedlog-distributedlog-core-4.14.2.jar:4.14.2] Jul 05 11:29:23 pulsar[797192]: at org.apache.distributedlog.BKAsyncLogWriter.asyncWrite(BKAsyncLogWriter.java:302) ~[org.apache.distributedlog-distributedlog-core-4.14.2.jar:4.14.2] Jul 05 11:29:23 pulsar[797192]: ... 12 more ``` If `StateStorageLifecycleComponent` gets enabled (and `initializedDlogMetadata` is set to `false`), following piece (stream paths change) occurs in logs when `pulsar-admin sources create` is called: ``` Jul 05 15:51:50 pulsar[96898]: 2023-07-05T15:51:50,642+0300 [DLM-/pulsar/functions-OrderedScheduler-0-0] INFO org.apache.distributedlog.bk.SimpleLedgerAllocator - Ledger allocator /pulsar/functions/public/default/file-test/67849712-9304-4be3-819c-991577feb171-pulsar-io-file-2.9.1.nar/<default>/allocation moved to phase ALLOCATING : version = 0. Jul 05 15:51:50 pulsar[96898]: 2023-07-05T15:51:50,647+0300 [DLM-/pulsar/functions-OrderedScheduler-0-0] INFO org.apache.zookeeper.ZooKeeper - Initiating client connection, connectString=localhost:2181 sessionTimeout=30000 watcher=org.apache.bookkeeper.zookeeper.ZooKeeperWatcherBase@5d5a5173 Jul 05 15:51:50 pulsar[96898]: 2023-07-05T15:51:50,647+0300 [DLM-/pulsar/functions-OrderedScheduler-0-0] INFO org.apache.zookeeper.ClientCnxnSocket - jute.maxbuffer value is 10485760 Bytes Jul 05 15:51:50 pulsar[96898]: 2023-07-05T15:51:50,648+0300 [DLM-/pulsar/functions-OrderedScheduler-0-0] INFO org.apache.zookeeper.ClientCnxn - zookeeper.request.timeout value is 0. feature enabled=false Jul 05 15:51:50 pulsar[96898]: 2023-07-05T15:51:50,658+0300 [DLM-/pulsar/functions-OrderedScheduler-0-0-SendThread(localhost:2181)] INFO org.apache.zookeeper.ClientCnxn - Opening socket connection to server localhost/127.0.0.1:2181. Jul 05 15:51:50 pulsar[96898]: 2023-07-05T15:51:50,659+0300 [DLM-/pulsar/functions-OrderedScheduler-0-0-SendThread(localhost:2181)] INFO org.apache.zookeeper.ClientCnxn - SASL config status: Will not attempt to authenticate using SASL (unknown error) Jul 05 15:51:50 audit[96898]: SYSCALL arch=c000003e syscall=41 success=yes exit=533 a0=2 a1=1 a2=0 a3=7f50a0807a01 items=0 ppid=1 pid=96898 auid=4294967295 uid=1008 gid=1008 euid=1008 suid=1008 fsuid=1008 egid=1008 sgid=1008 fsgid=1008 tty=(none) ses=4294967295 comm="DLM-/pulsar/fun" exe="/usr/lib/jvm/java-11-openjdk-amd64/bin/java" subj=unconfined key="mdatp" Jul 05 15:51:50 audit[96898]: SYSCALL arch=c000003e syscall=42 success=no exit=-115 a0=215 a1=7f5042273490 a2=10 a3=b52 items=0 ppid=1 pid=96898 auid=4294967295 uid=1008 gid=1008 euid=1008 suid=1008 fsuid=1008 egid=1008 sgid=1008 fsgid=1008 tty=(none) ses=4294967295 comm="DLM-/pulsar/fun" exe="/usr/lib/jvm/java-11-openjdk-amd64/bin/java" subj=unconfined key="mdatp" Jul 05 15:51:50 pulsar[96898]: 2023-07-05T15:51:50,661+0300 [DLM-/pulsar/functions-OrderedScheduler-0-0-SendThread(localhost:2181)] WARN org.apache.zookeeper.ClientCnxn - Session 0x0 for sever localhost/127.0.0.1:2181, Closing socket connection. Attempting reconnect except it is a SessionExpiredException. Jul 05 15:51:50 pulsar[96898]: java.net.ConnectException: Connection refused Jul 05 15:51:50 pulsar[96898]: at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method) ~[?:?] Jul 05 15:51:50 pulsar[96898]: at sun.nio.ch.SocketChannelImpl.finishConnect(SocketChannelImpl.java:777) ~[?:?] Jul 05 15:51:50 pulsar[96898]: at org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(ClientCnxnSocketNIO.java:344) ~[org.apache.zookeeper-zookeeper-3.6.3.jar:3.6.3] Jul 05 15:51:50 pulsar[96898]: at org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:1290) [org.apache.zookeeper-zookeeper-3.6.3.jar:3.6.3] ... Jul 05 15:52:21 pulsar[96898]: 2023-07-05T15:52:21,550+0300 [DLM-/pulsar/functions-OrderedScheduler-0-0-SendThread(localhost:2181)] INFO org.apache.zookeeper.ClientCnxn - Opening socket connection to server localhost/127.0.0.1:2181. Jul 05 15:52:21 pulsar[96898]: 2023-07-05T15:52:21,551+0300 [DLM-/pulsar/functions-OrderedScheduler-0-0-SendThread(localhost:2181)] INFO org.apache.zookeeper.ClientCnxn - SASL config status: Will not attempt to authenticate using SASL (unknown error) Jul 05 15:52:21 audit[96898]: SYSCALL arch=c000003e syscall=41 success=yes exit=537 a0=2 a1=1 a2=0 a3=7f50a0807a01 items=0 ppid=1 pid=96898 auid=4294967295 uid=1008 gid=1008 euid=1008 suid=1008 fsuid=1008 egid=1008 sgid=1008 fsgid=1008 tty=(none) ses=4294967295 comm="DLM-/pulsar/fun" exe="/usr/lib/jvm/java-11-openjdk-amd64/bin/java" subj=unconfined key="mdatp" Jul 05 15:52:21 audit[96898]: SYSCALL arch=c000003e syscall=42 success=no exit=-115 a0=219 a1=7f5042273490 a2=10 a3=bcc items=0 ppid=1 pid=96898 auid=4294967295 uid=1008 gid=1008 euid=1008 suid=1008 fsuid=1008 egid=1008 sgid=1008 fsgid=1008 tty=(none) ses=4294967295 comm="DLM-/pulsar/fun" exe="/usr/lib/jvm/java-11-openjdk-amd64/bin/java" subj=unconfined key="mdatp" Jul 05 15:52:21 pulsar[96898]: 2023-07-05T15:52:21,552+0300 [DLM-/pulsar/functions-OrderedScheduler-0-0-SendThread(localhost:2181)] WARN org.apache.zookeeper.ClientCnxn - An exception was thrown while closing send thread for session 0x0. Jul 05 15:52:21 pulsar[96898]: java.net.ConnectException: Connection refused Jul 05 15:52:21 pulsar[96898]: at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method) ~[?:?] Jul 05 15:52:21 pulsar[96898]: at sun.nio.ch.SocketChannelImpl.finishConnect(SocketChannelImpl.java:777) ~[?:?] Jul 05 15:52:21 pulsar[96898]: at org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(ClientCnxnSocketNIO.java:344) ~[org.apache.zookeeper-zookeeper-3.6.3.jar:3.6.3] Jul 05 15:52:21 pulsar[96898]: at org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:1290) [org.apache.zookeeper-zookeeper-3.6.3.jar:3.6.3] Jul 05 15:52:21 pulsar[96898]: 2023-07-05T15:52:21,655+0300 [DLM-/pulsar/functions-OrderedScheduler-0-0] INFO org.apache.zookeeper.ZooKeeper - Session: 0x0 closed Jul 05 15:52:21 pulsar[96898]: 2023-07-05T15:52:21,656+0300 [DLM-/pulsar/functions-OrderedScheduler-0-0-EventThread] INFO org.apache.zookeeper.ClientCnxn - EventThread shut down for session: 0x0 Jul 05 15:52:21 pulsar[96898]: 2023-07-05T15:52:21,657+0300 [DLM-/pulsar/functions-OrderedScheduler-0-0] ERROR org.apache.distributedlog.bk.SimpleLedgerAllocator - Error creating ledger for allocating /pulsar/functions/public/default/file-test/67849712-9304-4be3-819c-991577feb171-pulsar-io-file-2.9.1.nar/<default>/allocation : Jul 05 15:52:21 pulsar[96898]: org.apache.distributedlog.ZooKeeperClient$ZooKeeperConnectionException: Problem connecting to servers: localhost:2181 Jul 05 15:52:21 pulsar[96898]: at org.apache.distributedlog.ZooKeeperClient.buildZooKeeper(ZooKeeperClient.java:320) ~[org.apache.distributedlog-distributedlog-core-4.14.2.jar:4.14.2] Jul 05 15:52:21 pulsar[96898]: at org.apache.distributedlog.ZooKeeperClient.get(ZooKeeperClient.java:239) ~[org.apache.distributedlog-distributedlog-core-4.14.2.jar:4.14.2] Jul 05 15:52:21 pulsar[96898]: at org.apache.distributedlog.BookKeeperClient.commonInitialization(BookKeeperClient.java:115) ~[org.apache.distributedlog-distributedlog-core-4.14.2.jar:4.14.2] Jul 05 15:52:21 pulsar[96898]: at org.apache.distributedlog.BookKeeperClient.initialize(BookKeeperClient.java:172) ~[org.apache.distributedlog-distributedlog-core-4.14.2.jar:4.14.2] Jul 05 15:52:21 pulsar[96898]: at org.apache.distributedlog.BookKeeperClient.get(BookKeeperClient.java:199) ~[org.apache.distributedlog-distributedlog-core-4.14.2.jar:4.14.2] Jul 05 15:52:21 pulsar[96898]: at org.apache.distributedlog.BookKeeperClient.createLedger(BookKeeperClient.java:211) ~[org.apache.distributedlog-distributedlog-core-4.14.2.jar:4.14.2] Jul 05 15:52:21 pulsar[96898]: at org.apache.distributedlog.bk.SimpleLedgerAllocator.allocateLedger(SimpleLedgerAllocator.java:370) ~[org.apache.distributedlog-distributedlog-core-4.14.2.jar:4.14.2] Jul 05 15:52:21 pulsar[96898]: at org.apache.distributedlog.bk.SimpleLedgerAllocator.allocate(SimpleLedgerAllocator.java:271) ~[org.apache.distributedlog-distributedlog-core-4.14.2.jar:4.14.2] Jul 05 15:52:21 pulsar[96898]: at org.apache.distributedlog.bk.LedgerAllocatorDelegator.allocate(LedgerAllocatorDelegator.java:67) ~[org.apache.distributedlog-distributedlog-core-4.14.2.jar:4.14.2] Jul 05 15:52:21 pulsar[96898]: at org.apache.distributedlog.impl.logsegment.BKLogSegmentAllocator.allocate(BKLogSegmentAllocator.java:55) ~[org.apache.distributedlog-distributedlog-core-4.14.2.jar:4.14.2] Jul 05 15:52:21 pulsar[96898]: at org.apache.distributedlog.BKLogWriteHandler.doStartLogSegment(BKLogWriteHandler.java:571) ~[org.apache.distributedlog-distributedlog-core-4.14.2.jar:4.14.2] Jul 05 15:52:21 pulsar[96898]: at org.apache.distributedlog.BKLogWriteHandler$10.onSuccess(BKLogWriteHandler.java:538) ~[org.apache.distributedlog-distributedlog-core-4.14.2.jar:4.14.2] Jul 05 15:52:21 pulsar[96898]: at org.apache.distributedlog.BKLogWriteHandler$10.onSuccess(BKLogWriteHandler.java:530) ~[org.apache.distributedlog-distributedlog-core-4.14.2.jar:4.14.2] Jul 05 15:52:21 pulsar[96898]: at org.apache.bookkeeper.common.concurrent.FutureEventListener.accept(FutureEventListener.java:42) ~[org.apache.bookkeeper-bookkeeper-common-4.14.2.jar:4.14.2] Jul 05 15:52:21 pulsar[96898]: at org.apache.bookkeeper.common.concurrent.FutureEventListener.accept(FutureEventListener.java:26) ~[org.apache.bookkeeper-bookkeeper-common-4.14.2.jar:4.14.2] Jul 05 15:52:21 pulsar[96898]: at java.util.concurrent.CompletableFuture.uniWhenComplete(CompletableFuture.java:859) ~[?:?] Jul 05 15:52:21 pulsar[96898]: at java.util.concurrent.CompletableFuture.uniWhenCompleteStage(CompletableFuture.java:883) ~[?:?] Jul 05 15:52:21 pulsar[96898]: at java.util.concurrent.CompletableFuture.whenComplete(CompletableFuture.java:2251) ~[?:?] Jul 05 15:52:21 pulsar[96898]: at org.apache.distributedlog.BKLogWriteHandler.asyncStartLogSegment(BKLogWriteHandler.java:530) ~[org.apache.distributedlog-distributedlog-core-4.14.2.jar:4.14.2] Jul 05 15:52:21 pulsar[96898]: at org.apache.distributedlog.BKAbstractLogWriter.lambda$asyncStartNewLogSegment$1(BKAbstractLogWriter.java:379) ~[org.apache.distributedlog-distributedlog-core-4.14.2.jar:4.14.2] Jul 05 15:52:21 pulsar[96898]: at java.util.concurrent.CompletableFuture$UniCompose.tryFire(CompletableFuture.java:1072) [?:?] Jul 05 15:52:21 pulsar[96898]: at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:506) [?:?] Jul 05 15:52:21 pulsar[96898]: at java.util.concurrent.CompletableFuture.complete(CompletableFuture.java:2073) [?:?] Jul 05 15:52:21 pulsar[96898]: at org.apache.bookkeeper.common.concurrent.FutureUtils$ListFutureProcessor.run(FutureUtils.java:229) [org.apache.bookkeeper-bookkeeper-common-4.14.2.jar:4.14.2] Jul 05 15:52:21 pulsar[96898]: at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) [?:?] Jul 05 15:52:21 pulsar[96898]: at com.google.common.util.concurrent.TrustedListenableFutureTask$TrustedFutureInterruptibleTask.runInterruptibly(TrustedListenableFutureTask.java:125) [com.google.guava-guava-30.1-jre.jar:?] Jul 05 15:52:21 pulsar[96898]: at com.google.common.util.concurrent.InterruptibleTask.run(InterruptibleTask.java:69) [com.google.guava-guava-30.1-jre.jar:?] Jul 05 15:52:21 pulsar[96898]: at com.google.common.util.concurrent.TrustedListenableFutureTask.run(TrustedListenableFutureTask.java:78) [com.google.guava-guava-30.1-jre.jar:?] Jul 05 15:52:21 pulsar[96898]: at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) [?:?] Jul 05 15:52:21 pulsar[96898]: at java.util.concurrent.FutureTask.run(FutureTask.java:264) [?:?] Jul 05 15:52:21 pulsar[96898]: at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) [?:?] Jul 05 15:52:21 pulsar[96898]: at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?] Jul 05 15:52:21 pulsar[96898]: at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?] Jul 05 15:52:21 pulsar[96898]: at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) [io.netty-netty-common-4.1.72.Final.jar:4.1.72.Final] Jul 05 15:52:21 pulsar[96898]: at java.lang.Thread.run(Thread.java:829) [?:?] Jul 05 15:52:21 pulsar[96898]: Caused by: org.apache.zookeeper.KeeperException$ConnectionLossException: KeeperErrorCode = ConnectionLoss Jul 05 15:52:21 pulsar[96898]: at org.apache.zookeeper.KeeperException.create(KeeperException.java:102) ~[org.apache.zookeeper-zookeeper-3.6.3.jar:3.6.3] Jul 05 15:52:21 pulsar[96898]: at org.apache.bookkeeper.zookeeper.ZooKeeperWatcherBase.waitForConnection(ZooKeeperWatcherBase.java:159) ~[org.apache.bookkeeper-bookkeeper-server-4.14.2.jar:4.14.2] Jul 05 15:52:21 pulsar[96898]: at org.apache.bookkeeper.zookeeper.ZooKeeperClient$Builder.build(ZooKeeperClient.java:260) ~[org.apache.bookkeeper-bookkeeper-server-4.14.2.jar:4.14.2] Jul 05 15:52:21 pulsar[96898]: at org.apache.distributedlog.ZooKeeperClient.buildZooKeeper(ZooKeeperClient.java:318) ~[org.apache.distributedlog-distributedlog-core-4.14.2.jar:4.14.2] Jul 05 15:52:21 pulsar[96898]: ... 34 more Jul 05 15:52:21 pulsar[96898]: 2023-07-05T15:52:21,660+0300 [DLM-/pulsar/functions-OrderedScheduler-0-0] INFO org.apache.distributedlog.bk.SimpleLedgerAllocator - Ledger allocator /pulsar/functions/public/default/file-test/67849712-9304-4be3-819c-991577feb171-pulsar-io-file-2.9.1.nar/<default>/allocation moved to phase ERROR : version = 0. Jul 05 15:52:21 pulsar[96898]: 2023-07-05T15:52:21,688+0300 [DLM-/pulsar/functions-OrderedScheduler-0-0] INFO org.apache.distributedlog.bk.SimpleLedgerAllocator - Abort ledger allocator without cleaning up on /pulsar/functions/public/default/file-test/67849712-9304-4be3-819c-991577feb171-pulsar-io-file-2.9.1.nar/<default>/allocation. Jul 05 15:52:21 pulsar[96898]: 2023-07-05T15:52:21,691+0300 [pulsar-web-36-1] ERROR org.apache.pulsar.functions.worker.rest.api.SourcesImpl - Failed process Source public/default/file-test package: Jul 05 15:52:21 pulsar[96898]: org.apache.distributedlog.bk.SimpleLedgerAllocator$AllocationException: Error on allocating ledger under /pulsar/functions/public/default/file-test/67849712-9304-4be3-819c-991577feb171-pulsar-io-file-2.9.1.nar/<default>/allocation Jul 05 15:52:21 pulsar[96898]: at org.apache.distributedlog.bk.SimpleLedgerAllocator.tryObtain(SimpleLedgerAllocator.java:279) ~[org.apache.distributedlog-distributedlog-core-4.14.2.jar:4.14.2] Jul 05 15:52:21 pulsar[96898]: at org.apache.distributedlog.bk.LedgerAllocatorDelegator.tryObtain(LedgerAllocatorDelegator.java:73) ~[org.apache.distributedlog-distributedlog-core-4.14.2.jar:4.14.2] Jul 05 15:52:21 pulsar[96898]: at org.apache.distributedlog.impl.logsegment.BKLogSegmentAllocator.tryObtain(BKLogSegmentAllocator.java:61) ~[org.apache.distributedlog-distributedlog-core-4.14.2.jar:4.14.2] Jul 05 15:52:21 pulsar[96898]: at org.apache.distributedlog.BKLogWriteHandler.doStartLogSegment(BKLogWriteHandler.java:589) ~[org.apache.distributedlog-distributedlog-core-4.14.2.jar:4.14.2] Jul 05 15:52:21 pulsar[96898]: at org.apache.distributedlog.BKLogWriteHandler$10.onSuccess(BKLogWriteHandler.java:538) ~[org.apache.distributedlog-distributedlog-core-4.14.2.jar:4.14.2] Jul 05 15:52:21 pulsar[96898]: at org.apache.distributedlog.BKLogWriteHandler$10.onSuccess(BKLogWriteHandler.java:530) ~[org.apache.distributedlog-distributedlog-core-4.14.2.jar:4.14.2] Jul 05 15:52:21 pulsar[96898]: at org.apache.bookkeeper.common.concurrent.FutureEventListener.accept(FutureEventListener.java:42) ~[org.apache.bookkeeper-bookkeeper-common-4.14.2.jar:4.14.2] Jul 05 15:52:21 pulsar[96898]: at org.apache.bookkeeper.common.concurrent.FutureEventListener.accept(FutureEventListener.java:26) ~[org.apache.bookkeeper-bookkeeper-common-4.14.2.jar:4.14.2] Jul 05 15:52:21 pulsar[96898]: at java.util.concurrent.CompletableFuture.uniWhenComplete(CompletableFuture.java:859) ~[?:?] Jul 05 15:52:21 pulsar[96898]: at java.util.concurrent.CompletableFuture.uniWhenCompleteStage(CompletableFuture.java:883) ~[?:?] Jul 05 15:52:21 pulsar[96898]: at java.util.concurrent.CompletableFuture.whenComplete(CompletableFuture.java:2251) ~[?:?] Jul 05 15:52:21 pulsar[96898]: at org.apache.distributedlog.BKLogWriteHandler.asyncStartLogSegment(BKLogWriteHandler.java:530) ~[org.apache.distributedlog-distributedlog-core-4.14.2.jar:4.14.2] Jul 05 15:52:21 pulsar[96898]: at org.apache.distributedlog.BKAbstractLogWriter.lambda$asyncStartNewLogSegment$1(BKAbstractLogWriter.java:379) ~[org.apache.distributedlog-distributedlog-core-4.14.2.jar:4.14.2] Jul 05 15:52:21 pulsar[96898]: at java.util.concurrent.CompletableFuture$UniCompose.tryFire(CompletableFuture.java:1072) ~[?:?] Jul 05 15:52:21 pulsar[96898]: at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:506) ~[?:?] Jul 05 15:52:21 pulsar[96898]: at java.util.concurrent.CompletableFuture.complete(CompletableFuture.java:2073) ~[?:?] Jul 05 15:52:21 pulsar[96898]: at org.apache.bookkeeper.common.concurrent.FutureUtils$ListFutureProcessor.run(FutureUtils.java:229) ~[org.apache.bookkeeper-bookkeeper-common-4.14.2.jar:4.14.2] Jul 05 15:52:21 pulsar[96898]: at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) ~[?:?] Jul 05 15:52:21 pulsar[96898]: at com.google.common.util.concurrent.TrustedListenableFutureTask$TrustedFutureInterruptibleTask.runInterruptibly(TrustedListenableFutureTask.java:125) ~[com.google.guava-guava-30.1-jre.jar:?] Jul 05 15:52:21 pulsar[96898]: at com.google.common.util.concurrent.InterruptibleTask.run(InterruptibleTask.java:69) ~[com.google.guava-guava-30.1-jre.jar:?] Jul 05 15:52:21 pulsar[96898]: at com.google.common.util.concurrent.TrustedListenableFutureTask.run(TrustedListenableFutureTask.java:78) ~[com.google.guava-guava-30.1-jre.jar:?] Jul 05 15:52:21 pulsar[96898]: at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) ~[?:?] Jul 05 15:52:21 pulsar[96898]: at java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[?:?] Jul 05 15:52:21 pulsar[96898]: at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) ~[?:?] Jul 05 15:52:21 pulsar[96898]: at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?] Jul 05 15:52:21 pulsar[96898]: at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?] Jul 05 15:52:21 pulsar[96898]: at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) [io.netty-netty-common-4.1.72.Final.jar:4.1.72.Final] Jul 05 15:52:21 pulsar[96898]: at java.lang.Thread.run(Thread.java:829) [?:?] Jul 05 15:52:21 pulsar[96898]: Suppressed: org.apache.distributedlog.exceptions.WriteException: Write rejected because stream public/default/file-test/67849712-9304-4be3-819c-991577feb171-pulsar-io-file-2.9.1.nar has encountered an error : writer has been closed due to error. ... ``` ### Are you willing to submit a PR? - [ ] I'm willing to submit a PR! -- 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]
