zookeeper-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Zhenghua Chen (JIRA)" <j...@apache.org>
Subject [jira] [Updated] (ZOOKEEPER-2669) follower failed to reconnect to leader after a network error
Date Thu, 19 Jan 2017 11:34:26 GMT

     [ https://issues.apache.org/jira/browse/ZOOKEEPER-2669?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]

Zhenghua Chen updated ZOOKEEPER-2669:
-------------------------------------
    Description: 
We have a zookeeper cluster with 3 nodes named s1, s2, s3
By mistake, we shut down the ethernet interface of s2, and zk follower  shut down(zk process
remains there)
Later, after ethernet up again, s2 failed to reconnect to leader s3 to be a follower

follower s2 keeps printing log like this:
{quote}
2017-01-19 16:40:58,956 WARN  [QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:7181] o.a.z.s.q.Learner
- Got zxid 0x320001019f expected 0x1
2017-01-19 16:40:58,956 ERROR [SyncThread:1] o.a.z.s.ZooKeeperCriticalThread - Severe unrecoverable
error, from thread : SyncThread:1
java.nio.channels.ClosedChannelException: null
	at sun.nio.ch.FileChannelImpl.ensureOpen(FileChannelImpl.java:99)
	at sun.nio.ch.FileChannelImpl.position(FileChannelImpl.java:250)
	at org.apache.zookeeper.server.persistence.Util.padLogFile(Util.java:215)
	at org.apache.zookeeper.server.persistence.FileTxnLog.padFile(FileTxnLog.java:241)
	at org.apache.zookeeper.server.persistence.FileTxnLog.append(FileTxnLog.java:219)
	at org.apache.zookeeper.server.persistence.FileTxnSnapLog.append(FileTxnSnapLog.java:314)
	at org.apache.zookeeper.server.ZKDatabase.append(ZKDatabase.java:470)
	at org.apache.zookeeper.server.SyncRequestProcessor.run(SyncRequestProcessor.java:140)
2017-01-19 16:40:58,956 INFO  [SyncThread:1] o.a.z.s.ZooKeeperServerListenerImpl - Thread
SyncThread:1 exits, error code 1
2017-01-19 16:40:58,956 INFO  [SyncThread:1] o.a.z.s.SyncRequestProcessor - SyncRequestProcessor
exited!
2017-01-19 16:40:58,957 INFO  [QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:7181] o.a.z.s.q.Learner
- shutdown called
java.lang.Exception: shutdown Follower
	at org.apache.zookeeper.server.quorum.Follower.shutdown(Follower.java:164)
	at org.apache.zookeeper.server.quorum.QuorumPeer.run(QuorumPeer.java:850)
{quote}

And, leader s3 keeps printing log like this:
{quote}
2017-01-19 16:30:50,452 INFO  [LearnerHandler-/192.168.40.51:35949] o.a.z.s.q.LearnerHandler
- Follower sid: 1 : info : org.apache.zookeeper.server.quorum.QuorumPeer$QuorumServer@95258f0
2017-01-19 16:30:50,452 INFO  [LearnerHandler-/192.168.40.51:35949] o.a.z.s.q.LearnerHandler
- Synchronizing with Follower sid: 1 maxCommittedLog=0x320001019e minCommittedLog=0x320000ffaa
peerLastZxid=0x2300000000
2017-01-19 16:30:50,453 WARN  [LearnerHandler-/192.168.40.51:35949] o.a.z.s.q.LearnerHandler
- Unhandled proposal scenario
2017-01-19 16:30:50,453 INFO  [LearnerHandler-/192.168.40.51:35949] o.a.z.s.q.LearnerHandler
- Sending SNAP
2017-01-19 16:30:50,453 INFO  [LearnerHandler-/192.168.40.51:35949] o.a.z.s.q.LearnerHandler
- Sending snapshot last zxid of peer is 0x2300000000  zxid of leader is 0x320001019esent zxid
of db as 0x320001019e
2017-01-19 16:30:50,461 INFO  [LearnerHandler-/192.168.40.51:35949] o.a.z.s.q.LearnerHandler
- Received NEWLEADER-ACK message from 1
2017-01-19 16:30:51,738 ERROR [LearnerHandler-/192.168.40.51:35934] o.a.z.s.q.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.read(SocketInputStream.java:152)
	at java.net.SocketInputStream.read(SocketInputStream.java:122)
	at java.io.BufferedInputStream.fill(BufferedInputStream.java:235)
	at java.io.BufferedInputStream.read(BufferedInputStream.java:254)
	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:542)
{quote}

we execute netstat, found lots of close wait socket in s2,  and never closed.
{quote}
tcp6   10865      0 192.168.40.51:47181     192.168.40.57:7288      CLOSE_WAIT  2217/java
          
tcp6    2576      0 192.168.40.51:57181     192.168.40.57:7288      CLOSE_WAIT  2217/java
          
{quote}
seems that s2 has a connection leak.

after restart zk process of s2, it works fine.


  was:
We have a zookeeper cluster with 3 nodes named s1, s2, s3
By mistake, we shut down the ethernet interface of s2, and zk follower  shut down(zk process
remains there)
Later, after ethernet up again, s2 failed to reconnect to leader s3 to be a follower

log of follower s2:
{quote}
2017-01-19 16:40:58,956 WARN  [QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:7181] o.a.z.s.q.Learner
- Got zxid 0x320001019f expected 0x1
2017-01-19 16:40:58,956 ERROR [SyncThread:1] o.a.z.s.ZooKeeperCriticalThread - Severe unrecoverable
error, from thread : SyncThread:1
java.nio.channels.ClosedChannelException: null
	at sun.nio.ch.FileChannelImpl.ensureOpen(FileChannelImpl.java:99)
	at sun.nio.ch.FileChannelImpl.position(FileChannelImpl.java:250)
	at org.apache.zookeeper.server.persistence.Util.padLogFile(Util.java:215)
	at org.apache.zookeeper.server.persistence.FileTxnLog.padFile(FileTxnLog.java:241)
	at org.apache.zookeeper.server.persistence.FileTxnLog.append(FileTxnLog.java:219)
	at org.apache.zookeeper.server.persistence.FileTxnSnapLog.append(FileTxnSnapLog.java:314)
	at org.apache.zookeeper.server.ZKDatabase.append(ZKDatabase.java:470)
	at org.apache.zookeeper.server.SyncRequestProcessor.run(SyncRequestProcessor.java:140)
2017-01-19 16:40:58,956 INFO  [SyncThread:1] o.a.z.s.ZooKeeperServerListenerImpl - Thread
SyncThread:1 exits, error code 1
2017-01-19 16:40:58,956 INFO  [SyncThread:1] o.a.z.s.SyncRequestProcessor - SyncRequestProcessor
exited!
2017-01-19 16:40:58,957 INFO  [QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:7181] o.a.z.s.q.Learner
- shutdown called
java.lang.Exception: shutdown Follower
	at org.apache.zookeeper.server.quorum.Follower.shutdown(Follower.java:164)
	at org.apache.zookeeper.server.quorum.QuorumPeer.run(QuorumPeer.java:850)
{quote}

log of leader s3:
{quote}
2017-01-19 16:30:50,452 INFO  [LearnerHandler-/192.168.40.51:35949] o.a.z.s.q.LearnerHandler
- Follower sid: 1 : info : org.apache.zookeeper.server.quorum.QuorumPeer$QuorumServer@95258f0
2017-01-19 16:30:50,452 INFO  [LearnerHandler-/192.168.40.51:35949] o.a.z.s.q.LearnerHandler
- Synchronizing with Follower sid: 1 maxCommittedLog=0x320001019e minCommittedLog=0x320000ffaa
peerLastZxid=0x2300000000
2017-01-19 16:30:50,453 WARN  [LearnerHandler-/192.168.40.51:35949] o.a.z.s.q.LearnerHandler
- Unhandled proposal scenario
2017-01-19 16:30:50,453 INFO  [LearnerHandler-/192.168.40.51:35949] o.a.z.s.q.LearnerHandler
- Sending SNAP
2017-01-19 16:30:50,453 INFO  [LearnerHandler-/192.168.40.51:35949] o.a.z.s.q.LearnerHandler
- Sending snapshot last zxid of peer is 0x2300000000  zxid of leader is 0x320001019esent zxid
of db as 0x320001019e
2017-01-19 16:30:50,461 INFO  [LearnerHandler-/192.168.40.51:35949] o.a.z.s.q.LearnerHandler
- Received NEWLEADER-ACK message from 1
2017-01-19 16:30:51,738 ERROR [LearnerHandler-/192.168.40.51:35934] o.a.z.s.q.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.read(SocketInputStream.java:152)
	at java.net.SocketInputStream.read(SocketInputStream.java:122)
	at java.io.BufferedInputStream.fill(BufferedInputStream.java:235)
	at java.io.BufferedInputStream.read(BufferedInputStream.java:254)
	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:542)
{quote}

by using netstat, we found lots of close wait socket in s2, and never closed.
looks like this:
{quote}
tcp6   10865      0 192.168.40.51:47181     192.168.40.57:7288      CLOSE_WAIT  2217/java
          
tcp6    2576      0 192.168.40.51:57181     192.168.40.57:7288      CLOSE_WAIT  2217/java
          
{quote}
seems that s2 has a connection leak.

after restart zk process of s2, it works fine.



> follower failed to  reconnect to leader after a network error
> -------------------------------------------------------------
>
>                 Key: ZOOKEEPER-2669
>                 URL: https://issues.apache.org/jira/browse/ZOOKEEPER-2669
>             Project: ZooKeeper
>          Issue Type: Bug
>          Components: quorum, server
>    Affects Versions: 3.4.9
>         Environment: CentOS7
>            Reporter: Zhenghua Chen
>
> We have a zookeeper cluster with 3 nodes named s1, s2, s3
> By mistake, we shut down the ethernet interface of s2, and zk follower  shut down(zk
process remains there)
> Later, after ethernet up again, s2 failed to reconnect to leader s3 to be a follower
> follower s2 keeps printing log like this:
> {quote}
> 2017-01-19 16:40:58,956 WARN  [QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:7181] o.a.z.s.q.Learner
- Got zxid 0x320001019f expected 0x1
> 2017-01-19 16:40:58,956 ERROR [SyncThread:1] o.a.z.s.ZooKeeperCriticalThread - Severe
unrecoverable error, from thread : SyncThread:1
> java.nio.channels.ClosedChannelException: null
> 	at sun.nio.ch.FileChannelImpl.ensureOpen(FileChannelImpl.java:99)
> 	at sun.nio.ch.FileChannelImpl.position(FileChannelImpl.java:250)
> 	at org.apache.zookeeper.server.persistence.Util.padLogFile(Util.java:215)
> 	at org.apache.zookeeper.server.persistence.FileTxnLog.padFile(FileTxnLog.java:241)
> 	at org.apache.zookeeper.server.persistence.FileTxnLog.append(FileTxnLog.java:219)
> 	at org.apache.zookeeper.server.persistence.FileTxnSnapLog.append(FileTxnSnapLog.java:314)
> 	at org.apache.zookeeper.server.ZKDatabase.append(ZKDatabase.java:470)
> 	at org.apache.zookeeper.server.SyncRequestProcessor.run(SyncRequestProcessor.java:140)
> 2017-01-19 16:40:58,956 INFO  [SyncThread:1] o.a.z.s.ZooKeeperServerListenerImpl - Thread
SyncThread:1 exits, error code 1
> 2017-01-19 16:40:58,956 INFO  [SyncThread:1] o.a.z.s.SyncRequestProcessor - SyncRequestProcessor
exited!
> 2017-01-19 16:40:58,957 INFO  [QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:7181] o.a.z.s.q.Learner
- shutdown called
> java.lang.Exception: shutdown Follower
> 	at org.apache.zookeeper.server.quorum.Follower.shutdown(Follower.java:164)
> 	at org.apache.zookeeper.server.quorum.QuorumPeer.run(QuorumPeer.java:850)
> {quote}
> And, leader s3 keeps printing log like this:
> {quote}
> 2017-01-19 16:30:50,452 INFO  [LearnerHandler-/192.168.40.51:35949] o.a.z.s.q.LearnerHandler
- Follower sid: 1 : info : org.apache.zookeeper.server.quorum.QuorumPeer$QuorumServer@95258f0
> 2017-01-19 16:30:50,452 INFO  [LearnerHandler-/192.168.40.51:35949] o.a.z.s.q.LearnerHandler
- Synchronizing with Follower sid: 1 maxCommittedLog=0x320001019e minCommittedLog=0x320000ffaa
peerLastZxid=0x2300000000
> 2017-01-19 16:30:50,453 WARN  [LearnerHandler-/192.168.40.51:35949] o.a.z.s.q.LearnerHandler
- Unhandled proposal scenario
> 2017-01-19 16:30:50,453 INFO  [LearnerHandler-/192.168.40.51:35949] o.a.z.s.q.LearnerHandler
- Sending SNAP
> 2017-01-19 16:30:50,453 INFO  [LearnerHandler-/192.168.40.51:35949] o.a.z.s.q.LearnerHandler
- Sending snapshot last zxid of peer is 0x2300000000  zxid of leader is 0x320001019esent zxid
of db as 0x320001019e
> 2017-01-19 16:30:50,461 INFO  [LearnerHandler-/192.168.40.51:35949] o.a.z.s.q.LearnerHandler
- Received NEWLEADER-ACK message from 1
> 2017-01-19 16:30:51,738 ERROR [LearnerHandler-/192.168.40.51:35934] o.a.z.s.q.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.read(SocketInputStream.java:152)
> 	at java.net.SocketInputStream.read(SocketInputStream.java:122)
> 	at java.io.BufferedInputStream.fill(BufferedInputStream.java:235)
> 	at java.io.BufferedInputStream.read(BufferedInputStream.java:254)
> 	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:542)
> {quote}
> we execute netstat, found lots of close wait socket in s2,  and never closed.
> {quote}
> tcp6   10865      0 192.168.40.51:47181     192.168.40.57:7288      CLOSE_WAIT  2217/java
          
> tcp6    2576      0 192.168.40.51:57181     192.168.40.57:7288      CLOSE_WAIT  2217/java
          
> {quote}
> seems that s2 has a connection leak.
> after restart zk process of s2, it works fine.



--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

Mime
View raw message