Unexpected exception causing shutdown while sock still open

[#1]

Hi, all

CDH version: 5.13.1

Zookeeper log:

2018-11-28 10:07:13,902 ERROR org.apache.zookeeper.server.quorum.LearnerHandler: Unexpected exception causing shutdown while sock still open
java.net.SocketTimeoutException: Read timed out
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
at java.net.SocketInputStream.read(SocketInputStream.java:170)
at java.net.SocketInputStream.read(SocketInputStream.java:141)
at java.io.BufferedInputStream.fill(BufferedInputStream.java:246)
at java.io.BufferedInputStream.read(BufferedInputStream.java:265)
at java.io.DataInputStream.readInt(DataInputStream.java:387)
at org.apache.jute.BinaryInputArchive.readInt(BinaryInputArchive.java:63)
at org.apache.zookeeper.server.quorum.QuorumPacket.deserialize(QuorumPacket.java:83)
at org.apache.jute.BinaryInputArchive.readRecord(BinaryInputArchive.java:99)
at org.apache.zookeeper.server.quorum.LearnerHandler.run(LearnerHandler.java:499)
2018-11-28 10:07:13,902 ERROR org.apache.zookeeper.server.quorum.LearnerHandler: Unexpected exception causing shutdown while sock still open
java.net.SocketTimeoutException: Read timed out
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
at java.net.SocketInputStream.read(SocketInputStream.java:170)
at java.net.SocketInputStream.read(SocketInputStream.java:141)
at java.io.BufferedInputStream.fill(BufferedInputStream.java:246)
at java.io.BufferedInputStream.read(BufferedInputStream.java:265)
at java.io.DataInputStream.readInt(DataInputStream.java:387)
at org.apache.jute.BinaryInputArchive.readInt(BinaryInputArchive.java:63)
at org.apache.zookeeper.server.quorum.QuorumPacket.deserialize(QuorumPacket.java:83)
at org.apache.jute.BinaryInputArchive.readRecord(BinaryInputArchive.java:99)
at org.apache.zookeeper.server.quorum.LearnerHandler.run(LearnerHandler.java:499)
2018-11-28 10:07:13,986 INFO org.apache.zookeeper.server.quorum.FastLeaderElection: Notification: 4 (n.leader), 0x1001dd3b2 (n.zxid), 0x2 (n.round), LOOKING (n.state), 4 (n.sid), 0x1 (n.peerEPoch), LEADING (my state)
2018-11-28 10:07:13,908 ERROR org.apache.zookeeper.server.quorum.LearnerHandler: Unexpected exception causing shutdown while sock still open
java.net.SocketTimeoutException: Read timed out
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
at java.net.SocketInputStream.read(SocketInputStream.java:170)
at java.net.SocketInputStream.read(SocketInputStream.java:141)
at java.io.BufferedInputStream.fill(BufferedInputStream.java:246)
at java.io.BufferedInputStream.read(BufferedInputStream.java:265)
at java.io.DataInputStream.readInt(DataInputStream.java:387)
at org.apache.jute.BinaryInputArchive.readInt(BinaryInputArchive.java:63)
at org.apache.zookeeper.server.quorum.QuorumPacket.deserialize(QuorumPacket.java:83)
at org.apache.jute.BinaryInputArchive.readRecord(BinaryInputArchive.java:99)
at org.apache.zookeeper.server.quorum.LearnerHandler.run(LearnerHandler.java:499)
2018-11-28 10:07:13,904 WARN org.apache.zookeeper.server.quorum.LearnerHandler: ******* GOODBYE /10.8.100.81:57794 ********
2018-11-28 10:07:13,989 WARN org.apache.zookeeper.server.quorum.LearnerHandler: ******* GOODBYE /10.8.100.80:40504 ********
2018-11-28 10:07:13,989 WARN org.apache.zookeeper.server.quorum.LearnerHandler: ******* GOODBYE /10.8.100.79:44374 ********

Kafka log:

2018-11-28 10:07:13,920 INFO org.apache.zookeeper.ClientCnxn: Unable to read additional data from server sessionid 0x36666f33c21940c, likely server has closed socket, closing socket connection and attempting reconnect
2018-11-28 10:07:14,021 INFO org.I0Itec.zkclient.ZkClient: zookeeper state changed (Disconnected)
2018-11-28 10:07:14,874 INFO org.apache.zookeeper.ClientCnxn: Opening socket connection to server ylxny-uat-cdh2/10.8.100.77:2181. Will not attempt to authenticate using SASL (unknown error)
2018-11-28 10:07:14,875 INFO org.apache.zookeeper.ClientCnxn: Socket connection established, initiating session, client: /10.8.100.82:48766, server: ylxny-uat-cdh2/10.8.100.77:2181
2018-11-28 10:07:14,877 INFO org.I0Itec.zkclient.ZkClient: zookeeper state changed (Expired)
2018-11-28 10:07:14,877 INFO org.apache.zookeeper.ClientCnxn: Unable to reconnect to ZooKeeper service, session 0x36666f33c21940c has expired, closing socket connection
2018-11-28 10:07:14,877 INFO org.apache.zookeeper.ZooKeeper: Initiating client connection, connectString=ylxny-uat-cdh2:2181,ylxny-uat-cdh3:2181,ylxny-uat-cdh4:2181,ylxny-uat-cdh5:2181,ylxny-uat-cdh6:2181 sessionTimeout=6000 watcher=org.I0Itec.zkclient.ZkClient@40bffbca
2018-11-28 10:07:14,878 INFO org.apache.zookeeper.ClientCnxn: EventThread shut down
2018-11-28 10:07:14,881 INFO org.apache.zookeeper.ClientCnxn: Opening socket connection to server ylxny-uat-cdh5/10.8.100.80:2181. Will not attempt to authenticate using SASL (unknown error)
2018-11-28 10:07:14,883 INFO org.apache.zookeeper.ClientCnxn: Socket connection established, initiating session, client: /10.8.100.82:49360, server: ylxny-uat-cdh5/10.8.100.80:2181
2018-11-28 10:07:14,890 INFO org.apache.zookeeper.ClientCnxn: Session establishment complete on server ylxny-uat-cdh5/10.8.100.80:2181, sessionid = 0x467581202b00000, negotiated timeout = 6000
2018-11-28 10:07:14,890 INFO org.I0Itec.zkclient.ZkClient: zookeeper state changed (SyncConnected)
2018-11-28 10:07:14,890 INFO kafka.server.KafkaHealthcheck$SessionExpireListener: re-registering broker info in ZK for broker 62
2018-11-28 10:07:14,891 INFO kafka.utils.ZKCheckedEphemeral: Creating /brokers/ids/62 (is it secure? false)
2018-11-28 10:07:14,899 INFO kafka.utils.ZKCheckedEphemeral: Result of znode creation is: NODEEXISTS
2018-11-28 10:07:14,900 ERROR org.I0Itec.zkclient.ZkEventThread: Error handling event ZkEvent[New session event sent to kafka.server.KafkaHealthcheck$SessionExpireListener@3aa1c4cf]
java.lang.RuntimeException: A broker is already registered on the path /brokers/ids/62. This probably indicates that you either have configured a brokerid that is already in use, or else you have shutdown this broker and restarted it faster than the zookeeper timeout so it appears to be re-registering.
at kafka.utils.ZkUtils.registerBrokerInZk(ZkUtils.scala:440)
at kafka.utils.ZkUtils.registerBrokerInZk(ZkUtils.scala:426)
at kafka.server.KafkaHealthcheck.register(KafkaHealthcheck.scala:73)
at kafka.server.KafkaHealthcheck$SessionExpireListener.handleNewSession(KafkaHealthcheck.scala:121)
at org.I0Itec.zkclient.ZkClient$6.run(ZkClient.java:736)
at org.I0Itec.zkclient.ZkEventThread.run(ZkEventThread.java:72)
2018-11-28 10:07:23,871 INFO kafka.server.epoch.LeaderEpochFileCache: Updated PartitionLeaderEpoch. New: {epoch:33, offset:12058461}, Current: {epoch:32, offset11675224} for Partition: __consumer_offsets-23. Cache now contains 27 entries.

[#2]

Hi Victor,

"A broker is already registered on the path /brokers/ids/62"

ID uniquely identifying each broker, In your case while the broker is starting up id has already taken by different broker, which was taken care by zookeeper.

This issue can happen when the broker connected to a zk which is not yet part of zk ensemble yet or kafka broker might be killed or crashed which didn’t remove the znode properly.

To resolve
1. Try to clean up the broker ids in the zookeeper path /brokers/ids/[]. Use zookeeper-client tool to remove ids.
Once done start your broker.

Hope it helps. Let us know if any questions.

Thanks
Jerry

[#3]

Hi Jerry,

Thank you for your reply.

But when the zookeeper thorws "Unexpected exception causing shutdown while sock still open" (Maybe because of the Internet),  kafka shoud reconnect zookeeper, kafka log :

2018-11-28 10:07:13,920 INFO org.apache.zookeeper.ClientCnxn: Unable to read additional data from server sessionid 0x36666f33c21940c, likely server has closed socket, closing socket connection and attempting reconnect
2018-11-28 10:07:14,021 INFO org.I0Itec.zkclient.ZkClient: zookeeper state changed (Disconnected)
2018-11-28 10:07:14,874 INFO org.apache.zookeeper.ClientCnxn: Opening socket connection to server ylxny-uat-cdh2/10.8.100.77:2181. Will not attempt to authenticate using SASL (unknown error)
2018-11-28 10:07:14,875 INFO org.apache.zookeeper.ClientCnxn: Socket connection established, initiating session, client: /10.8.100.82:48766, server: ylxny-uat-cdh2/10.8.100.77:2181
2018-11-28 10:07:14,877 INFO org.I0Itec.zkclient.ZkClient: zookeeper state changed (Expired)
2018-11-28 10:07:14,877 INFO org.apache.zookeeper.ClientCnxn: Unable to reconnect to ZooKeeper service, session 0x36666f33c21940c has expired, closing socket connection
2018-11-28 10:07:14,877 INFO org.apache.zookeeper.ZooKeeper: Initiating client connection, connectString=ylxny-uat-cdh2:2181,ylxny-uat-cdh3:2181,ylxny-uat-cdh4:2181,ylxny-uat-cdh5:2181,ylxny-uat-cdh6:2181 sessionTimeout=6000 watcher=org.I0Itec.zkclient.ZkClient@40bffbca
2018-11-28 10:07:14,878 INFO org.apache.zookeeper.ClientCnxn: EventThread shut down
2018-11-28 10:07:14,881 INFO org.apache.zookeeper.ClientCnxn: Opening socket connection to server ylxny-uat-cdh5/10.8.100.80:2181. Will not attempt to authenticate using SASL (unknown error)
2018-11-28 10:07:14,883 INFO org.apache.zookeeper.ClientCnxn: Socket connection established, initiating session, client: /10.8.100.82:49360, server: ylxny-uat-cdh5/10.8.100.80:2181
2018-11-28 10:07:14,890 INFO org.apache.zookeeper.ClientCnxn: Session establishment complete on server ylxny-uat-cdh5/10.8.100.80:2181, sessionid = 0x467581202b00000, negotiated timeout = 6000
2018-11-28 10:07:14,890 INFO org.I0Itec.zkclient.ZkClient: zookeeper state changed (SyncConnected)
2018-11-28 10:07:14,890 INFO kafka.server.KafkaHealthcheck$SessionExpireListener: re-registering broker info in ZK for broker 62

Why kafka thorws "A broker is already registered on the path /brokers/ids/62" ? At this time kafka broker status is bad. 

I think it might be a kafka or zookeeper bug.

CDH version: 5.13.1-1.cdh5.13.1.p0.2

Kafka version: 3.1.0-1.3.1.0.p0.35