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

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

ZK首次连接失败问题

• 问题
• 项目版本
• 异常原因分析
• 解决办法

问题

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

17:04:22.932 [Curator-Framework-0] WARN  ExponentialBackoffRetry - [getSleepTimeMs,74] - Sleep extension too large (1100). Pinning to 500
17:04:23.433 [Curator-Framework-0] WARN  ExponentialBackoffRetry - [getSleepTimeMs,74] - Sleep extension too large (1350). Pinning to 500
17:04:23.935 [Curator-Framework-0] WARN  ExponentialBackoffRetry - [getSleepTimeMs,74] - Sleep extension too large (3300). Pinning to 500
17:04:24.438 [Curator-Framework-0] WARN  ExponentialBackoffRetry - [getSleepTimeMs,74] - Sleep extension too large (3750). Pinning to 500
17:04:24.939 [Curator-Framework-0] WARN  ExponentialBackoffRetry - [getSleepTimeMs,74] - Sleep extension too large (24450). Pinning to 500
17:04:25.440 [Curator-Framework-0] WARN  ExponentialBackoffRetry - [getSleepTimeMs,74] - Sleep extension too large (50350). Pinning to 500
17:04:25.943 [Curator-Framework-0] INFO  f.s.ConnectionStateManager - [postState,250] - State change: SUSPENDED
17:04:25.945 [Curator-Framework-0] ERROR f.i.CuratorFrameworkImpl - [logError,690] - Background operation retry gave up
keeper.KeeperException$ConnectionLossException: KeeperErrorCode = ConnectionLossat ate(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 urrent.FutureTask.run$$$capture(FutureTask.java:266)at urrent.FutureTask.run(FutureTask.java)at urrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)at urrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)at urrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)at urrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)at java.lang.Thread.run(Thread.java:745)
17:04:25.946 [Curator-Framework-0] ERROR 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>keeper</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行。

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

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

并且 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 {@Overridepublic void customize(CuratorFrameworkFactory.Builder builder) {keeperFactory(new DefaultZookeeperFactory());}public class DefaultZookeeperFactory implements ZookeeperFactory {public DefaultZookeeperFactory() {}@Overridepublic 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首次链接失败的问题，已经解决。