ZK::Exceptions::ConnectionLoss error with Zookeeper 3.9

brendar commented 11 months ago

I'm seeing a ZK::Exceptions::ConnectionLoss error immediately after connecting when trying to use zk version 1.10.0 and zookeeper version 1.5.5 with Zookeeper 3.9.0. The issue does not occur with Zookeeper 3.8.

$ podman run --rm -d -p 21818:2181 --name zookeeper_3_8 zookeeper:3.8

$ podman run --rm -d -p 21819:2181 --name zookeeper_3_9 zookeeper:3.9

$ irb
irb(main):001> RUBY_VERSION
=> "3.2.2"
irb(main):002> require "zk"
=> true
irb(main):003> require "zk/version"
=> true
irb(main):004> ZK::VERSION
=> "1.10.0"
irb(main):005> require "zookeeper/version"
=> true
irb(main):006> Zookeeper::VERSION
=> "1.5.5"

irb(main):007> client_3_8 = ZK.new("localhost:21818")
=> #<ZK::Client::Threaded:79940 zk_session_id=0x100024968220000 ...>
irb(main):008> client_3_8.exists?("/foo")
=> false

irb(main):009> client_3_9 = ZK.new("localhost:21819")
=> #<ZK::Client::Threaded:107880 zk_session_id=0x10002497ef50000 ...>
irb(main):010> client_3_9.exists?("/foo")
/Users/brendan/.gem/ruby/3.2.2/gems/zk-1.10.0/lib/zk/client/base.rb:1083:in `check_rc': inputs: {:path=>"/foo", :ignore=>:no_node} (ZK::Exceptions::ConnectionLoss)
    from /Users/brendan/.gem/ruby/3.2.2/gems/zk-1.10.0/lib/zk/client/base.rb:1072:in `call_and_check_rc'
    from /Users/brendan/.gem/ruby/3.2.2/gems/zk-1.10.0/lib/zk/client/threaded.rb:584:in `call_and_check_rc'
    from /Users/brendan/.gem/ruby/3.2.2/gems/zk-1.10.0/lib/zk/client/base.rb:623:in `block in stat'
    from /Users/brendan/.gem/ruby/3.2.2/gems/zk-1.10.0/lib/zk/event_handler.rb:292:in `setup_watcher!'
    from /Users/brendan/.gem/ruby/3.2.2/gems/zk-1.10.0/lib/zk/client/base.rb:1115:in `setup_watcher!'
    from /Users/brendan/.gem/ruby/3.2.2/gems/zk-1.10.0/lib/zk/client/base.rb:622:in `stat'
    from /Users/brendan/.gem/ruby/3.2.2/gems/zk-1.10.0/lib/zk/client/base.rb:648:in `exists?'
    from (irb):10:in `<main>'
    from /Users/brendan/.gem/ruby/3.2.2/gems/irb-1.8.1/exe/irb:9:in `<top (required)>'
    from /Users/brendan/.gem/ruby/3.2.2/bin/irb:25:in `load'
    from /Users/brendan/.gem/ruby/3.2.2/bin/irb:25:in `<main>'

Zookeeper 3.9.0 logs: podman logs zookeeper_3_9

``` ZooKeeper JMX enabled by default Using config: /conf/zoo.cfg 2023-10-03 17:39:58,725 [myid:] - INFO [main:o.a.z.s.q.QuorumPeerConfig@177] - Reading configuration from: /conf/zoo.cfg 2023-10-03 17:39:58,728 [myid:] - INFO [main:o.a.z.s.q.QuorumPeerConfig@431] - clientPort is not set 2023-10-03 17:39:58,728 [myid:] - INFO [main:o.a.z.s.q.QuorumPeerConfig@444] - secureClientPort is not set 2023-10-03 17:39:58,728 [myid:] - INFO [main:o.a.z.s.q.QuorumPeerConfig@460] - observerMasterPort is not set 2023-10-03 17:39:58,728 [myid:] - INFO [main:o.a.z.s.q.QuorumPeerConfig@477] - metricsProvider.className is org.apache.zookeeper.metrics.impl.DefaultMetricsProvider 2023-10-03 17:39:58,732 [myid:] - ERROR [main:o.a.z.s.q.QuorumPeerConfig@702] - Invalid configuration, only one server specified (ignoring) 2023-10-03 17:39:58,732 [myid:1] - INFO [main:o.a.z.s.DatadirCleanupManager@78] - autopurge.snapRetainCount set to 3 2023-10-03 17:39:58,733 [myid:1] - INFO [main:o.a.z.s.DatadirCleanupManager@79] - autopurge.purgeInterval set to 0 2023-10-03 17:39:58,733 [myid:1] - INFO [main:o.a.z.s.DatadirCleanupManager@101] - Purge task is not scheduled. 2023-10-03 17:39:58,733 [myid:1] - WARN [main:o.a.z.s.q.QuorumPeerMain@139] - Either no config or no quorum defined in config, running in standalone mode 2023-10-03 17:39:58,734 [myid:1] - INFO [main:o.a.z.j.ManagedUtil@46] - Log4j 1.2 jmx support not found; jmx disabled. 2023-10-03 17:39:58,734 [myid:1] - INFO [main:o.a.z.s.q.QuorumPeerConfig@177] - Reading configuration from: /conf/zoo.cfg 2023-10-03 17:39:58,735 [myid:1] - INFO [main:o.a.z.s.q.QuorumPeerConfig@431] - clientPort is not set 2023-10-03 17:39:58,735 [myid:1] - INFO [main:o.a.z.s.q.QuorumPeerConfig@444] - secureClientPort is not set 2023-10-03 17:39:58,735 [myid:1] - INFO [main:o.a.z.s.q.QuorumPeerConfig@460] - observerMasterPort is not set 2023-10-03 17:39:58,735 [myid:1] - INFO [main:o.a.z.s.q.QuorumPeerConfig@477] - metricsProvider.className is org.apache.zookeeper.metrics.impl.DefaultMetricsProvider 2023-10-03 17:39:58,735 [myid:1] - ERROR [main:o.a.z.s.q.QuorumPeerConfig@702] - Invalid configuration, only one server specified (ignoring) 2023-10-03 17:39:58,736 [myid:1] - INFO [main:o.a.z.s.ZooKeeperServerMain@123] - Starting server 2023-10-03 17:39:58,741 [myid:1] - INFO [main:o.a.z.s.ServerMetrics@64] - ServerMetrics initialized with provider org.apache.zookeeper.metrics.impl.DefaultMetricsProvider@55141def 2023-10-03 17:39:58,742 [myid:1] - INFO [main:o.a.z.s.a.DigestAuthenticationProvider@51] - ACL digest algorithm is: SHA1 2023-10-03 17:39:58,743 [myid:1] - INFO [main:o.a.z.s.a.DigestAuthenticationProvider@65] - zookeeper.DigestAuthenticationProvider.enabled = true 2023-10-03 17:39:58,744 [myid:1] - INFO [main:o.a.z.s.p.FileTxnSnapLog@124] - zookeeper.snapshot.trust.empty : false 2023-10-03 17:39:58,749 [myid:1] - INFO [main:o.a.z.ZookeeperBanner@42] - 2023-10-03 17:39:58,749 [myid:1] - INFO [main:o.a.z.ZookeeperBanner@42] - ______ _ 2023-10-03 17:39:58,749 [myid:1] - INFO [main:o.a.z.ZookeeperBanner@42] - |___ / | | 2023-10-03 17:39:58,749 [myid:1] - INFO [main:o.a.z.ZookeeperBanner@42] - / / ___ ___ | | __ ___ ___ _ __ ___ _ __ 2023-10-03 17:39:58,749 [myid:1] - INFO [main:o.a.z.ZookeeperBanner@42] - / / / _ \ / _ \ | |/ / / _ \ / _ \ | '_ \ / _ \ | '__| 2023-10-03 17:39:58,749 [myid:1] - INFO [main:o.a.z.ZookeeperBanner@42] - / /__ | (_) | | (_) | | < | __/ | __/ | |_) | | __/ | | 2023-10-03 17:39:58,749 [myid:1] - INFO [main:o.a.z.ZookeeperBanner@42] - /_____| \___/ \___/ |_|\_\ \___| \___| | .__/ \___| |_| 2023-10-03 17:39:58,750 [myid:1] - INFO [main:o.a.z.ZookeeperBanner@42] - | | 2023-10-03 17:39:58,750 [myid:1] - INFO [main:o.a.z.ZookeeperBanner@42] - |_| 2023-10-03 17:39:58,751 [myid:1] - INFO [main:o.a.z.ZookeeperBanner@42] - 2023-10-03 17:39:58,751 [myid:1] - INFO [main:o.a.z.Environment@98] - Server environment:zookeeper.version=3.9.0-1674a5e97f43bc38e9bf56b04f83a7ae34d68249, built on 2023-07-19 09:09 UTC 2023-10-03 17:39:58,751 [myid:1] - INFO [main:o.a.z.Environment@98] - Server environment:host.name=e29393b32ac6 2023-10-03 17:39:58,751 [myid:1] - INFO [main:o.a.z.Environment@98] - Server environment:java.version=11.0.20.1 2023-10-03 17:39:58,752 [myid:1] - INFO [main:o.a.z.Environment@98] - Server environment:java.vendor=Eclipse Adoptium 2023-10-03 17:39:58,752 [myid:1] - INFO [main:o.a.z.Environment@98] - Server environment:java.home=/opt/java/openjdk 2023-10-03 17:39:58,752 [myid:1] - INFO [main:o.a.z.Environment@98] - Server environment:java.class.path=/apache-zookeeper-3.9.0-bin/bin/../zookeeper-metrics-providers/zookeeper-prometheus-metrics/target/classes:/apache-zookeeper-3.9.0-bin/bin/../zookeeper-server/target/classes:/apache-zookeeper-3.9.0-bin/bin/../build/classes:/apache-zookeeper-3.9.0-bin/bin/../zookeeper-metrics-providers/zookeeper-prometheus-metrics/target/lib/*.jar:/apache-zookeeper-3.9.0-bin/bin/../zookeeper-server/target/lib/*.jar:/apache-zookeeper-3.9.0-bin/bin/../build/lib/*.jar:/apache-zookeeper-3.9.0-bin/bin/../lib/zookeeper-prometheus-metrics-3.9.0.jar:/apache-zookeeper-3.9.0-bin/bin/../lib/zookeeper-jute-3.9.0.jar:/apache-zookeeper-3.9.0-bin/bin/../lib/zookeeper-3.9.0.jar:/apache-zookeeper-3.9.0-bin/bin/../lib/snappy-java-1.1.10.1.jar:/apache-zookeeper-3.9.0-bin/bin/../lib/slf4j-api-1.7.30.jar:/apache-zookeeper-3.9.0-bin/bin/../lib/simpleclient_servlet-0.9.0.jar:/apache-zookeeper-3.9.0-bin/bin/../lib/simpleclient_hotspot-0.9.0.jar:/apache-zookeeper-3.9.0-bin/bin/../lib/simpleclient_common-0.9.0.jar:/apache-zookeeper-3.9.0-bin/bin/../lib/simpleclient-0.9.0.jar:/apache-zookeeper-3.9.0-bin/bin/../lib/netty-transport-native-unix-common-4.1.94.Final.jar:/apache-zookeeper-3.9.0-bin/bin/../lib/netty-transport-native-epoll-4.1.94.Final-linux-x86_64.jar:/apache-zookeeper-3.9.0-bin/bin/../lib/netty-transport-classes-epoll-4.1.94.Final.jar:/apache-zookeeper-3.9.0-bin/bin/../lib/netty-transport-4.1.94.Final.jar:/apache-zookeeper-3.9.0-bin/bin/../lib/netty-tcnative-classes-2.0.61.Final.jar:/apache-zookeeper-3.9.0-bin/bin/../lib/netty-tcnative-boringssl-static-2.0.61.Final-windows-x86_64.jar:/apache-zookeeper-3.9.0-bin/bin/../lib/netty-tcnative-boringssl-static-2.0.61.Final-osx-x86_64.jar:/apache-zookeeper-3.9.0-bin/bin/../lib/netty-tcnative-boringssl-static-2.0.61.Final-osx-aarch_64.jar:/apache-zookeeper-3.9.0-bin/bin/../lib/netty-tcnative-boringssl-static-2.0.61.Final-linux-x86_64.jar:/apache-zookeeper-3.9.0-bin/bin/../lib/netty-tcnative-boringssl-static-2.0.61.Final-linux-aarch_64.jar:/apache-zookeeper-3.9.0-bin/bin/../lib/netty-tcnative-boringssl-static-2.0.61.Final.jar:/apache-zookeeper-3.9.0-bin/bin/../lib/netty-resolver-4.1.94.Final.jar:/apache-zookeeper-3.9.0-bin/bin/../lib/netty-handler-4.1.94.Final.jar:/apache-zookeeper-3.9.0-bin/bin/../lib/netty-common-4.1.94.Final.jar:/apache-zookeeper-3.9.0-bin/bin/../lib/netty-codec-4.1.94.Final.jar:/apache-zookeeper-3.9.0-bin/bin/../lib/netty-buffer-4.1.94.Final.jar:/apache-zookeeper-3.9.0-bin/bin/../lib/metrics-core-4.1.12.1.jar:/apache-zookeeper-3.9.0-bin/bin/../lib/logback-core-1.2.10.jar:/apache-zookeeper-3.9.0-bin/bin/../lib/logback-classic-1.2.10.jar:/apache-zookeeper-3.9.0-bin/bin/../lib/jline-2.14.6.jar:/apache-zookeeper-3.9.0-bin/bin/../lib/jetty-util-ajax-9.4.51.v20230217.jar:/apache-zookeeper-3.9.0-bin/bin/../lib/jetty-util-9.4.51.v20230217.jar:/apache-zookeeper-3.9.0-bin/bin/../lib/jetty-servlet-9.4.51.v20230217.jar:/apache-zookeeper-3.9.0-bin/bin/../lib/jetty-server-9.4.51.v20230217.jar:/apache-zookeeper-3.9.0-bin/bin/../lib/jetty-security-9.4.51.v20230217.jar:/apache-zookeeper-3.9.0-bin/bin/../lib/jetty-io-9.4.51.v20230217.jar:/apache-zookeeper-3.9.0-bin/bin/../lib/jetty-http-9.4.51.v20230217.jar:/apache-zookeeper-3.9.0-bin/bin/../lib/javax.servlet-api-3.1.0.jar:/apache-zookeeper-3.9.0-bin/bin/../lib/jackson-databind-2.15.2.jar:/apache-zookeeper-3.9.0-bin/bin/../lib/jackson-core-2.15.2.jar:/apache-zookeeper-3.9.0-bin/bin/../lib/jackson-annotations-2.15.2.jar:/apache-zookeeper-3.9.0-bin/bin/../lib/commons-io-2.11.0.jar:/apache-zookeeper-3.9.0-bin/bin/../lib/commons-cli-1.5.0.jar:/apache-zookeeper-3.9.0-bin/bin/../lib/audience-annotations-0.12.0.jar:/apache-zookeeper-3.9.0-bin/bin/../zookeeper-*.jar:/apache-zookeeper-3.9.0-bin/bin/../zookeeper-server/src/main/resources/lib/*.jar:/conf: 2023-10-03 17:39:58,752 [myid:1] - INFO [main:o.a.z.Environment@98] - Server environment:java.library.path=/usr/java/packages/lib:/lib:/usr/lib:/usr/lib64:/lib64 2023-10-03 17:39:58,752 [myid:1] - INFO [main:o.a.z.Environment@98] - Server environment:java.io.tmpdir=/tmp 2023-10-03 17:39:58,752 [myid:1] - INFO [main:o.a.z.Environment@98] - Server environment:java.compiler= 2023-10-03 17:39:58,752 [myid:1] - INFO [main:o.a.z.Environment@98] - Server environment:os.name=Linux 2023-10-03 17:39:58,752 [myid:1] - INFO [main:o.a.z.Environment@98] - Server environment:os.arch=aarch64 2023-10-03 17:39:58,752 [myid:1] - INFO [main:o.a.z.Environment@98] - Server environment:os.version=6.4.15-200.fc38.aarch64 2023-10-03 17:39:58,752 [myid:1] - INFO [main:o.a.z.Environment@98] - Server environment:user.name=zookeeper 2023-10-03 17:39:58,752 [myid:1] - INFO [main:o.a.z.Environment@98] - Server environment:user.home=/home/zookeeper 2023-10-03 17:39:58,752 [myid:1] - INFO [main:o.a.z.Environment@98] - Server environment:user.dir=/apache-zookeeper-3.9.0-bin 2023-10-03 17:39:58,752 [myid:1] - INFO [main:o.a.z.Environment@98] - Server environment:os.memory.free=117MB 2023-10-03 17:39:58,752 [myid:1] - INFO [main:o.a.z.Environment@98] - Server environment:os.memory.max=1000MB 2023-10-03 17:39:58,752 [myid:1] - INFO [main:o.a.z.Environment@98] - Server environment:os.memory.total=126MB 2023-10-03 17:39:58,752 [myid:1] - INFO [main:o.a.z.s.ZooKeeperServer@149] - zookeeper.enableEagerACLCheck = false 2023-10-03 17:39:58,753 [myid:1] - INFO [main:o.a.z.s.ZooKeeperServer@162] - zookeeper.digest.enabled = true 2023-10-03 17:39:58,753 [myid:1] - INFO [main:o.a.z.s.ZooKeeperServer@166] - zookeeper.closeSessionTxn.enabled = true 2023-10-03 17:39:58,753 [myid:1] - INFO [main:o.a.z.s.ZooKeeperServer@2251] - zookeeper.serializeLastProcessedZxid.enabled = true 2023-10-03 17:39:58,753 [myid:1] - INFO [main:o.a.z.s.ZooKeeperServer@1594] - zookeeper.flushDelay = 0 ms 2023-10-03 17:39:58,753 [myid:1] - INFO [main:o.a.z.s.ZooKeeperServer@1603] - zookeeper.maxWriteQueuePollTime = 0 ms 2023-10-03 17:39:58,753 [myid:1] - INFO [main:o.a.z.s.ZooKeeperServer@1612] - zookeeper.maxBatchSize=1000 2023-10-03 17:39:58,753 [myid:1] - INFO [main:o.a.z.s.ZooKeeperServer@287] - zookeeper.intBufferStartingSizeBytes = 1024 2023-10-03 17:39:58,753 [myid:1] - INFO [main:o.a.z.s.BlueThrottle@141] - Weighed connection throttling is disabled 2023-10-03 17:39:58,754 [myid:1] - INFO [main:o.a.z.s.AuthenticationHelper@66] - zookeeper.enforce.auth.enabled = false 2023-10-03 17:39:58,754 [myid:1] - INFO [main:o.a.z.s.AuthenticationHelper@67] - zookeeper.enforce.auth.schemes = [] 2023-10-03 17:39:58,754 [myid:1] - INFO [main:o.a.z.s.ZooKeeperServer@1406] - minSessionTimeout set to 4000 ms 2023-10-03 17:39:58,754 [myid:1] - INFO [main:o.a.z.s.ZooKeeperServer@1415] - maxSessionTimeout set to 40000 ms 2023-10-03 17:39:58,755 [myid:1] - INFO [main:o.a.z.s.ResponseCache@45] - getData response cache size is initialized with value 400. 2023-10-03 17:39:58,755 [myid:1] - INFO [main:o.a.z.s.ResponseCache@45] - getChildren response cache size is initialized with value 400. 2023-10-03 17:39:58,755 [myid:1] - INFO [main:o.a.z.s.u.RequestPathMetricsCollector@109] - zookeeper.pathStats.slotCapacity = 60 2023-10-03 17:39:58,755 [myid:1] - INFO [main:o.a.z.s.u.RequestPathMetricsCollector@110] - zookeeper.pathStats.slotDuration = 15 2023-10-03 17:39:58,755 [myid:1] - INFO [main:o.a.z.s.u.RequestPathMetricsCollector@111] - zookeeper.pathStats.maxDepth = 6 2023-10-03 17:39:58,755 [myid:1] - INFO [main:o.a.z.s.u.RequestPathMetricsCollector@112] - zookeeper.pathStats.initialDelay = 5 2023-10-03 17:39:58,755 [myid:1] - INFO [main:o.a.z.s.u.RequestPathMetricsCollector@113] - zookeeper.pathStats.delay = 5 2023-10-03 17:39:58,755 [myid:1] - INFO [main:o.a.z.s.u.RequestPathMetricsCollector@114] - zookeeper.pathStats.enabled = false 2023-10-03 17:39:58,756 [myid:1] - INFO [main:o.a.z.s.ZooKeeperServer@1631] - The max bytes for all large requests are set to 104857600 2023-10-03 17:39:58,757 [myid:1] - INFO [main:o.a.z.s.ZooKeeperServer@1645] - The large request threshold is set to -1 2023-10-03 17:39:58,757 [myid:1] - INFO [main:o.a.z.s.ZooKeeperServer@385] - Created server with tickTime 2000 ms minSessionTimeout 4000 ms maxSessionTimeout 40000 ms clientPortListenBacklog -1 datadir /datalog/version-2 snapdir /data/version-2 2023-10-03 17:39:58,774 [myid:1] - INFO [main:o.e.j.u.l.Log@170] - Logging initialized @321ms to org.eclipse.jetty.util.log.Slf4jLog 2023-10-03 17:39:58,809 [myid:1] - WARN [main:o.e.j.s.h.ContextHandler@1662] - o.e.j.s.ServletContextHandler@4c1909a3{/,null,STOPPED} contextPath ends with /* 2023-10-03 17:39:58,810 [myid:1] - WARN [main:o.e.j.s.h.ContextHandler@1673] - Empty contextPath 2023-10-03 17:39:58,822 [myid:1] - INFO [main:o.e.j.s.Server@375] - jetty-9.4.51.v20230217; built: 2023-02-17T08:19:37.309Z; git: b45c405e4544384de066f814ed42ae3dceacdd49; jvm 11.0.20.1+1 2023-10-03 17:39:58,840 [myid:1] - INFO [main:o.e.j.s.s.DefaultSessionIdManager@334] - DefaultSessionIdManager workerName=node0 2023-10-03 17:39:58,840 [myid:1] - INFO [main:o.e.j.s.s.DefaultSessionIdManager@339] - No SessionScavenger set, using defaults 2023-10-03 17:39:58,840 [myid:1] - INFO [main:o.e.j.s.s.HouseKeeper@132] - node0 Scavenging every 660000ms 2023-10-03 17:39:58,842 [myid:1] - WARN [main:o.e.j.s.ConstraintSecurityHandler@759] - ServletContext@o.e.j.s.ServletContextHandler@4c1909a3{/,null,STARTING} has uncovered http methods for path: /* 2023-10-03 17:39:58,848 [myid:1] - INFO [main:o.e.j.s.h.ContextHandler@921] - Started o.e.j.s.ServletContextHandler@4c1909a3{/,null,AVAILABLE} 2023-10-03 17:39:58,856 [myid:1] - INFO [main:o.e.j.s.AbstractConnector@333] - Started ServerConnector@24fcf36f{HTTP/1.1, (http/1.1)}{0.0.0.0:8080} 2023-10-03 17:39:58,857 [myid:1] - INFO [main:o.e.j.s.Server@415] - Started @405ms 2023-10-03 17:39:58,857 [myid:1] - INFO [main:o.a.z.s.a.JettyAdminServer@201] - Started AdminServer on address 0.0.0.0, port 8080 and command URL /commands 2023-10-03 17:39:58,859 [myid:1] - INFO [main:o.a.z.s.ServerCnxnFactory@169] - Using org.apache.zookeeper.server.NIOServerCnxnFactory as server connection factory 2023-10-03 17:39:58,859 [myid:1] - WARN [main:o.a.z.s.ServerCnxnFactory@309] - maxCnxns is not configured, using default value 0. 2023-10-03 17:39:58,860 [myid:1] - INFO [main:o.a.z.s.NIOServerCnxnFactory@652] - Configuring NIO connection handler with 10s sessionless connection timeout, 1 selector thread(s), 8 worker threads, and 64 kB direct buffers. 2023-10-03 17:39:58,861 [myid:1] - INFO [main:o.a.z.s.NIOServerCnxnFactory@660] - binding to port /0.0.0.0:2181 2023-10-03 17:39:58,868 [myid:1] - INFO [main:o.a.z.s.w.WatchManagerFactory@42] - Using org.apache.zookeeper.server.watch.WatchManager as watch manager 2023-10-03 17:39:58,868 [myid:1] - INFO [main:o.a.z.s.w.WatchManagerFactory@42] - Using org.apache.zookeeper.server.watch.WatchManager as watch manager 2023-10-03 17:39:58,869 [myid:1] - INFO [main:o.a.z.s.ZKDatabase@135] - zookeeper.snapshotSizeFactor = 0.33 2023-10-03 17:39:58,869 [myid:1] - INFO [main:o.a.z.s.ZKDatabase@155] - zookeeper.commitLogCount=500 2023-10-03 17:39:58,871 [myid:1] - INFO [main:o.a.z.s.p.SnapStream@61] - zookeeper.snapshot.compression.method = CHECKED 2023-10-03 17:39:58,871 [myid:1] - INFO [main:o.a.z.s.p.FileTxnSnapLog@480] - Snapshotting: 0x0 to /data/version-2/snapshot.0 2023-10-03 17:39:58,873 [myid:1] - INFO [main:o.a.z.s.ZKDatabase@292] - Snapshot loaded in 4 ms, highest zxid is 0x0, digest is 1371985504 2023-10-03 17:39:58,873 [myid:1] - INFO [main:o.a.z.s.p.FileTxnSnapLog@480] - Snapshotting: 0x0 to /data/version-2/snapshot.0 2023-10-03 17:39:58,874 [myid:1] - INFO [main:o.a.z.s.ZooKeeperServer@589] - Snapshot taken in 1 ms 2023-10-03 17:39:58,879 [myid:] - INFO [ProcessThread(sid:0 cport:2181)::o.a.z.s.PrepRequestProcessor@138] - PrepRequestProcessor (sid:0) started, reconfigEnabled=false 2023-10-03 17:39:58,880 [myid:1] - INFO [main:o.a.z.s.RequestThrottler@75] - zookeeper.request_throttler.shutdownTimeout = 10000 ms 2023-10-03 17:39:58,889 [myid:1] - INFO [main:o.a.z.s.ContainerManager@83] - Using checkIntervalMs=60000 maxPerMinute=10000 maxNeverUsedIntervalMs=0 2023-10-03 17:39:58,890 [myid:1] - INFO [main:o.a.z.a.ZKAuditProvider@42] - ZooKeeper audit is disabled. 2023-10-03 17:40:42,509 [myid:] - WARN [NIOWorkerThread-1:o.a.z.s.ZooKeeperServer@1505] - Connection request from old client /192.168.127.1:30539; will be dropped if server is in r-o mode 2023-10-03 17:40:42,514 [myid:] - INFO [SyncThread:0:o.a.z.s.p.FileTxnLog@284] - Creating new log file: log.1 2023-10-03 17:40:46,853 [myid:] - INFO [NIOWorkerThread-5:o.a.z.s.NIOServerCnxn@339] - Unable to read additional data from client, it probably closed the socket: address = /192.168.127.1:30539, session = 0x10002497ef50000 2023-10-03 17:40:46,859 [myid:] - WARN [NIOWorkerThread-6:o.a.z.s.ZooKeeperServer@1505] - Connection request from old client /192.168.127.1:30540; will be dropped if server is in r-o mode 2023-10-03 17:40:53,543 [myid:] - INFO [NIOWorkerThread-2:o.a.z.s.NIOServerCnxn@339] - Unable to read additional data from client, it probably closed the socket: address = /192.168.127.1:30540, session = 0x10002497ef50000 2023-10-03 17:41:00,219 [myid:] - WARN [NIOWorkerThread-3:o.a.z.s.ZooKeeperServer@1505] - Connection request from old client /192.168.127.1:30541; will be dropped if server is in r-o mode 2023-10-03 17:41:06,894 [myid:] - INFO [NIOWorkerThread-7:o.a.z.s.NIOServerCnxn@339] - Unable to read additional data from client, it probably closed the socket: address = /192.168.127.1:30541, session = 0x10002497ef50000 2023-10-03 17:41:06,901 [myid:] - WARN [NIOWorkerThread-8:o.a.z.s.ZooKeeperServer@1505] - Connection request from old client /192.168.127.1:30543; will be dropped if server is in r-o mode 2023-10-03 17:41:07,530 [myid:] - INFO [NIOWorkerThread-3:o.a.z.s.NIOServerCnxn@339] - Unable to read additional data from client, it probably closed the socket: address = /192.168.127.1:30543, session = 0x10002497ef50000 ```

The above commands were executed on a mac, but I'm seeing the same issue on a linux CI host.

Is it possible this is a C client compatibility issue? zookeeper appears to be using a 3.4.x client, but the release announcement for 3.9.0 says

ZooKeeper clients from 3.5.x onwards are fully compatible with 3.9.x servers.

brandonvin commented 10 months ago

Seeing similar issues using zookeeper gem version 1.5.5, and ZooKeeper cluster version 3.9.1. Was able to work around this by rolling back the ZooKeeper cluster to 3.8.3.

Operations on paths return a result indicating the node doesn't exist, though the node does exist in ZooKeeper with children
Some operations time out after 30 seconds

$ echo srvr | nc zookeeper 2181
Zookeeper version: 3.9.1-1398af177833412e9ead6b9bb737dc9fd7418a45, built on 2023-10-04 09:54 UTC

In an irb session:

irb(main):001:0> require 'zookeeper'
=> true

irb(main):002:0> zk = Zookeeper.new("zookeeper:2181")
=>
#<Zookeeper::Client:0x0000560db4237018
...

irb(main):003:0> zk.stat(:path => "/")
=> {:req_id=>0, :rc=>-4, :stat=>#<Zookeeper::Stat:0x0000560db479fe60 @exists=false>}

irb(main):004:0> zk.get_children(:path => "/")
=> {:req_id=>1, :rc=>-2, :children=>nil, :stat=>#<Zookeeper::Stat:0x0000560db474b630 @exists=false>}

irb(main):005:0> zk.get_children(:path => "/")
/var/lib/gems/3.0.0/gems/zookeeper-1.5.5/lib/zookeeper/continuation.rb:117:in `block in value': response for meth: :get_children, args: [2, "/", nil, nil], not received within 30 seconds (Zookeeper::Exceptions::ContinuationTimeoutError)
        from /usr/lib/ruby/3.0.0/monitor.rb:202:in `synchronize'
        from /usr/lib/ruby/3.0.0/monitor.rb:202:in `mon_synchronize'
        from /var/lib/gems/3.0.0/gems/zookeeper-1.5.5/lib/zookeeper/continuation.rb:107:in `value'
        from /var/lib/gems/3.0.0/gems/zookeeper-1.5.5/ext/c_zookeeper.rb:233:in `submit_and_block'
        from /var/lib/gems/3.0.0/gems/zookeeper-1.5.5/ext/c_zookeeper.rb:42:in `get_children'
        from /usr/lib/ruby/3.0.0/forwardable.rb:238:in `get_children'
        from /var/lib/gems/3.0.0/gems/zookeeper-1.5.5/lib/zookeeper/client_methods.rb:69:in `get_children'
        from (irb):5:in `<main>'
        from /usr/lib/ruby/gems/3.0.0/gems/irb-1.3.5/exe/irb:11:in `<top (required)>'
        from /usr/bin/irb:23:in `load'
        from /usr/bin/irb:23:in `<main>'

agelwarg commented 5 days ago

Does anyone know if this project dead? Doesn't seem to be any movement on this or any other issues.

zk-ruby / zookeeper

ZK::Exceptions::ConnectionLoss error with Zookeeper 3.9 #124