irb output for zookeeper issue 4

################################## irb1
>> require 'zookeeper'
=> true
>> 
?> ZK = Zookeeper.new('192.168.2.93:2181, 192.168.2.94:2181, 192.168.2.95:2181')=> #<Zookeeper:0x16f9ab8 @dispatcher=#<Thread:0x16f9810 sleep>, data#<CZookeeper:0x16f99a0, @current_req_id=1, @host="192.168.2.93:2181, 192.168.2.94:2181, 192.168.2.95:2181", @req_mutex=#<Mutex:0x16f9a18>, watcher_reqs{-1=>{:watcher=>#<Proc:0x00000000017179c8@/usr/local/lib/ruby/gems/1.8/gems/zookeeper-0.4.2/lib/zookeeper.rb:228>}}, completion_reqs{}
>> 
?> 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-02-02 11:31:18,038:1844(0x7fbac89186f0):ZOO_DEBUG@zoo_awexists@2587: Sending request xid=0x4d493276 for path [/test] to 192.168.2.93:2181
2011-02-02 11:31:18,039:1844(0x412de950):ZOO_DEBUG@zookeeper_process@2025: Calling COMPLETION_STAT for xid=0x4d493276 rc=0
=> {:stat=>#<ZookeeperStat::Stat:0x16c48e0 @dataLength=2, @mtime=1296642671703, @exists=true, @ephemeralOwner=0, @ctime=1295261474350, @pzxid=4294967298, @aversion=0, @version=165, @mzxid=47244640293, @numChildren=0, @cversion=0, @czxid=4294967298>, :req_id=>1, :rc=>0}
>> ZK.set(:path => '/test', :data => '60')
2011-02-02 11:31:18,839:1844(0x7fbac89186f0):ZOO_DEBUG@zoo_aset@2455: Sending request xid=0x4d493277 for path [/test] to 192.168.2.93:2181
2011-02-02 11:31:18,878:1844(0x412de950):ZOO_DEBUG@zookeeper_process@1916: Processing WATCHER_EVENT
2011-02-02 11:31:18,878:1844(0x412de950):ZOO_DEBUG@zookeeper_process@2025: Calling COMPLETION_STAT for xid=0x4d493277 rc=0
2011-02-02 11:31:18,878:1844(0x41adf950):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 = 0x27f6b18, value = /test
=> {:stat=>#<ZookeeperStat::Stat:0x16b5908 @dataLength=2, @mtime=1296642678839, @exists=true, @ephemeralOwner=0, @ctime=1295261474350, @pzxid=4294967298, @aversion=0, @version=166, @mzxid=47244640295, @numChildren=0, @cversion=0, @czxid=4294967298>, :req_id=>2, :rc=>0}
>> callback fired for /test
2011-02-02 11:31:18,918:1844(0x7fbac89186f0):ZOO_DEBUG@zoo_awget@2414: Sending request xid=0x4d493278 for path [/test] to 192.168.2.93:2181
2011-02-02 11:31:18,919:1844(0x412de950):ZOO_DEBUG@zookeeper_process@2001: Calling COMPLETION_DATA for xid=0x4d493278 rc=0
value changed to 60
2011-02-02 11:31:18,919:1844(0x7fbac89186f0):ZOO_DEBUG@zoo_awexists@2587: Sending request xid=0x4d493279 for path [/test] to 192.168.2.93:2181
2011-02-02 11:31:18,919:1844(0x412de950):ZOO_DEBUG@zookeeper_process@2025: Calling COMPLETION_STAT for xid=0x4d493279 rc=0
2011-02-02 11:31:22,260:1844(0x412de950):ZOO_DEBUG@zookeeper_process@1983: Got ping response in 0 ms
2011-02-02 11:31:24,580:1844(0x412de950):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-02-02 11:31:24,580:1844(0x412de950):ZOO_DEBUG@handle_error@1141: Calling a watcher for a ZOO_SESSION_EVENT and the state=CONNECTING_STATE
2011-02-02 11:31:24,580:1844(0x41adf950):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 = 0x27f6b18, value = 
ZOOKEEPER_C_STATE WATCHER type = -1, state = 1, path = 0x27f6b18, value = 
2011-02-02 11:31:24,580:1844(0x412de950):ZOO_INFO@check_events@1585: initiated connection to server [192.168.2.94:2181]
2011-02-02 11:31:24,595:1844(0x412de950):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-02-02 11:31:24,596:1844(0x412de950):ZOO_ERROR@handle_socket_error_msg@1579: Socket [192.168.2.95:2181] zk retcode=-4, errno=111(Connection refused): server refused to accept the client
callback fired for /test
2011-02-02 11:31:27,945:1844(0x412de950):ZOO_WARN@zookeeper_interest@1461: Exceeded deadline by 16ms
2011-02-02 11:31:27,946:1844(0x412de950):ZOO_INFO@check_events@1585: initiated connection to server [192.168.2.93:2181]
2011-02-02 11:31:27,948:1844(0x412de950):ZOO_INFO@check_events@1632: session establishment complete on server [192.168.2.93:2181], sessionId=0x12de5e855010000, negotiated timeout=10000
2011-02-02 11:31:27,948:1844(0x412de950):ZOO_DEBUG@send_set_watches@1312: Sending set watches request to 192.168.2.93:2181
2011-02-02 11:31:27,948:1844(0x412de950):ZOO_DEBUG@check_events@1638: Calling a watcher for a ZOO_SESSION_EVENT and the state=ZOO_CONNECTED_STATE
2011-02-02 11:31:27,948:1844(0x41adf950):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 = 0x27f6b18, value = 
ZOOKEEPER_C_STATE WATCHER type = -1, state = 3, path = 0x27f6b18, value = 
2011-02-02 11:31:27,949:1844(0x412de950):ZOO_DEBUG@zookeeper_process@1930: Processing SET_WATCHES
2011-02-02 11:31:31,295:1844(0x412de950):ZOO_WARN@zookeeper_interest@1461: Exceeded deadline by 13ms
2011-02-02 11:31:31,304:1844(0x412de950):ZOO_DEBUG@zookeeper_process@1983: Got ping response in 8 ms

?> ZK.set(:path => '/test', :data => '60')
2011-02-02 11:31:33,318:1844(0x7fbac89186f0):ZOO_DEBUG@zoo_aset@2455: Sending request xid=0x4d49327a for path [/test] to 192.168.2.93:2181
2011-02-02 11:31:33,367:1844(0x412de950):ZOO_DEBUG@zookeeper_process@1916: Processing WATCHER_EVENT
2011-02-02 11:31:33,367:1844(0x41adf950):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 = 0x27f6b18, value = /test
2011-02-02 11:31:33,367:1844(0x412de950):ZOO_DEBUG@zookeeper_process@2025: Calling COMPLETION_STAT for xid=0x4d49327a rc=0
=> {:stat=>#<ZookeeperStat::Stat:0x16a5710 @dataLength=2, @mtime=1296642693319, @exists=true, @ephemeralOwner=0, @ctime=1295261474350, @pzxid=4294967298, @aversion=0, @version=167, @mzxid=51539607553, @numChildren=0, @cversion=0, @czxid=4294967298>, :req_id=>5, :rc=>0}
>> 
?> ZK.set(:path => '/test', :data => '60')
2011-02-02 11:31:35,567:1844(0x7fbac89186f0):ZOO_DEBUG@zoo_aset@2455: Sending request xid=0x4d49327b for path [/test] to 192.168.2.93:2181
2011-02-02 11:31:35,608:1844(0x412de950):ZOO_DEBUG@zookeeper_process@2025: Calling COMPLETION_STAT for xid=0x4d49327b rc=0
=> {:stat=>#<ZookeeperStat::Stat:0x16961c0 @dataLength=2, @mtime=1296642695568, @exists=true, @ephemeralOwner=0, @ctime=1295261474350, @pzxid=4294967298, @aversion=0, @version=168, @mzxid=51539607554, @numChildren=0, @cversion=0, @czxid=4294967298>, :req_id=>6, :rc=>0}
>> 
?> ZK.set(:path => '/test', :data => '60')
2011-02-02 11:31:37,439:1844(0x7fbac89186f0):ZOO_DEBUG@zoo_aset@2455: Sending request xid=0x4d49327c for path [/test] to 192.168.2.93:2181
2011-02-02 11:31:37,476:1844(0x412de950):ZOO_DEBUG@zookeeper_process@2025: Calling COMPLETION_STAT for xid=0x4d49327c rc=0
=> {:stat=>#<ZookeeperStat::Stat:0x1686c70 @dataLength=2, @mtime=1296642697440, @exists=true, @ephemeralOwner=0, @ctime=1295261474350, @pzxid=4294967298, @aversion=0, @version=169, @mzxid=51539607555, @numChildren=0, @cversion=0, @czxid=4294967298>, :req_id=>7, :rc=>0}
>> 2011-02-02 11:31:40,781:1844(0x412de950):ZOO_DEBUG@zookeeper_process@1983: Got ping response in 2 ms
2011-02-02 11:31:44,120:1844(0x412de950):ZOO_DEBUG@zookeeper_process@1983: Got ping response in 0 ms

?> exit
2011-02-02 11:31:46,425:1844(0x412de950):ZOO_DEBUG@do_io@317: IO thread terminated
2011-02-02 11:31:46,426:1844(0x41adf950):ZOO_DEBUG@do_completion@336: completion thread terminated
2011-02-02 11:31:46,426:1844(0x7fbac89186f0):ZOO_INFO@zookeeper_close@2304: Closing zookeeper sessionId=0x12de5e855010000 to [192.168.2.93:2181]

##################### irb2
>> require 'zookeeper'
=> true
>>                                                                             )
=> #<Zookeeper:0x16dfc80 @dispatcher=#<Thread:0x16df9d8 sleep>, data#<CZookeeper:0x16dfb68, @current_req_id=1, @host="192.168.2.93:2181, 192.168.2.94:2181, 192.168.2.95:2181", @req_mutex=#<Mutex:0x16dfbe0>, watcher_reqs{-1=>{:watcher=>#<Proc:0x00000000016fdb90@/usr/local/lib/ruby/gems/1.8/gems/zookeeper-0.4.2/lib/zookeeper.rb:228>}}, completion_reqs{}
>> 
?> 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-02-02 11:31:10,244:6333(0x7f40266ed6f0):ZOO_DEBUG@zoo_awexists@2587: Sending request xid=0x4d49326f for path [/test] to 192.168.2.95:2181
2011-02-02 11:31:10,247:6333(0x41a62950):ZOO_DEBUG@zookeeper_process@2025: Calling COMPLETION_STAT for xid=0x4d49326f rc=0
=> {:stat=>#<ZookeeperStat::Stat:0x16aaaa8 @dataLength=2, @mtime=1296642657952, @exists=true, @ephemeralOwner=0, @ctime=1295261474350, @pzxid=4294967298, @aversion=0, @version=164, @mzxid=47244640290, @numChildren=0, @cversion=0, @czxid=4294967298>, :req_id=>1, :rc=>0}
>> ZK.set(:path => '/test', :data => '60')
2011-02-02 11:31:11,702:6333(0x7f40266ed6f0):ZOO_DEBUG@zoo_aset@2455: Sending request xid=0x4d493270 for path [/test] to 192.168.2.95:2181
2011-02-02 11:31:11,756:6333(0x41a62950):ZOO_DEBUG@zookeeper_process@1916: Processing WATCHER_EVENT
2011-02-02 11:31:11,756:6333(0x41a62950):ZOO_DEBUG@zookeeper_process@2025: Calling COMPLETION_STAT for xid=0x4d493270 rc=0
2011-02-02 11:31:11,756:6333(0x42263950):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 = 0x2840318, value = /test
=> {:stat=>#<ZookeeperStat::Stat:0x169bad0 @dataLength=2, @mtime=1296642671703, @exists=true, @ephemeralOwner=0, @ctime=1295261474350, @pzxid=4294967298, @aversion=0, @version=165, @mzxid=47244640293, @numChildren=0, @cversion=0, @czxid=4294967298>, :req_id=>2, :rc=>0}
>> callback fired for /test
2011-02-02 11:31:11,771:6333(0x7f40266ed6f0):ZOO_DEBUG@zoo_awget@2414: Sending request xid=0x4d493271 for path [/test] to 192.168.2.95:2181
2011-02-02 11:31:11,774:6333(0x41a62950):ZOO_DEBUG@zookeeper_process@2001: Calling COMPLETION_DATA for xid=0x4d493271 rc=0
value changed to 60
2011-02-02 11:31:11,775:6333(0x7f40266ed6f0):ZOO_DEBUG@zoo_awexists@2587: Sending request xid=0x4d493272 for path [/test] to 192.168.2.95:2181
2011-02-02 11:31:11,780:6333(0x41a62950):ZOO_DEBUG@zookeeper_process@2025: Calling COMPLETION_STAT for xid=0x4d493272 rc=0
2011-02-02 11:31:15,111:6333(0x41a62950):ZOO_DEBUG@zookeeper_process@1983: Got ping response in 0 ms
2011-02-02 11:31:18,451:6333(0x41a62950):ZOO_DEBUG@zookeeper_process@1983: Got ping response in 0 ms
2011-02-02 11:31:18,877:6333(0x41a62950):ZOO_DEBUG@zookeeper_process@1916: Processing WATCHER_EVENT
2011-02-02 11:31:18,877:6333(0x42263950):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 = 0x2840318, value = /test
callback fired for /test
2011-02-02 11:31:18,915:6333(0x7f40266ed6f0):ZOO_DEBUG@zoo_awget@2414: Sending request xid=0x4d493273 for path [/test] to 192.168.2.95:2181
2011-02-02 11:31:18,916:6333(0x41a62950):ZOO_DEBUG@zookeeper_process@2001: Calling COMPLETION_DATA for xid=0x4d493273 rc=0
value changed to 60
2011-02-02 11:31:18,916:6333(0x7f40266ed6f0):ZOO_DEBUG@zoo_awexists@2587: Sending request xid=0x4d493274 for path [/test] to 192.168.2.95:2181
2011-02-02 11:31:18,919:6333(0x41a62950):ZOO_DEBUG@zookeeper_process@2025: Calling COMPLETION_STAT for xid=0x4d493274 rc=0
2011-02-02 11:31:22,253:6333(0x41a62950):ZOO_DEBUG@zookeeper_process@1983: Got ping response in 0 ms
2011-02-02 11:31:24,574:6333(0x41a62950):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
2011-02-02 11:31:24,574:6333(0x41a62950):ZOO_DEBUG@handle_error@1141: Calling a watcher for a ZOO_SESSION_EVENT and the state=CONNECTING_STATE
2011-02-02 11:31:24,574:6333(0x41a62950):ZOO_INFO@check_events@1585: initiated connection to server [192.168.2.93:2181]
2011-02-02 11:31:24,574:6333(0x42263950):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 = 0x2840318, value = 
ZOOKEEPER_C_STATE WATCHER type = -1, state = 1, path = 0x2840318, value = 
2011-02-02 11:31:24,577:6333(0x41a62950):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-02-02 11:31:24,577:6333(0x41a62950):ZOO_INFO@check_events@1585: initiated connection to server [192.168.2.94:2181]
2011-02-02 11:31:24,581:6333(0x41a62950):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
callback fired for /test
2011-02-02 11:31:27,915:6333(0x41a62950):ZOO_ERROR@handle_socket_error_msg@1579: Socket [192.168.2.95:2181] zk retcode=-4, errno=111(Connection refused): server refused to accept the client
2011-02-02 11:31:27,915:6333(0x41a62950):ZOO_INFO@check_events@1585: initiated connection to server [192.168.2.93:2181]
2011-02-02 11:31:27,918:6333(0x41a62950):ZOO_INFO@check_events@1632: session establishment complete on server [192.168.2.93:2181], sessionId=0x32de5e855360000, negotiated timeout=10000
2011-02-02 11:31:27,919:6333(0x41a62950):ZOO_DEBUG@send_set_watches@1312: Sending set watches request to 192.168.2.93:2181
2011-02-02 11:31:27,919:6333(0x41a62950):ZOO_DEBUG@check_events@1638: Calling a watcher for a ZOO_SESSION_EVENT and the state=ZOO_CONNECTED_STATE
2011-02-02 11:31:27,919:6333(0x42263950):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 = 0x2840318, value = 
ZOOKEEPER_C_STATE WATCHER type = -1, state = 3, path = 0x2840318, value = 
2011-02-02 11:31:27,920:6333(0x41a62950):ZOO_DEBUG@zookeeper_process@1930: Processing SET_WATCHES
2011-02-02 11:31:31,252:6333(0x41a62950):ZOO_DEBUG@zookeeper_process@1983: Got ping response in 0 ms
2011-02-02 11:31:33,365:6333(0x41a62950):ZOO_DEBUG@zookeeper_process@1916: Processing WATCHER_EVENT
2011-02-02 11:31:33,365:6333(0x42263950):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 = 0x2840318, value = /test
2011-02-02 11:31:34,585:6333(0x41a62950):ZOO_DEBUG@zookeeper_process@1983: Got ping response in 0 ms
2011-02-02 11:31:37,921:6333(0x41a62950):ZOO_DEBUG@zookeeper_process@1983: Got ping response in 0 ms
^C
>> 2011-02-02 11:31:41,257:6333(0x41a62950):ZOO_DEBUG@zookeeper_process@1983: Got ping response in 0 ms
exit
2011-02-02 11:31:43,088:6333(0x41a62950):ZOO_DEBUG@do_io@317: IO thread terminated
2011-02-02 11:31:43,088:6333(0x42263950):ZOO_DEBUG@do_completion@336: completion thread terminated
2011-02-02 11:31:43,088:6333(0x7f40266ed6f0):ZOO_INFO@zookeeper_close@2304: Closing zookeeper sessionId=0x32de5e855360000 to [192.168.2.93:2181]