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

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

@Configuration
public class ZookeeperConfigurer implements CuratorFrameworkCustomizer {
    @Override
    public void customize(CuratorFrameworkFactory.Builder builder) {
        builder.zookeeperFactory(new DefaultZookeeperFactory());
    }

    public class DefaultZookeeperFactory implements ZookeeperFactory {
        public DefaultZookeeperFactory() {
        }

        @Override
        public ZooKeeper newZooKeeper(String connectString, int sessionTimeout, Watcher watcher, boolean canBeReadOnly) throws Exception {
            ZKClientConfig zkClientConfig = new ZKClientConfig();
            zkClientConfig.setProperty(ZKClientConfig.ENABLE_CLIENT_SASL_KEY, "false");
            return new ZooKeeper(connectString, sessionTimeout, watcher, canBeReadOnly, zkClientConfig);
        }
    }
}

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