search

apache / pulsar

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

Pulsar functions worker fails to initialize #3715

Closed grantwwu closed 4 years ago

grantwwu commented 5 years ago

Describe the bug The Pulsar functions worker fails to initialize. This breaks Pulsar Functions functionality.

19:41:53.512 [BookKeeperClientWorker-OrderedExecutor-1-0] ERROR org.apache.bookkeeper.common.util.SafeRunnable - Unexpected throwable caught 
java.lang.ArrayIndexOutOfBoundsException: -2
    at com.google.common.collect.RegularImmutableList.get(RegularImmutableList.java:60) ~[com.google.guava-guava-21.0.jar:?]
    at org.apache.bookkeeper.client.PendingReadOp$SequenceReadRequest.sendNextRead(PendingReadOp.java:400) ~[org.apache.bookkeeper-bookkeeper-server-4.9.0.jar:4.9.0]
    at org.apache.bookkeeper.client.PendingReadOp$SequenceReadRequest.read(PendingReadOp.java:382) ~[org.apache.bookkeeper-bookkeeper-server-4.9.0.jar:4.9.0]
    at org.apache.bookkeeper.client.PendingReadOp.initiate(PendingReadOp.java:526) ~[org.apache.bookkeeper-bookkeeper-server-4.9.0.jar:4.9.0]
    at org.apache.bookkeeper.client.LedgerRecoveryOp.doRecoveryRead(LedgerRecoveryOp.java:148) ~[org.apache.bookkeeper-bookkeeper-server-4.9.0.jar:4.9.0]
    at org.apache.bookkeeper.client.LedgerRecoveryOp.access$000(LedgerRecoveryOp.java:37) ~[org.apache.bookkeeper-bookkeeper-server-4.9.0.jar:4.9.0]
    at org.apache.bookkeeper.client.LedgerRecoveryOp$1.readLastConfirmedDataComplete(LedgerRecoveryOp.java:109) ~[org.apache.bookkeeper-bookkeeper-server-4.9.0.jar:4.9.0]
    at org.apache.bookkeeper.client.ReadLastConfirmedOp.readEntryComplete(ReadLastConfirmedOp.java:135) ~[org.apache.bookkeeper-bookkeeper-server-4.9.0.jar:4.9.0]
    at org.apache.bookkeeper.proto.PerChannelBookieClient$ReadCompletion$1.readEntryComplete(PerChannelBookieClient.java:1797) ~[org.apache.bookkeeper-bookkeeper-server-4.9.0.jar:4.9.0]
    at org.apache.bookkeeper.proto.PerChannelBookieClient$ReadCompletion.handleReadResponse(PerChannelBookieClient.java:1878) ~[org.apache.bookkeeper-bookkeeper-server-4.9.0.jar:4.9.0]
    at org.apache.bookkeeper.proto.PerChannelBookieClient$ReadCompletion.handleV2Response(PerChannelBookieClient.java:1831) ~[org.apache.bookkeeper-bookkeeper-server-4.9.0.jar:4.9.0]
    at org.apache.bookkeeper.proto.PerChannelBookieClient$ReadV2ResponseCallback.safeRun(PerChannelBookieClient.java:1321) ~[org.apache.bookkeeper-bookkeeper-server-4.9.0.jar:4.9.0]
    at org.apache.bookkeeper.common.util.SafeRunnable.run(SafeRunnable.java:36) [org.apache.bookkeeper-bookkeeper-common-4.9.0.jar:4.9.0]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_181]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_181]
    at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) [io.netty-netty-all-4.1.32.Final.jar:4.1.32.Final]
    at java.lang.Thread.run(Thread.java:748) [?:1.8.0_181]
**root@pulsar-broker-56d59cf97d-zwtxf:/pulsar# bin/pulsar-admin functions list
Function worker service is not done initializing. Please try again in a little while.

Reason: HTTP 503 Service Unavailable

Note: this issue persisted for a time period on the scale of hours until I gave up and tore down the cluster.

To Reproduce Reproduction steps unclear. Could possibly be related to updating existing functions.

Expected behavior Expect Pulsar functions to behave as expected - pulsar-admin functions list should not say there's an HTTP 503, etc.

Platform (please complete the following information):

jerrypeng commented 5 years ago

@grantwwu how often have you seen this happen? Did you find the exceptions you listed above in function logs or worker/broker logs? How are you running cluster? Standalone?

grantwwu commented 5 years ago

In broker logs. Running in a 3 node cluster.

Unfortunately I'm not sure we can reproduce this anymore - it was breaking clusters frequently enough (once every 1 or 2 days?, with no obvious path to recovery) that we've downgraded to 2.2.1 entirely.

I'm going to test out 2.3.1 when it comes out - we were also hitting some Jetty thread pool issues that merlimat said were getting fixed then.

sde-melo commented 5 years ago

I confirm that it happens quite a lot. Pulsar is deployed on EKS with 2 brokers and 3 bookkeepers. A function is deployed, works well and after a few hours the function worker service becomes broken: "Function worker service is not done initializing. Please try again in a little while." and the brokers logs are full of this stack trace.

cavanaug commented 5 years ago

This is a blocking item for us as well...

jerrypeng commented 5 years ago

I have not seen this error so far on our deployments. Can anyone provide any more logs or stacktraces?

zarrarrana commented 5 years ago

@jerrypeng We are getting the same issue when we enable the token authentication and authorization in the broker. I have tried setting clientAuthenticationPlugin and clientAuthenticationParameters in the functions_worker.yaml and that's when we we get the above error. It also fails without setting the token. I have also tried setting authenticationEnabled but no luck. The functions worker is running inside the broker. Are there any other properties that needs to be set when authentication is enabled? Also the tokens I have tried are same as brokerClientAuthenticationParameters token and creating a new super role for the functions worker. Please let me know if you need any more info.

zarrarrana commented 5 years ago

Also we are running the pulsar cluster in kubernetes with functions_worker running inside the broker pod.

zarrarrana commented 5 years ago

@jerrypeng. Here are the logs.

[conf/pulsar_env.sh] Applying config PULSAR_GC = "-XX:+UseG1GC -XX:MaxGCPauseMillis=10" [conf/pulsar_env.sh] Applying config PULSAR_MEM = "-Xms15g -Xmx15g -XX:MaxDirectMemorySize=15g -Dio.netty.leakDetectionLevel=disabled -Dio.netty.recycler.linkCapacity=1024 -XX:+ParallelRefProcEnabled -XX:+UnlockExperimentalVMOptions -XX:+AggressiveOpts -XX:+DoEscapeAnalysis -XX:ParallelGCThreads=32 -XX:ConcGCThreads=32 -XX:G1NewSizePercent=50 -XX:+DisableExplicitGC -XX:-ResizePLAB -XX:+ExitOnOutOfMemoryError -XX:+PerfDisableSharedMem" [conf/broker.conf] Applying config advertisedAddress = 100.96.36.242 [conf/broker.conf] Applying config authenticationEnabled = true [conf/broker.conf] Applying config authenticationProviders = org.apache.pulsar.broker.authentication.AuthenticationProviderToken [conf/broker.conf] Applying config authorizationEnabled = true [conf/broker.conf] Applying config brokerClientAuthenticationParameters = token:<redacted> [conf/broker.conf] Applying config brokerClientAuthenticationPlugin = org.apache.pulsar.client.impl.auth.AuthenticationToken [conf/broker.conf] Applying config clusterName = pulsar [conf/broker.conf] Applying config configurationStoreServers = zk-0.zookeeper,zk-1.zookeeper,zk-2.zookeeper [conf/broker.conf] Applying config exposeTopicLevelMetricsInPrometheus = true [conf/broker.conf] Applying config functionsWorkerEnabled = true [conf/broker.conf] Applying config managedLedgerDefaultAckQuorum = 2 [conf/broker.conf] Applying config managedLedgerDefaultEnsembleSize = 3 [conf/broker.conf] Applying config managedLedgerDefaultWriteQuorum = 3 [conf/broker.conf] Applying config proxyRoles = my-proxy-role [conf/broker.conf] Applying config superUserRoles = broker-admin,my-proxy-role,functions-admin [conf/broker.conf] Applying config tokenPublicKey = file:///keys/my-public.key [conf/broker.conf] Applying config zookeeperServers = zk-0.zookeeper,zk-1.zookeeper,zk-2.zookeeper [conf/pulsar_env.sh] Applying config PULSAR_GC = "-XX:+UseG1GC -XX:MaxGCPauseMillis=10" [conf/pulsar_env.sh] Applying config PULSAR_MEM = "-Xms15g -Xmx15g -XX:MaxDirectMemorySize=15g -Dio.netty.leakDetectionLevel=disabled -Dio.netty.recycler.linkCapacity=1024 -XX:+ParallelRefProcEnabled -XX:+UnlockExperimentalVMOptions -XX:+AggressiveOpts -XX:+DoEscapeAnalysis -XX:ParallelGCThreads=32 -XX:ConcGCThreads=32 -XX:G1NewSizePercent=50 -XX:+DisableExplicitGC -XX:-ResizePLAB -XX:+ExitOnOutOfMemoryError -XX:+PerfDisableSharedMem" [conf/pulsar_env.sh] Applying config PULSAR_GC = "-XX:+UseG1GC -XX:MaxGCPauseMillis=10" [conf/pulsar_env.sh] Applying config PULSAR_MEM = "-Xms15g -Xmx15g -XX:MaxDirectMemorySize=15g -Dio.netty.leakDetectionLevel=disabled -Dio.netty.recycler.linkCapacity=1024 -XX:+ParallelRefProcEnabled -XX:+UnlockExperimentalVMOptions -XX:+AggressiveOpts -XX:+DoEscapeAnalysis -XX:ParallelGCThreads=32 -XX:ConcGCThreads=32 -XX:G1NewSizePercent=50 -XX:+DisableExplicitGC -XX:-ResizePLAB -XX:+ExitOnOutOfMemoryError -XX:+PerfDisableSharedMem" [AppClassLoader@18b4aac2] info AspectJ Weaver Version 1.9.2 built on Wednesday Oct 24, 2018 at 15:43:33 GMT [AppClassLoader@18b4aac2] info register classloader sun.misc.Launcher$AppClassLoader@18b4aac2 [AppClassLoader@18b4aac2] info using configuration file:/pulsar/lib/org.apache.pulsar-pulsar-zookeeper-2.3.0.jar!/META-INF/aop.xml [AppClassLoader@18b4aac2] info using configuration file:/pulsar/lib/org.apache.pulsar-pulsar-zookeeper-utils-2.3.0.jar!/META-INF/aop.xml [AppClassLoader@18b4aac2] info register aspect org.apache.pulsar.zookeeper.FinalRequestProcessorAspect [AppClassLoader@18b4aac2] info register aspect org.apache.pulsar.zookeeper.ZooKeeperServerAspect [AppClassLoader@18b4aac2] info register aspect org.apache.pulsar.zookeeper.SerializeUtilsAspect [AppClassLoader@18b4aac2] info register aspect org.apache.pulsar.broker.zookeeper.aspectj.ClientCnxnAspect [MethodUtil@405f913f] info AspectJ Weaver Version 1.9.2 built on Wednesday Oct 24, 2018 at 15:43:33 GMT [MethodUtil@405f913f] info register classloader sun.reflect.misc.MethodUtil@405f913f [MethodUtil@405f913f] info using configuration file:/pulsar/lib/org.apache.pulsar-pulsar-zookeeper-2.3.0.jar!/META-INF/aop.xml [MethodUtil@405f913f] info using configuration file:/pulsar/lib/org.apache.pulsar-pulsar-zookeeper-utils-2.3.0.jar!/META-INF/aop.xml [MethodUtil@405f913f] info register aspect org.apache.pulsar.zookeeper.FinalRequestProcessorAspect [MethodUtil@405f913f] info register aspect org.apache.pulsar.zookeeper.ZooKeeperServerAspect [MethodUtil@405f913f] info register aspect org.apache.pulsar.zookeeper.SerializeUtilsAspect [MethodUtil@405f913f] info register aspect org.apache.pulsar.broker.zookeeper.aspectj.ClientCnxnAspect 23:46:31.219 [main] INFO org.apache.pulsar.broker.PulsarService - Starting Pulsar Broker service; version: '2.3.0.0' 23:46:31.230 [main] INFO org.apache.pulsar.broker.PulsarService - Git Revision 52fc45e990800c9a34147b6c4ed5080a79dd2d99 23:46:31.232 [main] INFO org.apache.pulsar.broker.PulsarService - Built by Matteo Merli <mmerli@apache.org> on pepito at 2019-02-20T10:49:47-0800 23:46:31.266 [pulsar-ordered-OrderedExecutor-0-0] INFO org.apache.zookeeper.ZooKeeper - Client environment:zookeeper.version=3.4.13-2d71af4dbe22557fda74f9a9b4309b15a7487f03, built on 06/29/2018 00:39 GMT 23:46:31.269 [pulsar-ordered-OrderedExecutor-0-0] INFO org.apache.zookeeper.ZooKeeper - Client environment:host.name=broker-74fb7b65cf-n9wdw 23:46:31.274 [pulsar-ordered-OrderedExecutor-0-0] INFO org.apache.zookeeper.ZooKeeper - Client environment:java.version=1.8.0_181 23:46:31.274 [pulsar-ordered-OrderedExecutor-0-0] INFO org.apache.zookeeper.ZooKeeper - Client environment:java.vendor=Oracle Corporation 23:46:31.275 [pulsar-ordered-OrderedExecutor-0-0] INFO org.apache.zookeeper.ZooKeeper - Client environment:java.home=/usr/lib/jvm/java-8-openjdk-amd64/jre 23:46:31.275 [pulsar-ordered-OrderedExecutor-0-0] INFO org.apache.zookeeper.ZooKeeper - Client environment:java.class.path=/pulsar/conf:::/pulsar/lib/org.apache.logging.log4j-log4j-api-2.10.0.jar:/pulsar/lib/org.apache.pulsar-pulsar-functions-instance-2.3.0.jar:/pulsar/lib/org.jctools-jctools-core-2.1.2.jar:/pulsar/lib/com.sun.activation-javax.activation-1.2.0.jar:/pulsar/lib/org.eclipse.jetty-jetty-io-9.4.12.v20180830.jar:/pulsar/lib/org.apache.pulsar-pulsar-functions-runtime-2.3.0.jar:/pulsar/lib/com.yahoo.datasketches-sketches-core-0.8.3.jar:/pulsar/lib/org.bouncycastle-bcprov-ext-jdk15on-1.60.jar:/pulsar/lib/org.glassfish.jersey.media-jersey-media-multipart-2.27.jar:/pulsar/lib/io.kubernetes-client-java-api-2.0.0.jar:/pulsar/lib/org.apache.pulsar-pulsar-broker-2.3.0.jar:/pulsar/lib/org.glassfish.hk2.external-javax.inject-2.5.0-b42.jar:/pulsar/lib/io.opencensus-opencensus-api-0.18.0.jar:/pulsar/lib/com.squareup.okio-okio-1.13.0.jar:/pulsar/lib/org.apache.pulsar-pulsar-functions-api-2.3.0.jar:/pulsar/lib/org.apache.yetus-audience-annotations-0.5.0.jar:/pulsar/lib/org.apache.bookkeeper-bookkeeper-common-4.9.0.jar:/pulsar/lib/org.bouncycastle-bcprov-jdk15on-1.60.jar:/pulsar/lib/org.glassfish.hk2-hk2-api-2.5.0-b42.jar:/pulsar/lib/org.glassfish.hk2.external-aopalliance-repackaged-2.5.0-b42.jar:/pulsar/lib/com.typesafe.netty-netty-reactive-streams-2.0.0.jar:/pulsar/lib/org.apache.distributedlog-distributedlog-core-4.9.0.jar:/pulsar/lib/com.yahoo.datasketches-memory-0.8.3.jar:/pulsar/lib/commons-io-commons-io-2.5.jar:/pulsar/lib/org.jvnet.mimepull-mimepull-1.9.6.jar:/pulsar/lib/org.eclipse.jetty-jetty-http-9.4.12.v20180830.jar:/pulsar/lib/org.apache.avro-avro-1.8.2.jar:/pulsar/lib/com.squareup.okhttp-okhttp-2.5.0.jar:/pulsar/lib/com.squareup.okhttp-okhttp-ws-2.7.5.jar:/pulsar/lib/org.apache.bookkeeper-stream-storage-server-4.9.0.jar:/pulsar/lib/io.prometheus-simpleclient-0.5.0.jar:/pulsar/lib/org.apache.bookkeeper-stream-storage-common-4.9.0.jar:/pulsar/lib/org.apache.distributedlog-distributedlog-protocol-4.9.0.jar:/pulsar/lib/org.slf4j-slf4j-api-1.7.25.jar:/pulsar/lib/com.github.luben-zstd-jni-1.3.7-3.jar:/pulsar/lib/com.fasterxml.jackson.module-jackson-module-jsonSchema-2.9.7.jar:/pulsar/lib/org.codehaus.mojo-animal-sniffer-annotations-1.17.jar:/pulsar/lib/io.prometheus-simpleclient_jetty-0.5.0.jar:/pulsar/lib/org.apache.bookkeeper-bookkeeper-proto-4.9.0.jar:/pulsar/lib/org.eclipse.jetty-jetty-continuation-9.4.12.v20180830.jar:/pulsar/lib/org.eclipse.jetty.websocket-websocket-server-9.4.12.v20180830.jar:/pulsar/lib/com.fasterxml.jackson.core-jackson-annotations-2.9.7.jar:/pulsar/lib/com.google.auth-google-auth-library-credentials-0.9.0.jar:/pulsar/lib/org.apache.curator-curator-framework-4.0.1.jar:/pulsar/lib/io.swagger-swagger-core-1.5.21.jar:/pulsar/lib/org.eclipse.jetty.websocket-websocket-common-9.4.12.v20180830.jar:/pulsar/lib/jline-jline-0.9.94.jar:/pulsar/lib/io.prometheus-simpleclient_servlet-0.5.0.jar:/pulsar/lib/commons-beanutils-commons-beanutils-core-1.8.0.jar:/pulsar/lib/org.glassfish.jersey.media-jersey-media-jaxb-2.27.jar:/pulsar/lib/org.apache.logging.log4j-log4j-slf4j-impl-2.10.0.jar:/pulsar/lib/io.netty-netty-all-4.1.32.Final.jar:/pulsar/lib/com.github.zafarkhaja-java-semver-0.9.0.jar:/pulsar/lib/org.eclipse.jetty.websocket-javax-websocket-client-impl-9.4.12.v20180830.jar:/pulsar/lib/org.apache.bookkeeper-stream-storage-service-impl-4.9.0.jar:/pulsar/lib/org.apache.curator-curator-client-4.0.1.jar:/pulsar/lib/org.apache.pulsar-pulsar-zookeeper-2.3.0.jar:/pulsar/lib/io.grpc-grpc-okhttp-1.18.0.jar:/pulsar/lib/org.glassfish.jersey.containers-jersey-container-servlet-core-2.27.jar:/pulsar/lib/io.dropwizard.metrics-metrics-jvm-3.1.0.jar:/pulsar/lib/com.google.protobuf.nano-protobuf-javanano-3.0.0-alpha-5.jar:/pulsar/lib/org.apache.pulsar-pulsar-discovery-service-2.3.0.jar:/pulsar/lib/io.dropwizard.metrics-metrics-core-3.1.0.jar:/pulsar/lib/org.apache.bookkeeper-circe-checksum-4.9.0.jar:/pulsar/lib/log4j-log4j-1.2.17.jar:/pulsar/lib/org.eclipse.jetty-jetty-proxy-9.4.12.v20180830.jar:/pulsar/lib/org.xerial.snappy-snappy-java-1.1.1.3.jar:/pulsar/lib/io.grpc-grpc-protobuf-1.18.0.jar:/pulsar/lib/org.apache.distributedlog-distributedlog-common-4.9.0.jar:/pulsar/lib/io.grpc-grpc-protobuf-nano-1.18.0.jar:/pulsar/lib/io.swagger-swagger-annotations-1.5.21.jar:/pulsar/lib/org.glassfish.jersey.ext-jersey-entity-filtering-2.27.jar:/pulsar/lib/org.reactivestreams-reactive-streams-1.0.2.jar:/pulsar/lib/org.glassfish.hk2-hk2-utils-2.5.0-b42.jar:/pulsar/lib/org.apache.commons-commons-compress-1.15.jar:/pulsar/lib/javax.servlet-javax.servlet-api-3.1.0.jar:/pulsar/lib/com.fasterxml.jackson.module-jackson-module-jaxb-annotations-2.9.7.jar:/pulsar/lib/commons-collections-commons-collections-3.2.2.jar:/pulsar/lib/javax.xml.bind-activation-1.0.2.jar:/pulsar/lib/javax.validation-validation-api-1.1.0.Final.jar:/pulsar/lib/io.grpc-grpc-core-1.18.0.jar:/pulsar/lib/org.apache.httpcomponents-httpcore-4.4.9.jar:/pulsar/lib/org.apache.avro-avro-protobuf-1.8.2.jar:/pulsar/lib/io.grpc-grpc-netty-1.18.0.jar:/pulsar/lib/commons-codec-commons-codec-1.10.jar:/pulsar/lib/io.grpc-grpc-auth-1.18.0.jar:/pulsar/lib/org.apache.commons-commons-lang3-3.4.jar:/pulsar/lib/org.glassfish.hk2-osgi-resource-locator-1.0.1.jar:/pulsar/lib/org.eclipse.jetty-jetty-servlet-9.4.12.v20180830.jar:/pulsar/lib/org.codehaus.jackson-jackson-mapper-asl-1.9.13.jar:/pulsar/lib/org.apache.pulsar-pulsar-proxy-2.3.0.jar:/pulsar/lib/org.codehaus.jackson-jackson-core-asl-1.9.13.jar:/pulsar/lib/org.apache.pulsar-pulsar-io-core-2.3.0.jar:/pulsar/lib/org.tukaani-xz-1.5.jar:/pulsar/lib/org.rocksdb-rocksdbjni-5.13.3.jar:/pulsar/lib/com.google.api.grpc-proto-google-common-protos-1.12.0.jar:/pulsar/lib/com.google.protobuf-protobuf-java-3.5.1.jar:/pulsar/lib/org.glassfish.jersey.media-jersey-media-json-jackson-2.27.jar:/pulsar/lib/org.eclipse.jetty-jetty-xml-9.4.12.v20180830.jar:/pulsar/lib/org.apache.pulsar-pulsar-functions-api-examples-2.3.0.jar:/pulsar/lib/org.apache.logging.log4j-log4j-core-2.10.0.jar:/pulsar/lib/io.swagger-swagger-models-1.5.21.jar:/pulsar/lib/org.aspectj-aspectjweaver-1.9.2.jar:/pulsar/lib/org.apache.logging.log4j-log4j-web-2.10.0.jar:/pulsar/lib/org.apache.pulsar-protobuf-shaded-2.1.0-incubating.jar:/pulsar/lib/org.apache.curator-curator-recipes-4.0.1.jar:/pulsar/lib/org.apache.pulsar-pulsar-functions-runtime-all-2.3.0.jar:/pulsar/lib/commons-cli-commons-cli-1.2.jar:/pulsar/lib/com.google.protobuf-protobuf-java-util-3.5.1.jar:/pulsar/lib/com.carrotsearch-hppc-0.7.3.jar:/pulsar/lib/net.java.dev.jna-jna-4.2.0.jar:/pulsar/lib/org.apache.httpcomponents-httpclient-4.5.5.jar:/pulsar/lib/org.apache.pulsar-pulsar-client-original-2.3.0.jar:/pulsar/lib/com.beust-jcommander-1.48.jar:/pulsar/lib/com.squareup.okhttp-logging-interceptor-2.7.5.jar:/pulsar/lib/org.objenesis-objenesis-2.1.jar:/pulsar/lib/org.apache.bookkeeper.http-vertx-http-server-4.9.0.jar:/pulsar/lib/io.jsonwebtoken-jjwt-api-0.10.5.jar:/pulsar/lib/org.eclipse.jetty-jetty-client-9.4.12.v20180830.jar:/pulsar/lib/org.eclipse.jetty-jetty-security-9.4.12.v20180830.jar:/pulsar/lib/org.apache.bookkeeper.stats-codahale-metrics-provider-4.9.0.jar:/pulsar/lib/org.glassfish.jersey.containers-jersey-container-servlet-2.27.jar:/pulsar/lib/io.vertx-vertx-auth-common-3.4.1.jar:/pulsar/lib/org.apache.pulsar-pulsar-websocket-2.3.0.jar:/pulsar/lib/javax.activation-javax.activation-api-1.2.0.jar:/pulsar/lib/javax.xml.bind-jaxb-api-2.3.1.jar:/pulsar/lib/org.eclipse.jetty-jetty-util-9.4.12.v20180830.jar:/pulsar/lib/org.javassist-javassist-3.21.0-GA.jar:/pulsar/lib/org.apache.pulsar-pulsar-broker-common-2.3.0.jar:/pulsar/lib/org.slf4j-jcl-over-slf4j-1.7.25.jar:/pulsar/lib/org.apache.bookkeeper-bookkeeper-common-allocator-4.9.0.jar:/pulsar/lib/org.apache.bookkeeper.stats-bookkeeper-stats-api-4.9.0.jar:/pulsar/lib/io.grpc-grpc-all-1.18.0.jar:/pulsar/lib/javax.websocket-javax.websocket-client-api-1.0.jar:/pulsar/lib/io.jsonwebtoken-jjwt-jackson-0.10.5.jar:/pulsar/lib/org.apache.pulsar-pulsar-functions-utils-2.3.0.jar:/pulsar/lib/org.glassfish.jersey.core-jersey-client-2.27.jar:/pulsar/lib/org.apache.bookkeeper-bookkeeper-tools-framework-4.9.0.jar:/pulsar/lib/org.glassfish.hk2-hk2-locator-2.5.0-b42.jar:/pulsar/lib/com.fasterxml.jackson.core-jackson-databind-2.9.7.jar:/pulsar/lib/org.hdrhistogram-HdrHistogram-2.1.9.jar:/pulsar/lib/org.inferred-freebuilder-1.14.9.jar:/pulsar/lib/org.lz4-lz4-java-1.5.0.jar:/pulsar/lib/org.apache.pulsar-pulsar-testclient-2.3.0.jar:/pulsar/lib/org.apache.pulsar-pulsar-client-admin-original-2.3.0.jar:/pulsar/lib/org.eclipse.jetty.websocket-websocket-api-9.4.12.v20180830.jar:/pulsar/lib/org.apache.distributedlog-distributedlog-core-4.9.0-tests.jar:/pulsar/lib/javax.inject-javax.inject-1.jar:/pulsar/lib/io.grpc-grpc-protobuf-lite-1.18.0.jar:/pulsar/lib/org.asynchttpclient-async-http-client-2.7.0.jar:/pulsar/lib/commons-beanutils-commons-beanutils-1.7.0.jar:/pulsar/lib/org.bouncycastle-bcpkix-jdk15on-1.60.jar:/pulsar/lib/org.apache.bookkeeper-statelib-4.9.0.jar:/pulsar/lib/com.fasterxml.jackson.dataformat-jackson-dataformat-yaml-2.9.7.jar:/pulsar/lib/org.apache.pulsar-pulsar-zookeeper-utils-2.3.0.jar:/pulsar/lib/org.apache.bookkeeper-stream-storage-api-4.9.0.jar:/pulsar/lib/org.aspectj-aspectjrt-1.9.2.jar:/pulsar/lib/commons-configuration-commons-configuration-1.6.jar:/pulsar/lib/org.apache.bookkeeper.tests-stream-storage-tests-common-4.9.0.jar:/pulsar/lib/com.google.code.gson-gson-2.8.2.jar:/pulsar/lib/io.prometheus-simpleclient_hotspot-0.5.0.jar:/pulsar/lib/org.glassfish.jersey.core-jersey-server-2.27.jar:/pulsar/lib/io.prometheus-simpleclient_httpserver-0.5.0.jar:/pulsar/lib/org.glassfish.jersey.inject-jersey-hk2-2.27.jar:/pulsar/lib/org.apache.pulsar-pulsar-client-tools-2.3.0.jar:/pulsar/lib/com.fasterxml.jackson.jaxrs-jackson-jaxrs-base-2.9.7.jar:/pulsar/lib/io.jsonwebtoken-jjwt-impl-0.10.5.jar:/pulsar/lib/javax.annotation-javax.annotation-api-1.2.jar:/pulsar/lib/io.prometheus-simpleclient_log4j2-0.5.0.jar:/pulsar/lib/io.vertx-vertx-web-3.4.1.jar:/pulsar/lib/commons-lang-commons-lang-2.4.jar:/pulsar/lib/com.google.code.findbugs-jsr305-3.0.2.jar:/pulsar/lib/io.kubernetes-client-java-2.0.0.jar:/pulsar/lib/io.grpc-grpc-testing-1.12.0.jar:/pulsar/lib/io.netty-netty-3.10.1.Final.jar:/pulsar/lib/io.prometheus-simpleclient_common-0.5.0.jar:/pulsar/lib/io.vertx-vertx-core-3.4.1.jar:/pulsar/lib/org.checkerframework-checker-compat-qual-2.5.2.jar:/pulsar/lib/com.thoughtworks.paranamer-paranamer-2.7.jar:/pulsar/lib/org.eclipse.jetty.websocket-websocket-servlet-9.4.12.v20180830.jar:/pulsar/lib/io.dropwizard.metrics-metrics-graphite-3.1.0.jar:/pulsar/lib/org.yaml-snakeyaml-1.23.jar:/pulsar/lib/org.apache.pulsar-pulsar-functions-secrets-2.3.0.jar:/pulsar/lib/org.apache.commons-commons-collections4-4.1.jar:/pulsar/lib/org.apache.pulsar-pulsar-functions-worker-2.3.0.jar:/pulsar/lib/org.apache.bookkeeper.http-http-server-4.9.0.jar:/pulsar/lib/org.apache.bookkeeper-stream-storage-java-client-4.9.0.jar:/pulsar/lib/org.apache.bookkeeper-cpu-affinity-4.9.0.jar:/pulsar/lib/org.eclipse.jetty-jetty-server-9.4.12.v20180830.jar:/pulsar/lib/org.glassfish.jersey.core-jersey-common-2.27.jar:/pulsar/lib/com.fasterxml.jackson.core-jackson-core-2.9.7.jar:/pulsar/lib/io.grpc-grpc-stub-1.18.0.jar:/pulsar/lib/com.github.ben-manes.caffeine-caffeine-2.6.2.jar:/pulsar/lib/org.apache.pulsar-pulsar-client-api-2.3.0.jar:/pulsar/lib/com.google.errorprone-error_prone_annotations-2.2.0.jar:/pulsar/lib/com.fasterxml.jackson.jaxrs-jackson-jaxrs-json-provider-2.9.7.jar:/pulsar/lib/org.apache.bookkeeper-stream-storage-service-api-4.9.0.jar:/pulsar/lib/org.slf4j-jul-to-slf4j-1.7.25.jar:/pulsar/lib/org.apache.bookkeeper-stream-storage-java-client-base-4.9.0.jar:/pulsar/lib/org.asynchttpclient-async-http-client-netty-utils-2.7.0.jar:/pulsar/lib/io.netty-netty-tcnative-boringssl-static-2.0.20.Final.jar:/pulsar/lib/org.apache.bookkeeper.stats-prometheus-metrics-provider-4.9.0.jar:/pulsar/lib/org.apache.pulsar-pulsar-common-2.3.0.jar:/pulsar/lib/commons-logging-commons-logging-1.1.1.jar:/pulsar/lib/io.opencensus-opencensus-contrib-grpc-metrics-0.18.0.jar:/pulsar/lib/net.jodah-typetools-0.5.0.jar:/pulsar/lib/commons-digester-commons-digester-1.8.jar:/pulsar/lib/javax.ws.rs-javax.ws.rs-api-2.1.jar:/pulsar/lib/io.kubernetes-client-java-proto-2.0.0.jar:/pulsar/lib/io.grpc-grpc-context-1.18.0.jar:/pulsar/lib/org.eclipse.jetty-jetty-servlets-9.4.12.v20180830.jar:/pulsar/lib/org.apache.bookkeeper-bookkeeper-server-4.9.0.jar:/pulsar/lib/org.apache.bookkeeper-stream-storage-proto-4.9.0.jar:/pulsar/lib/joda-time-joda-time-2.9.3.jar:/pulsar/lib/org.apache.pulsar-managed-ledger-original-2.3.0.jar:/pulsar/lib/org.eclipse.jetty.websocket-websocket-client-9.4.12.v20180830.jar:/pulsar/lib/org.apache.pulsar-pulsar-functions-proto-2.3.0.jar:/pulsar/lib/com.google.guava-guava-21.0.jar::/pulsar/lib/org.aspectj-aspectjweaver-1.9.2.jar 23:46:31.282 [pulsar-ordered-OrderedExecutor-0-0] INFO org.apache.zookeeper.ZooKeeper - Client environment:java.library.path=/usr/java/packages/lib/amd64:/usr/lib/x86_64-linux-gnu/jni:/lib/x86_64-linux-gnu:/usr/lib/x86_64-linux-gnu:/usr/lib/jni:/lib:/usr/lib 23:46:31.282 [pulsar-ordered-OrderedExecutor-0-0] INFO org.apache.zookeeper.ZooKeeper - Client environment:java.io.tmpdir=/tmp 23:46:31.283 [pulsar-ordered-OrderedExecutor-0-0] INFO org.apache.zookeeper.ZooKeeper - Client environment:java.compiler=<NA> 23:46:31.283 [pulsar-ordered-OrderedExecutor-0-0] INFO org.apache.zookeeper.ZooKeeper - Client environment:os.name=Linux 23:46:31.283 [pulsar-ordered-OrderedExecutor-0-0] INFO org.apache.zookeeper.ZooKeeper - Client environment:os.arch=amd64 23:46:31.283 [pulsar-ordered-OrderedExecutor-0-0] INFO org.apache.zookeeper.ZooKeeper - Client environment:os.version=4.4.0-1075-aws 23:46:31.283 [pulsar-ordered-OrderedExecutor-0-0] INFO org.apache.zookeeper.ZooKeeper - Client environment:user.name=root 23:46:31.283 [pulsar-ordered-OrderedExecutor-0-0] INFO org.apache.zookeeper.ZooKeeper - Client environment:user.home=/root 23:46:31.284 [pulsar-ordered-OrderedExecutor-0-0] INFO org.apache.zookeeper.ZooKeeper - Client environment:user.dir=/pulsar 23:46:31.293 [pulsar-ordered-OrderedExecutor-0-0] INFO org.apache.zookeeper.ZooKeeper - Initiating client connection, connectString=zk-0.zookeeper,zk-1.zookeeper,zk-2.zookeeper sessionTimeout=30000 watcher=org.apache.bookkeeper.zookeeper.ZooKeeperWatcherBase@65e47655 23:46:31.413 [pulsar-ordered-OrderedExecutor-0-0-SendThread(zk-1.zookeeper:2181)] INFO org.apache.zookeeper.ClientCnxn - Opening socket connection to server zk-1.zookeeper/100.96.40.251:2181. Will not attempt to authenticate using SASL (unknown error) 23:46:31.426 [pulsar-ordered-OrderedExecutor-0-0-SendThread(zk-1.zookeeper:2181)] INFO org.apache.zookeeper.ClientCnxn - Socket connection established to zk-1.zookeeper/100.96.40.251:2181, initiating session 23:46:31.437 [pulsar-ordered-OrderedExecutor-0-0-SendThread(zk-1.zookeeper:2181)] INFO org.apache.zookeeper.ClientCnxn - Session establishment complete on server zk-1.zookeeper/100.96.40.251:2181, sessionid = 0x2001579c1c70073, negotiated timeout = 30000 23:46:31.440 [pulsar-ordered-OrderedExecutor-0-0-EventThread] INFO org.apache.bookkeeper.zookeeper.ZooKeeperWatcherBase - ZooKeeper client is connected now. 23:46:31.441 [pulsar-ordered-OrderedExecutor-0-0] INFO org.apache.pulsar.zookeeper.ZookeeperBkClientFactoryImpl - ZooKeeper session established: State:CONNECTED Timeout:30000 sessionid:0x2001579c1c70073 local:/100.96.36.242:34752 remoteserver:zk-1.zookeeper/100.96.40.251:2181 lastZxid:0 xid:1 sent:1 recv:1 queuedpkts:0 pendingresp:0 queuedevents:0 23:46:31.444 [main] INFO org.apache.pulsar.broker.PulsarService - starting configuration cache service 23:46:31.513 [pulsar-ordered-OrderedExecutor-4-0] INFO org.apache.zookeeper.ZooKeeper - Initiating client connection, connectString=zk-0.zookeeper,zk-1.zookeeper,zk-2.zookeeper sessionTimeout=30000 watcher=org.apache.bookkeeper.zookeeper.ZooKeeperWatcherBase@598a5299 23:46:31.515 [pulsar-ordered-OrderedExecutor-4-0-SendThread(zk-1.zookeeper:2181)] INFO org.apache.zookeeper.ClientCnxn - Opening socket connection to server zk-1.zookeeper/100.96.40.251:2181. Will not attempt to authenticate using SASL (unknown error) 23:46:31.517 [pulsar-ordered-OrderedExecutor-4-0-SendThread(zk-1.zookeeper:2181)] INFO org.apache.zookeeper.ClientCnxn - Socket connection established to zk-1.zookeeper/100.96.40.251:2181, initiating session 23:46:31.526 [pulsar-ordered-OrderedExecutor-4-0-SendThread(zk-1.zookeeper:2181)] INFO org.apache.zookeeper.ClientCnxn - Session establishment complete on server zk-1.zookeeper/100.96.40.251:2181, sessionid = 0x2001579c1c70074, negotiated timeout = 30000 23:46:31.527 [pulsar-ordered-OrderedExecutor-4-0-EventThread] INFO org.apache.bookkeeper.zookeeper.ZooKeeperWatcherBase - ZooKeeper client is connected now. 23:46:31.528 [pulsar-ordered-OrderedExecutor-4-0] INFO org.apache.pulsar.zookeeper.ZookeeperBkClientFactoryImpl - ZooKeeper session established: State:CONNECTED Timeout:30000 sessionid:0x2001579c1c70074 local:/100.96.36.242:34756 remoteserver:zk-1.zookeeper/100.96.40.251:2181 lastZxid:0 xid:1 sent:1 recv:1 queuedpkts:0 pendingresp:0 queuedevents:0 23:46:31.757 [main] INFO org.apache.bookkeeper.meta.MetadataDrivers - BookKeeper metadata driver manager initialized 23:46:31.758 [main] INFO org.apache.bookkeeper.meta.MetadataDrivers - BookKeeper metadata driver manager initialized 23:46:31.758 [main] INFO org.apache.bookkeeper.meta.MetadataDrivers - BookKeeper metadata driver manager initialized 23:46:31.764 [main] INFO org.apache.bookkeeper.meta.zk.ZKMetadataDriverBase - Initialize zookeeper metadata driver with external zookeeper client : ledgersRootPath = /ledgers. 23:46:32.016 [pulsar-ordered-OrderedExecutor-0-0-EventThread] INFO org.apache.pulsar.zookeeper.ZkBookieRackAffinityMapping - Reloading the bookie rack affinity mapping cache. 23:46:32.085 [main] INFO org.apache.bookkeeper.client.RackawareEnsemblePlacementPolicyImpl - Initialize rackaware ensemble placement policy @ <Bookie:100.96.36.242:0> @ /default-rack : org.apache.pulsar.zookeeper.ZkBookieRackAffinityMapping. 23:46:32.086 [main] INFO org.apache.bookkeeper.client.RackawareEnsemblePlacementPolicyImpl - Not weighted 23:46:32.098 [main] INFO org.apache.bookkeeper.client.BookKeeper - Weighted ledger placement is not enabled 23:46:32.169 [BookKeeperClientScheduler-OrderedScheduler-0-0] INFO org.apache.bookkeeper.net.NetworkTopologyImpl - Adding a new node: /default-rack/bookkeeper-1.bookkeeper.pulsar.svc.cluster.local:3181 23:46:32.172 [BookKeeperClientScheduler-OrderedScheduler-0-0] INFO org.apache.bookkeeper.net.NetworkTopologyImpl - Adding a new node: /default-rack/bookkeeper-0.bookkeeper.pulsar.svc.cluster.local:3181 23:46:32.175 [BookKeeperClientScheduler-OrderedScheduler-0-0] INFO org.apache.bookkeeper.net.NetworkTopologyImpl - Adding a new node: /default-rack/bookkeeper-2.bookkeeper.pulsar.svc.cluster.local:3181 23:46:32.268 [main] INFO org.apache.bookkeeper.mledger.impl.EntryCacheManager - Initialized managed-ledger entry cache of 3072.0 Mb 23:46:32.400 [main] INFO org.apache.pulsar.broker.service.BrokerService - Using 4 threads for broker service IO 23:46:32.406 [main] INFO org.apache.pulsar.broker.authorization.AuthorizationService - org.apache.pulsar.broker.authorization.PulsarAuthorizationProvider has been loaded. 23:46:32.451 [main] INFO org.apache.pulsar.broker.authentication.AuthenticationService - org.apache.pulsar.broker.authentication.AuthenticationProviderToken has been loaded. 23:46:32.473 [main] INFO org.apache.pulsar.broker.service.BrokerService - Disabling per broker unack-msg blocking due invalid unAckMsgSubscriptionPercentageLimitOnBrokerBlocked 0.16 23:46:32.546 [main] INFO org.apache.pulsar.broker.loadbalance.LeaderElectionService - LeaderElectionService started 23:46:32.582 [main] INFO org.apache.pulsar.broker.loadbalance.LeaderElectionService - Broker [http://100.96.36.242:8080] is the follower now. Waiting for the watch to trigger... 23:46:32.583 [main] INFO org.apache.pulsar.broker.PulsarService - Starting name space service, bootstrap namespaces=[] 23:46:32.762 [main] INFO org.apache.pulsar.broker.PulsarService - No ledger offloader configured, using NULL instance 23:46:32.872 [main] INFO org.apache.pulsar.broker.service.DistributedIdGenerator - Created sequential node at /counters/producer-name/-0000000093 -- Generator Id is pulsar-93 23:46:33.155 [main] INFO org.apache.pulsar.broker.service.BrokerService - Started Pulsar Broker service on port 6650 23:46:33.286 [main] INFO org.apache.pulsar.broker.service.BrokerService - Scheduling a thread to check backlog quota after [60] seconds in background 23:46:33.387 [main] INFO org.eclipse.jetty.util.log - Logging initialized @7575ms to org.eclipse.jetty.util.log.Slf4jLog 23:46:33.997 [main] INFO org.apache.pulsar.broker.cache.LocalZooKeeperCacheService - Successfully created local policies for /admin/local-policies/pulsar/pulsar/100.96.36.242:8080 -- Optional.empty 23:46:34.093 [main] INFO org.apache.pulsar.broker.namespace.OwnershipCache - Trying to acquire ownership of pulsar/pulsar/100.96.36.242:8080/0x00000000_0xffffffff 23:46:34.784 [pulsar-ordered-OrderedExecutor-0-0-EventThread] INFO org.apache.pulsar.broker.namespace.OwnershipCache - Successfully acquired ownership of /namespace/pulsar/pulsar/100.96.36.242:8080/0x00000000_0xffffffff 23:46:34.786 [main] INFO org.apache.pulsar.broker.namespace.NamespaceService - added heartbeat namespace name in local cache: ns=pulsar/pulsar/100.96.36.242:8080 23:46:34.795 [pulsar-3-1] INFO org.apache.pulsar.broker.PulsarService - Loading all topics on bundle: pulsar/pulsar/100.96.36.242:8080/0x00000000_0xffffffff 23:46:35.879 [main] INFO org.apache.bookkeeper.meta.zk.ZKMetadataDriverBase - Initialize zookeeper metadata driver with external zookeeper client : ledgersRootPath = /ledgers. 23:46:35.885 [main] INFO org.apache.bookkeeper.client.RackawareEnsemblePlacementPolicyImpl - Initialize rackaware ensemble placement policy @ <Bookie:100.96.36.242:0> @ /default-rack : org.apache.pulsar.zookeeper.ZkBookieRackAffinityMapping. 23:46:35.886 [main] INFO org.apache.bookkeeper.client.RackawareEnsemblePlacementPolicyImpl - Not weighted 23:46:35.886 [main] INFO org.apache.bookkeeper.client.BookKeeper - Weighted ledger placement is not enabled 23:46:35.896 [BookKeeperClientScheduler-OrderedScheduler-0-0] INFO org.apache.bookkeeper.net.NetworkTopologyImpl - Adding a new node: /default-rack/bookkeeper-1.bookkeeper.pulsar.svc.cluster.local:3181 23:46:35.897 [BookKeeperClientScheduler-OrderedScheduler-0-0] INFO org.apache.bookkeeper.net.NetworkTopologyImpl - Adding a new node: /default-rack/bookkeeper-0.bookkeeper.pulsar.svc.cluster.local:3181 23:46:35.899 [BookKeeperClientScheduler-OrderedScheduler-0-0] INFO org.apache.bookkeeper.net.NetworkTopologyImpl - Adding a new node: /default-rack/bookkeeper-2.bookkeeper.pulsar.svc.cluster.local:3181 23:46:35.971 [main] INFO org.eclipse.jetty.server.Server - jetty-9.4.12.v20180830; built: 2018-08-30T13:59:14.071Z; git: 27208684755d94a92186989f695db2d7b21ebc51; jvm 1.8.0_181-8u181-b13-2~deb9u1-b13 23:46:36.074 [main] INFO org.eclipse.jetty.server.session - DefaultSessionIdManager workerName=node0 23:46:36.074 [main] INFO org.eclipse.jetty.server.session - No SessionScavenger set, using defaults 23:46:36.076 [main] INFO org.eclipse.jetty.server.session - node0 Scavenging every 600000ms 23:46:37.127 [pulsar-ordered-OrderedExecutor-0-0-EventThread] WARN org.apache.pulsar.broker.loadbalance.LeaderElectionService - Type of the event is [NodeDeleted] and path is [/loadbalance/leader] 23:46:37.129 [pulsar-ordered-OrderedExecutor-0-0-EventThread] WARN org.apache.pulsar.broker.loadbalance.LeaderElectionService - Election node /loadbalance/leader is deleted, attempting re-election... 23:46:37.130 [pulsar-ordered-OrderedExecutor-0-0-EventThread] INFO org.apache.pulsar.broker.loadbalance.LeaderElectionService - This should call elect again... 23:46:37.131 [pulsar-3-1] INFO org.apache.pulsar.broker.loadbalance.LeaderElectionService - Broker [http://100.96.36.242:8080] is calling re-election from the thread 23:46:37.208 [pulsar-3-1] INFO org.apache.pulsar.broker.loadbalance.LeaderElectionService - Broker [http://100.96.36.242:8080] is the leader now, notifying the listener... 23:46:39.254 [main] INFO org.eclipse.jetty.server.handler.ContextHandler - Started o.e.j.s.ServletContextHandler@50194e8d{/,null,AVAILABLE} 23:46:39.539 [main] INFO org.eclipse.jetty.server.handler.ContextHandler - Started o.e.j.s.ServletContextHandler@3cee53dc{/,null,AVAILABLE} 23:46:43.355 [main] INFO org.eclipse.jetty.server.handler.ContextHandler - Started o.e.j.s.ServletContextHandler@290aeb20{/admin,null,AVAILABLE} 23:46:44.503 [main] INFO org.eclipse.jetty.server.handler.ContextHandler - Started o.e.j.s.ServletContextHandler@73ad4ecc{/admin/v2,null,AVAILABLE} 23:46:45.133 [main] INFO org.eclipse.jetty.server.handler.ContextHandler - Started o.e.j.s.ServletContextHandler@69da0b12{/admin/v3,null,AVAILABLE} 23:46:45.694 [main] INFO org.eclipse.jetty.server.handler.ContextHandler - Started o.e.j.s.ServletContextHandler@2764c546{/lookup,null,AVAILABLE} 23:46:45.703 [main] INFO org.eclipse.jetty.server.handler.ContextHandler - Started o.e.j.s.ServletContextHandler@59496961{/metrics,null,AVAILABLE} 23:46:45.710 [main] INFO org.eclipse.jetty.server.handler.ContextHandler - Started o.e.j.s.h.ContextHandler@408b87aa{/static,null,AVAILABLE} 23:46:45.765 [main] INFO org.eclipse.jetty.server.AbstractConnector - Started PulsarServerConnector@6aff97d6{HTTP/1.1,[http/1.1]}{0.0.0.0:8080} 23:46:45.770 [main] INFO org.eclipse.jetty.server.Server - Started @19962ms 23:46:45.771 [main] INFO org.apache.pulsar.broker.web.WebService - Web Service started at http://100.96.36.242:8080 23:46:45.785 [main] INFO org.apache.pulsar.broker.PulsarService - Starting load management service ... 23:46:45.959 [main] INFO org.apache.pulsar.broker.PulsarService - Starting load balancer 23:46:45.969 [main] INFO org.apache.pulsar.broker.PulsarService - SLA Namespace = sla-monitor/pulsar/100.96.36.242:8080 doesn't exist. 23:46:45.969 [main] INFO org.apache.pulsar.broker.PulsarService - Starting function worker service 23:46:46.103 [main] INFO org.apache.distributedlog.namespace.NamespaceDriverManager - DistributedLog NamespaceDriverManager initialized 23:46:46.133 [main] INFO org.apache.zookeeper.ZooKeeper - Initiating client connection, connectString=zk-0.zookeeper,zk-1.zookeeper,zk-2.zookeeper sessionTimeout=30000 watcher=org.apache.bookkeeper.zookeeper.ZooKeeperWatcherBase@43c39321 23:46:46.139 [main-SendThread(zk-2.zookeeper:2181)] INFO org.apache.zookeeper.ClientCnxn - Opening socket connection to server zk-2.zookeeper/100.96.31.145:2181. Will not attempt to authenticate using SASL (unknown error) 23:46:46.140 [main-SendThread(zk-2.zookeeper:2181)] INFO org.apache.zookeeper.ClientCnxn - Socket connection established to zk-2.zookeeper/100.96.31.145:2181, initiating session 23:46:46.144 [main-SendThread(zk-2.zookeeper:2181)] INFO org.apache.zookeeper.ClientCnxn - Session establishment complete on server zk-2.zookeeper/100.96.31.145:2181, sessionid = 0x300caa75e8d008b, negotiated timeout = 30000 23:46:46.146 [main-EventThread] INFO org.apache.bookkeeper.zookeeper.ZooKeeperWatcherBase - ZooKeeper client is connected now. 23:46:46.166 [main] INFO org.apache.distributedlog.ZooKeeperClient - Close zookeeper client default. 23:46:46.166 [main] INFO org.apache.distributedlog.ZooKeeperClient - Closing zookeeper client default. 23:46:46.169 [main] INFO org.apache.zookeeper.ZooKeeper - Session: 0x300caa75e8d008b closed 23:46:46.169 [main] INFO org.apache.distributedlog.ZooKeeperClient - Closed zookeeper client default. 23:46:46.169 [main] INFO org.apache.pulsar.broker.PulsarService - Function worker service setup completed 23:46:46.170 [main] INFO org.apache.pulsar.functions.worker.WorkerService - Starting worker c-pulsar-fw-100.96.36.242-8080... 23:46:46.171 [main-EventThread] INFO org.apache.zookeeper.ClientCnxn - EventThread shut down for session: 0x300caa75e8d008b 23:46:47.299 [main] INFO org.apache.pulsar.functions.worker.WorkerService - Worker Configs: { "workerId" : "c-pulsar-fw-100.96.36.242-8080", "workerHostname" : "100.96.36.242", "workerPort" : 8080, "workerPortTls" : 6751, "jvmGCMetricsLoggerClassName" : null, "numHttpServerThreads" : 8, "connectorsDirectory" : "./connectors", "functionMetadataTopicName" : "metadata", "functionWebServiceUrl" : null, "pulsarServiceUrl" : "pulsar://127.0.0.1:6650", "pulsarWebServiceUrl" : "http://127.0.0.1:8080", "clusterCoordinationTopicName" : "coordinate", "pulsarFunctionsNamespace" : "public/functions", "pulsarFunctionsCluster" : "pulsar", "numFunctionPackageReplicas" : 1, "downloadDirectory" : "/tmp/pulsar_functions", "stateStorageServiceUrl" : null, "functionAssignmentTopicName" : "assignments", "schedulerClassName" : "org.apache.pulsar.functions.worker.scheduler.RoundRobinScheduler", "failureCheckFreqMs" : 30000, "rescheduleTimeoutMs" : 60000, "initialBrokerReconnectMaxRetries" : 60, "assignmentWriteMaxRetries" : 60, "instanceLivenessCheckFreqMs" : 30000, "clientAuthenticationPlugin" : "org.apache.pulsar.client.impl.auth.AuthenticationToken", "clientAuthenticationParameters" : "token:<redacted>", "topicCompactionFrequencySec" : 1800, "tlsEnabled" : true, "tlsCertificateFilePath" : null, "tlsKeyFilePath" : null, "tlsTrustCertsFilePath" : null, "tlsAllowInsecureConnection" : false, "tlsRequireTrustedClientCertOnConnect" : false, "useTls" : false, "tlsHostnameVerificationEnable" : false, "authenticationEnabled" : false, "authenticationProviders" : null, "authorizationEnabled" : false, "superUserRoles" : null, "properties" : { }, "threadContainerFactory" : null, "processContainerFactory" : { "javaInstanceJarLocation" : null, "pythonInstanceLocation" : null, "logDirectory" : null, "extraFunctionDependenciesDir" : null }, "kubernetesContainerFactory" : null, "secretsProviderConfiguratorClassName" : null, "secretsProviderConfiguratorConfig" : null, "functionInstanceMinResources" : null, "functionMetadataTopic" : "persistent://public/functions/metadata", "clusterCoordinationTopic" : "persistent://public/functions/coordinate", "functionAssignmentTopic" : "persistent://public/functions/assignments", "workerWebAddress" : "http://100.96.36.242:8080" } 23:46:47.327 [main] INFO org.apache.distributedlog.api.namespace.NamespaceBuilder - No feature provider is set. All features are disabled now. 23:46:47.344 [main] INFO org.apache.distributedlog.impl.BKNamespaceDriver - Created shared zooKeeper client builder dlzk:distributedlog://zk-0.zookeeper,zk-1.zookeeper,zk-2.zookeeper/pulsar/functions:factory_writer_shared: zkServers = zk-0.zookeeper,zk-1.zookeeper,zk-2.zookeeper, numRetries = 3, sessionTimeout = 30000, retryBackoff = 5000, maxRetryBackoff = 30000, zkAclId = null. 23:46:47.346 [main] INFO org.apache.zookeeper.ZooKeeper - Initiating client connection, connectString=zk-0.zookeeper,zk-1.zookeeper,zk-2.zookeeper sessionTimeout=30000 watcher=org.apache.bookkeeper.zookeeper.ZooKeeperWatcherBase@65844c96 23:46:47.371 [main-SendThread(zk-1.zookeeper:2181)] INFO org.apache.zookeeper.ClientCnxn - Opening socket connection to server zk-1.zookeeper/100.96.40.251:2181. Will not attempt to authenticate using SASL (unknown error) 23:46:47.372 [main-SendThread(zk-1.zookeeper:2181)] INFO org.apache.zookeeper.ClientCnxn - Socket connection established to zk-1.zookeeper/100.96.40.251:2181, initiating session 23:46:47.377 [main-SendThread(zk-1.zookeeper:2181)] INFO org.apache.zookeeper.ClientCnxn - Session establishment complete on server zk-1.zookeeper/100.96.40.251:2181, sessionid = 0x2001579c1c70075, negotiated timeout = 30000 23:46:47.378 [main-EventThread] INFO org.apache.bookkeeper.zookeeper.ZooKeeperWatcherBase - ZooKeeper client is connected now. 23:46:47.387 [main] INFO org.apache.distributedlog.impl.BKNamespaceDriver - Created shared client builder bk:distributedlog://zk-0.zookeeper,zk-1.zookeeper,zk-2.zookeeper/pulsar/functions:factory_writer_shared : zkServers = zk-0.zookeeper,zk-1.zookeeper,zk-2.zookeeper, ledgersPath = /ledgers, numIOThreads = 2 23:46:47.393 [main] INFO org.apache.distributedlog.impl.metadata.BKDLConfig - Propagate BKDLConfig to DLConfig : encodeRegionID = false, firstLogSegmentSequenceNumber = 1, createStreamIfNotExists = true, isFederated = false. 23:46:47.410 [main] INFO org.apache.distributedlog.impl.BKNamespaceDriver - Initialized BK namespace driver: clientId = function-worker-c-pulsar-fw-100.96.36.242-8080, regionId = 0, federated = false. 23:46:47.419 [main] INFO org.apache.distributedlog.logsegment.LogSegmentMetadataCache - Log segment cache is enabled = true 23:46:47.542 [main] INFO org.apache.pulsar.functions.worker.WorkerService - Created Pulsar client 23:46:47.861 [pulsar-io-23-1] INFO org.apache.pulsar.broker.service.ServerCnx - New connection from /127.0.0.1:51294 23:46:47.824 [pulsar-client-io-41-1] INFO org.apache.pulsar.client.impl.ConnectionPool - [[id: 0x4f9dd195, L:/127.0.0.1:51294 - R:127.0.0.1/127.0.0.1:6650]] Connected to server 23:46:48.732 [pulsar-io-23-1] INFO org.apache.pulsar.broker.service.ServerCnx - [/127.0.0.1:51294] Client successfully authenticated with token role functions-admin and originalPrincipal null 23:46:49.113 [pulsar-client-io-41-1] INFO org.apache.pulsar.client.impl.ProducerStatsRecorderImpl - Starting Pulsar producer perf with config: { "topicName" : "persistent://public/functions/assignments", "producerName" : null, "sendTimeoutMs" : 0, "blockIfQueueFull" : true, "maxPendingMessages" : 1000, "maxPendingMessagesAcrossPartitions" : 50000, "messageRoutingMode" : "RoundRobinPartition", "hashingScheme" : "JavaStringHash", "cryptoFailureAction" : "FAIL", "batchingMaxPublishDelayMicros" : 1000, "batchingMaxMessages" : 1000, "batchingEnabled" : false, "compressionType" : "LZ4", "initialSequenceId" : null, "autoUpdatePartitions" : true, "properties" : { } } 23:46:49.118 [pulsar-client-io-41-1] INFO org.apache.pulsar.client.impl.ProducerStatsRecorderImpl - Pulsar client config: { "serviceUrl" : "pulsar://127.0.0.1:6650", "operationTimeoutMs" : 30000, "statsIntervalSeconds" : 60, "numIoThreads" : 1, "numListenerThreads" : 1, "connectionsPerBroker" : 1, "useTcpNoDelay" : true, "useTls" : false, "tlsTrustCertsFilePath" : null, "tlsAllowInsecureConnection" : false, "tlsHostnameVerificationEnable" : false, "concurrentLookupRequest" : 5000, "maxLookupRequest" : 50000, "maxNumberOfRejectedRequestPerConnection" : 50, "keepAliveIntervalSeconds" : 30, "connectionTimeoutMs" : 10000 } 23:46:49.251 [pulsar-3-1] INFO org.apache.pulsar.broker.loadbalance.impl.ModularLoadManagerImpl - 1 brokers being considered for assignment of public/functions/0x40000000_0x80000000 23:46:49.253 [pulsar-3-1] INFO org.apache.pulsar.broker.namespace.OwnershipCache - Trying to acquire ownership of public/functions/0x40000000_0x80000000 23:46:49.260 [pulsar-ordered-OrderedExecutor-0-0-EventThread] INFO org.apache.pulsar.broker.namespace.OwnershipCache - Successfully acquired ownership of /namespace/public/functions/0x40000000_0x80000000 23:46:49.261 [pulsar-3-3] INFO org.apache.pulsar.broker.PulsarService - Loading all topics on bundle: public/functions/0x40000000_0x80000000 23:46:49.285 [pulsar-client-io-41-1] INFO org.apache.pulsar.client.impl.ConnectionPool - [[id: 0xc16e4a48, L:/100.96.36.242:50998 - R:100.96.36.242/100.96.36.242:6650]] Connected to server 23:46:49.330 [pulsar-io-23-2] INFO org.apache.pulsar.broker.service.ServerCnx - New connection from /100.96.36.242:50998 23:46:49.333 [pulsar-io-23-2] INFO org.apache.pulsar.broker.service.ServerCnx - [/100.96.36.242:50998] Client successfully authenticated with token role functions-admin and originalPrincipal null 23:46:49.333 [pulsar-client-io-41-1] INFO org.apache.pulsar.client.impl.ProducerImpl - [persistent://public/functions/assignments] [null] Creating producer on cnx [id: 0xc16e4a48, L:/100.96.36.242:50998 - R:100.96.36.242/100.96.36.242:6650] 23:46:49.376 [Thread-5] INFO org.apache.pulsar.broker.service.ServerCnx - [/100.96.36.242:50998][persistent://public/functions/assignments] Creating producer. producerId=0 23:46:49.633 [pulsar-3-3] INFO org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl - Opening managed ledger public/functions/persistent/assignments 23:46:49.696 [pulsar-3-3] INFO org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl - Opening managed ledger public/functions/persistent/coordinate 23:46:49.712 [pulsar-3-3] INFO org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl - Opening managed ledger public/functions/persistent/metadata 23:46:50.508 [bookkeeper-io-14-2] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - Successfully connected to bookie: [id: 0xcaa39f3c, L:/100.96.36.242:35602 - R:bookkeeper-1.bookkeeper.pulsar.svc.cluster.local/100.96.40.252:3181] 23:46:50.508 [bookkeeper-io-14-4] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - Successfully connected to bookie: [id: 0xc7e99134, L:/100.96.36.242:35598 - R:bookkeeper-1.bookkeeper.pulsar.svc.cluster.local/100.96.40.252:3181] 23:46:50.508 [bookkeeper-io-14-1] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - Successfully connected to bookie: [id: 0xca602354, L:/100.96.36.242:35604 - R:bookkeeper-1.bookkeeper.pulsar.svc.cluster.local/100.96.40.252:3181] 23:46:50.508 [bookkeeper-io-14-1] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - Successfully connected to bookie: bookkeeper-1.bookkeeper.pulsar.svc.cluster.local:3181 23:46:50.509 [bookkeeper-io-14-4] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - Successfully connected to bookie: bookkeeper-1.bookkeeper.pulsar.svc.cluster.local:3181 23:46:50.512 [bookkeeper-io-14-2] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - Successfully connected to bookie: bookkeeper-1.bookkeeper.pulsar.svc.cluster.local:3181 23:46:50.508 [bookkeeper-io-14-3] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - Successfully connected to bookie: [id: 0x9f584e69, L:/100.96.36.242:35600 - R:bookkeeper-1.bookkeeper.pulsar.svc.cluster.local/100.96.40.252:3181] 23:46:50.513 [bookkeeper-io-14-3] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - Successfully connected to bookie: bookkeeper-1.bookkeeper.pulsar.svc.cluster.local:3181 23:46:50.513 [bookkeeper-io-14-4] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - connection [id: 0xc7e99134, L:/100.96.36.242:35598 - R:bookkeeper-1.bookkeeper.pulsar.svc.cluster.local/100.96.40.252:3181] authenticated as BookKeeperPrincipal{ANONYMOUS} 23:46:50.514 [bookkeeper-io-14-2] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - connection [id: 0xcaa39f3c, L:/100.96.36.242:35602 - R:bookkeeper-1.bookkeeper.pulsar.svc.cluster.local/100.96.40.252:3181] authenticated as BookKeeperPrincipal{ANONYMOUS} 23:46:50.514 [bookkeeper-io-14-3] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - connection [id: 0x9f584e69, L:/100.96.36.242:35600 - R:bookkeeper-1.bookkeeper.pulsar.svc.cluster.local/100.96.40.252:3181] authenticated as BookKeeperPrincipal{ANONYMOUS} 23:46:50.520 [bookkeeper-io-14-3] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - Successfully connected to bookie: [id: 0x5e00b64e, L:/100.96.36.242:35606 - R:bookkeeper-1.bookkeeper.pulsar.svc.cluster.local/100.96.40.252:3181] 23:46:50.520 [bookkeeper-io-14-3] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - Successfully connected to bookie: bookkeeper-1.bookkeeper.pulsar.svc.cluster.local:3181 23:46:50.522 [bookkeeper-io-14-3] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - connection [id: 0x5e00b64e, L:/100.96.36.242:35606 - R:bookkeeper-1.bookkeeper.pulsar.svc.cluster.local/100.96.40.252:3181] authenticated as BookKeeperPrincipal{ANONYMOUS} 23:46:50.519 [bookkeeper-io-14-2] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - Successfully connected to bookie: [id: 0x884a83f8, L:/100.96.36.242:35608 - R:bookkeeper-1.bookkeeper.pulsar.svc.cluster.local/100.96.40.252:3181] 23:46:50.522 [bookkeeper-io-14-2] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - Successfully connected to bookie: bookkeeper-1.bookkeeper.pulsar.svc.cluster.local:3181 23:46:50.522 [bookkeeper-io-14-2] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - connection [id: 0x884a83f8, L:/100.96.36.242:35608 - R:bookkeeper-1.bookkeeper.pulsar.svc.cluster.local/100.96.40.252:3181] authenticated as BookKeeperPrincipal{ANONYMOUS} 23:46:50.522 [bookkeeper-io-14-4] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - Successfully connected to bookie: [id: 0xa32410db, L:/100.96.36.242:35610 - R:bookkeeper-1.bookkeeper.pulsar.svc.cluster.local/100.96.40.252:3181] 23:46:50.522 [bookkeeper-io-14-4] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - Successfully connected to bookie: bookkeeper-1.bookkeeper.pulsar.svc.cluster.local:3181 23:46:50.522 [bookkeeper-io-14-4] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - connection [id: 0xa32410db, L:/100.96.36.242:35610 - R:bookkeeper-1.bookkeeper.pulsar.svc.cluster.local/100.96.40.252:3181] authenticated as BookKeeperPrincipal{ANONYMOUS} 23:46:50.523 [bookkeeper-io-14-3] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - Successfully connected to bookie: [id: 0xcb0757e8, L:/100.96.36.242:35614 - R:bookkeeper-1.bookkeeper.pulsar.svc.cluster.local/100.96.40.252:3181] 23:46:50.523 [bookkeeper-io-14-3] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - Successfully connected to bookie: bookkeeper-1.bookkeeper.pulsar.svc.cluster.local:3181 23:46:50.523 [bookkeeper-io-14-3] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - connection [id: 0xcb0757e8, L:/100.96.36.242:35614 - R:bookkeeper-1.bookkeeper.pulsar.svc.cluster.local/100.96.40.252:3181] authenticated as BookKeeperPrincipal{ANONYMOUS} 23:46:50.523 [bookkeeper-io-14-2] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - Successfully connected to bookie: [id: 0x96fa5dfe, L:/100.96.36.242:35616 - R:bookkeeper-1.bookkeeper.pulsar.svc.cluster.local/100.96.40.252:3181] 23:46:50.523 [bookkeeper-io-14-2] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - Successfully connected to bookie: bookkeeper-1.bookkeeper.pulsar.svc.cluster.local:3181 23:46:50.523 [bookkeeper-io-14-2] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - connection [id: 0x96fa5dfe, L:/100.96.36.242:35616 - R:bookkeeper-1.bookkeeper.pulsar.svc.cluster.local/100.96.40.252:3181] authenticated as BookKeeperPrincipal{ANONYMOUS} 23:46:50.523 [bookkeeper-io-14-4] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - Successfully connected to bookie: [id: 0xeec06fc8, L:/100.96.36.242:35618 - R:bookkeeper-1.bookkeeper.pulsar.svc.cluster.local/100.96.40.252:3181] 23:46:50.524 [bookkeeper-io-14-4] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - Successfully connected to bookie: bookkeeper-1.bookkeeper.pulsar.svc.cluster.local:3181 23:46:50.524 [bookkeeper-io-14-4] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - connection [id: 0xeec06fc8, L:/100.96.36.242:35618 - R:bookkeeper-1.bookkeeper.pulsar.svc.cluster.local/100.96.40.252:3181] authenticated as BookKeeperPrincipal{ANONYMOUS} 23:46:50.524 [bookkeeper-io-14-3] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - Successfully connected to bookie: [id: 0xe4a81a4e, L:/100.96.36.242:35622 - R:bookkeeper-1.bookkeeper.pulsar.svc.cluster.local/100.96.40.252:3181] 23:46:50.524 [bookkeeper-io-14-3] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - Successfully connected to bookie: bookkeeper-1.bookkeeper.pulsar.svc.cluster.local:3181 23:46:50.525 [bookkeeper-io-14-2] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - Successfully connected to bookie: [id: 0xab29194f, L:/100.96.36.242:35624 - R:bookkeeper-1.bookkeeper.pulsar.svc.cluster.local/100.96.40.252:3181] 23:46:50.526 [bookkeeper-io-14-2] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - Successfully connected to bookie: bookkeeper-1.bookkeeper.pulsar.svc.cluster.local:3181 23:46:50.526 [bookkeeper-io-14-4] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - Successfully connected to bookie: [id: 0x53b8a756, L:/100.96.36.242:35626 - R:bookkeeper-1.bookkeeper.pulsar.svc.cluster.local/100.96.40.252:3181] 23:46:50.526 [bookkeeper-io-14-2] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - connection [id: 0xab29194f, L:/100.96.36.242:35624 - R:bookkeeper-1.bookkeeper.pulsar.svc.cluster.local/100.96.40.252:3181] authenticated as BookKeeperPrincipal{ANONYMOUS} 23:46:50.526 [bookkeeper-io-14-4] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - Successfully connected to bookie: bookkeeper-1.bookkeeper.pulsar.svc.cluster.local:3181 23:46:50.528 [bookkeeper-io-14-2] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - Successfully connected to bookie: [id: 0x3e664070, L:/100.96.36.242:43610 - R:bookkeeper-0.bookkeeper.pulsar.svc.cluster.local/100.96.45.87:3181] 23:46:50.528 [bookkeeper-io-14-2] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - Successfully connected to bookie: bookkeeper-0.bookkeeper.pulsar.svc.cluster.local:3181 23:46:50.528 [bookkeeper-io-14-2] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - connection [id: 0x3e664070, L:/100.96.36.242:43610 - R:bookkeeper-0.bookkeeper.pulsar.svc.cluster.local/100.96.45.87:3181] authenticated as BookKeeperPrincipal{ANONYMOUS} 23:46:50.529 [bookkeeper-io-14-2] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - Successfully connected to bookie: [id: 0x3bc9a20b, L:/100.96.36.242:43616 - R:bookkeeper-0.bookkeeper.pulsar.svc.cluster.local/100.96.45.87:3181] 23:46:50.529 [bookkeeper-io-14-2] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - Successfully connected to bookie: bookkeeper-0.bookkeeper.pulsar.svc.cluster.local:3181 23:46:50.529 [bookkeeper-io-14-2] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - connection [id: 0x3bc9a20b, L:/100.96.36.242:43616 - R:bookkeeper-0.bookkeeper.pulsar.svc.cluster.local/100.96.45.87:3181] authenticated as BookKeeperPrincipal{ANONYMOUS} 23:46:50.530 [bookkeeper-io-14-2] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - Successfully connected to bookie: [id: 0x316f9ec0, L:/100.96.36.242:43618 - R:bookkeeper-0.bookkeeper.pulsar.svc.cluster.local/100.96.45.87:3181] 23:46:50.530 [bookkeeper-io-14-2] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - Successfully connected to bookie: bookkeeper-0.bookkeeper.pulsar.svc.cluster.local:3181 23:46:50.530 [bookkeeper-io-14-2] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - connection [id: 0x316f9ec0, L:/100.96.36.242:43618 - R:bookkeeper-0.bookkeeper.pulsar.svc.cluster.local/100.96.45.87:3181] authenticated as BookKeeperPrincipal{ANONYMOUS} 23:46:50.532 [bookkeeper-io-14-3] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - connection [id: 0xe4a81a4e, L:/100.96.36.242:35622 - R:bookkeeper-1.bookkeeper.pulsar.svc.cluster.local/100.96.40.252:3181] authenticated as BookKeeperPrincipal{ANONYMOUS} 23:46:50.532 [bookkeeper-io-14-4] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - connection [id: 0x53b8a756, L:/100.96.36.242:35626 - R:bookkeeper-1.bookkeeper.pulsar.svc.cluster.local/100.96.40.252:3181] authenticated as BookKeeperPrincipal{ANONYMOUS} 23:46:50.539 [bookkeeper-io-14-1] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - connection [id: 0xca602354, L:/100.96.36.242:35604 - R:bookkeeper-1.bookkeeper.pulsar.svc.cluster.local/100.96.40.252:3181] authenticated as BookKeeperPrincipal{ANONYMOUS} 23:46:50.539 [bookkeeper-io-14-2] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - Successfully connected to bookie: [id: 0x5ace16ae, L:/100.96.36.242:43620 - R:bookkeeper-0.bookkeeper.pulsar.svc.cluster.local/100.96.45.87:3181] 23:46:50.539 [bookkeeper-io-14-2] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - Successfully connected to bookie: bookkeeper-0.bookkeeper.pulsar.svc.cluster.local:3181 23:46:50.539 [bookkeeper-io-14-2] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - connection [id: 0x5ace16ae, L:/100.96.36.242:43620 - R:bookkeeper-0.bookkeeper.pulsar.svc.cluster.local/100.96.45.87:3181] authenticated as BookKeeperPrincipal{ANONYMOUS} 23:46:50.541 [bookkeeper-io-14-4] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - Successfully connected to bookie: [id: 0xf29b7341, L:/100.96.36.242:43612 - R:bookkeeper-0.bookkeeper.pulsar.svc.cluster.local/100.96.45.87:3181] 23:46:50.541 [bookkeeper-io-14-3] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - Successfully connected to bookie: [id: 0x839e8057, L:/100.96.36.242:43608 - R:bookkeeper-0.bookkeeper.pulsar.svc.cluster.local/100.96.45.87:3181] 23:46:50.541 [bookkeeper-io-14-2] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - Successfully connected to bookie: [id: 0x70d32a59, L:/100.96.36.242:37176 - R:bookkeeper-2.bookkeeper.pulsar.svc.cluster.local/100.96.45.90:3181] 23:46:50.541 [bookkeeper-io-14-2] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - Successfully connected to bookie: bookkeeper-2.bookkeeper.pulsar.svc.cluster.local:3181 23:46:50.541 [bookkeeper-io-14-2] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - connection [id: 0x70d32a59, L:/100.96.36.242:37176 - R:bookkeeper-2.bookkeeper.pulsar.svc.cluster.local/100.96.45.90:3181] authenticated as BookKeeperPrincipal{ANONYMOUS} 23:46:50.542 [bookkeeper-io-14-2] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - Successfully connected to bookie: [id: 0x4ab0f7bc, L:/100.96.36.242:37178 - R:bookkeeper-2.bookkeeper.pulsar.svc.cluster.local/100.96.45.90:3181] 23:46:50.542 [bookkeeper-io-14-2] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - Successfully connected to bookie: bookkeeper-2.bookkeeper.pulsar.svc.cluster.local:3181 23:46:50.542 [bookkeeper-io-14-2] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - connection [id: 0x4ab0f7bc, L:/100.96.36.242:37178 - R:bookkeeper-2.bookkeeper.pulsar.svc.cluster.local/100.96.45.90:3181] authenticated as BookKeeperPrincipal{ANONYMOUS} 23:46:50.542 [bookkeeper-io-14-2] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - Successfully connected to bookie: [id: 0x229d74d4, L:/100.96.36.242:37180 - R:bookkeeper-2.bookkeeper.pulsar.svc.cluster.local/100.96.45.90:3181] 23:46:50.543 [bookkeeper-io-14-2] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - Successfully connected to bookie: bookkeeper-2.bookkeeper.pulsar.svc.cluster.local:3181 23:46:50.543 [bookkeeper-io-14-3] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - Successfully connected to bookie: bookkeeper-0.bookkeeper.pulsar.svc.cluster.local:3181 23:46:50.543 [bookkeeper-io-14-2] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - connection [id: 0x229d74d4, L:/100.96.36.242:37180 - R:bookkeeper-2.bookkeeper.pulsar.svc.cluster.local/100.96.45.90:3181] authenticated as BookKeeperPrincipal{ANONYMOUS} 23:46:50.543 [bookkeeper-io-14-3] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - connection [id: 0x839e8057, L:/100.96.36.242:43608 - R:bookkeeper-0.bookkeeper.pulsar.svc.cluster.local/100.96.45.87:3181] authenticated as BookKeeperPrincipal{ANONYMOUS} 23:46:50.543 [bookkeeper-io-14-3] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - Successfully connected to bookie: [id: 0x5e67bd3b, L:/100.96.36.242:43630 - R:bookkeeper-0.bookkeeper.pulsar.svc.cluster.local/100.96.45.87:3181] 23:46:50.544 [bookkeeper-io-14-3] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - Successfully connected to bookie: bookkeeper-0.bookkeeper.pulsar.svc.cluster.local:3181 23:46:50.544 [bookkeeper-io-14-2] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - Successfully connected to bookie: [id: 0xd208cac4, L:/100.96.36.242:37196 - R:bookkeeper-2.bookkeeper.pulsar.svc.cluster.local/100.96.45.90:3181] 23:46:50.544 [bookkeeper-io-14-2] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - Successfully connected to bookie: bookkeeper-2.bookkeeper.pulsar.svc.cluster.local:3181 23:46:50.544 [bookkeeper-io-14-3] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - connection [id: 0x5e67bd3b, L:/100.96.36.242:43630 - R:bookkeeper-0.bookkeeper.pulsar.svc.cluster.local/100.96.45.87:3181] authenticated as BookKeeperPrincipal{ANONYMOUS} 23:46:50.544 [bookkeeper-io-14-2] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - connection [id: 0xd208cac4, L:/100.96.36.242:37196 - R:bookkeeper-2.bookkeeper.pulsar.svc.cluster.local/100.96.45.90:3181] authenticated as BookKeeperPrincipal{ANONYMOUS} 23:46:50.541 [bookkeeper-io-14-4] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - Successfully connected to bookie: bookkeeper-0.bookkeeper.pulsar.svc.cluster.local:3181 23:46:50.545 [bookkeeper-io-14-3] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - Successfully connected to bookie: [id: 0xb0d004fd, L:/100.96.36.242:43632 - R:bookkeeper-0.bookkeeper.pulsar.svc.cluster.local/100.96.45.87:3181] 23:46:50.545 [bookkeeper-io-14-3] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - Successfully connected to bookie: bookkeeper-0.bookkeeper.pulsar.svc.cluster.local:3181 23:46:50.546 [bookkeeper-io-14-4] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - connection [id: 0xf29b7341, L:/100.96.36.242:43612 - R:bookkeeper-0.bookkeeper.pulsar.svc.cluster.local/100.96.45.87:3181] authenticated as BookKeeperPrincipal{ANONYMOUS} 23:46:50.546 [bookkeeper-io-14-3] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - connection [id: 0xb0d004fd, L:/100.96.36.242:43632 - R:bookkeeper-0.bookkeeper.pulsar.svc.cluster.local/100.96.45.87:3181] authenticated as BookKeeperPrincipal{ANONYMOUS} 23:46:50.547 [bookkeeper-io-14-4] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - Successfully connected to bookie: [id: 0xbbb80673, L:/100.96.36.242:43622 - R:bookkeeper-0.bookkeeper.pulsar.svc.cluster.local/100.96.45.87:3181] 23:46:50.547 [bookkeeper-io-14-1] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - Successfully connected to bookie: [id: 0x4068fc18, L:/100.96.36.242:35612 - R:bookkeeper-1.bookkeeper.pulsar.svc.cluster.local/100.96.40.252:3181] 23:46:50.547 [bookkeeper-io-14-3] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - Successfully connected to bookie: [id: 0xa9723dc9, L:/100.96.36.242:43634 - R:bookkeeper-0.bookkeeper.pulsar.svc.cluster.local/100.96.45.87:3181] 23:46:50.547 [bookkeeper-io-14-4] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - Successfully connected to bookie: bookkeeper-0.bookkeeper.pulsar.svc.cluster.local:3181 23:46:50.548 [bookkeeper-io-14-4] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - connection [id: 0xbbb80673, L:/100.96.36.242:43622 - R:bookkeeper-0.bookkeeper.pulsar.svc.cluster.local/100.96.45.87:3181] authenticated as BookKeeperPrincipal{ANONYMOUS} 23:46:50.548 [bookkeeper-io-14-4] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - Successfully connected to bookie: [id: 0xd853754d, L:/100.96.36.242:43624 - R:bookkeeper-0.bookkeeper.pulsar.svc.cluster.local/100.96.45.87:3181] 23:46:50.548 [bookkeeper-io-14-4] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - Successfully connected to bookie: bookkeeper-0.bookkeeper.pulsar.svc.cluster.local:3181 23:46:50.548 [bookkeeper-io-14-4] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - connection [id: 0xd853754d, L:/100.96.36.242:43624 - R:bookkeeper-0.bookkeeper.pulsar.svc.cluster.local/100.96.45.87:3181] authenticated as BookKeeperPrincipal{ANONYMOUS} 23:46:50.548 [bookkeeper-io-14-4] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - Successfully connected to bookie: [id: 0xb88d65f6, L:/100.96.36.242:43626 - R:bookkeeper-0.bookkeeper.pulsar.svc.cluster.local/100.96.45.87:3181] 23:46:50.548 [bookkeeper-io-14-4] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - Successfully connected to bookie: bookkeeper-0.bookkeeper.pulsar.svc.cluster.local:3181 23:46:50.548 [bookkeeper-io-14-4] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - connection [id: 0xb88d65f6, L:/100.96.36.242:43626 - R:bookkeeper-0.bookkeeper.pulsar.svc.cluster.local/100.96.45.87:3181] authenticated as BookKeeperPrincipal{ANONYMOUS} 23:46:50.549 [bookkeeper-io-14-3] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - Successfully connected to bookie: bookkeeper-0.bookkeeper.pulsar.svc.cluster.local:3181 23:46:50.549 [bookkeeper-io-14-3] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - connection [id: 0xa9723dc9, L:/100.96.36.242:43634 - R:bookkeeper-0.bookkeeper.pulsar.svc.cluster.local/100.96.45.87:3181] authenticated as BookKeeperPrincipal{ANONYMOUS} 23:46:50.549 [bookkeeper-io-14-3] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - Successfully connected to bookie: [id: 0x72af9b18, L:/100.96.36.242:37170 - R:bookkeeper-2.bookkeeper.pulsar.svc.cluster.local/100.96.45.90:3181] 23:46:50.549 [bookkeeper-io-14-3] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - Successfully connected to bookie: bookkeeper-2.bookkeeper.pulsar.svc.cluster.local:3181 23:46:50.549 [bookkeeper-io-14-3] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - connection [id: 0x72af9b18, L:/100.96.36.242:37170 - R:bookkeeper-2.bookkeeper.pulsar.svc.cluster.local/100.96.45.90:3181] authenticated as BookKeeperPrincipal{ANONYMOUS} 23:46:50.550 [bookkeeper-io-14-3] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - Successfully connected to bookie: [id: 0x51934c32, L:/100.96.36.242:37172 - R:bookkeeper-2.bookkeeper.pulsar.svc.cluster.local/100.96.45.90:3181] 23:46:50.550 [bookkeeper-io-14-3] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - Successfully connected to bookie: bookkeeper-2.bookkeeper.pulsar.svc.cluster.local:3181 23:46:50.552 [bookkeeper-io-14-3] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - connection [id: 0x51934c32, L:/100.96.36.242:37172 - R:bookkeeper-2.bookkeeper.pulsar.svc.cluster.local/100.96.45.90:3181] authenticated as BookKeeperPrincipal{ANONYMOUS} 23:46:50.551 [bookkeeper-io-14-4] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - Successfully connected to bookie: [id: 0x1a9918ff, L:/100.96.36.242:37182 - R:bookkeeper-2.bookkeeper.pulsar.svc.cluster.local/100.96.45.90:3181] 23:46:50.547 [bookkeeper-io-14-1] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - Successfully connected to bookie: bookkeeper-1.bookkeeper.pulsar.svc.cluster.local:3181 23:46:50.553 [bookkeeper-io-14-1] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - connection [id: 0x4068fc18, L:/100.96.36.242:35612 - R:bookkeeper-1.bookkeeper.pulsar.svc.cluster.local/100.96.40.252:3181] authenticated as BookKeeperPrincipal{ANONYMOUS} 23:46:50.553 [bookkeeper-io-14-1] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - Successfully connected to bookie: [id: 0xc633dd09, L:/100.96.36.242:35620 - R:bookkeeper-1.bookkeeper.pulsar.svc.cluster.local/100.96.40.252:3181] 23:46:50.553 [bookkeeper-io-14-1] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - Successfully connected to bookie: bookkeeper-1.bookkeeper.pulsar.svc.cluster.local:3181 23:46:50.553 [bookkeeper-io-14-1] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - connection [id: 0xc633dd09, L:/100.96.36.242:35620 - R:bookkeeper-1.bookkeeper.pulsar.svc.cluster.local/100.96.40.252:3181] authenticated as BookKeeperPrincipal{ANONYMOUS} 23:46:50.554 [bookkeeper-io-14-1] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - Successfully connected to bookie: [id: 0xd6259f0c, L:/100.96.36.242:35628 - R:bookkeeper-1.bookkeeper.pulsar.svc.cluster.local/100.96.40.252:3181] 23:46:50.554 [bookkeeper-io-14-1] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - Successfully connected to bookie: bookkeeper-1.bookkeeper.pulsar.svc.cluster.local:3181 23:46:50.554 [bookkeeper-io-14-1] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - connection [id: 0xd6259f0c, L:/100.96.36.242:35628 - R:bookkeeper-1.bookkeeper.pulsar.svc.cluster.local/100.96.40.252:3181] authenticated as BookKeeperPrincipal{ANONYMOUS} 23:46:50.552 [bookkeeper-io-14-3] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - Successfully connected to bookie: [id: 0x3db5e43a, L:/100.96.36.242:37174 - R:bookkeeper-2.bookkeeper.pulsar.svc.cluster.local/100.96.45.90:3181] 23:46:50.554 [bookkeeper-io-14-3] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - Successfully connected to bookie: bookkeeper-2.bookkeeper.pulsar.svc.cluster.local:3181 23:46:50.553 [bookkeeper-io-14-4] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - Successfully connected to bookie: bookkeeper-2.bookkeeper.pulsar.svc.cluster.local:3181 23:46:50.556 [bookkeeper-io-14-3] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - connection [id: 0x3db5e43a, L:/100.96.36.242:37174 - R:bookkeeper-2.bookkeeper.pulsar.svc.cluster.local/100.96.45.90:3181] authenticated as BookKeeperPrincipal{ANONYMOUS} 23:46:50.556 [bookkeeper-io-14-1] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - Successfully connected to bookie: [id: 0x64f6998e, L:/100.96.36.242:43614 - R:bookkeeper-0.bookkeeper.pulsar.svc.cluster.local/100.96.45.87:3181] 23:46:50.556 [bookkeeper-io-14-4] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - connection [id: 0x1a9918ff, L:/100.96.36.242:37182 - R:bookkeeper-2.bookkeeper.pulsar.svc.cluster.local/100.96.45.90:3181] authenticated as BookKeeperPrincipal{ANONYMOUS} 23:46:50.556 [bookkeeper-io-14-1] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - Successfully connected to bookie: bookkeeper-0.bookkeeper.pulsar.svc.cluster.local:3181 23:46:50.557 [bookkeeper-io-14-4] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - Successfully connected to bookie: [id: 0xe6c8575f, L:/100.96.36.242:37184 - R:bookkeeper-2.bookkeeper.pulsar.svc.cluster.local/100.96.45.90:3181] 23:46:50.557 [bookkeeper-io-14-4] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - Successfully connected to bookie: bookkeeper-2.bookkeeper.pulsar.svc.cluster.local:3181 23:46:50.557 [bookkeeper-io-14-3] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - Successfully connected to bookie: [id: 0xcbd1554c, L:/100.96.36.242:37194 - R:bookkeeper-2.bookkeeper.pulsar.svc.cluster.local/100.96.45.90:3181] 23:46:50.557 [bookkeeper-io-14-1] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - connection [id: 0x64f6998e, L:/100.96.36.242:43614 - R:bookkeeper-0.bookkeeper.pulsar.svc.cluster.local/100.96.45.87:3181] authenticated as BookKeeperPrincipal{ANONYMOUS} 23:46:50.558 [bookkeeper-io-14-3] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - Successfully connected to bookie: bookkeeper-2.bookkeeper.pulsar.svc.cluster.local:3181 23:46:50.557 [bookkeeper-io-14-4] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - connection [id: 0xe6c8575f, L:/100.96.36.242:37184 - R:bookkeeper-2.bookkeeper.pulsar.svc.cluster.local/100.96.45.90:3181] authenticated as BookKeeperPrincipal{ANONYMOUS} 23:46:50.558 [bookkeeper-io-14-3] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - connection [id: 0xcbd1554c, L:/100.96.36.242:37194 - R:bookkeeper-2.bookkeeper.pulsar.svc.cluster.local/100.96.45.90:3181] authenticated as BookKeeperPrincipal{ANONYMOUS} 23:46:50.559 [bookkeeper-io-14-4] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - Successfully connected to bookie: [id: 0x3e0c9fea, L:/100.96.36.242:37186 - R:bookkeeper-2.bookkeeper.pulsar.svc.cluster.local/100.96.45.90:3181] 23:46:50.559 [bookkeeper-io-14-4] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - Successfully connected to bookie: bookkeeper-2.bookkeeper.pulsar.svc.cluster.local:3181 23:46:50.560 [bookkeeper-io-14-4] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - connection [id: 0x3e0c9fea, L:/100.96.36.242:37186 - R:bookkeeper-2.bookkeeper.pulsar.svc.cluster.local/100.96.45.90:3181] authenticated as BookKeeperPrincipal{ANONYMOUS} 23:46:50.562 [bookkeeper-io-14-1] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - Successfully connected to bookie: [id: 0x2fac6636, L:/100.96.36.242:43628 - R:bookkeeper-0.bookkeeper.pulsar.svc.cluster.local/100.96.45.87:3181] 23:46:50.562 [bookkeeper-io-14-4] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - Successfully connected to bookie: [id: 0x86e6b7f0, L:/100.96.36.242:37198 - R:bookkeeper-2.bookkeeper.pulsar.svc.cluster.local/100.96.45.90:3181] 23:46:50.562 [bookkeeper-io-14-4] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - Successfully connected to bookie: bookkeeper-2.bookkeeper.pulsar.svc.cluster.local:3181 23:46:50.563 [bookkeeper-io-14-4] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - connection [id: 0x86e6b7f0, L:/100.96.36.242:37198 - R:bookkeeper-2.bookkeeper.pulsar.svc.cluster.local/100.96.45.90:3181] authenticated as BookKeeperPrincipal{ANONYMOUS} 23:46:50.562 [bookkeeper-io-14-1] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - Successfully connected to bookie: bookkeeper-0.bookkeeper.pulsar.svc.cluster.local:3181 23:46:50.564 [bookkeeper-io-14-1] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - connection [id: 0x2fac6636, L:/100.96.36.242:43628 - R:bookkeeper-0.bookkeeper.pulsar.svc.cluster.local/100.96.45.87:3181] authenticated as BookKeeperPrincipal{ANONYMOUS} 23:46:50.564 [bookkeeper-io-14-1] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - Successfully connected to bookie: [id: 0x9ffdf212, L:/100.96.36.242:43636 - R:bookkeeper-0.bookkeeper.pulsar.svc.cluster.local/100.96.45.87:3181] 23:46:50.565 [bookkeeper-io-14-1] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - Successfully connected to bookie: bookkeeper-0.bookkeeper.pulsar.svc.cluster.local:3181 23:46:50.565 [bookkeeper-io-14-1] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - connection [id: 0x9ffdf212, L:/100.96.36.242:43636 - R:bookkeeper-0.bookkeeper.pulsar.svc.cluster.local/100.96.45.87:3181] authenticated as BookKeeperPrincipal{ANONYMOUS} 23:46:50.566 [bookkeeper-io-14-1] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - Successfully connected to bookie: [id: 0xd752a509, L:/100.96.36.242:43638 - R:bookkeeper-0.bookkeeper.pulsar.svc.cluster.local/100.96.45.87:3181] 23:46:50.566 [bookkeeper-io-14-1] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - Successfully connected to bookie: bookkeeper-0.bookkeeper.pulsar.svc.cluster.local:3181 23:46:50.566 [bookkeeper-io-14-1] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - connection [id: 0xd752a509, L:/100.96.36.242:43638 - R:bookkeeper-0.bookkeeper.pulsar.svc.cluster.local/100.96.45.87:3181] authenticated as BookKeeperPrincipal{ANONYMOUS} 23:46:50.567 [bookkeeper-io-14-1] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - Successfully connected to bookie: [id: 0x2cedd42f, L:/100.96.36.242:37188 - R:bookkeeper-2.bookkeeper.pulsar.svc.cluster.local/100.96.45.90:3181] 23:46:50.568 [bookkeeper-io-14-1] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - Successfully connected to bookie: bookkeeper-2.bookkeeper.pulsar.svc.cluster.local:3181 23:46:50.569 [bookkeeper-io-14-1] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - connection [id: 0x2cedd42f, L:/100.96.36.242:37188 - R:bookkeeper-2.bookkeeper.pulsar.svc.cluster.local/100.96.45.90:3181] authenticated as BookKeeperPrincipal{ANONYMOUS} 23:46:50.571 [bookkeeper-io-14-1] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - Successfully connected to bookie: [id: 0x3df9ccd6, L:/100.96.36.242:37190 - R:bookkeeper-2.bookkeeper.pulsar.svc.cluster.local/100.96.45.90:3181] 23:46:50.573 [bookkeeper-io-14-1] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - Successfully connected to bookie: bookkeeper-2.bookkeeper.pulsar.svc.cluster.local:3181 23:46:50.574 [bookkeeper-io-14-1] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - connection [id: 0x3df9ccd6, L:/100.96.36.242:37190 - R:bookkeeper-2.bookkeeper.pulsar.svc.cluster.local/100.96.45.90:3181] authenticated as BookKeeperPrincipal{ANONYMOUS} 23:46:50.575 [bookkeeper-io-14-1] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - Successfully connected to bookie: [id: 0x45d132df, L:/100.96.36.242:37192 - R:bookkeeper-2.bookkeeper.pulsar.svc.cluster.local/100.96.45.90:3181] 23:46:50.575 [bookkeeper-io-14-1] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - Successfully connected to bookie: bookkeeper-2.bookkeeper.pulsar.svc.cluster.local:3181 23:46:50.576 [bookkeeper-io-14-1] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - connection [id: 0x45d132df, L:/100.96.36.242:37192 - R:bookkeeper-2.bookkeeper.pulsar.svc.cluster.local/100.96.45.90:3181] authenticated as BookKeeperPrincipal{ANONYMOUS} 23:46:50.577 [bookkeeper-io-14-1] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - Successfully connected to bookie: [id: 0x7f7d1fc3, L:/100.96.36.242:37200 - R:bookkeeper-2.bookkeeper.pulsar.svc.cluster.local/100.96.45.90:3181] 23:46:50.577 [bookkeeper-io-14-1] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - Successfully connected to bookie: bookkeeper-2.bookkeeper.pulsar.svc.cluster.local:3181 23:46:50.680 [bookkeeper-io-14-1] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - connection [id: 0x7f7d1fc3, L:/100.96.36.242:37200 - R:bookkeeper-2.bookkeeper.pulsar.svc.cluster.local/100.96.45.90:3181] authenticated as BookKeeperPrincipal{ANONYMOUS} 23:46:50.764 [BookKeeperClientWorker-OrderedExecutor-1-0] INFO com.scurrilous.circe.checksum.Crc32cIntChecksum - SSE4.2 CRC32C provider initialized 23:46:50.881 [BookKeeperClientWorker-OrderedExecutor-0-0] ERROR org.apache.bookkeeper.common.util.SafeRunnable - Unexpected throwable caught java.lang.ArrayIndexOutOfBoundsException: -2 at com.google.common.collect.RegularImmutableList.get(RegularImmutableList.java:60) ~[com.google.guava-guava-21.0.jar:?] at org.apache.bookkeeper.client.PendingReadOp$SequenceReadRequest.sendNextRead(PendingReadOp.java:400) ~[org.apache.bookkeeper-bookkeeper-server-4.9.0.jar:4.9.0] at org.apache.bookkeeper.client.PendingReadOp$SequenceReadRequest.read(PendingReadOp.java:382) ~[org.apache.bookkeeper-bookkeeper-server-4.9.0.jar:4.9.0] at org.apache.bookkeeper.client.PendingReadOp.initiate(PendingReadOp.java:526) ~[org.apache.bookkeeper-bookkeeper-server-4.9.0.jar:4.9.0] at org.apache.bookkeeper.client.LedgerRecoveryOp.doRecoveryRead(LedgerRecoveryOp.java:148) ~[org.apache.bookkeeper-bookkeeper-server-4.9.0.jar:4.9.0] at org.apache.bookkeeper.client.LedgerRecoveryOp.access$000(LedgerRecoveryOp.java:37) ~[org.apache.bookkeeper-bookkeeper-server-4.9.0.jar:4.9.0] at org.apache.bookkeeper.client.LedgerRecoveryOp$1.readLastConfirmedDataComplete(LedgerRecoveryOp.java:109) ~[org.apache.bookkeeper-bookkeeper-server-4.9.0.jar:4.9.0] at org.apache.bookkeeper.client.ReadLastConfirmedOp.readEntryComplete(ReadLastConfirmedOp.java:135) ~[org.apache.bookkeeper-bookkeeper-server-4.9.0.jar:4.9.0] at org.apache.bookkeeper.proto.PerChannelBookieClient$ReadCompletion$1.readEntryComplete(PerChannelBookieClient.java:1797) ~[org.apache.bookkeeper-bookkeeper-server-4.9.0.jar:4.9.0] at org.apache.bookkeeper.proto.PerChannelBookieClient$ReadCompletion.handleReadResponse(PerChannelBookieClient.java:1878) ~[org.apache.bookkeeper-bookkeeper-server-4.9.0.jar:4.9.0] at org.apache.bookkeeper.proto.PerChannelBookieClient$ReadCompletion.handleV2Response(PerChannelBookieClient.java:1831) ~[org.apache.bookkeeper-bookkeeper-server-4.9.0.jar:4.9.0] at org.apache.bookkeeper.proto.PerChannelBookieClient$ReadV2ResponseCallback.safeRun(PerChannelBookieClient.java:1321) ~[org.apache.bookkeeper-bookkeeper-server-4.9.0.jar:4.9.0] at org.apache.bookkeeper.common.util.SafeRunnable.run(SafeRunnable.java:36) [org.apache.bookkeeper-bookkeeper-common-4.9.0.jar:4.9.0] at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_181] at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_181] at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) [io.netty-netty-all-4.1.32.Final.jar:4.1.32.Final] at java.lang.Thread.run(Thread.java:748) [?:1.8.0_181] 23:46:51.036 [BookKeeperClientWorker-OrderedExecutor-0-0] INFO org.apache.bookkeeper.client.ReadOnlyLedgerHandle - Closing recovered ledger 94 at entry -1 23:46:51.057 [BookKeeperClientWorker-OrderedExecutor-1-0] INFO org.apache.bookkeeper.client.ReadOnlyLedgerHandle - Closing recovered ledger 95 at entry 1 23:46:51.106 [bookkeeper-ml-workers-OrderedExecutor-0-0] WARN org.apache.bookkeeper.client.BookieWatcherImpl - New ensemble: [bookkeeper-2.bookkeeper.pulsar.svc.cluster.local:3181, bookkeeper-0.bookkeeper.pulsar.svc.cluster.local:3181, bookkeeper-1.bookkeeper.pulsar.svc.cluster.local:3181] is not adhering to Placement Policy. quarantinedBookies: [] 23:46:51.107 [bookkeeper-ml-workers-OrderedExecutor-6-0] WARN org.apache.bookkeeper.client.BookieWatcherImpl - New ensemble: [bookkeeper-2.bookkeeper.pulsar.svc.cluster.local:3181, bookkeeper-1.bookkeeper.pulsar.svc.cluster.local:3181, bookkeeper-0.bookkeeper.pulsar.svc.cluster.local:3181] is not adhering to Placement Policy. quarantinedBookies: [] 23:46:51.135 [pulsar-ordered-OrderedExecutor-0-0-EventThread] INFO org.apache.bookkeeper.client.LedgerCreateOp - Ensemble: [bookkeeper-2.bookkeeper.pulsar.svc.cluster.local:3181, bookkeeper-1.bookkeeper.pulsar.svc.cluster.local:3181, bookkeeper-0.bookkeeper.pulsar.svc.cluster.local:3181] for ledger: 98 23:46:51.139 [bookkeeper-ml-workers-OrderedExecutor-6-0] INFO org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl - [public/functions/persistent/coordinate] Created ledger 98 23:46:51.148 [pulsar-ordered-OrderedExecutor-0-0-EventThread] INFO org.apache.bookkeeper.client.LedgerCreateOp - Ensemble: [bookkeeper-2.bookkeeper.pulsar.svc.cluster.local:3181, bookkeeper-0.bookkeeper.pulsar.svc.cluster.local:3181, bookkeeper-1.bookkeeper.pulsar.svc.cluster.local:3181] for ledger: 99 23:46:51.152 [bookkeeper-ml-workers-OrderedExecutor-0-0] INFO org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl - [public/functions/persistent/assignments] Created ledger 99 23:46:51.219 [bookkeeper-ml-workers-OrderedExecutor-0-0] INFO org.apache.bookkeeper.mledger.impl.ManagedCursorImpl - [public/functions/persistent/assignments] Recovering from bookkeeper ledger cursor: __compaction 23:46:51.220 [bookkeeper-ml-workers-OrderedExecutor-6-0] INFO org.apache.bookkeeper.mledger.impl.ManagedCursorImpl - [public/functions/persistent/coordinate] Recovering from bookkeeper ledger cursor: participants 23:46:51.237 [bookkeeper-ml-workers-OrderedExecutor-0-0] INFO org.apache.bookkeeper.mledger.impl.ManagedCursorImpl - [public/functions/persistent/assignments] Consumer __compaction meta-data recover from ledger 97 23:46:51.238 [bookkeeper-ml-workers-OrderedExecutor-6-0] INFO org.apache.bookkeeper.mledger.impl.ManagedCursorImpl - [public/functions/persistent/coordinate] Consumer participants meta-data recover from ledger 3 23:46:51.340 [BookKeeperClientWorker-OrderedExecutor-1-0] INFO org.apache.bookkeeper.mledger.impl.ManagedCursorImpl - [public/functions/persistent/coordinate] Cursor participants recovered to position 98:-1 23:46:51.344 [BookKeeperClientWorker-OrderedExecutor-1-0] INFO org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl - [public/functions/persistent/coordinate] Recovery for cursor participants completed. pos=98:-1 -- todo=0 23:46:51.423 [BookKeeperClientWorker-OrderedExecutor-1-0] INFO org.apache.pulsar.broker.service.BrokerService - Created topic persistent://public/functions/coordinate - dedup is disabled 23:46:51.440 [BookKeeperClientWorker-OrderedExecutor-1-0] INFO org.apache.bookkeeper.client.ReadOnlyLedgerHandle - Closing recovered ledger 97 at entry 1 23:46:51.447 [BookKeeperClientWorker-OrderedExecutor-1-0] INFO org.apache.bookkeeper.mledger.impl.ManagedCursorImpl - [public/functions/persistent/assignments] Cursor __compaction recovered to position 0:-1 23:46:51.449 [BookKeeperClientWorker-OrderedExecutor-1-0] INFO org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl - [public/functions/persistent/assignments] Recovery for cursor __compaction completed. pos=0:-1 -- todo=0 23:46:51.451 [BookKeeperClientWorker-OrderedExecutor-1-0] INFO org.apache.pulsar.broker.service.BrokerService - Created topic persistent://public/functions/assignments - dedup is disabled 23:46:51.569 [BookKeeperClientWorker-OrderedExecutor-1-0] INFO org.apache.pulsar.broker.service.ServerCnx - [/100.96.36.242:50998] Created new producer: Producer{topic=PersistentTopic{topic=persistent://public/functions/assignments}, client=/100.96.36.242:50998, producerName=pulsar-93-0, producerId=0} 23:46:51.589 [pulsar-client-io-41-1] INFO org.apache.pulsar.client.impl.ProducerImpl - [persistent://public/functions/assignments] [pulsar-93-0] Created producer on cnx [id: 0xc16e4a48, L:/100.96.36.242:50998 - R:100.96.36.242/100.96.36.242:6650] 23:46:51.797 [pulsar-client-io-41-1] INFO org.apache.pulsar.client.impl.ProducerStatsRecorderImpl - Starting Pulsar producer perf with config: { "topicName" : "persistent://public/functions/metadata", "producerName" : null, "sendTimeoutMs" : 30000, "blockIfQueueFull" : false, "maxPendingMessages" : 1000, "maxPendingMessagesAcrossPartitions" : 50000, "messageRoutingMode" : "RoundRobinPartition", "hashingScheme" : "JavaStringHash", "cryptoFailureAction" : "FAIL", "batchingMaxPublishDelayMicros" : 1000, "batchingMaxMessages" : 1000, "batchingEnabled" : true, "compressionType" : "NONE", "initialSequenceId" : null, "autoUpdatePartitions" : true, "properties" : { } } 23:46:51.806 [pulsar-client-io-41-1] INFO org.apache.pulsar.client.impl.ProducerStatsRecorderImpl - Pulsar client config: { "serviceUrl" : "pulsar://127.0.0.1:6650", "operationTimeoutMs" : 30000, "statsIntervalSeconds" : 60, "numIoThreads" : 1, "numListenerThreads" : 1, "connectionsPerBroker" : 1, "useTcpNoDelay" : true, "useTls" : false, "tlsTrustCertsFilePath" : null, "tlsAllowInsecureConnection" : false, "tlsHostnameVerificationEnable" : false, "concurrentLookupRequest" : 5000, "maxLookupRequest" : 50000, "maxNumberOfRejectedRequestPerConnection" : 50, "keepAliveIntervalSeconds" : 30, "connectionTimeoutMs" : 10000 } 23:46:51.841 [pulsar-client-io-41-1] INFO org.apache.pulsar.client.impl.ProducerImpl - [persistent://public/functions/metadata] [null] Creating producer on cnx [id: 0xc16e4a48, L:/100.96.36.242:50998 - R:100.96.36.242/100.96.36.242:6650] 23:46:51.843 [Thread-9] INFO org.apache.pulsar.broker.service.ServerCnx - [/100.96.36.242:50998][persistent://public/functions/metadata] Creating producer. producerId=1

jerrypeng commented 5 years ago

broker (1).log

log provided by @zarrarrana what the issue

chairmank commented 5 years ago

I see this problem only when triggering offload to tiered storage:

14:13:53.419 [bookkeeper-ml-workers-OrderedExecutor-2-0] INFO  org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl - [foo/test/persistent/redacted] End Offlo[1825/30696]
60, uuid=dc6c1e97-3e9c-4bbd-aa2a-fba14250eedc
14:13:53.420 [bookkeeper-ml-scheduler-OrderedScheduler-2-0] INFO  org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl - [foo/test/persistent/redacted] Preparing metadata
 to offload ledger 161 with uuid a929b551-f701-4219-828b-e22dcf79a0e7
14:13:53.428 [bookkeeper-ml-workers-OrderedExecutor-2-0] INFO  org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl - [foo/test/persistent/redacted] Metadata prepared for
 offload of ledger 161 with uuid a929b551-f701-4219-828b-e22dcf79a0e7
14:13:53.447 [offloader-OrderedScheduler-1-0] ERROR org.apache.bookkeeper.common.util.SafeRunnable - Unexpected throwable caught 
java.lang.ArrayIndexOutOfBoundsException: Index -2 out of bounds for length 3
        at com.google.common.collect.RegularImmutableList.get(RegularImmutableList.java:60) ~[com.google.guava-guava-21.0.jar:?]
        at org.apache.bookkeeper.client.PendingReadOp$SequenceReadRequest.sendNextRead(PendingReadOp.java:400) ~[org.apache.bookkeeper-bookkeeper-server-4.9.0.jar:4.9.0]
        at org.apache.bookkeeper.client.PendingReadOp$SequenceReadRequest.read(PendingReadOp.java:382) ~[org.apache.bookkeeper-bookkeeper-server-4.9.0.jar:4.9.0]
        at org.apache.bookkeeper.client.PendingReadOp.initiate(PendingReadOp.java:526) ~[org.apache.bookkeeper-bookkeeper-server-4.9.0.jar:4.9.0]
        at org.apache.bookkeeper.client.PendingReadOp.safeRun(PendingReadOp.java:536) ~[org.apache.bookkeeper-bookkeeper-server-4.9.0.jar:4.9.0]
        at org.apache.bookkeeper.common.util.SafeRunnable.run(SafeRunnable.java:36) [org.apache.bookkeeper-bookkeeper-common-4.9.0.jar:4.9.0]
        at org.apache.bookkeeper.client.LedgerHandle.readEntriesInternalAsync(LedgerHandle.java:894) [org.apache.bookkeeper-bookkeeper-server-4.9.0.jar:4.9.0]
        at org.apache.bookkeeper.client.LedgerHandle.readAsync(LedgerHandle.java:757) [org.apache.bookkeeper-bookkeeper-server-4.9.0.jar:4.9.0]
        at org.apache.bookkeeper.mledger.offload.jcloud.impl.BlockAwareSegmentInputStreamImpl.readNextEntriesFromLedger(BlockAwareSegmentInputStreamImpl.java:117) [tiered-storage-jc
loud-2.4.0-SNAPSHOT.nar-unpacked/:?]
        at org.apache.bookkeeper.mledger.offload.jcloud.impl.BlockAwareSegmentInputStreamImpl.readEntries(BlockAwareSegmentInputStreamImpl.java:89) [tiered-storage-jcloud-2.4.0-SNAP
SHOT.nar-unpacked/:?]
        at org.apache.bookkeeper.mledger.offload.jcloud.impl.BlockAwareSegmentInputStreamImpl.read(BlockAwareSegmentInputStreamImpl.java:157) [tiered-storage-jcloud-2.4.0-SNAPSHOT.n
ar-unpacked/:?]
        at java.io.InputStream.read(InputStream.java:280) [?:?]
        at java.io.InputStream.read(InputStream.java:205) [?:?]
        at org.apache.pulsar.shaded.com.google.common.io.ByteStreams.copy(ByteStreams.java:106) [jclouds-shaded-2.4.0-SNAPSHOT.jar:2.4.0-SNAPSHOT]
        at org.jclouds.http.internal.JavaUrlHttpCommandExecutorService.writePayloadToConnection(JavaUrlHttpCommandExecutorService.java:298) [jclouds-shaded-2.4.0-SNAPSHOT.jar:2.4.0-
SNAPSHOT]
        at org.jclouds.http.internal.JavaUrlHttpCommandExecutorService.convert(JavaUrlHttpCommandExecutorService.java:171) [jclouds-shaded-2.4.0-SNAPSHOT.jar:2.4.0-SNAPSHOT]
        at org.jclouds.http.internal.JavaUrlHttpCommandExecutorService.convert(JavaUrlHttpCommandExecutorService.java:65) [jclouds-shaded-2.4.0-SNAPSHOT.jar:2.4.0-SNAPSHOT]
        at org.jclouds.http.internal.BaseHttpCommandExecutorService.invoke(BaseHttpCommandExecutorService.java:97) [jclouds-shaded-2.4.0-SNAPSHOT.jar:2.4.0-SNAPSHOT]
        at org.jclouds.rest.internal.InvokeHttpMethod.invoke(InvokeHttpMethod.java:91) [jclouds-shaded-2.4.0-SNAPSHOT.jar:2.4.0-SNAPSHOT]
        at org.jclouds.rest.internal.InvokeHttpMethod.apply(InvokeHttpMethod.java:74) [jclouds-shaded-2.4.0-SNAPSHOT.jar:2.4.0-SNAPSHOT]
        at org.jclouds.rest.internal.InvokeHttpMethod.apply(InvokeHttpMethod.java:45) [jclouds-shaded-2.4.0-SNAPSHOT.jar:2.4.0-SNAPSHOT]
        at org.jclouds.rest.internal.DelegatesToInvocationFunction.handle(DelegatesToInvocationFunction.java:156) [jclouds-shaded-2.4.0-SNAPSHOT.jar:2.4.0-SNAPSHOT]
        at org.jclouds.rest.internal.DelegatesToInvocationFunction.invoke(DelegatesToInvocationFunction.java:123) [jclouds-shaded-2.4.0-SNAPSHOT.jar:2.4.0-SNAPSHOT]
        at com.sun.proxy.$Proxy72.uploadPart(Unknown Source) [?:?]
        at org.jclouds.s3.blobstore.S3BlobStore.uploadMultipartPart(S3BlobStore.java:393) [jclouds-shaded-2.4.0-SNAPSHOT.jar:2.4.0-SNAPSHOT]
        at org.apache.bookkeeper.mledger.offload.jcloud.impl.BlobStoreManagedLedgerOffloader.lambda$offload$2(BlobStoreManagedLedgerOffloader.java:424) [tiered-storage-jcloud-2.4.0-
SNAPSHOT.nar-unpacked/:?]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) [?:?]
        at com.google.common.util.concurrent.TrustedListenableFutureTask$TrustedFutureInterruptibleTask.runInterruptibly(TrustedListenableFutureTask.java:111) [com.google.guava-guav
a-21.0.jar:?]
        at com.google.common.util.concurrent.InterruptibleTask.run(InterruptibleTask.java:58) [com.google.guava-guava-21.0.jar:?]
        at com.google.common.util.concurrent.TrustedListenableFutureTask.run(TrustedListenableFutureTask.java:75) [com.google.guava-guava-21.0.jar:?]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) [?:?]
        at java.util.concurrent.FutureTask.run(FutureTask.java:264) [?:?]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) [?:?]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]

On https://github.com/apache/bookkeeper/issues/1970, I described my investigation of this issue. Something (I haven't traced exactly what) is calling the readAsync method of org.apache.bookkeeper.client.LedgerHandle with an entry ID of -2, and org.apache.bookkeeper.client.RoundRobinDistributionSchedule can not handle a negative entryId.

sijie commented 5 years ago

@chairmank I think your problem is related to #3913 when offloader attempts to offload an empty ledger.

jerrypeng commented 5 years ago

@sijie some users who do not have tiered storage turned on are also reporting this problem

zarrarrana commented 5 years ago

With help form @jerrypeng , I have been able to get pass the issue by changing the following properties

managedLedgerDefaultAckQuorum: 2
managedLedgerDefaultEnsembleSize: 3
managedLedgerDefaultWriteQuorum: 2

to

managedLedgerDefaultAckQuorum: 2
managedLedgerDefaultEnsembleSize: 2
managedLedgerDefaultWriteQuorum: 2

Our pulsar cluster is on kubernetes with 3 bookies, 3 zookeepers and 3 brokers. It might help you narrow down the issue.

sijie commented 5 years ago

The problem was due to the StickyRead feature introduced in bookkeeper since 4.9.0. Pulsar 2.3.0 turns on this feature by default.

I am fixing this issue. At the same time, for people who encountered this issue, you can disable sticky read on broker to get around it.

bookkeeperEnableStickyReads=false
sijie commented 5 years ago

moved this to 2.5.0 since it is unlikely we will get the fix in time.

sijie commented 5 years ago

sticky read will be disabled by default in 2.4.0. it should be good enough.

sijie commented 4 years ago

Closed this issue since the bookkeeper version is updated to 4.10 including the bookkeeper client fix.