session expired suddenly after just receive 'Unable to read data from server'

[JinHwan Hwang <ca...@gmail.com>]

The below is what i received at zookeeper client. Something i can't
understand is time between 'unable to read' and 'socket connection'. As you
see at below, that is just 1 second. That is too small for expiration.
negotiated time of the client is 6000ms and tick time is 2000ms. In my
opinion, it should be at least 4 or 6 seconds to get expiration from
getting 'unable to read'.

What i'm currently suspicious about is JVM setting. Before I set up
concurrent garbage collector on zookeeper server, there were really many
 connection loss. Can that weird connection loss come from not setting up
garbage collector on zk client JVM? There were no gc logging at the client,
and i can't reproduce this error.

thanks for reading.
______________________________________________________________________________________________
INFO ][01:00:00]-Unable to read additional data from server sessionid
0x13f3b16dcb70005, likely server has closed socket, closing socket
connection and attempting reconnect
[INFO ][01:00:01]-Opening socket connection to server
172.16.143.6/172.16.143.6:2181
[INFO ][01:00:01]-Socket connection established to
172.16.143.6/172.16.143.6:2181, initiating session
[INFO ][01:00:01]-Unable to reconnect to ZooKeeper service, session
0x13f3b16dcb70005 has expired, closing socket connection
[INFO ][01:00:01]-Initiating client connection, connectString=
172.16.143.6:2181,172.16.143.7:2181,172.16.143.8:2181 sessionTimeout=6000
watcher=com.gabia.cage.ZkSessionManager@7977b9b
[INFO ][01:00:01]-EventThread shut down
[INFO ][01:00:01]-Opening socket connection to server /172.16.143.6:2181
[INFO ][01:00:01]-Socket connection established to
172.16.143.6/172.16.143.6:2181, initiating session
[INFO ][01:00:01]-Session establishment complete on server
172.16.143.6/172.16.143.6:2181, sessionid = 0x13f40fb42210001, negotiated
timeout = 6000
___________________________________________________________________________________________

Re: session expired suddenly after just receive 'Unable to read data from server'

[Martin Kou <bi...@gmail.com>]

Have you checked the corresponding ZooKeeper logs on the server side?
Perhaps the ZooKeeper server had already expired the session before 01:00?

Best Regards,
Martin Kou


On Wed, Jun 19, 2013 at 6:21 PM, JinHwan Hwang <ca...@gmail.com> wrote:

> The below is what i received at zookeeper client. Something i can't
> understand is time between 'unable to read' and 'socket connection'. As you
> see at below, that is just 1 second. That is too small for expiration.
> negotiated time of the client is 6000ms and tick time is 2000ms. In my
> opinion, it should be at least 4 or 6 seconds to get expiration from
> getting 'unable to read'.
>
> What i'm currently suspicious about is JVM setting. Before I set up
> concurrent garbage collector on zookeeper server, there were really many
>  connection loss. Can that weird connection loss come from not setting up
> garbage collector on zk client JVM? There were no gc logging at the client,
> and i can't reproduce this error.
>
> thanks for reading.
>
> ______________________________________________________________________________________________
> INFO ][01:00:00]-Unable to read additional data from server sessionid
> 0x13f3b16dcb70005, likely server has closed socket, closing socket
> connection and attempting reconnect
> [INFO ][01:00:01]-Opening socket connection to server
> 172.16.143.6/172.16.143.6:2181
> [INFO ][01:00:01]-Socket connection established to
> 172.16.143.6/172.16.143.6:2181, initiating session
> [INFO ][01:00:01]-Unable to reconnect to ZooKeeper service, session
> 0x13f3b16dcb70005 has expired, closing socket connection
> [INFO ][01:00:01]-Initiating client connection, connectString=
> 172.16.143.6:2181,172.16.143.7:2181,172.16.143.8:2181 sessionTimeout=6000
> watcher=com.gabia.cage.ZkSessionManager@7977b9b
> [INFO ][01:00:01]-EventThread shut down
> [INFO ][01:00:01]-Opening socket connection to server /172.16.143.6:2181
> [INFO ][01:00:01]-Socket connection established to
> 172.16.143.6/172.16.143.6:2181, initiating session
> [INFO ][01:00:01]-Session establishment complete on server
> 172.16.143.6/172.16.143.6:2181, sessionid = 0x13f40fb42210001, negotiated
> timeout = 6000
>
> ___________________________________________________________________________________________
>