[ZOOKEEPER-4489] Refusing session request for client: zxid misalignment

• Type: Bug
• Status: Open
• Priority: Blocker
• Resolution: Unresolved
• Affects Version/s: 3.6.3
• Component/s: server

Environment

Environment is:

• OS is Ubuntu 21.10
• kafka_2.13-3.1.0, which includes zookeeper 3.6.3–6401e4ad2087061bc6b9f80dec2d69f2e3c8660a.
• Configuration is standalone

• Assignee: Unassigned
• Reporter: Antonio Antonucci
• Created: 06/Mar/22 14:14
• Updated: 05/Apr/22 03:34

Description

Hi everybody, I am having an issue zookeeper 3.6.3

Two things to highlight:

• 1) The issue I am having is:

INFO Refusing session request for client /192.168.1.163:42230 as it has seen zxid 0xa25 our last zxid is 0x23 client must try another server (org.apache.zookeeper.server.ZooKeeperServer)

>> Initially the zookeeper datadir was configured as per default under /tmp.

>> Following this error I have moved the datadir under /opt/zookeeper, deleted all the logs directory content and rebooted the server. 

>> Soon after the rebooting, the errror message was:

INFO Refusing session request for client /192.168.1.163:41738 as it has seen zxid 0xa25 our last zxid is 0x0 client must try another server (org.apache.zookeeper.server.ZooKeeperServer)

>> However once I started Kafka, the error went back to the original "... it has seen zxid 0xa25 our last zxid is 0x23.. "

>> I don't know how to sort this out

• 2) I have tried to run the ZkWorkarounderMultiThreaded java file (proposed in ZOOKEEPER-832), however I am getting the following errors:

(base) oo0v0oo@kafka-n1:~/zkworkaround/zk-work_around/src$  java -cp "/opt/kafka_2.13-3.1.0/libs/*" ZkWorkarounderMultiThreaded.java 192.168.1.160:2181 /kafka-n1 1 1

0 [pool-1-thread-1] INFO org.apache.zookeeper.ZooKeeper  - Client environment:zookeeper.version=3.6.3--6401e4ad2087061bc6b9f80dec2d69f2e3c8660a, built on 04/08/2021 16:35 GMT

1 [pool-1-thread-1] INFO org.apache.zookeeper.ZooKeeper  - Client environment:host.name=kafka-n1

1 [pool-1-thread-1] INFO org.apache.zookeeper.ZooKeeper  - Client environment:java.version=17.0.1

1 [pool-1-thread-1] INFO org.apache.zookeeper.ZooKeeper  - Client environment:java.vendor=Private Build

1 [pool-1-thread-1] INFO org.apache.zookeeper.ZooKeeper  - Client environment:java.home=/usr/lib/jvm/java-17-openjdk-amd64

1 [pool-1-thread-1] INFO org.apache.zookeeper.ZooKeeper  - Client environment:java.class.path=/opt/kafka_2.13-3.1.0/libs/connect-basic-auth-extension-3.1.0.jar:/opt/kafka_2.13-3.1.0/libs/kafka_2.13-3.1.0.jar:/opt/kafka_2.13-3.1.0/libs/jackson-core-2.12.3.jar:/opt/kafka_2.13-3.1.0/libs/kafka-streams-3.1.0.jar:/opt/kafka_2.13-3.1.0/libs/netty-transport-native-epoll-4.1.68.Final.jar:/opt/kafka_2.13-3.1.0/libs/hk2-utils-2.6.1.jar:/opt/kafka_2.13-3.1.0/libs/zookeeper-3.6.3.jar:/opt/kafka_2.13-3.1.0/libs/jetty-security-9.4.43.v20210629.jar:/opt/kafka_2.13-3.1.0/libs/jetty-util-ajax-9.4.43.v20210629.jar:/opt/kafka_2.13-3.1.0/libs/kafka-clients-3.1.0.jar:/opt/kafka_2.13-3.1.0/libs/jersey-container-servlet-2.34.jar:/opt/kafka_2.13-3.1.0/libs/activation-1.1.1.jar:/opt/kafka_2.13-3.1.0/libs/hk2-locator-2.6.1.jar:/opt/kafka_2.13-3.1.0/libs/kafka-metadata-3.1.0.jar:/opt/kafka_2.13-3.1.0/libs/netty-buffer-4.1.68.Final.jar:/opt/kafka_2.13-3.1.0/libs/jackson-module-scala_2.13-2.12.3.jar:/opt/kafka_2.13-3.1.0/libs/jetty-servlet-9.4.43.v20210629.jar:/opt/kafka_2.13-3.1.0/libs/maven-artifact-3.8.1.jar:/opt/kafka_2.13-3.1.0/libs/plexus-utils-3.2.1.jar:/opt/kafka_2.13-3.1.0/libs/zstd-jni-1.5.0-4.jar:/opt/kafka_2.13-3.1.0/libs/jersey-container-servlet-core-2.34.jar:/opt/kafka_2.13-3.1.0/libs/connect-api-3.1.0.jar:/opt/kafka_2.13-3.1.0/libs/jackson-jaxrs-base-2.12.3.jar:/opt/kafka_2.13-3.1.0/libs/kafka-storage-api-3.1.0.jar:/opt/kafka_2.13-3.1.0/libs/javax.servlet-api-3.1.0.jar:/opt/kafka_2.13-3.1.0/libs/zookeeper-jute-3.6.3.jar:/opt/kafka_2.13-3.1.0/libs/connect-json-3.1.0.jar:/opt/kafka_2.13-3.1.0/libs/jline-3.12.1.jar:/opt/kafka_2.13-3.1.0/libs/netty-handler-4.1.68.Final.jar:/opt/kafka_2.13-3.1.0/libs/kafka-raft-3.1.0.jar:/opt/kafka_2.13-3.1.0/libs/javassist-3.27.0-GA.jar:/opt/kafka_2.13-3.1.0/libs/jakarta.inject-2.6.1.jar:/opt/kafka_2.13-3.1.0/libs/metrics-core-4.1.12.1.jar:/opt/kafka_2.13-3.1.0/libs/kafka-streams-scala_2.13-3.1.0.jar:/opt/kafka_2.13-3.1.0/libs/jose4j-0.7.8.jar:/opt/kafka_2.13-3.1.0/libs/jersey-hk2-2.34.jar:/opt/kafka_2.13-3.1.0/libs/jaxb-api-2.3.0.jar:/opt/kafka_2.13-3.1.0/libs/connect-transforms-3.1.0.jar:/opt/kafka_2.13-3.1.0/libs/kafka-shell-3.1.0.jar:/opt/kafka_2.13-3.1.0/libs/snappy-java-1.1.8.4.jar:/opt/kafka_2.13-3.1.0/libs/netty-codec-4.1.68.Final.jar:/opt/kafka_2.13-3.1.0/libs/jackson-dataformat-csv-2.12.3.jar:/opt/kafka_2.13-3.1.0/libs/audience-annotations-0.5.0.jar:/opt/kafka_2.13-3.1.0/libs/kafka-log4j-appender-3.1.0.jar:/opt/kafka_2.13-3.1.0/libs/slf4j-log4j12-1.7.30.jar:/opt/kafka_2.13-3.1.0/libs/log4j-1.2.17.jar:/opt/kafka_2.13-3.1.0/libs/scala-reflect-2.13.6.jar:/opt/kafka_2.13-3.1.0/libs/scala-logging_2.13-3.9.3.jar:/opt/kafka_2.13-3.1.0/libs/paranamer-2.8.jar:/opt/kafka_2.13-3.1.0/libs/jakarta.xml.bind-api-2.3.2.jar:/opt/kafka_2.13-3.1.0/libs/rocksdbjni-6.22.1.1.jar:/opt/kafka_2.13-3.1.0/libs/lz4-java-1.8.0.jar:/opt/kafka_2.13-3.1.0/libs/argparse4j-0.7.0.jar:/opt/kafka_2.13-3.1.0/libs/jetty-util-9.4.43.v20210629.jar:/opt/kafka_2.13-3.1.0/libs/jakarta.activation-api-1.2.1.jar:/opt/kafka_2.13-3.1.0/libs/osgi-resource-locator-1.0.3.jar:/opt/kafka_2.13-3.1.0/libs/jetty-server-9.4.43.v20210629.jar:/opt/kafka_2.13-3.1.0/libs/aopalliance-repackaged-2.6.1.jar:/opt/kafka_2.13-3.1.0/libs/trogdor-3.1.0.jar:/opt/kafka_2.13-3.1.0/libs/netty-transport-native-unix-common-4.1.68.Final.jar:/opt/kafka_2.13-3.1.0/libs/kafka-streams-test-utils-3.1.0.jar:/opt/kafka_2.13-3.1.0/libs/jakarta.validation-api-2.0.2.jar:/opt/kafka_2.13-3.1.0/libs/jopt-simple-5.0.4.jar:/opt/kafka_2.13-3.1.0/libs/netty-transport-4.1.68.Final.jar:/opt/kafka_2.13-3.1.0/libs/jersey-common-2.34.jar:/opt/kafka_2.13-3.1.0/libs/jetty-http-9.4.43.v20210629.jar:/opt/kafka_2.13-3.1.0/libs/jakarta.annotation-api-1.3.5.jar:/opt/kafka_2.13-3.1.0/libs/slf4j-api-1.7.30.jar:/opt/kafka_2.13-3.1.0/libs/commons-lang3-3.8.1.jar:/opt/kafka_2.13-3.1.0/libs/jackson-annotations-2.12.3.jar:/opt/kafka_2.13-3.1.0/libs/netty-resolver-4.1.68.Final.jar:/opt/kafka_2.13-3.1.0/libs/jackson-databind-2.12.3.jar:/opt/kafka_2.13-3.1.0/libs/jersey-server-2.34.jar:/opt/kafka_2.13-3.1.0/libs/metrics-core-2.2.0.jar:/opt/kafka_2.13-3.1.0/libs/jackson-jaxrs-json-provider-2.12.3.jar:/opt/kafka_2.13-3.1.0/libs/netty-common-4.1.68.Final.jar:/opt/kafka_2.13-3.1.0/libs/kafka-server-common-3.1.0.jar:/opt/kafka_2.13-3.1.0/libs/reflections-0.9.12.jar:/opt/kafka_2.13-3.1.0/libs/kafka-streams-examples-3.1.0.jar:/opt/kafka_2.13-3.1.0/libs/jackson-datatype-jdk8-2.12.3.jar:/opt/kafka_2.13-3.1.0/libs/jakarta.ws.rs-api-2.1.6.jar:/opt/kafka_2.13-3.1.0/libs/jersey-client-2.34.jar:/opt/kafka_2.13-3.1.0/libs/kafka-tools-3.1.0.jar:/opt/kafka_2.13-3.1.0/libs/scala-java8-compat_2.13-1.0.0.jar:/opt/kafka_2.13-3.1.0/libs/hk2-api-2.6.1.jar:/opt/kafka_2.13-3.1.0/libs/scala-collection-compat_2.13-2.4.4.jar:/opt/kafka_2.13-3.1.0/libs/jackson-module-jaxb-annotations-2.12.3.jar:/opt/kafka_2.13-3.1.0/libs/scala-library-2.13.6.jar:/opt/kafka_2.13-3.1.0/libs/jetty-io-9.4.43.v20210629.jar:/opt/kafka_2.13-3.1.0/libs/jetty-client-9.4.43.v20210629.jar:/opt/kafka_2.13-3.1.0/libs/commons-cli-1.4.jar:/opt/kafka_2.13-3.1.0/libs/kafka-storage-3.1.0.jar:/opt/kafka_2.13-3.1.0/libs/javax.ws.rs-api-2.1.1.jar:/opt/kafka_2.13-3.1.0/libs/jetty-continuation-9.4.43.v20210629.jar:/opt/kafka_2.13-3.1.0/libs/connect-file-3.1.0.jar:/opt/kafka_2.13-3.1.0/libs/connect-runtime-3.1.0.jar:/opt/kafka_2.13-3.1.0/libs/jetty-servlets-9.4.43.v20210629.jar:/opt/kafka_2.13-3.1.0/libs/connect-mirror-client-3.1.0.jar:/opt/kafka_2.13-3.1.0/libs/connect-mirror-3.1.0.jar

1 [pool-1-thread-1] INFO org.apache.zookeeper.ZooKeeper  - Client environment:java.library.path=/usr/java/packages/lib:/usr/lib/x86_64-linux-gnu/jni:/lib/x86_64-linux-gnu:/usr/lib/x86_64-linux-gnu:/usr/lib/jni:/lib:/usr/lib

1 [pool-1-thread-1] INFO org.apache.zookeeper.ZooKeeper  - Client environment:java.io.tmpdir=/tmp

1 [pool-1-thread-1] INFO org.apache.zookeeper.ZooKeeper  - Client environment:java.compiler=<NA>

1 [pool-1-thread-1] INFO org.apache.zookeeper.ZooKeeper  - Client environment:os.name=Linux

1 [pool-1-thread-1] INFO org.apache.zookeeper.ZooKeeper  - Client environment:os.arch=amd64

1 [pool-1-thread-1] INFO org.apache.zookeeper.ZooKeeper  - Client environment:os.version=5.13.0-30-generic

1 [pool-1-thread-1] INFO org.apache.zookeeper.ZooKeeper  - Client environment:user.name=oo0v0oo

1 [pool-1-thread-1] INFO org.apache.zookeeper.ZooKeeper  - Client environment:user.home=/home/oo0v0oo

1 [pool-1-thread-1] INFO org.apache.zookeeper.ZooKeeper  - Client environment:user.dir=/home/oo0v0oo/zkworkaround/zk-work_around/src

1 [pool-1-thread-1] INFO org.apache.zookeeper.ZooKeeper  - Client environment:os.memory.free=40MB

1 [pool-1-thread-1] INFO org.apache.zookeeper.ZooKeeper  - Client environment:os.memory.max=982MB

1 [pool-1-thread-1] INFO org.apache.zookeeper.ZooKeeper  - Client environment:os.memory.total=64MB

6 [pool-1-thread-1] INFO org.apache.zookeeper.ZooKeeper  - Initiating client connection, connectString=192.168.1.160:2181 sessionTimeout=3000 watcher=ZkWorkarounderMultiThreaded$1@18d72986

9 [pool-1-thread-1] INFO org.apache.zookeeper.common.X509Util  - Setting -D jdk.tls.rejectClientInitiatedRenegotiation=true to disable client-initiated TLS renegotiation

17 [pool-1-thread-1] INFO org.apache.zookeeper.ClientCnxnSocket  - jute.maxbuffer value is 1048575 Bytes

23 [pool-1-thread-1] INFO org.apache.zookeeper.ClientCnxn  - zookeeper.request.timeout value is 0. feature enabled=false

57 [pool-1-thread-1-SendThread(192.168.1.160:2181)] DEBUG org.apache.zookeeper.SaslServerPrincipal  - Canonicalized address to kafka-n1.homenet.telecomitalia.it

59 [pool-1-thread-1-SendThread(192.168.1.160:2181)] INFO org.apache.zookeeper.ClientCnxn  - Opening socket connection to server kafka-n1.homenet.telecomitalia.it/192.168.1.160:2181.

59 [pool-1-thread-1-SendThread(192.168.1.160:2181)] INFO org.apache.zookeeper.ClientCnxn  - SASL config status: Will not attempt to authenticate using SASL (unknown error)

71 [pool-1-thread-1-SendThread(192.168.1.160:2181)] INFO org.apache.zookeeper.ClientCnxn  - Socket connection established, initiating session, client: /192.168.1.160:54046, server: kafka-n1.homenet.telecomitalia.it/192.168.1.160:2181

72 [pool-1-thread-1-SendThread(192.168.1.160:2181)] DEBUG org.apache.zookeeper.ClientCnxn  - Session establishment request sent on kafka-n1.homenet.telecomitalia.it/192.168.1.160:2181

75 [pool-1-thread-1-SendThread(192.168.1.160:2181)] INFO org.apache.zookeeper.ClientCnxn  - Session establishment complete on server kafka-n1.homenet.telecomitalia.it/192.168.1.160:2181, session id = 0x100009333020014, negotiated timeout = 6000

81 [pool-1-thread-1-SendThread(192.168.1.160:2181)] DEBUG org.apache.zookeeper.ClientCnxn  - Reading reply session id: 0x100009333020014, packet:: clientPath:null serverPath:null finished:false header:: 1,1  replyHeader:: 1,101,-110  request:: '/kafka-n1,,v{s{31,s

{'world,'anyone}}},0  response::  

105 [pool-1-thread-1-SendThread(192.168.1.160:2181)] DEBUG org.apache.zookeeper.ClientCnxn  - Reading reply session id: 0x100009333020014, packet:: clientPath:null serverPath:null finished:false header:: 2,1  replyHeader:: 2,102,0  request:: '/kafka-n1/ZkWorkarounderMultiThreaded@2b344318,,v{s{31,s{'world,'anyone}

}},0  response:: '/kafka-n1/ZkWorkarounderMultiThreaded@2b344318 

109 [pool-1-thread-1-SendThread(192.168.1.160:2181)] DEBUG org.apache.zookeeper.ClientCnxn  - Reading reply session id: 0x100009333020014, packet:: clientPath:null serverPath:null finished:false header:: 3,3  replyHeader:: 3,102,0  request:: '/kafka-n1/ZkWorkarounderMultiThreaded@2b344318,T  response:: s{102,102,1646588048633,1646588048633,0,0,0,0,0,0,102} 

111 [pool-1-thread-1-SendThread(192.168.1.160:2181)] DEBUG org.apache.zookeeper.ClientCnxn  - Got notification session id: 0x100009333020014

112 [pool-1-thread-1-SendThread(192.168.1.160:2181)] DEBUG org.apache.zookeeper.ClientCnxn  - Got WatchedEvent state:SyncConnected type:NodeDataChanged path:/kafka-n1/ZkWorkarounderMultiThreaded@2b344318 for session id 0x100009333020014

114 [pool-1-thread-1-SendThread(192.168.1.160:2181)] DEBUG org.apache.zookeeper.ClientCnxn  - Reading reply session id: 0x100009333020014, packet:: clientPath:null serverPath:null finished:false header:: 4,5  replyHeader:: 4,103,0  request:: '/kafka-n1/ZkWorkarounderMultiThreaded@2b344318,,0  response:: s{102,103,1646588048633,1646588048641,1,0,0,0,0,0,102} 

118 [pool-1-thread-1-SendThread(192.168.1.160:2181)] DEBUG org.apache.zookeeper.ClientCnxn  - Reading reply session id: 0x100009333020014, packet:: clientPath:null serverPath:null finished:false header:: 5,3  replyHeader:: 5,103,0  request:: '/kafka-n1/ZkWorkarounderMultiThreaded@2b344318,T  response:: s{102,103,1646588048633,1646588048641,1,0,0,0,0,0,102} 

120 [pool-1-thread-1-SendThread(192.168.1.160:2181)] DEBUG org.apache.zookeeper.ClientCnxn  - Got notification session id: 0x100009333020014

120 [pool-1-thread-1-SendThread(192.168.1.160:2181)] DEBUG org.apache.zookeeper.ClientCnxn  - Got WatchedEvent state:SyncConnected type:NodeDeleted path:/kafka-n1/ZkWorkarounderMultiThreaded@2b344318 for session id 0x100009333020014

121 [pool-1-thread-1-SendThread(192.168.1.160:2181)] DEBUG org.apache.zookeeper.ClientCnxn  - Reading reply session id: 0x100009333020014, packet:: clientPath:null serverPath:null finished:false header:: 6,2  replyHeader:: 6,104,0  request:: '/kafka-n1/ZkWorkarounderMultiThreaded@2b344318,1  response:: null

121 [pool-1-thread-1] DEBUG org.apache.zookeeper.ZooKeeper  - Closing session: 0x100009333020014

121 [pool-1-thread-1] DEBUG org.apache.zookeeper.ClientCnxn  - Closing client for session: 0x100009333020014

122 [pool-1-thread-1-SendThread(192.168.1.160:2181)] DEBUG org.apache.zookeeper.ClientCnxn  - Reading reply session id: 0x100009333020014, packet:: clientPath:null serverPath:null finished:false header:: 7,-11  replyHeader:: 7,105,0  request:: null response:: null

123 [pool-1-thread-1] DEBUG org.apache.zookeeper.ClientCnxn  - Disconnecting client for session: 0x100009333020014

123 [pool-1-thread-1-SendThread(192.168.1.160:2181)] WARN org.apache.zookeeper.ClientCnxn  - An exception was thrown while closing send thread for session 0x100009333020014.

EndOfStreamException: Unable to read additional data from server sessionid 0x100009333020014, likely server has closed socket

at org.apache.zookeeper.ClientCnxnSocketNIO.doIO(ClientCnxnSocketNIO.java:77)

at org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(ClientCnxnSocketNIO.java:350)

at org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:1290)

228 [pool-1-thread-1] INFO org.apache.zookeeper.ZooKeeper  - Session: 0x100009333020014 closed

228 [pool-1-thread-1-EventThread] INFO org.apache.zookeeper.ClientCnxn  - EventThread shut down for session: 0x100009333020014

>> I don't literally know how to sort this out.

>> Can somebody help me please?