Please tell me what should I check.Thank you. [hadoop@master zookeeper]$ getenforce Disabled [hadoop@master zookeeper]$ /bin/systemctl status iptables.service iptables.service Loaded: not-found (Reason: No such file or directory) Active: inactive (dead) [hadoop@master zookeeper]$ ssh slave1 Last login: Fri Apr 22 11:54:06 2016 from master [hadoop@slave1 ~]$ exit logout Connection to slave1 closed. [hadoop@master zookeeper]$ ssh slave2 Last login: Fri Apr 22 11:54:18 2016 from slave1 [hadoop@slave2 ~]$ exit logout Connection to slave2 closed. [hadoop@master zookeeper]$ ssh 192.168.1.2 Last login: Fri Apr 22 11:54:33 2016 from slave2 [hadoop@master ~]$ exit logout Connection to 192.168.1.2 closed. [hadoop@master zookeeper]$ ssh 192.168.1.4 Last login: Fri Apr 22 12:06:40 2016 from master [hadoop@slave2 ~]$ exit logout Connection to 192.168.1.4 closed.
[hadoop@slave1 ~]$ getenforce Disabled [hadoop@slave1 ~]$ /bin/systemctl status iptables.service iptables.service Loaded: not-found (Reason: No such file or directory) Active: inactive (dead) [hadoop@slave1 ~]$ ping master PING master (192.168.1.2) 56(84) bytes of data. 64 bytes from master (192.168.1.2): icmp_seq=1 ttl=64 time=0.284 ms 64 bytes from master (192.168.1.2): icmp_seq=2 ttl=64 time=0.900 ms 64 bytes from master (192.168.1.2): icmp_seq=3 ttl=64 time=0.543 ms ^C --- master ping statistics --- 3 packets transmitted, 3 received, 0% packet loss, time 2003ms rtt min/avg/max/mdev = 0.284/0.575/0.900/0.254 ms [hadoop@slave1 ~]$ ping slave2 PING slave2 (192.168.1.4) 56(84) bytes of data. 64 bytes from slave2 (192.168.1.4): icmp_seq=1 ttl=64 time=11.6 ms 64 bytes from slave2 (192.168.1.4): icmp_seq=2 ttl=64 time=0.406 ms 64 bytes from slave2 (192.168.1.4): icmp_seq=3 ttl=64 time=0.395 ms [hadoop@slave2 ~]$ getenforce Disabled [hadoop@slave2 ~]$ service iptables status Redirecting to /bin/systemctl status iptables.service iptables.service Loaded: not-found (Reason: No such file or directory) Active: inactive (dead) Eric Gao Keep on going never give up. Blog: http://gaoqiang.blog.chinaunix.net/ http://gaoqiangdba.blog.163.com/ From: Flavio Junqueira Date: 2016-04-22 13:01 To: user CC: camille Subject: Re: Zookeeper is unable to start The ensemble is electing a leader, but from this: 2016-04-21 11:06:44,705 [myid:3] - INFO [LearnerHandler-/192.168.1.3:54214:LearnerHandler@518] - Received NEWLEADER-ACK message from 2 2016-04-21 11:07:45,832 [myid:3] - ERROR [LearnerHandler-/192.168.1.2:35258:LearnerHandler@631] - Unexpected exception causing shutdown while sock still open java.io.EOFException It looks like the connection to the follower is timing out and the leader is losing quorum, that's the reason you're seeing these messages that the service isn't available. You need to determine why the connection is dropping. Does it happen every time you start it? -Flavio > On 21 Apr 2016, at 19:39, Eric Gao <[email protected]> wrote: > > Sorry. > > > Here are the logs: > Master's zookeeper.out： > 2016-04-21 11:30:06,645 [myid:] - INFO [main:QuorumPeerConfig@103] - Reading > configuration from: /opt/zookeeper/bin/../conf/zoo.cfg > 2016-04-21 11:30:06,724 [myid:] - INFO [main:QuorumPeer$QuorumServer@149] - > Resolved hostname: 192.168.1.4 to address: /192.168.1.4 > 2016-04-21 11:30:06,725 [myid:] - INFO [main:QuorumPeer$QuorumServer@149] - > Resolved hostname: 192.168.1.3 to address: /192.168.1.3 > 2016-04-21 11:30:06,726 [myid:] - INFO [main:QuorumPeer$QuorumServer@149] - > Resolved hostname: 192.168.1.2 to address: /192.168.1.2 > 2016-04-21 11:30:06,727 [myid:] - INFO [main:QuorumPeerConfig@331] - > Defaulting to majority quorums > 2016-04-21 11:30:06,737 [myid:1] - INFO [main:DatadirCleanupManager@78] - > autopurge.snapRetainCount set to 3 > 2016-04-21 11:30:06,738 [myid:1] - INFO [main:DatadirCleanupManager@79] - > autopurge.purgeInterval set to 0 > 2016-04-21 11:30:06,738 [myid:1] - INFO [main:DatadirCleanupManager@101] - > Purge task is not scheduled. > 2016-04-21 11:30:06,765 [myid:1] - INFO [main:QuorumPeerMain@127] - Starting > quorum peer > 2016-04-21 11:30:06,794 [myid:1] - INFO [main:NIOServerCnxnFactory@89] - > binding to port 0.0.0.0/0.0.0.0:2181 > 2016-04-21 11:30:06,815 [myid:1] - INFO [main:QuorumPeer@1019] - tickTime > set to 2000 > 2016-04-21 11:30:06,815 [myid:1] - INFO [main:QuorumPeer@1039] - > minSessionTimeout set to -1 > 2016-04-21 11:30:06,816 [myid:1] - INFO [main:QuorumPeer@1050] - > maxSessionTimeout set to -1 > 2016-04-21 11:30:06,816 [myid:1] - INFO [main:QuorumPeer@1065] - initLimit > set to 10 > 2016-04-21 11:30:06,851 [myid:1] - INFO [main:FileSnap@83] - Reading > snapshot /opt/zookeeper/data/version-2/snapshot.200000000 > 2016-04-21 11:30:06,882 [myid:1] - INFO > [ListenerThread:QuorumCnxManager$Listener@534] - My election bind port: > /192.168.1.2:3887 > 2016-04-21 11:30:06,989 [myid:1] - INFO > [QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:2181:QuorumPeer@774] - LOOKING > 00 > 0 (n.zxid), 0x1 (n.round), LOOKING (n.state), 1 (n.sid), 0x2 (n.peerEpoch) > LOOKING (my state) > 2016-04-21 11:30:07,020 [myid:1] - INFO > [WorkerSender[myid=1]:QuorumCnxManager@199] - Have smaller server identifier, > so dropping the connection: (2, 1) > 2016-04-21 11:30:07,024 [myid:1] - INFO > [WorkerSender[myid=1]:QuorumCnxManager@199] - Have smaller server identifier, > so dropping the connection: (3, 1) > 2016-04-21 11:30:07,035 [myid:1] - INFO > [/192.168.1.2:3887:QuorumCnxManager$Listener@541] - Received connection > request /192.168.1.3:56474 > d), 0x1 (n.round), FOLLOWING (n.state), 2 (n.sid), 0x2 (n.peerEpoch) LOOKING > (my state) > d), 0x1 (n.round), FOLLOWING (n.state), 2 (n.sid), 0x2 (n.peerEpoch) LOOKING > (my state) > 2016-04-21 11:30:07,043 [myid:1] - INFO > [/192.168.1.2:3887:QuorumCnxManager$Listener@541] - Received connection > request /192.168.1.4:46486 > d), 0x1 (n.round), LEADING (n.state), 3 (n.sid), 0x2 (n.peerEpoch) LOOKING > (my state) > 2016-04-21 11:30:07,050 [myid:1] - INFO > [QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:2181:QuorumPeer@844] - FOLLOWING > 2016-04-21 11:30:07,058 [myid:1] - INFO > [QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:2181:Learner@86] - TCP NoDelay set to: > true > 02/06/2016 03:18 GMT > 2016-04-21 11:30:07,071 [myid:1] - INFO > [QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server > environment:host.name=master > 2016-04-21 11:30:07,071 [myid:1] - INFO > [QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server > environment:java.version=1.7.0_75 > 2016-04-21 11:30:07,072 [myid:1] - INFO > [QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server > environment:java.vendor=Oracle Corporation > njdk-1.7.0.75-2.5.4.2.el7_0.x86_64/jre > lib > lib/amd64:/usr/lib64:/lib64:/lib:/usr/lib > 2016-04-21 11:30:07,072 [myid:1] - INFO > [QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server > environment:java.io.tmpdir=/tmp > 2016-04-21 11:30:07,073 [myid:1] - INFO > [QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server > environment:java.compiler=<NA> > 2016-04-21 11:30:07,073 [myid:1] - INFO > [QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server > environment:os.name=Linux > 2016-04-21 11:30:07,073 [myid:1] - INFO > [QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server > environment:os.arch=amd64 > 2016-04-21 11:30:07,073 [myid:1] - INFO > [QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server > environment:os.version=3.10.0-229.el7.x86_64 > 2016-04-21 11:30:07,073 [myid:1] - INFO > [QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server > environment:user.name=hadoop > 2016-04-21 11:30:07,073 [myid:1] - INFO > [QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server > environment:user.home=/home/hadoop > 2016-04-21 11:30:07,074 [myid:1] - INFO > [QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server > environment:user.dir=/home/hadoop > 4000 maxSessionTimeout 40000 datadir /opt/zookeeper/log/version-2 snapdir > /opt/zookeeper/data/version-2 > 2016-04-21 11:30:07,081 [myid:1] - INFO > [QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:2181:Follower@63] - FOLLOWING - LEADER > ELECTION TOOK - 90 > 192.168.1.4 > d), 0x1 (n.round), LEADING (n.state), 3 (n.sid), 0x2 (n.peerEpoch) FOLLOWING > (my state) > 2016-04-21 11:30:07,178 [myid:1] - INFO > [QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:2181:Learner@326] - Getting a diff from > the leader 0x200000000 > ion-2/snapshot.200000000 > > > slave1's zookeeper.out: > 2016-04-21 11:30:30,626 [myid:] - INFO [main:QuorumPeerConfig@103] - Reading > configuration from: /opt/zookeeper/bin/../conf/zoo.cfg > 2016-04-21 11:30:30,658 [myid:] - INFO [main:QuorumPeer$QuorumServer@149] - > Resolved hostname: 192.168.1.4 to address: /192.168.1.4 > 2016-04-21 11:30:30,659 [myid:] - INFO [main:QuorumPeer$QuorumServer@149] - > Resolved hostname: 192.168.1.3 to address: /192.168.1.3 > 2016-04-21 11:30:30,662 [myid:] - INFO [main:QuorumPeer$QuorumServer@149] - > Resolved hostname: 192.168.1.2 to address: /192.168.1.2 > 2016-04-21 11:30:30,662 [myid:] - INFO [main:QuorumPeerConfig@331] - > Defaulting to majority quorums > 2016-04-21 11:30:30,668 [myid:2] - INFO [main:DatadirCleanupManager@78] - > autopurge.snapRetainCount set to 3 > 2016-04-21 11:30:30,668 [myid:2] - INFO [main:DatadirCleanupManager@79] - > autopurge.purgeInterval set to 0 > 2016-04-21 11:30:30,668 [myid:2] - INFO [main:DatadirCleanupManager@101] - > Purge task is not scheduled. > 2016-04-21 11:30:30,686 [myid:2] - INFO [main:QuorumPeerMain@127] - Starting > quorum peer > 2016-04-21 11:30:30,697 [myid:2] - INFO [main:NIOServerCnxnFactory@89] - > binding to port 0.0.0.0/0.0.0.0:2181 > 2016-04-21 11:30:30,706 [myid:2] - INFO [main:QuorumPeer@1019] - tickTime > set to 2000 > 2016-04-21 11:30:30,706 [myid:2] - INFO [main:QuorumPeer@1039] - > minSessionTimeout set to -1 > 2016-04-21 11:30:30,706 [myid:2] - INFO [main:QuorumPeer@1050] - > maxSessionTimeout set to -1 > 2016-04-21 11:30:30,707 [myid:2] - INFO [main:QuorumPeer@1065] - initLimit > set to 10 > 2016-04-21 11:30:30,731 [myid:2] - INFO [main:FileSnap@83] - Reading > snapshot /opt/zookeeper/data/version-2/snapshot.0 > 2016-04-21 11:30:30,742 [myid:2] - INFO > [ListenerThread:QuorumCnxManager$Listener@534] - My election bind port: > /192.168.1.3:3888 > 2016-04-21 11:30:30,756 [myid:2] - INFO > [QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:QuorumPeer@774] - LOOKING > 2016-04-21 11:30:30,758 [myid:2] - INFO > [QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:FastLeaderElection@818] - New > election. My id = 2, proposed zxid=0x0 > d), 0x1 (n.round), LOOKING (n.state), 2 (n.sid), 0x2 (n.peerEpoch) LOOKING > (my state) > 0 (n.zxid), 0x1 (n.round), LOOKING (n.state), 1 (n.sid), 0x2 (n.peerEpoch) > LOOKING (my state) > 2016-04-21 11:30:30,768 [myid:2] - INFO > [WorkerSender[myid=2]:QuorumCnxManager@199] - Have smaller server identifier, > so dropping the connection: (3, 2) > 0 (n.zxid), 0x1 (n.round), LOOKING (n.state), 2 (n.sid), 0x2 (n.peerEpoch) > LOOKING (my state) > 2016-04-21 11:30:30,771 [myid:2] - INFO > [/192.168.1.3:3888:QuorumCnxManager$Listener@541] - Received connection > request /192.168.1.4:35199 > 2016-04-21 11:30:30,772 [myid:2] - INFO > [WorkerSender[myid=2]:QuorumCnxManager@199] - Have smaller server identifier, > so dropping the connection: (3, 2) > d), 0x1 (n.round), LOOKING (n.state), 3 (n.sid), 0x1 (n.peerEpoch) LOOKING > (my state) > 2016-04-21 11:30:30,777 [myid:2] - INFO > [/192.168.1.3:3888:QuorumCnxManager$Listener@541] - Received connection > request /192.168.1.4:35200 > 2016-04-21 11:30:30,779 [myid:2] - WARN > [RecvWorker:3:QuorumCnxManager$RecvWorker@810] - Connection broken for id 3, > my id = 2, error = > java.net.SocketException: Socket closed > at java.net.SocketInputStream.read(SocketInputStream.java:190) > at java.net.SocketInputStream.read(SocketInputStream.java:122) > at java.net.SocketInputStream.read(SocketInputStream.java:210) > at java.io.DataInputStream.readInt(DataInputStream.java:387) > at > org.apache.zookeeper.server.quorum.QuorumCnxManager$RecvWorker.run(QuorumCnxManager.java:795) > d), 0x1 (n.round), FOLLOWING (n.state), 1 (n.sid), 0x2 (n.peerEpoch) LOOKING > (my state) > 2016-04-21 11:30:30,783 [myid:2] - WARN > [SendWorker:3:QuorumCnxManager$SendWorker@727] - Interrupted while waiting > for message on queue > java.lang.InterruptedException > at > java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.reportInterruptAfterWait(AbstractQueuedSynchronizer.java:2017) > at > java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2095) > at java.util.concurrent.ArrayBlockingQueue.poll(ArrayBlockingQueue.java:389) > at > org.apache.zookeeper.server.quorum.QuorumCnxManager.pollSendQueue(QuorumCnxManager.java:879) > at > org.apache.zookeeper.server.quorum.QuorumCnxManager.access$500(QuorumCnxManager.java:65) > at > org.apache.zookeeper.server.quorum.QuorumCnxManager$SendWorker.run(QuorumCnxManager.java:715) > 2016-04-21 11:30:30,784 [myid:2] - WARN > [SendWorker:3:QuorumCnxManager$SendWorker@736] - Send worker leaving thread > 2016-04-21 11:30:30,783 [myid:2] - WARN > [RecvWorker:3:QuorumCnxManager$RecvWorker@813] - Interrupting SendWorker > d), 0x1 (n.round), FOLLOWING (n.state), 1 (n.sid), 0x2 (n.peerEpoch) LOOKING > (my state) > d), 0x1 (n.round), LEADING (n.state), 3 (n.sid), 0x2 (n.peerEpoch) LOOKING > (my state) > d), 0x1 (n.round), LEADING (n.state), 3 (n.sid), 0x2 (n.peerEpoch) LOOKING > (my state) > 2016-04-21 11:30:30,993 [myid:2] - INFO > [QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:QuorumPeer@844] - FOLLOWING > 2016-04-21 11:30:31,000 [myid:2] - INFO > [QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:Learner@86] - TCP NoDelay set to: > true > 02/06/2016 03:18 GMT > 2016-04-21 11:30:31,012 [myid:2] - INFO > [QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server > environment:host.name=slave1 > 2016-04-21 11:30:31,013 [myid:2] - INFO > [QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server > environment:java.version=1.7.0_75 > 2016-04-21 11:30:31,013 [myid:2] - INFO > [QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server > environment:java.vendor=Oracle Corporation > njdk-1.7.0.75-2.5.4.2.el7_0.x86_64/jre > lib > lib/amd64:/usr/lib64:/lib64:/lib:/usr/lib > 2016-04-21 11:30:31,014 [myid:2] - INFO > [QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server > environment:java.io.tmpdir=/tmp > 2016-04-21 11:30:31,014 [myid:2] - INFO > [QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server > environment:java.compiler=<NA> > 2016-04-21 11:30:31,014 [myid:2] - INFO > [QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server > environment:os.name=Linux > 2016-04-21 11:30:31,014 [myid:2] - INFO > [QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server > environment:os.arch=amd64 > 2016-04-21 11:30:31,014 [myid:2] - INFO > [QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server > environment:os.version=3.10.0-229.el7.x86_64 > 2016-04-21 11:30:31,014 [myid:2] - INFO > [QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server > environment:user.name=hadoop > 2016-04-21 11:30:31,015 [myid:2] - INFO > [QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server > environment:user.home=/home/hadoop > 2016-04-21 11:30:31,015 [myid:2] - INFO > [QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server > environment:user.dir=/home/hadoop > 4000 maxSessionTimeout 40000 datadir /opt/zookeeper/log/version-2 snapdir > /opt/zookeeper/data/version-2 > 2016-04-21 11:30:31,019 [myid:2] - INFO > [QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:Follower@63] - FOLLOWING - LEADER > ELECTION TOOK - 261 > 192.168.1.2 > 87 > java.net.ConnectException: Connection refused > at java.net.PlainSocketImpl.socketConnect(Native Method) > at > java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:339) > at > java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:200) > at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:182) > at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392) > at java.net.Socket.connect(Socket.java:579) > at > org.apache.zookeeper.server.quorum.Learner.connectToLeader(Learner.java:228) > at org.apache.zookeeper.server.quorum.Follower.followLeader(Follower.java:71) > at org.apache.zookeeper.server.quorum.QuorumPeer.run(QuorumPeer.java:846) > 87 > java.net.ConnectException: Connection refused > at java.net.PlainSocketImpl.socketConnect(Native Method) > at > java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:339) > at > java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:200) > at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:182) > at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392) > at java.net.Socket.connect(Socket.java:579) > at > org.apache.zookeeper.server.quorum.Learner.connectToLeader(Learner.java:228) > at org.apache.zookeeper.server.quorum.Follower.followLeader(Follower.java:71) > at org.apache.zookeeper.server.quorum.QuorumPeer.run(QuorumPeer.java:846)\ > > > > > slave2's zookeeper.out: > 2016-04-21 11:06:42,294 [myid:] - INFO [main:QuorumPeerConfig@103] - Reading > configuration from: /opt/zookeeper/bin/../conf/zoo.cfg > 2016-04-21 11:06:42,752 [myid:] - INFO [main:QuorumPeer$QuorumServer@149] - > Resolved hostname: 192.168.1.4 to address: /192.168.1.4 > 2016-04-21 11:06:42,753 [myid:] - INFO [main:QuorumPeer$QuorumServer@149] - > Resolved hostname: 192.168.1.3 to address: /192.168.1.3 > 2016-04-21 11:06:42,754 [myid:] - INFO [main:QuorumPeer$QuorumServer@149] - > Resolved hostname: 192.168.1.2 to address: /192.168.1.2 > 2016-04-21 11:06:42,755 [myid:] - INFO [main:QuorumPeerConfig@331] - > Defaulting to majority quorums > 2016-04-21 11:06:42,768 [myid:3] - INFO [main:DatadirCleanupManager@78] - > autopurge.snapRetainCount set to 3 > 2016-04-21 11:06:42,768 [myid:3] - INFO [main:DatadirCleanupManager@79] - > autopurge.purgeInterval set to 0 > 2016-04-21 11:06:42,768 [myid:3] - INFO [main:DatadirCleanupManager@101] - > Purge task is not scheduled. > 2016-04-21 11:06:42,808 [myid:3] - INFO [main:QuorumPeerMain@127] - Starting > quorum peer > 2016-04-21 11:06:42,832 [myid:3] - INFO [main:NIOServerCnxnFactory@89] - > binding to port 0.0.0.0/0.0.0.0:2181 > 2016-04-21 11:06:42,847 [myid:3] - INFO [main:QuorumPeer@1019] - tickTime > set to 2000 > 2016-04-21 11:06:42,847 [myid:3] - INFO [main:QuorumPeer@1039] - > minSessionTimeout set to -1 > 2016-04-21 11:06:42,847 [myid:3] - INFO [main:QuorumPeer@1050] - > maxSessionTimeout set to -1 > 2016-04-21 11:06:42,847 [myid:3] - INFO [main:QuorumPeer@1065] - initLimit > set to 10 > 2016-04-21 11:06:42,971 [myid:3] - INFO > [ListenerThread:QuorumCnxManager$Listener@534] - My election bind port: > /192.168.1.4:3889 > 2016-04-21 11:06:43,001 [myid:3] - INFO > [QuorumPeer[myid=3]/0:0:0:0:0:0:0:0:2181:QuorumPeer@774] - LOOKING > 2016-04-21 11:06:43,011 [myid:3] - INFO > [QuorumPeer[myid=3]/0:0:0:0:0:0:0:0:2181:FastLeaderElection@818] - New > election. My id = 3, proposed zxid=0x0 > 2016-04-21 11:06:43,161 [myid:3] - WARN > [WorkerSender[myid=3]:QuorumCnxManager@400] - Cannot open channel to 2 at > election address /192.168.1.3:3888 > java.net.ConnectException: Connection refused > at java.net.PlainSocketImpl.socketConnect(Native Method) > at > java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:339) > at > java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:200) > at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:182) > at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392) > at java.net.Socket.connect(Socket.java:579) > at > org.apache.zookeeper.server.quorum.QuorumCnxManager.connectOne(QuorumCnxManager.java:381) > at > org.apache.zookeeper.server.quorum.QuorumCnxManager.toSend(QuorumCnxManager.java:354) > at > org.apache.zookeeper.server.quorum.FastLeaderElection$Messenger$WorkerSender.process(FastLeaderElection.java:452) > at > org.apache.zookeeper.server.quorum.FastLeaderElection$Messenger$WorkerSender.run(FastLeaderElection.java:433) > at java.lang.Thread.run(Thread.java:745) > 2016-04-21 11:06:43,165 [myid:3] - INFO > [WorkerSender[myid=3]:QuorumPeer$QuorumServer@149] - Resolved hostname: > 192.168.1.3 to address: /192.168.1.3 > 2016-04-21 11:06:43,167 [myid:3] - INFO > [WorkerReceiver[myid=3]:FastLeaderElection@600] - Notification: 1 (message > format version), 3 (n.leader), 0x0 (n.zxid), 0x1 (n.round), LOOKING > (n.state), 3 (n.sid), 0x1 (n.peerEpoch) LOOKING (my state) > 2016-04-21 11:06:43,192 [myid:3] - INFO > [WorkerReceiver[myid=3]:FastLeaderElection@600] - Notification: 1 (message > format version), 1 (n.leader), 0x0 (n.zxid), 0x1 (n.round), LOOKING > (n.state), 1 (n.sid), 0x1 (n.peerEpoch) LOOKING (my state) > 2016-04-21 11:06:43,197 [myid:3] - INFO > [WorkerReceiver[myid=3]:FastLeaderElection@600] - Notification: 1 (message > format version), 3 (n.leader), 0x0 (n.zxid), 0x1 (n.round), LOOKING > (n.state), 1 (n.sid), 0x1 (n.peerEpoch) LOOKING (my state) > 2016-04-21 11:06:43,282 [myid:3] - INFO > [/192.168.1.4:3889:QuorumCnxManager$Listener@541] - Received connection > request /192.168.1.3:38903 > 2016-04-21 11:06:43,286 [myid:3] - INFO > [/192.168.1.4:3889:QuorumCnxManager$Listener@541] - Received connection > request /192.168.1.3:38904 > 2016-04-21 11:06:43,287 [myid:3] - WARN > [RecvWorker:2:QuorumCnxManager$RecvWorker@810] - Connection broken for id 2, > my id = 3, error = > java.net.SocketException: Socket closed > 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.net.SocketInputStream.read(SocketInputStream.java:210) > at java.io.DataInputStream.readInt(DataInputStream.java:387) > at > org.apache.zookeeper.server.quorum.QuorumCnxManager$RecvWorker.run(QuorumCnxManager.java:795) > 2016-04-21 11:06:43,288 [myid:3] - WARN > [SendWorker:2:QuorumCnxManager$SendWorker@727] - Interrupted while waiting > for message on queue > java.lang.InterruptedException > at > java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.reportInterruptAfterWait(AbstractQueuedSynchronizer.java:2017) > at > java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2095) > at java.util.concurrent.ArrayBlockingQueue.poll(ArrayBlockingQueue.java:389) > at > org.apache.zookeeper.server.quorum.QuorumCnxManager.pollSendQueue(QuorumCnxManager.java:879) > at > org.apache.zookeeper.server.quorum.QuorumCnxManager.access$500(QuorumCnxManager.java:65) > at > org.apache.zookeeper.server.quorum.QuorumCnxManager$SendWorker.run(QuorumCnxManager.java:715) > 2016-04-21 11:06:43,288 [myid:3] - WARN > [RecvWorker:2:QuorumCnxManager$RecvWorker@813] - Interrupting SendWorker > 2016-04-21 11:06:43,289 [myid:3] - WARN > [SendWorker:2:QuorumCnxManager$SendWorker@736] - Send worker leaving thread > 2016-04-21 11:06:43,301 [myid:3] - INFO > [WorkerReceiver[myid=3]:FastLeaderElection@600] - Notification: 1 (message > format version), 3 (n.leader), 0x0 (n.zxid), 0x1 (n.round), LOOKING > (n.state), 2 (n.sid), 0x1 (n.peerEpoch) LOOKING (my state) > 2016-04-21 11:06:43,505 [myid:3] - INFO > [QuorumPeer[myid=3]/0:0:0:0:0:0:0:0:2181:QuorumPeer@856] - LEADING > 2016-04-21 11:06:43,510 [myid:3] - INFO > [QuorumPeer[myid=3]/0:0:0:0:0:0:0:0:2181:Leader@59] - TCP NoDelay set to: true > 2016-04-21 11:06:43,543 [myid:3] - INFO > [QuorumPeer[myid=3]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server > environment:zookeeper.version=3.4.8--1, built on 02/06/2016 03:18 GMT > 2016-04-21 11:06:43,543 [myid:3] - INFO > [QuorumPeer[myid=3]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server > environment:host.name=slave2 > 2016-04-21 11:06:43,572 [myid:3] - INFO > [QuorumPeer[myid=3]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server > environment:java.version=1.7.0_75 > 2016-04-21 11:06:43,573 [myid:3] - INFO > [QuorumPeer[myid=3]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server > environment:java.vendor=Oracle Corporation > 2016-04-21 11:06:43,573 [myid:3] - INFO > [QuorumPeer[myid=3]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server > environment:java.home=/usr/lib/jvm/java-1.7.0-openjdk-1.7.0.75-2.5.4.2.el7_0.x86_64/jre > 2016-04-21 11:06:43,573 [myid:3] - INFO > [QuorumPeer[myid=3]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server > environment:java.class.path=/opt/zookeeper/bin/../build/classes:/opt/zookeeper/bin/../build/lib/*.jar:/opt/zookeeper/bin/../lib/slf4j-log4j12-1.6.1.jar:/opt/zookeeper/bin/../lib/slf4j-api-1.6.1.jar:/opt/zookeeper/bin/../lib/netty-3.7.0.Final.jar:/opt/zookeeper/bin/../lib/log4j-1.2.16.jar:/opt/zookeeper/bin/../lib/jline-0.9.94.jar:/opt/zookeeper/bin/../zookeeper-3.4.8.jar:/opt/zookeeper/bin/../src/java/lib/*.jar:/opt/zookeeper/bin/../conf:/opt/zookeeper/bin/../build/classes:/opt/zookeeper/bin/../build/lib/*.jar:/opt/zookeeper/bin/../lib/slf4j-log4j12-1.6.1.jar:/opt/zookeeper/bin/../lib/slf4j-api-1.6.1.jar:/opt/zookeeper/bin/../lib/netty-3.7.0.Final.jar:/opt/zookeeper/bin/../lib/log4j-1.2.16.jar:/opt/zookeeper/bin/../lib/jline-0.9.94.jar:/opt/zookeeper/bin/../zookeeper-3.4.8.jar:/opt/zookeeper/bin/../src/java/lib/*.jar:/opt/zookeeper/bin/../conf:.::/usr/lib/jvm/java-1.7.0-openjdk-1.7.0.75-2.5.4.2.el7_0.x86_64/lib:/usr/lib/jvm/java-1.7.0-openjdk-1.7.0.75-2.5.4.2.el7_0.x86_64/jre/lib > 2016-04-21 11:06:43,573 [myid:3] - INFO > [QuorumPeer[myid=3]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server > environment:java.library.path=/usr/java/packages/lib/amd64:/usr/lib64:/lib64:/lib:/usr/lib > 2016-04-21 11:06:43,574 [myid:3] - INFO > [QuorumPeer[myid=3]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server > environment:java.io.tmpdir=/tmp > 2016-04-21 11:06:43,574 [myid:3] - INFO > [QuorumPeer[myid=3]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server > environment:java.compiler=<NA> > 2016-04-21 11:06:43,574 [myid:3] - INFO > [QuorumPeer[myid=3]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server > environment:os.name=Linux > 2016-04-21 11:06:43,574 [myid:3] - INFO > [QuorumPeer[myid=3]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server > environment:os.arch=amd64 > 2016-04-21 11:06:43,574 [myid:3] - INFO > [QuorumPeer[myid=3]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server > environment:os.version=3.10.0-229.el7.x86_64 > 2016-04-21 11:06:43,575 [myid:3] - INFO > [QuorumPeer[myid=3]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server > environment:user.name=hadoop > 2016-04-21 11:06:43,575 [myid:3] - INFO > [QuorumPeer[myid=3]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server > environment:user.home=/home/hadoop > 2016-04-21 11:06:43,575 [myid:3] - INFO > [QuorumPeer[myid=3]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server > environment:user.dir=/home/hadoop > 2016-04-21 11:06:43,580 [myid:3] - INFO > [QuorumPeer[myid=3]/0:0:0:0:0:0:0:0:2181:ZooKeeperServer@170] - Created > server with tickTime 2000 minSessionTimeout 4000 maxSessionTimeout 40000 > datadir /opt/zookeeper/log/version-2 snapdir /opt/zookeeper/data/version-2 > 2016-04-21 11:06:43,582 [myid:3] - INFO > [QuorumPeer[myid=3]/0:0:0:0:0:0:0:0:2181:Leader@361] - LEADING - LEADER > ELECTION TOOK - 571 > 2016-04-21 11:06:44,568 [myid:3] - INFO > [LearnerHandler-/192.168.1.2:35258:LearnerHandler@329] - Follower sid: 1 : > info : org.apache.zookeeper.server.quorum.QuorumPeer$QuorumServer@4a7baf7d > 2016-04-21 11:06:44,595 [myid:3] - INFO > [LearnerHandler-/192.168.1.2:35258:LearnerHandler@384] - Synchronizing with > Follower sid: 1 maxCommittedLog=0x0 minCommittedLog=0x0 peerLastZxid=0x0 > 2016-04-21 11:06:44,596 [myid:3] - INFO > [LearnerHandler-/192.168.1.2:35258:LearnerHandler@393] - leader and follower > are in sync, zxid=0x0 > 2016-04-21 11:06:44,596 [myid:3] - INFO > [LearnerHandler-/192.168.1.2:35258:LearnerHandler@458] - Sending DIFF > 2016-04-21 11:06:44,615 [myid:3] - INFO > [LearnerHandler-/192.168.1.2:35258:LearnerHandler@518] - Received > NEWLEADER-ACK message from 1 > 2016-04-21 11:06:44,619 [myid:3] - INFO > [QuorumPeer[myid=3]/0:0:0:0:0:0:0:0:2181:Leader@946] - Have quorum of > supporters, sids: [ 1,3 ]; starting up and setting last processed zxid: > 0x200000000 > 2016-04-21 11:06:44,622 [myid:3] - INFO > [LearnerHandler-/192.168.1.3:54214:LearnerHandler@329] - Follower sid: 2 : > info : org.apache.zookeeper.server.quorum.QuorumPeer$QuorumServer@72e042cb > 2016-04-21 11:06:44,633 [myid:3] - INFO > [LearnerHandler-/192.168.1.3:54214:LearnerHandler@384] - Synchronizing with > Follower sid: 2 maxCommittedLog=0x0 minCommittedLog=0x0 peerLastZxid=0x0 > 2016-04-21 11:06:44,633 [myid:3] - INFO > [LearnerHandler-/192.168.1.3:54214:LearnerHandler@393] - leader and follower > are in sync, zxid=0x0 > 2016-04-21 11:06:44,634 [myid:3] - INFO > [LearnerHandler-/192.168.1.3:54214:LearnerHandler@458] - Sending DIFF > 2016-04-21 11:06:44,705 [myid:3] - INFO > [LearnerHandler-/192.168.1.3:54214:LearnerHandler@518] - Received > NEWLEADER-ACK message from 2 > 2016-04-21 11:07:45,832 [myid:3] - ERROR > [LearnerHandler-/192.168.1.2:35258:LearnerHandler@631] - Unexpected exception > causing shutdown while sock still open > java.io.EOFException > at java.io.DataInputStream.readInt(DataInputStream.java:392) > 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) > 2016-04-21 11:07:45,834 [myid:3] - WARN > [LearnerHandler-/192.168.1.2:35258:LearnerHandler@644] - ******* GOODBYE > /192.168.1.2:35258 ******** > 2016-04-21 11:07:45,874 [myid:3] - WARN > [RecvWorker:1:QuorumCnxManager$RecvWorker@810] - Connection broken for id 1, > my id = 3, error = > java.io.EOFException > at java.io.DataInputStream.readInt(DataInputStream.java:392) > at > org.apache.zookeeper.server.quorum.QuorumCnxManager$RecvWorker.run(QuorumCnxManager.java:795) > 2016-04-21 11:07:45,876 [myid:3] - WARN > [RecvWorker:1:QuorumCnxManager$RecvWorker@813] - Interrupting SendWorker > 2016-04-21 11:07:45,888 [myid:3] - WARN > [SendWorker:1:QuorumCnxManager$SendWorker@727] - Interrupted while waiting > for message on queue > java.lang.InterruptedException > at > java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.reportInterruptAfterWait(AbstractQueuedSynchronizer.java:2017) > at > java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2095) > at java.util.concurrent.ArrayBlockingQueue.poll(ArrayBlockingQueue.java:389) > at > org.apache.zookeeper.server.quorum.QuorumCnxManager.pollSendQueue(QuorumCnxManager.java:879) > at > org.apache.zookeeper.server.quorum.QuorumCnxManager.access$500(QuorumCnxManager.java:65) > at > org.apache.zookeeper.server.quorum.QuorumCnxManager$SendWorker.run(QuorumCnxManager.java:715) > 2016-04-21 11:07:45,889 [myid:3] - WARN > [SendWorker:1:QuorumCnxManager$SendWorker@736] - Send worker leaving thread > 2016-04-21 11:07:58,881 [myid:3] - INFO > [/192.168.1.4:3889:QuorumCnxManager$Listener@541] - Received connection > request /192.168.1.2:51099 > 2016-04-21 11:07:58,915 [myid:3] - INFO > [WorkerReceiver[myid=3]:FastLeaderElection@600] - Notification: 1 (message > format version), 1 (n.leader), 0x0 (n.zxid), 0x1 (n.round), LOOKING > (n.state), 1 (n.sid), 0x2 (n.peerEpoch) LEADING (my state) > 2016-04-21 11:07:59,150 [myid:3] - INFO > [LearnerHandler-/192.168.1.2:35263:LearnerHandler@329] - Follower sid: 1 : > info : org.apache.zookeeper.server.quorum.QuorumPeer$QuorumServer@4a7baf7d > 2016-04-21 11:07:59,155 [myid:3] - INFO > [LearnerHandler-/192.168.1.2:35263:LearnerHandler@384] - Synchronizing with > Follower sid: 1 maxCommittedLog=0x0 minCommittedLog=0x0 peerLastZxid=0x0 > 2016-04-21 11:07:59,155 [myid:3] - INFO > [LearnerHandler-/192.168.1.2:35263:LearnerHandler@458] - Sending SNAP > 2016-04-21 11:07:59,156 [myid:3] - INFO > [LearnerHandler-/192.168.1.2:35263:LearnerHandler@482] - Sending snapshot > last zxid of peer is 0x0 zxid of leader is 0x200000000sent zxid of db as > 0x200000000 > 2016-04-21 11:07:59,212 [myid:3] - INFO > [LearnerHandler-/192.168.1.2:35263:LearnerHandler@518] - Received > NEWLEADER-ACK message from 1 > > > Eric Gao > Keep on going never give up. > Blog: > http://gaoqiang.blog.chinaunix.net/ > http://gaoqiangdba.blog.163.com/ > > > > From: Camille Fournier > Date: 2016-04-22 10:25 > To: [email protected] > Subject: Re: Zookeeper is unable to start > Your attachments won't come through. Can you look at the log files and copy > some of the last log lines into email? > > > On Thu, Apr 21, 2016 at 10:23 PM, Eric Gao <[email protected]> wrote: > >> Dear exports, >> I have encountered a problem when I have started the zookeeper: >> >> [root@master data]# /opt/zookeeper/bin/zkServer.sh start >> ZooKeeper JMX enabled by default >> Using config: /opt/zookeeper/bin/../conf/zoo.cfg >> Starting zookeeper ... date >> STARTED >> >> [root@master ~]# /opt/zookeeper/bin/zkServer.sh status >> ZooKeeper JMX enabled by default >> Using config: /opt/zookeeper/bin/../conf/zoo.cfg >> Error contacting service. It is probably not running. >> >> All the 3 servers have the same status. >> >> >> Here is the configuration information: >> >> zoo.cfg: >> tickTime=2000 >> initLimit=10 >> syncLimit=5 >> clientPort=2181 >> server.1=192.168.1.2:2887:3887 >> server.2=192.168.1.3:2888:3888 >> server.3=192.168.1.4:2889:3889 >> dataDir=/opt/zookeeper/data >> dataLogDir=/opt/zookeeper/log >> >> >> And the 3 servers' zookeeper.out are put in attachment files. >> >> Thanks for your attention. >> >> >> ------------------------------ >> *Eric Gao* >> Keep on going never give up. >> *Blog:* >> http://gaoqiang.blog.chinaunix.net/ >> http://gaoqiangdba.blog.163.com/ >> >> >>
