Broker restarted due to ZooKeeper client is disconnected

[oneforalone]

Hi, I'm just new to Pulsar, and trying to deploy it to k8s cluster. However, stucking in broker pods keep restarting. And the log show that the ZooKeeper client is disconnected, but the zookeeper pods' status show they're ready. And after checking with the log, it keep printing:

2023-07-10T18:03:59,442+0000 [NIOWorkerThread-3] WARN  org.apache.zookeeper.server.NIOServerCnxn - Unexpected exception
org.apache.zookeeper.server.ServerCnxn$EndOfStreamException: Unable to read additional data from client, it probably closed the socket: address = /10.0.0.168:48160, session = 0x10030a0ed220043
	at org.apache.zookeeper.server.NIOServerCnxn.handleFailedRead(NIOServerCnxn.java:170) ~[org.apache.zookeeper-zookeeper-3.8.0.jar:3.8.0]
	at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:333) ~[org.apache.zookeeper-zookeeper-3.8.0.jar:3.8.0]
	at org.apache.zookeeper.server.NIOServerCnxnFactory$IOWorkRequest.doWork(NIOServerCnxnFactory.java:508) ~[org.apache.zookeeper-zookeeper-3.8.0.jar:3.8.0]
	at org.apache.zookeeper.server.WorkerService$ScheduledWorkRequest.run(WorkerService.java:153) ~[org.apache.zookeeper-zookeeper-3.8.0.jar:3.8.0]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136) ~[?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) ~[?:?]
	at java.lang.Thread.run(Thread.java:833) ~[?:?]
2023-07-10T18:04:03,966+0000 [SyncThread:1] WARN  org.apache.zookeeper.server.persistence.FileTxnLog - fsync-ing the write ahead log in SyncThread:1 took 4765ms which will adversely effect operation latency.File size is 67108880 bytes. See the ZooKeeper troubleshooting guide
2023-07-10T18:04:03,967+0000 [CommitProcessor:1] INFO  org.apache.zookeeper.server.quorum.LearnerSessionTracker - Committing global session 0x2004566c5d3004f
2023-07-10T18:04:06,215+0000 [SyncThread:1] WARN  org.apache.zookeeper.server.persistence.FileTxnLog - fsync-ing the write ahead log in SyncThread:1 took 2239ms which will adversely effect operation latency.File size is 67108880 bytes. See the ZooKeeper troubleshooting guide
2023-07-10T18:04:08,003+0000 [CommitProcessor:1] INFO  org.apache.zookeeper.server.quorum.LearnerSessionTracker - Committing global session 0x2004566c5d30050
2023-07-10T18:04:10,779+0000 [SyncThread:1] WARN  org.apache.zookeeper.server.persistence.FileTxnLog - fsync-ing the write ahead log in SyncThread:1 took 4548ms which will adversely effect operation latency.File size is 67108880 bytes. See the ZooKeeper troubleshooting guide
2023-07-10T18:04:10,779+0000 [CommitProcessor:1] INFO  org.apache.zookeeper.server.quorum.LearnerSessionTracker - Committing global session 0x10030a0ed220044
2023-07-10T18:04:11,638+0000 [NIOWorkerThread-14] INFO  org.apache.zookeeper.server.NIOServerCnxn - Processing ruok command from /127.0.0.1:52822
2023-07-10T18:04:11,649+0000 [NIOWorkerThread-12] INFO  org.apache.zookeeper.server.NIOServerCnxn - Processing ruok command from /127.0.0.1:52826
2023-07-10T18:04:12,914+0000 [SyncThread:1] WARN  org.apache.zookeeper.server.persistence.FileTxnLog - fsync-ing the write ahead log in SyncThread:1 took 2121ms which will adversely effect operation latency.File size is 67108880 bytes. See the ZooKeeper troubleshooting guide
2023-07-10T18:04:15,014+0000 [CommitProcessor:1] INFO  org.apache.zookeeper.server.quorum.LearnerSessionTracker - Committing global session 0x2004566c5d30051
2023-07-10T18:04:17,095+0000 [CommitProcessor:1] INFO  org.apache.zookeeper.server.quorum.LearnerSessionTracker - Committing global session 0x3004566d0950046
2023-07-10T18:04:17,273+0000 [SyncThread:1] WARN  org.apache.zookeeper.server.persistence.FileTxnLog - fsync-ing the write ahead log in SyncThread:1 took 4345ms which will adversely effect operation latency.File size is 67108880 bytes. See the ZooKeeper troubleshooting guide
2023-07-10T18:04:17,274+0000 [CommitProcessor:1] INFO  org.apache.zookeeper.server.quorum.LearnerSessionTracker - Committing global session 0x2004566c5d30052
2023-07-10T18:04:19,449+0000 [SyncThread:1] WARN  org.apache.zookeeper.server.persistence.FileTxnLog - fsync-ing the write ahead log in SyncThread:1 took 2168ms which will adversely effect operation latency.File size is 67108880 bytes. See the ZooKeeper troubleshooting guide
2023-07-10T18:04:22,090+0000 [CommitProcessor:1] INFO  org.apache.zookeeper.server.quorum.LearnerSessionTracker - Committing global session 0x2004566c5d30053
2023-07-10T18:04:24,144+0000 [CommitProcessor:1] INFO  org.apache.zookeeper.server.quorum.LearnerSessionTracker - Committing global session 0x2004566c5d30054
2023-07-10T18:04:24,173+0000 [SyncThread:1] WARN  org.apache.zookeeper.server.persistence.FileTxnLog - fsync-ing the write ahead log in SyncThread:1 took 4700ms which will adversely effect operation latency.File size is 67108880 bytes. See the ZooKeeper troubleshooting guide
2023-07-10T18:04:26,207+0000 [SyncThread:1] WARN  org.apache.zookeeper.server.persistence.FileTxnLog - fsync-ing the write ahead log in SyncThread:1 took 2026ms which will adversely effect operation latency.File size is 67108880 bytes. See the ZooKeeper troubleshooting guide
2023-07-10T18:04:30,831+0000 [SyncThread:1] WARN  org.apache.zookeeper.server.persistence.FileTxnLog - fsync-ing the write ahead log in SyncThread:1 took 4605ms which will adversely effect operation latency.File size is 67108880 bytes. See the ZooKeeper troubleshooting guide
2023-07-10T18:04:30,999+0000 [CommitProcessor:1] INFO  org.apache.zookeeper.server.quorum.LearnerSessionTracker - Committing global session 0x2004566c5d30055
2023-07-10T18:04:32,981+0000 [SyncThread:1] WARN  org.apache.zookeeper.server.persistence.FileTxnLog - fsync-ing the write ahead log in SyncThread:1 took 2143ms which will adversely effect operation latency.File size is 67108880 bytes. See the ZooKeeper troubleshooting guide
2023-07-10T18:04:37,601+0000 [SyncThread:1] WARN  org.apache.zookeeper.server.persistence.FileTxnLog - fsync-ing the write ahead log in SyncThread:1 took 4606ms which will adversely effect operation latency.File size is 67108880 bytes. See the ZooKeeper troubleshooting guide
2023-07-10T18:04:39,851+0000 [SyncThread:1] WARN  org.apache.zookeeper.server.persistence.FileTxnLog - fsync-ing the write ahead log in SyncThread:1 took 2248ms which will adversely effect operation latency.File size is 67108880 bytes. See the ZooKeeper troubleshooting guide
2023-07-10T18:04:41,637+0000 [NIOWorkerThread-6] INFO  org.apache.zookeeper.server.NIOServerCnxn - Processing ruok command from /127.0.0.1:57874
2023-07-10T18:04:41,647+0000 [NIOWorkerThread-2] INFO  org.apache.zookeeper.server.NIOServerCnxn - Processing ruok command from /127.0.0.1:57890
2023-07-10T18:04:44,421+0000 [SyncThread:1] WARN  org.apache.zookeeper.server.persistence.FileTxnLog - fsync-ing the write ahead log in SyncThread:1 took 4528ms which will adversely effect operation latency.File size is 67108880 bytes. See the ZooKeeper troubleshooting guide
2023-07-10T18:04:46,605+0000 [SyncThread:1] WARN  org.apache.zookeeper.server.persistence.FileTxnLog - fsync-ing the write ahead log in SyncThread:1 took 2175ms which will adversely effect operation latency.File size is 67108880 bytes. See the ZooKeeper troubleshooting guide
2023-07-10T18:04:51,271+0000 [SyncThread:1] WARN  org.apache.zookeeper.server.persistence.FileTxnLog - fsync-ing the write ahead log in SyncThread:1 took 4644ms which will adversely effect operation latency.File size is 67108880 bytes. See the ZooKeeper troubleshooting guide
2023-07-10T18:04:53,335+0000 [SyncThread:1] WARN  org.apache.zookeeper.server.persistence.FileTxnLog - fsync-ing the write ahead log in SyncThread:1 took 2058ms which will adversely effect operation latency.File size is 67108880 bytes. See the ZooKeeper troubleshooting guide
2023-07-10T18:04:57,591+0000 [SyncThread:1] WARN  org.apache.zookeeper.server.persistence.FileTxnLog - fsync-ing the write ahead log in SyncThread:1 took 4226ms which will adversely effect operation latency.File size is 67108880 bytes. See the ZooKeeper troubleshooting guide
2023-07-10T18:04:59,804+0000 [SyncThread:1] WARN  org.apache.zookeeper.server.persistence.FileTxnLog - fsync-ing the write ahead log in SyncThread:1 took 2203ms which will adversely effect operation latency.File size is 67108880 bytes. See the ZooKeeper troubleshooting guide
2023-07-10T18:05:03,975+0000 [SyncThread:1] WARN  org.apache.zookeeper.server.persistence.FileTxnLog - fsync-ing the write ahead log in SyncThread:1 took 4159ms which will adversely effect operation latency.File size is 67108880 bytes. See the ZooKeeper troubleshooting guide
2023-07-10T18:05:06,244+0000 [SyncThread:1] WARN  org.apache.zookeeper.server.persistence.FileTxnLog - fsync-ing the write ahead log in SyncThread:1 took 2256ms which will adversely effect operation latency.File size is 67108880 bytes. See the ZooKeeper troubleshooting guide
2023-07-10T18:05:10,901+0000 [SyncThread:1] WARN  org.apache.zookeeper.server.persistence.FileTxnLog - fsync-ing the write ahead log in SyncThread:1 took 4644ms which will adversely effect operation latency.File size is 67108880 bytes. See the ZooKeeper troubleshooting guide
2023-07-10T18:05:11,637+0000 [NIOWorkerThread-11] INFO  org.apache.zookeeper.server.NIOServerCnxn - Processing ruok command from /127.0.0.1:33448
2023-07-10T18:05:11,646+0000 [NIOWorkerThread-16] INFO  org.apache.zookeeper.server.NIOServerCnxn - Processing ruok command from /127.0.0.1:33450
2023-07-10T18:05:13,017+0000 [SyncThread:1] WARN  org.apache.zookeeper.server.persistence.FileTxnLog - fsync-ing the write ahead log in SyncThread:1 took 2107ms which will adversely effect operation latency.File size is 67108880 bytes. See the ZooKeeper troubleshooting guide
2023-07-10T18:05:17,592+0000 [SyncThread:1] WARN  org.apache.zookeeper.server.persistence.FileTxnLog - fsync-ing the write ahead log in SyncThread:1 took 4563ms which will adversely effect operation latency.File size is 67108880 bytes. See the ZooKeeper troubleshooting guide
2023-07-10T18:05:19,816+0000 [SyncThread:1] WARN  org.apache.zookeeper.server.persistence.FileTxnLog - fsync-ing the write ahead log in SyncThread:1 took 2214ms which will adversely effect operation latency.File size is 67108880 bytes. See the ZooKeeper troubleshooting guide
2023-07-10T18:05:24,126+0000 [SyncThread:1] WARN  org.apache.zookeeper.server.persistence.FileTxnLog - fsync-ing the write ahead log in SyncThread:1 took 4297ms which will adversely effect operation latency.File size is 67108880 bytes. See the ZooKeeper troubleshooting guide

What's wrong with it? Don't know how to dealing with this case. Anyone can help me out?

[oneforalone]

BTW, i'm using the latest version of kubectl and helm. Here is the version info:

• kubectl

Client Version: version.Info{Major:"1", Minor:"26+", GitVersion:"v1.26.3-aliyun.1", GitCommit:"55e48a5160770253d1a32f2523435cd31367843f", GitTreeState:"clean", BuildDate:"2023-06-13T02:00:50Z", GoVersion:"go1.19.7", Compiler:"gc", Platform:"linux/amd64"}
Kustomize Version: v4.5.7
Server Version: version.Info{Major:"1", Minor:"26+", GitVersion:"v1.26.3-aliyun.1", GitCommit:"833527c1e14974c10e68fe0130013a43e45e8ec1", GitTreeState:"clean", BuildDate:"2023-04-17T02:57:57Z", GoVersion:"go1.19.7", Compiler:"gc", Platform:"linux/amd64"}

• helm

version.BuildInfo{Version:"v3.12.1", GitCommit:"f32a527a060157990e2aa86bf45010dfb3cc8b8d", GitTreeState:"clean", GoVersion:"go1.20.4"}

And pulsar-all image is using 3.0.0, pulsar-manager is using v0.4.0.

Plus, the value.yaml file is:

kube-prometheus-stack:
  enabled: false
  prometheusOperator:
    enabled: false
  grafana:
    enabled: false
  alertmanager:
    enabled: false
  prometheus:
    enabled: false

auth:
  authentication:
    enabled: true
    provider: "jwt"
    jwt:
      usingSecretKey: false
  authorization:
    enabled: true
  superUsers:
    # broker to broker communication
    broker: "broker-admin"
    # proxy to broker communication
    proxy: "proxy-admin"
    # pulsar-admin client to broker/proxy communication
    client: "admin"


components:
  autorecovery: true
  bookkeeper: true
  broker: true
  functions: true
  proxy: true
  pulsar_manager: true
  toolset: true
  zookeeper: true


volumes:
  local_storage: true



proxy:
  nodeSelector:
    node-role.kubernetes.io/pulsar: pulsar
  tolerations:
  - key: "dedicated"
    operator: "Equal"
    value: "pulsar"
    effect: "NoSchedule"
  configData:
     PULSAR_PREFIX_authenticateMetricsEndpoint: "false"


broker:
  nodeSelector:
    node-role.kubernetes.io/pulsar: pulsar
  tolerations:
  - key: "dedicated"
    operator: "Equal"
    value: "pulsar"
    effect: "NoSchedule"


zookeeper:
  securityContext:
    runAsUser: 0
    fsGroup: 0
    fsGroupChangePolicy: "OnRootMismatch"
  replicaCount: 3
  tolerations:
  - key: "dedicated"
    operator: "Equal"
    value: "pulsar"
    effect: "NoSchedule"
  volumes:
    data:
      local_storage: true
      size: 20Gi

bookkeeper:
  securityContext:
    runAsUser: 0
    fsGroup: 0
    fsGroupChangePolicy: "OnRootMismatch"
  replicaCount: 3
  tolerations:
  - key: "dedicated"
    operator: "Equal"
    value: "pulsar"
    effect: "NoSchedule"
  volumes:
    journal:
      local_storage: true
      size: 50Gi
  ledgers:
      local_storage: true
      size: 50Gi

pulsar_manager:
  replicaCount: 1
  admin:
    user: pulsar_manager
    password: <my-password>
  configData:
    DRIVER_CLASS_NAME: org.postgresql.Driver
    URL: jdbc:postgresql://192.168.100.19:5432/pulsar_manager
    LOG_LEVEL: INFO
    JWT_TOKEN: pulsar-token-admin


autorecovery:
  replicaCount: 1
  nodeSelector:
    node-role.kubernetes.io/pulsar: pulsar
  tolerations:
  - key: "dedicated"
    operator: "Equal"
    value: "pulsar"
    effect: "NoSchedule"

toolset:
  replicaCount: 1
  nodeSelector:
    node-role.kubernetes.io/pulsar: pulsar
  tolerations:
  - key: "dedicated"
    operator: "Equal"
    value: "pulsar"
    effect: "NoSchedule

[lhotari]

And pulsar-all image is using 3.0.0

The pulsar-all 3.0.0 image is invalid. It's actually Pulsar 2.11, see #20420

The apache/pulsar-helm-chart project has some unreleased changes to some issues. Today I made a change to support k8s 1.24+.
apache/pulsar-helm-chart#368 (was part of apache/pulsar-helm-chart#370 changes).

Pulsar helm chart isn't compatible with k8s 1.24+ since there isn't a way to configure Zookeeper service with publishNotReadyAddresses: true.

• service.alpha.kubernetes.io/tolerate-unready-endpoints annotation was removed in k8s 1.24 with commit kubernetes/kubernetes@ae9f117

I'm not exactly sure if this is the issue in your case.

[oneforalone]

The pulsar-all 3.0.0 image is invalid. It's actually Pulsar 2.11
So, what exact version should I use. Is that 2.9.5 ok?

[lhotari]

For the slow fsync, make sure to deploy with a fast disk (SSD).

One example from the apache/pulsar-helm-chart is https://github.com/apache/pulsar-helm-chart/blob/f43c6f6d9e7a4d2f0186ab59b3af21797530e148/examples/values-zookeeper-aws.yaml#L58-L75

more examples in the default values.yaml:
https://github.com/apache/pulsar-helm-chart/blob/f43c6f6d9e7a4d2f0186ab59b3af21797530e148/charts/pulsar/values.yaml#L359-L369

[oneforalone]

Okay, appreciate for the suggestion. Does this slow fsync matters, would it effect the starting/deploying procedure or it would just slow down the message syncing?

[oneforalone]

@lhotari The problem remains the same, is that related with the slow fsync?