zookeeper-user mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Jordan Zimmerman <jzimmer...@netflix.com>
Subject Re: Testing expired sessions bug?
Date Tue, 21 Aug 2012 20:02:53 GMT
FYI - Curator has a utility for expiring a session:

https://github.com/Netflix/curator/blob/master/curator-test/src/main/java/com/netflix/curator/test/KillSession.java

On Aug 21, 2012, at 1:00 PM, Ben Bangert <ben@groovie.org<mailto:ben@groovie.org>>
 wrote:

The Zookeeper FAQ documents the following to create a session expiration for testing:

"In the case of testing we want to cause a problem, so to explicitly expire a session an application
connects to ZooKeeper, saves the session id and password, creates another ZooKeeper handle
with that id and password, and then closes the new handle. Since both handles reference the
same session, the close on second handle will invalidate the session causing a SESSION_EXPIRED
on the first handle."


This apparently works.... some of the time. Our tests show that it seems to work as this describes
about 95% of the time. The other times, the new client being connected with the existing client
id immediately gets an EXPIRED_SESSION_STATE upon connecting. The existing client does *not*
get the session expiration as the docs seem to think, its session is fine. This is a bit odd
as the client attempting to re-use the session ID/password is told the session is expired,
while the existing connected client is fine (seemingly invalidating the claim that the session
is expired).

This appears in a 3-server setup when having the new client go to a separate server in the
cluster from the first one, and when they're both on the same Zookeeper server.

When they go to the same server, I get rather confusing information by watching the clients
global watcher debug info:

ZooKeeper: INFO: log_env@712: Client environment:zookeeper.version=zookeeper C client 3.4.3
ZooKeeper: INFO: log_env@716: Client environment:host.name=Lars.local
ZooKeeper: INFO: log_env@723: Client environment:os.name=Darwin
ZooKeeper: INFO: log_env@724: Client environment:os.arch=12.0.0
ZooKeeper: INFO: log_env@725: Client environment:os.version=Darwin Kernel Version 12.0.0:
Sun Jun 24 23:00:16 PDT 2012; root:xnu-2050.7.9~1/RELEASE_X86_64
ZooKeeper: INFO: zookeeper_init@786: Initiating client connection, host=127.0.0.1:20000/kazootests6859289a29b041e9bf7c4f69afde7e6c
sessionTimeout=10000 watcher=0x1016c2420 sessionId=0 sessionPasswd=<null> context=0x102d12f00
flags=0
ZooKeeper: INFO: check_events@1701: initiated connection to server [127.0.0.1:20000]
ZooKeeper: INFO: check_events@1748: session establishment complete on server [127.0.0.1:20000],
sessionId=0x1393db197700bff, negotiated timeout=10000
kazoo.client: DEBUG: Client Instance: 4319500112, Handle: 2, Type: SESSION_EVENT, State: CONNECTED_STATE,
Path:
ZooKeeper: INFO: zookeeper_init@786: Initiating client connection, host=127.0.0.1:20000 sessionTimeout=10000
watcher=0x1016c2420 sessionId=0x1393db197700bff sessionPasswd=<hidden> context=0x102d14050
flags=0
ZooKeeper: INFO: check_events@1701: initiated connection to server [127.0.0.1:20000]
ZooKeeper: ERROR: handle_socket_error_msg@1719: Socket [127.0.0.1:20000] zk retcode=-4, errno=64(Host
is down): failed while receiving a server response
ZooKeeper: ERROR: handle_socket_error_msg@1737: Socket [127.0.0.1:20000] zk retcode=-112,
errno=70(Stale NFS file handle): sessionId=0x1393db197700bff has expired.
kazoo.client: DEBUG: Client Instance: 4319532240, Handle: 3, Type: SESSION_EVENT, State: EXPIRED_SESSION_STATE,
Path:
kazoo.client: DEBUG: Client Instance: 4319500112, Handle: 2, Type: SESSION_EVENT, State: CONNECTING_STATE,
Path:
ZooKeeper: INFO: zookeeper_init@786: Initiating client connection, host=127.0.0.1:20000 sessionTimeout=10000
watcher=0x1016c2420 sessionId=0 sessionPasswd=<null> context=0x102d08cc0 flags=0
ZooKeeper: INFO: check_events@1701: initiated connection to server [127.0.0.1:20000]
ZooKeeper: INFO: check_events@1748: session establishment complete on server [127.0.0.1:20000],
sessionId=0x1393db197700c00, negotiated timeout=10000
kazoo.client: DEBUG: Client Instance: 4319532240, Handle: 4, Type: SESSION_EVENT, State: CONNECTED_STATE,
Path:
ZooKeeper: INFO: zookeeper_close@2506: Closing zookeeper sessionId=0x1393db197700c00 to [127.0.0.1:20000]
ZooKeeper: INFO: check_events@1701: initiated connection to server [127.0.0.1:20000]
ZooKeeper: INFO: check_events@1748: session establishment complete on server [127.0.0.1:20000],
sessionId=0x1393db197700bff, negotiated timeout=10000
kazoo.client: DEBUG: Client Instance: 4319500112, Handle: 2, Type: SESSION_EVENT, State: CONNECTED_STATE,
Path:

The second client gets an expired session state upon connecting, the first client gets disconnect
(but NOT expired). The debug clearly indicates the server just said that sessionId 0x1393db197700bff
has expired. Yet the second line from the bottom, we can see the first client successfully
reconnect with its session that supposedly is expired.

When the second client uses a different server, it just gets kicked off and the first client
never gets disconnected:

ZooKeeper: INFO: zookeeper_init@786: Initiating client connection, host=127.0.0.1:20000/kazootests0209e8a645674d4d865d22960fb579bb
sessionTimeout=10000 watcher=0x1016c2420 sessionId=0 sessionPasswd=<null> context=0x10189bf10
flags=0
ZooKeeper: INFO: check_events@1701: initiated connection to server [127.0.0.1:20000]
ZooKeeper: INFO: check_events@1748: session establishment complete on server [127.0.0.1:20000],
sessionId=0x1393db197700cc7, negotiated timeout=10000
kazoo.client: DEBUG: Client Instance: 4319500688, Handle: 2, Type: SESSION_EVENT, State: CONNECTED_STATE,
Path:
ZooKeeper: INFO: zookeeper_init@786: Initiating client connection, host=127.0.0.1:20010 sessionTimeout=10000
watcher=0x1016c2420 sessionId=0x1393db197700cc7 sessionPasswd=<hidden> context=0x101835030
flags=0
ZooKeeper: INFO: check_events@1701: initiated connection to server [127.0.0.1:20010]
ZooKeeper: ERROR: handle_socket_error_msg@1737: Socket [127.0.0.1:20010] zk retcode=-112,
errno=70(Stale NFS file handle): sessionId=0x1393db197700cc7 has expired.
kazoo.client: DEBUG: Client Instance: 4319532240, Handle: 3, Type: SESSION_EVENT, State: EXPIRED_SESSION_STATE,
Path:
ZooKeeper: INFO: zookeeper_init@786: Initiating client connection, host=127.0.0.1:20010 sessionTimeout=10000
watcher=0x1016c2420 sessionId=0 sessionPasswd=<null> context=0x1015e0070 flags=0
ZooKeeper: INFO: check_events@1701: initiated connection to server [127.0.0.1:20010]
ZooKeeper: INFO: check_events@1748: session establishment complete on server [127.0.0.1:20010],
sessionId=0x2393db19cfe0015, negotiated timeout=10000
kazoo.client: DEBUG: Client Instance: 4319532240, Handle: 4, Type: SESSION_EVENT, State: CONNECTED_STATE,
Path:
ZooKeeper: INFO: zookeeper_close@2506: Closing zookeeper sessionId=0x2393db19cfe0015 to [127.0.0.1:20010]

I've even setup the test so that it creates new ephemeral nodes and such with the old supposedly
expired session, and its just fine.

Is this intended behavior?

I have the tickTime set at 2000, setting it to 20000 didn't seem to help, nor did waiting
longer to see if the first client would someday get its session expired.

Cheers,
Ben


Mime
  • Unnamed multipart/alternative (inline, None, 0 bytes)
View raw message