You are viewing a plain text version of this content. The canonical link for it is here.
Posted to user@zookeeper.apache.org by Sebastian Mattheis <Se...@bmw-carit.de> on 2016/06/10 12:18:47 UTC
Zookeeper 3.5.1 dynamic configuration fails with EOFException
Zookeeper 3.5.1 (https://github.com/apache/zookeeper/releases/tag/release-3.5.1) dynamic configuration fails with two servers that are started one after the other throwing an EOFException. This is the same, if server 2 is configured as observer or participant. Is the usage wrong? Is this a known bug?
# server.1:
## /opt/zookeeper/var/myid
1
## /opt/zookeeper/conf/zoo.cfg
autopurge.purgeInterval=1
initLimit=10
syncLimit=5
autopurge.snapRetainCount=4
tickTime=2000
dataDir=/opt/zookeeper/var
dataLogDir=/opt/zookeeper/logs
standaloneEnabled=false
dynamicConfigFile=/opt/zookeeper/conf/zoo.cfg.dynamic
## /opt/zookeeper/conf/zoo.cfg.dynamic
server.1=192.168.99.100:2888:3888;2181
## Output (on connection of server.2 after start-up):
…
2016-06-09 09:22:32,309 [myid:1] - INFO [NIOServerCxnFactory.AcceptThread:/0.0.0.0:2181:NIOServerCnxnFactory$AcceptThread@296] - Accepted socket connection from /192.168.99.101:43222
2016-06-09 09:22:32,378 [myid:1] - INFO [NIOWorkerThread-1:ZooKeeperServer@964] - Client attempting to establish new session at /192.168.99.101:43222
2016-06-09 09:22:32,382 [myid:1] - INFO [SyncThread:1:FileTxnLog@200] - Creating new log file: log.100000001
2016-06-09 09:22:32,392 [myid:1] - INFO [CommitProcWorkThread-1:ZooKeeperServer@678] - Established session 0x10001af5f770000 with negotiated timeout 30000 for client /192.168.99.101:43222
2016-06-09 09:22:32,410 [myid:1] - WARN [NIOWorkerThread-1:NIOServerCnxn@365] - Unable to read additional data from client sessionid 0x10001af5f770000, likely client has closed socket
2016-06-09 09:22:32,411 [myid:1] - INFO [NIOWorkerThread-1:MBeanRegistry@119] - Unregister MBean [org.apache.ZooKeeperService:name0=ReplicatedServer_id1,name1=replica.1,name2=Leader,name3=Connections,name4=192.168.99.101,name5=0x10001af5f770000]
2016-06-09 09:22:32,412 [myid:1] - INFO [NIOWorkerThread-1:NIOServerCnxn@606] - Closed socket connection for client /192.168.99.101:43222 which had sessionid 0x10001af5f770000
2016-06-09 09:22:33,133 [myid:1] - INFO [/192.168.99.100:3888:QuorumCnxManager$Listener@637] - Received connection request /192.168.99.101:44396
2016-06-09 09:22:33,154 [myid:1] - WARN [RecvWorker:2:QuorumCnxManager$RecvWorker@917] - Connection broken for id 2, my id = 1, error =
java.io.EOFException
at java.io.DataInputStream.readInt(DataInputStream.java:392)
at org.apache.zookeeper.server.quorum.QuorumCnxManager$RecvWorker.run(QuorumCnxManager.java:902)
2016-06-09 09:22:33,158 [myid:1] - WARN [RecvWorker:2:QuorumCnxManager$RecvWorker@920] - Interrupting SendWorker
2016-06-09 09:22:33,159 [myid:1] - WARN [SendWorker:2:QuorumCnxManager$SendWorker@834] - Interrupted while waiting for message on queue
java.lang.InterruptedException
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.reportInterruptAfterWait(AbstractQueuedSynchronizer.java:2014)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2088)
at java.util.concurrent.ArrayBlockingQueue.poll(ArrayBlockingQueue.java:418)
at org.apache.zookeeper.server.quorum.QuorumCnxManager.pollSendQueue(QuorumCnxManager.java:986)
at org.apache.zookeeper.server.quorum.QuorumCnxManager.access$500(QuorumCnxManager.java:63)
at org.apache.zookeeper.server.quorum.QuorumCnxManager$SendWorker.run(QuorumCnxManager.java:822)
2016-06-09 09:22:33,164 [myid:1] - WARN [SendWorker:2:QuorumCnxManager$SendWorker@843] - Send worker leaving thread id 2 my id = 1
2016-06-09 09:22:33,348 [myid:1] - INFO [/192.168.99.100:3888:QuorumCnxManager$Listener@637] - Received connection request /192.168.99.101:44398
2016-06-09 09:22:33,352 [myid:1] - ERROR [SendWorker:2:QuorumCnxManager$SendWorker@810] - Failed to send last message. Shutting down thread.
java.net.SocketException: Broken pipe
at java.net.SocketOutputStream.socketWrite0(Native Method)
at java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:109)
at java.net.SocketOutputStream.write(SocketOutputStream.java:132)
at java.io.DataOutputStream.writeInt(DataOutputStream.java:200)
at org.apache.zookeeper.server.quorum.QuorumCnxManager$SendWorker.send(QuorumCnxManager.java:779)
at org.apache.zookeeper.server.quorum.QuorumCnxManager$SendWorker.run(QuorumCnxManager.java:806)
2016-06-09 09:22:33,359 [myid:1] - INFO [/192.168.99.100:3888:QuorumCnxManager$Listener@637] - Received connection request /192.168.99.101:44400
2016-06-09 09:22:33,365 [myid:1] - WARN [SendWorker:2:QuorumCnxManager$SendWorker@843] - Send worker leaving thread id 2 my id = 1
2016-06-09 09:22:33,366 [myid:1] - WARN [RecvWorker:2:QuorumCnxManager$RecvWorker@920] - Interrupting SendWorker
2016-06-09 09:22:33,413 [myid:1] - INFO [LearnerHandler-/192.168.99.101:48832:LearnerHandler@385] - Follower sid: 2 not in the current config 100000000
2016-06-09 09:22:33,425 [myid:1] - INFO [LearnerHandler-/192.168.99.101:48832:LearnerHandler@683] - Synchronizing with Follower sid: 2 maxCommittedLog=0x100000001 minCommittedLog=0x100000001 lastProcessedZxid=0x100000001 peerLastZxid=0x0
2016-06-09 09:22:33,427 [myid:1] - WARN [LearnerHandler-/192.168.99.101:48832:ZKDatabase@310] - Unable to find proposals from txnlog for zxid: 0
2016-06-09 09:22:33,430 [myid:1] - INFO [LearnerHandler-/192.168.99.101:48832:LearnerHandler@455] - Sending snapshot last zxid of peer is 0x0, zxid of leader is 0x100000001, send zxid of db as 0x100000001, 1 concurrent snapshots, snapshot was exempt from throttle
2016-06-09 09:23:03,908 [myid:1] - INFO [SessionTracker:ZooKeeperServer@384] - Expiring session 0x10001af5f770000, timeout of 30000ms exceeded
2016-06-09 09:23:03,909 [myid:1] - INFO [SessionTracker:QuorumZooKeeperServer@132] - Submitting global closeSession request for session 0x10001af5f770000
2016-06-09 09:23:03,910 [myid:1] - INFO [ProcessThread(sid:1 cport:-1)::PrepRequestProcessor@649] - Processed session termination for sessionid: 0x10001af5f770000
# server.2:
## /opt/zookeeper/var/myid
2
## /opt/zookeeper/conf/zoo.cfg
autopurge.purgeInterval=1
initLimit=10
syncLimit=5
autopurge.snapRetainCount=4
tickTime=2000
dataDir=/opt/zookeeper/var
dataLogDir=/opt/zookeeper/logs
standaloneEnabled=false
dynamicConfigFile=/opt/zookeeper/conf/zoo.cfg.dynamic
## /opt/zookeeper/conf/zoo.cfg.dynamic
server.2=192.168.99.101:2888:3888:observer;2181
server.1=192.168.99.100:2888:3888:participant;0.0.0.0:2181
## Output (on start-up):
Using config: /opt/zookeeper/bin/../conf/zoo.cfg
2016-06-09 09:22:32,833 [myid:] - INFO [main:QuorumPeerConfig@114] - Reading configuration from: /opt/zookeeper/bin/../conf/zoo.cfg
2016-06-09 09:22:32,847 [myid:] - INFO [main:QuorumPeerConfig@306] - clientPort is not set
2016-06-09 09:22:32,848 [myid:] - INFO [main:QuorumPeerConfig@320] - secureClientPort is not set
2016-06-09 09:22:32,853 [myid:] - WARN [main:QuorumPeerConfig@555] - No server failure will be tolerated. You need at least 3 servers.
2016-06-09 09:22:32,863 [myid:2] - INFO [main:DatadirCleanupManager@78] - autopurge.snapRetainCount set to 4
2016-06-09 09:22:32,863 [myid:2] - INFO [main:DatadirCleanupManager@79] - autopurge.purgeInterval set to 1
2016-06-09 09:22:32,869 [myid:2] - INFO [PurgeTask:DatadirCleanupManager$PurgeTask@138] - Purge task started.
2016-06-09 09:22:32,888 [myid:2] - INFO [main:QuorumPeerMain@136] - Starting quorum peer
2016-06-09 09:22:32,893 [myid:2] - INFO [PurgeTask:DatadirCleanupManager$PurgeTask@144] - Purge task completed.
2016-06-09 09:22:32,910 [myid:2] - INFO [main:NIOServerCnxnFactory@673] - Configuring NIO connection handler with 10s sessionless connection timeout, 1 selector thread(s), 2 worker threads, and 64 kB direct buffers.
2016-06-09 09:22:32,916 [myid:2] - INFO [main:NIOServerCnxnFactory@686] - binding to port /0.0.0.0:2181
2016-06-09 09:22:32,979 [myid:2] - INFO [main:Slf4jLog@67] - Logging to org.slf4j.impl.Log4jLoggerAdapter(org.mortbay.log) via org.mortbay.log.Slf4jLog
2016-06-09 09:22:33,019 [myid:2] - INFO [main:QuorumPeer@1280] - Local sessions disabled
2016-06-09 09:22:33,022 [myid:2] - INFO [main:QuorumPeer@1291] - Local session upgrading disabled
2016-06-09 09:22:33,023 [myid:2] - INFO [main:QuorumPeer@1258] - tickTime set to 2000
2016-06-09 09:22:33,023 [myid:2] - INFO [main:QuorumPeer@1302] - minSessionTimeout set to 4000
2016-06-09 09:22:33,025 [myid:2] - INFO [main:QuorumPeer@1313] - maxSessionTimeout set to 40000
2016-06-09 09:22:33,026 [myid:2] - INFO [main:QuorumPeer@1328] - initLimit set to 10
2016-06-09 09:22:33,041 [myid:2] - INFO [main:QuorumPeer@744] - currentEpoch not found! Creating with a reasonable default of 0. This should only happen when you are upgrading your installation
2016-06-09 09:22:33,056 [myid:2] - INFO [main:QuorumPeer@759] - acceptedEpoch not found! Creating with a reasonable default of 0. This should only happen when you are upgrading your installation
2016-06-09 09:22:33,061 [myid:2] - INFO [main:Slf4jLog@67] - jetty-6.1.26
2016-06-09 09:22:33,100 [myid:2] - INFO [main:Slf4jLog@67] - Started SelectChannelConnector@0.0.0.0:8080
2016-06-09 09:22:33,104 [myid:2] - INFO [main:JettyAdminServer@105] - Started AdminServer on address 0.0.0.0, port 8080 and command URL /commands
2016-06-09 09:22:33,112 [myid:2] - INFO [QuorumPeerListener:QuorumCnxManager$Listener@631] - My election bind port: /192.168.99.101:3888
2016-06-09 09:22:33,125 [myid:2] - INFO [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):QuorumPeer@986] - LOOKING
2016-06-09 09:22:33,127 [myid:2] - INFO [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):FastLeaderElection@894] - New election. My id = 2, proposed zxid=0x0
2016-06-09 09:22:33,142 [myid:2] - INFO [WorkerReceiver[myid=2]:FastLeaderElection@688] - Notification: 2 (message format version), 2 (n.leader), 0x0 (n.zxid), 0x1 (n.round), LOOKING (n.state), 2 (n.sid), 0x0 (n.peerEPoch), LOOKING (my state)0 (n.config version)
2016-06-09 09:22:33,150 [myid:2] - INFO [WorkerReceiver[myid=2]:FastLeaderElection$Messenger$WorkerReceiver@294] - 2 Received version: 100000000 my version: 0
2016-06-09 09:22:33,156 [myid:2] - INFO [WorkerReceiver[myid=2]:FastLeaderElection$Messenger$WorkerReceiver@301] - restarting leader election
2016-06-09 09:22:33,157 [myid:2] - INFO [/192.168.99.101:3888:QuorumCnxManager$Listener@659] - Leaving listener
2016-06-09 09:22:33,163 [myid:2] - WARN [RecvWorker:1:QuorumCnxManager$RecvWorker@917] - Connection broken for id 1, my id = 2, error =
java.net.SocketException: Socket closed
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
at java.net.SocketInputStream.read(SocketInputStream.java:170)
at java.net.SocketInputStream.read(SocketInputStream.java:141)
at java.net.SocketInputStream.read(SocketInputStream.java:223)
at java.io.DataInputStream.readInt(DataInputStream.java:387)
at org.apache.zookeeper.server.quorum.QuorumCnxManager$RecvWorker.run(QuorumCnxManager.java:902)
2016-06-09 09:22:33,166 [myid:2] - INFO [WorkerReceiver[myid=2]:FastLeaderElection$Messenger$WorkerReceiver@440] - WorkerReceiver is down
2016-06-09 09:22:33,166 [myid:2] - WARN [SendWorker:1:QuorumCnxManager$SendWorker@834] - Interrupted while waiting for message on queue
java.lang.InterruptedException
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.reportInterruptAfterWait(AbstractQueuedSynchronizer.java:2014)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2088)
at java.util.concurrent.ArrayBlockingQueue.poll(ArrayBlockingQueue.java:418)
at org.apache.zookeeper.server.quorum.QuorumCnxManager.pollSendQueue(QuorumCnxManager.java:986)
at org.apache.zookeeper.server.quorum.QuorumCnxManager.access$500(QuorumCnxManager.java:63)
at org.apache.zookeeper.server.quorum.QuorumCnxManager$SendWorker.run(QuorumCnxManager.java:822)
2016-06-09 09:22:33,173 [myid:2] - WARN [SendWorker:1:QuorumCnxManager$SendWorker@843] - Send worker leaving thread id 1 my id = 2
2016-06-09 09:22:33,174 [myid:2] - WARN [RecvWorker:1:QuorumCnxManager$RecvWorker@920] - Interrupting SendWorker
2016-06-09 09:22:33,350 [myid:2] - INFO [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):FastLeaderElection@928] - Notification time out: 400
2016-06-09 09:22:33,353 [myid:2] - INFO [WorkerSender[myid=2]:FastLeaderElection$Messenger$WorkerSender@470] - WorkerSender is down
2016-06-09 09:22:33,354 [myid:2] - INFO [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):MBeanRegistry@119] - Unregister MBean [org.apache.ZooKeeperService:name0=ReplicatedServer_id2,name1=replica.2,name2=LeaderElection]
2016-06-09 09:22:33,355 [myid:2] - INFO [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):QuorumPeer@986] - LOOKING
2016-06-09 09:22:33,356 [myid:2] - WARN [RecvWorker:1:QuorumCnxManager$RecvWorker@920] - Interrupting SendWorker
2016-06-09 09:22:33,357 [myid:2] - INFO [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):FastLeaderElection@894] - New election. My id = 2, proposed zxid=0x0
2016-06-09 09:22:33,359 [myid:2] - INFO [QuorumPeerListener:QuorumCnxManager$Listener@631] - My election bind port: /192.168.99.101:3888
2016-06-09 09:22:33,358 [myid:2] - WARN [SendWorker:1:QuorumCnxManager$SendWorker@843] - Send worker leaving thread id 1 my id = 2
2016-06-09 09:22:33,374 [myid:2] - INFO [WorkerReceiver[myid=2]:FastLeaderElection@688] - Notification: 2 (message format version), 1 (n.leader), 0x0 (n.zxid), 0x1 (n.round), LEADING (n.state), 1 (n.sid), 0x1 (n.peerEPoch), LOOKING (my state)100000000 (n.config version)
2016-06-09 09:22:33,376 [myid:2] - INFO [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):MBeanRegistry@119] - Unregister MBean [org.apache.ZooKeeperService:name0=ReplicatedServer_id2,name1=replica.2,name2=LeaderElection]
2016-06-09 09:22:33,378 [myid:2] - INFO [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):QuorumPeer@1062] - FOLLOWING
2016-06-09 09:22:33,385 [myid:2] - INFO [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):Learner@88] - TCP NoDelay set to: true
2016-06-09 09:22:33,385 [myid:2] - INFO [WorkerReceiver[myid=2]:FastLeaderElection@688] - Notification: 2 (message format version), 1 (n.leader), 0x0 (n.zxid), 0x1 (n.round), LEADING (n.state), 1 (n.sid), 0x1 (n.peerEPoch), FOLLOWING (my state)100000000 (n.config version)
2016-06-09 09:22:33,394 [myid:2] - INFO [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):Environment@109] - Server environment:zookeeper.version=3.5.1-alpha--1, built on 06/09/2016 09:19 GMT
2016-06-09 09:22:33,395 [myid:2] - INFO [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):Environment@109] - Server environment:host.name=footstep-server-2
2016-06-09 09:22:33,395 [myid:2] - INFO [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):Environment@109] - Server environment:java.version=1.8.0_91
2016-06-09 09:22:33,396 [myid:2] - INFO [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):Environment@109] - Server environment:java.vendor=Oracle Corporation
2016-06-09 09:22:33,396 [myid:2] - INFO [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):Environment@109] - Server environment:java.home=/usr/lib/jvm/java-8-openjdk-amd64/jre
2016-06-09 09:22:33,397 [myid:2] - INFO [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):Environment@109] - Server environment:java.class.path=/opt/zookeeper/bin/../build/classes:/opt/zookeeper/bin/../build/lib/slf4j-log4j12-1.7.5.jar:/opt/zookeeper/bin/../build/lib/slf4j-api-1.7.5.jar:/opt/zookeeper/bin/../build/lib/servlet-api-2.5-20081211.jar:/opt/zookeeper/bin/../build/lib/netty-3.7.0.Final.jar:/opt/zookeeper/bin/../build/lib/log4j-1.2.16.jar:/opt/zookeeper/bin/../build/lib/jline-2.11.jar:/opt/zookeeper/bin/../build/lib/jetty-util-6.1.26.jar:/opt/zookeeper/bin/../build/lib/jetty-6.1.26.jar:/opt/zookeeper/bin/../build/lib/javacc.jar:/opt/zookeeper/bin/../build/lib/jackson-mapper-asl-1.9.11.jar:/opt/zookeeper/bin/../build/lib/jackson-core-asl-1.9.11.jar:/opt/zookeeper/bin/../build/lib/commons-cli-1.2.jar:/opt/zookeeper/bin/../lib/*.jar:/opt/zookeeper/bin/../zookeeper-*.jar:/opt/zookeeper/bin/../src/java/lib/ivy-2.2.0.jar:/opt/zookeeper/bin/../conf:
2016-06-09 09:22:33,397 [myid:2] - INFO [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):Environment@109] - Server environment:java.library.path=/usr/java/packages/lib/amd64:/usr/lib/x86_64-linux-gnu/jni:/lib/x86_64-linux-gnu:/usr/lib/x86_64-linux-gnu:/usr/lib/jni:/lib:/usr/lib
2016-06-09 09:22:33,398 [myid:2] - INFO [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):Environment@109] - Server environment:java.io.tmpdir=/tmp
2016-06-09 09:22:33,398 [myid:2] - INFO [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):Environment@109] - Server environment:java.compiler=<NA>
2016-06-09 09:22:33,399 [myid:2] - INFO [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):Environment@109] - Server environment:os.name=Linux
2016-06-09 09:22:33,399 [myid:2] - INFO [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):Environment@109] - Server environment:os.arch=amd64
2016-06-09 09:22:33,399 [myid:2] - INFO [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):Environment@109] - Server environment:os.version=4.4.12-boot2docker
2016-06-09 09:22:33,400 [myid:2] - INFO [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):Environment@109] - Server environment:user.name=root
2016-06-09 09:22:33,401 [myid:2] - INFO [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):Environment@109] - Server environment:user.home=/root
2016-06-09 09:22:33,401 [myid:2] - INFO [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):Environment@109] - Server environment:user.dir=/
2016-06-09 09:22:33,401 [myid:2] - INFO [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):Environment@109] - Server environment:os.memory.free=9MB
2016-06-09 09:22:33,402 [myid:2] - INFO [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):Environment@109] - Server environment:os.memory.max=966MB
2016-06-09 09:22:33,402 [myid:2] - INFO [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):Environment@109] - Server environment:os.memory.total=15MB
2016-06-09 09:22:33,403 [myid:2] - INFO [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):ZooKeeperServer@858] - minSessionTimeout set to 4000
2016-06-09 09:22:33,404 [myid:2] - INFO [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):ZooKeeperServer@867] - maxSessionTimeout set to 40000
2016-06-09 09:22:33,405 [myid:2] - INFO [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):ZooKeeperServer@156] - Created server with tickTime 2000 minSessionTimeout 4000 maxSessionTimeout 40000 datadir /opt/zookeeper/logs/version-2 snapdir /opt/zookeeper/var/version-2
2016-06-09 09:22:33,406 [myid:2] - INFO [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):Follower@66] - FOLLOWING - LEADER ELECTION TOOK - 28
2016-06-09 09:22:33,434 [myid:2] - INFO [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):Learner@369] - Getting a snapshot from leader
2016-06-09 09:22:33,442 [myid:2] - INFO [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):Learner@509] - Learner received NEWLEADER message
2016-06-09 09:22:33,446 [myid:2] - INFO [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):FileTxnSnapLog@298] - Snapshotting: 0x100000001 to /opt/zookeeper/var/version-2/snapshot.100000001
2016-06-09 09:22:33,452 [myid:2] - INFO [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):Learner@493] - Learner received UPTODATE message
2016-06-09 09:22:33,457 [myid:2] - INFO [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):CommitProcessor@254] - Configuring CommitProcessor with 1 worker threads.
Re: Zookeeper 3.5.1 dynamic configuration fails with EOFException
Posted by Alexander Shraer <sh...@gmail.com>.
even if you start 2 as follower, it may restart leader election and drop a
connection since it learns about a more up to date configuration.
We didn't optimize such restarts for simplicity.
On Fri, Jun 10, 2016 at 9:16 PM, Alexander Shraer <sh...@gmail.com> wrote:
> In this specific case, the initial failure could be explained since server
> 1 will push its config to server 2, then server 2 finds out that instead
> of observer
> it must be a "non voting follower", which will cause it to throw an
> exception and load a different stack of protocols, and restarts leader
> election. This may
> explain the failure. Then they connect normally and 2 becomes FOLLOWING
> and gets an UPTODATE message as you see in the log. This looks ok.
> At the end, 2 isn't a real follower, in order to add it to the ensemble
> you need to issue a reconfig command.
>
> On Fri, Jun 10, 2016 at 3:18 PM, Sebastian Mattheis <
> Sebastian.Mattheis@bmw-carit.de> wrote:
>
>> Zookeeper 3.5.1 (
>> https://github.com/apache/zookeeper/releases/tag/release-3.5.1) dynamic
>> configuration fails with two servers that are started one after the other
>> throwing an EOFException. This is the same, if server 2 is configured as
>> observer or participant. Is the usage wrong? Is this a known bug?
>>
>> # server.1:
>>
>> ## /opt/zookeeper/var/myid
>> 1
>>
>> ## /opt/zookeeper/conf/zoo.cfg
>> autopurge.purgeInterval=1
>> initLimit=10
>> syncLimit=5
>> autopurge.snapRetainCount=4
>> tickTime=2000
>> dataDir=/opt/zookeeper/var
>> dataLogDir=/opt/zookeeper/logs
>> standaloneEnabled=false
>> dynamicConfigFile=/opt/zookeeper/conf/zoo.cfg.dynamic
>>
>> ## /opt/zookeeper/conf/zoo.cfg.dynamic
>> server.1=192.168.99.100:2888:3888;2181
>>
>> ## Output (on connection of server.2 after start-up):
>>
>> …
>> 2016-06-09 09:22:32,309 [myid:1] - INFO
>> [NIOServerCxnFactory.AcceptThread:/0.0.0.0:2181
>> :NIOServerCnxnFactory$AcceptThread@296] - Accepted socket connection
>> from /192.168.99.101:43222
>> 2016-06-09 09:22:32,378 [myid:1] - INFO
>> [NIOWorkerThread-1:ZooKeeperServer@964] - Client attempting to establish
>> new session at /192.168.99.101:43222
>> 2016-06-09 09:22:32,382 [myid:1] - INFO [SyncThread:1:FileTxnLog@200] -
>> Creating new log file: log.100000001
>> 2016-06-09 09:22:32,392 [myid:1] - INFO
>> [CommitProcWorkThread-1:ZooKeeperServer@678] - Established session
>> 0x10001af5f770000 with negotiated timeout 30000 for client /
>> 192.168.99.101:43222
>> 2016-06-09 09:22:32,410 [myid:1] - WARN
>> [NIOWorkerThread-1:NIOServerCnxn@365] - Unable to read additional data
>> from client sessionid 0x10001af5f770000, likely client has closed socket
>> 2016-06-09 09:22:32,411 [myid:1] - INFO
>> [NIOWorkerThread-1:MBeanRegistry@119] - Unregister MBean
>> [org.apache.ZooKeeperService:name0=ReplicatedServer_id1,name1=replica.1,name2=Leader,name3=Connections,name4=192.168.99.101,name5=0x10001af5f770000]
>> 2016-06-09 09:22:32,412 [myid:1] - INFO
>> [NIOWorkerThread-1:NIOServerCnxn@606] - Closed socket connection for
>> client /192.168.99.101:43222 which had sessionid 0x10001af5f770000
>> 2016-06-09 09:22:33,133 [myid:1] - INFO [/192.168.99.100:3888
>> :QuorumCnxManager$Listener@637] - Received connection request /
>> 192.168.99.101:44396
>> 2016-06-09 09:22:33,154 [myid:1] - WARN
>> [RecvWorker:2:QuorumCnxManager$RecvWorker@917] - Connection broken for
>> id 2, my id = 1, error =
>> java.io.EOFException
>> at java.io.DataInputStream.readInt(DataInputStream.java:392)
>> at
>> org.apache.zookeeper.server.quorum.QuorumCnxManager$RecvWorker.run(QuorumCnxManager.java:902)
>> 2016-06-09 09:22:33,158 [myid:1] - WARN
>> [RecvWorker:2:QuorumCnxManager$RecvWorker@920] - Interrupting SendWorker
>> 2016-06-09 09:22:33,159 [myid:1] - WARN
>> [SendWorker:2:QuorumCnxManager$SendWorker@834] - Interrupted while
>> waiting for message on queue
>> java.lang.InterruptedException
>> at
>> java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.reportInterruptAfterWait(AbstractQueuedSynchronizer.java:2014)
>> at
>> java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2088)
>> at
>> java.util.concurrent.ArrayBlockingQueue.poll(ArrayBlockingQueue.java:418)
>> at
>> org.apache.zookeeper.server.quorum.QuorumCnxManager.pollSendQueue(QuorumCnxManager.java:986)
>> at
>> org.apache.zookeeper.server.quorum.QuorumCnxManager.access$500(QuorumCnxManager.java:63)
>> at
>> org.apache.zookeeper.server.quorum.QuorumCnxManager$SendWorker.run(QuorumCnxManager.java:822)
>> 2016-06-09 09:22:33,164 [myid:1] - WARN
>> [SendWorker:2:QuorumCnxManager$SendWorker@843] - Send worker leaving
>> thread id 2 my id = 1
>> 2016-06-09 09:22:33,348 [myid:1] - INFO [/192.168.99.100:3888
>> :QuorumCnxManager$Listener@637] - Received connection request /
>> 192.168.99.101:44398
>> 2016-06-09 09:22:33,352 [myid:1] - ERROR
>> [SendWorker:2:QuorumCnxManager$SendWorker@810] - Failed to send last
>> message. Shutting down thread.
>> java.net.SocketException: Broken pipe
>> at java.net.SocketOutputStream.socketWrite0(Native Method)
>> at
>> java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:109)
>> at java.net.SocketOutputStream.write(SocketOutputStream.java:132)
>> at java.io.DataOutputStream.writeInt(DataOutputStream.java:200)
>> at
>> org.apache.zookeeper.server.quorum.QuorumCnxManager$SendWorker.send(QuorumCnxManager.java:779)
>> at
>> org.apache.zookeeper.server.quorum.QuorumCnxManager$SendWorker.run(QuorumCnxManager.java:806)
>> 2016-06-09 09:22:33,359 [myid:1] - INFO [/192.168.99.100:3888
>> :QuorumCnxManager$Listener@637] - Received connection request /
>> 192.168.99.101:44400
>> 2016-06-09 09:22:33,365 [myid:1] - WARN
>> [SendWorker:2:QuorumCnxManager$SendWorker@843] - Send worker leaving
>> thread id 2 my id = 1
>> 2016-06-09 09:22:33,366 [myid:1] - WARN
>> [RecvWorker:2:QuorumCnxManager$RecvWorker@920] - Interrupting SendWorker
>> 2016-06-09 09:22:33,413 [myid:1] - INFO
>> [LearnerHandler-/192.168.99.101:48832:LearnerHandler@385] - Follower
>> sid: 2 not in the current config 100000000
>> 2016-06-09 09:22:33,425 [myid:1] - INFO
>> [LearnerHandler-/192.168.99.101:48832:LearnerHandler@683] -
>> Synchronizing with Follower sid: 2 maxCommittedLog=0x100000001
>> minCommittedLog=0x100000001 lastProcessedZxid=0x100000001 peerLastZxid=0x0
>> 2016-06-09 09:22:33,427 [myid:1] - WARN
>> [LearnerHandler-/192.168.99.101:48832:ZKDatabase@310] - Unable to find
>> proposals from txnlog for zxid: 0
>> 2016-06-09 09:22:33,430 [myid:1] - INFO
>> [LearnerHandler-/192.168.99.101:48832:LearnerHandler@455] - Sending
>> snapshot last zxid of peer is 0x0, zxid of leader is 0x100000001, send zxid
>> of db as 0x100000001, 1 concurrent snapshots, snapshot was exempt from
>> throttle
>> 2016-06-09 09:23:03,908 [myid:1] - INFO
>> [SessionTracker:ZooKeeperServer@384] - Expiring session
>> 0x10001af5f770000, timeout of 30000ms exceeded
>> 2016-06-09 09:23:03,909 [myid:1] - INFO
>> [SessionTracker:QuorumZooKeeperServer@132] - Submitting global
>> closeSession request for session 0x10001af5f770000
>> 2016-06-09 09:23:03,910 [myid:1] - INFO [ProcessThread(sid:1
>> cport:-1)::PrepRequestProcessor@649] - Processed session termination for
>> sessionid: 0x10001af5f770000
>>
>> # server.2:
>>
>> ## /opt/zookeeper/var/myid
>> 2
>>
>> ## /opt/zookeeper/conf/zoo.cfg
>>
>> autopurge.purgeInterval=1
>> initLimit=10
>> syncLimit=5
>> autopurge.snapRetainCount=4
>> tickTime=2000
>> dataDir=/opt/zookeeper/var
>> dataLogDir=/opt/zookeeper/logs
>> standaloneEnabled=false
>> dynamicConfigFile=/opt/zookeeper/conf/zoo.cfg.dynamic
>>
>> ## /opt/zookeeper/conf/zoo.cfg.dynamic
>> server.2=192.168.99.101:2888:3888:observer;2181
>> server.1=192.168.99.100:2888:3888:participant;0.0.0.0:2181
>>
>> ## Output (on start-up):
>>
>> Using config: /opt/zookeeper/bin/../conf/zoo.cfg
>> 2016-06-09 09:22:32,833 [myid:] - INFO [main:QuorumPeerConfig@114] -
>> Reading configuration from: /opt/zookeeper/bin/../conf/zoo.cfg
>> 2016-06-09 09:22:32,847 [myid:] - INFO [main:QuorumPeerConfig@306] -
>> clientPort is not set
>> 2016-06-09 09:22:32,848 [myid:] - INFO [main:QuorumPeerConfig@320] -
>> secureClientPort is not set
>> 2016-06-09 09:22:32,853 [myid:] - WARN [main:QuorumPeerConfig@555] - No
>> server failure will be tolerated. You need at least 3 servers.
>> 2016-06-09 09:22:32,863 [myid:2] - INFO [main:DatadirCleanupManager@78]
>> - autopurge.snapRetainCount set to 4
>> 2016-06-09 09:22:32,863 [myid:2] - INFO [main:DatadirCleanupManager@79]
>> - autopurge.purgeInterval set to 1
>> 2016-06-09 09:22:32,869 [myid:2] - INFO
>> [PurgeTask:DatadirCleanupManager$PurgeTask@138] - Purge task started.
>> 2016-06-09 09:22:32,888 [myid:2] - INFO [main:QuorumPeerMain@136] -
>> Starting quorum peer
>> 2016-06-09 09:22:32,893 [myid:2] - INFO
>> [PurgeTask:DatadirCleanupManager$PurgeTask@144] - Purge task completed.
>> 2016-06-09 09:22:32,910 [myid:2] - INFO [main:NIOServerCnxnFactory@673]
>> - Configuring NIO connection handler with 10s sessionless connection
>> timeout, 1 selector thread(s), 2 worker threads, and 64 kB direct buffers.
>> 2016-06-09 09:22:32,916 [myid:2] - INFO [main:NIOServerCnxnFactory@686]
>> - binding to port /0.0.0.0:2181
>> 2016-06-09 09:22:32,979 [myid:2] - INFO [main:Slf4jLog@67] - Logging to
>> org.slf4j.impl.Log4jLoggerAdapter(org.mortbay.log) via
>> org.mortbay.log.Slf4jLog
>> 2016-06-09 09:22:33,019 [myid:2] - INFO [main:QuorumPeer@1280] - Local
>> sessions disabled
>> 2016-06-09 09:22:33,022 [myid:2] - INFO [main:QuorumPeer@1291] - Local
>> session upgrading disabled
>> 2016-06-09 09:22:33,023 [myid:2] - INFO [main:QuorumPeer@1258] -
>> tickTime set to 2000
>> 2016-06-09 09:22:33,023 [myid:2] - INFO [main:QuorumPeer@1302] -
>> minSessionTimeout set to 4000
>> 2016-06-09 09:22:33,025 [myid:2] - INFO [main:QuorumPeer@1313] -
>> maxSessionTimeout set to 40000
>> 2016-06-09 09:22:33,026 [myid:2] - INFO [main:QuorumPeer@1328] -
>> initLimit set to 10
>> 2016-06-09 09:22:33,041 [myid:2] - INFO [main:QuorumPeer@744] -
>> currentEpoch not found! Creating with a reasonable default of 0. This
>> should only happen when you are upgrading your installation
>> 2016-06-09 09:22:33,056 [myid:2] - INFO [main:QuorumPeer@759] -
>> acceptedEpoch not found! Creating with a reasonable default of 0. This
>> should only happen when you are upgrading your installation
>> 2016-06-09 09:22:33,061 [myid:2] - INFO [main:Slf4jLog@67] -
>> jetty-6.1.26
>> 2016-06-09 09:22:33,100 [myid:2] - INFO [main:Slf4jLog@67] - Started
>> SelectChannelConnector@0.0.0.0:8080
>> 2016-06-09 09:22:33,104 [myid:2] - INFO [main:JettyAdminServer@105] -
>> Started AdminServer on address 0.0.0.0, port 8080 and command URL /commands
>> 2016-06-09 09:22:33,112 [myid:2] - INFO
>> [QuorumPeerListener:QuorumCnxManager$Listener@631] - My election bind
>> port: /192.168.99.101:3888
>> 2016-06-09 09:22:33,125 [myid:2] - INFO
>> [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):QuorumPeer@986]
>> - LOOKING
>> 2016-06-09 09:22:33,127 [myid:2] - INFO
>> [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):FastLeaderElection@894]
>> - New election. My id = 2, proposed zxid=0x0
>> 2016-06-09 09:22:33,142 [myid:2] - INFO
>> [WorkerReceiver[myid=2]:FastLeaderElection@688] - Notification: 2
>> (message format version), 2 (n.leader), 0x0 (n.zxid), 0x1 (n.round),
>> LOOKING (n.state), 2 (n.sid), 0x0 (n.peerEPoch), LOOKING (my state)0
>> (n.config version)
>> 2016-06-09 09:22:33,150 [myid:2] - INFO
>> [WorkerReceiver[myid=2]:FastLeaderElection$Messenger$WorkerReceiver@294]
>> - 2 Received version: 100000000 my version: 0
>> 2016-06-09 09:22:33,156 [myid:2] - INFO
>> [WorkerReceiver[myid=2]:FastLeaderElection$Messenger$WorkerReceiver@301]
>> - restarting leader election
>> 2016-06-09 09:22:33,157 [myid:2] - INFO [/192.168.99.101:3888
>> :QuorumCnxManager$Listener@659] - Leaving listener
>> 2016-06-09 09:22:33,163 [myid:2] - WARN
>> [RecvWorker:1:QuorumCnxManager$RecvWorker@917] - Connection broken for
>> id 1, my id = 2, error =
>> java.net.SocketException: Socket closed
>> at java.net.SocketInputStream.socketRead0(Native Method)
>> at
>> java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
>> at java.net.SocketInputStream.read(SocketInputStream.java:170)
>> at java.net.SocketInputStream.read(SocketInputStream.java:141)
>> at java.net.SocketInputStream.read(SocketInputStream.java:223)
>> at java.io.DataInputStream.readInt(DataInputStream.java:387)
>> at
>> org.apache.zookeeper.server.quorum.QuorumCnxManager$RecvWorker.run(QuorumCnxManager.java:902)
>> 2016-06-09 09:22:33,166 [myid:2] - INFO
>> [WorkerReceiver[myid=2]:FastLeaderElection$Messenger$WorkerReceiver@440]
>> - WorkerReceiver is down
>> 2016-06-09 09:22:33,166 [myid:2] - WARN
>> [SendWorker:1:QuorumCnxManager$SendWorker@834] - Interrupted while
>> waiting for message on queue
>> java.lang.InterruptedException
>> at
>> java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.reportInterruptAfterWait(AbstractQueuedSynchronizer.java:2014)
>> at
>> java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2088)
>> at
>> java.util.concurrent.ArrayBlockingQueue.poll(ArrayBlockingQueue.java:418)
>> at
>> org.apache.zookeeper.server.quorum.QuorumCnxManager.pollSendQueue(QuorumCnxManager.java:986)
>> at
>> org.apache.zookeeper.server.quorum.QuorumCnxManager.access$500(QuorumCnxManager.java:63)
>> at
>> org.apache.zookeeper.server.quorum.QuorumCnxManager$SendWorker.run(QuorumCnxManager.java:822)
>> 2016-06-09 09:22:33,173 [myid:2] - WARN
>> [SendWorker:1:QuorumCnxManager$SendWorker@843] - Send worker leaving
>> thread id 1 my id = 2
>> 2016-06-09 09:22:33,174 [myid:2] - WARN
>> [RecvWorker:1:QuorumCnxManager$RecvWorker@920] - Interrupting SendWorker
>> 2016-06-09 09:22:33,350 [myid:2] - INFO
>> [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):FastLeaderElection@928]
>> - Notification time out: 400
>> 2016-06-09 09:22:33,353 [myid:2] - INFO
>> [WorkerSender[myid=2]:FastLeaderElection$Messenger$WorkerSender@470] -
>> WorkerSender is down
>> 2016-06-09 09:22:33,354 [myid:2] - INFO
>> [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):MBeanRegistry@119]
>> - Unregister MBean
>> [org.apache.ZooKeeperService:name0=ReplicatedServer_id2,name1=replica.2,name2=LeaderElection]
>> 2016-06-09 09:22:33,355 [myid:2] - INFO
>> [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):QuorumPeer@986]
>> - LOOKING
>> 2016-06-09 09:22:33,356 [myid:2] - WARN
>> [RecvWorker:1:QuorumCnxManager$RecvWorker@920] - Interrupting SendWorker
>> 2016-06-09 09:22:33,357 [myid:2] - INFO
>> [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):FastLeaderElection@894]
>> - New election. My id = 2, proposed zxid=0x0
>> 2016-06-09 09:22:33,359 [myid:2] - INFO
>> [QuorumPeerListener:QuorumCnxManager$Listener@631] - My election bind
>> port: /192.168.99.101:3888
>> 2016-06-09 09:22:33,358 [myid:2] - WARN
>> [SendWorker:1:QuorumCnxManager$SendWorker@843] - Send worker leaving
>> thread id 1 my id = 2
>> 2016-06-09 09:22:33,374 [myid:2] - INFO
>> [WorkerReceiver[myid=2]:FastLeaderElection@688] - Notification: 2
>> (message format version), 1 (n.leader), 0x0 (n.zxid), 0x1 (n.round),
>> LEADING (n.state), 1 (n.sid), 0x1 (n.peerEPoch), LOOKING (my
>> state)100000000 (n.config version)
>> 2016-06-09 09:22:33,376 [myid:2] - INFO
>> [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):MBeanRegistry@119]
>> - Unregister MBean
>> [org.apache.ZooKeeperService:name0=ReplicatedServer_id2,name1=replica.2,name2=LeaderElection]
>> 2016-06-09 09:22:33,378 [myid:2] - INFO
>> [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):QuorumPeer@1062]
>> - FOLLOWING
>> 2016-06-09 09:22:33,385 [myid:2] - INFO
>> [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):Learner@88]
>> - TCP NoDelay set to: true
>> 2016-06-09 09:22:33,385 [myid:2] - INFO
>> [WorkerReceiver[myid=2]:FastLeaderElection@688] - Notification: 2
>> (message format version), 1 (n.leader), 0x0 (n.zxid), 0x1 (n.round),
>> LEADING (n.state), 1 (n.sid), 0x1 (n.peerEPoch), FOLLOWING (my
>> state)100000000 (n.config version)
>> 2016-06-09 09:22:33,394 [myid:2] - INFO
>> [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):Environment@109]
>> - Server environment:zookeeper.version=3.5.1-alpha--1, built on 06/09/2016
>> 09:19 GMT
>> 2016-06-09 09:22:33,395 [myid:2] - INFO
>> [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):Environment@109]
>> - Server environment:host.name=footstep-server-2
>> 2016-06-09 09:22:33,395 [myid:2] - INFO
>> [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):Environment@109]
>> - Server environment:java.version=1.8.0_91
>> 2016-06-09 09:22:33,396 [myid:2] - INFO
>> [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):Environment@109]
>> - Server environment:java.vendor=Oracle Corporation
>> 2016-06-09 09:22:33,396 [myid:2] - INFO
>> [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):Environment@109]
>> - Server environment:java.home=/usr/lib/jvm/java-8-openjdk-amd64/jre
>> 2016-06-09 09:22:33,397 [myid:2] - INFO
>> [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):Environment@109]
>> - Server
>> environment:java.class.path=/opt/zookeeper/bin/../build/classes:/opt/zookeeper/bin/../build/lib/slf4j-log4j12-1.7.5.jar:/opt/zookeeper/bin/../build/lib/slf4j-api-1.7.5.jar:/opt/zookeeper/bin/../build/lib/servlet-api-2.5-20081211.jar:/opt/zookeeper/bin/../build/lib/netty-3.7.0.Final.jar:/opt/zookeeper/bin/../build/lib/log4j-1.2.16.jar:/opt/zookeeper/bin/../build/lib/jline-2.11.jar:/opt/zookeeper/bin/../build/lib/jetty-util-6.1.26.jar:/opt/zookeeper/bin/../build/lib/jetty-6.1.26.jar:/opt/zookeeper/bin/../build/lib/javacc.jar:/opt/zookeeper/bin/../build/lib/jackson-mapper-asl-1.9.11.jar:/opt/zookeeper/bin/../build/lib/jackson-core-asl-1.9.11.jar:/opt/zookeeper/bin/../build/lib/commons-cli-1.2.jar:/opt/zookeeper/bin/../lib/*.jar:/opt/zookeeper/bin/../zookeeper-*.jar:/opt/zookeeper/bin/../src/java/lib/ivy-2.2.0.jar:/opt/zookeeper/bin/../conf:
>> 2016-06-09 09:22:33,397 [myid:2] - INFO
>> [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):Environment@109]
>> - Server
>> environment:java.library.path=/usr/java/packages/lib/amd64:/usr/lib/x86_64-linux-gnu/jni:/lib/x86_64-linux-gnu:/usr/lib/x86_64-linux-gnu:/usr/lib/jni:/lib:/usr/lib
>> 2016-06-09 09:22:33,398 [myid:2] - INFO
>> [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):Environment@109]
>> - Server environment:java.io.tmpdir=/tmp
>> 2016-06-09 09:22:33,398 [myid:2] - INFO
>> [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):Environment@109]
>> - Server environment:java.compiler=<NA>
>> 2016-06-09 09:22:33,399 [myid:2] - INFO
>> [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):Environment@109]
>> - Server environment:os.name=Linux
>> 2016-06-09 09:22:33,399 [myid:2] - INFO
>> [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):Environment@109]
>> - Server environment:os.arch=amd64
>> 2016-06-09 09:22:33,399 [myid:2] - INFO
>> [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):Environment@109]
>> - Server environment:os.version=4.4.12-boot2docker
>> 2016-06-09 09:22:33,400 [myid:2] - INFO
>> [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):Environment@109]
>> - Server environment:user.name=root
>> 2016-06-09 09:22:33,401 [myid:2] - INFO
>> [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):Environment@109]
>> - Server environment:user.home=/root
>> 2016-06-09 09:22:33,401 [myid:2] - INFO
>> [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):Environment@109]
>> - Server environment:user.dir=/
>> 2016-06-09 09:22:33,401 [myid:2] - INFO
>> [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):Environment@109]
>> - Server environment:os.memory.free=9MB
>> 2016-06-09 09:22:33,402 [myid:2] - INFO
>> [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):Environment@109]
>> - Server environment:os.memory.max=966MB
>> 2016-06-09 09:22:33,402 [myid:2] - INFO
>> [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):Environment@109]
>> - Server environment:os.memory.total=15MB
>> 2016-06-09 09:22:33,403 [myid:2] - INFO
>> [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):ZooKeeperServer@858]
>> - minSessionTimeout set to 4000
>> 2016-06-09 09:22:33,404 [myid:2] - INFO
>> [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):ZooKeeperServer@867]
>> - maxSessionTimeout set to 40000
>> 2016-06-09 09:22:33,405 [myid:2] - INFO
>> [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):ZooKeeperServer@156]
>> - Created server with tickTime 2000 minSessionTimeout 4000
>> maxSessionTimeout 40000 datadir /opt/zookeeper/logs/version-2 snapdir
>> /opt/zookeeper/var/version-2
>> 2016-06-09 09:22:33,406 [myid:2] - INFO
>> [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):Follower@66]
>> - FOLLOWING - LEADER ELECTION TOOK - 28
>> 2016-06-09 09:22:33,434 [myid:2] - INFO
>> [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):Learner@369]
>> - Getting a snapshot from leader
>> 2016-06-09 09:22:33,442 [myid:2] - INFO
>> [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):Learner@509]
>> - Learner received NEWLEADER message
>> 2016-06-09 09:22:33,446 [myid:2] - INFO
>> [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):FileTxnSnapLog@298]
>> - Snapshotting: 0x100000001 to
>> /opt/zookeeper/var/version-2/snapshot.100000001
>> 2016-06-09 09:22:33,452 [myid:2] - INFO
>> [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):Learner@493]
>> - Learner received UPTODATE message
>> 2016-06-09 09:22:33,457 [myid:2] - INFO
>> [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):CommitProcessor@254]
>> - Configuring CommitProcessor with 1 worker threads.
>>
>>
>>
>
Re: Zookeeper 3.5.1 dynamic configuration fails with EOFException
Posted by Alexander Shraer <sh...@gmail.com>.
In this specific case, the initial failure could be explained since server
1 will push its config to server 2, then server 2 finds out that instead
of observer
it must be a "non voting follower", which will cause it to throw an
exception and load a different stack of protocols, and restarts leader
election. This may
explain the failure. Then they connect normally and 2 becomes FOLLOWING and
gets an UPTODATE message as you see in the log. This looks ok.
At the end, 2 isn't a real follower, in order to add it to the ensemble you
need to issue a reconfig command.
On Fri, Jun 10, 2016 at 3:18 PM, Sebastian Mattheis <
Sebastian.Mattheis@bmw-carit.de> wrote:
> Zookeeper 3.5.1 (
> https://github.com/apache/zookeeper/releases/tag/release-3.5.1) dynamic
> configuration fails with two servers that are started one after the other
> throwing an EOFException. This is the same, if server 2 is configured as
> observer or participant. Is the usage wrong? Is this a known bug?
>
> # server.1:
>
> ## /opt/zookeeper/var/myid
> 1
>
> ## /opt/zookeeper/conf/zoo.cfg
> autopurge.purgeInterval=1
> initLimit=10
> syncLimit=5
> autopurge.snapRetainCount=4
> tickTime=2000
> dataDir=/opt/zookeeper/var
> dataLogDir=/opt/zookeeper/logs
> standaloneEnabled=false
> dynamicConfigFile=/opt/zookeeper/conf/zoo.cfg.dynamic
>
> ## /opt/zookeeper/conf/zoo.cfg.dynamic
> server.1=192.168.99.100:2888:3888;2181
>
> ## Output (on connection of server.2 after start-up):
>
> …
> 2016-06-09 09:22:32,309 [myid:1] - INFO
> [NIOServerCxnFactory.AcceptThread:/0.0.0.0:2181
> :NIOServerCnxnFactory$AcceptThread@296] - Accepted socket connection from
> /192.168.99.101:43222
> 2016-06-09 09:22:32,378 [myid:1] - INFO
> [NIOWorkerThread-1:ZooKeeperServer@964] - Client attempting to establish
> new session at /192.168.99.101:43222
> 2016-06-09 09:22:32,382 [myid:1] - INFO [SyncThread:1:FileTxnLog@200] -
> Creating new log file: log.100000001
> 2016-06-09 09:22:32,392 [myid:1] - INFO
> [CommitProcWorkThread-1:ZooKeeperServer@678] - Established session
> 0x10001af5f770000 with negotiated timeout 30000 for client /
> 192.168.99.101:43222
> 2016-06-09 09:22:32,410 [myid:1] - WARN
> [NIOWorkerThread-1:NIOServerCnxn@365] - Unable to read additional data
> from client sessionid 0x10001af5f770000, likely client has closed socket
> 2016-06-09 09:22:32,411 [myid:1] - INFO
> [NIOWorkerThread-1:MBeanRegistry@119] - Unregister MBean
> [org.apache.ZooKeeperService:name0=ReplicatedServer_id1,name1=replica.1,name2=Leader,name3=Connections,name4=192.168.99.101,name5=0x10001af5f770000]
> 2016-06-09 09:22:32,412 [myid:1] - INFO
> [NIOWorkerThread-1:NIOServerCnxn@606] - Closed socket connection for
> client /192.168.99.101:43222 which had sessionid 0x10001af5f770000
> 2016-06-09 09:22:33,133 [myid:1] - INFO [/192.168.99.100:3888
> :QuorumCnxManager$Listener@637] - Received connection request /
> 192.168.99.101:44396
> 2016-06-09 09:22:33,154 [myid:1] - WARN
> [RecvWorker:2:QuorumCnxManager$RecvWorker@917] - Connection broken for id
> 2, my id = 1, error =
> java.io.EOFException
> at java.io.DataInputStream.readInt(DataInputStream.java:392)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager$RecvWorker.run(QuorumCnxManager.java:902)
> 2016-06-09 09:22:33,158 [myid:1] - WARN
> [RecvWorker:2:QuorumCnxManager$RecvWorker@920] - Interrupting SendWorker
> 2016-06-09 09:22:33,159 [myid:1] - WARN
> [SendWorker:2:QuorumCnxManager$SendWorker@834] - Interrupted while
> waiting for message on queue
> java.lang.InterruptedException
> at
> java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.reportInterruptAfterWait(AbstractQueuedSynchronizer.java:2014)
> at
> java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2088)
> at
> java.util.concurrent.ArrayBlockingQueue.poll(ArrayBlockingQueue.java:418)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager.pollSendQueue(QuorumCnxManager.java:986)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager.access$500(QuorumCnxManager.java:63)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager$SendWorker.run(QuorumCnxManager.java:822)
> 2016-06-09 09:22:33,164 [myid:1] - WARN
> [SendWorker:2:QuorumCnxManager$SendWorker@843] - Send worker leaving
> thread id 2 my id = 1
> 2016-06-09 09:22:33,348 [myid:1] - INFO [/192.168.99.100:3888
> :QuorumCnxManager$Listener@637] - Received connection request /
> 192.168.99.101:44398
> 2016-06-09 09:22:33,352 [myid:1] - ERROR
> [SendWorker:2:QuorumCnxManager$SendWorker@810] - Failed to send last
> message. Shutting down thread.
> java.net.SocketException: Broken pipe
> at java.net.SocketOutputStream.socketWrite0(Native Method)
> at
> java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:109)
> at java.net.SocketOutputStream.write(SocketOutputStream.java:132)
> at java.io.DataOutputStream.writeInt(DataOutputStream.java:200)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager$SendWorker.send(QuorumCnxManager.java:779)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager$SendWorker.run(QuorumCnxManager.java:806)
> 2016-06-09 09:22:33,359 [myid:1] - INFO [/192.168.99.100:3888
> :QuorumCnxManager$Listener@637] - Received connection request /
> 192.168.99.101:44400
> 2016-06-09 09:22:33,365 [myid:1] - WARN
> [SendWorker:2:QuorumCnxManager$SendWorker@843] - Send worker leaving
> thread id 2 my id = 1
> 2016-06-09 09:22:33,366 [myid:1] - WARN
> [RecvWorker:2:QuorumCnxManager$RecvWorker@920] - Interrupting SendWorker
> 2016-06-09 09:22:33,413 [myid:1] - INFO
> [LearnerHandler-/192.168.99.101:48832:LearnerHandler@385] - Follower sid:
> 2 not in the current config 100000000
> 2016-06-09 09:22:33,425 [myid:1] - INFO
> [LearnerHandler-/192.168.99.101:48832:LearnerHandler@683] - Synchronizing
> with Follower sid: 2 maxCommittedLog=0x100000001
> minCommittedLog=0x100000001 lastProcessedZxid=0x100000001 peerLastZxid=0x0
> 2016-06-09 09:22:33,427 [myid:1] - WARN
> [LearnerHandler-/192.168.99.101:48832:ZKDatabase@310] - Unable to find
> proposals from txnlog for zxid: 0
> 2016-06-09 09:22:33,430 [myid:1] - INFO
> [LearnerHandler-/192.168.99.101:48832:LearnerHandler@455] - Sending
> snapshot last zxid of peer is 0x0, zxid of leader is 0x100000001, send zxid
> of db as 0x100000001, 1 concurrent snapshots, snapshot was exempt from
> throttle
> 2016-06-09 09:23:03,908 [myid:1] - INFO
> [SessionTracker:ZooKeeperServer@384] - Expiring session
> 0x10001af5f770000, timeout of 30000ms exceeded
> 2016-06-09 09:23:03,909 [myid:1] - INFO
> [SessionTracker:QuorumZooKeeperServer@132] - Submitting global
> closeSession request for session 0x10001af5f770000
> 2016-06-09 09:23:03,910 [myid:1] - INFO [ProcessThread(sid:1
> cport:-1)::PrepRequestProcessor@649] - Processed session termination for
> sessionid: 0x10001af5f770000
>
> # server.2:
>
> ## /opt/zookeeper/var/myid
> 2
>
> ## /opt/zookeeper/conf/zoo.cfg
>
> autopurge.purgeInterval=1
> initLimit=10
> syncLimit=5
> autopurge.snapRetainCount=4
> tickTime=2000
> dataDir=/opt/zookeeper/var
> dataLogDir=/opt/zookeeper/logs
> standaloneEnabled=false
> dynamicConfigFile=/opt/zookeeper/conf/zoo.cfg.dynamic
>
> ## /opt/zookeeper/conf/zoo.cfg.dynamic
> server.2=192.168.99.101:2888:3888:observer;2181
> server.1=192.168.99.100:2888:3888:participant;0.0.0.0:2181
>
> ## Output (on start-up):
>
> Using config: /opt/zookeeper/bin/../conf/zoo.cfg
> 2016-06-09 09:22:32,833 [myid:] - INFO [main:QuorumPeerConfig@114] -
> Reading configuration from: /opt/zookeeper/bin/../conf/zoo.cfg
> 2016-06-09 09:22:32,847 [myid:] - INFO [main:QuorumPeerConfig@306] -
> clientPort is not set
> 2016-06-09 09:22:32,848 [myid:] - INFO [main:QuorumPeerConfig@320] -
> secureClientPort is not set
> 2016-06-09 09:22:32,853 [myid:] - WARN [main:QuorumPeerConfig@555] - No
> server failure will be tolerated. You need at least 3 servers.
> 2016-06-09 09:22:32,863 [myid:2] - INFO [main:DatadirCleanupManager@78]
> - autopurge.snapRetainCount set to 4
> 2016-06-09 09:22:32,863 [myid:2] - INFO [main:DatadirCleanupManager@79]
> - autopurge.purgeInterval set to 1
> 2016-06-09 09:22:32,869 [myid:2] - INFO
> [PurgeTask:DatadirCleanupManager$PurgeTask@138] - Purge task started.
> 2016-06-09 09:22:32,888 [myid:2] - INFO [main:QuorumPeerMain@136] -
> Starting quorum peer
> 2016-06-09 09:22:32,893 [myid:2] - INFO
> [PurgeTask:DatadirCleanupManager$PurgeTask@144] - Purge task completed.
> 2016-06-09 09:22:32,910 [myid:2] - INFO [main:NIOServerCnxnFactory@673]
> - Configuring NIO connection handler with 10s sessionless connection
> timeout, 1 selector thread(s), 2 worker threads, and 64 kB direct buffers.
> 2016-06-09 09:22:32,916 [myid:2] - INFO [main:NIOServerCnxnFactory@686]
> - binding to port /0.0.0.0:2181
> 2016-06-09 09:22:32,979 [myid:2] - INFO [main:Slf4jLog@67] - Logging to
> org.slf4j.impl.Log4jLoggerAdapter(org.mortbay.log) via
> org.mortbay.log.Slf4jLog
> 2016-06-09 09:22:33,019 [myid:2] - INFO [main:QuorumPeer@1280] - Local
> sessions disabled
> 2016-06-09 09:22:33,022 [myid:2] - INFO [main:QuorumPeer@1291] - Local
> session upgrading disabled
> 2016-06-09 09:22:33,023 [myid:2] - INFO [main:QuorumPeer@1258] -
> tickTime set to 2000
> 2016-06-09 09:22:33,023 [myid:2] - INFO [main:QuorumPeer@1302] -
> minSessionTimeout set to 4000
> 2016-06-09 09:22:33,025 [myid:2] - INFO [main:QuorumPeer@1313] -
> maxSessionTimeout set to 40000
> 2016-06-09 09:22:33,026 [myid:2] - INFO [main:QuorumPeer@1328] -
> initLimit set to 10
> 2016-06-09 09:22:33,041 [myid:2] - INFO [main:QuorumPeer@744] -
> currentEpoch not found! Creating with a reasonable default of 0. This
> should only happen when you are upgrading your installation
> 2016-06-09 09:22:33,056 [myid:2] - INFO [main:QuorumPeer@759] -
> acceptedEpoch not found! Creating with a reasonable default of 0. This
> should only happen when you are upgrading your installation
> 2016-06-09 09:22:33,061 [myid:2] - INFO [main:Slf4jLog@67] - jetty-6.1.26
> 2016-06-09 09:22:33,100 [myid:2] - INFO [main:Slf4jLog@67] - Started
> SelectChannelConnector@0.0.0.0:8080
> 2016-06-09 09:22:33,104 [myid:2] - INFO [main:JettyAdminServer@105] -
> Started AdminServer on address 0.0.0.0, port 8080 and command URL /commands
> 2016-06-09 09:22:33,112 [myid:2] - INFO
> [QuorumPeerListener:QuorumCnxManager$Listener@631] - My election bind
> port: /192.168.99.101:3888
> 2016-06-09 09:22:33,125 [myid:2] - INFO
> [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):QuorumPeer@986]
> - LOOKING
> 2016-06-09 09:22:33,127 [myid:2] - INFO
> [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):FastLeaderElection@894]
> - New election. My id = 2, proposed zxid=0x0
> 2016-06-09 09:22:33,142 [myid:2] - INFO
> [WorkerReceiver[myid=2]:FastLeaderElection@688] - Notification: 2
> (message format version), 2 (n.leader), 0x0 (n.zxid), 0x1 (n.round),
> LOOKING (n.state), 2 (n.sid), 0x0 (n.peerEPoch), LOOKING (my state)0
> (n.config version)
> 2016-06-09 09:22:33,150 [myid:2] - INFO
> [WorkerReceiver[myid=2]:FastLeaderElection$Messenger$WorkerReceiver@294]
> - 2 Received version: 100000000 my version: 0
> 2016-06-09 09:22:33,156 [myid:2] - INFO
> [WorkerReceiver[myid=2]:FastLeaderElection$Messenger$WorkerReceiver@301]
> - restarting leader election
> 2016-06-09 09:22:33,157 [myid:2] - INFO [/192.168.99.101:3888
> :QuorumCnxManager$Listener@659] - Leaving listener
> 2016-06-09 09:22:33,163 [myid:2] - WARN
> [RecvWorker:1:QuorumCnxManager$RecvWorker@917] - Connection broken for id
> 1, my id = 2, error =
> java.net.SocketException: Socket closed
> at java.net.SocketInputStream.socketRead0(Native Method)
> at
> java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
> at java.net.SocketInputStream.read(SocketInputStream.java:170)
> at java.net.SocketInputStream.read(SocketInputStream.java:141)
> at java.net.SocketInputStream.read(SocketInputStream.java:223)
> at java.io.DataInputStream.readInt(DataInputStream.java:387)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager$RecvWorker.run(QuorumCnxManager.java:902)
> 2016-06-09 09:22:33,166 [myid:2] - INFO
> [WorkerReceiver[myid=2]:FastLeaderElection$Messenger$WorkerReceiver@440]
> - WorkerReceiver is down
> 2016-06-09 09:22:33,166 [myid:2] - WARN
> [SendWorker:1:QuorumCnxManager$SendWorker@834] - Interrupted while
> waiting for message on queue
> java.lang.InterruptedException
> at
> java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.reportInterruptAfterWait(AbstractQueuedSynchronizer.java:2014)
> at
> java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2088)
> at
> java.util.concurrent.ArrayBlockingQueue.poll(ArrayBlockingQueue.java:418)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager.pollSendQueue(QuorumCnxManager.java:986)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager.access$500(QuorumCnxManager.java:63)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager$SendWorker.run(QuorumCnxManager.java:822)
> 2016-06-09 09:22:33,173 [myid:2] - WARN
> [SendWorker:1:QuorumCnxManager$SendWorker@843] - Send worker leaving
> thread id 1 my id = 2
> 2016-06-09 09:22:33,174 [myid:2] - WARN
> [RecvWorker:1:QuorumCnxManager$RecvWorker@920] - Interrupting SendWorker
> 2016-06-09 09:22:33,350 [myid:2] - INFO
> [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):FastLeaderElection@928]
> - Notification time out: 400
> 2016-06-09 09:22:33,353 [myid:2] - INFO
> [WorkerSender[myid=2]:FastLeaderElection$Messenger$WorkerSender@470] -
> WorkerSender is down
> 2016-06-09 09:22:33,354 [myid:2] - INFO
> [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):MBeanRegistry@119]
> - Unregister MBean
> [org.apache.ZooKeeperService:name0=ReplicatedServer_id2,name1=replica.2,name2=LeaderElection]
> 2016-06-09 09:22:33,355 [myid:2] - INFO
> [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):QuorumPeer@986]
> - LOOKING
> 2016-06-09 09:22:33,356 [myid:2] - WARN
> [RecvWorker:1:QuorumCnxManager$RecvWorker@920] - Interrupting SendWorker
> 2016-06-09 09:22:33,357 [myid:2] - INFO
> [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):FastLeaderElection@894]
> - New election. My id = 2, proposed zxid=0x0
> 2016-06-09 09:22:33,359 [myid:2] - INFO
> [QuorumPeerListener:QuorumCnxManager$Listener@631] - My election bind
> port: /192.168.99.101:3888
> 2016-06-09 09:22:33,358 [myid:2] - WARN
> [SendWorker:1:QuorumCnxManager$SendWorker@843] - Send worker leaving
> thread id 1 my id = 2
> 2016-06-09 09:22:33,374 [myid:2] - INFO
> [WorkerReceiver[myid=2]:FastLeaderElection@688] - Notification: 2
> (message format version), 1 (n.leader), 0x0 (n.zxid), 0x1 (n.round),
> LEADING (n.state), 1 (n.sid), 0x1 (n.peerEPoch), LOOKING (my
> state)100000000 (n.config version)
> 2016-06-09 09:22:33,376 [myid:2] - INFO
> [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):MBeanRegistry@119]
> - Unregister MBean
> [org.apache.ZooKeeperService:name0=ReplicatedServer_id2,name1=replica.2,name2=LeaderElection]
> 2016-06-09 09:22:33,378 [myid:2] - INFO
> [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):QuorumPeer@1062]
> - FOLLOWING
> 2016-06-09 09:22:33,385 [myid:2] - INFO
> [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):Learner@88]
> - TCP NoDelay set to: true
> 2016-06-09 09:22:33,385 [myid:2] - INFO
> [WorkerReceiver[myid=2]:FastLeaderElection@688] - Notification: 2
> (message format version), 1 (n.leader), 0x0 (n.zxid), 0x1 (n.round),
> LEADING (n.state), 1 (n.sid), 0x1 (n.peerEPoch), FOLLOWING (my
> state)100000000 (n.config version)
> 2016-06-09 09:22:33,394 [myid:2] - INFO
> [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):Environment@109]
> - Server environment:zookeeper.version=3.5.1-alpha--1, built on 06/09/2016
> 09:19 GMT
> 2016-06-09 09:22:33,395 [myid:2] - INFO
> [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):Environment@109]
> - Server environment:host.name=footstep-server-2
> 2016-06-09 09:22:33,395 [myid:2] - INFO
> [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):Environment@109]
> - Server environment:java.version=1.8.0_91
> 2016-06-09 09:22:33,396 [myid:2] - INFO
> [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):Environment@109]
> - Server environment:java.vendor=Oracle Corporation
> 2016-06-09 09:22:33,396 [myid:2] - INFO
> [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):Environment@109]
> - Server environment:java.home=/usr/lib/jvm/java-8-openjdk-amd64/jre
> 2016-06-09 09:22:33,397 [myid:2] - INFO
> [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):Environment@109]
> - Server
> environment:java.class.path=/opt/zookeeper/bin/../build/classes:/opt/zookeeper/bin/../build/lib/slf4j-log4j12-1.7.5.jar:/opt/zookeeper/bin/../build/lib/slf4j-api-1.7.5.jar:/opt/zookeeper/bin/../build/lib/servlet-api-2.5-20081211.jar:/opt/zookeeper/bin/../build/lib/netty-3.7.0.Final.jar:/opt/zookeeper/bin/../build/lib/log4j-1.2.16.jar:/opt/zookeeper/bin/../build/lib/jline-2.11.jar:/opt/zookeeper/bin/../build/lib/jetty-util-6.1.26.jar:/opt/zookeeper/bin/../build/lib/jetty-6.1.26.jar:/opt/zookeeper/bin/../build/lib/javacc.jar:/opt/zookeeper/bin/../build/lib/jackson-mapper-asl-1.9.11.jar:/opt/zookeeper/bin/../build/lib/jackson-core-asl-1.9.11.jar:/opt/zookeeper/bin/../build/lib/commons-cli-1.2.jar:/opt/zookeeper/bin/../lib/*.jar:/opt/zookeeper/bin/../zookeeper-*.jar:/opt/zookeeper/bin/../src/java/lib/ivy-2.2.0.jar:/opt/zookeeper/bin/../conf:
> 2016-06-09 09:22:33,397 [myid:2] - INFO
> [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):Environment@109]
> - Server
> environment:java.library.path=/usr/java/packages/lib/amd64:/usr/lib/x86_64-linux-gnu/jni:/lib/x86_64-linux-gnu:/usr/lib/x86_64-linux-gnu:/usr/lib/jni:/lib:/usr/lib
> 2016-06-09 09:22:33,398 [myid:2] - INFO
> [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):Environment@109]
> - Server environment:java.io.tmpdir=/tmp
> 2016-06-09 09:22:33,398 [myid:2] - INFO
> [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):Environment@109]
> - Server environment:java.compiler=<NA>
> 2016-06-09 09:22:33,399 [myid:2] - INFO
> [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):Environment@109]
> - Server environment:os.name=Linux
> 2016-06-09 09:22:33,399 [myid:2] - INFO
> [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):Environment@109]
> - Server environment:os.arch=amd64
> 2016-06-09 09:22:33,399 [myid:2] - INFO
> [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):Environment@109]
> - Server environment:os.version=4.4.12-boot2docker
> 2016-06-09 09:22:33,400 [myid:2] - INFO
> [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):Environment@109]
> - Server environment:user.name=root
> 2016-06-09 09:22:33,401 [myid:2] - INFO
> [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):Environment@109]
> - Server environment:user.home=/root
> 2016-06-09 09:22:33,401 [myid:2] - INFO
> [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):Environment@109]
> - Server environment:user.dir=/
> 2016-06-09 09:22:33,401 [myid:2] - INFO
> [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):Environment@109]
> - Server environment:os.memory.free=9MB
> 2016-06-09 09:22:33,402 [myid:2] - INFO
> [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):Environment@109]
> - Server environment:os.memory.max=966MB
> 2016-06-09 09:22:33,402 [myid:2] - INFO
> [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):Environment@109]
> - Server environment:os.memory.total=15MB
> 2016-06-09 09:22:33,403 [myid:2] - INFO
> [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):ZooKeeperServer@858]
> - minSessionTimeout set to 4000
> 2016-06-09 09:22:33,404 [myid:2] - INFO
> [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):ZooKeeperServer@867]
> - maxSessionTimeout set to 40000
> 2016-06-09 09:22:33,405 [myid:2] - INFO
> [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):ZooKeeperServer@156]
> - Created server with tickTime 2000 minSessionTimeout 4000
> maxSessionTimeout 40000 datadir /opt/zookeeper/logs/version-2 snapdir
> /opt/zookeeper/var/version-2
> 2016-06-09 09:22:33,406 [myid:2] - INFO
> [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):Follower@66]
> - FOLLOWING - LEADER ELECTION TOOK - 28
> 2016-06-09 09:22:33,434 [myid:2] - INFO
> [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):Learner@369]
> - Getting a snapshot from leader
> 2016-06-09 09:22:33,442 [myid:2] - INFO
> [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):Learner@509]
> - Learner received NEWLEADER message
> 2016-06-09 09:22:33,446 [myid:2] - INFO
> [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):FileTxnSnapLog@298]
> - Snapshotting: 0x100000001 to
> /opt/zookeeper/var/version-2/snapshot.100000001
> 2016-06-09 09:22:33,452 [myid:2] - INFO
> [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):Learner@493]
> - Learner received UPTODATE message
> 2016-06-09 09:22:33,457 [myid:2] - INFO
> [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):CommitProcessor@254]
> - Configuring CommitProcessor with 1 worker threads.
>
>
>