Hi all, yesterday during a short VMWare Patching apply, there a was a very
short network outage, something about 3/5 seconds, but for one of our ZooKeeper
node it didn't come back automatically.
Our ensemble cluster has 5 members and only one got this kind of behavior. I
needed to manually restart it to get it back. In this case this member/zk was
not receving connections from kafka, it's only a repository backup, but anyway
it was supposed to get back "automatically" right ?
It was trying to call the leader, but only this got this kind of behavior, all
the others nodes got the ellection process and reestablished the ensemble.
Bellow there is a log's chunk:
[2021-02-28 09:11:38,119] WARN Exception when following the leader
(org.apache.zookeeper.server.quorum.Learner)
java.io.EOFException
at java.io.DataInputStream.readInt(DataInputStream.java:392)
at
org.apache.jute.BinaryInputArchive.readInt(BinaryInputArchive.java:84)
at
org.apache.zookeeper.server.quorum.QuorumPacket.deserialize(QuorumPacket.java:86)
at
org.apache.jute.BinaryInputArchive.readRecord(BinaryInputArchive.java:118)
at
org.apache.zookeeper.server.quorum.Learner.readPacket(Learner.java:158)
at
org.apache.zookeeper.server.quorum.Follower.followLeader(Follower.java:92)
at
org.apache.zookeeper.server.quorum.QuorumPeer.run(QuorumPeer.java:1253)
[2021-02-28 09:11:38,119] WARN Closing connection to leader, exception during
packet send (org.apache.zookeeper.server.quorum.SendAckRequestProcessor)
javax.net.ssl.SSLException: Connection or outbound has been closed
at sun.security.ssl.Alert.createSSLException(Alert.java:127)
at sun.security.ssl.TransportContext.fatal(TransportContext.java:324)
at sun.security.ssl.TransportContext.fatal(TransportContext.java:267)
at sun.security.ssl.TransportContext.fatal(TransportContext.java:262)
at
sun.security.ssl.SSLSocketImpl$AppOutputStream.write(SSLSocketImpl.java:979)
at
java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:82)
at java.io.BufferedOutputStream.flush(BufferedOutputStream.java:140)
at
org.apache.zookeeper.server.quorum.Learner.writePacket(Learner.java:144)
at
org.apache.zookeeper.server.quorum.SendAckRequestProcessor.flush(SendAckRequestProcessor.java:62)
at
org.apache.zookeeper.server.SyncRequestProcessor.flush(SyncRequestProcessor.java:186)
at
org.apache.zookeeper.server.SyncRequestProcessor.run(SyncRequestProcessor.java:113)
Caused by: java.net.SocketException: Connection or outbound has been closed
at
sun.security.ssl.SSLSocketOutputRecord.deliver(SSLSocketOutputRecord.java:267)
at
sun.security.ssl.SSLSocketImpl$AppOutputStream.write(SSLSocketImpl.java:974)
... 6 more
[2021-02-28 09:11:38,120] INFO shutdown called
(org.apache.zookeeper.server.quorum.Learner)
java.lang.Exception: shutdown Follower
at
org.apache.zookeeper.server.quorum.Follower.shutdown(Follower.java:201)
at
org.apache.zookeeper.server.quorum.QuorumPeer.run(QuorumPeer.java:1257)
[2021-02-28 09:11:38,120] INFO Shutting down
(org.apache.zookeeper.server.ZooKeeperServer)
[2021-02-28 09:11:38,120] INFO shutting down
(org.apache.zookeeper.server.ZooKeeperServer)
[2021-02-28 09:11:38,120] INFO Shutting down
(org.apache.zookeeper.server.quorum.FollowerRequestProcessor)
[2021-02-28 09:11:38,121] INFO Shutting down
(org.apache.zookeeper.server.quorum.CommitProcessor)
[2021-02-28 09:11:38,121] INFO FollowerRequestProcessor exited loop!
(org.apache.zookeeper.server.quorum.FollowerRequestProcessor)
[2021-02-28 09:11:38,121] INFO CommitProcessor exited loop!
(org.apache.zookeeper.server.quorum.CommitProcessor)
[2021-02-28 09:11:38,123] INFO shutdown of request processor complete
(org.apache.zookeeper.server.FinalRequestProcessor)
[2021-02-28 09:11:38,132] INFO Shutting down
(org.apache.zookeeper.server.SyncRequestProcessor)
[2021-02-28 09:11:38,132] INFO SyncRequestProcessor exited!
(org.apache.zookeeper.server.SyncRequestProcessor)
[2021-02-28 09:11:38,132] WARN PeerState set to LOOKING
(org.apache.zookeeper.server.quorum.QuorumPeer)
[2021-02-28 09:11:38,132] INFO LOOKING
(org.apache.zookeeper.server.quorum.QuorumPeer)
[2021-02-28 09:11:38,133] INFO New election. My id = 111, proposed
zxid=0x2800000dd6 (org.apache.zookeeper.server.quorum.FastLeaderElection)
[2021-02-28 09:11:38,135] INFO Notification: 2 (message format version), 111
(n.leader), 0x2800000dd6 (n.zxid), 0xf8 (n.round), LOOKING (n.state), 111
(n.sid), 0x28 (n.peerEPoch), LOOKING (my state)0 (n.config version)
(org.apache.zookeeper.server.quorum.FastLeaderElection)
[2021-02-28 09:11:38,336] INFO Notification time out: 400
(org.apache.zookeeper.server.quorum.FastLeaderElection)
[2021-02-28 09:11:38,337] INFO Notification: 2 (message format version), 111
(n.leader), 0x2800000dd6 (n.zxid), 0xf8 (n.round), LOOKING (n.state), 111
(n.sid), 0x28 (n.peerEPoch), LOOKING (my state)0 (n.config version)
(org.apache.zookeeper.server.quorum.FastLeaderElection)
[2021-02-28 09:11:38,737] INFO Notification time out: 800
(org.apache.zookeeper.server.quorum.FastLeaderElection)
[2021-02-28 09:11:38,738] INFO Notification: 2 (message format version), 111
(n.leader), 0x2800000dd6 (n.zxid), 0xf8 (n.round), LOOKING (n.state), 111
(n.sid), 0x28 (n.peerEPoch), LOOKING (my state)0 (n.config version)
(org.apache.zookeeper.server.quorum.FastLeaderElection)
[2021-02-28 09:11:39,538] INFO Notification time out: 1600
(org.apache.zookeeper.server.quorum.FastLeaderElection)
[2021-02-28 09:11:39,539] INFO Notification: 2 (message format version), 111
(n.leader), 0x2800000dd6 (n.zxid), 0xf8 (n.round), LOOKING (n.state), 111
(n.sid), 0x28 (n.peerEPoch), LOOKING (my state)0 (n.config version)
(org.apache.zookeeper.server.quorum.FastLeaderElection)
[2021-02-28 09:11:41,139] INFO Notification time out: 3200
(org.apache.zookeeper.server.quorum.FastLeaderElection)
[2021-02-28 09:11:41,140] INFO Notification: 2 (message format version), 111
(n.leader), 0x2800000dd6 (n.zxid), 0xf8 (n.round), LOOKING (n.state), 111
(n.sid), 0x28 (n.peerEPoch), LOOKING (my state)0 (n.config version)
(org.apache.zookeeper.server.quorum.FastLeaderElection)
[2021-02-28 09:11:44,340] INFO Notification time out: 6400
(org.apache.zookeeper.server.quorum.FastLeaderElection)
[2021-02-28 09:11:44,341] INFO Notification: 2 (message format version), 111
(n.leader), 0x2800000dd6 (n.zxid), 0xf8 (n.round), LOOKING (n.state), 111
(n.sid), 0x28 (n.peerEPoch), LOOKING (my state)0 (n.config version)
(org.apache.zookeeper.server.quorum.FastLeaderElection)
[2021-02-28 09:11:50,741] INFO Notification time out: 12800
(org.apache.zookeeper.server.quorum.FastLeaderElection)
[2021-02-28 09:11:50,741] INFO Notification: 2 (message format version), 111
(n.leader), 0x2800000dd6 (n.zxid), 0xf8 (n.round), LOOKING (n.state), 111
(n.sid), 0x28 (n.peerEPoch), LOOKING (my state)0 (n.config version)
(org.apache.zookeeper.server.quorum.FastLeaderElection)
[2021-02-28 09:12:03,542] INFO Notification time out: 25600
(org.apache.zookeeper.server.quorum.FastLeaderElection)
[2021-02-28 09:12:03,542] INFO Notification: 2 (message format version), 111
(n.leader), 0x2800000dd6 (n.zxid), 0xf8 (n.round), LOOKING (n.state), 111
(n.sid), 0x28 (n.peerEPoch), LOOKING (my state)0 (n.config version)
(org.apache.zookeeper.server.quorum.FastLeaderElection)
[2021-02-28 09:12:29,142] INFO Notification time out: 51200
(org.apache.zookeeper.server.quorum.FastLeaderElection)
[2021-02-28 09:12:29,143] INFO Notification: 2 (message format version), 111
(n.leader), 0x2800000dd6 (n.zxid), 0xf8 (n.round), LOOKING (n.state), 111
(n.sid), 0x28 (n.peerEPoch), LOOKING (my state)0 (n.config version)
(org.apache.zookeeper.server.quorum.FastLeaderElection)
[2021-02-28 09:13:20,344] INFO Notification time out: 60000
(org.apache.zookeeper.server.quorum.FastLeaderElection)
[2021-02-28 09:13:20,345] INFO Notification: 2 (message format version), 111
(n.leader), 0x2800000dd6 (n.zxid), 0xf8 (n.round), LOOKING (n.state), 111
(n.sid), 0x28 (n.peerEPoch), LOOKING (my state)0 (n.config version)
(org.apache.zookeeper.server.quorum.FastLeaderElection)
[2021-02-28 09:14:20,345] INFO Notification time out: 60000
(org.apache.zookeeper.server.quorum.FastLeaderElection)
[2021-02-28 09:14:20,346] INFO Notification: 2 (message format version), 111
(n.leader), 0x2800000dd6 (n.zxid), 0xf8 (n.round), LOOKING (n.state), 111
(n.sid), 0x28 (n.peerEPoch), LOOKING (my state)0 (n.config version)
(org.apache.zookeeper.server.quorum.FastLeaderElection)
[2021-02-28 09:15:20,346] INFO Notification time out: 60000
(org.apache.zookeeper.server.quorum.FastLeaderElection)
[2021-02-28 09:15:20,347] INFO Notification: 2 (message format version), 111
(n.leader), 0x2800000dd6 (n.zxid), 0xf8 (n.round), LOOKING (n.state), 111
(n.sid), 0x28 (n.peerEPoch), LOOKING (my state)0 (n.config version)
(org.apache.zookeeper.server.quorum.FastLeaderElection)
[2021-02-28 09:16:20,347] INFO Notification time out: 60000
(org.apache.zookeeper.server.quorum.FastLeaderElection)
[2021-02-28 09:16:20,348] INFO Notification: 2 (message format version), 111
(n.leader), 0x2800000dd6 (n.zxid), 0xf8 (n.round), LOOKING (n.state), 111
(n.sid), 0x28 (n.peerEPoch), LOOKING (my state)0 (n.config version)
(org.apache.zookeeper.server.quorum.FastLeaderElection)
[2021-02-28 09:17:20,348] INFO Notification time out: 60000
(org.apache.zookeeper.server.quorum.FastLeaderElection)
[2021-02-28 09:17:20,350] INFO Notification: 2 (message format version), 111
(n.leader), 0x2800000dd6 (n.zxid), 0xf8 (n.round), LOOKING (n.state), 111
(n.sid), 0x28 (n.peerEPoch), LOOKING (my state)0 (n.config version)
(org.apache.zookeeper.server.quorum.FastLeaderElection)
[2021-02-28 09:18:20,350] INFO Notification time out: 60000
(org.apache.zookeeper.server.quorum.FastLeaderElection)
[2021-02-28 09:18:20,351] INFO Notification: 2 (message format version), 111
(n.leader), 0x2800000dd6 (n.zxid), 0xf8 (n.round), LOOKING (n.state), 111
(n.sid), 0x28 (n.peerEPoch), LOOKING (my state)0 (n.config version)
(org.apache.zookeeper.server.quorum.FastLeaderElection)
[2021-02-28 09:19:20,352] INFO Notification time out: 60000
(org.apache.zookeeper.server.quorum.FastLeaderElection)
[2021-02-28 09:19:20,352] INFO Notification: 2 (message format version), 111
(n.leader), 0x2800000dd6 (n.zxid), 0xf8 (n.round), LOOKING (n.state), 111
(n.sid), 0x28 (n.peerEPoch), LOOKING (my state)0 (n.config version)
(org.apache.zookeeper.server.quorum.FastLeaderElection)
[2021-02-28 09:20:20,353] INFO Notification time out: 60000
(org.apache.zookeeper.server.quorum.FastLeaderElection)
[2021-02-28 09:20:20,357] INFO Notification: 2 (message format version), 111
(n.leader), 0x2800000dd6 (n.zxid), 0xf8 (n.round), LOOKING (n.state), 111
(n.sid), 0x28 (n.peerEPoch), LOOKING (my state)0 (n.config version)
(org.apache.zookeeper.server.quorum.FastLeaderElection)
[2021-02-28 09:21:20,357] INFO Notification time out: 60000
(org.apache.zookeeper.server.quorum.FastLeaderElection)
[2021-02-28 09:21:20,358] INFO Notification: 2 (message format version), 111
(n.leader), 0x2800000dd6 (n.zxid), 0xf8 (n.round), LOOKING (n.state), 111
(n.sid), 0x28 (n.peerEPoch), LOOKING (my state)0 (n.config version)
(org.apache.zookeeper.server.quorum.FastLeaderElection)
#############################################################
Needed to manually restart to force reconnect to ensemble cluster.
#############################################################
[2021-02-28 09:21:56,110] INFO Reading configuration from:
/opt/kafka/config/zookeeper.properties
(org.apache.zookeeper.server.quorum.QuorumPeerConfig)
[2021-02-28 09:21:56,113] INFO clientPort is not set
(org.apache.zookeeper.server.quorum.QuorumPeerConfig)
[2021-02-28 09:21:56,115] INFO secureClientPortAddress is 0.0.0.0:3184
(org.apache.zookeeper.server.quorum.QuorumPeerConfig)
[2021-02-28 09:21:56,118] INFO Setting -D
jdk.tls.rejectClientInitiatedRenegotiation=true to disable client-initiated TLS
renegotiation (org.apache.zookeeper.common.X509Util)
[2021-02-28 09:21:56,126] INFO autopurge.snapRetainCount set to 10
(org.apache.zookeeper.server.DatadirCleanupManager)
[2021-02-28 09:21:56,126] INFO autopurge.purgeInterval set to 1
(org.apache.zookeeper.server.DatadirCleanupManager)
[2021-02-28 09:21:56,129] INFO Purge task started.
(org.apache.zookeeper.server.DatadirCleanupManager)
[2021-02-28 09:21:56,129] INFO Log4j 1.2 jmx support found and enabled.
(org.apache.zookeeper.jmx.ManagedUtil)
[2021-02-28 09:21:56,135] INFO Starting quorum peer
(org.apache.zookeeper.server.quorum.QuorumPeerMain)
[2021-02-28 09:21:56,137] INFO zookeeper.snapshot.trust.empty : false
(org.apache.zookeeper.server.persistence.FileTxnSnapLog)
[2021-02-28 09:21:56,146] INFO Purge task completed.
(org.apache.zookeeper.server.DatadirCleanupManager)
[2021-02-28 09:21:56,187] INFO zookeeper.client.portUnification=false
(org.apache.zookeeper.server.NettyServerCnxnFactory)
[2021-02-28 09:21:56,220] INFO Using
org.apache.zookeeper.server.NettyServerCnxnFactory as server connection factory
(org.apache.zookeeper.server.ServerCnxnFactory)
[2021-02-28 09:21:56,228] INFO Server successfully logged in.
(org.apache.zookeeper.Login)
[2021-02-28 09:21:56,242] INFO zookeeper.snapshot.trust.empty : false
(org.apache.zookeeper.server.persistence.FileTxnSnapLog)
[2021-02-28 09:21:56,242] INFO Local sessions disabled
(org.apache.zookeeper.server.quorum.QuorumPeer)
[2021-02-28 09:21:56,242] INFO Local session upgrading disabled
(org.apache.zookeeper.server.quorum.QuorumPeer)
[2021-02-28 09:21:56,243] INFO tickTime set to 2000
(org.apache.zookeeper.server.quorum.QuorumPeer)
[2021-02-28 09:21:56,243] INFO minSessionTimeout set to 4000
(org.apache.zookeeper.server.quorum.QuorumPeer)
[2021-02-28 09:21:56,243] INFO maxSessionTimeout set to 40000
(org.apache.zookeeper.server.quorum.QuorumPeer)
[2021-02-28 09:21:56,243] INFO initLimit set to 5
(org.apache.zookeeper.server.quorum.QuorumPeer)
[2021-02-28 09:21:56,253] INFO zookeeper.snapshotSizeFactor = 0.33
(org.apache.zookeeper.server.ZKDatabase)
[2021-02-28 09:21:56,255] INFO Using TLS encrypted quorum communication
(org.apache.zookeeper.server.quorum.QuorumPeer)
[2021-02-28 09:21:56,255] INFO Port unification disabled
(org.apache.zookeeper.server.quorum.QuorumPeer)
[2021-02-28 09:21:56,255] INFO quorum.auth.enableSasl set to true
(org.apache.zookeeper.server.quorum.QuorumPeer)
[2021-02-28 09:21:56,255] INFO quorum.auth.serverRequireSasl set to true
(org.apache.zookeeper.server.quorum.QuorumPeer)
[2021-02-28 09:21:56,255] INFO quorum.auth.learnerRequireSasl set to true
(org.apache.zookeeper.server.quorum.QuorumPeer)
[2021-02-28 09:21:56,255] INFO quorum.auth.kerberos.servicePrincipal set to
zkquorum/localhost (org.apache.zookeeper.server.quorum.QuorumPeer)
[2021-02-28 09:21:56,255] INFO quorum.auth.server.saslLoginContext set to
QuorumServer (org.apache.zookeeper.server.quorum.QuorumPeer)
[2021-02-28 09:21:56,255] INFO quorum.auth.learner.saslLoginContext set to
QuorumLearner (org.apache.zookeeper.server.quorum.QuorumPeer)
[2021-02-28 09:21:56,255] INFO quorum.cnxn.threads.size set to 20
(org.apache.zookeeper.server.quorum.QuorumPeer)
[2021-02-28 09:21:56,257] INFO QuorumServer successfully logged in.
(org.apache.zookeeper.Login)
[2021-02-28 09:21:56,258] INFO QuorumLearner successfully logged in.
(org.apache.zookeeper.Login)
[2021-02-28 09:21:56,260] INFO Reading snapshot
/zookeeper-datastore/version-2/snapshot.2400000034
(org.apache.zookeeper.server.persistence.FileSnap)
[2021-02-28 09:21:56,511] INFO binding to port 0.0.0.0/0.0.0.0:3184
(org.apache.zookeeper.server.NettyServerCnxnFactory)
[2021-02-28 09:21:56,565] INFO bound to port 3184
(org.apache.zookeeper.server.NettyServerCnxnFactory)
[2021-02-28 09:21:56,571] INFO Election port bind maximum retries is 3
(org.apache.zookeeper.server.quorum.QuorumCnxManager)
[2021-02-28 09:21:56,574] INFO Creating TLS-only quorum server socket
(org.apache.zookeeper.server.quorum.QuorumCnxManager)
[2021-02-28 09:21:56,575] INFO 111 is accepting connections now, my election
bind port: zk-xpto.production.com/10.1.1.99:3888
(org.apache.zookeeper.server.quorum.QuorumCnxManager)
[2021-02-28 09:21:56,587] INFO LOOKING
(org.apache.zookeeper.server.quorum.QuorumPeer)
[2021-02-28 09:21:56,592] INFO New election. My id = 111, proposed
zxid=0x2800000dd6 (org.apache.zookeeper.server.quorum.FastLeaderElection)
