I'm not sure about the ports, but the configuration is below. Firewall is
turned off, this shouldn't be a problem.
Configuration file for zk1:
dataDir=/opt/zookeeper/zk_server_{1,2,3}
clientPort=1400{1,2,3}
maxClientCnxns=0
tickTime=2000
initLimit=5
syncLimit=2
server.1=10.54.1.51:12001:13001
server.2=10.54.1.52:12001:13001
server.3=10.54.1.53:12001:13001
autopurge.snapRetainCount=3
autopurge.purgeInterval=1
dataLogDir=/opt/zookeeper/zk_log_{1,2,3}
{1,2,3} means different values for instances: 1 for zk1, 2 for zk2 and 3
for zk3.
10.54.1.{51,52,53} are IP addresses on local interfaces, can be pinged from
any machine(problem is observed on one single machine indeed).
Increasing initLimit results with no success.
Also changing election and quorum port results with fail
(
...
server.1=10.54.1.51:12001:13001
server.2=10.54.1.52:12002:13002
server.3=10.54.1.53:12003:13003
...
)
Scenario is:
>>> zk1(follower)
>>> zk2(leader)
>>> zk3(follower)
>>>
>>> step 1. stop zk1
>>> step 2. stop zk2
>>> step 3. start zk1
>>>
>>> result:
>>> zk1 and zk3 cannot create a cluster of 2 zk instances
I found in a log that follower logs another time for leader election than
new leader (log is attached):
step 3. start of zk1:
[2016-10-20 04:03:34,627] INFO Reading configuration from:
/opt/kafka/config/zookeeper.properties.1
(org.apache.zookeeper.server.quorum.QuorumPeerConfig)
after around 10 seconds(!) follower logs time of leader election
[2016-10-20 04:03:44,991] INFO FOLLOWING - LEADER ELECTION TOOK - 10255
(org.apache.zookeeper.server.quorum.Learner)
Then follower tries to connect to leader on quorum server communication
port(12001):
[2016-10-20 04:03:44,996] WARN Unexpected exception, tries=0, connecting to
/10.54.1.53:12001 (org.apache.zookeeper.server.quorum.Learner)
java.net.ConnectException: Connection refused
After 4 tries(0,1,2,3) follower is shutdown:
[2016-10-20 04:03:49,002] INFO shutdown called
(org.apache.zookeeper.server.quorum.Learner)
java.lang.Exception: shutdown Follower
Then leader seems to resolve the election:
[2016-10-20 04:03:49,764] INFO LEADING - LEADER ELECTION TOOK - 39709
(org.apache.zookeeper.server.quorum.Leader)
And starts listening on server communication port(12001).
There are many logs informing that communication to zk2 fails (10.54.1.52).
This is correct as this instance is not active.
Before starting zk1 communication to zk1 fails ([2016-10-20 04:03:30,070]).
This is correct as this instance is not yet active.
In correct scenario information LEADER ELECTION TOOK for leader is near the
log for the follower(a part of another log):
[2016-10-20 02:48:47,675] INFO FOLLOWING - LEADER ELECTION TOOK - 15283
(org.apache.zookeeper.server.quorum.Learner)
[2016-10-20 02:48:47,690] INFO LEADING - LEADER ELECTION TOOK - 174954
(org.apache.zookeeper.server.quorum.Leader)
regards,
Krzysztof
On Tue, Oct 25, 2016 at 8:15 PM, Flavio Junqueira <[email protected]> wrote:
> There are two potential reasons I can think of:
>
> 1- The configuration is incorrect and it is pointing to the wrong port.
> Keep in mind that the election port is different from the quorum server
> communication port.
> 2- There is something block traffic on the configured port between those
> two servers.
>
> Could it be any of these?
>
> -Flavio
>
> > On 25 Oct 2016, at 14:33, Krzysztof Rybak <krzysztof.rybak@
> motorolasolutions.com> wrote:
> >
> > Hi,
> > first log is a little misleading as epoch exception is observed later in
> a
> > log and may be a consequence of lack of connection.
> > The first exception observed in failing scenario is:
> >
> > [2016-10-25 07:48:41,107] WARN Unexpected exception, tries=0, connecting
> to
> > /10.54.1.53:12001 (org.apache.zookeeper.server.quorum.Learner)
> > java.net.ConnectException: Connection refused
> > at java.net.PlainSocketImpl.socketConnect(Native Method)
> > at
> > java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:
> 350)
> > at
> > java.net.AbstractPlainSocketImpl.connectToAddress(
> AbstractPlainSocketImpl.java:206)
> > at
> > java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:
> 188)
> > at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)
> > at java.net.Socket.connect(Socket.java:589)
> > at
> > org.apache.zookeeper.server.quorum.Learner.connectToLeader(Learner.java:
> 225)
> > at
> > org.apache.zookeeper.server.quorum.Follower.followLeader(
> Follower.java:71)
> > at
> > org.apache.zookeeper.server.quorum.QuorumPeer.run(QuorumPeer.java:786)
> >
> > I think that instances are able to elect a Leader(zookeeper instance on
> > address 10.54.1.53, leader port 12001-2888 in zookeeper examples) as such
> > information is logged before exception:
> >
> > [2016-10-25 07:48:41,103] INFO FOLLOWING - LEADER ELECTION TOOK - 10249
> > (org.apache.zookeeper.server.quorum.Learner)
> > Then follower tries to connect to leader but this fails.
> >
> > - If a leader is being elected but the leader isn't being able to sync
> and
> > establish itself, then you need to determine the reason. Is the follower
> > being able to connect to the leader? Is the initialization taking too
> long
> > such that it times out? Is the socket read timing out?
> >
> > This seems to be an issue that follower cannot connect to a leader on
> > leader port (12001 in my case).
> > Exception is related to connect() method:
> >
> > at
> > org.apache.zookeeper.server.quorum.Learner.connectToLeader(Learner.java:
> 225)
> >
> > and the exception is
> >
> > java.net.ConnectException: Connection refused
> >
> > Follower tries to connect just after the leader stops listening on a
> leader
> > port (12001 in my case, 2888 in zookeeper examples).
> > I just don't know why follower starts trying to connect after around 10
> > seconds after setting a new leader(during this 10 seconds leader listens
> on
> > a leader port). There is no timeout in socket connect as leader has
> already
> > stopped listening.
> > This seems to be a reason, but why this happens ?
> >
> > I assume this scenario is supported and server should be set.
> >
> >> [2016-10-20 04:04:19,996] WARN Unexpected exception, tries=0, connecting
> > to
> >> /10.54.1.53:12001 (org.apache.zookeeper.server.quorum.Learner)
> >> java.net.ConnectException: Connection refused
> >> at java.net.PlainSocketImpl.socketConnect(Native Method)
> >> at
> >> java.net.AbstractPlainSocketImpl.doConnect(
> AbstractPlainSocketImpl.java:
> > 350)
> >> at
> >> java.net.AbstractPlainSocketImpl.connectToAddress(
> > AbstractPlainSocketImpl.java:206)
> >> at
> >> java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:
> 188)
> >> at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)
> >> at java.net.Socket.connect(Socket.java:589)
> >> at
> >> org.apache.zookeeper.server.quorum.Learner.
> connectToLeader(Learner.java:
> > 225)
> >> at
> >> org.apache.zookeeper.server.quorum.Follower.followLeader(
> Follower.java:71)
> >> at org.apache.zookeeper.server.quorum.QuorumPeer.run(
> QuorumPeer.java:786)
> >
> >
> >
> > On Mon, Oct 24, 2016 at 6:57 PM, Flavio Junqueira <[email protected]>
> wrote:
> >
> >> Hi Krzysztof,
> >>
> >> Your first message seems to indicate that a leader is being elected, but
> >> it is not being able to sync with enough followers (in your case 1
> >> follower). I'm saying this because of this line:
> >>
> >>> at org.apache.zookeeper.server.quorum.Leader.lead(Leader.java:377)
> >>
> >> You say that the issue is timing in your second message, but it isn't
> >> entirely clear to me why you think so. I think you need to determine the
> >> following:
> >>
> >> - Are the two remaining servers being able to elect a leader among them?
> >> If not, is the problem that they can't connect to each other?
> >> - If a leader is being elected but the leader isn't being able to sync
> and
> >> establish itself, then you need to determine the reason. Is the follower
> >> being able to connect to the leader? Is the initialization taking too
> long
> >> such that it times out? Is the socket read timing out?
> >>
> >> -Flavio
> >>
> >>
> >>> On 24 Oct 2016, at 11:37, Krzysztof Rybak <krzysztof.rybak@
> >> motorolasolutions.com> wrote:
> >>>
> >>> Hi,
> >>> I've logged some more information and the problem seems to be a timing
> >>> issue.
> >>> Long story short, the scenario is:
> >>> zk1(follower)
> >>> zk2(leader)
> >>> zk3(follower)
> >>>
> >>> step 1. stop zk1
> >>> step 2. stop zk2
> >>> step 3. start zk1
> >>>
> >>> result:
> >>> zk1 and zk3 cannot create a cluster of 2 zk instances(is such scenario
> >>> supported by zookeeper?).
> >>> When zk2 is started again instead of zk1, cluster is created.
> >>>
> >>> Observation:
> >>> After step 3., zk3 is elected to be a leader and starts listening on
> port
> >>> 2888
> >>> ( example port from example
> >>> http://zookeeper.apache.org/doc/trunk/zookeeperStarted.html ).
> Listening
> >>> takes around 10 seconds but during this time zk1 is not trying to
> >> connect.
> >>> zk1 tries to connect just after zk3 stops listening.
> >>>
> >>> a part of a log is:
> >>> zk3 stops listening on 04:04:17(testing with netstat) and zk1 starts
> >> trying
> >>> to connect at 04:04:19,996 as below.
> >>>
> >>> [2016-10-20 04:04:19,996] WARN Unexpected exception, tries=0,
> connecting
> >> to
> >>> /10.54.1.53:12001 (org.apache.zookeeper.server.quorum.Learner)
> >>> java.net.ConnectException: Connection refused
> >>> at java.net.PlainSocketImpl.socketConnect(Native Method)
> >>> at
> >>> java.net.AbstractPlainSocketImpl.doConnect(
> AbstractPlainSocketImpl.java:
> >> 350)
> >>> at
> >>> java.net.AbstractPlainSocketImpl.connectToAddress(
> >> AbstractPlainSocketImpl.java:206)
> >>> at
> >>> java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:
> >> 188)
> >>> at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)
> >>> at java.net.Socket.connect(Socket.java:589)
> >>> at
> >>> org.apache.zookeeper.server.quorum.Learner.
> connectToLeader(Learner.java:
> >> 225)
> >>> at
> >>> org.apache.zookeeper.server.quorum.Follower.followLeader(
> >> Follower.java:71)
> >>> at org.apache.zookeeper.server.quorum.QuorumPeer.run(
> >> QuorumPeer.java:786)
> >>>
> >>> This is strange as I couldn't reproduce this on local VM VirtualBox but
> >> on
> >>> VMware reproduction is 100%.
> >>>
> >>> thanks,
> >>> Krzysztof
> >>>
> >>> ---------- Forwarded message ----------
> >>> From: Krzysztof Rybak <[email protected]>
> >>> Date: Thu, Oct 20, 2016 at 4:50 PM
> >>> Subject: Zookeeper exception: Timeout while waiting for epoch from
> quorum
> >>> To: [email protected]
> >>>
> >>>
> >>> Hi All,
> >>> first mail in the group so sorry for possible inconsistency in advance.
> >>> Zookeeper version is zookeeper-3.4.6.
> >>>
> >>> I'm facing a problem when zookeeper is reconfiguring a cluster.
> >>>
> >>> Initial state:
> >>> machine A:
> >>> zk1(follower)
> >>> zk2(leader)
> >>> machine B:
> >>> zk3(follower)
> >>>
> >>> zk1 and zk2 are stopped (in that order).
> >>> zk1 is started on machine B.
> >>> zk1 and zk3 are not creating a cluster, status is (using srvr word)
> >>> 'This ZooKeeper instance is not currently serving requests'
> >>>
> >>> A part of a log is:
> >>> [2016-10-20 04:03:10,053] WARN Unexpected exception
> >>> (org.apache.zookeeper.server.quorum.QuorumPeer)
> >>> java.lang.InterruptedException: Timeout while waiting for epoch from
> >> quorum
> >>> at org.apache.zookeeper.server.quorum.Leader.
> >> getEpochToPropose(Leader.java:
> >>> 878)
> >>> at org.apache.zookeeper.server.quorum.Leader.lead(Leader.java:377)
> >>> at org.apache.zookeeper.server.quorum.QuorumPeer.run(
> >> QuorumPeer.java:799)
> >>> [2016-10-20 04:03:10,054] INFO Shutting down
> >> (org.apache.zookeeper.server.
> >>> quorum.Leader)
> >>> [2016-10-20 04:03:10,054] INFO Shutdown called
> >> (org.apache.zookeeper.server.
> >>> quorum.Leader)
> >>> java.lang.Exception: shutdown Leader! reason: Forcing shutdown
> >>> at org.apache.zookeeper.server.quorum.Leader.shutdown(Leader.java:499)
> >>> at org.apache.zookeeper.server.quorum.QuorumPeer.run(
> >> QuorumPeer.java:805)
> >>> [2016-10-20 04:03:10,054] INFO shutting down
> >> (org.apache.zookeeper.server.
> >>> ZooKeeperServer)
> >>>
> >>> What is interesting: when zk2(previous leader) is started on machine B
> >>> (instead of zk1) cluster is configured correctly.
> >>> The same situation happens when all happen on the single machine.
> >>>
> >>> Issue is similar to this, but algorithm used by me is 3 (by default and
> >>> confirmed with electionAlg=3 in .cfg files)
> >>> https://issues.apache.org/jira/browse/ZOOKEEPER-2400
> >>>
> >>> thanks,
> >>> Krzysztof
> >>
> >>
>
>
[2016-10-20 04:03:25,068] WARN Cannot open channel to 1 at election address
/10.54.1.51:13001 (org.apache.zookeeper.server.quorum.QuorumCnxManager)
java.net.SocketTimeoutException: connect timed out
at java.net.PlainSocketImpl.socketConnect(Native Method)
at
java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:350)
at
java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:206)
at
java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:188)
at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)
at java.net.Socket.connect(Socket.java:589)
at
org.apache.zookeeper.server.quorum.QuorumCnxManager.connectOne(QuorumCnxManager.java:368)
at
org.apache.zookeeper.server.quorum.QuorumCnxManager.connectAll(QuorumCnxManager.java:402)
at
org.apache.zookeeper.server.quorum.FastLeaderElection.lookForLeader(FastLeaderElection.java:840)
at
org.apache.zookeeper.server.quorum.QuorumPeer.run(QuorumPeer.java:762)
[2016-10-20 04:03:30,070] WARN Cannot open channel to 2 at election address
/10.54.1.52:13001 (org.apache.zookeeper.server.quorum.QuorumCnxManager)
java.net.SocketTimeoutException: connect timed out
at java.net.PlainSocketImpl.socketConnect(Native Method)
at
java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:350)
at
java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:206)
at
java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:188)
at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)
at java.net.Socket.connect(Socket.java:589)
at
org.apache.zookeeper.server.quorum.QuorumCnxManager.connectOne(QuorumCnxManager.java:368)
at
org.apache.zookeeper.server.quorum.QuorumCnxManager.connectAll(QuorumCnxManager.java:402)
at
org.apache.zookeeper.server.quorum.FastLeaderElection.lookForLeader(FastLeaderElection.java:840)
at
org.apache.zookeeper.server.quorum.QuorumPeer.run(QuorumPeer.java:762)
[2016-10-20 04:03:30,071] INFO Notification time out: 400
(org.apache.zookeeper.server.quorum.FastLeaderElection)
[2016-10-20 04:03:31,092] INFO Accepted socket connection from
/10.54.1.53:55022 (org.apache.zookeeper.server.NIOServerCnxnFactory)
[2016-10-20 04:03:31,092] INFO Processing srvr command from /10.54.1.53:55022
(org.apache.zookeeper.server.NIOServerCnxn)
[2016-10-20 04:03:31,094] INFO Closed socket connection for client
/10.54.1.53:55022 (no session established for client)
(org.apache.zookeeper.server.NIOServerCnxn)
[2016-10-20 04:03:33,478] WARN Cannot open channel to 1 at election address
/10.54.1.51:13001 (org.apache.zookeeper.server.quorum.QuorumCnxManager)
java.net.ConnectException: Connection refused
at java.net.PlainSocketImpl.socketConnect(Native Method)
at
java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:350)
at
java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:206)
at
java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:188)
at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)
at java.net.Socket.connect(Socket.java:589)
at
org.apache.zookeeper.server.quorum.QuorumCnxManager.connectOne(QuorumCnxManager.java:368)
at
org.apache.zookeeper.server.quorum.QuorumCnxManager.connectAll(QuorumCnxManager.java:402)
at
org.apache.zookeeper.server.quorum.FastLeaderElection.lookForLeader(FastLeaderElection.java:840)
at
org.apache.zookeeper.server.quorum.QuorumPeer.run(QuorumPeer.java:762)
[2016-10-20 04:03:34,627] INFO Reading configuration from:
/opt/kafka/config/zookeeper.properties.1
(org.apache.zookeeper.server.quorum.QuorumPeerConfig)
[2016-10-20 04:03:34,629] INFO Defaulting to majority quorums
(org.apache.zookeeper.server.quorum.QuorumPeerConfig)
[2016-10-20 04:03:34,634] INFO autopurge.snapRetainCount set to 3
(org.apache.zookeeper.server.DatadirCleanupManager)
[2016-10-20 04:03:34,634] INFO autopurge.purgeInterval set to 1
(org.apache.zookeeper.server.DatadirCleanupManager)
[2016-10-20 04:03:34,641] INFO Purge task started.
(org.apache.zookeeper.server.DatadirCleanupManager)
[2016-10-20 04:03:34,656] INFO Starting quorum peer
(org.apache.zookeeper.server.quorum.QuorumPeerMain)
[2016-10-20 04:03:34,662] INFO Purge task completed.
(org.apache.zookeeper.server.DatadirCleanupManager)
[2016-10-20 04:03:34,673] INFO binding to port 0.0.0.0/0.0.0.0:14001
(org.apache.zookeeper.server.NIOServerCnxnFactory)
[2016-10-20 04:03:34,684] INFO tickTime set to 2000
(org.apache.zookeeper.server.quorum.QuorumPeer)
[2016-10-20 04:03:34,684] INFO minSessionTimeout set to -1
(org.apache.zookeeper.server.quorum.QuorumPeer)
[2016-10-20 04:03:34,684] INFO maxSessionTimeout set to -1
(org.apache.zookeeper.server.quorum.QuorumPeer)
[2016-10-20 04:03:34,684] INFO initLimit set to 5
(org.apache.zookeeper.server.quorum.QuorumPeer)
[2016-10-20 04:03:34,701] INFO currentEpoch not found! Creating with a
reasonable default of 0. This should only happen when you are upgrading your
installation (org.apache.zookeeper.server.quorum.QuorumPeer)
[2016-10-20 04:03:34,706] INFO acceptedEpoch not found! Creating with a
reasonable default of 0. This should only happen when you are upgrading your
installation (org.apache.zookeeper.server.quorum.QuorumPeer)
[2016-10-20 04:03:34,714] INFO My election bind port: /10.54.1.51:13001
(org.apache.zookeeper.server.quorum.QuorumCnxManager)
[2016-10-20 04:03:34,734] INFO LOOKING
(org.apache.zookeeper.server.quorum.QuorumPeer)
[2016-10-20 04:03:34,736] INFO New election. My id = 1, proposed zxid=0x0
(org.apache.zookeeper.server.quorum.FastLeaderElection)
[2016-10-20 04:03:34,742] INFO Notification: 1 (message format version), 1
(n.leader), 0x0 (n.zxid), 0x1 (n.round), LOOKING (n.state), 1 (n.sid), 0x0
(n.peerEpoch) LOOKING (my state)
(org.apache.zookeeper.server.quorum.FastLeaderElection)
[2016-10-20 04:03:38,484] WARN Cannot open channel to 2 at election address
/10.54.1.52:13001 (org.apache.zookeeper.server.quorum.QuorumCnxManager)
java.net.SocketTimeoutException: connect timed out
at java.net.PlainSocketImpl.socketConnect(Native Method)
at
java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:350)
at
java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:206)
at
java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:188)
at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)
at java.net.Socket.connect(Socket.java:589)
at
org.apache.zookeeper.server.quorum.QuorumCnxManager.connectOne(QuorumCnxManager.java:368)
at
org.apache.zookeeper.server.quorum.QuorumCnxManager.connectAll(QuorumCnxManager.java:402)
at
org.apache.zookeeper.server.quorum.FastLeaderElection.lookForLeader(FastLeaderElection.java:840)
at
org.apache.zookeeper.server.quorum.QuorumPeer.run(QuorumPeer.java:762)
[2016-10-20 04:03:38,485] INFO Notification time out: 800
(org.apache.zookeeper.server.quorum.FastLeaderElection)
[2016-10-20 04:03:39,286] INFO Received connection request /10.54.1.51:60210
(org.apache.zookeeper.server.quorum.QuorumCnxManager)
[2016-10-20 04:03:39,292] INFO Notification: 1 (message format version), 3
(n.leader), 0x100000000 (n.zxid), 0x3 (n.round), LOOKING (n.state), 3 (n.sid),
0x1 (n.peerEpoch) LOOKING (my state)
(org.apache.zookeeper.server.quorum.FastLeaderElection)
[2016-10-20 04:03:39,747] WARN Cannot open channel to 2 at election address
/10.54.1.52:13001 (org.apache.zookeeper.server.quorum.QuorumCnxManager)
java.net.SocketTimeoutException: connect timed out
at java.net.PlainSocketImpl.socketConnect(Native Method)
at
java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:350)
at
java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:206)
at
java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:188)
at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)
at java.net.Socket.connect(Socket.java:589)
at
org.apache.zookeeper.server.quorum.QuorumCnxManager.connectOne(QuorumCnxManager.java:368)
at
org.apache.zookeeper.server.quorum.QuorumCnxManager.toSend(QuorumCnxManager.java:341)
at
org.apache.zookeeper.server.quorum.FastLeaderElection$Messenger$WorkerSender.process(FastLeaderElection.java:449)
at
org.apache.zookeeper.server.quorum.FastLeaderElection$Messenger$WorkerSender.run(FastLeaderElection.java:430)
at java.lang.Thread.run(Thread.java:745)
[2016-10-20 04:03:39,752] INFO Notification: 1 (message format version), 1
(n.leader), 0x0 (n.zxid), 0x1 (n.round), LOOKING (n.state), 1 (n.sid), 0x0
(n.peerEpoch) LOOKING (my state)
(org.apache.zookeeper.server.quorum.FastLeaderElection)
[2016-10-20 04:03:39,753] INFO Notification: 1 (message format version), 3
(n.leader), 0x100000000 (n.zxid), 0x3 (n.round), LOOKING (n.state), 3 (n.sid),
0x1 (n.peerEpoch) LOOKING (my state)
(org.apache.zookeeper.server.quorum.FastLeaderElection)
[2016-10-20 04:03:42,488] INFO Accepted socket connection from
/10.54.1.53:55036 (org.apache.zookeeper.server.NIOServerCnxnFactory)
[2016-10-20 04:03:42,490] INFO Processing srvr command from /10.54.1.53:55036
(org.apache.zookeeper.server.NIOServerCnxn)
[2016-10-20 04:03:42,491] INFO Closed socket connection for client
/10.54.1.53:55036 (no session established for client)
(org.apache.zookeeper.server.NIOServerCnxn)
[2016-10-20 04:03:44,292] WARN Cannot open channel to 2 at election address
/10.54.1.52:13001 (org.apache.zookeeper.server.quorum.QuorumCnxManager)
java.net.SocketTimeoutException: connect timed out
at java.net.PlainSocketImpl.socketConnect(Native Method)
at
java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:350)
at
java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:206)
at
java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:188)
at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)
at java.net.Socket.connect(Socket.java:589)
at
org.apache.zookeeper.server.quorum.QuorumCnxManager.connectOne(QuorumCnxManager.java:368)
at
org.apache.zookeeper.server.quorum.QuorumCnxManager.connectAll(QuorumCnxManager.java:402)
at
org.apache.zookeeper.server.quorum.FastLeaderElection.lookForLeader(FastLeaderElection.java:840)
at
org.apache.zookeeper.server.quorum.QuorumPeer.run(QuorumPeer.java:762)
[2016-10-20 04:03:44,292] INFO Notification time out: 1600
(org.apache.zookeeper.server.quorum.FastLeaderElection)
[2016-10-20 04:03:44,752] WARN Cannot open channel to 2 at election address
/10.54.1.52:13001 (org.apache.zookeeper.server.quorum.QuorumCnxManager)
java.net.SocketTimeoutException: connect timed out
at java.net.PlainSocketImpl.socketConnect(Native Method)
at
java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:350)
at
java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:206)
at
java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:188)
at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)
at java.net.Socket.connect(Socket.java:589)
at
org.apache.zookeeper.server.quorum.QuorumCnxManager.connectOne(QuorumCnxManager.java:368)
at
org.apache.zookeeper.server.quorum.QuorumCnxManager.connectAll(QuorumCnxManager.java:402)
at
org.apache.zookeeper.server.quorum.FastLeaderElection.lookForLeader(FastLeaderElection.java:840)
at
org.apache.zookeeper.server.quorum.QuorumPeer.run(QuorumPeer.java:762)
[2016-10-20 04:03:44,754] INFO Notification time out: 400
(org.apache.zookeeper.server.quorum.FastLeaderElection)
[2016-10-20 04:03:44,758] INFO Notification: 1 (message format version), 3
(n.leader), 0x100000000 (n.zxid), 0x3 (n.round), LOOKING (n.state), 1 (n.sid),
0x1 (n.peerEpoch) LOOKING (my state)
(org.apache.zookeeper.server.quorum.FastLeaderElection)
[2016-10-20 04:03:44,960] INFO FOLLOWING
(org.apache.zookeeper.server.quorum.QuorumPeer)
[2016-10-20 04:03:44,973] INFO TCP NoDelay set to: true
(org.apache.zookeeper.server.quorum.Learner)
[2016-10-20 04:03:44,986] INFO Server
environment:zookeeper.version=3.4.6-1569965, built on 02/20/2014 09:09 GMT
(org.apache.zookeeper.server.ZooKeeperServer)
[2016-10-20 04:03:44,986] INFO Server
environment:host.name=pslte_psm.pslte.mot.com
(org.apache.zookeeper.server.ZooKeeperServer)
[2016-10-20 04:03:44,987] INFO Server environment:java.version=1.8.0_101
(org.apache.zookeeper.server.ZooKeeperServer)
[2016-10-20 04:03:44,987] INFO Server environment:java.vendor=Oracle
Corporation (org.apache.zookeeper.server.ZooKeeperServer)
[2016-10-20 04:03:44,987] INFO Server
environment:java.home=/usr/lib/jvm/java-1.8.0-openjdk-1.8.0.101-3.b13.el6_8.i386/jre
(org.apache.zookeeper.server.ZooKeeperServer)
[2016-10-20 04:03:44,987] INFO Server
environment:java.class.path=:/opt/kafka/bin/../core/build/dependant-libs-2.10.4*/*.jar:/opt/kafka/bin/../examples/build/libs//kafka-examples*.jar:/opt/kafka/bin/../contrib/hadoop-consumer/build/libs//kafka-hadoop-consumer*.jar:/opt/kafka/bin/../contrib/hadoop-producer/build/libs//kafka-hadoop-producer*.jar:/opt/kafka/bin/../clients/build/libs/kafka-clients*.jar:/opt/kafka/bin/../libs/jopt-simple-3.2.jar:/opt/kafka/bin/../libs/kafka-clients-0.8.2.1.jar:/opt/kafka/bin/../libs/kafka-graphite-1.0.0.jar:/opt/kafka/bin/../libs/kafka_2.10-0.8.2.1.jar:/opt/kafka/bin/../libs/log4j-1.2.16.jar:/opt/kafka/bin/../libs/lz4-1.2.0.jar:/opt/kafka/bin/../libs/metrics-core-2.2.0.jar:/opt/kafka/bin/../libs/metrics-graphite-2.2.0.jar:/opt/kafka/bin/../libs/scala-library-2.10.4.jar:/opt/kafka/bin/../libs/slf4j-api-1.7.6.jar:/opt/kafka/bin/../libs/slf4j-log4j12-1.6.1.jar:/opt/kafka/bin/../libs/snappy-java-1.1.1.6.jar:/opt/kafka/bin/../libs/zkclient-0.3.jar:/opt/kafka/bin/../libs/zookeeper-3.4.6.jar:/opt/kafka/bin/../core/build/libs/kafka_2.10*.jar
(org.apache.zookeeper.server.ZooKeeperServer)
[2016-10-20 04:03:44,987] INFO Server
environment:java.library.path=/opt/motoagent/agent/lib:/opt/motoagent/agent/../thirdparty/lib:/opt/lib:/usr/java/packages/lib/i386:/lib:/usr/lib
(org.apache.zookeeper.server.ZooKeeperServer)
[2016-10-20 04:03:44,987] INFO Server environment:java.io.tmpdir=/tmp
(org.apache.zookeeper.server.ZooKeeperServer)
[2016-10-20 04:03:44,987] INFO Server environment:java.compiler=<NA>
(org.apache.zookeeper.server.ZooKeeperServer)
[2016-10-20 04:03:44,987] INFO Server environment:os.name=Linux
(org.apache.zookeeper.server.ZooKeeperServer)
[2016-10-20 04:03:44,988] INFO Server environment:os.arch=i386
(org.apache.zookeeper.server.ZooKeeperServer)
[2016-10-20 04:03:44,988] INFO Server
environment:os.version=3.10.0-327.22.2.el7.x86_64
(org.apache.zookeeper.server.ZooKeeperServer)
[2016-10-20 04:03:44,988] INFO Server environment:user.name=root
(org.apache.zookeeper.server.ZooKeeperServer)
[2016-10-20 04:03:44,988] INFO Server environment:user.home=/root
(org.apache.zookeeper.server.ZooKeeperServer)
[2016-10-20 04:03:44,988] INFO Server environment:user.dir=/root
(org.apache.zookeeper.server.ZooKeeperServer)
[2016-10-20 04:03:44,990] INFO Created server with tickTime 2000
minSessionTimeout 4000 maxSessionTimeout 40000 datadir
/opt/zookeeper/zk_log_1/version-2 snapdir /opt/zookeeper/zk_server_1/version-2
(org.apache.zookeeper.server.ZooKeeperServer)
[2016-10-20 04:03:44,991] INFO FOLLOWING - LEADER ELECTION TOOK - 10255
(org.apache.zookeeper.server.quorum.Learner)
[2016-10-20 04:03:44,996] WARN Unexpected exception, tries=0, connecting to
/10.54.1.53:12001 (org.apache.zookeeper.server.quorum.Learner)
java.net.ConnectException: Connection refused
at java.net.PlainSocketImpl.socketConnect(Native Method)
at
java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:350)
at
java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:206)
at
java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:188)
at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)
at java.net.Socket.connect(Socket.java:589)
at
org.apache.zookeeper.server.quorum.Learner.connectToLeader(Learner.java:225)
at
org.apache.zookeeper.server.quorum.Follower.followLeader(Follower.java:71)
at
org.apache.zookeeper.server.quorum.QuorumPeer.run(QuorumPeer.java:786)
[2016-10-20 04:03:45,893] INFO Notification time out: 3200
(org.apache.zookeeper.server.quorum.FastLeaderElection)
[2016-10-20 04:03:45,893] INFO Notification: 1 (message format version), 3
(n.leader), 0x100000000 (n.zxid), 0x3 (n.round), LOOKING (n.state), 3 (n.sid),
0x1 (n.peerEpoch) FOLLOWING (my state)
(org.apache.zookeeper.server.quorum.FastLeaderElection)
[2016-10-20 04:03:45,997] WARN Unexpected exception, tries=1, connecting to
/10.54.1.53:12001 (org.apache.zookeeper.server.quorum.Learner)
java.net.ConnectException: Connection refused
at java.net.PlainSocketImpl.socketConnect(Native Method)
at
java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:350)
at
java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:206)
at
java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:188)
at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)
at java.net.Socket.connect(Socket.java:589)
at
org.apache.zookeeper.server.quorum.Learner.connectToLeader(Learner.java:225)
at
org.apache.zookeeper.server.quorum.Follower.followLeader(Follower.java:71)
at
org.apache.zookeeper.server.quorum.QuorumPeer.run(QuorumPeer.java:786)
[2016-10-20 04:03:46,998] WARN Unexpected exception, tries=2, connecting to
/10.54.1.53:12001 (org.apache.zookeeper.server.quorum.Learner)
java.net.ConnectException: Connection refused
at java.net.PlainSocketImpl.socketConnect(Native Method)
at
java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:350)
at
java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:206)
at
java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:188)
at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)
at java.net.Socket.connect(Socket.java:589)
at
org.apache.zookeeper.server.quorum.Learner.connectToLeader(Learner.java:225)
at
org.apache.zookeeper.server.quorum.Follower.followLeader(Follower.java:71)
at
org.apache.zookeeper.server.quorum.QuorumPeer.run(QuorumPeer.java:786)
[2016-10-20 04:03:47,108] INFO Accepted socket connection from
/10.54.1.51:50906 (org.apache.zookeeper.server.NIOServerCnxnFactory)
[2016-10-20 04:03:47,220] INFO Processing srvr command from /10.54.1.51:50906
(org.apache.zookeeper.server.NIOServerCnxn)
[2016-10-20 04:03:47,224] INFO Closed socket connection for client
/10.54.1.51:50906 (no session established for client)
(org.apache.zookeeper.server.NIOServerCnxn)
[2016-10-20 04:03:48,000] WARN Unexpected exception, tries=3, connecting to
/10.54.1.53:12001 (org.apache.zookeeper.server.quorum.Learner)
java.net.ConnectException: Connection refused
at java.net.PlainSocketImpl.socketConnect(Native Method)
at
java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:350)
at
java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:206)
at
java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:188)
at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)
at java.net.Socket.connect(Socket.java:589)
at
org.apache.zookeeper.server.quorum.Learner.connectToLeader(Learner.java:225)
at
org.apache.zookeeper.server.quorum.Follower.followLeader(Follower.java:71)
at
org.apache.zookeeper.server.quorum.QuorumPeer.run(QuorumPeer.java:786)
[2016-10-20 04:03:49,001] ERROR Unexpected exception
(org.apache.zookeeper.server.quorum.Learner)
java.net.ConnectException: Connection refused
at java.net.PlainSocketImpl.socketConnect(Native Method)
at
java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:350)
at
java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:206)
at
java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:188)
at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)
at java.net.Socket.connect(Socket.java:589)
at
org.apache.zookeeper.server.quorum.Learner.connectToLeader(Learner.java:225)
at
org.apache.zookeeper.server.quorum.Follower.followLeader(Follower.java:71)
at
org.apache.zookeeper.server.quorum.QuorumPeer.run(QuorumPeer.java:786)
[2016-10-20 04:03:49,002] WARN Exception when following the leader
(org.apache.zookeeper.server.quorum.Learner)
java.net.ConnectException: Connection refused
at java.net.PlainSocketImpl.socketConnect(Native Method)
at
java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:350)
at
java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:206)
at
java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:188)
at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)
at java.net.Socket.connect(Socket.java:589)
at
org.apache.zookeeper.server.quorum.Learner.connectToLeader(Learner.java:225)
at
org.apache.zookeeper.server.quorum.Follower.followLeader(Follower.java:71)
at
org.apache.zookeeper.server.quorum.QuorumPeer.run(QuorumPeer.java:786)
[2016-10-20 04:03:49,002] INFO shutdown called
(org.apache.zookeeper.server.quorum.Learner)
java.lang.Exception: shutdown Follower
at
org.apache.zookeeper.server.quorum.Follower.shutdown(Follower.java:166)
at
org.apache.zookeeper.server.quorum.QuorumPeer.run(QuorumPeer.java:790)
[2016-10-20 04:03:49,004] INFO Shutting down
(org.apache.zookeeper.server.quorum.FollowerZooKeeperServer)
[2016-10-20 04:03:49,004] INFO shutting down
(org.apache.zookeeper.server.ZooKeeperServer)
[2016-10-20 04:03:49,004] INFO LOOKING
(org.apache.zookeeper.server.quorum.QuorumPeer)
[2016-10-20 04:03:49,005] INFO New election. My id = 1, proposed zxid=0x0
(org.apache.zookeeper.server.quorum.FastLeaderElection)
[2016-10-20 04:03:49,093] INFO Notification time out: 6400
(org.apache.zookeeper.server.quorum.FastLeaderElection)
[2016-10-20 04:03:49,206] INFO Notification time out: 400
(org.apache.zookeeper.server.quorum.FastLeaderElection)
[2016-10-20 04:03:49,606] INFO Notification time out: 800
(org.apache.zookeeper.server.quorum.FastLeaderElection)
[2016-10-20 04:03:49,762] WARN Cannot open channel to 2 at election address
/10.54.1.52:13001 (org.apache.zookeeper.server.quorum.QuorumCnxManager)
java.net.SocketTimeoutException: connect timed out
at java.net.PlainSocketImpl.socketConnect(Native Method)
at
java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:350)
at
java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:206)
at
java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:188)
at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)
at java.net.Socket.connect(Socket.java:589)
at
org.apache.zookeeper.server.quorum.QuorumCnxManager.connectOne(QuorumCnxManager.java:368)
at
org.apache.zookeeper.server.quorum.QuorumCnxManager.toSend(QuorumCnxManager.java:341)
at
org.apache.zookeeper.server.quorum.FastLeaderElection$Messenger$WorkerSender.process(FastLeaderElection.java:449)
at
org.apache.zookeeper.server.quorum.FastLeaderElection$Messenger$WorkerSender.run(FastLeaderElection.java:430)
at java.lang.Thread.run(Thread.java:745)
[2016-10-20 04:03:49,764] INFO Notification: 1 (message format version), 3
(n.leader), 0x100000000 (n.zxid), 0x3 (n.round), FOLLOWING (n.state), 1
(n.sid), 0x1 (n.peerEpoch) LOOKING (my state)
(org.apache.zookeeper.server.quorum.FastLeaderElection)
[2016-10-20 04:03:49,764] INFO Notification: 1 (message format version), 1
(n.leader), 0x0 (n.zxid), 0x4 (n.round), LOOKING (n.state), 1 (n.sid), 0x0
(n.peerEpoch) LOOKING (my state)
(org.apache.zookeeper.server.quorum.FastLeaderElection)
[2016-10-20 04:03:49,764] INFO LEADING
(org.apache.zookeeper.server.quorum.QuorumPeer)
[2016-10-20 04:03:49,764] INFO Created server with tickTime 2000
minSessionTimeout 4000 maxSessionTimeout 40000 datadir
/opt/zookeeper/zk_log_3/version-2 snapdir /opt/zookeeper/zk_server_3/version-2
(org.apache.zookeeper.server.ZooKeeperServer)
[2016-10-20 04:03:49,764] INFO LEADING - LEADER ELECTION TOOK - 39709
(org.apache.zookeeper.server.quorum.Leader)
[2016-10-20 04:03:50,565] INFO Notification time out: 1600
(org.apache.zookeeper.server.quorum.FastLeaderElection)
[2016-10-20 04:03:50,893] WARN Cannot open channel to 2 at election address
/10.54.1.52:13001 (org.apache.zookeeper.server.quorum.QuorumCnxManager)
java.net.SocketTimeoutException: connect timed out
at java.net.PlainSocketImpl.socketConnect(Native Method)
at
java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:350)
at
java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:206)
at
java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:188)
at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)
at java.net.Socket.connect(Socket.java:589)
at
org.apache.zookeeper.server.quorum.QuorumCnxManager.connectOne(QuorumCnxManager.java:368)
at
org.apache.zookeeper.server.quorum.QuorumCnxManager.toSend(QuorumCnxManager.java:341)
at
org.apache.zookeeper.server.quorum.FastLeaderElection$Messenger$WorkerSender.process(FastLeaderElection.java:449)
at
org.apache.zookeeper.server.quorum.FastLeaderElection$Messenger$WorkerSender.run(FastLeaderElection.java:430)
at java.lang.Thread.run(Thread.java:745)
