Skip to content

Instantly share code, notes, and snippets.

@mindreframer

mindreframer/zookeeper_rb_segfault

Created January 18, 2011 23:56
Show Gist options
  • Save mindreframer/785414 to your computer and use it in GitHub Desktop.
Save mindreframer/785414 to your computer and use it in GitHub Desktop.
Download ZIP
Raw
zookeeper_rb_segfault
- servers on 93 => 1, 94 => 2, 95 => 3 (checked)
# zoo.cfg ###############################################################
tickTime=2000
dataDir=/var/zookeeper
clientPort=2181
initLimit=5
syncLimit=2
server.1=192.168.2.93:2888:3888
server.2=192.168.2.94:2888:3888
server.3=192.168.2.95:2888:3888
- leader was 94, it was restartet
- all other nodes were online
- ruby client seems not to get the connection to other servers...
-
# ruby ###################################################################
>> require 'zookeeper'
=> true
>> ZK = Zookeeper.new('192.168.2.93:2181, 192.168.2.94:2181, 192.168.2.95:2181')
=> #<Zookeeper:0x16df640 @host="192.168.2.93:2181, 192.168.2.94:2181, 192.168.2.95:2181", @completion_reqs={}, @watcher_reqs={-1=>{:watcher=>#<Proc:0x0000000001702b40@/usr/local/lib/ruby/gems/1.8/gems/zookeeper-0.4.2/lib/zookeeper.rb:228>}}, @dispatcher=#<Thread:0x16df398 sleep>, @data=#<CZookeeper:0x16df528>, @current_req_id=1, @req_mutex=#<Mutex:0x16df5a0>>
>>
?>
?>
?> def set_callback(path)
>> wcb = Zookeeper::WatcherCallback.new do
?> puts "callback fired for #{path}"
>> new_value = ZK.get(:path => path)[:data]
>> puts "value changed to #{new_value}"
>> set_callback(path)
>> end
>> ZK.stat(:path => path, :watcher => wcb)
>> end
=> nil
>>
?> ZK.set_debug_level(Zookeeper::ZOO_LOG_LEVEL_DEBUG)
=> nil
>> set_callback('/test')
2011-01-19 00:40:56,158:22204(0x7f24e975c6f0):ZOO_DEBUG@zoo_awexists@2587: Sending request xid=0x4d362509 for path [/test] to 192.168.2.94:2181
2011-01-19 00:40:56,161:22204(0x4181a950):ZOO_DEBUG@zookeeper_process@2025: Calling COMPLETION_STAT for xid=0x4d362509 rc=0
=> {:stat=>#<ZookeeperStat::Stat:0x16a9c48 @mzxid=30064771075, @numChildren=0, @version=118, @cversion=0, @czxid=4294967298, @dataLength=2, @mtime=1295393891350, @exists=true, @ephemeralOwner=0, @ctime=1295261474350, @pzxid=4294967298, @aversion=0>, :req_id=>1, :rc=>0}
>> ZK.set(:path => '/test', :data => '60')
2011-01-19 00:40:56,164:22204(0x7f24e975c6f0):ZOO_DEBUG@zoo_aset@2455: Sending request xid=0x4d36250a for path [/test] to 192.168.2.94:2181
2011-01-19 00:40:56,177:22204(0x4181a950):ZOO_DEBUG@zookeeper_process@1916: Processing WATCHER_EVENT
2011-01-19 00:40:56,177:22204(0x4201b950):ZOO_DEBUG@process_completions@1765: Calling a watcher for node [/test], type = -1 event=ZOO_CHANGED_EVENT
ZOOKEEPER_C_STATE WATCHER type = 3, state = 3, path = 0x0x2838b18, value = /test
2011-01-19 00:40:56,177:22204(0x4181a950):ZOO_DEBUG@zookeeper_process@2025: Calling COMPLETION_STAT for xid=0x4d36250a rc=0
=> {:stat=>#<ZookeeperStat::Stat:0x169ace8 @mzxid=34359738371, @numChildren=0, @version=119, @cversion=0, @czxid=4294967298, @dataLength=2, @mtime=1295394056164, @exists=true, @ephemeralOwner=0, @ctime=1295261474350, @pzxid=4294967298, @aversion=0>, :req_id=>2, :rc=>0}
>> callback fired for /test
2011-01-19 00:40:56,250:22204(0x7f24e975c6f0):ZOO_DEBUG@zoo_awget@2414: Sending request xid=0x4d36250b for path [/test] to 192.168.2.94:2181
2011-01-19 00:40:56,252:22204(0x4181a950):ZOO_DEBUG@zookeeper_process@2001: Calling COMPLETION_DATA for xid=0x4d36250b rc=0
value changed to 60
2011-01-19 00:40:56,252:22204(0x7f24e975c6f0):ZOO_DEBUG@zoo_awexists@2587: Sending request xid=0x4d36250c for path [/test] to 192.168.2.94:2181
2011-01-19 00:40:56,253:22204(0x4181a950):ZOO_DEBUG@zookeeper_process@2025: Calling COMPLETION_STAT for xid=0x4d36250c rc=0
2011-01-19 00:40:59,587:22204(0x4181a950):ZOO_DEBUG@zookeeper_process@1983: Got ping response in 0 ms
2011-01-19 00:41:02,927:22204(0x4181a950):ZOO_DEBUG@zookeeper_process@1983: Got ping response in 0 ms
2011-01-19 00:41:06,261:22204(0x4181a950):ZOO_DEBUG@zookeeper_process@1983: Got ping response in 0 ms
2011-01-19 00:41:09,597:22204(0x4181a950):ZOO_DEBUG@zookeeper_process@1983: Got ping response in 0 ms
2011-01-19 00:41:12,933:22204(0x4181a950):ZOO_DEBUG@zookeeper_process@1983: Got ping response in 0 ms
2011-01-19 00:41:16,271:22204(0x4181a950):ZOO_DEBUG@zookeeper_process@1983: Got ping response in 0 ms
2011-01-19 00:41:19,605:22204(0x4181a950):ZOO_DEBUG@zookeeper_process@1983: Got ping response in 0 ms
2011-01-19 00:41:22,942:22204(0x4181a950):ZOO_DEBUG@zookeeper_process@1983: Got ping response in 0 ms
2011-01-19 00:41:26,277:22204(0x4181a950):ZOO_DEBUG@zookeeper_process@1983: Got ping response in 0 ms
2011-01-19 00:41:29,615:22204(0x4181a950):ZOO_DEBUG@zookeeper_process@1983: Got ping response in 0 ms
2011-01-19 00:41:32,950:22204(0x4181a950):ZOO_DEBUG@zookeeper_process@1983: Got ping response in 0 ms
2011-01-19 00:41:36,285:22204(0x4181a950):ZOO_DEBUG@zookeeper_process@1983: Got ping response in 0 ms
2011-01-19 00:41:39,623:22204(0x4181a950):ZOO_DEBUG@zookeeper_process@1983: Got ping response in 0 ms
2011-01-19 00:41:42,958:22204(0x4181a950):ZOO_DEBUG@zookeeper_process@1983: Got ping response in 0 ms
2011-01-19 00:41:46,295:22204(0x4181a950):ZOO_DEBUG@zookeeper_process@1983: Got ping response in 0 ms
2011-01-19 00:41:49,629:22204(0x4181a950):ZOO_DEBUG@zookeeper_process@1983: Got ping response in 0 ms
2011-01-19 00:41:52,965:22204(0x4181a950):ZOO_DEBUG@zookeeper_process@1983: Got ping response in 0 ms
2011-01-19 00:41:56,303:22204(0x4181a950):ZOO_DEBUG@zookeeper_process@1983: Got ping response in 0 ms
2011-01-19 00:41:59,638:22204(0x4181a950):ZOO_DEBUG@zookeeper_process@1983: Got ping response in 0 ms
2011-01-19 00:42:02,974:22204(0x4181a950):ZOO_DEBUG@zookeeper_process@1983: Got ping response in 0 ms
2011-01-19 00:42:06,311:22204(0x4181a950):ZOO_DEBUG@zookeeper_process@1983: Got ping response in 0 ms
2011-01-19 00:42:09,646:22204(0x4181a950):ZOO_DEBUG@zookeeper_process@1983: Got ping response in 0 ms
2011-01-19 00:42:11,773:22204(0x4181a950):ZOO_ERROR@handle_socket_error_msg@1603: Socket [192.168.2.94:2181] zk retcode=-4, errno=112(Host is down): failed while receiving a server response
2011-01-19 00:42:11,773:22204(0x4181a950):ZOO_DEBUG@handle_error@1141: Calling a watcher for a ZOO_SESSION_EVENT and the state=CONNECTING_STATE
2011-01-19 00:42:11,773:22204(0x4201b950):ZOO_DEBUG@process_completions@1765: Calling a watcher for node [], type = -1 event=ZOO_SESSION_EVENT
ZOOKEEPER_C_STATE WATCHER type = -1, state = 1, path = 0x0x2838b18, value =
ZOOKEEPER_C_STATE WATCHER type = -1, state = 1, path = 0x0x2838b18, value =
2011-01-19 00:42:11,774:22204(0x4181a950):ZOO_INFO@check_events@1585: initiated connection to server [192.168.2.93:2181]
2011-01-19 00:42:11,778:22204(0x4181a950):ZOO_ERROR@handle_socket_error_msg@1603: Socket [192.168.2.93:2181] zk retcode=-4, errno=112(Host is down): failed while receiving a server response
2011-01-19 00:42:11,782:22204(0x4181a950):ZOO_INFO@check_events@1585: initiated connection to server [192.168.2.95:2181]
2011-01-19 00:42:11,786:22204(0x4181a950):ZOO_ERROR@handle_socket_error_msg@1603: Socket [192.168.2.95:2181] zk retcode=-4, errno=112(Host is down): failed while receiving a server response
callback fired for /test
2011-01-19 00:42:15,122:22204(0x4181a950):ZOO_ERROR@handle_socket_error_msg@1579: Socket [192.168.2.94:2181] zk retcode=-4, errno=111(Connection refused): server refused to accept the client
2011-01-19 00:42:15,123:22204(0x4181a950):ZOO_INFO@check_events@1585: initiated connection to server [192.168.2.93:2181]
2011-01-19 00:42:15,126:22204(0x4181a950):ZOO_INFO@check_events@1632: session establishment complete on server [192.168.2.93:2181], sessionId=0x22d9b7e38c40000, negotiated timeout=10000
2011-01-19 00:42:15,126:22204(0x4181a950):ZOO_DEBUG@send_set_watches@1312: Sending set watches request to 192.168.2.93:2181
2011-01-19 00:42:15,126:22204(0x4181a950):ZOO_DEBUG@check_events@1638: Calling a watcher for a ZOO_SESSION_EVENT and the state=ZOO_CONNECTED_STATE
2011-01-19 00:42:15,126:22204(0x4201b950):ZOO_DEBUG@process_completions@1765: Calling a watcher for node [], type = -1 event=ZOO_SESSION_EVENT
ZOOKEEPER_C_STATE WATCHER type = -1, state = 3, path = 0x0x2838b18, value =
/usr/local/lib/ruby/gems/1.8/gems/zookeeper-0.4.2/lib/zookeeper.rb:239: [BUG] Segmentation fault
ruby 1.8.7 (2009-12-24 patchlevel 248) [x86_64-linux], MBARI 0x6770, Ruby Enterprise Edition 2010.01
Aborted
# 94 #########################################################################
2011-01-19 00:40:56,049 - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn$Factory@251] - Accepted socket connection from /192.168.2.91:58270
2011-01-19 00:40:56,050 - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@777] - Client attempting to establish new session at /192.168.2.91:58270
2011-01-19 00:40:56,097 - INFO [CommitProcessor:2:NIOServerCnxn@1580] - Established session 0x22d9b7e38c40000 with negotiated timeout 10000 for client /192.168.2.91:58270
2011-01-19 00:40:56,176 - ERROR [CommitProcessor:2:NIOServerCnxn@445] - Unexpected Exception:
java.nio.channels.CancelledKeyException
at sun.nio.ch.SelectionKeyImpl.ensureValid(SelectionKeyImpl.java:73)
at sun.nio.ch.SelectionKeyImpl.interestOps(SelectionKeyImpl.java:77)
at org.apache.zookeeper.server.NIOServerCnxn.sendBuffer(NIOServerCnxn.java:418)
at org.apache.zookeeper.server.NIOServerCnxn.sendResponse(NIOServerCnxn.java:1509)
at org.apache.zookeeper.server.NIOServerCnxn.process(NIOServerCnxn.java:1545)
at org.apache.zookeeper.server.WatchManager.triggerWatch(WatchManager.java:115)
at org.apache.zookeeper.server.WatchManager.triggerWatch(WatchManager.java:87)
at org.apache.zookeeper.server.DataTree.setData(DataTree.java:606)
at org.apache.zookeeper.server.DataTree.processTxn(DataTree.java:774)
at org.apache.zookeeper.server.ZKDatabase.processTxn(ZKDatabase.java:299)
at org.apache.zookeeper.server.FinalRequestProcessor.processRequest(FinalRequestProcessor.java:103)
at org.apache.zookeeper.server.quorum.Leader$ToBeAppliedRequestProcessor.processRequest(Leader.java:540)
at org.apache.zookeeper.server.quorum.CommitProcessor.run(CommitProcessor.java:73)
root@blade24:/home/roman# /etc/init.d/zookeeper restart
JMX enabled by default
Using config: /opt/zookeeper-3.3.2/bin/../conf/zoo.cfg
JMX enabled by default
Using config: /opt/zookeeper-3.3.2/bin/../conf/zoo.cfg
Stopping zookeeper ...
STOPPED
JMX enabled by default
Using config: /opt/zookeeper-3.3.2/bin/../conf/zoo.cfg
Starting zookeeper ...
STARTED
root@blade24:/home/roman# 2011-01-19 00:42:15,173 - INFO [main:QuorumPeerConfig@90] - Reading configuration from: /opt/zookeeper-3.3.2/bin/../conf/zoo.cfg
2011-01-19 00:42:15,180 - INFO [main:QuorumPeerConfig@310] - Defaulting to majority quorums
2011-01-19 00:42:15,207 - INFO [main:QuorumPeerMain@119] - Starting quorum peer
2011-01-19 00:42:15,245 - INFO [main:NIOServerCnxn$Factory@143] - binding to port 0.0.0.0/0.0.0.0:2181
2011-01-19 00:42:15,263 - INFO [main:QuorumPeer@818] - tickTime set to 2000
2011-01-19 00:42:15,264 - INFO [main:QuorumPeer@829] - minSessionTimeout set to -1
2011-01-19 00:42:15,265 - INFO [main:QuorumPeer@840] - maxSessionTimeout set to -1
2011-01-19 00:42:15,265 - INFO [main:QuorumPeer@855] - initLimit set to 5
2011-01-19 00:42:15,288 - INFO [main:FileSnap@82] - Reading snapshot /var/zookeeper/version-2/snapshot.700000003
2011-01-19 00:42:15,326 - INFO [Thread-1:QuorumCnxManager$Listener@454] - My election bind port: 3888
2011-01-19 00:42:15,356 - INFO [QuorumPeer:/0:0:0:0:0:0:0:0:2181:QuorumPeer@620] - LOOKING
2011-01-19 00:42:15,358 - INFO [QuorumPeer:/0:0:0:0:0:0:0:0:2181:FastLeaderElection@663] - New election. My id = 2, Proposed zxid = 34359738371
2011-01-19 00:42:15,366 - INFO [WorkerReceiver Thread:FastLeaderElection@496] - Notification: 2 (n.leader), 34359738371 (n.zxid), 1 (n.round), LOOKING (n.state), 2 (n.sid), LOOKING (my state)
2011-01-19 00:42:15,367 - INFO [WorkerSender Thread:QuorumCnxManager@176] - Have smaller server identifier, so dropping the connection: (3, 2)
2011-01-19 00:42:15,369 - INFO [WorkerReceiver Thread:FastLeaderElection@496] - Notification: 3 (n.leader), 34359738371 (n.zxid), 13 (n.round), LOOKING (n.state), 3 (n.sid), LOOKING (my state)
2011-01-19 00:42:15,370 - INFO [WorkerReceiver Thread:FastLeaderElection@496] - Notification: 3 (n.leader), 34359738371 (n.zxid), 13 (n.round), LEADING (n.state), 3 (n.sid), LOOKING (my state)
2011-01-19 00:42:15,370 - INFO [WorkerReceiver Thread:FastLeaderElection@496] - Notification: 3 (n.leader), 34359738371 (n.zxid), 13 (n.round), LOOKING (n.state), 2 (n.sid), FOLLOWING (my state)
2011-01-19 00:42:15,371 - INFO [QuorumPeer:/0:0:0:0:0:0:0:0:2181:QuorumPeer@642] - FOLLOWING
2011-01-19 00:42:15,372 - INFO [WorkerReceiver Thread:FastLeaderElection@496] - Notification: 1 (n.leader), 34359738371 (n.zxid), 13 (n.round), LOOKING (n.state), 1 (n.sid), FOLLOWING (my state)
2011-01-19 00:42:15,373 - INFO [WorkerReceiver Thread:FastLeaderElection@496] - Notification: 3 (n.leader), 34359738371 (n.zxid), 13 (n.round), LOOKING (n.state), 1 (n.sid), FOLLOWING (my state)
2011-01-19 00:42:15,373 - INFO [WorkerReceiver Thread:FastLeaderElection@496] - Notification: 3 (n.leader), 34359738371 (n.zxid), 13 (n.round), FOLLOWING (n.state), 1 (n.sid), FOLLOWING (my state)
2011-01-19 00:42:15,376 - INFO [WorkerReceiver Thread:FastLeaderElection@496] - Notification: 3 (n.leader), 34359738371 (n.zxid), 13 (n.round), FOLLOWING (n.state), 1 (n.sid), FOLLOWING (my state)
2011-01-19 00:42:15,376 - INFO [WorkerReceiver Thread:FastLeaderElection@496] - Notification: 3 (n.leader), 34359738371 (n.zxid), 13 (n.round), LEADING (n.state), 3 (n.sid), FOLLOWING (my state)
2011-01-19 00:42:15,377 - INFO [WorkerReceiver Thread:FastLeaderElection@496] - Notification: 3 (n.leader), 34359738371 (n.zxid), 13 (n.round), FOLLOWING (n.state), 2 (n.sid), FOLLOWING (my state)
2011-01-19 00:42:15,379 - INFO [QuorumPeer:/0:0:0:0:0:0:0:0:2181:Learner@72] - TCP NoDelay set to: true
2011-01-19 00:42:15,429 - INFO [QuorumPeer:/0:0:0:0:0:0:0:0:2181:Environment@97] - Server environment:zookeeper.version=3.3.2-1031432, built on 11/05/2010 05:32 GMT
2011-01-19 00:42:15,429 - INFO [QuorumPeer:/0:0:0:0:0:0:0:0:2181:Environment@97] - Server environment:host.name=212.91.241.20
2011-01-19 00:42:15,430 - INFO [QuorumPeer:/0:0:0:0:0:0:0:0:2181:Environment@97] - Server environment:java.version=1.6.0_18
2011-01-19 00:42:15,430 - INFO [QuorumPeer:/0:0:0:0:0:0:0:0:2181:Environment@97] - Server environment:java.vendor=Sun Microsystems Inc.
2011-01-19 00:42:15,430 - INFO [QuorumPeer:/0:0:0:0:0:0:0:0:2181:Environment@97] - Server environment:java.home=/usr/lib/jvm/java-6-openjdk/jre
2011-01-19 00:42:15,431 - INFO [QuorumPeer:/0:0:0:0:0:0:0:0:2181:Environment@97] - Server environment:java.class.path=/opt/zookeeper-3.3.2/bin/../build/classes:/opt/zookeeper-3.3.2/bin/../build/lib/*.jar:/opt/zookeeper-3.3.2/bin/../zookeeper-3.3.2.jar:/opt/zookeeper-3.3.2/bin/../lib/log4j-1.2.15.jar:/opt/zookeeper-3.3.2/bin/../lib/jline-0.9.94.jar:/opt/zookeeper-3.3.2/bin/../src/java/lib/*.jar:/opt/zookeeper-3.3.2/bin/../conf:
2011-01-19 00:42:15,431 - INFO [QuorumPeer:/0:0:0:0:0:0:0:0:2181:Environment@97] - Server environment:java.library.path=/usr/lib/jvm/java-6-openjdk/jre/lib/amd64/server:/usr/lib/jvm/java-6-openjdk/jre/lib/amd64:/usr/lib/jvm/java-6-openjdk/jre/../lib/amd64:/usr/java/packages/lib/amd64:/usr/lib/jni:/lib:/usr/lib
2011-01-19 00:42:15,432 - INFO [QuorumPeer:/0:0:0:0:0:0:0:0:2181:Environment@97] - Server environment:java.io.tmpdir=/tmp
2011-01-19 00:42:15,432 - INFO [QuorumPeer:/0:0:0:0:0:0:0:0:2181:Environment@97] - Server environment:java.compiler=<NA>
2011-01-19 00:42:15,432 - INFO [QuorumPeer:/0:0:0:0:0:0:0:0:2181:Environment@97] - Server environment:os.name=Linux
2011-01-19 00:42:15,433 - INFO [QuorumPeer:/0:0:0:0:0:0:0:0:2181:Environment@97] - Server environment:os.arch=amd64
2011-01-19 00:42:15,433 - INFO [QuorumPeer:/0:0:0:0:0:0:0:0:2181:Environment@97] - Server environment:os.version=2.6.24-28-server
2011-01-19 00:42:15,434 - INFO [QuorumPeer:/0:0:0:0:0:0:0:0:2181:Environment@97] - Server environment:user.name=root
2011-01-19 00:42:15,434 - INFO [QuorumPeer:/0:0:0:0:0:0:0:0:2181:Environment@97] - Server environment:user.home=/root
2011-01-19 00:42:15,434 - INFO [QuorumPeer:/0:0:0:0:0:0:0:0:2181:Environment@97] - Server environment:user.dir=/home/roman
2011-01-19 00:42:15,436 - INFO [QuorumPeer:/0:0:0:0:0:0:0:0:2181:ZooKeeperServer@151] - Created server with tickTime 2000 minSessionTimeout 4000 maxSessionTimeout 40000 datadir /var/zookeeper/version-2 snapdir /var/zookeeper/version-2
2011-01-19 00:42:15,449 - INFO [QuorumPeer:/0:0:0:0:0:0:0:0:2181:Learner@285] - Getting a snapshot from leader
2011-01-19 00:42:15,450 - INFO [QuorumPeer:/0:0:0:0:0:0:0:0:2181:Learner@315] - Setting leader epoch 9
2011-01-19 00:42:15,463 - INFO [QuorumPeer:/0:0:0:0:0:0:0:0:2181:FileTxnSnapLog@208] - Snapshotting: 900000000
2011-01-19 00:42:28,002 - WARN [QuorumPeer:/0:0:0:0:0:0:0:0:2181:Follower@116] - Got zxid 0x900000001 expected 0x1
2011-01-19 00:42:28,002 - INFO [SyncThread:2:FileTxnLog@197] - Creating new log file: log.900000001
# 95 ###########################################################################
2011-01-19 00:42:11,773 - WARN [Thread-5:QuorumCnxManager$RecvWorker@702] - Connection broken for id 2, my id = 3, error = java.io.IOException: Channel eof
2011-01-19 00:42:11,775 - WARN [QuorumPeer:/0:0:0:0:0:0:0:0:2181:Follower@82] - Exception when following the leader
java.io.EOFException
at java.io.DataInputStream.readInt(DataInputStream.java:392)
at org.apache.jute.BinaryInputArchive.readInt(BinaryInputArchive.java:63)
at org.apache.zookeeper.server.quorum.QuorumPacket.deserialize(QuorumPacket.java:84)
at org.apache.jute.BinaryInputArchive.readRecord(BinaryInputArchive.java:108)
at org.apache.zookeeper.server.quorum.Learner.readPacket(Learner.java:140)
at org.apache.zookeeper.server.quorum.Follower.followLeader(Follower.java:78)
at org.apache.zookeeper.server.quorum.QuorumPeer.run(QuorumPeer.java:644)
2011-01-19 00:42:11,777 - INFO [QuorumPeer:/0:0:0:0:0:0:0:0:2181:Follower@166] - shutdown called
java.lang.Exception: shutdown Follower
at org.apache.zookeeper.server.quorum.Follower.shutdown(Follower.java:166)
at org.apache.zookeeper.server.quorum.QuorumPeer.run(QuorumPeer.java:648)
2011-01-19 00:42:11,777 - INFO [QuorumPeer:/0:0:0:0:0:0:0:0:2181:FinalRequestProcessor@378] - shutdown of request processor complete
2011-01-19 00:42:11,777 - INFO [CommitProcessor:3:CommitProcessor@148] - CommitProcessor exited loop!
2011-01-19 00:42:11,778 - INFO [SyncThread:3:SyncRequestProcessor@151] - SyncRequestProcessor exited!
2011-01-19 00:42:11,777 - INFO [FollowerRequestProcessor:3:FollowerRequestProcessor@93] - FollowerRequestProcessor exited loop!
2011-01-19 00:42:11,778 - INFO [QuorumPeer:/0:0:0:0:0:0:0:0:2181:QuorumPeer@620] - LOOKING
2011-01-19 00:42:11,783 - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn$Factory@251] - Accepted socket connection from /192.168.2.91:49121
2011-01-19 00:42:11,785 - WARN [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@639] - Exception causing close of session 0x0 due to java.io.IOException: ZooKeeperServer not running
2011-01-19 00:42:11,785 - INFO [QuorumPeer:/0:0:0:0:0:0:0:0:2181:FileSnap@82] - Reading snapshot /var/zookeeper/version-2/snapshot.800000000
2011-01-19 00:42:11,785 - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@1435] - Closed socket connection for client /192.168.2.91:49121 (no session established for client)
2011-01-19 00:42:11,791 - INFO [WorkerReceiver Thread:FastLeaderElection@496] - Notification: 1 (n.leader), 34359738371 (n.zxid), 13 (n.round), LOOKING (n.state), 1 (n.sid), LOOKING (my state)
2011-01-19 00:42:11,794 - INFO [QuorumPeer:/0:0:0:0:0:0:0:0:2181:FastLeaderElection@663] - New election. My id = 3, Proposed zxid = 34359738371
2011-01-19 00:42:11,794 - INFO [WorkerReceiver Thread:FastLeaderElection@496] - Notification: 3 (n.leader), 34359738371 (n.zxid), 13 (n.round), LOOKING (n.state), 3 (n.sid), LOOKING (my state)
2011-01-19 00:42:11,796 - WARN [Thread-4:QuorumCnxManager$SendWorker@617] - Exception when using channel: for id 2 my id = 3 error = java.nio.channels.ClosedChannelException
2011-01-19 00:42:11,797 - WARN [Thread-4:QuorumCnxManager$SendWorker@621] - Send worker leaving thread
2011-01-19 00:42:11,800 - INFO [WorkerReceiver Thread:FastLeaderElection@496] - Notification: 3 (n.leader), 34359738371 (n.zxid), 13 (n.round), LOOKING (n.state), 1 (n.sid), LOOKING (my state)
2011-01-19 00:42:12,001 - INFO [QuorumPeer:/0:0:0:0:0:0:0:0:2181:QuorumPeer@654] - LEADING
2011-01-19 00:42:12,004 - INFO [QuorumPeer:/0:0:0:0:0:0:0:0:2181:Leader@54] - TCP NoDelay set to: true
2011-01-19 00:42:12,006 - INFO [QuorumPeer:/0:0:0:0:0:0:0:0:2181:ZooKeeperServer@151] - Created server with tickTime 2000 minSessionTimeout 4000 maxSessionTimeout 40000 datadir /var/zookeeper/version-2 snapdir /var/zookeeper/version-2
2011-01-19 00:42:12,014 - INFO [QuorumPeer:/0:0:0:0:0:0:0:0:2181:FileSnap@82] - Reading snapshot /var/zookeeper/version-2/snapshot.800000000
2011-01-19 00:42:12,023 - INFO [QuorumPeer:/0:0:0:0:0:0:0:0:2181:FileTxnSnapLog@208] - Snapshotting: 800000003
2011-01-19 00:42:13,005 - INFO [LearnerHandler-/192.168.2.93:36180:LearnerHandler@247] - Follower sid: 1 : info : org.apache.zookeeper.server.quorum.QuorumPeer$QuorumServer@1fa12495
2011-01-19 00:42:13,007 - WARN [LearnerHandler-/192.168.2.93:36180:LearnerHandler@326] - Sending snapshot last zxid of peer is 0x800000003 zxid of leader is 0x900000000
2011-01-19 00:42:13,053 - WARN [LearnerHandler-/192.168.2.93:36180:Leader@471] - Commiting zxid 0x900000000 from /192.168.2.95:2888 not first!
2011-01-19 00:42:13,054 - WARN [LearnerHandler-/192.168.2.93:36180:Leader@473] - First is 0
2011-01-19 00:42:13,054 - INFO [LearnerHandler-/192.168.2.93:36180:Leader@497] - Have quorum of supporters; starting up and setting last processed zxid: 38654705664
2011-01-19 00:42:15,369 - INFO [WorkerReceiver Thread:FastLeaderElection@496] - Notification: 2 (n.leader), 34359738371 (n.zxid), 1 (n.round), LOOKING (n.state), 2 (n.sid), LEADING (my state)
2011-01-19 00:42:15,371 - INFO [WorkerReceiver Thread:FastLeaderElection@496] - Notification: 3 (n.leader), 34359738371 (n.zxid), 13 (n.round), LOOKING (n.state), 2 (n.sid), LEADING (my state)
2011-01-19 00:42:15,449 - INFO [LearnerHandler-/192.168.2.94:47769:LearnerHandler@247] - Follower sid: 2 : info : org.apache.zookeeper.server.quorum.QuorumPeer$QuorumServer@2fa918d5
2011-01-19 00:42:15,449 - WARN [LearnerHandler-/192.168.2.94:47769:LearnerHandler@326] - Sending snapshot last zxid of peer is 0x800000003 zxid of leader is 0x900000000
2011-01-19 00:42:28,000 - INFO [SessionTracker:ZooKeeperServer@314] - Expiring session 0x22d9b7e38c40000, timeout of 10000ms exceeded
2011-01-19 00:42:28,001 - INFO [ProcessThread:-1:PrepRequestProcessor@387] - Processed session termination for sessionid: 0x22d9b7e38c40000
# 93 ###########################################################################
2011-01-19 00:42:11,774 - WARN [Thread-9:QuorumCnxManager$RecvWorker@702] - Connection broken for id 2, my id = 1, error = java.io.IOException: Channel eof
2011-01-19 00:42:11,775 - WARN [QuorumPeer:/0:0:0:0:0:0:0:0:2181:Follower@82] - Exception when following the leader
java.io.EOFException
at java.io.DataInputStream.readInt(DataInputStream.java:392)
at org.apache.jute.BinaryInputArchive.readInt(BinaryInputArchive.java:63)
at org.apache.zookeeper.server.quorum.QuorumPacket.deserialize(QuorumPacket.java:84)
at org.apache.jute.BinaryInputArchive.readRecord(BinaryInputArchive.java:108)
at org.apache.zookeeper.server.quorum.Learner.readPacket(Learner.java:140)
at org.apache.zookeeper.server.quorum.Follower.followLeader(Follower.java:78)
at org.apache.zookeeper.server.quorum.QuorumPeer.run(QuorumPeer.java:644)
2011-01-19 00:42:11,775 - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn$Factory@251] - Accepted socket connection from /192.168.2.91:53770
2011-01-19 00:42:11,776 - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@770] - Client attempting to renew session 0x22d9b7e38c40000 at /192.168.2.91:53770
2011-01-19 00:42:11,777 - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:Learner@95] - Revalidating client: 156952528448389120
2011-01-19 00:42:11,776 - INFO [QuorumPeer:/0:0:0:0:0:0:0:0:2181:Follower@166] - shutdown called
java.lang.Exception: shutdown Follower
at org.apache.zookeeper.server.quorum.Follower.shutdown(Follower.java:166)
at org.apache.zookeeper.server.quorum.QuorumPeer.run(QuorumPeer.java:648)
2011-01-19 00:42:11,778 - WARN [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@639] - Exception causing close of session 0x22d9b7e38c40000 due to java.net.SocketException: Socket closed
2011-01-19 00:42:11,779 - INFO [QuorumPeer:/0:0:0:0:0:0:0:0:2181:NIOServerCnxn@1435] - Closed socket connection for client /192.168.2.91:53770 which had sessionid 0x22d9b7e38c40000
2011-01-19 00:42:11,779 - INFO [QuorumPeer:/0:0:0:0:0:0:0:0:2181:FinalRequestProcessor@378] - shutdown of request processor complete
2011-01-19 00:42:11,779 - INFO [CommitProcessor:1:CommitProcessor@148] - CommitProcessor exited loop!
2011-01-19 00:42:11,780 - INFO [SyncThread:1:SyncRequestProcessor@151] - SyncRequestProcessor exited!
2011-01-19 00:42:11,780 - INFO [QuorumPeer:/0:0:0:0:0:0:0:0:2181:QuorumPeer@620] - LOOKING
2011-01-19 00:42:11,779 - INFO [FollowerRequestProcessor:1:FollowerRequestProcessor@93] - FollowerRequestProcessor exited loop!
2011-01-19 00:42:11,785 - INFO [QuorumPeer:/0:0:0:0:0:0:0:0:2181:FileSnap@82] - Reading snapshot /var/zookeeper/version-2/snapshot.800000000
2011-01-19 00:42:11,790 - INFO [QuorumPeer:/0:0:0:0:0:0:0:0:2181:FastLeaderElection@663] - New election. My id = 1, Proposed zxid = 34359738371
2011-01-19 00:42:11,791 - INFO [WorkerReceiver Thread:FastLeaderElection@496] - Notification: 1 (n.leader), 34359738371 (n.zxid), 13 (n.round), LOOKING (n.state), 1 (n.sid), LOOKING (my state)
2011-01-19 00:42:11,792 - WARN [Thread-8:QuorumCnxManager$SendWorker@617] - Exception when using channel: for id 2 my id = 1 error = java.nio.channels.ClosedChannelException
2011-01-19 00:42:11,792 - WARN [Thread-8:QuorumCnxManager$SendWorker@621] - Send worker leaving thread
2011-01-19 00:42:11,798 - INFO [WorkerReceiver Thread:FastLeaderElection@496] - Notification: 3 (n.leader), 34359738371 (n.zxid), 13 (n.round), LOOKING (n.state), 3 (n.sid), LOOKING (my state)
2011-01-19 00:42:11,799 - INFO [QuorumPeer:/0:0:0:0:0:0:0:0:2181:FastLeaderElection@721] - Updating proposal
2011-01-19 00:42:11,799 - INFO [WorkerReceiver Thread:FastLeaderElection@496] - Notification: 3 (n.leader), 34359738371 (n.zxid), 13 (n.round), LOOKING (n.state), 1 (n.sid), LOOKING (my state)
2011-01-19 00:42:11,800 - WARN [WorkerSender Thread:QuorumCnxManager@379] - Cannot open channel to 2 at election address /192.168.2.94:3888
java.net.ConnectException: Connection refused
at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)
at sun.nio.ch.SocketChannelImpl.finishConnect(SocketChannelImpl.java:592)
at sun.nio.ch.SocketAdaptor.connect(SocketAdaptor.java:118)
at org.apache.zookeeper.server.quorum.QuorumCnxManager.connectOne(QuorumCnxManager.java:366)
at org.apache.zookeeper.server.quorum.QuorumCnxManager.toSend(QuorumCnxManager.java:335)
at org.apache.zookeeper.server.quorum.FastLeaderElection$Messenger$WorkerSender.process(FastLeaderElection.java:360)
at org.apache.zookeeper.server.quorum.FastLeaderElection$Messenger$WorkerSender.run(FastLeaderElection.java:333)
at java.lang.Thread.run(Thread.java:636)
2011-01-19 00:42:12,000 - INFO [QuorumPeer:/0:0:0:0:0:0:0:0:2181:QuorumPeer@642] - FOLLOWING
2011-01-19 00:42:12,000 - INFO [QuorumPeer:/0:0:0:0:0:0:0:0:2181:ZooKeeperServer@151] - Created server with tickTime 2000 minSessionTimeout 4000 maxSessionTimeout 40000 datadir /var/zookeeper/version-2 snapdir /var/zookeeper/version-2
2011-01-19 00:42:12,001 - WARN [QuorumPeer:/0:0:0:0:0:0:0:0:2181:Learner@220] - Unexpected exception, tries=0, connecting to /192.168.2.95:2888
java.net.ConnectException: Connection refused
at java.net.PlainSocketImpl.socketConnect(Native Method)
at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:310)
at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:176)
at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:163)
at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:384)
at java.net.Socket.connect(Socket.java:546)
at org.apache.zookeeper.server.quorum.Learner.connectToLeader(Learner.java:212)
at org.apache.zookeeper.server.quorum.Follower.followLeader(Follower.java:65)
at org.apache.zookeeper.server.quorum.QuorumPeer.run(QuorumPeer.java:644)
2011-01-19 00:42:13,008 - INFO [QuorumPeer:/0:0:0:0:0:0:0:0:2181:Learner@285] - Getting a snapshot from leader
2011-01-19 00:42:13,009 - INFO [QuorumPeer:/0:0:0:0:0:0:0:0:2181:Learner@315] - Setting leader epoch 9
2011-01-19 00:42:13,054 - INFO [QuorumPeer:/0:0:0:0:0:0:0:0:2181:FileTxnSnapLog@208] - Snapshotting: 900000000
2011-01-19 00:42:15,124 - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn$Factory@251] - Accepted socket connection from /192.168.2.91:53779
2011-01-19 00:42:15,125 - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@770] - Client attempting to renew session 0x22d9b7e38c40000 at /192.168.2.91:53779
2011-01-19 00:42:15,125 - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:Learner@95] - Revalidating client: 156952528448389120
2011-01-19 00:42:15,127 - INFO [QuorumPeer:/0:0:0:0:0:0:0:0:2181:NIOServerCnxn@1580] - Established session 0x22d9b7e38c40000 with negotiated timeout 10000 for client /192.168.2.91:53779
2011-01-19 00:42:15,132 - WARN [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@639] - Exception causing close of session 0x22d9b7e38c40000 due to java.io.IOException: Connection reset by peer
2011-01-19 00:42:15,133 - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@1435] - Closed socket connection for client /192.168.2.91:53779 which had sessionid 0x22d9b7e38c40000
2011-01-19 00:42:15,371 - INFO [WorkerReceiver Thread:FastLeaderElection@496] - Notification: 2 (n.leader), 34359738371 (n.zxid), 1 (n.round), LOOKING (n.state), 2 (n.sid), FOLLOWING (my state)
2011-01-19 00:42:15,371 - INFO [WorkerReceiver Thread:FastLeaderElection@496] - Notification: 3 (n.leader), 34359738371 (n.zxid), 13 (n.round), LOOKING (n.state), 2 (n.sid), FOLLOWING (my state)
2011-01-19 00:42:15,375 - INFO [WorkerReceiver Thread:FastLeaderElection@496] - Notification: 3 (n.leader), 34359738371 (n.zxid), 13 (n.round), FOLLOWING (n.state), 2 (n.sid), FOLLOWING (my state)
2011-01-19 00:42:15,381 - INFO [WorkerReceiver Thread:FastLeaderElection@496] - Notification: 3 (n.leader), 34359738371 (n.zxid), 13 (n.round), FOLLOWING (n.state), 2 (n.sid), FOLLOWING (my state)
2011-01-19 00:42:28,003 - WARN [QuorumPeer:/0:0:0:0:0:0:0:0:2181:Follower@116] - Got zxid 0x900000001 expected 0x1
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment