zookeeper-user mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Patrick Hunt <ph...@apache.org>
Subject Re: Help looking at ZK logs
Date Thu, 12 May 2016 23:04:40 GMT
> What does it mean to repeat "ZooKeeperServer not running" when the JVM is
still running?

The server process might be running, but if the process has not joined the
quorum it will report that message.

I'm not super familiar with R/O mode but my guess would be that the quorum
should try to re-form. See
https://issues.apache.org/jira/browse/ZOOKEEPER-784 - I see comments in
there also mentioning "rejoining the quorum" and implications.

fwiw I also noticed this in your logs, which it typically not a good sign:

> fsync-ing the write ahead log in SyncThread:2 took 1721ms which will adversely
effect operation latency.

Patrick

ps. Consider attaching the logs next time, the email formatting makes it
difficult to parse (at least for me).


On Thu, May 12, 2016 at 3:47 PM, Benjamin Jaton <benjamin.jaton@gmail.com>
wrote:

> bump
>
> On Wed, May 4, 2016 at 2:55 PM, Benjamin Jaton <benjamin.jaton@gmail.com>
> wrote:
>
> > Hello,
> >
> > I have a 2 nodes ZK ensemble, the first node shows:
> >
> > WARN
> >
> [QuorumPeer[myid=1](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):Follower@93
> ]
> > - Exception when following the leader
> > java.net.SocketTimeoutException: Read timed out
> >         at java.net.SocketInputStream.socketRead0(Native Method)
> > ~[?:1.8.0_91]
> >         at
> > java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
> > ~[?:1.8.0_91]
> >         at java.net.SocketInputStream.read(SocketInputStream.java:170)
> > ~[?:1.8.0_91]
> >         at java.net.SocketInputStream.read(SocketInputStream.java:141)
> > ~[?:1.8.0_91]
> >         at java.io.BufferedInputStream.fill(BufferedInputStream.java:246)
> > ~[?:1.8.0_91]
> >         at java.io.BufferedInputStream.read(BufferedInputStream.java:265)
> > ~[?:1.8.0_91]
> >         at java.io.DataInputStream.readInt(DataInputStream.java:387)
> > ~[?:1.8.0_91]
> >         at
> > org.apache.jute.BinaryInputArchive.readInt(BinaryInputArchive.java:63)
> > ~[zookeeper-3.5.0-alpha.jar:3.5.2-alpha-SNAPSHOT-1702518]
> >         at
> >
> org.apache.zookeeper.server.quorum.QuorumPacket.deserialize(QuorumPacket.java:83)
> > ~[zookeeper-3.5.0-alpha.jar:?]
> >         at
> > org.apache.jute.BinaryInputArchive.readRecord(BinaryInputArchive.java:99)
> > ~[zookeeper-3.5.0-alpha.jar:3.5.2-alpha-SNAPSHOT-1702518]
> >         at
> > org.apache.zookeeper.server.quorum.Learner.readPacket(Learner.java:155)
> > ~[zookeeper-3.5.0-alpha.jar:?]
> >         at
> >
> org.apache.zookeeper.server.quorum.Follower.followLeader(Follower.java:89)
> > [zookeeper-3.5.0-alpha.jar:?]
> >         at
> > org.apache.zookeeper.server.quorum.QuorumPeer.run(QuorumPeer.java:1064)
> > [zookeeper-3.5.0-alpha.jar:?]
> >
> >
> [QuorumPeer[myid=1](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):Follower@198
> ]
> > - shutdown called
> > java.lang.Exception: shutdown Follower
> >         at
> > org.apache.zookeeper.server.quorum.Follower.shutdown(Follower.java:198)
> > [zookeeper-3.5.0-alpha.jar:?]
> >         at
> > org.apache.zookeeper.server.quorum.QuorumPeer.run(QuorumPeer.java:1068)
> > [zookeeper-3.5.0-alpha.jar:?]
> >
> >
> > and proceeds to go into read-ony mode.
> > The second node shows:
> >
> >
> > 2016-05-04T13:15:27,819 [myid:] - INFO
> > [NIOWorkerThread-1:NIOServerCnxn@606] - Closed socket connection for
> > client /127.0.1.1:45412 which had sessionid 0x2000092b4fa0052
> > 2016-05-04T13:15:27,932 [myid:] - INFO
> > [NIOServerCxnFactory.AcceptThread:/0.0.0.0:2181
> > :NIOServerCnxnFactory$AcceptThread@296] - Accepted socket connection
> from
> > /127.0.1.1:45416
> > 2016-05-04T13:15:27,940 [myid:] - INFO
> > [NIOWorkerThread-2:ZooKeeperServer@969] - Client attempting to establish
> > new session at /127.0.1.1:45416
> > 2016-05-04T13:15:27,961 [myid:] - INFO
> > [CommitProcWorkThread-1:ZooKeeperServer@678] - Established session
> > 0x2000092b4fa0053 with negotiated timeout 60000 for client /
> > 127.0.1.1:45416
> > 2016-05-04T13:15:27,961 [myid:] - INFO
> > [NIOWorkerThread-2:ZooKeeperServer@1006] - got auth packet /
> > 127.0.1.1:45416
> > 2016-05-04T13:15:27,962 [myid:] - INFO
> > [NIOWorkerThread-2:ZooKeeperServer@1024] - auth success /127.0.1.1:45416
> > 2016-05-04T13:15:27,962 [myid:] - INFO
> > [NIOWorkerThread-1:ZooKeeperServer@1006] - got auth packet /
> > 127.0.1.1:45416
> > 2016-05-04T13:15:27,962 [myid:] - INFO
> > [NIOWorkerThread-1:ZooKeeperServer@1024] - auth success /127.0.1.1:45416
> > 2016-05-04T13:15:28,054 [myid:] - INFO  [ProcessThread(sid:2
> > cport:-1)::PrepRequestProcessor@649] - Processed session termination for
> > sessionid: 0x10005f496940051
> > 2016-05-04T13:15:40,659 [myid:] - INFO
> [SessionTracker:ZooKeeperServer@384]
> > - Expiring session 0x10005f496940050, timeout of 5000ms exceeded
> > 2016-05-04T13:15:40,659 [myid:] - INFO
> > [SessionTracker:QuorumZooKeeperServer@132] - Submitting global
> > closeSession request for session 0x10005f496940050
> > 2016-05-04T13:15:40,659 [myid:] - INFO
> > [NIOServerCxnFactory.AcceptThread:/0.0.0.0:2181
> > :NIOServerCnxnFactory$AcceptThread@296] - Accepted socket connection
> from
> > /127.0.1.1:45427
> > 2016-05-04T13:15:40,659 [myid:] - INFO
> > [NIOServerCxnFactory.AcceptThread:/0.0.0.0:2181
> > :NIOServerCnxnFactory$AcceptThread@296] - Accepted socket connection
> from
> > /127.0.1.1:45429
> > 2016-05-04T13:15:40,660 [myid:] - INFO
> > [NIOServerCxnFactory.AcceptThread:/0.0.0.0:2181
> > :NIOServerCnxnFactory$AcceptThread@296] - Accepted socket connection
> from
> > /127.0.1.1:45431
> > 2016-05-04T13:15:40,660 [myid:] - INFO
> > [NIOServerCxnFactory.AcceptThread:/0.0.0.0:2181
> > :NIOServerCnxnFactory$AcceptThread@296] - Accepted socket connection
> from
> > /10.11.12.4:51958
> > 2016-05-04T13:15:40,660 [myid:] - INFO
> > [NIOServerCxnFactory.AcceptThread:/0.0.0.0:2181
> > :NIOServerCnxnFactory$AcceptThread@296] - Accepted socket connection
> from
> > /10.11.12.4:51959
> > 2016-05-04T13:15:40,660 [myid:] - INFO
> > [NIOServerCxnFactory.AcceptThread:/0.0.0.0:2181
> > :NIOServerCnxnFactory$AcceptThread@296] - Accepted socket connection
> from
> > /127.0.1.1:45433
> > 2016-05-04T13:15:40,663 [myid:] - INFO  [ProcessThread(sid:2
> > cport:-1)::PrepRequestProcessor@649] - Processed session termination for
> > sessionid: 0x10005f496940050
> > 2016-05-04T13:15:41,190 [myid:] - INFO
> > [WorkerReceiver[myid=2]:FastLeaderElection@688] - Notification: 2
> > (message format version), 1 (n.leader), 0x70000056d (n.zxid), 0x2
> > (n.round), LOOKING (n.state), 1 (n.sid), 0x7 (n.peerEPoch), LEADING (my
> > state)10000041c (n.config version)
> > 2016-05-04T13:15:41,193 [myid:] - INFO
> > [WorkerReceiver[myid=2]:FastLeaderElection@688] - Notification: 2
> > (message format version), 1 (n.leader), 0x70000056d (n.zxid), 0x2
> > (n.round), LOOKING (n.state), 1 (n.sid), 0x7 (n.peerEPoch), LEADING (my
> > state)10000041c (n.config version)
> > 2016-05-04T13:15:41,193 [myid:] - INFO
> > [WorkerReceiver[myid=2]:FastLeaderElection@688] - Notification: 2
> > (message format version), 1 (n.leader), 0x70000056d (n.zxid), 0x2
> > (n.round), LOOKING (n.state), 1 (n.sid), 0x7 (n.peerEPoch), LEADING (my
> > state)10000041c (n.config version)
> > 2016-05-04T13:15:41,193 [myid:] - INFO
> > [WorkerReceiver[myid=2]:FastLeaderElection@688] - Notification: 2
> > (message format version), 1 (n.leader), 0x70000056d (n.zxid), 0x2
> > (n.round), LOOKING (n.state), 1 (n.sid), 0x7 (n.peerEPoch), LEADING (my
> > state)10000041c (n.config version)
> > 2016-05-04T13:15:41,194 [myid:] - INFO
> > [WorkerReceiver[myid=2]:FastLeaderElection@688] - Notification: 2
> > (message format version), 1 (n.leader), 0x70000056d (n.zxid), 0x2
> > (n.round), LOOKING (n.state), 1 (n.sid), 0x7 (n.peerEPoch), LEADING (my
> > state)10000041c (n.config version)
> > 2016-05-04T13:15:41,259 [myid:] - INFO
> > [NIOWorkerThread-2:ZooKeeperServer@974] - Client attempting to renew
> > session 0x10005f496940002 at /10.11.12.4:51958
> > 2016-05-04T13:15:41,260 [myid:] - INFO
> > [NIOWorkerThread-2:ZooKeeperServer@678] - Established session
> > 0x10005f496940002 with negotiated timeout 60000 for client /
> > 10.11.12.4:51958
> > 2016-05-04T13:15:41,260 [myid:] - INFO
> > [NIOWorkerThread-1:ZooKeeperServer@974] - Client attempting to renew
> > session 0x10005f496940005 at /127.0.1.1:45433
> > 2016-05-04T13:15:41,260 [myid:] - INFO
> > [NIOWorkerThread-1:ZooKeeperServer@678] - Established session
> > 0x10005f496940005 with negotiated timeout 60000 for client /
> > 127.0.1.1:45433
> > 2016-05-04T13:15:41,261 [myid:] - INFO
> > [NIOWorkerThread-1:ZooKeeperServer@969] - Client attempting to establish
> > new session at /127.0.1.1:45427
> > 2016-05-04T13:15:41,261 [myid:] - INFO
> > [NIOWorkerThread-1:ZooKeeperServer@969] - Client attempting to establish
> > new session at /127.0.1.1:45429
> > 2016-05-04T13:15:41,261 [myid:] - INFO
> > [NIOWorkerThread-1:ZooKeeperServer@974] - Client attempting to renew
> > session 0x10005f496940000 at /10.11.12.4:51959
> > 2016-05-04T13:15:41,261 [myid:] - INFO
> > [NIOWorkerThread-1:ZooKeeperServer@678] - Established session
> > 0x10005f496940000 with negotiated timeout 60000 for client /
> > 10.11.12.4:51959
> > 2016-05-04T13:15:41,261 [myid:] - INFO
> > [NIOWorkerThread-1:ZooKeeperServer@969] - Client attempting to establish
> > new session at /127.0.1.1:45431
> > 2016-05-04T13:15:41,275 [myid:] - INFO
> > [NIOWorkerThread-1:ZooKeeperServer@1006] - got auth packet /
> > 10.11.12.4:51958
> > 2016-05-04T13:15:41,275 [myid:] - INFO
> > [NIOWorkerThread-1:ZooKeeperServer@1024] - auth success /
> 10.11.12.4:51958
> > 2016-05-04T13:15:41,275 [myid:] - INFO
> > [NIOWorkerThread-1:ZooKeeperServer@1006] - got auth packet /
> > 127.0.1.1:45433
> > 2016-05-04T13:15:41,275 [myid:] - INFO
> > [NIOWorkerThread-1:ZooKeeperServer@1024] - auth success /127.0.1.1:45433
> > 2016-05-04T13:15:41,275 [myid:] - INFO
> > [NIOWorkerThread-2:ZooKeeperServer@1006] - got auth packet /
> > 10.11.12.4:51959
> > 2016-05-04T13:15:41,276 [myid:] - INFO
> > [NIOWorkerThread-2:ZooKeeperServer@1024] - auth success /
> 10.11.12.4:51959
> > 2016-05-04T13:15:40,661 [myid:] - ERROR [LearnerHandler-/
> 10.11.12.4:39206
> > :LearnerHandler@620] - Unexpected exception causing shutdown while sock
> > still open
> > java.io.EOFException
> >     at java.io.DataInputStream.readInt(DataInputStream.java:392)
> > ~[?:1.8.0_91]
> >     at
> > org.apache.jute.BinaryInputArchive.readInt(BinaryInputArchive.java:63)
> > ~[zookeeper-3.5.0-alpha.jar:3.5.2-alpha-SNAPSHOT-1702518]
> >     at
> >
> org.apache.zookeeper.server.quorum.QuorumPacket.deserialize(QuorumPacket.java:83)
> > ~[zookeeper-3.5.0-alpha.jar:?]
> >     at
> > org.apache.jute.BinaryInputArchive.readRecord(BinaryInputArchive.java:99)
> > ~[zookeeper-3.5.0-alpha.jar:3.5.2-alpha-SNAPSHOT-1702518]
> >     at
> >
> org.apache.zookeeper.server.quorum.LearnerHandler.run(LearnerHandler.java:514)
> > [zookeeper-3.5.0-alpha.jar:?]
> > 2016-05-04T13:15:41,267 [myid:] - WARN  [Sender-/10.11.12.4:39206
> > :LearnerHandler@241] - Unexpected exception at LearnerHandler
> > Socket[addr=/10.11.12.4,port=39206,localport=2888]
> > tickOfNextAckDeadline:1331 synced?:true queuedPacketLength:3
> > java.net.SocketException: Broken pipe
> >     at java.net.SocketOutputStream.socketWrite0(Native Method)
> > ~[?:1.8.0_91]
> >     at
> > java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:109)
> > ~[?:1.8.0_91]
> >     at java.net.SocketOutputStream.write(SocketOutputStream.java:153)
> > ~[?:1.8.0_91]
> >     at
> > java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:82)
> > ~[?:1.8.0_91]
> >     at java.io.BufferedOutputStream.flush(BufferedOutputStream.java:140)
> > ~[?:1.8.0_91]
> >     at
> >
> org.apache.zookeeper.server.quorum.LearnerHandler.sendPackets(LearnerHandler.java:221)
> > [zookeeper-3.5.0-alpha.jar:?]
> >     at
> >
> org.apache.zookeeper.server.quorum.LearnerHandler.access$200(LearnerHandler.java:58)
> > [zookeeper-3.5.0-alpha.jar:?]
> >     at
> >
> org.apache.zookeeper.server.quorum.LearnerHandler$1.run(LearnerHandler.java:653)
> > [zookeeper-3.5.0-alpha.jar:?]
> > 2016-05-04T13:15:42,066 [myid:] - WARN  [LearnerHandler-/
> 10.11.12.4:39206
> > :LearnerHandler@635] - ******* GOODBYE /10.11.12.4:39206 ********
> > 2016-05-04T13:15:42,394 [myid:] - INFO
> > [NIOServerCxnFactory.AcceptThread:/0.0.0.0:2181
> > :NIOServerCnxnFactory$AcceptThread@296] - Accepted socket connection
> from
> > /127.0.1.1:45438
> > 2016-05-04T13:15:42,395 [myid:] - INFO
> > [NIOWorkerThread-1:ZooKeeperServer@969] - Client attempting to establish
> > new session at /127.0.1.1:45438
> > 2016-05-04T13:15:42,984 [myid:] - WARN  [SyncThread:2:FileTxnLog@335] -
> > fsync-ing the write ahead log in SyncThread:2 took 1721ms which will
> > adversely effect operation latency. See the ZooKeeper troubleshooting
> guide
> > 2016-05-04T13:15:43,043 [myid:] - INFO
> >
> [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):Leader@613
> ]
> > - Shutting down
> > 2016-05-04T13:15:43,071 [myid:] - INFO
> >
> [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):Leader@619
> ]
> > - Shutdown called
> > java.lang.Exception: shutdown Leader! reason: Not sufficient followers
> > synced, only synced with sids: [ [2] ]
> >     at
> org.apache.zookeeper.server.quorum.Leader.shutdown(Leader.java:619)
> > [zookeeper-3.5.0-alpha.jar:?]
> >     at org.apache.zookeeper.server.quorum.Leader.lead(Leader.java:590)
> > [zookeeper-3.5.0-alpha.jar:?]
> >     at
> > org.apache.zookeeper.server.quorum.QuorumPeer.run(QuorumPeer.java:1077)
> > [zookeeper-3.5.0-alpha.jar:?]
> > 2016-05-04T13:15:43,161 [myid:] - INFO
> >
> [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):NIOServerCnxn@606
> ]
> > - Closed socket connection for client /127.0.1.1:45431 which had
> > sessionid 0x2000092b4fa0056
> > 2016-05-04T13:15:43,161 [myid:] - INFO
> >
> [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):MBeanRegistry@128
> ]
> > - Unregister MBean
> >
> [org.apache.ZooKeeperService:name0=ReplicatedServer_id2,name1=replica.2,name2=Leader,name3=Connections,name4=10.11.12.4,name5=0x2000092b4fa0000]
> > 2016-05-04T13:15:43,161 [myid:] - INFO
> >
> [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):NIOServerCnxn@606
> ]
> > - Closed socket connection for client /10.11.12.4:59834 which had
> > sessionid 0x2000092b4fa0000
> > 2016-05-04T13:15:43,162 [myid:] - INFO
> > [LearnerCnxAcceptor-0.0.0.0/0.0.0.0:2888:Leader$LearnerCnxAcceptor@373]
> -
> > exception while shutting down acceptor: java.net.SocketException: Socket
> > closed
> > 2016-05-04T13:15:43,162 [myid:] - INFO
> >
> [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):NIOServerCnxn@606
> ]
> > - Closed socket connection for client /127.0.1.1:45438 which had
> > sessionid 0x2000092b4fa0057
> > 2016-05-04T13:15:43,171 [myid:] - INFO
> >
> [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):MBeanRegistry@128
> ]
> > - Unregister MBean
> >
> [org.apache.ZooKeeperService:name0=ReplicatedServer_id2,name1=replica.2,name2=Leader,name3=Connections,name4=127.0.1.1,name5=0x2000092b4fa0002]
> > 2016-05-04T13:15:43,171 [myid:] - INFO
> >
> [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):NIOServerCnxn@606
> ]
> > - Closed socket connection for client /127.0.1.1:35055 which had
> > sessionid 0x2000092b4fa0002
> > 2016-05-04T13:15:43,172 [myid:] - INFO
> > [main-SendThread(ubuntu2:2181):ClientCnxn$SendThread@1253] - Unable to
> > read additional data from server sessionid 0x2000092b4fa0002, likely
> server
> > has closed socket, closing socket connection and attempting reconnect
> > 2016-05-04T13:15:43,172 [myid:] - INFO
> >
> [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):NIOServerCnxn@606
> ]
> > - Closed socket connection for client /127.0.1.1:45427 which had
> > sessionid 0x2000092b4fa0054
> > 2016-05-04T13:15:43,172 [myid:] - INFO
> >
> [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):ZooKeeperServer@498
> ]
> > - shutting down
> > 2016-05-04T13:15:43,172 [myid:] - INFO
> >
> [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):SessionTrackerImpl@232
> ]
> > - Shutting down
> > 2016-05-04T13:15:43,172 [myid:] - INFO
> >
> [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):LeaderRequestProcessor@77
> ]
> > - Shutting down
> > 2016-05-04T13:15:43,172 [myid:] - INFO
> >
> [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):PrepRequestProcessor@967
> ]
> > - Shutting down
> > 2016-05-04T13:15:43,173 [myid:] - INFO  [ProcessThread(sid:2
> > cport:-1)::PrepRequestProcessor@154] - PrepRequestProcessor exited loop!
> > 2016-05-04T13:15:43,173 [myid:] - INFO
> >
> [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):ProposalRequestProcessor@88
> ]
> > - Shutting down
> > 2016-05-04T13:15:43,174 [myid:] - INFO
> >
> [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):CommitProcessor@358
> ]
> > - Shutting down
> > 2016-05-04T13:15:43,174 [myid:] - INFO
> >
> [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):Leader$ToBeAppliedRequestProcessor@914
> ]
> > - Shutting down
> > 2016-05-04T13:15:43,175 [myid:] - INFO
> >
> [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):FinalRequestProcessor@492
> ]
> > - shutdown of request processor complete
> > 2016-05-04T13:15:43,175 [myid:] - INFO
> >
> [QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):SyncRequestProcessor@191
> ]
> > - Shutting down
> > 2016-05-04T13:15:43,210 [myid:] - INFO
> > [CommitProcessor:2:CommitProcessor@193] - CommitProcessor exited loop!
> > 2016-05-04T13:15:43,440 [myid:] - INFO
> > [NIOServerCxnFactory.AcceptThread:/0.0.0.0:2181
> > :NIOServerCnxnFactory$AcceptThread@296] - Accepted socket connection
> from
> > /127.0.1.1:45441
> > 2016-05-04T13:15:43,441 [myid:] - INFO
> > [NIOWorkerThread-2:NIOServerCnxn@485] - Processing isro command from /
> > 127.0.1.1:45441
> > 2016-05-04T13:15:43,458 [myid:] - INFO
> > [NIOServerCxnFactory.AcceptThread:/0.0.0.0:2181
> > :NIOServerCnxnFactory$AcceptThread@296] - Accepted socket connection
> from
> > /10.11.12.4:51963
> > 2016-05-04T13:15:43,458 [myid:] - INFO
> > [NIOWorkerThread-1:NIOServerCnxn@485] - Processing isro command from /
> > 10.11.12.4:51963
> > 2016-05-04T13:15:43,558 [myid:] - INFO
> > [main-EventThread:ConnectionStateManager@228] - State change: SUSPENDED
> > 2016-05-04T13:15:43,607 [myid:] - INFO
> > [NIOServerCxnFactory.AcceptThread:/0.0.0.0:2181
> > :NIOServerCnxnFactory$AcceptThread@296] - Accepted socket connection
> from
> > /10.11.12.4:51965
> > 2016-05-04T13:15:43,731 [myid:] - INFO
> > [NIOServerCxnFactory.AcceptThread:/0.0.0.0:2181
> > :NIOServerCnxnFactory$AcceptThread@296] - Accepted socket connection
> from
> > /127.0.1.1:45444
> > 2016-05-04T13:15:43,796 [myid:] - INFO
> > [Curator-ConnectionStateManager-0:ZooManagerConnectionStateListener@104]
> > - Curator connection state change: SUSPENDED (session:
> 144115818177363970)
> > 2016-05-04T13:15:43,797 [myid:] - WARN
> > [Curator-ConnectionStateManager-0:ZooManagerConnectionStateListener@48]
> -
> > Connection suspended (session: 144115818177363970)
> > 2016-05-04T13:15:43,797 [myid:] - INFO
> > [Curator-ConnectionStateManager-0:ZooManagerConnectionStateListener@139]
> > - Starting session lost thread for session 144115818177363970
> > 2016-05-04T13:15:43,825 [myid:] - INFO
> > [NIOServerCxnFactory.AcceptThread:/0.0.0.0:2181
> > :NIOServerCnxnFactory$AcceptThread@296] - Accepted socket connection
> from
> > /10.11.12.4:51967
> > 2016-05-04T13:15:43,946 [myid:] - INFO
> > [main-SendThread(w-rli09-ben:2181):ClientCnxn$SendThread@1138] - Opening
> > socket connection to server w-rli09-ben/10.11.12.4:2181. Will not
> attempt
> > to authenticate using SASL (unknown error)
> > 2016-05-04T13:15:43,947 [myid:] - INFO
> > [main-SendThread(w-rli09-ben:2181):ClientCnxn$SendThread@980] - Socket
> > connection established, initiating session, client: /10.11.1.2:56315,
> > server: w-rli09-ben/10.11.12.4:2181
> > 2016-05-04T13:15:43,949 [myid:] - INFO
> > [main-SendThread(w-rli09-ben:2181):ClientCnxn$SendThread@1400] - Session
> > establishment complete on server w-rli09-ben/10.11.12.4:2181, sessionid
> =
> > 0x2000092b4fa0002, negotiated timeout = 60000 (READ-ONLY mode)
> > 2016-05-04T13:15:43,949 [myid:] - INFO
> > [main-EventThread:ConnectionStateManager@228] - State change: READ_ONLY
> > 2016-05-04T13:15:43,949 [myid:] - INFO
> > [Curator-ConnectionStateManager-0:ZooManagerConnectionStateListener@104]
> > - Curator connection state change: READ_ONLY (session:
> 144115818177363970)
> > 2016-05-04T13:15:43,949 [myid:] - INFO
> > [Curator-ConnectionStateManager-0:ZooManagerConnectionStateListener@206]
> > - VDS-ZK connection state changed: READ_ONLY
> > 2016-05-04T13:15:44,007 [myid:] - WARN
> > [Curator-ConnectionStateManager-0:ZooManager@300] - ZooManager
> connection
> > state changed: READ_ONLY
> > 2016-05-04T13:15:44,007 [myid:] - INFO
> > [SessionTracker:SessionTrackerImpl@158] - SessionTrackerImpl exited
> loop!
> > 2016-05-04T13:15:44,029 [myid:] - INFO
> > [main-SendThread(w-rli09-ben:2181):ClientCnxn$SendThread@1297] -
> Checking
> > server ubuntu2/127.0.1.1:2181 for being r/w. Timeout 200
> > 2016-05-04T13:15:44,030 [myid:] - INFO
> > [NIOServerCxnFactory.AcceptThread:/0.0.0.0:2181
> > :NIOServerCnxnFactory$AcceptThread@296] - Accepted socket connection
> from
> > /127.0.1.1:45447
> > 2016-05-04T13:15:44,170 [myid:] - INFO
> > [NIOWorkerThread-1:NIOServerCnxn@606] - Closed socket connection for
> > client /10.11.12.4:51963 (no session established for client)
> > 2016-05-04T13:15:44,171 [myid:] - INFO
> > [NIOWorkerThread-1:NIOServerCnxn@485] - Processing isro command from /
> > 10.11.12.4:51965
> > 2016-05-04T13:15:44,171 [myid:] - INFO
> > [NIOWorkerThread-2:NIOServerCnxn@606] - Closed socket connection for
> > client /127.0.1.1:45441 (no session established for client)
> > 2016-05-04T13:15:44,171 [myid:] - INFO
> > [NIOWorkerThread-2:NIOServerCnxn@485] - Processing isro command from /
> > 127.0.1.1:45444
> > 2016-05-04T13:15:44,171 [myid:] - INFO
> > [NIOWorkerThread-2:NIOServerCnxn@606] - Closed socket connection for
> > client /127.0.1.1:45444 (no session established for client)
> > 2016-05-04T13:15:44,171 [myid:] - INFO
> > [NIOWorkerThread-2:NIOServerCnxn@485] - Processing isro command from /
> > 10.11.12.4:51967
> > 2016-05-04T13:15:44,174 [myid:] - INFO
> > [NIOWorkerThread-1:NIOServerCnxn@606] - Closed socket connection for
> > client /10.11.12.4:51965 (no session established for client)
> > 2016-05-04T13:15:44,175 [myid:] - INFO
> > [NIOWorkerThread-1:NIOServerCnxn@485] - Processing isro command from /
> > 127.0.1.1:45447
> > 2016-05-04T13:15:44,175 [myid:] - INFO
> > [NIOWorkerThread-2:NIOServerCnxn@606] - Closed socket connection for
> > client /10.11.12.4:51967 (no session established for client)
> > 2016-05-04T13:15:44,177 [myid:] - INFO
> > [NIOWorkerThread-1:NIOServerCnxn@606] - Closed socket connection for
> > client /127.0.1.1:45447 (no session established for client)
> > 2016-05-04T13:15:44,190 [myid:] - INFO
> > [NIOServerCxnFactory.AcceptThread:/0.0.0.0:2181
> > :NIOServerCnxnFactory$AcceptThread@296] - Accepted socket connection
> from
> > /10.11.12.4:51970
> > 2016-05-04T13:15:44,191 [myid:] - INFO
> > [NIOWorkerThread-2:NIOServerCnxn@485] - Processing isro command from /
> > 10.11.12.4:51970
> > 2016-05-04T13:15:44,191 [myid:] - INFO
> > [NIOWorkerThread-2:NIOServerCnxn@606] - Closed socket connection for
> > client /10.11.12.4:51970 (no session established for client)
> > 2016-05-04T13:15:44,210 [myid:] - INFO
> > [main-SendThread(w-rli09-ben:2181):ClientCnxn$SendThread@1297] -
> Checking
> > server w-rli09-ben/10.11.12.4:2181 for being r/w. Timeout 400
> > 2016-05-04T13:15:44,470 [myid:] - INFO
> > [WorkerReceiver[myid=2]:FastLeaderElection@688] - Notification: 2
> > (message format version), 1 (n.leader), 0x70000056d (n.zxid), 0x2
> > (n.round), LOOKING (n.state), 1 (n.sid), 0x7 (n.peerEPoch), LEADING (my
> > state)10000041c (n.config version)
> > 2016-05-04T13:15:44,578 [myid:] - INFO
> > [NIOServerCxnFactory.AcceptThread:/0.0.0.0:2181
> > :NIOServerCnxnFactory$AcceptThread@296] - Accepted socket connection
> from
> > /10.11.12.4:51972
> > 2016-05-04T13:15:44,579 [myid:] - INFO
> > [NIOWorkerThread-1:NIOServerCnxn@485] - Processing isro command from /
> > 10.11.12.4:51972
> > 2016-05-04T13:15:44,579 [myid:] - INFO
> > [NIOWorkerThread-1:NIOServerCnxn@606] - Closed socket connection for
> > client /10.11.12.4:51972 (no session established for client)
> > 2016-05-04T13:15:44,609 [myid:] - INFO
> > [main-SendThread(w-rli09-ben:2181):ClientCnxn$SendThread@1297] -
> Checking
> > server ubuntu2/127.0.1.1:2181 for being r/w. Timeout 800
> > 2016-05-04T13:15:44,610 [myid:] - INFO
> > [NIOServerCxnFactory.AcceptThread:/0.0.0.0:2181
> > :NIOServerCnxnFactory$AcceptThread@296] - Accepted socket connection
> from
> > /127.0.1.1:45454
> > 2016-05-04T13:15:44,610 [myid:] - INFO
> > [NIOWorkerThread-2:NIOServerCnxn@485] - Processing isro command from /
> > 127.0.1.1:45454
> > 2016-05-04T13:15:44,611 [myid:] - INFO
> > [NIOWorkerThread-2:NIOServerCnxn@606] - Closed socket connection for
> > client /127.0.1.1:45454 (no session established for client)
> > 2016-05-04T13:15:44,780 [myid:] - INFO
> > [NIOServerCxnFactory.AcceptThread:/0.0.0.0:2181
> > :NIOServerCnxnFactory$AcceptThread@296] - Accepted socket connection
> from
> > /127.0.1.1:45455
> > 2016-05-04T13:15:44,780 [myid:] - INFO
> > [NIOWorkerThread-1:NIOServerCnxn@485] - Processing isro command from /
> > 127.0.1.1:45455
> > 2016-05-04T13:15:44,781 [myid:] - INFO
> > [NIOWorkerThread-1:NIOServerCnxn@606] - Closed socket connection for
> > client /127.0.1.1:45455 (no session established for client)
> > 2016-05-04T13:15:44,844 [myid:] - INFO
> > [NIOServerCxnFactory.AcceptThread:/0.0.0.0:2181
> > :NIOServerCnxnFactory$AcceptThread@296] - Accepted socket connection
> from
> > /127.0.1.1:45456
> > 2016-05-04T13:15:44,846 [myid:] - WARN
> > [NIOWorkerThread-2:NIOServerCnxn@369] - Exception causing close of
> > session 0x0: ZooKeeperServer not running
> > 2016-05-04T13:15:44,846 [myid:] - INFO
> > [NIOWorkerThread-2:NIOServerCnxn@606] - Closed socket connection for
> > client /127.0.1.1:45456 (no session established for client)
> > 2016-05-04T13:15:45,314 [myid:] - INFO
> > [NIOServerCxnFactory.AcceptThread:/0.0.0.0:2181
> > :NIOServerCnxnFactory$AcceptThread@296] - Accepted socket connection
> from
> > /10.11.12.4:51975
> > 2016-05-04T13:15:45,315 [myid:] - INFO
> > [NIOWorkerThread-1:NIOServerCnxn@485] - Processing isro command from /
> > 10.11.12.4:51975
> > 2016-05-04T13:15:45,315 [myid:] - INFO
> > [NIOWorkerThread-1:NIOServerCnxn@606] - Closed socket connection for
> > client /10.11.12.4:51975 (no session established for client)
> > 2016-05-04T13:15:45,376 [myid:] - INFO
> > [NIOServerCxnFactory.AcceptThread:/0.0.0.0:2181
> > :NIOServerCnxnFactory$AcceptThread@296] - Accepted socket connection
> from
> > /127.0.1.1:45457
> > 2016-05-04T13:15:45,376 [myid:] - WARN
> > [NIOWorkerThread-2:NIOServerCnxn@369] - Exception causing close of
> > session 0x0: ZooKeeperServer not running
> > 2016-05-04T13:15:45,376 [myid:] - INFO
> > [NIOWorkerThread-2:NIOServerCnxn@606] - Closed socket connection for
> > client /127.0.1.1:45457 (no session established for client)
> > 2016-05-04T13:15:45,410 [myid:] - INFO
> > [main-SendThread(w-rli09-ben:2181):ClientCnxn$SendThread@1297] -
> Checking
> > server w-rli09-ben/10.11.12.4:2181 for being r/w. Timeout 1600
> > 2016-05-04T13:15:46,423 [myid:] - INFO
> > [NIOServerCxnFactory.AcceptThread:/0.0.0.0:2181
> > :NIOServerCnxnFactory$AcceptThread@296] - Accepted socket connection
> from
> > /127.0.1.1:45462
> > 2016-05-04T13:15:46,425 [myid:] - INFO
> > [NIOWorkerThread-1:NIOServerCnxn@485] - Processing isro command from /
> > 127.0.1.1:45462
> > 2016-05-04T13:15:46,508 [myid:] - INFO
> > [NIOWorkerThread-1:NIOServerCnxn@606] - Closed socket connection for
> > client /127.0.1.1:45462 (no session established for client)
> > 2016-05-04T13:15:46,643 [myid:] - INFO
> > [NIOServerCxnFactory.AcceptThread:/0.0.0.0:2181
> > :NIOServerCnxnFactory$AcceptThread@296] - Accepted socket connection
> from
> > /127.0.1.1:45463
> > 2016-05-04T13:15:46,643 [myid:] - WARN
> > [NIOWorkerThread-2:NIOServerCnxn@369] - Exception causing close of
> > session 0x0: ZooKeeperServer not running
> >
> >
> >
> > So I have several question:
> > Is the second node supposed to retry recreating an ensemble at some
> point?
> > Or was there a critical error?
> > What does it mean to repeat "ZooKeeperServer not running" when the JVM is
> > still running?
> >
> > Thanks a lot,
> > Ben
> >
> >
> >
> >
> >
>

Mime
  • Unnamed multipart/alternative (inline, None, 0 bytes)
View raw message