zetcd hangs on lock test

[glycerine]

osx 10.11.6, go1.8rc1, etcd 3.0.16, zetcd at bca6863

See https://github.com/glycerine/ezk/blob/master/recipes/lock_test.go for the test

against actual zookeeper-3.4.9/bin/zkServer.sh start: the basic lock test finishes quickly

~/go/src/github.com/glycerine/ezk/recipes (master) $ go test -v
2017/01/20 08:41:00 Connected to 127.0.0.1:2181
2017/01/20 08:41:00 Authenticated: id=97316385888796672, timeout=10000
2017/01/20 08:41:00 Re-submitting `0` credentials after reconnect
=== RUN   TestLock
--- PASS: TestLock (0.13s)
=== RUN   TestLockWithCleaner
--- PASS: TestLockWithCleaner (0.12s)
=== RUN   TestTryLock
--- PASS: TestTryLock (0.11s)
=== RUN   TestTryLockWithCleaner
--- PASS: TestTryLockWithCleaner (0.12s)
PASS
2017/01/20 08:41:01 Recv loop terminated: err=EOF
2017/01/20 08:41:01 Send loop terminated: err=<nil>
ok  	github.com/glycerine/ezk/recipes	0.618s
~/go/src/github.com/glycerine/ezk/recipes (master) $

against zetcd, the lock test just hangs forever:

~/go/src/github.com/glycerine/ezk/recipes (master) $ go test -v
2017/01/20 08:42:44 Connected to 127.0.0.1:2181

where zetcd was started as:

$ zetcd -zkaddr 0.0.0.0:2181 -endpoint localhost:2379
Running zetcd proxy

[glycerine]

ah, I didn't start etcd before. When I start a one node etcd, I still get a hang on the 2nd test:

$ go test -v                                                                                
2017/01/20 09:13:16 Connected to 127.0.0.1:2181                                             
2017/01/20 09:13:16 Authenticated: id=7587819614895799044, timeout=10000                    
2017/01/20 09:13:16 Re-submitting `0` credentials after reconnect                           
=== RUN   TestLock                                                                          
--- PASS: TestLock (0.18s)                                                                  
=== RUN   TestLockWithCleaner                                                               
          ~~~

[heyitsanthony]

bug confirmed via xchk:

I0122 15:47:32.292040   14898 zklog.go:38] Exists(10,{Path:/ezk/testlock/_c_5bdc0b1160d16df15d75b0cb12c8d13a-lock.0000000000 Watch:false})
I0122 15:47:32.292046   14898 zklog.go:38] Exists(10,{Path:/ezk/testlock/_c_5bdc0b1160d16df15d75b0cb12c8d13a-lock.0000000000 Watch:false})
I0122 15:47:32.292392   14898 session.go:116] waitFutureSendResp=&{Path:/ezk/testlock/_c_5bdc0b1160d16df15d75b0cb12c8d13a-lock.0000000000 Watch:false}
I0122 15:47:32.293267   14898 session.go:136] zk/zkresp=({Xid:10 Zxid:4 Err:0},&{Stat:{Czxid:4 Mzxid:4 Ctime:1485128852088 Mtime:1485128852088 Version:0 Cversion:0 Aversion:0 EphemeralOwner:97329403244118016 DataLength:0 NumChildren:0 Pzxid:4}})
I0122 15:47:32.293303   14898 zketcd.go:276] Exists(10) = (zxid=5, resp={Stat:{Czxid:4 Mzxid:4 Ctime:1485128852088839 Mtime:1485128852088839 Version:0 Cversion:0 Aversion:0 EphemeralOwner:8488258115690905899 DataLength:0 NumChildren:0 Pzxid:4}})
I0122 15:47:32.293369   14898 conn.go:131] sendXchk Xid:10 ZXid:4 Resp:&{Stat:{Czxid:4 Mzxid:4 Ctime:1485128852088 Mtime:1485128852088 Version:0 Cversion:0 Aversion:0 EphemeralOwner:97329403244118016 DataLength:0 NumChildren:0 Pzxid:4}}
I0122 15:47:32.293628   14898 conn.go:133] conn.Send(xid=10, zxid=4, &{Stat:{Czxid:4 Mzxid:4 Ctime:1485128852088 Mtime:1485128852088 Version:0 Cversion:0 Aversion:0 EphemeralOwner:97329403244118016 DataLength:0 NumChildren:0 Pzxid:4}})
I0122 15:47:32.293769   14898 server.go:110] zkreq={xid:11 req:*zetcd.DeleteRequest:&{Path:/ezk/testlock/_c_5bdc0b1160d16df15d75b0cb12c8d13a-lock.0000000000 Version:0}}
I0122 15:47:32.293809   14898 zklog.go:33] Delete(11,{Path:/ezk/testlock/_c_5bdc0b1160d16df15d75b0cb12c8d13a-lock.0000000000 Version:0})
I0122 15:47:32.293818   14898 zklog.go:33] Delete(11,{Path:/ezk/testlock/_c_5bdc0b1160d16df15d75b0cb12c8d13a-lock.0000000000 Version:0})
I0122 15:47:32.294133   14898 session.go:116] waitFutureSendResp=&{Path:/ezk/testlock/_c_5bdc0b1160d16df15d75b0cb12c8d13a-lock.0000000000 Version:0}
I0122 15:47:32.295936   14898 zketcd.go:238] Delete(11) = (zxid=6, resp={})
I0122 15:47:32.307672   14898 session.go:136] zk/zkresp=({Xid:11 Zxid:5 Err:0},&{})
I0122 15:47:32.307699   14898 conn.go:131] sendXchk Xid:11 ZXid:5 Resp:&{}
I0122 15:47:32.308101   14898 conn.go:133] conn.Send(xid=11, zxid=5, &{})
I0122 15:47:32.308722   14898 server.go:110] zkreq={xid:12 req:*zetcd.CreateRequest:&{Path:/ezk/testlock/_c_2c322449cb8ac47d451189150fa11a1e-lock. Data:[] Acl:[{Perms:31 Scheme:world ID:anyone}] Flags:3}}
I0122 15:47:32.308771   14898 zklog.go:28] Create(12,{Path:/ezk/testlock/_c_2c322449cb8ac47d451189150fa11a1e-lock. Data:[] Acl:[{Perms:31 Scheme:world ID:anyone}] Flags:3})
I0122 15:47:32.308776   14898 zklog.go:28] Create(12,{Path:/ezk/testlock/_c_2c322449cb8ac47d451189150fa11a1e-lock. Data:[] Acl:[{Perms:31 Scheme:world ID:anyone}] Flags:3})
I0122 15:47:32.309165   14898 session.go:116] waitFutureSendResp=&{Path:/ezk/testlock/_c_2c322449cb8ac47d451189150fa11a1e-lock. Data:[] Acl:[{Perms:31 Scheme:world ID:anyone}] Flags:3}
I0122 15:47:32.318608   14898 session.go:136] zk/zkresp=({Xid:12 Zxid:6 Err:0},&{Path:/ezk/testlock/_c_2c322449cb8ac47d451189150fa11a1e-lock.0000000001})
I0122 15:47:32.362611   14898 zketcd.go:125] Create(7) = (zxid=12, resp={Path:/ezk/testlock/_c_2c322449cb8ac47d451189150fa11a1e-lock.0000000001}); txnresp.Header: cluster_id:8925027824743593106 member_id:13803658152347727308 revision:7 raft_term:2
I0122 15:47:32.362652   14898 conn.go:131] sendXchk Xid:12 ZXid:6 Resp:&{Path:/ezk/testlock/_c_2c322449cb8ac47d451189150fa11a1e-lock.0000000001}
I0122 15:47:32.362936   14898 conn.go:133] conn.Send(xid=12, zxid=6, &{Path:/ezk/testlock/_c_2c322449cb8ac47d451189150fa11a1e-lock.0000000001})
I0122 15:47:32.363080   14898 server.go:110] zkreq={xid:13 req:*zetcd.GetChildren2Request:&{Path:/ezk/testlock Watch:false}}
I0122 15:47:32.363129   14898 zklog.go:78] GetChildren2(13,{Path:/ezk/testlock Watch:false})
I0122 15:47:32.363136   14898 zklog.go:78] GetChildren2(13,{Path:/ezk/testlock Watch:false})
I0122 15:47:32.363495   14898 session.go:116] waitFutureSendResp=&{Path:/ezk/testlock Watch:false}
I0122 15:47:32.364192   14898 session.go:136] zk/zkresp=({Xid:13 Zxid:6 Err:0},&{Children:[_c_2c322449cb8ac47d451189150fa11a1e-lock.0000000001] Stat:{Czxid:3 Mzxid:3 Ctime:1485128852082 Mtime:1485128852082 Version:0 Cversion:3 Aversion:0 EphemeralOwner:0 DataLength:0 NumChildren:1 Pzxid:6}})
I0122 15:47:32.364432   14898 zketcd.go:165] GetChildren2(7) = (zxid=13, resp={Children:[_c_2c322449cb8ac47d451189150fa11a1e-lock.0000000001] Stat:{Czxid:3 Mzxid:5 Ctime:1485128852082379 Mtime:1485128852295412 Version:1 Cversion:3 Aversion:0 EphemeralOwner:0 DataLength:0 NumChildren:1 Pzxid:6}})
W0122 15:47:32.364455   14898 zk.go:326] xchk failed (stat mismatch)
candiate: &{Children:[_c_2c322449cb8ac47d451189150fa11a1e-lock.0000000001] Stat:{Czxid:3 Mzxid:5 Ctime:1485128852082379 Mtime:1485128852295412 Version:1 Cversion:3 Aversion:0 EphemeralOwner:0 DataLength:0 NumChildren:1 Pzxid:6}}
oracle: &{Children:[_c_2c322449cb8ac47d451189150fa11a1e-lock.0000000001] Stat:{Czxid:3 Mzxid:3 Ctime:1485128852082 Mtime:1485128852082 Version:0 Cversion:3 Aversion:0 EphemeralOwner:0 DataLength:0 NumChildren:1 Pzxid:6}}