apache / pulsar

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

[Bug] Unable to create Connectors on Pulsar 2.9.1 (bare metal cluster) #20722

Closed rob-kvietkauskas-ign closed 1 year ago

rob-kvietkauskas-ign commented 1 year ago

Search before asking

Version

OS: Debian 5.10.162-1 (2023-01-21) x86_64 GNU/Linux Pulsar: 2.9.1 / 2.11.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:

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//78b1ef8d-ab3c-4deb-8b60-0579ff0ba395-.nar//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?

rob-kvietkauskas-ign commented 1 year ago

I have deployed a new cluster of 6 nodes (3 broker + bookkeeper machines and 3 zookeeper machines), running Pulsar 2.11.1. Using pretty much same configuration, I encounter same error: Error on allocating ledger under /pulsar/functions/ ...

rob-kvietkauskas-ign commented 1 year ago

Yesterday I have spent some time analizing 2.11.1 Pulsar source code, trying to figure out what may be the cause of zookeper connection to localhost (even though, nor broker, nor bookie, nor functions worker configuration does not contain any entries related to localhost). After digging the code that is mentioned in the stacktraces I've provided and stacktraces I get using Pulsar 2.11.1, I have a strong feeling that problem is located in uploadToBookKeeper(Namespace, InputStream, String) method call in WorkerUtils class. After this method gets called, BookKeeper client tries to access a bookkeeper via ZooKeeper, but somehow (not sure how exactly) ZooKeeperClient gets initialized with localhost value.

rob-kvietkauskas-ign commented 1 year ago

I have managed to register both source (both file and Debezium PostgreSQL Source) and (custom) sink connectors in 2.11.1 cluster. Stream storage service was disabled (as it is by default). I have set functionsWorkerEnablePackageManagement=true and enablePackagesManagement=true, restarted brokers and finally was able to run the connectors! I tried to do the same on 2.9.1, but result did not change at all – I still got ledger allocation errors.

rob-kvietkauskas-ign commented 1 year ago

I have finally managed to register both source (both file and Debezium PostgreSQL Source) and (custom) sink connectors in 2.9.1 bare-metal cluster. Once I added file:// schema prefix to path of the archive (I have provided absolute or relative file system paths of the archives until this discovery, same way as it is described in documentation), all the connectors that I was testing, got created (registered) successfully, operated properly after restart of broker node. It was not the case in 2.11.1 cluster with functionsWorkerEnablePackageManagement enabled – after restart of the broker, connector didn't start automatically and ended up having underlying internal error).

tisonkun commented 1 year ago

Once I added file:// schema prefix to path of the archive

Could you elaborate a bit what archive you configured? IIRC we use Path type for archive path and it should not take file:// input

It was not the case in 2.11.1

This seems a new issue. cc @jiangpengcheng @cbornet as you work on functions related logics recently. Do you have any thoughts on this kind of exceptions?

tisonkun commented 1 year ago

Seems not a bug but usability to be improved.

No specific action and duplicate with the open-ended discussion https://github.com/apache/pulsar/discussions/20796.

Let's move the discussion there and spawn any concrete issue to improve.