Exploring https://github.com/slyphon/zk/issues/68

01_zk_watcher_test.rb

# from https://github.com/slyphon/zk/issues/68

require 'zk'

ZK_PATH = '/test/path/child'
CHILD_PATH = ZK_PATH + '/foo'
SLEEP_TIME = 1

class Writer
  def initialize(start_signal, finish_signal)
    @start_signal, @finish_signal = start_signal, finish_signal
  end

  def call
    @zk = ZK.new('localhost:2181')
    @zk.rm_rf(File.dirname(ZK_PATH))
    @zk.mkdir_p(File.dirname(ZK_PATH))
    
    @start_signal.wait
    
    (1..2).each do |attempt|
      puts "-- #{attempt} --"
      create
      add_child
      delete_child
      delete
    end

    @finish_signal.signal
    
    @zk.close
  end

  def create
    puts 'CREATE'
    @zk.create(ZK_PATH, rand.to_s)
    sleep(SLEEP_TIME)
  end

  def delete
    puts 'DELETE'
    @zk.delete(ZK_PATH)
    sleep(SLEEP_TIME)
  end

  def add_child
    puts 'ADD_CHILD'
    @zk.create(CHILD_PATH, rand.to_s)
    sleep(SLEEP_TIME)
  end

  def delete_child
    puts 'DELETE_CHILD'
    @zk.delete(CHILD_PATH)
    sleep(SLEEP_TIME)
  end
end


class Reader
  def initialize(start_signal, finish_signal)
    @start_signal, @finish_signal = start_signal, finish_signal
  end

  def call
    if ENV['DEBUG']
      ZK.logger        = logger('reader', 'zk')
      Zookeeper.logger = logger('reader', 'zookeeper')
    end
    
    @zkw = ZK.new('localhost:2181')
    watch = @zkw.register(ZK_PATH) do |event|
      puts "  #{event.event_name}: #{event.path}" 
  
      puts '    STAT'
      stat = @zkw.stat(ZK_PATH, :watch => true)

      if stat.exists?
        puts '    CHILDREN'
        @zkw.children(ZK_PATH, :watch => true)
      end
    end
    @zkw.stat(ZK_PATH, :watch => true)
    
    @zkw.on_connected do
      puts 'CONNECTED'
    end
    
    @start_signal.signal
    
    @finish_signal.wait
    
    puts 'DONE'
    
    @zkw.close
  end
  
  def logger(*prefixes)
    l = Logger.new(STDOUT)
    unless prefixes.empty?
      prefixes = prefixes.join(': ') + ': '
    end
    l.formatter = proc do |a, b, c, msg|
      msg = prefixes.to_s + msg + "\n"
    end
    l
  end
end

class Signaler
  def initialize
    @r, @w = IO.pipe
  end
  
  def wait
    @r.read(1)
  end
  
  def signal
    @w.write('x')
  end
end

start_signal, finish_signal = Signaler.new, Signaler.new

reader = Reader.new(start_signal, finish_signal)
writer = Writer.new(start_signal, finish_signal)

reader_pid = fork do
  reader.call
end

writer_pid = fork do
  writer.call
end

Process.waitpid(reader_pid)
Process.waitpid(writer_pid)

02_output.txt

-- 1 --
CREATE
  ZOO_CREATED_EVENT: /test/path/child
    STAT
    CHILDREN
ADD_CHILD
  ZOO_CHILD_EVENT: /test/path/child
    STAT
    CHILDREN
DELETE_CHILD
  ZOO_CHILD_EVENT: /test/path/child
    STAT
    CHILDREN
DELETE
  ZOO_DELETED_EVENT: /test/path/child
    STAT
  ZOO_DELETED_EVENT: /test/path/child
    STAT
-- 2 --
CREATE
  ZOO_CREATED_EVENT: /test/path/child
    STAT
    CHILDREN
  ZOO_CREATED_EVENT: /test/path/child
    STAT
    CHILDREN
ADD_CHILD
DELETE_CHILD
DELETE
  ZOO_DELETED_EVENT: /test/path/child
    STAT
  ZOO_DELETED_EVENT: /test/path/child
    STAT

03_debug_output.txt

I, [2013-05-31T23:44:52.794885 #81644]  INFO -- : initiating connection to localhost:2181
D, [2013-05-31T23:44:52.797014 #81644] DEBUG -- : #zkc_set_running_and_notify!
D, [2013-05-31T23:44:52.797434 #81644] DEBUG -- : #event_thread_body starting event thread
D, [2013-05-31T23:44:52.797670 #81644] DEBUG -- : init returned!
D, [2013-05-31T23:44:52.797821 #81644] DEBUG -- : event_thread waiting until running: true
D, [2013-05-31T23:44:52.797975 #81644] DEBUG -- : event_thread running: true
D, [2013-05-31T23:44:52.799044 #81644] DEBUG -- : #iterate_event_delivery got {:type=>-1, :path=>"", :state=>3, :req_id=>-1} 
D, [2013-05-31T23:44:52.799470 #81644] DEBUG -- : starting dispatch thread
D, [2013-05-31T23:44:52.799680 #81644] DEBUG -- : Zookeeper::Client#get_next_event delivering event {:type=>-1, :path=>"", :state=>3, :req_id=>-1}
D, [2013-05-31T23:44:52.799930 #81644] DEBUG -- : get_next_event returned: {:type=>"session", :path=>"", :state=>"connected", :req_id=>:global_session}
D, [2013-05-31T23:44:52.800710 #81644] DEBUG -- : EventHandler#process dispatching event: #<Zookeeper::Callbacks::WatcherCallback:0x106946e50 @type=-1, @completed=false, @state=3, @context=nil, @proc=#<Proc:0x0000000106291dd0@/Users/eric/src/zk/vendor/bundle/gems/zookeeper-1.4.4/lib/zookeeper/callbacks.rb:24>, @path="">
D, [2013-05-31T23:44:52.800855 #81644] DEBUG -- : wait_until_connected_or_dying @last_cnx_state: 3, time_left? true, @client_state: :running
D, [2013-05-31T23:44:52.801723 #81644] DEBUG -- : async_args, meth: exists ary: [0, "/test/path/child", nil, #<Zookeeper::Callbacks::WatcherCallback:0x106945460 @completed=false, @proc=#<Proc:0x0000000106291dd0@/Users/eric/src/zk/vendor/bundle/gems/zookeeper-1.4.4/lib/zookeeper/callbacks.rb:24>>], 2
D, [2013-05-31T23:44:52.802241 #81644] DEBUG -- : #iterate_event_delivery got {:stat=>nil, :rc=>-101, :req_id=>0} 
D, [2013-05-31T23:44:52.802363 #81644] DEBUG -- : continuation req_id 0, got hash: {:stat=>nil, :rc=>-101, :req_id=>0}
D, [2013-05-31T23:44:52.802444 #81644] DEBUG -- : delivering result [-101, nil]
-- 1 --
CREATE
D, [2013-05-31T23:44:52.806400 #81644] DEBUG -- : #iterate_event_delivery got {:type=>1, :path=>"/test/path/child", :state=>3, :req_id=>0} 
D, [2013-05-31T23:44:52.806614 #81644] DEBUG -- : Zookeeper::Client#get_next_event delivering event {:type=>1, :path=>"/test/path/child", :state=>3, :req_id=>0}
D, [2013-05-31T23:44:52.806777 #81644] DEBUG -- : get_next_event returned: {:type=>"created", :path=>"/test/path/child", :state=>"connected", :req_id=>0}
D, [2013-05-31T23:44:52.806908 #81644] DEBUG -- : EventHandler#process dispatching event: #<Zookeeper::Callbacks::WatcherCallback:0x106945460 @type=1, @completed=false, @state=3, @context=nil, @proc=#<Proc:0x0000000106291dd0@/Users/eric/src/zk/vendor/bundle/gems/zookeeper-1.4.4/lib/zookeeper/callbacks.rb:24>, @path="/test/path/child">
D, [2013-05-31T23:44:52.807728 #81644] DEBUG -- : called #<ZK::EventHandlerSubscription::Base:0x106945898 @interests=#<Set: {:changed, :created, :child, :deleted}>, @callable=#<Proc:0x000000010647c7d0@test.rb:69>, @mutex=#<ZK::Monitor:0x106945820 @mon_entering_queue=[], @mon_count=0, @mon_owner=nil, @mon_waiting_queue=[]>, @path="/test/path/child", @parent=#<ZK::EventHandler:0x10694bae0 @default_watcher_block=#<Proc:0x0000000106a77e78@/Users/eric/src/zk/lib/zk/event_handler.rb:251>, @thread_opt=:single, @orig_pid=81644, @state=:running, @outstanding_watches={:child=>#<Set: {}>, :data=>#<Set: {}>}, @mutex=#<ZK::Monitor:0x10694b478 @mon_entering_queue=[], @mon_count=0, @mon_owner=nil, @mon_waiting_queue=[]>, @callbacks={:all_node_events=>[], :all_state_events=>[], "/test/path/child"=>[#<ZK::EventHandlerSubscription::Base:0x106945898 ...>], "state_3"=>[#<ZK::EventHandlerSubscription::Base:0x1069433e0 @interests=#<Set: {:changed, :created, :child, :deleted}>, @callable=#<Proc:0x000000010647bdd0@test.rb:82>, @mutex=#<ZK::Monitor:0x106943368 @mon_entering_queue=[], @mon_count=0, @mon_owner=nil, @mon_waiting_queue=[]>, @path="state_3", @parent=#<ZK::EventHandler:0x10694bae0 ...>>]}, @zk=#<ZK::Client::Threaded:2202689880 zk_session_id=0x13d906e10860421 ...>>> with [#<Zookeeper::Callbacks::WatcherCallback:0x106945460 @type=1, @completed=true, @state=3, @context=nil, @proc=#<Proc:0x0000000106291dd0@/Users/eric/src/zk/vendor/bundle/gems/zookeeper-1.4.4/lib/zookeeper/callbacks.rb:24>, @zk=#<ZK::Client::Threaded:2202689880 zk_session_id=0x13d906e10860421 ...>, @path="/test/path/child">] on threadpool
  ZOO_CREATED_EVENT: /test/path/child
D, [2013-05-31T23:44:52.808441 #81644] DEBUG -- : async_args, meth: exists ary: [1, "/test/path/child", nil, #<Zookeeper::Callbacks::WatcherCallback:0x1069404b0 @completed=false, @proc=#<Proc:0x0000000106291dd0@/Users/eric/src/zk/vendor/bundle/gems/zookeeper-1.4.4/lib/zookeeper/callbacks.rb:24>>], 2
D, [2013-05-31T23:44:52.808958 #81644] DEBUG -- : #iterate_event_delivery got {:stat=>[106502, 106502, 1370069092805, 1370069092805, 0, 0, 0, 0, 17, 0, 106502], :rc=>0, :req_id=>1} 
D, [2013-05-31T23:44:52.809095 #81644] DEBUG -- : continuation req_id 1, got hash: {:stat=>[106502, 106502, 1370069092805, 1370069092805, 0, 0, 0, 0, 17, 0, 106502], :rc=>0, :req_id=>1}
D, [2013-05-31T23:44:52.809184 #81644] DEBUG -- : delivering result [0, [106502, 106502, 1370069092805, 1370069092805, 0, 0, 0, 0, 17, 0, 106502]]
    STAT
D, [2013-05-31T23:44:52.810175 #81644] DEBUG -- : async_args, meth: get_children ary: [2, "/test/path/child", nil, #<Zookeeper::Callbacks::WatcherCallback:0x10693e188 @completed=false, @proc=#<Proc:0x0000000106291dd0@/Users/eric/src/zk/vendor/bundle/gems/zookeeper-1.4.4/lib/zookeeper/callbacks.rb:24>>], 2
D, [2013-05-31T23:44:52.810751 #81644] DEBUG -- : #iterate_event_delivery got {:strings=>[], :stat=>[106502, 106502, 1370069092805, 1370069092805, 0, 0, 0, 0, 17, 0, 106502], :rc=>0, :req_id=>2} 
D, [2013-05-31T23:44:52.810885 #81644] DEBUG -- : continuation req_id 2, got hash: {:strings=>[], :stat=>[106502, 106502, 1370069092805, 1370069092805, 0, 0, 0, 0, 17, 0, 106502], :rc=>0, :req_id=>2}
D, [2013-05-31T23:44:52.811008 #81644] DEBUG -- : delivering result [0, [], [106502, 106502, 1370069092805, 1370069092805, 0, 0, 0, 0, 17, 0, 106502]]
    CHILDREN
ADD_CHILD
D, [2013-05-31T23:44:53.809015 #81644] DEBUG -- : #iterate_event_delivery got {:type=>4, :path=>"/test/path/child", :state=>3, :req_id=>2} 
D, [2013-05-31T23:44:53.809345 #81644] DEBUG -- : Zookeeper::Client#get_next_event delivering event {:type=>4, :path=>"/test/path/child", :state=>3, :req_id=>2}
D, [2013-05-31T23:44:53.809587 #81644] DEBUG -- : get_next_event returned: {:type=>"child", :path=>"/test/path/child", :state=>"connected", :req_id=>2}
D, [2013-05-31T23:44:53.809836 #81644] DEBUG -- : EventHandler#process dispatching event: #<Zookeeper::Callbacks::WatcherCallback:0x10693e188 @type=4, @completed=false, @state=3, @context=nil, @proc=#<Proc:0x0000000106291dd0@/Users/eric/src/zk/vendor/bundle/gems/zookeeper-1.4.4/lib/zookeeper/callbacks.rb:24>, @path="/test/path/child">
D, [2013-05-31T23:44:53.810566 #81644] DEBUG -- : called #<ZK::EventHandlerSubscription::Base:0x106945898 @interests=#<Set: {:changed, :created, :child, :deleted}>, @callable=#<Proc:0x000000010647c7d0@test.rb:69>, @mutex=#<ZK::Monitor:0x106945820 @mon_entering_queue=[], @mon_count=0, @mon_owner=nil, @mon_waiting_queue=[]>, @path="/test/path/child", @parent=#<ZK::EventHandler:0x10694bae0 @default_watcher_block=#<Proc:0x0000000106a77e78@/Users/eric/src/zk/lib/zk/event_handler.rb:251>, @thread_opt=:single, @orig_pid=81644, @state=:running, @outstanding_watches={:child=>#<Set: {}>, :data=>#<Set: {"/test/path/child"}>}, @mutex=#<ZK::Monitor:0x10694b478 @mon_entering_queue=[], @mon_count=0, @mon_owner=nil, @mon_waiting_queue=[]>, @callbacks={:all_node_events=>[], :all_state_events=>[], "/test/path/child"=>[#<ZK::EventHandlerSubscription::Base:0x106945898 ...>], "state_3"=>[#<ZK::EventHandlerSubscription::Base:0x1069433e0 @interests=#<Set: {:changed, :created, :child, :deleted}>, @callable=#<Proc:0x000000010647bdd0@test.rb:82>, @mutex=#<ZK::Monitor:0x106943368 @mon_entering_queue=[], @mon_count=0, @mon_owner=nil, @mon_waiting_queue=[]>, @path="state_3", @parent=#<ZK::EventHandler:0x10694bae0 ...>>]}, @zk=#<ZK::Client::Threaded:2202689880 zk_session_id=0x13d906e10860421 ...>>> with [#<Zookeeper::Callbacks::WatcherCallback:0x10693e188 @type=4, @completed=true, @state=3, @context=nil, @proc=#<Proc:0x0000000106291dd0@/Users/eric/src/zk/vendor/bundle/gems/zookeeper-1.4.4/lib/zookeeper/callbacks.rb:24>, @zk=#<ZK::Client::Threaded:2202689880 zk_session_id=0x13d906e10860421 ...>, @path="/test/path/child">] on threadpool
  ZOO_CHILD_EVENT: /test/path/child
D, [2013-05-31T23:44:53.811382 #81644] DEBUG -- : async_args, meth: exists ary: [3, "/test/path/child", nil, nil], 2
D, [2013-05-31T23:44:53.811899 #81644] DEBUG -- : #iterate_event_delivery got {:stat=>[106502, 106502, 1370069092805, 1370069092805, 0, 1, 0, 0, 17, 1, 106503], :rc=>0, :req_id=>3} 
D, [2013-05-31T23:44:53.812056 #81644] DEBUG -- : continuation req_id 3, got hash: {:stat=>[106502, 106502, 1370069092805, 1370069092805, 0, 1, 0, 0, 17, 1, 106503], :rc=>0, :req_id=>3}
D, [2013-05-31T23:44:53.812192 #81644] DEBUG -- : delivering result [0, [106502, 106502, 1370069092805, 1370069092805, 0, 1, 0, 0, 17, 1, 106503]]
    STAT
D, [2013-05-31T23:44:53.813253 #81644] DEBUG -- : async_args, meth: get_children ary: [4, "/test/path/child", nil, #<Zookeeper::Callbacks::WatcherCallback:0x106936e10 @completed=false, @proc=#<Proc:0x0000000106291dd0@/Users/eric/src/zk/vendor/bundle/gems/zookeeper-1.4.4/lib/zookeeper/callbacks.rb:24>>], 2
D, [2013-05-31T23:44:53.813739 #81644] DEBUG -- : #iterate_event_delivery got {:strings=>["foo"], :stat=>[106502, 106502, 1370069092805, 1370069092805, 0, 1, 0, 0, 17, 1, 106503], :rc=>0, :req_id=>4} 
D, [2013-05-31T23:44:53.813863 #81644] DEBUG -- : continuation req_id 4, got hash: {:strings=>["foo"], :stat=>[106502, 106502, 1370069092805, 1370069092805, 0, 1, 0, 0, 17, 1, 106503], :rc=>0, :req_id=>4}
D, [2013-05-31T23:44:53.814006 #81644] DEBUG -- : delivering result [0, ["foo"], [106502, 106502, 1370069092805, 1370069092805, 0, 1, 0, 0, 17, 1, 106503]]
    CHILDREN
DELETE_CHILD
D, [2013-05-31T23:44:54.811820 #81644] DEBUG -- : #iterate_event_delivery got {:type=>4, :path=>"/test/path/child", :state=>3, :req_id=>4} 
D, [2013-05-31T23:44:54.812232 #81644] DEBUG -- : Zookeeper::Client#get_next_event delivering event {:type=>4, :path=>"/test/path/child", :state=>3, :req_id=>4}
D, [2013-05-31T23:44:54.812520 #81644] DEBUG -- : get_next_event returned: {:type=>"child", :path=>"/test/path/child", :state=>"connected", :req_id=>4}
D, [2013-05-31T23:44:54.812766 #81644] DEBUG -- : EventHandler#process dispatching event: #<Zookeeper::Callbacks::WatcherCallback:0x106936e10 @type=4, @completed=false, @state=3, @context=nil, @proc=#<Proc:0x0000000106291dd0@/Users/eric/src/zk/vendor/bundle/gems/zookeeper-1.4.4/lib/zookeeper/callbacks.rb:24>, @path="/test/path/child">
D, [2013-05-31T23:44:54.813777 #81644] DEBUG -- : called #<ZK::EventHandlerSubscription::Base:0x106945898 @interests=#<Set: {:changed, :created, :child, :deleted}>, @callable=#<Proc:0x000000010647c7d0@test.rb:69>, @mutex=#<ZK::Monitor:0x106945820 @mon_entering_queue=[], @mon_count=0, @mon_owner=nil, @mon_waiting_queue=[]>, @path="/test/path/child", @parent=#<ZK::EventHandler:0x10694bae0 @default_watcher_block=#<Proc:0x0000000106a77e78@/Users/eric/src/zk/lib/zk/event_handler.rb:251>, @thread_opt=:single, @orig_pid=81644, @state=:running, @outstanding_watches={:child=>#<Set: {}>, :data=>#<Set: {"/test/path/child"}>}, @mutex=#<ZK::Monitor:0x10694b478 @mon_entering_queue=[], @mon_count=0, @mon_owner=nil, @mon_waiting_queue=[]>, @callbacks={:all_node_events=>[], :all_state_events=>[], "/test/path/child"=>[#<ZK::EventHandlerSubscription::Base:0x106945898 ...>], "state_3"=>[#<ZK::EventHandlerSubscription::Base:0x1069433e0 @interests=#<Set: {:changed, :created, :child, :deleted}>, @callable=#<Proc:0x000000010647bdd0@test.rb:82>, @mutex=#<ZK::Monitor:0x106943368 @mon_entering_queue=[], @mon_count=0, @mon_owner=nil, @mon_waiting_queue=[]>, @path="state_3", @parent=#<ZK::EventHandler:0x10694bae0 ...>>]}, @zk=#<ZK::Client::Threaded:2202689880 zk_session_id=0x13d906e10860421 ...>>> with [#<Zookeeper::Callbacks::WatcherCallback:0x106936e10 @type=4, @completed=true, @state=3, @context=nil, @proc=#<Proc:0x0000000106291dd0@/Users/eric/src/zk/vendor/bundle/gems/zookeeper-1.4.4/lib/zookeeper/callbacks.rb:24>, @zk=#<ZK::Client::Threaded:2202689880 zk_session_id=0x13d906e10860421 ...>, @path="/test/path/child">] on threadpool
  ZOO_CHILD_EVENT: /test/path/child
D, [2013-05-31T23:44:54.815068 #81644] DEBUG -- : async_args, meth: exists ary: [5, "/test/path/child", nil, nil], 2
D, [2013-05-31T23:44:54.815939 #81644] DEBUG -- : #iterate_event_delivery got {:stat=>[106502, 106502, 1370069092805, 1370069092805, 0, 2, 0, 0, 17, 0, 106504], :rc=>0, :req_id=>5} 
D, [2013-05-31T23:44:54.816139 #81644] DEBUG -- : continuation req_id 5, got hash: {:stat=>[106502, 106502, 1370069092805, 1370069092805, 0, 2, 0, 0, 17, 0, 106504], :rc=>0, :req_id=>5}
D, [2013-05-31T23:44:54.816289 #81644] DEBUG -- : delivering result [0, [106502, 106502, 1370069092805, 1370069092805, 0, 2, 0, 0, 17, 0, 106504]]
    STAT
D, [2013-05-31T23:44:54.817512 #81644] DEBUG -- : async_args, meth: get_children ary: [6, "/test/path/child", nil, #<Zookeeper::Callbacks::WatcherCallback:0x10692fa70 @completed=false, @proc=#<Proc:0x0000000106291dd0@/Users/eric/src/zk/vendor/bundle/gems/zookeeper-1.4.4/lib/zookeeper/callbacks.rb:24>>], 2
D, [2013-05-31T23:44:54.818241 #81644] DEBUG -- : #iterate_event_delivery got {:strings=>[], :stat=>[106502, 106502, 1370069092805, 1370069092805, 0, 2, 0, 0, 17, 0, 106504], :rc=>0, :req_id=>6} 
D, [2013-05-31T23:44:54.818434 #81644] DEBUG -- : continuation req_id 6, got hash: {:strings=>[], :stat=>[106502, 106502, 1370069092805, 1370069092805, 0, 2, 0, 0, 17, 0, 106504], :rc=>0, :req_id=>6}
D, [2013-05-31T23:44:54.818591 #81644] DEBUG -- : delivering result [0, [], [106502, 106502, 1370069092805, 1370069092805, 0, 2, 0, 0, 17, 0, 106504]]
    CHILDREN
DELETE
D, [2013-05-31T23:44:55.815481 #81644] DEBUG -- : #iterate_event_delivery got {:type=>2, :path=>"/test/path/child", :state=>3, :req_id=>6} 
D, [2013-05-31T23:44:55.815831 #81644] DEBUG -- : Zookeeper::Client#get_next_event delivering event {:type=>2, :path=>"/test/path/child", :state=>3, :req_id=>6}
D, [2013-05-31T23:44:55.816030 #81644] DEBUG -- : #iterate_event_delivery got {:type=>2, :path=>"/test/path/child", :state=>3, :req_id=>1} 
D, [2013-05-31T23:44:55.816214 #81644] DEBUG -- : get_next_event returned: {:type=>"deleted", :path=>"/test/path/child", :state=>"connected", :req_id=>6}
D, [2013-05-31T23:44:55.816515 #81644] DEBUG -- : EventHandler#process dispatching event: #<Zookeeper::Callbacks::WatcherCallback:0x10692fa70 @type=2, @completed=false, @state=3, @context=nil, @proc=#<Proc:0x0000000106291dd0@/Users/eric/src/zk/vendor/bundle/gems/zookeeper-1.4.4/lib/zookeeper/callbacks.rb:24>, @path="/test/path/child">
D, [2013-05-31T23:44:55.818670 #81644] DEBUG -- : Zookeeper::Client#get_next_event delivering event {:type=>2, :path=>"/test/path/child", :state=>3, :req_id=>1}
D, [2013-05-31T23:44:55.818906 #81644] DEBUG -- : get_next_event returned: {:type=>"deleted", :path=>"/test/path/child", :state=>"connected", :req_id=>1}
D, [2013-05-31T23:44:55.819237 #81644] DEBUG -- : EventHandler#process dispatching event: #<Zookeeper::Callbacks::WatcherCallback:0x1069404b0 @type=2, @completed=false, @state=3, @context=nil, @proc=#<Proc:0x0000000106291dd0@/Users/eric/src/zk/vendor/bundle/gems/zookeeper-1.4.4/lib/zookeeper/callbacks.rb:24>, @path="/test/path/child">
D, [2013-05-31T23:44:55.819814 #81644] DEBUG -- : called #<ZK::EventHandlerSubscription::Base:0x106945898 @interests=#<Set: {:changed, :created, :child, :deleted}>, @callable=#<Proc:0x000000010647c7d0@test.rb:69>, @mutex=#<ZK::Monitor:0x106945820 @mon_entering_queue=[], @mon_count=0, @mon_owner=nil, @mon_waiting_queue=[]>, @path="/test/path/child", @parent=#<ZK::EventHandler:0x10694bae0 @default_watcher_block=#<Proc:0x0000000106a77e78@/Users/eric/src/zk/lib/zk/event_handler.rb:251>, @thread_opt=:single, @orig_pid=81644, @state=:running, @outstanding_watches={:child=>#<Set: {"/test/path/child"}>, :data=>#<Set: {}>}, @mutex=#<ZK::Monitor:0x10694b478 @mon_entering_queue=[], @mon_count=0, @mon_owner=nil, @mon_waiting_queue=[]>, @callbacks={:all_node_events=>[], :all_state_events=>[], "/test/path/child"=>[#<ZK::EventHandlerSubscription::Base:0x106945898 ...>], "state_3"=>[#<ZK::EventHandlerSubscription::Base:0x1069433e0 @interests=#<Set: {:changed, :created, :child, :deleted}>, @callable=#<Proc:0x000000010647bdd0@test.rb:82>, @mutex=#<ZK::Monitor:0x106943368 @mon_entering_queue=[], @mon_count=0, @mon_owner=nil, @mon_waiting_queue=[]>, @path="state_3", @parent=#<ZK::EventHandler:0x10694bae0 ...>>]}, @zk=#<ZK::Client::Threaded:2202689880 zk_session_id=0x13d906e10860421 ...>>> with [#<Zookeeper::Callbacks::WatcherCallback:0x10692fa70 @type=2, @completed=true, @state=3, @context=nil, @proc=#<Proc:0x0000000106291dd0@/Users/eric/src/zk/vendor/bundle/gems/zookeeper-1.4.4/lib/zookeeper/callbacks.rb:24>, @zk=#<ZK::Client::Threaded:2202689880 zk_session_id=0x13d906e10860421 ...>, @path="/test/path/child">] on threadpool
  ZOO_DELETED_EVENT: /test/path/child
D, [2013-05-31T23:44:55.820680 #81644] DEBUG -- : async_args, meth: exists ary: [7, "/test/path/child", nil, #<Zookeeper::Callbacks::WatcherCallback:0x106928db0 @completed=false, @proc=#<Proc:0x0000000106291dd0@/Users/eric/src/zk/vendor/bundle/gems/zookeeper-1.4.4/lib/zookeeper/callbacks.rb:24>>], 2
D, [2013-05-31T23:44:55.821394 #81644] DEBUG -- : #iterate_event_delivery got {:stat=>nil, :rc=>-101, :req_id=>7} 
D, [2013-05-31T23:44:55.821539 #81644] DEBUG -- : continuation req_id 7, got hash: {:stat=>nil, :rc=>-101, :req_id=>7}
D, [2013-05-31T23:44:55.821633 #81644] DEBUG -- : delivering result [-101, nil]
    STAT
D, [2013-05-31T23:44:55.822425 #81644] DEBUG -- : called #<ZK::EventHandlerSubscription::Base:0x106945898 @interests=#<Set: {:changed, :created, :child, :deleted}>, @callable=#<Proc:0x000000010647c7d0@test.rb:69>, @mutex=#<ZK::Monitor:0x106945820 @mon_entering_queue=[], @mon_count=0, @mon_owner=nil, @mon_waiting_queue=[]>, @path="/test/path/child", @parent=#<ZK::EventHandler:0x10694bae0 @default_watcher_block=#<Proc:0x0000000106a77e78@/Users/eric/src/zk/lib/zk/event_handler.rb:251>, @thread_opt=:single, @orig_pid=81644, @state=:running, @outstanding_watches={:child=>#<Set: {"/test/path/child"}>, :data=>#<Set: {"/test/path/child"}>}, @mutex=#<ZK::Monitor:0x10694b478 @mon_entering_queue=[], @mon_count=0, @mon_owner=nil, @mon_waiting_queue=[]>, @callbacks={:all_node_events=>[], :all_state_events=>[], "/test/path/child"=>[#<ZK::EventHandlerSubscription::Base:0x106945898 ...>], "state_3"=>[#<ZK::EventHandlerSubscription::Base:0x1069433e0 @interests=#<Set: {:changed, :created, :child, :deleted}>, @callable=#<Proc:0x000000010647bdd0@test.rb:82>, @mutex=#<ZK::Monitor:0x106943368 @mon_entering_queue=[], @mon_count=0, @mon_owner=nil, @mon_waiting_queue=[]>, @path="state_3", @parent=#<ZK::EventHandler:0x10694bae0 ...>>]}, @zk=#<ZK::Client::Threaded:2202689880 zk_session_id=0x13d906e10860421 ...>>> with [#<Zookeeper::Callbacks::WatcherCallback:0x1069404b0 @type=2, @completed=true, @state=3, @context=nil, @proc=#<Proc:0x0000000106291dd0@/Users/eric/src/zk/vendor/bundle/gems/zookeeper-1.4.4/lib/zookeeper/callbacks.rb:24>, @zk=#<ZK::Client::Threaded:2202689880 zk_session_id=0x13d906e10860421 ...>, @path="/test/path/child">] on threadpool
  ZOO_DELETED_EVENT: /test/path/child
D, [2013-05-31T23:44:55.823008 #81644] DEBUG -- : async_args, meth: exists ary: [8, "/test/path/child", nil, nil], 2
D, [2013-05-31T23:44:55.823514 #81644] DEBUG -- : #iterate_event_delivery got {:stat=>nil, :rc=>-101, :req_id=>8} 
D, [2013-05-31T23:44:55.823623 #81644] DEBUG -- : continuation req_id 8, got hash: {:stat=>nil, :rc=>-101, :req_id=>8}
D, [2013-05-31T23:44:55.823703 #81644] DEBUG -- : delivering result [-101, nil]
    STAT
-- 2 --
CREATE
D, [2013-05-31T23:44:56.819076 #81644] DEBUG -- : #iterate_event_delivery got {:type=>1, :path=>"/test/path/child", :state=>3, :req_id=>7} 
D, [2013-05-31T23:44:56.819586 #81644] DEBUG -- : Zookeeper::Client#get_next_event delivering event {:type=>1, :path=>"/test/path/child", :state=>3, :req_id=>7}
D, [2013-05-31T23:44:56.819975 #81644] DEBUG -- : get_next_event returned: {:type=>"created", :path=>"/test/path/child", :state=>"connected", :req_id=>7}
D, [2013-05-31T23:44:56.820326 #81644] DEBUG -- : EventHandler#process dispatching event: #<Zookeeper::Callbacks::WatcherCallback:0x106928db0 @type=1, @completed=false, @state=3, @context=nil, @proc=#<Proc:0x0000000106291dd0@/Users/eric/src/zk/vendor/bundle/gems/zookeeper-1.4.4/lib/zookeeper/callbacks.rb:24>, @path="/test/path/child">
D, [2013-05-31T23:44:56.821341 #81644] DEBUG -- : called #<ZK::EventHandlerSubscription::Base:0x106945898 @interests=#<Set: {:changed, :created, :child, :deleted}>, @callable=#<Proc:0x000000010647c7d0@test.rb:69>, @mutex=#<ZK::Monitor:0x106945820 @mon_entering_queue=[], @mon_count=0, @mon_owner=nil, @mon_waiting_queue=[]>, @path="/test/path/child", @parent=#<ZK::EventHandler:0x10694bae0 @default_watcher_block=#<Proc:0x0000000106a77e78@/Users/eric/src/zk/lib/zk/event_handler.rb:251>, @thread_opt=:single, @orig_pid=81644, @state=:running, @outstanding_watches={:child=>#<Set: {"/test/path/child"}>, :data=>#<Set: {}>}, @mutex=#<ZK::Monitor:0x10694b478 @mon_entering_queue=[], @mon_count=0, @mon_owner=nil, @mon_waiting_queue=[]>, @callbacks={:all_node_events=>[], :all_state_events=>[], "/test/path/child"=>[#<ZK::EventHandlerSubscription::Base:0x106945898 ...>], "state_3"=>[#<ZK::EventHandlerSubscription::Base:0x1069433e0 @interests=#<Set: {:changed, :created, :child, :deleted}>, @callable=#<Proc:0x000000010647bdd0@test.rb:82>, @mutex=#<ZK::Monitor:0x106943368 @mon_entering_queue=[], @mon_count=0, @mon_owner=nil, @mon_waiting_queue=[]>, @path="state_3", @parent=#<ZK::EventHandler:0x10694bae0 ...>>]}, @zk=#<ZK::Client::Threaded:2202689880 zk_session_id=0x13d906e10860421 ...>>> with [#<Zookeeper::Callbacks::WatcherCallback:0x106928db0 @type=1, @completed=true, @state=3, @context=nil, @proc=#<Proc:0x0000000106291dd0@/Users/eric/src/zk/vendor/bundle/gems/zookeeper-1.4.4/lib/zookeeper/callbacks.rb:24>, @zk=#<ZK::Client::Threaded:2202689880 zk_session_id=0x13d906e10860421 ...>, @path="/test/path/child">] on threadpool
  ZOO_CREATED_EVENT: /test/path/child
D, [2013-05-31T23:44:56.822790 #81644] DEBUG -- : async_args, meth: exists ary: [9, "/test/path/child", nil, #<Zookeeper::Callbacks::WatcherCallback:0x106920e08 @completed=false, @proc=#<Proc:0x0000000106291dd0@/Users/eric/src/zk/vendor/bundle/gems/zookeeper-1.4.4/lib/zookeeper/callbacks.rb:24>>], 2
D, [2013-05-31T23:44:56.823715 #81644] DEBUG -- : #iterate_event_delivery got {:stat=>[106506, 106506, 1370069096818, 1370069096818, 0, 0, 0, 0, 18, 0, 106506], :rc=>0, :req_id=>9} 
D, [2013-05-31T23:44:56.823976 #81644] DEBUG -- : continuation req_id 9, got hash: {:stat=>[106506, 106506, 1370069096818, 1370069096818, 0, 0, 0, 0, 18, 0, 106506], :rc=>0, :req_id=>9}
D, [2013-05-31T23:44:56.824137 #81644] DEBUG -- : delivering result [0, [106506, 106506, 1370069096818, 1370069096818, 0, 0, 0, 0, 18, 0, 106506]]
    STAT
D, [2013-05-31T23:44:56.825481 #81644] DEBUG -- : async_args, meth: get_children ary: [10, "/test/path/child", nil, nil], 2
D, [2013-05-31T23:44:56.826185 #81644] DEBUG -- : #iterate_event_delivery got {:strings=>[], :stat=>[106506, 106506, 1370069096818, 1370069096818, 0, 0, 0, 0, 18, 0, 106506], :rc=>0, :req_id=>10} 
D, [2013-05-31T23:44:56.826377 #81644] DEBUG -- : continuation req_id 10, got hash: {:strings=>[], :stat=>[106506, 106506, 1370069096818, 1370069096818, 0, 0, 0, 0, 18, 0, 106506], :rc=>0, :req_id=>10}
D, [2013-05-31T23:44:56.826576 #81644] DEBUG -- : delivering result [0, [], [106506, 106506, 1370069096818, 1370069096818, 0, 0, 0, 0, 18, 0, 106506]]
    CHILDREN
ADD_CHILD
DELETE_CHILD
DELETE
D, [2013-05-31T23:44:59.828870 #81644] DEBUG -- : #iterate_event_delivery got {:type=>2, :path=>"/test/path/child", :state=>3, :req_id=>9} 
D, [2013-05-31T23:44:59.829278 #81644] DEBUG -- : Zookeeper::Client#get_next_event delivering event {:type=>2, :path=>"/test/path/child", :state=>3, :req_id=>9}
D, [2013-05-31T23:44:59.829587 #81644] DEBUG -- : get_next_event returned: {:type=>"deleted", :path=>"/test/path/child", :state=>"connected", :req_id=>9}
D, [2013-05-31T23:44:59.829843 #81644] DEBUG -- : EventHandler#process dispatching event: #<Zookeeper::Callbacks::WatcherCallback:0x106920e08 @type=2, @completed=false, @state=3, @context=nil, @proc=#<Proc:0x0000000106291dd0@/Users/eric/src/zk/vendor/bundle/gems/zookeeper-1.4.4/lib/zookeeper/callbacks.rb:24>, @path="/test/path/child">
D, [2013-05-31T23:44:59.830839 #81644] DEBUG -- : called #<ZK::EventHandlerSubscription::Base:0x106945898 @interests=#<Set: {:changed, :created, :child, :deleted}>, @callable=#<Proc:0x000000010647c7d0@test.rb:69>, @mutex=#<ZK::Monitor:0x106945820 @mon_entering_queue=[], @mon_count=0, @mon_owner=nil, @mon_waiting_queue=[]>, @path="/test/path/child", @parent=#<ZK::EventHandler:0x10694bae0 @default_watcher_block=#<Proc:0x0000000106a77e78@/Users/eric/src/zk/lib/zk/event_handler.rb:251>, @thread_opt=:single, @orig_pid=81644, @state=:running, @outstanding_watches={:child=>#<Set: {"/test/path/child"}>, :data=>#<Set: {}>}, @mutex=#<ZK::Monitor:0x10694b478 @mon_entering_queue=[], @mon_count=0, @mon_owner=nil, @mon_waiting_queue=[]>, @callbacks={:all_node_events=>[], :all_state_events=>[], "/test/path/child"=>[#<ZK::EventHandlerSubscription::Base:0x106945898 ...>], "state_3"=>[#<ZK::EventHandlerSubscription::Base:0x1069433e0 @interests=#<Set: {:changed, :created, :child, :deleted}>, @callable=#<Proc:0x000000010647bdd0@test.rb:82>, @mutex=#<ZK::Monitor:0x106943368 @mon_entering_queue=[], @mon_count=0, @mon_owner=nil, @mon_waiting_queue=[]>, @path="state_3", @parent=#<ZK::EventHandler:0x10694bae0 ...>>]}, @zk=#<ZK::Client::Threaded:2202689880 zk_session_id=0x13d906e10860421 ...>>> with [#<Zookeeper::Callbacks::WatcherCallback:0x106920e08 @type=2, @completed=true, @state=3, @context=nil, @proc=#<Proc:0x0000000106291dd0@/Users/eric/src/zk/vendor/bundle/gems/zookeeper-1.4.4/lib/zookeeper/callbacks.rb:24>, @zk=#<ZK::Client::Threaded:2202689880 zk_session_id=0x13d906e10860421 ...>, @path="/test/path/child">] on threadpool
  ZOO_DELETED_EVENT: /test/path/child
D, [2013-05-31T23:44:59.832043 #81644] DEBUG -- : async_args, meth: exists ary: [11, "/test/path/child", nil, #<Zookeeper::Callbacks::WatcherCallback:0x106919e28 @completed=false, @proc=#<Proc:0x0000000106291dd0@/Users/eric/src/zk/vendor/bundle/gems/zookeeper-1.4.4/lib/zookeeper/callbacks.rb:24>>], 2
D, [2013-05-31T23:44:59.832775 #81644] DEBUG -- : #iterate_event_delivery got {:stat=>nil, :rc=>-101, :req_id=>11} 
D, [2013-05-31T23:44:59.832926 #81644] DEBUG -- : continuation req_id 11, got hash: {:stat=>nil, :rc=>-101, :req_id=>11}
D, [2013-05-31T23:44:59.833046 #81644] DEBUG -- : delivering result [-101, nil]
    STAT
D, [2013-05-31T23:45:00.830837 #81644] DEBUG -- : Zookeeper::Client#stop_dispatch_thread!
D, [2013-05-31T23:45:00.831286 #81644] DEBUG -- : Zookeeper::Common::QueueWithPipe#graceful_close! gracefully closing
I, [2013-05-31T23:45:00.831749 #81644]  INFO -- : dispatch thread exiting, got shutdown exception
D, [2013-05-31T23:45:00.832021 #81644] DEBUG -- : dispatch thread exiting!
D, [2013-05-31T23:45:00.832429 #81644] DEBUG -- : #stop_event_thread
D, [2013-05-31T23:45:00.832578 #81644] DEBUG -- : #shut_down!
D, [2013-05-31T23:45:00.832826 #81644] DEBUG -- : we're in shutting down state, there are 0 in_flight completions
D, [2013-05-31T23:45:00.832963 #81644] DEBUG -- : finished completions
D, [2013-05-31T23:45:00.833100 #81644] DEBUG -- : there are 0 completions to awaken
D, [2013-05-31T23:45:00.833241 #81644] DEBUG -- : #event_thread_body exiting
D, [2013-05-31T23:45:00.833436 #81644] DEBUG -- : CALLING CLOSE HANDLE!!