You are viewing a plain text version of this content. The canonical link for it is here.
Posted to user@zookeeper.apache.org by Prabhjot Bharaj <pr...@gmail.com> on 2015/08/10 19:50:46 UTC
Zookeeper clients unable to get lock
Hello Friends,
I have seen a strange behaviour in zookeeper. I'm starting zookeeper server
on 3 nodes (within less than 5 seconds). Also, after 10 seconds of starting
the server, I'm starting clients on 3 machines. All the 3 clients try to
acquire lock. But, none of them is able to get the lock.
My theory is:-
1. Nodes are not clustered together properly, when clients try to get lock.
But, 10 seconds is too much of a time for the nodes to get clustered
together. Not sure of the reason
So, I'm pasting entire info log from 3 zookeeper servers here.
Appreciate your help in finding the root of this.
Thanks,
Prabcs
Info logs on 198.18.85.48 . 85 and 106 are at the bottom of the page
=====================================================================
2015-08-10 13:44:15,917 - INFO [main:QuorumPeerConfig@103] - Reading
configuration from: /a/dna_zookeeper/conf/zoo.cfg
2015-08-10 13:44:15,922 - INFO [main:QuorumPeerConfig@340] - Defaulting to
majority quorums
2015-08-10 13:44:15,927 - INFO [main:DatadirCleanupManager@78] -
autopurge.snapRetainCount set to 3
2015-08-10 13:44:15,927 - INFO [main:DatadirCleanupManager@79] -
autopurge.purgeInterval set to 0
2015-08-10 13:44:15,928 - INFO [main:DatadirCleanupManager@101] - Purge
task is not scheduled.
2015-08-10 13:44:15,940 - INFO [main:QuorumPeerMain@127] - Starting quorum
peer
2015-08-10 13:44:15,953 - INFO [main:NIOServerCnxnFactory@94] - binding to
port 0.0.0.0/0.0.0.0:2181
2015-08-10 13:44:15,973 - INFO [main:QuorumPeer@959] - tickTime set to 2000
2015-08-10 13:44:15,973 - INFO [main:QuorumPeer@979] - minSessionTimeout
set to -1
2015-08-10 13:44:15,974 - INFO [main:QuorumPeer@990] - maxSessionTimeout
set to -1
2015-08-10 13:44:15,974 - INFO [main:QuorumPeer@1005] - initLimit set to 10
2015-08-10 13:44:15,989 - INFO [main:FileSnap@83] - Reading snapshot
/zookeeper_data/version-2/snapshot.1500000019
2015-08-10 13:44:16,019 - INFO [Thread-1:QuorumCnxManager$Listener@504] -
My election bind port: /198.18.85.48:3888
2015-08-10 13:44:16,029 - INFO
[QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:QuorumPeer@714] - LOOKING
2015-08-10 13:44:16,031 - INFO
[QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:FastLeaderElection@815] - New
election. My id = 2, proposed zxid=0x1700000018
2015-08-10 13:44:16,034 - WARN [WorkerSender[myid=2]:QuorumCnxManager@382]
- Cannot open channel to 1 at election address /198.18.85.106: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: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)
2015-08-10 13:44:16,039 - WARN [WorkerSender[myid=2]:QuorumCnxManager@382]
- Cannot open channel to 3 at election address /198.18.85.85: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: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)
2015-08-10 13:44:16,039 - INFO
[WorkerReceiver[myid=2]:FastLeaderElection@597] - Notification: 1 (message
format version), 2 (n.leader), 0x1700000018 (n.zxid), 0x1 (n.round),
LOOKING (n.state), 2 (n.sid), 0x17 (n.peerEpoch) LOOKING (my state)
2015-08-10 13:44:16,242 - WARN
[QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:QuorumCnxManager@382] - Cannot
open channel to 1 at election address /198.18.85.106: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: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)
2015-08-10 13:44:16,243 - WARN
[QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:QuorumCnxManager@382] - Cannot
open channel to 3 at election address /198.18.85.85: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: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)
2015-08-10 13:44:16,243 - INFO
[QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:FastLeaderElection@849] -
Notification time out: 400
2015-08-10 13:44:16,644 - WARN
[QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:QuorumCnxManager@382] - Cannot
open channel to 1 at election address /198.18.85.106: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: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)
2015-08-10 13:44:16,645 - WARN
[QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:QuorumCnxManager@382] - Cannot
open channel to 3 at election address /198.18.85.85: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: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)
2015-08-10 13:44:16,645 - INFO
[QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:FastLeaderElection@849] -
Notification time out: 800
2015-08-10 13:44:17,446 - WARN
[QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:QuorumCnxManager@382] - Cannot
open channel to 1 at election address /198.18.85.106: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: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)
2015-08-10 13:44:17,447 - WARN
[QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:QuorumCnxManager@382] - Cannot
open channel to 3 at election address /198.18.85.85: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: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)
2015-08-10 13:44:17,447 - INFO
[QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:FastLeaderElection@849] -
Notification time out: 1600
2015-08-10 13:44:17,665 - INFO [/198.18.85.48:3888
:QuorumCnxManager$Listener@511] - Received connection request /
198.18.85.85:45728
2015-08-10 13:44:17,669 - INFO
[WorkerReceiver[myid=2]:FastLeaderElection@597] - Notification: 1 (message
format version), 3 (n.leader), 0x1700000018 (n.zxid), 0x1 (n.round),
LOOKING (n.state), 3 (n.sid), 0x17 (n.peerEpoch) LOOKING (my state)
2015-08-10 13:44:17,669 - WARN [WorkerSender[myid=2]:QuorumCnxManager@382]
- Cannot open channel to 1 at election address /198.18.85.106: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: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)
2015-08-10 13:44:17,670 - INFO
[WorkerReceiver[myid=2]:FastLeaderElection@597] - Notification: 1 (message
format version), 3 (n.leader), 0x1700000018 (n.zxid), 0x1 (n.round),
LOOKING (n.state), 2 (n.sid), 0x17 (n.peerEpoch) LOOKING (my state)
2015-08-10 13:44:17,871 - INFO
[QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:QuorumPeer@784] - FOLLOWING
2015-08-10 13:44:17,876 - INFO
[QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:Learner@86] - TCP NoDelay set to:
true
2015-08-10 13:44:17,883 - INFO
[QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server
environment:zookeeper.version=3.4.6-1569965, built on 02/20/2014 09:09 GMT
2015-08-10 13:44:17,884 - INFO
[QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server
environment:host.name=a198-18-85-48.
2015-08-10 13:44:17,884 - INFO
[QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server
environment:java.version=1.7.0_75
2015-08-10 13:44:17,884 - INFO
[QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server
environment:java.vendor=Oracle Corporation
2015-08-10 13:44:17,884 - INFO
[QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server
environment:java.home=/usr/local/java/jdk1.7.0/jre
2015-08-10 13:44:17,884 - INFO
[QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server
environment:java.class.path=/a/dna_zookeeper/lib/slf4j-log4j12-1.6.1.jar:/a/dna_zookeeper/lib/slf4j-api-1.6.1.jar:/a/dna_zookeeper/lib/netty-3.7.0.Final.jar:/a/dna_zookeeper/lib/log4j-1.2.16.jar:/a/dna_zookeeper/lib/jline-0.9.94.jar:/a/dna_zookeeper/bin/zookeeper-3.4.6.jar:/a/dna_zookeeper/conf::/usr/local/lib:/usr/local/lib:/usr/local/lib
2015-08-10 13:44:17,884 - INFO
[QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server
environment:java.library.path=:/usr/local/lib:/usr/local/lib:/usr/local/lib:/usr/java/packages/lib/i386:/lib:/usr/lib
2015-08-10 13:44:17,884 - INFO
[QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server
environment:java.io.tmpdir=/tmp
2015-08-10 13:44:17,884 - INFO
[QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server
environment:java.compiler=<NA>
2015-08-10 13:44:17,884 - INFO
[QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server
environment:os.name=Linux
2015-08-10 13:44:17,884 - INFO
[QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server
environment:os.arch=i386
2015-08-10 13:44:17,885 - INFO
[QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server
environment:os.version=3.14.35-3.14.1.1-amd64-15536989
2015-08-10 13:44:17,885 - INFO
[QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server
environment:user.name=root
2015-08-10 13:44:17,885 - INFO
[QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server
environment:user.home=/root
2015-08-10 13:44:17,885 - INFO
[QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server
environment:user.dir=/usr/local/tmp
2015-08-10 13:44:17,886 - INFO
[QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:ZooKeeperServer@162] - Created
server with tickTime 2000 minSessionTimeout 4000 maxSessionTimeout 40000
datadir /zookeeper_data/version-2 snapdir /zookeeper_data/version-2
2015-08-10 13:44:17,887 - INFO
[QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:Follower@63] - FOLLOWING - LEADER
ELECTION TOOK - 1856
2015-08-10 13:44:17,890 - WARN
[QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:Learner@233] - Unexpected
exception, tries=0, connecting to /198.18.85.85:2888
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:225)
at
org.apache.zookeeper.server.quorum.Follower.followLeader(Follower.java:71)
at org.apache.zookeeper.server.quorum.QuorumPeer.run(QuorumPeer.java:786)
2015-08-10 13:44:18,905 - INFO
[QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:Learner@323] - Getting a diff from
the leader 0x1700000018
2015-08-10 13:44:18,910 - INFO
[QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:FileTxnSnapLog@240] -
Snapshotting: 0x1700000018 to /zookeeper_data/version-2/snapshot.1700000018
2015-08-10 13:44:19,203 - INFO [/198.18.85.48:3888
:QuorumCnxManager$Listener@511] - Received connection request /
198.18.85.106:60242
2015-08-10 13:44:19,210 - INFO
[WorkerReceiver[myid=2]:FastLeaderElection@597] - Notification: 1 (message
format version), 1 (n.leader), 0x1700000018 (n.zxid), 0x1 (n.round),
LOOKING (n.state), 1 (n.sid), 0x17 (n.peerEpoch) FOLLOWING (my state)
2015-08-10 13:44:19,211 - INFO
[WorkerReceiver[myid=2]:FastLeaderElection@597] - Notification: 1 (message
format version), 3 (n.leader), 0x1700000018 (n.zxid), 0x1 (n.round),
LOOKING (n.state), 1 (n.sid), 0x17 (n.peerEpoch) FOLLOWING (my state)
2015-08-10 13:44:25,924 - INFO [NIOServerCxn.Factory:
0.0.0.0/0.0.0.0:2181:NIOServerCnxnFactory@197] - Accepted socket connection
from /198.18.85.48:33057
2015-08-10 13:44:25,930 - WARN [NIOServerCxn.Factory:
0.0.0.0/0.0.0.0:2181:ZooKeeperServer@822] - Connection request from old
client /198.18.85.48:33057; will be dropped if server is in r-o mode
2015-08-10 13:44:25,931 - INFO [NIOServerCxn.Factory:
0.0.0.0/0.0.0.0:2181:ZooKeeperServer@868] - Client attempting to establish
new session at /198.18.85.48:33057
2015-08-10 13:44:25,932 - WARN
[QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:Follower@118] - Got zxid
0x1800000001 expected 0x1
2015-08-10 13:44:25,933 - INFO [SyncThread:2:FileTxnLog@199] - Creating
new log file: log.1800000001
2015-08-10 13:44:25,938 - INFO [CommitProcessor:2:ZooKeeperServer@617] -
Established session 0x24f17dacadc0000 with negotiated timeout 30000 for
client /198.18.85.48:33057
2015-08-10 13:44:25,966 - INFO [NIOServerCxn.Factory:
0.0.0.0/0.0.0.0:2181:NIOServerCnxnFactory@197] - Accepted socket connection
from /198.18.85.48:33058
2015-08-10 13:44:25,967 - WARN [NIOServerCxn.Factory:
0.0.0.0/0.0.0.0:2181:ZooKeeperServer@822] - Connection request from old
client /198.18.85.48:33058; will be dropped if server is in r-o mode
2015-08-10 13:44:25,967 - INFO [NIOServerCxn.Factory:
0.0.0.0/0.0.0.0:2181:ZooKeeperServer@868] - Client attempting to establish
new session at /198.18.85.48:33058
2015-08-10 13:44:25,968 - INFO [CommitProcessor:2:ZooKeeperServer@617] -
Established session 0x24f17dacadc0001 with negotiated timeout 10000 for
client /198.18.85.48:33058
2015-08-10 13:44:29,078 - INFO [NIOServerCxn.Factory:
0.0.0.0/0.0.0.0:2181:NIOServerCnxnFactory@197] - Accepted socket connection
from /198.18.85.106:56296
2015-08-10 13:44:29,079 - WARN [NIOServerCxn.Factory:
0.0.0.0/0.0.0.0:2181:ZooKeeperServer@822] - Connection request from old
client /198.18.85.106:56296; will be dropped if server is in r-o mode
2015-08-10 13:44:29,079 - INFO [NIOServerCxn.Factory:
0.0.0.0/0.0.0.0:2181:ZooKeeperServer@868] - Client attempting to establish
new session at /198.18.85.106:56296
2015-08-10 13:44:29,080 - INFO [CommitProcessor:2:ZooKeeperServer@617] -
Established session 0x24f17dacadc0002 with negotiated timeout 10000 for
client /198.18.85.106:56296
============================================================
Info logs on 198.18.85.85 . 106 is at the bottom of the page
============================================================
2015-08-10 13:44:17,509 - INFO [main:QuorumPeerConfig@103] - Reading
configuration from: /a/dna_zookeeper/conf/zoo.cfg
2015-08-10 13:44:17,515 - INFO [main:QuorumPeerConfig@340] - Defaulting to
majority quorums
2015-08-10 13:44:17,521 - INFO [main:DatadirCleanupManager@78] -
autopurge.snapRetainCount set to 3
2015-08-10 13:44:17,521 - INFO [main:DatadirCleanupManager@79] -
autopurge.purgeInterval set to 0
2015-08-10 13:44:17,522 - INFO [main:DatadirCleanupManager@101] - Purge
task is not scheduled.
2015-08-10 13:44:17,539 - INFO [main:QuorumPeerMain@127] - Starting quorum
peer
2015-08-10 13:44:17,556 - INFO [main:NIOServerCnxnFactory@94] - binding to
port 0.0.0.0/0.0.0.0:2181
2015-08-10 13:44:17,582 - INFO [main:QuorumPeer@959] - tickTime set to 2000
2015-08-10 13:44:17,582 - INFO [main:QuorumPeer@979] - minSessionTimeout
set to -1
2015-08-10 13:44:17,582 - INFO [main:QuorumPeer@990] - maxSessionTimeout
set to -1
2015-08-10 13:44:17,582 - INFO [main:QuorumPeer@1005] - initLimit set to 10
2015-08-10 13:44:17,603 - INFO [main:FileSnap@83] - Reading snapshot
/zookeeper_data/version-2/snapshot.1600000035
2015-08-10 13:44:17,640 - INFO [Thread-1:QuorumCnxManager$Listener@504] -
My election bind port: /198.18.85.85:3888
2015-08-10 13:44:17,654 - INFO
[QuorumPeer[myid=3]/0:0:0:0:0:0:0:0:2181:QuorumPeer@714] - LOOKING
2015-08-10 13:44:17,655 - INFO
[QuorumPeer[myid=3]/0:0:0:0:0:0:0:0:2181:FastLeaderElection@815] - New
election. My id = 3, proposed zxid=0x1700000018
2015-08-10 13:44:17,660 - WARN [WorkerSender[myid=3]:QuorumCnxManager@382]
- Cannot open channel to 1 at election address /198.18.85.106: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: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)
2015-08-10 13:44:17,671 - INFO
[WorkerReceiver[myid=3]:FastLeaderElection@597] - Notification: 1 (message
format version), 3 (n.leader), 0x1700000018 (n.zxid), 0x1 (n.round),
LOOKING (n.state), 3 (n.sid), 0x17 (n.peerEpoch) LOOKING (my state)
2015-08-10 13:44:17,672 - INFO
[WorkerReceiver[myid=3]:FastLeaderElection@597] - Notification: 1 (message
format version), 2 (n.leader), 0x1700000018 (n.zxid), 0x1 (n.round),
LOOKING (n.state), 2 (n.sid), 0x17 (n.peerEpoch) LOOKING (my state)
2015-08-10 13:44:17,672 - INFO
[WorkerReceiver[myid=3]:FastLeaderElection@597] - Notification: 1 (message
format version), 3 (n.leader), 0x1700000018 (n.zxid), 0x1 (n.round),
LOOKING (n.state), 2 (n.sid), 0x17 (n.peerEpoch) LOOKING (my state)
2015-08-10 13:44:17,873 - INFO
[QuorumPeer[myid=3]/0:0:0:0:0:0:0:0:2181:QuorumPeer@796] - LEADING
2015-08-10 13:44:17,878 - INFO
[QuorumPeer[myid=3]/0:0:0:0:0:0:0:0:2181:Leader@60] - TCP NoDelay set to:
true
2015-08-10 13:44:17,889 - INFO
[QuorumPeer[myid=3]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server
environment:zookeeper.version=3.4.6-1569965, built on 02/20/2014 09:09 GMT
2015-08-10 13:44:17,889 - INFO
[QuorumPeer[myid=3]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server
environment:host.name=a198-18-85-85.
2015-08-10 13:44:17,889 - INFO
[QuorumPeer[myid=3]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server
environment:java.version=1.7.0_75
2015-08-10 13:44:17,889 - INFO
[QuorumPeer[myid=3]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server
environment:java.vendor=Oracle Corporation
2015-08-10 13:44:17,889 - INFO
[QuorumPeer[myid=3]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server
environment:java.home=/usr/local/java/jdk1.7.0/jre
2015-08-10 13:44:17,889 - INFO
[QuorumPeer[myid=3]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server
environment:java.class.path=/a/dna_zookeeper/lib/slf4j-log4j12-1.6.1.jar:/a/dna_zookeeper/lib/slf4j-api-1.6.1.jar:/a/dna_zookeeper/lib/netty-3.7.0.Final.jar:/a/dna_zookeeper/lib/log4j-1.2.16.jar:/a/dna_zookeeper/lib/jline-0.9.94.jar:/a/dna_zookeeper/bin/zookeeper-3.4.6.jar:/a/dna_zookeeper/conf::/usr/local/lib:/usr/local/lib:/usr/local/lib
2015-08-10 13:44:17,890 - INFO
[QuorumPeer[myid=3]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server
environment:java.library.path=:/usr/local/lib:/usr/local/lib:/usr/local/lib:/usr/java/packages/lib/i386:/lib:/usr/lib
2015-08-10 13:44:17,890 - INFO
[QuorumPeer[myid=3]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server
environment:java.io.tmpdir=/tmp
2015-08-10 13:44:17,890 - INFO
[QuorumPeer[myid=3]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server
environment:java.compiler=<NA>
2015-08-10 13:44:17,890 - INFO
[QuorumPeer[myid=3]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server
environment:os.name=Linux
2015-08-10 13:44:17,890 - INFO
[QuorumPeer[myid=3]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server
environment:os.arch=i386
2015-08-10 13:44:17,890 - INFO
[QuorumPeer[myid=3]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server
environment:os.version=3.14.35-3.14.1.1-amd64-15536989
2015-08-10 13:44:17,890 - INFO
[QuorumPeer[myid=3]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server
environment:user.name=root
2015-08-10 13:44:17,891 - INFO
[QuorumPeer[myid=3]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server
environment:user.home=/root
2015-08-10 13:44:17,891 - INFO
[QuorumPeer[myid=3]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server
environment:user.dir=/usr/local/tmp
2015-08-10 13:44:17,893 - INFO
[QuorumPeer[myid=3]/0:0:0:0:0:0:0:0:2181:ZooKeeperServer@162] - Created
server with tickTime 2000 minSessionTimeout 4000 maxSessionTimeout 40000
datadir /zookeeper_data/version-2 snapdir /zookeeper_data/version-2
2015-08-10 13:44:17,894 - INFO
[QuorumPeer[myid=3]/0:0:0:0:0:0:0:0:2181:Leader@358] - LEADING - LEADER
ELECTION TOOK - 239
2015-08-10 13:44:18,901 - INFO [LearnerHandler-/198.18.85.48:34143
:LearnerHandler@330] - Follower sid: 2 : info :
org.apache.zookeeper.server.quorum.QuorumPeer$QuorumServer@1b84411
2015-08-10 13:44:18,906 - INFO [LearnerHandler-/198.18.85.48:34143
:LearnerHandler@385] - Synchronizing with Follower sid: 2
maxCommittedLog=0x1700000018 minCommittedLog=0x1700000001
peerLastZxid=0x1700000018
2015-08-10 13:44:18,906 - INFO [LearnerHandler-/198.18.85.48:34143
:LearnerHandler@462] - Sending DIFF
2015-08-10 13:44:18,913 - INFO [LearnerHandler-/198.18.85.48:34143
:LearnerHandler@522] - Received NEWLEADER-ACK message from 2
2015-08-10 13:44:18,916 - INFO
[QuorumPeer[myid=3]/0:0:0:0:0:0:0:0:2181:Leader@943] - Have quorum of
supporters, sids: [ 2,3 ]; starting up and setting last processed zxid:
0x1800000000
2015-08-10 13:44:19,208 - INFO [/198.18.85.85:3888
:QuorumCnxManager$Listener@511] - Received connection request /
198.18.85.106:48469
2015-08-10 13:44:19,212 - INFO
[WorkerReceiver[myid=3]:FastLeaderElection@597] - Notification: 1 (message
format version), 1 (n.leader), 0x1700000018 (n.zxid), 0x1 (n.round),
LOOKING (n.state), 1 (n.sid), 0x17 (n.peerEpoch) LEADING (my state)
2015-08-10 13:44:19,213 - INFO
[WorkerReceiver[myid=3]:FastLeaderElection@597] - Notification: 1 (message
format version), 3 (n.leader), 0x1700000018 (n.zxid), 0x1 (n.round),
LOOKING (n.state), 1 (n.sid), 0x17 (n.peerEpoch) LEADING (my state)
2015-08-10 13:44:19,241 - INFO [LearnerHandler-/198.18.85.106:36014
:LearnerHandler@330] - Follower sid: 1 : info :
org.apache.zookeeper.server.quorum.QuorumPeer$QuorumServer@8e5360
2015-08-10 13:44:19,243 - INFO [LearnerHandler-/198.18.85.106:36014
:LearnerHandler@385] - Synchronizing with Follower sid: 1
maxCommittedLog=0x1700000018 minCommittedLog=0x1700000001
peerLastZxid=0x1700000018
2015-08-10 13:44:19,243 - INFO [LearnerHandler-/198.18.85.106:36014
:LearnerHandler@462] - Sending DIFF
2015-08-10 13:44:19,253 - INFO [LearnerHandler-/198.18.85.106:36014
:LearnerHandler@522] - Received NEWLEADER-ACK message from 1
2015-08-10 13:44:25,934 - INFO [SyncThread:3:FileTxnLog@199] - Creating
new log file: log.1800000001
2015-08-10 13:44:27,565 - INFO [NIOServerCxn.Factory:
0.0.0.0/0.0.0.0:2181:NIOServerCnxnFactory@197] - Accepted socket connection
from /198.18.85.85:57552
2015-08-10 13:44:27,572 - WARN [NIOServerCxn.Factory:
0.0.0.0/0.0.0.0:2181:ZooKeeperServer@822] - Connection request from old
client /198.18.85.85:57552; will be dropped if server is in r-o mode
2015-08-10 13:44:27,573 - INFO [NIOServerCxn.Factory:
0.0.0.0/0.0.0.0:2181:ZooKeeperServer@868] - Client attempting to establish
new session at /198.18.85.85:57552
2015-08-10 13:44:27,579 - INFO [CommitProcessor:3:ZooKeeperServer@617] -
Established session 0x34f17dacae60000 with negotiated timeout 10000 for
client /198.18.85.85:57552
2015-08-10 13:44:30,000 - INFO [SessionTracker:ZooKeeperServer@347] -
Expiring session 0x34f17d862b90001, timeout of 10000ms exceeded
2015-08-10 13:44:30,000 - INFO [SessionTracker:ZooKeeperServer@347] -
Expiring session 0x14f17d85f780000, timeout of 10000ms exceeded
2015-08-10 13:44:30,000 - INFO [SessionTracker:ZooKeeperServer@347] -
Expiring session 0x24f17d85f800001, timeout of 10000ms exceeded
2015-08-10 13:44:30,000 - INFO [SessionTracker:ZooKeeperServer@347] -
Expiring session 0x34f17d862b90003, timeout of 10000ms exceeded
2015-08-10 13:44:30,001 - INFO [ProcessThread(sid:3
cport:-1)::PrepRequestProcessor@494] - Processed session termination for
sessionid: 0x34f17d862b90001
2015-08-10 13:44:30,001 - INFO [ProcessThread(sid:3
cport:-1)::PrepRequestProcessor@494] - Processed session termination for
sessionid: 0x14f17d85f780000
2015-08-10 13:44:30,001 - INFO [ProcessThread(sid:3
cport:-1)::PrepRequestProcessor@494] - Processed session termination for
sessionid: 0x24f17d85f800001
2015-08-10 13:44:30,001 - INFO [ProcessThread(sid:3
cport:-1)::PrepRequestProcessor@494] - Processed session termination for
sessionid: 0x34f17d862b90003
2015-08-10 13:44:50,000 - INFO [SessionTracker:ZooKeeperServer@347] -
Expiring session 0x34f17d862b90002, timeout of 30000ms exceeded
2015-08-10 13:44:50,001 - INFO [SessionTracker:ZooKeeperServer@347] -
Expiring session 0x24f17d85f800000, timeout of 30000ms exceeded
2015-08-10 13:44:50,001 - INFO [SessionTracker:ZooKeeperServer@347] -
Expiring session 0x34f17d862b90000, timeout of 30000ms exceeded
2015-08-10 13:44:50,001 - INFO [ProcessThread(sid:3
cport:-1)::PrepRequestProcessor@494] - Processed session termination for
sessionid: 0x34f17d862b90002
2015-08-10 13:44:50,001 - INFO [ProcessThread(sid:3
cport:-1)::PrepRequestProcessor@494] - Processed session termination for
sessionid: 0x24f17d85f800000
2015-08-10 13:44:50,002 - INFO [ProcessThread(sid:3
cport:-1)::PrepRequestProcessor@494] - Processed session termination for
sessionid: 0x34f17d862b90000
============================================================
Info logs on 198.18.85.106
============================================================
2015-08-10 13:44:19,051 - INFO [main:QuorumPeerConfig@103] - Reading
configuration from: /a/dna_zookeeper/conf/zoo.cfg
2015-08-10 13:44:19,057 - INFO [main:QuorumPeerConfig@340] - Defaulting to
majority quorums
2015-08-10 13:44:19,064 - INFO [main:DatadirCleanupManager@78] -
autopurge.snapRetainCount set to 3
2015-08-10 13:44:19,064 - INFO [main:DatadirCleanupManager@79] -
autopurge.purgeInterval set to 0
2015-08-10 13:44:19,065 - INFO [main:DatadirCleanupManager@101] - Purge
task is not scheduled.
2015-08-10 13:44:19,082 - INFO [main:QuorumPeerMain@127] - Starting quorum
peer
2015-08-10 13:44:19,099 - INFO [main:NIOServerCnxnFactory@94] - binding to
port 0.0.0.0/0.0.0.0:2181
2015-08-10 13:44:19,127 - INFO [main:QuorumPeer@959] - tickTime set to 2000
2015-08-10 13:44:19,127 - INFO [main:QuorumPeer@979] - minSessionTimeout
set to -1
2015-08-10 13:44:19,128 - INFO [main:QuorumPeer@990] - maxSessionTimeout
set to -1
2015-08-10 13:44:19,128 - INFO [main:QuorumPeer@1005] - initLimit set to 10
2015-08-10 13:44:19,148 - INFO [main:FileSnap@83] - Reading snapshot
/zookeeper_data/version-2/snapshot.1600000035
2015-08-10 13:44:19,184 - INFO [Thread-1:QuorumCnxManager$Listener@504] -
My election bind port: /198.18.85.106:3888
2015-08-10 13:44:19,198 - INFO
[QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:2181:QuorumPeer@714] - LOOKING
2015-08-10 13:44:19,200 - INFO
[QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:2181:FastLeaderElection@815] - New
election. My id = 1, proposed zxid=0x1700000018
2015-08-10 13:44:19,202 - INFO
[WorkerReceiver[myid=1]:FastLeaderElection@597] - Notification: 1 (message
format version), 1 (n.leader), 0x1700000018 (n.zxid), 0x1 (n.round),
LOOKING (n.state), 1 (n.sid), 0x17 (n.peerEpoch) LOOKING (my state)
2015-08-10 13:44:19,207 - INFO [WorkerSender[myid=1]:QuorumCnxManager@193]
- Have smaller server identifier, so dropping the connection: (2, 1)
2015-08-10 13:44:19,208 - INFO [/198.18.85.106:3888
:QuorumCnxManager$Listener@511] - Received connection request /
198.18.85.48:40751
2015-08-10 13:44:19,208 - INFO [WorkerSender[myid=1]:QuorumCnxManager@193]
- Have smaller server identifier, so dropping the connection: (3, 1)
2015-08-10 13:44:19,211 - INFO [/198.18.85.106:3888
:QuorumCnxManager$Listener@511] - Received connection request /
198.18.85.85:58481
2015-08-10 13:44:19,212 - INFO
[WorkerReceiver[myid=1]:FastLeaderElection@597] - Notification: 1 (message
format version), 3 (n.leader), 0x1700000018 (n.zxid), 0x1 (n.round),
LOOKING (n.state), 2 (n.sid), 0x17 (n.peerEpoch) LOOKING (my state)
2015-08-10 13:44:19,212 - INFO
[WorkerReceiver[myid=1]:FastLeaderElection@597] - Notification: 1 (message
format version), 3 (n.leader), 0x1700000018 (n.zxid), 0x1 (n.round),
LOOKING (n.state), 1 (n.sid), 0x17 (n.peerEpoch) LOOKING (my state)
2015-08-10 13:44:19,213 - INFO
[WorkerReceiver[myid=1]:FastLeaderElection@597] - Notification: 1 (message
format version), 3 (n.leader), 0x1700000018 (n.zxid), 0x1 (n.round),
LOOKING (n.state), 3 (n.sid), 0x17 (n.peerEpoch) LOOKING (my state)
2015-08-10 13:44:19,213 - INFO
[WorkerReceiver[myid=1]:FastLeaderElection@597] - Notification: 1 (message
format version), 3 (n.leader), 0x1700000018 (n.zxid), 0x1 (n.round),
LEADING (n.state), 3 (n.sid), 0x18 (n.peerEpoch) LOOKING (my state)
2015-08-10 13:44:19,213 - INFO
[WorkerReceiver[myid=1]:FastLeaderElection@597] - Notification: 1 (message
format version), 3 (n.leader), 0x1700000018 (n.zxid), 0x1 (n.round),
LEADING (n.state), 3 (n.sid), 0x18 (n.peerEpoch) LOOKING (my state)
2015-08-10 13:44:19,214 - INFO
[WorkerReceiver[myid=1]:FastLeaderElection@597] - Notification: 1 (message
format version), 3 (n.leader), 0x1700000018 (n.zxid), 0x1 (n.round),
FOLLOWING (n.state), 2 (n.sid), 0x18 (n.peerEpoch) LOOKING (my state)
2015-08-10 13:44:19,214 - INFO
[WorkerReceiver[myid=1]:FastLeaderElection@597] - Notification: 1 (message
format version), 3 (n.leader), 0x1700000018 (n.zxid), 0x1 (n.round),
FOLLOWING (n.state), 2 (n.sid), 0x18 (n.peerEpoch) FOLLOWING (my state)
2015-08-10 13:44:19,214 - INFO
[QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:2181:QuorumPeer@784] - FOLLOWING
2015-08-10 13:44:19,221 - INFO
[QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:2181:Learner@86] - TCP NoDelay set to:
true
2015-08-10 13:44:19,231 - INFO
[QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server
environment:zookeeper.version=3.4.6-1569965, built on 02/20/2014 09:09 GMT
2015-08-10 13:44:19,231 - INFO
[QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server
environment:host.name=a198-18-85-106.
2015-08-10 13:44:19,231 - INFO
[QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server
environment:java.version=1.7.0_75
2015-08-10 13:44:19,231 - INFO
[QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server
environment:java.vendor=Oracle Corporation
2015-08-10 13:44:19,232 - INFO
[QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server
environment:java.home=/usr/local/java/jdk1.7.0/jre
2015-08-10 13:44:19,232 - INFO
[QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server
environment:java.class.path=/a/dna_zookeeper/lib/slf4j-log4j12-1.6.1.jar:/a/dna_zookeeper/lib/slf4j-api-1.6.1.jar:/a/dna_zookeeper/lib/netty-3.7.0.Final.jar:/a/dna_zookeeper/lib/log4j-1.2.16.jar:/a/dna_zookeeper/lib/jline-0.9.94.jar:/a/dna_zookeeper/bin/zookeeper-3.4.6.jar:/a/dna_zookeeper/conf::/usr/local/lib:/usr/local/lib:/usr/local/lib
2015-08-10 13:44:19,232 - INFO
[QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server
environment:java.library.path=:/usr/local/lib:/usr/local/lib:/usr/local/lib:/usr/java/packages/lib/i386:/lib:/usr/lib
2015-08-10 13:44:19,232 - INFO
[QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server
environment:java.io.tmpdir=/tmp
2015-08-10 13:44:19,232 - INFO
[QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server
environment:java.compiler=<NA>
2015-08-10 13:44:19,232 - INFO
[QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server
environment:os.name=Linux
2015-08-10 13:44:19,232 - INFO
[QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server
environment:os.arch=i386
2015-08-10 13:44:19,233 - INFO
[QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server
environment:os.version=3.14.35-3.14.1.1-amd64-15536989
2015-08-10 13:44:19,233 - INFO
[QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server
environment:user.name=root
2015-08-10 13:44:19,233 - INFO
[QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server
environment:user.home=/root
2015-08-10 13:44:19,233 - INFO
[QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server
environment:user.dir=/usr/local/tmp
2015-08-10 13:44:19,235 - INFO
[QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:2181:ZooKeeperServer@162] - Created
server with tickTime 2000 minSessionTimeout 4000 maxSessionTimeout 40000
datadir /zookeeper_data/version-2 snapdir /zookeeper_data/version-2
2015-08-10 13:44:19,236 - INFO
[QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:2181:Follower@63] - FOLLOWING - LEADER
ELECTION TOOK - 37
2015-08-10 13:44:19,244 - INFO
[QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:2181:Learner@323] - Getting a diff from
the leader 0x1700000018
2015-08-10 13:44:19,250 - INFO
[QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:2181:FileTxnSnapLog@240] -
Snapshotting: 0x1700000018 to /zookeeper_data/version-2/snapshot.1700000018
2015-08-10 13:44:25,934 - WARN
[QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:2181:Follower@118] - Got zxid
0x1800000001 expected 0x1
2015-08-10 13:44:25,935 - INFO [SyncThread:1:FileTxnLog@199] - Creating
new log file: log.1800000001
2015-08-10 13:44:27,516 - INFO [NIOServerCxn.Factory:
0.0.0.0/0.0.0.0:2181:NIOServerCnxnFactory@197] - Accepted socket connection
from /198.18.85.85:33490
2015-08-10 13:44:27,524 - WARN [NIOServerCxn.Factory:
0.0.0.0/0.0.0.0:2181:ZooKeeperServer@822] - Connection request from old
client /198.18.85.85:33490; will be dropped if server is in r-o mode
2015-08-10 13:44:27,525 - INFO [NIOServerCxn.Factory:
0.0.0.0/0.0.0.0:2181:ZooKeeperServer@868] - Client attempting to establish
new session at /198.18.85.85:33490
2015-08-10 13:44:27,531 - INFO [CommitProcessor:1:ZooKeeperServer@617] -
Established session 0x14f17dacc2f0000 with negotiated timeout 30000 for
client /198.18.85.85:33490
2015-08-10 13:44:29,059 - INFO [NIOServerCxn.Factory:
0.0.0.0/0.0.0.0:2181:NIOServerCnxnFactory@197] - Accepted socket connection
from /198.18.85.106:34327
2015-08-10 13:44:29,060 - WARN [NIOServerCxn.Factory:
0.0.0.0/0.0.0.0:2181:ZooKeeperServer@822] - Connection request from old
client /198.18.85.106:34327; will be dropped if server is in r-o mode
2015-08-10 13:44:29,060 - INFO [NIOServerCxn.Factory:
0.0.0.0/0.0.0.0:2181:ZooKeeperServer@868] - Client attempting to establish
new session at /198.18.85.106:34327
2015-08-10 13:44:29,062 - INFO [CommitProcessor:1:ZooKeeperServer@617] -
Established session 0x14f17dacc2f0001 with negotiated timeout 30000 for
client /198.18.85.106:34327
Re: Zookeeper clients unable to get lock
Posted by Ivan Kelly <iv...@apache.org>.
Hi Prabcs,
The leader seems to be elected without issue. What exceptions are you
seeing from the client side? Do you have any client side logs?
-Ivan
On Mon, Aug 10, 2015 at 7:51 PM Prabhjot Bharaj <pr...@gmail.com>
wrote:
> Hello Friends,
>
> I have seen a strange behaviour in zookeeper. I'm starting zookeeper server
> on 3 nodes (within less than 5 seconds). Also, after 10 seconds of starting
> the server, I'm starting clients on 3 machines. All the 3 clients try to
> acquire lock. But, none of them is able to get the lock.
>
> My theory is:-
>
> 1. Nodes are not clustered together properly, when clients try to get lock.
> But, 10 seconds is too much of a time for the nodes to get clustered
> together. Not sure of the reason
>
> So, I'm pasting entire info log from 3 zookeeper servers here.
>
> Appreciate your help in finding the root of this.
>
> Thanks,
>
> Prabcs
>
>
> Info logs on 198.18.85.48 . 85 and 106 are at the bottom of the page
>
> =====================================================================
>
> 2015-08-10 13:44:15,917 - INFO [main:QuorumPeerConfig@103] - Reading
> configuration from: /a/dna_zookeeper/conf/zoo.cfg
>
> 2015-08-10 13:44:15,922 - INFO [main:QuorumPeerConfig@340] - Defaulting
> to
> majority quorums
>
> 2015-08-10 13:44:15,927 - INFO [main:DatadirCleanupManager@78] -
> autopurge.snapRetainCount set to 3
>
> 2015-08-10 13:44:15,927 - INFO [main:DatadirCleanupManager@79] -
> autopurge.purgeInterval set to 0
>
> 2015-08-10 13:44:15,928 - INFO [main:DatadirCleanupManager@101] - Purge
> task is not scheduled.
>
> 2015-08-10 13:44:15,940 - INFO [main:QuorumPeerMain@127] - Starting
> quorum
> peer
>
> 2015-08-10 13:44:15,953 - INFO [main:NIOServerCnxnFactory@94] - binding
> to
> port 0.0.0.0/0.0.0.0:2181
>
> 2015-08-10 13:44:15,973 - INFO [main:QuorumPeer@959] - tickTime set to
> 2000
>
> 2015-08-10 13:44:15,973 - INFO [main:QuorumPeer@979] - minSessionTimeout
> set to -1
>
> 2015-08-10 13:44:15,974 - INFO [main:QuorumPeer@990] - maxSessionTimeout
> set to -1
>
> 2015-08-10 13:44:15,974 - INFO [main:QuorumPeer@1005] - initLimit set to
> 10
>
> 2015-08-10 13:44:15,989 - INFO [main:FileSnap@83] - Reading snapshot
> /zookeeper_data/version-2/snapshot.1500000019
>
> 2015-08-10 13:44:16,019 - INFO [Thread-1:QuorumCnxManager$Listener@504] -
> My election bind port: /198.18.85.48:3888
>
> 2015-08-10 13:44:16,029 - INFO
> [QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:QuorumPeer@714] - LOOKING
>
> 2015-08-10 13:44:16,031 - INFO
> [QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:FastLeaderElection@815] - New
> election. My id = 2, proposed zxid=0x1700000018
>
> 2015-08-10 13:44:16,034 - WARN [WorkerSender[myid=2]:QuorumCnxManager@382
> ]
> - Cannot open channel to 1 at election address /198.18.85.106: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: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)
>
> 2015-08-10 13:44:16,039 - WARN [WorkerSender[myid=2]:QuorumCnxManager@382
> ]
> - Cannot open channel to 3 at election address /198.18.85.85: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: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)
>
> 2015-08-10 13:44:16,039 - INFO
> [WorkerReceiver[myid=2]:FastLeaderElection@597] - Notification: 1 (message
> format version), 2 (n.leader), 0x1700000018 (n.zxid), 0x1 (n.round),
> LOOKING (n.state), 2 (n.sid), 0x17 (n.peerEpoch) LOOKING (my state)
>
> 2015-08-10 13:44:16,242 - WARN
> [QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:QuorumCnxManager@382] - Cannot
> open channel to 1 at election address /198.18.85.106: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: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)
>
> 2015-08-10 13:44:16,243 - WARN
> [QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:QuorumCnxManager@382] - Cannot
> open channel to 3 at election address /198.18.85.85: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: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)
>
> 2015-08-10 13:44:16,243 - INFO
> [QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:FastLeaderElection@849] -
> Notification time out: 400
>
> 2015-08-10 13:44:16,644 - WARN
> [QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:QuorumCnxManager@382] - Cannot
> open channel to 1 at election address /198.18.85.106: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: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)
>
> 2015-08-10 13:44:16,645 - WARN
> [QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:QuorumCnxManager@382] - Cannot
> open channel to 3 at election address /198.18.85.85: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: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)
>
> 2015-08-10 13:44:16,645 - INFO
> [QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:FastLeaderElection@849] -
> Notification time out: 800
>
> 2015-08-10 13:44:17,446 - WARN
> [QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:QuorumCnxManager@382] - Cannot
> open channel to 1 at election address /198.18.85.106: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: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)
>
> 2015-08-10 13:44:17,447 - WARN
> [QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:QuorumCnxManager@382] - Cannot
> open channel to 3 at election address /198.18.85.85: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: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)
>
> 2015-08-10 13:44:17,447 - INFO
> [QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:FastLeaderElection@849] -
> Notification time out: 1600
>
> 2015-08-10 13:44:17,665 - INFO [/198.18.85.48:3888
> :QuorumCnxManager$Listener@511] - Received connection request /
> 198.18.85.85:45728
>
> 2015-08-10 13:44:17,669 - INFO
> [WorkerReceiver[myid=2]:FastLeaderElection@597] - Notification: 1 (message
> format version), 3 (n.leader), 0x1700000018 (n.zxid), 0x1 (n.round),
> LOOKING (n.state), 3 (n.sid), 0x17 (n.peerEpoch) LOOKING (my state)
>
> 2015-08-10 13:44:17,669 - WARN [WorkerSender[myid=2]:QuorumCnxManager@382
> ]
> - Cannot open channel to 1 at election address /198.18.85.106: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: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)
>
> 2015-08-10 13:44:17,670 - INFO
> [WorkerReceiver[myid=2]:FastLeaderElection@597] - Notification: 1 (message
> format version), 3 (n.leader), 0x1700000018 (n.zxid), 0x1 (n.round),
> LOOKING (n.state), 2 (n.sid), 0x17 (n.peerEpoch) LOOKING (my state)
>
> 2015-08-10 13:44:17,871 - INFO
> [QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:QuorumPeer@784] - FOLLOWING
>
> 2015-08-10 13:44:17,876 - INFO
> [QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:Learner@86] - TCP NoDelay set to:
> true
>
> 2015-08-10 13:44:17,883 - INFO
> [QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server
> environment:zookeeper.version=3.4.6-1569965, built on 02/20/2014 09:09 GMT
>
> 2015-08-10 13:44:17,884 - INFO
> [QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server
> environment:host.name=a198-18-85-48.
>
> 2015-08-10 13:44:17,884 - INFO
> [QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server
> environment:java.version=1.7.0_75
>
> 2015-08-10 13:44:17,884 - INFO
> [QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server
> environment:java.vendor=Oracle Corporation
>
> 2015-08-10 13:44:17,884 - INFO
> [QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server
> environment:java.home=/usr/local/java/jdk1.7.0/jre
>
> 2015-08-10 13:44:17,884 - INFO
> [QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server
>
> environment:java.class.path=/a/dna_zookeeper/lib/slf4j-log4j12-1.6.1.jar:/a/dna_zookeeper/lib/slf4j-api-1.6.1.jar:/a/dna_zookeeper/lib/netty-3.7.0.Final.jar:/a/dna_zookeeper/lib/log4j-1.2.16.jar:/a/dna_zookeeper/lib/jline-0.9.94.jar:/a/dna_zookeeper/bin/zookeeper-3.4.6.jar:/a/dna_zookeeper/conf::/usr/local/lib:/usr/local/lib:/usr/local/lib
>
> 2015-08-10 13:44:17,884 - INFO
> [QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server
>
> environment:java.library.path=:/usr/local/lib:/usr/local/lib:/usr/local/lib:/usr/java/packages/lib/i386:/lib:/usr/lib
>
> 2015-08-10 13:44:17,884 - INFO
> [QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server
> environment:java.io.tmpdir=/tmp
>
> 2015-08-10 13:44:17,884 - INFO
> [QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server
> environment:java.compiler=<NA>
>
> 2015-08-10 13:44:17,884 - INFO
> [QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server
> environment:os.name=Linux
>
> 2015-08-10 13:44:17,884 - INFO
> [QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server
> environment:os.arch=i386
>
> 2015-08-10 13:44:17,885 - INFO
> [QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server
> environment:os.version=3.14.35-3.14.1.1-amd64-15536989
>
> 2015-08-10 13:44:17,885 - INFO
> [QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server
> environment:user.name=root
>
> 2015-08-10 13:44:17,885 - INFO
> [QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server
> environment:user.home=/root
>
> 2015-08-10 13:44:17,885 - INFO
> [QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server
> environment:user.dir=/usr/local/tmp
>
> 2015-08-10 13:44:17,886 - INFO
> [QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:ZooKeeperServer@162] - Created
> server with tickTime 2000 minSessionTimeout 4000 maxSessionTimeout 40000
> datadir /zookeeper_data/version-2 snapdir /zookeeper_data/version-2
>
> 2015-08-10 13:44:17,887 - INFO
> [QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:Follower@63] - FOLLOWING - LEADER
> ELECTION TOOK - 1856
>
> 2015-08-10 13:44:17,890 - WARN
> [QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:Learner@233] - Unexpected
> exception, tries=0, connecting to /198.18.85.85:2888
>
> 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:225)
>
> at
> org.apache.zookeeper.server.quorum.Follower.followLeader(Follower.java:71)
>
> at org.apache.zookeeper.server.quorum.QuorumPeer.run(QuorumPeer.java:786)
>
> 2015-08-10 13:44:18,905 - INFO
> [QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:Learner@323] - Getting a diff
> from
> the leader 0x1700000018
>
> 2015-08-10 13:44:18,910 - INFO
> [QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:FileTxnSnapLog@240] -
> Snapshotting: 0x1700000018 to /zookeeper_data/version-2/snapshot.1700000018
>
> 2015-08-10 13:44:19,203 - INFO [/198.18.85.48:3888
> :QuorumCnxManager$Listener@511] - Received connection request /
> 198.18.85.106:60242
>
> 2015-08-10 13:44:19,210 - INFO
> [WorkerReceiver[myid=2]:FastLeaderElection@597] - Notification: 1 (message
> format version), 1 (n.leader), 0x1700000018 (n.zxid), 0x1 (n.round),
> LOOKING (n.state), 1 (n.sid), 0x17 (n.peerEpoch) FOLLOWING (my state)
>
> 2015-08-10 13:44:19,211 - INFO
> [WorkerReceiver[myid=2]:FastLeaderElection@597] - Notification: 1 (message
> format version), 3 (n.leader), 0x1700000018 (n.zxid), 0x1 (n.round),
> LOOKING (n.state), 1 (n.sid), 0x17 (n.peerEpoch) FOLLOWING (my state)
>
> 2015-08-10 13:44:25,924 - INFO [NIOServerCxn.Factory:
> 0.0.0.0/0.0.0.0:2181:NIOServerCnxnFactory@197] - Accepted socket
> connection
> from /198.18.85.48:33057
>
> 2015-08-10 13:44:25,930 - WARN [NIOServerCxn.Factory:
> 0.0.0.0/0.0.0.0:2181:ZooKeeperServer@822] - Connection request from old
> client /198.18.85.48:33057; will be dropped if server is in r-o mode
>
> 2015-08-10 13:44:25,931 - INFO [NIOServerCxn.Factory:
> 0.0.0.0/0.0.0.0:2181:ZooKeeperServer@868] - Client attempting to establish
> new session at /198.18.85.48:33057
>
> 2015-08-10 13:44:25,932 - WARN
> [QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:Follower@118] - Got zxid
> 0x1800000001 expected 0x1
>
> 2015-08-10 13:44:25,933 - INFO [SyncThread:2:FileTxnLog@199] - Creating
> new log file: log.1800000001
>
> 2015-08-10 13:44:25,938 - INFO [CommitProcessor:2:ZooKeeperServer@617] -
> Established session 0x24f17dacadc0000 with negotiated timeout 30000 for
> client /198.18.85.48:33057
>
> 2015-08-10 13:44:25,966 - INFO [NIOServerCxn.Factory:
> 0.0.0.0/0.0.0.0:2181:NIOServerCnxnFactory@197] - Accepted socket
> connection
> from /198.18.85.48:33058
>
> 2015-08-10 13:44:25,967 - WARN [NIOServerCxn.Factory:
> 0.0.0.0/0.0.0.0:2181:ZooKeeperServer@822] - Connection request from old
> client /198.18.85.48:33058; will be dropped if server is in r-o mode
>
> 2015-08-10 13:44:25,967 - INFO [NIOServerCxn.Factory:
> 0.0.0.0/0.0.0.0:2181:ZooKeeperServer@868] - Client attempting to establish
> new session at /198.18.85.48:33058
>
> 2015-08-10 13:44:25,968 - INFO [CommitProcessor:2:ZooKeeperServer@617] -
> Established session 0x24f17dacadc0001 with negotiated timeout 10000 for
> client /198.18.85.48:33058
>
> 2015-08-10 13:44:29,078 - INFO [NIOServerCxn.Factory:
> 0.0.0.0/0.0.0.0:2181:NIOServerCnxnFactory@197] - Accepted socket
> connection
> from /198.18.85.106:56296
>
> 2015-08-10 13:44:29,079 - WARN [NIOServerCxn.Factory:
> 0.0.0.0/0.0.0.0:2181:ZooKeeperServer@822] - Connection request from old
> client /198.18.85.106:56296; will be dropped if server is in r-o mode
>
> 2015-08-10 13:44:29,079 - INFO [NIOServerCxn.Factory:
> 0.0.0.0/0.0.0.0:2181:ZooKeeperServer@868] - Client attempting to establish
> new session at /198.18.85.106:56296
>
> 2015-08-10 13:44:29,080 - INFO [CommitProcessor:2:ZooKeeperServer@617] -
> Established session 0x24f17dacadc0002 with negotiated timeout 10000 for
> client /198.18.85.106:56296
>
>
>
>
>
>
>
>
>
>
> ============================================================
>
> Info logs on 198.18.85.85 . 106 is at the bottom of the page
>
> ============================================================
>
>
>
>
>
>
>
>
>
> 2015-08-10 13:44:17,509 - INFO [main:QuorumPeerConfig@103] - Reading
> configuration from: /a/dna_zookeeper/conf/zoo.cfg
>
> 2015-08-10 13:44:17,515 - INFO [main:QuorumPeerConfig@340] - Defaulting
> to
> majority quorums
>
> 2015-08-10 13:44:17,521 - INFO [main:DatadirCleanupManager@78] -
> autopurge.snapRetainCount set to 3
>
> 2015-08-10 13:44:17,521 - INFO [main:DatadirCleanupManager@79] -
> autopurge.purgeInterval set to 0
>
> 2015-08-10 13:44:17,522 - INFO [main:DatadirCleanupManager@101] - Purge
> task is not scheduled.
>
> 2015-08-10 13:44:17,539 - INFO [main:QuorumPeerMain@127] - Starting
> quorum
> peer
>
> 2015-08-10 13:44:17,556 - INFO [main:NIOServerCnxnFactory@94] - binding
> to
> port 0.0.0.0/0.0.0.0:2181
>
> 2015-08-10 13:44:17,582 - INFO [main:QuorumPeer@959] - tickTime set to
> 2000
>
> 2015-08-10 13:44:17,582 - INFO [main:QuorumPeer@979] - minSessionTimeout
> set to -1
>
> 2015-08-10 13:44:17,582 - INFO [main:QuorumPeer@990] - maxSessionTimeout
> set to -1
>
> 2015-08-10 13:44:17,582 - INFO [main:QuorumPeer@1005] - initLimit set to
> 10
>
> 2015-08-10 13:44:17,603 - INFO [main:FileSnap@83] - Reading snapshot
> /zookeeper_data/version-2/snapshot.1600000035
>
> 2015-08-10 13:44:17,640 - INFO [Thread-1:QuorumCnxManager$Listener@504] -
> My election bind port: /198.18.85.85:3888
>
> 2015-08-10 13:44:17,654 - INFO
> [QuorumPeer[myid=3]/0:0:0:0:0:0:0:0:2181:QuorumPeer@714] - LOOKING
>
> 2015-08-10 13:44:17,655 - INFO
> [QuorumPeer[myid=3]/0:0:0:0:0:0:0:0:2181:FastLeaderElection@815] - New
> election. My id = 3, proposed zxid=0x1700000018
>
> 2015-08-10 13:44:17,660 - WARN [WorkerSender[myid=3]:QuorumCnxManager@382
> ]
> - Cannot open channel to 1 at election address /198.18.85.106: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: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)
>
> 2015-08-10 13:44:17,671 - INFO
> [WorkerReceiver[myid=3]:FastLeaderElection@597] - Notification: 1 (message
> format version), 3 (n.leader), 0x1700000018 (n.zxid), 0x1 (n.round),
> LOOKING (n.state), 3 (n.sid), 0x17 (n.peerEpoch) LOOKING (my state)
>
> 2015-08-10 13:44:17,672 - INFO
> [WorkerReceiver[myid=3]:FastLeaderElection@597] - Notification: 1 (message
> format version), 2 (n.leader), 0x1700000018 (n.zxid), 0x1 (n.round),
> LOOKING (n.state), 2 (n.sid), 0x17 (n.peerEpoch) LOOKING (my state)
>
> 2015-08-10 13:44:17,672 - INFO
> [WorkerReceiver[myid=3]:FastLeaderElection@597] - Notification: 1 (message
> format version), 3 (n.leader), 0x1700000018 (n.zxid), 0x1 (n.round),
> LOOKING (n.state), 2 (n.sid), 0x17 (n.peerEpoch) LOOKING (my state)
>
> 2015-08-10 13:44:17,873 - INFO
> [QuorumPeer[myid=3]/0:0:0:0:0:0:0:0:2181:QuorumPeer@796] - LEADING
>
> 2015-08-10 13:44:17,878 - INFO
> [QuorumPeer[myid=3]/0:0:0:0:0:0:0:0:2181:Leader@60] - TCP NoDelay set to:
> true
>
> 2015-08-10 13:44:17,889 - INFO
> [QuorumPeer[myid=3]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server
> environment:zookeeper.version=3.4.6-1569965, built on 02/20/2014 09:09 GMT
>
> 2015-08-10 13:44:17,889 - INFO
> [QuorumPeer[myid=3]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server
> environment:host.name=a198-18-85-85.
>
> 2015-08-10 13:44:17,889 - INFO
> [QuorumPeer[myid=3]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server
> environment:java.version=1.7.0_75
>
> 2015-08-10 13:44:17,889 - INFO
> [QuorumPeer[myid=3]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server
> environment:java.vendor=Oracle Corporation
>
> 2015-08-10 13:44:17,889 - INFO
> [QuorumPeer[myid=3]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server
> environment:java.home=/usr/local/java/jdk1.7.0/jre
>
> 2015-08-10 13:44:17,889 - INFO
> [QuorumPeer[myid=3]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server
>
> environment:java.class.path=/a/dna_zookeeper/lib/slf4j-log4j12-1.6.1.jar:/a/dna_zookeeper/lib/slf4j-api-1.6.1.jar:/a/dna_zookeeper/lib/netty-3.7.0.Final.jar:/a/dna_zookeeper/lib/log4j-1.2.16.jar:/a/dna_zookeeper/lib/jline-0.9.94.jar:/a/dna_zookeeper/bin/zookeeper-3.4.6.jar:/a/dna_zookeeper/conf::/usr/local/lib:/usr/local/lib:/usr/local/lib
>
> 2015-08-10 13:44:17,890 - INFO
> [QuorumPeer[myid=3]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server
>
> environment:java.library.path=:/usr/local/lib:/usr/local/lib:/usr/local/lib:/usr/java/packages/lib/i386:/lib:/usr/lib
>
> 2015-08-10 13:44:17,890 - INFO
> [QuorumPeer[myid=3]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server
> environment:java.io.tmpdir=/tmp
>
> 2015-08-10 13:44:17,890 - INFO
> [QuorumPeer[myid=3]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server
> environment:java.compiler=<NA>
>
> 2015-08-10 13:44:17,890 - INFO
> [QuorumPeer[myid=3]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server
> environment:os.name=Linux
>
> 2015-08-10 13:44:17,890 - INFO
> [QuorumPeer[myid=3]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server
> environment:os.arch=i386
>
> 2015-08-10 13:44:17,890 - INFO
> [QuorumPeer[myid=3]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server
> environment:os.version=3.14.35-3.14.1.1-amd64-15536989
>
> 2015-08-10 13:44:17,890 - INFO
> [QuorumPeer[myid=3]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server
> environment:user.name=root
>
> 2015-08-10 13:44:17,891 - INFO
> [QuorumPeer[myid=3]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server
> environment:user.home=/root
>
> 2015-08-10 13:44:17,891 - INFO
> [QuorumPeer[myid=3]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server
> environment:user.dir=/usr/local/tmp
>
> 2015-08-10 13:44:17,893 - INFO
> [QuorumPeer[myid=3]/0:0:0:0:0:0:0:0:2181:ZooKeeperServer@162] - Created
> server with tickTime 2000 minSessionTimeout 4000 maxSessionTimeout 40000
> datadir /zookeeper_data/version-2 snapdir /zookeeper_data/version-2
>
> 2015-08-10 13:44:17,894 - INFO
> [QuorumPeer[myid=3]/0:0:0:0:0:0:0:0:2181:Leader@358] - LEADING - LEADER
> ELECTION TOOK - 239
>
> 2015-08-10 13:44:18,901 - INFO [LearnerHandler-/198.18.85.48:34143
> :LearnerHandler@330] - Follower sid: 2 : info :
> org.apache.zookeeper.server.quorum.QuorumPeer$QuorumServer@1b84411
>
> 2015-08-10 13:44:18,906 - INFO [LearnerHandler-/198.18.85.48:34143
> :LearnerHandler@385] - Synchronizing with Follower sid: 2
> maxCommittedLog=0x1700000018 minCommittedLog=0x1700000001
> peerLastZxid=0x1700000018
>
> 2015-08-10 13:44:18,906 - INFO [LearnerHandler-/198.18.85.48:34143
> :LearnerHandler@462] - Sending DIFF
>
> 2015-08-10 13:44:18,913 - INFO [LearnerHandler-/198.18.85.48:34143
> :LearnerHandler@522] - Received NEWLEADER-ACK message from 2
>
> 2015-08-10 13:44:18,916 - INFO
> [QuorumPeer[myid=3]/0:0:0:0:0:0:0:0:2181:Leader@943] - Have quorum of
> supporters, sids: [ 2,3 ]; starting up and setting last processed zxid:
> 0x1800000000
>
> 2015-08-10 13:44:19,208 - INFO [/198.18.85.85:3888
> :QuorumCnxManager$Listener@511] - Received connection request /
> 198.18.85.106:48469
>
> 2015-08-10 13:44:19,212 - INFO
> [WorkerReceiver[myid=3]:FastLeaderElection@597] - Notification: 1 (message
> format version), 1 (n.leader), 0x1700000018 (n.zxid), 0x1 (n.round),
> LOOKING (n.state), 1 (n.sid), 0x17 (n.peerEpoch) LEADING (my state)
>
> 2015-08-10 13:44:19,213 - INFO
> [WorkerReceiver[myid=3]:FastLeaderElection@597] - Notification: 1 (message
> format version), 3 (n.leader), 0x1700000018 (n.zxid), 0x1 (n.round),
> LOOKING (n.state), 1 (n.sid), 0x17 (n.peerEpoch) LEADING (my state)
>
> 2015-08-10 13:44:19,241 - INFO [LearnerHandler-/198.18.85.106:36014
> :LearnerHandler@330] - Follower sid: 1 : info :
> org.apache.zookeeper.server.quorum.QuorumPeer$QuorumServer@8e5360
>
> 2015-08-10 13:44:19,243 - INFO [LearnerHandler-/198.18.85.106:36014
> :LearnerHandler@385] - Synchronizing with Follower sid: 1
> maxCommittedLog=0x1700000018 minCommittedLog=0x1700000001
> peerLastZxid=0x1700000018
>
> 2015-08-10 13:44:19,243 - INFO [LearnerHandler-/198.18.85.106:36014
> :LearnerHandler@462] - Sending DIFF
>
> 2015-08-10 13:44:19,253 - INFO [LearnerHandler-/198.18.85.106:36014
> :LearnerHandler@522] - Received NEWLEADER-ACK message from 1
>
> 2015-08-10 13:44:25,934 - INFO [SyncThread:3:FileTxnLog@199] - Creating
> new log file: log.1800000001
>
> 2015-08-10 13:44:27,565 - INFO [NIOServerCxn.Factory:
> 0.0.0.0/0.0.0.0:2181:NIOServerCnxnFactory@197] - Accepted socket
> connection
> from /198.18.85.85:57552
>
> 2015-08-10 13:44:27,572 - WARN [NIOServerCxn.Factory:
> 0.0.0.0/0.0.0.0:2181:ZooKeeperServer@822] - Connection request from old
> client /198.18.85.85:57552; will be dropped if server is in r-o mode
>
> 2015-08-10 13:44:27,573 - INFO [NIOServerCxn.Factory:
> 0.0.0.0/0.0.0.0:2181:ZooKeeperServer@868] - Client attempting to establish
> new session at /198.18.85.85:57552
>
> 2015-08-10 13:44:27,579 - INFO [CommitProcessor:3:ZooKeeperServer@617] -
> Established session 0x34f17dacae60000 with negotiated timeout 10000 for
> client /198.18.85.85:57552
>
> 2015-08-10 13:44:30,000 - INFO [SessionTracker:ZooKeeperServer@347] -
> Expiring session 0x34f17d862b90001, timeout of 10000ms exceeded
>
> 2015-08-10 13:44:30,000 - INFO [SessionTracker:ZooKeeperServer@347] -
> Expiring session 0x14f17d85f780000, timeout of 10000ms exceeded
>
> 2015-08-10 13:44:30,000 - INFO [SessionTracker:ZooKeeperServer@347] -
> Expiring session 0x24f17d85f800001, timeout of 10000ms exceeded
>
> 2015-08-10 13:44:30,000 - INFO [SessionTracker:ZooKeeperServer@347] -
> Expiring session 0x34f17d862b90003, timeout of 10000ms exceeded
>
> 2015-08-10 13:44:30,001 - INFO [ProcessThread(sid:3
> cport:-1)::PrepRequestProcessor@494] - Processed session termination for
> sessionid: 0x34f17d862b90001
>
> 2015-08-10 13:44:30,001 - INFO [ProcessThread(sid:3
> cport:-1)::PrepRequestProcessor@494] - Processed session termination for
> sessionid: 0x14f17d85f780000
>
> 2015-08-10 13:44:30,001 - INFO [ProcessThread(sid:3
> cport:-1)::PrepRequestProcessor@494] - Processed session termination for
> sessionid: 0x24f17d85f800001
>
> 2015-08-10 13:44:30,001 - INFO [ProcessThread(sid:3
> cport:-1)::PrepRequestProcessor@494] - Processed session termination for
> sessionid: 0x34f17d862b90003
>
> 2015-08-10 13:44:50,000 - INFO [SessionTracker:ZooKeeperServer@347] -
> Expiring session 0x34f17d862b90002, timeout of 30000ms exceeded
>
> 2015-08-10 13:44:50,001 - INFO [SessionTracker:ZooKeeperServer@347] -
> Expiring session 0x24f17d85f800000, timeout of 30000ms exceeded
>
> 2015-08-10 13:44:50,001 - INFO [SessionTracker:ZooKeeperServer@347] -
> Expiring session 0x34f17d862b90000, timeout of 30000ms exceeded
>
> 2015-08-10 13:44:50,001 - INFO [ProcessThread(sid:3
> cport:-1)::PrepRequestProcessor@494] - Processed session termination for
> sessionid: 0x34f17d862b90002
>
> 2015-08-10 13:44:50,001 - INFO [ProcessThread(sid:3
> cport:-1)::PrepRequestProcessor@494] - Processed session termination for
> sessionid: 0x24f17d85f800000
>
> 2015-08-10 13:44:50,002 - INFO [ProcessThread(sid:3
> cport:-1)::PrepRequestProcessor@494] - Processed session termination for
> sessionid: 0x34f17d862b90000
>
>
>
>
>
>
>
>
>
>
>
>
>
>
> ============================================================
>
> Info logs on 198.18.85.106
>
> ============================================================
>
>
>
>
>
>
> 2015-08-10 13:44:19,051 - INFO [main:QuorumPeerConfig@103] - Reading
> configuration from: /a/dna_zookeeper/conf/zoo.cfg
>
> 2015-08-10 13:44:19,057 - INFO [main:QuorumPeerConfig@340] - Defaulting
> to
> majority quorums
>
> 2015-08-10 13:44:19,064 - INFO [main:DatadirCleanupManager@78] -
> autopurge.snapRetainCount set to 3
>
> 2015-08-10 13:44:19,064 - INFO [main:DatadirCleanupManager@79] -
> autopurge.purgeInterval set to 0
>
> 2015-08-10 13:44:19,065 - INFO [main:DatadirCleanupManager@101] - Purge
> task is not scheduled.
>
> 2015-08-10 13:44:19,082 - INFO [main:QuorumPeerMain@127] - Starting
> quorum
> peer
>
> 2015-08-10 13:44:19,099 - INFO [main:NIOServerCnxnFactory@94] - binding
> to
> port 0.0.0.0/0.0.0.0:2181
>
> 2015-08-10 13:44:19,127 - INFO [main:QuorumPeer@959] - tickTime set to
> 2000
>
> 2015-08-10 13:44:19,127 - INFO [main:QuorumPeer@979] - minSessionTimeout
> set to -1
>
> 2015-08-10 13:44:19,128 - INFO [main:QuorumPeer@990] - maxSessionTimeout
> set to -1
>
> 2015-08-10 13:44:19,128 - INFO [main:QuorumPeer@1005] - initLimit set to
> 10
>
> 2015-08-10 13:44:19,148 - INFO [main:FileSnap@83] - Reading snapshot
> /zookeeper_data/version-2/snapshot.1600000035
>
> 2015-08-10 13:44:19,184 - INFO [Thread-1:QuorumCnxManager$Listener@504] -
> My election bind port: /198.18.85.106:3888
>
> 2015-08-10 13:44:19,198 - INFO
> [QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:2181:QuorumPeer@714] - LOOKING
>
> 2015-08-10 13:44:19,200 - INFO
> [QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:2181:FastLeaderElection@815] - New
> election. My id = 1, proposed zxid=0x1700000018
>
> 2015-08-10 13:44:19,202 - INFO
> [WorkerReceiver[myid=1]:FastLeaderElection@597] - Notification: 1 (message
> format version), 1 (n.leader), 0x1700000018 (n.zxid), 0x1 (n.round),
> LOOKING (n.state), 1 (n.sid), 0x17 (n.peerEpoch) LOOKING (my state)
>
> 2015-08-10 13:44:19,207 - INFO [WorkerSender[myid=1]:QuorumCnxManager@193
> ]
> - Have smaller server identifier, so dropping the connection: (2, 1)
>
> 2015-08-10 13:44:19,208 - INFO [/198.18.85.106:3888
> :QuorumCnxManager$Listener@511] - Received connection request /
> 198.18.85.48:40751
>
> 2015-08-10 13:44:19,208 - INFO [WorkerSender[myid=1]:QuorumCnxManager@193
> ]
> - Have smaller server identifier, so dropping the connection: (3, 1)
>
> 2015-08-10 13:44:19,211 - INFO [/198.18.85.106:3888
> :QuorumCnxManager$Listener@511] - Received connection request /
> 198.18.85.85:58481
>
> 2015-08-10 13:44:19,212 - INFO
> [WorkerReceiver[myid=1]:FastLeaderElection@597] - Notification: 1 (message
> format version), 3 (n.leader), 0x1700000018 (n.zxid), 0x1 (n.round),
> LOOKING (n.state), 2 (n.sid), 0x17 (n.peerEpoch) LOOKING (my state)
>
> 2015-08-10 13:44:19,212 - INFO
> [WorkerReceiver[myid=1]:FastLeaderElection@597] - Notification: 1 (message
> format version), 3 (n.leader), 0x1700000018 (n.zxid), 0x1 (n.round),
> LOOKING (n.state), 1 (n.sid), 0x17 (n.peerEpoch) LOOKING (my state)
>
> 2015-08-10 13:44:19,213 - INFO
> [WorkerReceiver[myid=1]:FastLeaderElection@597] - Notification: 1 (message
> format version), 3 (n.leader), 0x1700000018 (n.zxid), 0x1 (n.round),
> LOOKING (n.state), 3 (n.sid), 0x17 (n.peerEpoch) LOOKING (my state)
>
> 2015-08-10 13:44:19,213 - INFO
> [WorkerReceiver[myid=1]:FastLeaderElection@597] - Notification: 1 (message
> format version), 3 (n.leader), 0x1700000018 (n.zxid), 0x1 (n.round),
> LEADING (n.state), 3 (n.sid), 0x18 (n.peerEpoch) LOOKING (my state)
>
> 2015-08-10 13:44:19,213 - INFO
> [WorkerReceiver[myid=1]:FastLeaderElection@597] - Notification: 1 (message
> format version), 3 (n.leader), 0x1700000018 (n.zxid), 0x1 (n.round),
> LEADING (n.state), 3 (n.sid), 0x18 (n.peerEpoch) LOOKING (my state)
>
> 2015-08-10 13:44:19,214 - INFO
> [WorkerReceiver[myid=1]:FastLeaderElection@597] - Notification: 1 (message
> format version), 3 (n.leader), 0x1700000018 (n.zxid), 0x1 (n.round),
> FOLLOWING (n.state), 2 (n.sid), 0x18 (n.peerEpoch) LOOKING (my state)
>
> 2015-08-10 13:44:19,214 - INFO
> [WorkerReceiver[myid=1]:FastLeaderElection@597] - Notification: 1 (message
> format version), 3 (n.leader), 0x1700000018 (n.zxid), 0x1 (n.round),
> FOLLOWING (n.state), 2 (n.sid), 0x18 (n.peerEpoch) FOLLOWING (my state)
>
> 2015-08-10 13:44:19,214 - INFO
> [QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:2181:QuorumPeer@784] - FOLLOWING
>
> 2015-08-10 13:44:19,221 - INFO
> [QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:2181:Learner@86] - TCP NoDelay set to:
> true
>
> 2015-08-10 13:44:19,231 - INFO
> [QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server
> environment:zookeeper.version=3.4.6-1569965, built on 02/20/2014 09:09 GMT
>
> 2015-08-10 13:44:19,231 - INFO
> [QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server
> environment:host.name=a198-18-85-106.
>
> 2015-08-10 13:44:19,231 - INFO
> [QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server
> environment:java.version=1.7.0_75
>
> 2015-08-10 13:44:19,231 - INFO
> [QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server
> environment:java.vendor=Oracle Corporation
>
> 2015-08-10 13:44:19,232 - INFO
> [QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server
> environment:java.home=/usr/local/java/jdk1.7.0/jre
>
> 2015-08-10 13:44:19,232 - INFO
> [QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server
>
> environment:java.class.path=/a/dna_zookeeper/lib/slf4j-log4j12-1.6.1.jar:/a/dna_zookeeper/lib/slf4j-api-1.6.1.jar:/a/dna_zookeeper/lib/netty-3.7.0.Final.jar:/a/dna_zookeeper/lib/log4j-1.2.16.jar:/a/dna_zookeeper/lib/jline-0.9.94.jar:/a/dna_zookeeper/bin/zookeeper-3.4.6.jar:/a/dna_zookeeper/conf::/usr/local/lib:/usr/local/lib:/usr/local/lib
>
> 2015-08-10 13:44:19,232 - INFO
> [QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server
>
> environment:java.library.path=:/usr/local/lib:/usr/local/lib:/usr/local/lib:/usr/java/packages/lib/i386:/lib:/usr/lib
>
> 2015-08-10 13:44:19,232 - INFO
> [QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server
> environment:java.io.tmpdir=/tmp
>
> 2015-08-10 13:44:19,232 - INFO
> [QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server
> environment:java.compiler=<NA>
>
> 2015-08-10 13:44:19,232 - INFO
> [QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server
> environment:os.name=Linux
>
> 2015-08-10 13:44:19,232 - INFO
> [QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server
> environment:os.arch=i386
>
> 2015-08-10 13:44:19,233 - INFO
> [QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server
> environment:os.version=3.14.35-3.14.1.1-amd64-15536989
>
> 2015-08-10 13:44:19,233 - INFO
> [QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server
> environment:user.name=root
>
> 2015-08-10 13:44:19,233 - INFO
> [QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server
> environment:user.home=/root
>
> 2015-08-10 13:44:19,233 - INFO
> [QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server
> environment:user.dir=/usr/local/tmp
>
> 2015-08-10 13:44:19,235 - INFO
> [QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:2181:ZooKeeperServer@162] - Created
> server with tickTime 2000 minSessionTimeout 4000 maxSessionTimeout 40000
> datadir /zookeeper_data/version-2 snapdir /zookeeper_data/version-2
>
> 2015-08-10 13:44:19,236 - INFO
> [QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:2181:Follower@63] - FOLLOWING - LEADER
> ELECTION TOOK - 37
>
> 2015-08-10 13:44:19,244 - INFO
> [QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:2181:Learner@323] - Getting a diff
> from
> the leader 0x1700000018
>
> 2015-08-10 13:44:19,250 - INFO
> [QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:2181:FileTxnSnapLog@240] -
> Snapshotting: 0x1700000018 to /zookeeper_data/version-2/snapshot.1700000018
>
> 2015-08-10 13:44:25,934 - WARN
> [QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:2181:Follower@118] - Got zxid
> 0x1800000001 expected 0x1
>
> 2015-08-10 13:44:25,935 - INFO [SyncThread:1:FileTxnLog@199] - Creating
> new log file: log.1800000001
>
> 2015-08-10 13:44:27,516 - INFO [NIOServerCxn.Factory:
> 0.0.0.0/0.0.0.0:2181:NIOServerCnxnFactory@197] - Accepted socket
> connection
> from /198.18.85.85:33490
>
> 2015-08-10 13:44:27,524 - WARN [NIOServerCxn.Factory:
> 0.0.0.0/0.0.0.0:2181:ZooKeeperServer@822] - Connection request from old
> client /198.18.85.85:33490; will be dropped if server is in r-o mode
>
> 2015-08-10 13:44:27,525 - INFO [NIOServerCxn.Factory:
> 0.0.0.0/0.0.0.0:2181:ZooKeeperServer@868] - Client attempting to establish
> new session at /198.18.85.85:33490
>
> 2015-08-10 13:44:27,531 - INFO [CommitProcessor:1:ZooKeeperServer@617] -
> Established session 0x14f17dacc2f0000 with negotiated timeout 30000 for
> client /198.18.85.85:33490
>
> 2015-08-10 13:44:29,059 - INFO [NIOServerCxn.Factory:
> 0.0.0.0/0.0.0.0:2181:NIOServerCnxnFactory@197] - Accepted socket
> connection
> from /198.18.85.106:34327
>
> 2015-08-10 13:44:29,060 - WARN [NIOServerCxn.Factory:
> 0.0.0.0/0.0.0.0:2181:ZooKeeperServer@822] - Connection request from old
> client /198.18.85.106:34327; will be dropped if server is in r-o mode
>
> 2015-08-10 13:44:29,060 - INFO [NIOServerCxn.Factory:
> 0.0.0.0/0.0.0.0:2181:ZooKeeperServer@868] - Client attempting to establish
> new session at /198.18.85.106:34327
>
> 2015-08-10 13:44:29,062 - INFO [CommitProcessor:1:ZooKeeperServer@617] -
> Established session 0x14f17dacc2f0001 with negotiated timeout 30000 for
> client /198.18.85.106:34327
>