ZK首次连接失败，第二次连接成功的问题排查和解决

ZK首次连接失败问题

问题

项目中配置zk后，启动时zk第一次链接总是失败，过一会后又会链接成功。异常如下：

17:04:22.932 [Curator-Framework-0] WARN  o.a.c.r.ExponentialBackoffRetry - [getSleepTimeMs,74] - Sleep extension too large (1100). Pinning to 500
17:04:23.433 [Curator-Framework-0] WARN  o.a.c.r.ExponentialBackoffRetry - [getSleepTimeMs,74] - Sleep extension too large (1350). Pinning to 500
17:04:23.935 [Curator-Framework-0] WARN  o.a.c.r.ExponentialBackoffRetry - [getSleepTimeMs,74] - Sleep extension too large (3300). Pinning to 500
17:04:24.438 [Curator-Framework-0] WARN  o.a.c.r.ExponentialBackoffRetry - [getSleepTimeMs,74] - Sleep extension too large (3750). Pinning to 500
17:04:24.939 [Curator-Framework-0] WARN  o.a.c.r.ExponentialBackoffRetry - [getSleepTimeMs,74] - Sleep extension too large (24450). Pinning to 500
17:04:25.440 [Curator-Framework-0] WARN  o.a.c.r.ExponentialBackoffRetry - [getSleepTimeMs,74] - Sleep extension too large (50350). Pinning to 500
17:04:25.943 [Curator-Framework-0] INFO  o.a.c.f.s.ConnectionStateManager - [postState,250] - State change: SUSPENDED
17:04:25.945 [Curator-Framework-0] ERROR o.a.c.f.i.CuratorFrameworkImpl - [logError,690] - Background operation retry gave up
org.apache.zookeeper.KeeperException$ConnectionLossException: KeeperErrorCode = ConnectionLoss
    at org.apache.zookeeper.KeeperException.create(KeeperException.java:102)
    at org.apache.curator.framework.imps.CuratorFrameworkImpl.checkBackgroundRetry(CuratorFrameworkImpl.java:851)
    at org.apache.curator.framework.imps.CuratorFrameworkImpl.performBackgroundOperation(CuratorFrameworkImpl.java:999)
    at org.apache.curator.framework.imps.CuratorFrameworkImpl.backgroundOperationsLoop(CuratorFrameworkImpl.java:952)
    at org.apache.curator.framework.imps.CuratorFrameworkImpl.access$300(CuratorFrameworkImpl.java:66)
    at org.apache.curator.framework.imps.CuratorFrameworkImpl$4.call(CuratorFrameworkImpl.java:342)
    at java.util.concurrent.FutureTask.run$$$capture(FutureTask.java:266)
    at java.util.concurrent.FutureTask.run(FutureTask.java)
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
    at java.lang.Thread.run(Thread.java:745)
17:04:25.946 [Curator-Framework-0] ERROR o.a.c.f.i.CuratorFrameworkImpl - [logError,690] - Background retry gave up

项目版本

<springboot.version>2.5.14</springboot.version><spring.cloud.version>2020.0.6</spring.cloud.version><org.apache.curator.version>5.1.0</org.apache.curator.version><zookeeper.version>3.6.0</zookeeper.version><dependency><groupId>org.apache.zookeeper</groupId><artifactId>zookeeper</artifactId><version>${zookeeper.version}</version></dependency><dependency><groupId>org.springframework.cloud</groupId><artifactId>spring-cloud-dependencies</artifactId><version>${spring.cloud.version}</version></dependency>

异常原因分析

zk默认的connectionTimeout是15s（可以配置，这里用默认的），zk在这个时间之内没有连接成功，就会报出这个异常。经排查，链接超时，代码卡在解析ip的地方，1134行。

SaslServerPrincipal.getServerPrincipal(addr, clientConfig) 在进行解析配置的zk地址时，使用Sasl来进行解析。继续追查发现，使用 Inet6AddressImpl来解析，具体实现方法，是一个Native方法。

这里就比较奇怪了，项目只是配置了一个ip地址，却要默认进行 Inet6 来进行解析。主要原因，是 1129 行的 clientConfig.isSaslClientEnabled()，在 ZKClientConfig 中，这个参数默认为true。为啥默认是true，请看 https://issues.apache.org/jira/browse/ZOOKEEPER-1657。

并且 spring cloud 在自动配置 zk CuratorFramework 的时候，使用了默认的 DefaultZookeeperFactory 构造器。

这里并没有传入 ZKClientConfig，因此，Zookeeper 将会使用默认的ZKClientConfig 来进行配置。默认的如下所示：

解决办法

关闭 saslClientEnabled 即可。

1. 添加 -Dzookeeper.sasl.client=false

java -jar -Dzookeeper.sasl.client=false xxx.jar

1. 让spring cloud 在自动配置 zk CuratorFramework 的时候，不要使用默认的 DefaultZookeeperFactory。 zk 自动配置源码如下： 源码中画红框处，可以使用自定义的CuratorFramework 提供者。因此我们对项目进行改造，实现 CuratorFrameworkCustomizer 接口，使用自定义的 DefaultZookeeperFactory ，并且配置 ENABLE_CLIENT_SASL_KEY 为 false 即可。

@ConfigurationpublicclassZookeeperConfigurerimplementsCuratorFrameworkCustomizer{@Overridepublicvoidcustomize(CuratorFrameworkFactory.Builder builder){
        builder.zookeeperFactory(newDefaultZookeeperFactory());}publicclassDefaultZookeeperFactoryimplementsZookeeperFactory{publicDefaultZookeeperFactory(){}@OverridepublicZooKeepernewZooKeeper(String connectString,int sessionTimeout,Watcher watcher,boolean canBeReadOnly)throwsException{ZKClientConfig zkClientConfig =newZKClientConfig();
            zkClientConfig.setProperty(ZKClientConfig.ENABLE_CLIENT_SASL_KEY,"false");returnnewZooKeeper(connectString, sessionTimeout, watcher, canBeReadOnly, zkClientConfig);}}}

重启项目，发现zk首次链接失败的问题，已经解决。