Also forgot to mention, The client api does keep pinging the servers and expects response from servers. This is to find out if a server/network is down....
Thanks mahadev On 9/14/09 5:03 PM, "Rob Baccus" <r...@audiencescience.com> wrote: > I am trying to automate creating an Ensemble then add data to it, and > then pull it out. I am finding that after I call setData() there > becomes an infinite loop of pings. This was working then just stopped > when I changed some code around to use JUnit 4.1 instead of 3.8.1 which > I would expect has nothing to do with this issue. I saw the issue > relating to session expiration due to system resources but I don't > believe this is the issue since this was working fine. > > My configuration: > Linux VM with 1.5GB RAM > Running in Eclipse 3.3 > Configured 4 zookeeper servers running each with different client and > leader/leader election ports and different local transaction log > locations. > All 4 servers come up without issues and a Leader is elected. > > Below is the stack trace that I am seeing with log4j DEBUG turned on for > org.apache.zookeeper after the setData() call is made. > > DEBUG [main] > (com.audiencescience.util.zookeeper.qa.failover.FailOverTest.testSimpleZ > KClientFailover:124) - ************************** Before Set Data > ************************** > INFO [main-SendThread] > (org.apache.zookeeper.ClientCnxn$SendThread.primeConnection:716) - > Priming connection to java.nio.channels.SocketChannel[connected > local=/172.17.1.133:40933 > remote=robb02linux.corp.digimine.com/172.17.1.133:2181] > INFO [main-SendThread] > (org.apache.zookeeper.ClientCnxn$SendThread.run:868) - Server connection > successful > INFO [NIOServerCxn.Factory:2181] > (org.apache.zookeeper.server.NIOServerCnxn.readConnectRequest:503) - > Connected to /172.17.1.133:40933 lastZxid 0 > INFO [NIOServerCxn.Factory:2181] > (org.apache.zookeeper.server.NIOServerCnxn.readConnectRequest:534) - > Creating new session 0x123bafb088a0000 > DEBUG [FollowerRequestProcessor:1] > (org.apache.zookeeper.server.quorum.CommitProcessor.processRequest:168) > - Processing request:: sessionid:0x123bafb088a0000 type:createSession > cxid:0x0 zxid:0xfffffffffffffffe txntype:unknown n/a > DEBUG [ProcessThread:-1] > (org.apache.zookeeper.server.quorum.CommitProcessor.processRequest:168) > - Processing request:: sessionid:0x123bafb088a0000 type:createSession > cxid:0x0 zxid:0x300000001 txntype:-10 n/a > DEBUG [ProcessThread:-1] > (org.apache.zookeeper.server.quorum.Leader.propose:560) - Proposing:: > sessionid:0x123bafb088a0000 type:createSession cxid:0x0 zxid:0x300000001 > txntype:-10 n/a > WARN [QuorumPeer:/0:0:0:0:0:0:0:0:2183] > (org.apache.zookeeper.server.quorum.Follower.followLeader:242) - Got > zxid 0x300000001 expected 0x1 > WARN [QuorumPeer:/0:0:0:0:0:0:0:0:2182] > (org.apache.zookeeper.server.quorum.Follower.followLeader:242) - Got > zxid 0x300000001 expected 0x1 > WARN [QuorumPeer:/0:0:0:0:0:0:0:0:2181] > (org.apache.zookeeper.server.quorum.Follower.followLeader:242) - Got > zxid 0x300000001 expected 0x1 > INFO [SessionTracker] > (org.apache.zookeeper.server.SessionTrackerImpl.run:132) - Expiring > session 0x123baf02f280000 > INFO [SessionTracker] > (org.apache.zookeeper.server.ZooKeeperServer.expire:317) - Expiring > session 0x123baf02f280000 > INFO [ProcessThread:-1] > (org.apache.zookeeper.server.PrepRequestProcessor.pRequest:360) - > Processed session termination request for id: 0x123baf02f280000 > DEBUG [ProcessThread:-1] > (org.apache.zookeeper.server.quorum.CommitProcessor.processRequest:168) > - Processing request:: sessionid:0x123baf02f280000 type:closeSession > cxid:0x0 zxid:0x300000002 txntype:-11 n/a > DEBUG [ProcessThread:-1] > (org.apache.zookeeper.server.quorum.Leader.propose:560) - Proposing:: > sessionid:0x123baf02f280000 type:closeSession cxid:0x0 zxid:0x300000002 > txntype:-11 n/a > DEBUG [FollowerHandler-/172.17.1.133:40537] > (org.apache.zookeeper.server.quorum.Leader.processAck:382) - Ack zxid: > 0x300000001 > DEBUG [FollowerHandler-/172.17.1.133:40537] > (org.apache.zookeeper.server.quorum.Leader.processAck:385) - outstanding > proposal: 0x300000001 > DEBUG [FollowerHandler-/172.17.1.133:40537] > (org.apache.zookeeper.server.quorum.Leader.processAck:385) - outstanding > proposal: 0x300000002 > DEBUG [FollowerHandler-/172.17.1.133:40537] > (org.apache.zookeeper.server.quorum.Leader.processAck:388) - outstanding > proposals all > DEBUG [FollowerHandler-/172.17.1.133:40537] > (org.apache.zookeeper.server.quorum.Leader.processAck:411) - Count for > zxid: 0x300000001 is 1 > DEBUG [FollowerHandler-/172.17.1.133:40537] > (org.apache.zookeeper.server.quorum.Leader.processAck:382) - Ack zxid: > 0x300000002 > DEBUG [FollowerHandler-/172.17.1.133:40537] > (org.apache.zookeeper.server.quorum.Leader.processAck:385) - outstanding > proposal: 0x300000001 > DEBUG [FollowerHandler-/172.17.1.133:40537] > (org.apache.zookeeper.server.quorum.Leader.processAck:385) - outstanding > proposal: 0x300000002 > DEBUG [FollowerHandler-/172.17.1.133:40537] > (org.apache.zookeeper.server.quorum.Leader.processAck:388) - outstanding > proposals all > DEBUG [FollowerHandler-/172.17.1.133:40537] > (org.apache.zookeeper.server.quorum.Leader.processAck:411) - Count for > zxid: 0x300000002 is 1 > DEBUG [SyncThread:0] > (org.apache.zookeeper.server.quorum.Leader.processAck:382) - Ack zxid: > 0x300000001 > DEBUG [SyncThread:0] > (org.apache.zookeeper.server.quorum.Leader.processAck:385) - outstanding > proposal: 0x300000001 > DEBUG [SyncThread:0] > (org.apache.zookeeper.server.quorum.Leader.processAck:385) - outstanding > proposal: 0x300000002 > DEBUG [SyncThread:0] > (org.apache.zookeeper.server.quorum.Leader.processAck:388) - outstanding > proposals all > DEBUG [SyncThread:0] > (org.apache.zookeeper.server.quorum.Leader.processAck:411) - Count for > zxid: 0x300000001 is 2 > DEBUG [FollowerHandler-/172.17.1.133:40536] > (org.apache.zookeeper.server.quorum.Leader.processAck:382) - Ack zxid: > 0x300000001 > DEBUG [FollowerHandler-/172.17.1.133:40536] > (org.apache.zookeeper.server.quorum.Leader.processAck:385) - outstanding > proposal: 0x300000001 > DEBUG [FollowerHandler-/172.17.1.133:40536] > (org.apache.zookeeper.server.quorum.Leader.processAck:385) - outstanding > proposal: 0x300000002 > DEBUG [FollowerHandler-/172.17.1.133:40536] > (org.apache.zookeeper.server.quorum.Leader.processAck:388) - outstanding > proposals all > DEBUG [FollowerHandler-/172.17.1.133:40536] > (org.apache.zookeeper.server.quorum.Leader.processAck:411) - Count for > zxid: 0x300000001 is 3 > DEBUG [FollowerHandler-/172.17.1.133:40536] > (org.apache.zookeeper.server.quorum.CommitProcessor.commit:158) - > Committing request:: sessionid:0x123bafb088a0000 type:createSession > cxid:0x0 zxid:0x300000001 txntype:-10 n/a > DEBUG [FollowerHandler-/172.17.1.133:40536] > (org.apache.zookeeper.server.quorum.Leader.processAck:382) - Ack zxid: > 0x300000002 > DEBUG [FollowerHandler-/172.17.1.133:40536] > (org.apache.zookeeper.server.quorum.Leader.processAck:385) - outstanding > proposal: 0x300000002 > DEBUG [FollowerHandler-/172.17.1.133:40536] > (org.apache.zookeeper.server.quorum.Leader.processAck:388) - outstanding > proposals all > DEBUG [FollowerHandler-/172.17.1.133:40536] > (org.apache.zookeeper.server.quorum.Leader.processAck:411) - Count for > zxid: 0x300000002 is 2 > DEBUG [CommitProcessor:0] > (org.apache.zookeeper.server.FinalRequestProcessor.processRequest:74) - > Processing request:: sessionid:0x123bafb088a0000 type:createSession > cxid:0x0 zxid:0x300000001 txntype:-10 n/a > DEBUG [QuorumPeer:/0:0:0:0:0:0:0:0:2182] > (org.apache.zookeeper.server.quorum.CommitProcessor.commit:158) - > Committing request:: sessionid:0x123bafb088a0000 type:createSession > cxid:0x0 zxid:0x300000001 txntype:-10 n/a > DEBUG [CommitProcessor:2] > (org.apache.zookeeper.server.FinalRequestProcessor.processRequest:74) - > Processing request:: sessionid:0x123bafb088a0000 type:createSession > cxid:0x0 zxid:0x300000001 txntype:-10 n/a > DEBUG [QuorumPeer:/0:0:0:0:0:0:0:0:2183] > (org.apache.zookeeper.server.quorum.CommitProcessor.commit:158) - > Committing request:: sessionid:0x123bafb088a0000 type:createSession > cxid:0x0 zxid:0x300000001 txntype:-10 n/a > DEBUG [CommitProcessor:3] > (org.apache.zookeeper.server.FinalRequestProcessor.processRequest:74) - > Processing request:: sessionid:0x123bafb088a0000 type:createSession > cxid:0x0 zxid:0x300000001 txntype:-10 n/a > DEBUG [QuorumPeer:/0:0:0:0:0:0:0:0:2181] > (org.apache.zookeeper.server.quorum.CommitProcessor.commit:158) - > Committing request:: sessionid:0x123bafb088a0000 type:createSession > cxid:0x0 zxid:0x300000001 txntype:-10 n/a > DEBUG [CommitProcessor:1] > (org.apache.zookeeper.server.FinalRequestProcessor.processRequest:74) - > Processing request:: sessionid:0x123bafb088a0000 type:createSession > cxid:0x0 zxid:0x300000001 txntype:-10 n/a > DEBUG [CommitProcessor:1] > (org.apache.zookeeper.server.FinalRequestProcessor.processRequest:137) - > sessionid:0x123bafb088a0000 type:createSession cxid:0x0 zxid:0x300000001 > txntype:-10 n/a > DEBUG [FollowerHandler-/172.17.1.133:40541] > (org.apache.zookeeper.server.quorum.Leader.processAck:382) - Ack zxid: > 0x300000001 > DEBUG [FollowerHandler-/172.17.1.133:40541] > (org.apache.zookeeper.server.quorum.Leader.processAck:385) - outstanding > proposal: 0x300000002 > DEBUG [FollowerHandler-/172.17.1.133:40541] > (org.apache.zookeeper.server.quorum.Leader.processAck:388) - outstanding > proposals all > DEBUG [FollowerHandler-/172.17.1.133:40541] > (org.apache.zookeeper.server.quorum.Leader.processAck:399) - proposal > has already been committed, pzxid:12884901890 zxid:12884901889 > DEBUG [FollowerHandler-/172.17.1.133:40541] > (org.apache.zookeeper.server.quorum.Leader.processAck:382) - Ack zxid: > 0x300000002 > DEBUG [FollowerHandler-/172.17.1.133:40541] > (org.apache.zookeeper.server.quorum.Leader.processAck:385) - outstanding > proposal: 0x300000002 > DEBUG [FollowerHandler-/172.17.1.133:40541] > (org.apache.zookeeper.server.quorum.Leader.processAck:388) - outstanding > proposals all > DEBUG [FollowerHandler-/172.17.1.133:40541] > (org.apache.zookeeper.server.quorum.Leader.processAck:411) - Count for > zxid: 0x300000002 is 3 > DEBUG [QuorumPeer:/0:0:0:0:0:0:0:0:2183] > (org.apache.zookeeper.server.quorum.CommitProcessor.commit:158) - > Committing request:: sessionid:0x123baf02f280000 type:closeSession > cxid:0x0 zxid:0x300000002 txntype:-11 n/a > DEBUG [CommitProcessor:3] > (org.apache.zookeeper.server.FinalRequestProcessor.processRequest:74) - > Processing request:: sessionid:0x123baf02f280000 type:closeSession > cxid:0x0 zxid:0x300000002 txntype:-11 n/a > DEBUG [QuorumPeer:/0:0:0:0:0:0:0:0:2181] > (org.apache.zookeeper.server.quorum.CommitProcessor.commit:158) - > Committing request:: sessionid:0x123baf02f280000 type:closeSession > cxid:0x0 zxid:0x300000002 txntype:-11 n/a > DEBUG [FollowerHandler-/172.17.1.133:40541] > (org.apache.zookeeper.server.quorum.CommitProcessor.commit:158) - > Committing request:: sessionid:0x123baf02f280000 type:closeSession > cxid:0x0 zxid:0x300000002 txntype:-11 n/a > DEBUG [QuorumPeer:/0:0:0:0:0:0:0:0:2182] > (org.apache.zookeeper.server.quorum.CommitProcessor.commit:158) - > Committing request:: sessionid:0x123baf02f280000 type:closeSession > cxid:0x0 zxid:0x300000002 txntype:-11 n/a > DEBUG [CommitProcessor:2] > (org.apache.zookeeper.server.FinalRequestProcessor.processRequest:74) - > Processing request:: sessionid:0x123baf02f280000 type:closeSession > cxid:0x0 zxid:0x300000002 txntype:-11 n/a > DEBUG [CommitProcessor:0] > (org.apache.zookeeper.server.FinalRequestProcessor.processRequest:74) - > Processing request:: sessionid:0x123baf02f280000 type:closeSession > cxid:0x0 zxid:0x300000002 txntype:-11 n/a > DEBUG [SyncThread:0] > (org.apache.zookeeper.server.quorum.Leader.processAck:382) - Ack zxid: > 0x300000002 > DEBUG [SyncThread:0] > (org.apache.zookeeper.server.quorum.Leader.processAck:388) - outstanding > proposals all > DEBUG [SyncThread:0] > (org.apache.zookeeper.server.quorum.Leader.processAck:393) - outstanding > is 0 > DEBUG [main-EventThread] > (com.audiencescience.util.zookeeper.qa.failover.FailOverTest$ZKWatcher.p > rocess:150) - ZK Watcher Called! > INFO [CommitProcessor:1] > (org.apache.zookeeper.server.NIOServerCnxn.finishSessionInit:881) - > Finished init of 0x123bafb088a0000 valid:true > DEBUG [CommitProcessor:1] > (org.apache.zookeeper.server.FinalRequestProcessor.processRequest:74) - > Processing request:: sessionid:0x123baf02f280000 type:closeSession > cxid:0x0 zxid:0x300000002 txntype:-11 n/a > DEBUG [FollowerRequestProcessor:1] > (org.apache.zookeeper.server.quorum.CommitProcessor.processRequest:168) > - Processing request:: sessionid:0x123bafb088a0000 type:setWatches > cxid:0xfffffffffffffff8 zxid:0xfffffffffffffffe txntype:unknown > DEBUG [FollowerRequestProcessor:1] > (org.apache.zookeeper.server.quorum.CommitProcessor.processRequest:168) > - Processing request:: sessionid:0x123bafb088a0000 type:setData cxid:0x1 > zxid:0xfffffffffffffffe txntype:unknown /test/simple/failover > DEBUG [ProcessThread:-1] > (org.apache.zookeeper.server.quorum.CommitProcessor.processRequest:168) > - Processing request:: sessionid:0x123bafb088a0000 type:setData cxid:0x1 > zxid:0x300000003 txntype:-1 n/a > DEBUG [ProcessThread:-1] > (org.apache.zookeeper.server.quorum.Leader.propose:560) - Proposing:: > sessionid:0x123bafb088a0000 type:setData cxid:0x1 zxid:0x300000003 > txntype:-1 n/a > DEBUG [FollowerHandler-/172.17.1.133:40537] > (org.apache.zookeeper.server.quorum.Leader.processAck:382) - Ack zxid: > 0x300000003 > DEBUG [FollowerHandler-/172.17.1.133:40537] > (org.apache.zookeeper.server.quorum.Leader.processAck:385) - outstanding > proposal: 0x300000003 > DEBUG [FollowerHandler-/172.17.1.133:40537] > (org.apache.zookeeper.server.quorum.Leader.processAck:388) - outstanding > proposals all > DEBUG [FollowerHandler-/172.17.1.133:40537] > (org.apache.zookeeper.server.quorum.Leader.processAck:411) - Count for > zxid: 0x300000003 is 1 > DEBUG [FollowerHandler-/172.17.1.133:40541] > (org.apache.zookeeper.server.quorum.Leader.processAck:382) - Ack zxid: > 0x300000003 > DEBUG [FollowerHandler-/172.17.1.133:40541] > (org.apache.zookeeper.server.quorum.Leader.processAck:385) - outstanding > proposal: 0x300000003 > DEBUG [FollowerHandler-/172.17.1.133:40541] > (org.apache.zookeeper.server.quorum.Leader.processAck:388) - outstanding > proposals all > DEBUG [FollowerHandler-/172.17.1.133:40541] > (org.apache.zookeeper.server.quorum.Leader.processAck:411) - Count for > zxid: 0x300000003 is 2 > DEBUG [FollowerHandler-/172.17.1.133:40536] > (org.apache.zookeeper.server.quorum.Leader.processAck:382) - Ack zxid: > 0x300000003 > DEBUG [FollowerHandler-/172.17.1.133:40536] > (org.apache.zookeeper.server.quorum.Leader.processAck:385) - outstanding > proposal: 0x300000003 > DEBUG [FollowerHandler-/172.17.1.133:40536] > (org.apache.zookeeper.server.quorum.Leader.processAck:388) - outstanding > proposals all > DEBUG [FollowerHandler-/172.17.1.133:40536] > (org.apache.zookeeper.server.quorum.Leader.processAck:411) - Count for > zxid: 0x300000003 is 3 > DEBUG [QuorumPeer:/0:0:0:0:0:0:0:0:2183] > (org.apache.zookeeper.server.quorum.CommitProcessor.commit:158) - > Committing request:: sessionid:0x123bafb088a0000 type:error cxid:0x1 > zxid:0x300000003 txntype:-1 n/a > DEBUG [CommitProcessor:3] > (org.apache.zookeeper.server.FinalRequestProcessor.processRequest:74) - > Processing request:: sessionid:0x123bafb088a0000 type:error cxid:0x1 > zxid:0x300000003 txntype:-1 n/a > DEBUG [QuorumPeer:/0:0:0:0:0:0:0:0:2181] > (org.apache.zookeeper.server.quorum.CommitProcessor.commit:158) - > Committing request:: sessionid:0x123bafb088a0000 type:error cxid:0x1 > zxid:0x300000003 txntype:-1 n/a > DEBUG [QuorumPeer:/0:0:0:0:0:0:0:0:2182] > (org.apache.zookeeper.server.quorum.CommitProcessor.commit:158) - > Committing request:: sessionid:0x123bafb088a0000 type:error cxid:0x1 > zxid:0x300000003 txntype:-1 n/a > DEBUG [CommitProcessor:2] > (org.apache.zookeeper.server.FinalRequestProcessor.processRequest:74) - > Processing request:: sessionid:0x123bafb088a0000 type:error cxid:0x1 > zxid:0x300000003 txntype:-1 n/a > DEBUG [FollowerHandler-/172.17.1.133:40536] > (org.apache.zookeeper.server.quorum.CommitProcessor.commit:158) - > Committing request:: sessionid:0x123bafb088a0000 type:setData cxid:0x1 > zxid:0x300000003 txntype:-1 n/a > DEBUG [CommitProcessor:0] > (org.apache.zookeeper.server.FinalRequestProcessor.processRequest:74) - > Processing request:: sessionid:0x123bafb088a0000 type:setData cxid:0x1 > zxid:0x300000003 txntype:-1 n/a > DEBUG [SyncThread:0] > (org.apache.zookeeper.server.quorum.Leader.processAck:382) - Ack zxid: > 0x300000003 > DEBUG [SyncThread:0] > (org.apache.zookeeper.server.quorum.Leader.processAck:388) - outstanding > proposals all > DEBUG [SyncThread:0] > (org.apache.zookeeper.server.quorum.Leader.processAck:393) - outstanding > is 0 > DEBUG [CommitProcessor:1] > (org.apache.zookeeper.server.FinalRequestProcessor.processRequest:74) - > Processing request:: sessionid:0x123bafb088a0000 type:setWatches > cxid:0xfffffffffffffff8 zxid:0xfffffffffffffffe txntype:unknown > DEBUG [CommitProcessor:1] > (org.apache.zookeeper.server.FinalRequestProcessor.processRequest:137) - > sessionid:0x123bafb088a0000 type:setWatches cxid:0xfffffffffffffff8 > zxid:0xfffffffffffffffe txntype:unknown > DEBUG [CommitProcessor:1] > (org.apache.zookeeper.server.FinalRequestProcessor.processRequest:74) - > Processing request:: sessionid:0x123bafb088a0000 type:setData cxid:0x1 > zxid:0x300000003 txntype:-1 /test/simple/failover > DEBUG [main-SendThread] > (org.apache.zookeeper.ClientCnxn$SendThread.readResponse:610) - Reading > reply sessionid:0x123bafb088a0000, packet:: path:null finished:false > header:: -8,101 replyHeader:: -8,-1,0 request:: 0,v{},v{},v{} > response:: null > DEBUG [main-SendThread] > (org.apache.zookeeper.ClientCnxn$SendThread.readResponse:610) - Reading > reply sessionid:0x123bafb088a0000, packet:: path:null finished:false > header:: 1,5 replyHeader:: 1,12884901891,-101 request:: > '/test/simple/failover,#5468697320697320612074657374,1 response:: > DEBUG [FollowerRequestProcessor:1] > (org.apache.zookeeper.server.quorum.CommitProcessor.processRequest:168) > - Processing request:: sessionid:0x123bafb088a0000 type:ping > cxid:0xfffffffffffffffe zxid:0xfffffffffffffffe txntype:unknown n/a > DEBUG [CommitProcessor:1] > (org.apache.zookeeper.server.FinalRequestProcessor.processRequest:74) - > Processing request:: sessionid:0x123bafb088a0000 type:ping > cxid:0xfffffffffffffffe zxid:0xfffffffffffffffe txntype:unknown n/a > DEBUG [CommitProcessor:1] > (org.apache.zookeeper.server.FinalRequestProcessor.processRequest:137) - > sessionid:0x123bafb088a0000 type:ping cxid:0xfffffffffffffffe > zxid:0xfffffffffffffffe txntype:unknown n/a > DEBUG [main-SendThread] > (org.apache.zookeeper.ClientCnxn$SendThread.readResponse:548) - Got ping > response for sessionid:0x123bafb088a0000 after 2ms > DEBUG [FollowerRequestProcessor:1] > (org.apache.zookeeper.server.quorum.CommitProcessor.processRequest:168) > - Processing request:: sessionid:0x123bafb088a0000 type:ping > cxid:0xfffffffffffffffe zxid:0xfffffffffffffffe txntype:unknown n/a > DEBUG [CommitProcessor:1] > (org.apache.zookeeper.server.FinalRequestProcessor.processRequest:74) - > Processing request:: sessionid:0x123bafb088a0000 type:ping > cxid:0xfffffffffffffffe zxid:0xfffffffffffffffe txntype:unknown n/a > DEBUG [CommitProcessor:1] > (org.apache.zookeeper.server.FinalRequestProcessor.processRequest:137) - > sessionid:0x123bafb088a0000 type:ping cxid:0xfffffffffffffffe > zxid:0xfffffffffffffffe txntype:unknown n/a > DEBUG [main-SendThread] > (org.apache.zookeeper.ClientCnxn$SendThread.readResponse:548) - Got ping > response for sessionid:0x123bafb088a0000 after 2ms > > The last 3 lines get repeated for ever.... > > > Rob Baccus > 425-201-3812 >