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

Reply via email to