You are viewing a plain text version of this content. The canonical link for it is here.
Posted to user@zookeeper.apache.org by Martin Serrano <ma...@attivio.com> on 2011/10/19 17:48:50 UTC
is there a 40s connection timeout that expires a session?
I'm seeing something a bit weird. In our environment we've upped the session timeout to 10 minutes. I see that the client connections successfully negotiate the 10 minute timeout. However I've seen a case where the client session gets timed out in 40s if it is unable to ever initiate the session. Is there a separate timeout somewhere?
Thanks,
Martin
Log excerpts below (unfortunately the server-side logs are not available):
2011-10-18 21:38:59,218 INFO ClientCnxn [ZooKeeperClientCnxn--SendThread()-0] - Opening socket connection to server localhost/0:0:0:0:0:0:0:1:16015
2011-10-18 21:38:59,220 WARN ClientCnxn [ZooKeeperClientCnxn--SendThread(localhost:16015)-0] - Session 0x0 for server null, unexpected error, closing socket connection and attempting reconnect
2011-10-18 21:39:00,181 INFO ClientCnxn [ZooKeeperClientCnxn--SendThread(localhost:16015)-0] - Opening socket connection to server localhost/127.0.0.1:16015
2011-10-18 21:39:00,184 INFO ClientCnxn [ZooKeeperClientCnxn--SendThread(localhost:16015)-0] - Socket connection established to localhost/127.0.0.1:16015, initiating session
2011-10-18 21:39:00,241 INFO ClientCnxn [ZooKeeperClientCnxn--SendThread-13319d4a8c3000c] - Session establishment complete on server localhost/127.0.0.1:16015, sessionid = 0x13319d4a8c3000c, negotiated timeout = 600000
2011-10-18 21:39:00,326 INFO ZooKeeper [main] - Initiating client connection, connectString=localhost:16015 sessionTimeout=600000 watcher=com.attivio.global.AieZooKeeper@45490eb5
2011-10-18 21:39:00,329 INFO ClientCnxn [ZooKeeperClientCnxn--SendThread()-0] - Opening socket connection to server localhost/0:0:0:0:0:0:0:1:16015
2011-10-18 21:39:00,329 WARN ClientCnxn [ZooKeeperClientCnxn--SendThread(localhost:16015)-0] - Session 0x0 for server null, unexpected error, closing socket connection and attempting reconnect
2011-10-18 21:39:00,665 INFO ClientCnxn [ZooKeeperClientCnxn--SendThread(localhost:16015)-0] - Opening socket connection to server localhost/127.0.0.1:16015
2011-10-18 21:39:00,666 INFO ClientCnxn [ZooKeeperClientCnxn--SendThread(localhost:16015)-0] - Socket connection established to localhost/127.0.0.1:16015, initiating session
2011-10-18 21:39:00,670 INFO ClientCnxn [ZooKeeperClientCnxn--SendThread-13319d4a8c3000d] - Session establishment complete on server localhost/127.0.0.1:16015, sessionid = 0x13319d4a8c3000d, negotiated timeout = 600000
2011-10-18 21:39:02,125 INFO ClientCnxn [ZooKeeperClientCnxn--SendThread-13319d4a8c3000d] - Unable to read additional data from server sessionid 0x13319d4a8c3000d, likely server has closed socket, closing socket connection and attempting reconnect
2011-10-18 21:39:02,125 INFO ClientCnxn [ZooKeeperClientCnxn--SendThread-13319d4a8c3000c] - Unable to read additional data from server sessionid 0x13319d4a8c3000c, likely server has closed socket, closing socket connection and attempting reconnect
2011-10-18 21:39:02,295 INFO ClientCnxn [ZooKeeperClientCnxn--SendThread-13319d4a8c3000d] - Opening socket connection to server localhost/0:0:0:0:0:0:0:1:16015
2011-10-18 21:39:02,295 WARN ClientCnxn [ZooKeeperClientCnxn--SendThread-13319d4a8c3000d] - Session 0x13319d4a8c3000d for server null, unexpected error, closing socket connection and attempting reconnect
2011-10-18 21:39:02,873 INFO ClientCnxn [ZooKeeperClientCnxn--SendThread-13319d4a8c3000c] - Opening socket connection to server localhost/0:0:0:0:0:0:0:1:16015
2011-10-18 21:39:02,873 WARN ClientCnxn [ZooKeeperClientCnxn--SendThread-13319d4a8c3000c] - Session 0x13319d4a8c3000c for server null, unexpected error, closing socket connection and attempting reconnect
2011-10-18 21:39:03,676 INFO ClientCnxn [ZooKeeperClientCnxn--SendThread-13319d4a8c3000d] - Opening socket connection to server localhost/127.0.0.1:16015
2011-10-18 21:39:03,677 INFO ClientCnxn [ZooKeeperClientCnxn--SendThread-13319d4a8c3000d] - Socket connection established to localhost/127.0.0.1:16015, initiating session
2011-10-18 21:39:03,678 WARN ClientCnxn [ZooKeeperClientCnxn--SendThread-13319d4a8c3000d] - Session 0x13319d4a8c3000d for server localhost/127.0.0.1:16015, unexpected error, closing socket connection and attempting reconnect
2011-10-18 21:39:04,027 INFO ClientCnxn [ZooKeeperClientCnxn--SendThread-13319d4a8c3000d] - Opening socket connection to server localhost/0:0:0:0:0:0:0:1:16015
2011-10-18 21:39:04,027 WARN ClientCnxn [ZooKeeperClientCnxn--SendThread-13319d4a8c3000d] - Session 0x13319d4a8c3000d for server null, unexpected error, closing socket connection and attempting reconnect
2011-10-18 21:39:04,416 INFO ClientCnxn [ZooKeeperClientCnxn--SendThread-13319d4a8c3000c] - Opening socket connection to server localhost/127.0.0.1:16015
2011-10-18 21:39:04,417 INFO ClientCnxn [ZooKeeperClientCnxn--SendThread-13319d4a8c3000c] - Socket connection established to localhost/127.0.0.1:16015, initiating session
2011-10-18 21:39:04,417 INFO ClientCnxn [ZooKeeperClientCnxn--SendThread-13319d4a8c3000c] - Unable to read additional data from server sessionid 0x13319d4a8c3000c, likely server has closed socket, closing socket connection and attempting reconnect
2011-10-18 21:39:04,705 INFO ClientCnxn [ZooKeeperClientCnxn--SendThread-13319d4a8c3000c] - Opening socket connection to server localhost/0:0:0:0:0:0:0:1:16015
2011-10-18 21:39:04,705 WARN ClientCnxn [ZooKeeperClientCnxn--SendThread-13319d4a8c3000c] - Session 0x13319d4a8c3000c for server null, unexpected error, closing socket connection and attempting reconnect
2011-10-18 21:39:05,447 INFO ClientCnxn [ZooKeeperClientCnxn--SendThread-13319d4a8c3000d] - Opening socket connection to server localhost/127.0.0.1:16015
2011-10-18 21:39:05,448 INFO ClientCnxn [ZooKeeperClientCnxn--SendThread-13319d4a8c3000d] - Socket connection established to localhost/127.0.0.1:16015, initiating session
2011-10-18 21:39:05,449 INFO ClientCnxn [ZooKeeperClientCnxn--SendThread-13319d4a8c3000d] - Unable to read additional data from server sessionid 0x13319d4a8c3000d, likely server has closed socket, closing socket connection and attempting reconnect
Lots more of those, then:
2011-10-18 21:39:39,387 INFO ClientCnxn [ZooKeeperClientCnxn--SendThread-13319d4a8c3000c] - Opening socket connection to server localhost/127.0.0.1:16015
2011-10-18 21:39:39,388 INFO ClientCnxn [ZooKeeperClientCnxn--SendThread-13319d4a8c3000c] - Socket connection established to localhost/127.0.0.1:16015, initiating session
2011-10-18 21:39:39,388 INFO ClientCnxn [ZooKeeperClientCnxn--SendThread-13319d4a8c3000c] - Unable to read additional data from server sessionid 0x13319d4a8c3000c, likely server has closed socket, closing socket connection and attempting reconnect
2011-10-18 21:39:39,592 INFO ClientCnxn [ZooKeeperClientCnxn--SendThread-13319d4a8c3000d] - Opening socket connection to server localhost/0:0:0:0:0:0:0:1:16015
2011-10-18 21:39:39,592 WARN ClientCnxn [ZooKeeperClientCnxn--SendThread-13319d4a8c3000d] - Session 0x13319d4a8c3000d for server null, unexpected error, closing socket connection and attempting reconnect
2011-10-18 21:39:39,735 INFO ClientCnxn [ZooKeeperClientCnxn--SendThread-13319d4a8c3000c] - Opening socket connection to server localhost/0:0:0:0:0:0:0:1:16015
2011-10-18 21:39:39,735 WARN ClientCnxn [ZooKeeperClientCnxn--SendThread-13319d4a8c3000c] - Session 0x13319d4a8c3000c for server null, unexpected error, closing socket connection and attempting reconnect
2011-10-18 21:39:41,400 INFO ClientCnxn [ZooKeeperClientCnxn--SendThread-13319d4a8c3000d] - Opening socket connection to server localhost/127.0.0.1:16015
2011-10-18 21:39:41,401 INFO ClientCnxn [ZooKeeperClientCnxn--SendThread-13319d4a8c3000d] - Socket connection established to localhost/127.0.0.1:16015, initiating session
2011-10-18 21:39:41,402 INFO ClientCnxn [ZooKeeperClientCnxn--SendThread-13319d4a8c3000d] - Unable to reconnect to ZooKeeper service, session 0x13319d4a8c3000d has expired, closing socket connection
RE: is there a 40s connection timeout that expires a session?
Posted by jodzga <jo...@gmail.com>.
Did you manage to solve this problem? I am seeing the same behavior...
--
View this message in context: http://zookeeper-user.578899.n2.nabble.com/is-there-a-40s-connection-timeout-that-expires-a-session-tp6909250p7579292.html
Sent from the zookeeper-user mailing list archive at Nabble.com.
Re: is there a 40s connection timeout that expires a session?
Posted by Patrick Hunt <ph...@apache.org>.
Ack, sorry about that, jumped directly to my canned response. :-)
Does 600 seconds typically work, but just failed in this particular
case? (what version of zk are you using?) Can you reproduce this or
just a one off?
Could the time on the server have been changed? ie say via ntp? (we've
seen this before)
Any idea why the client is unable to access the server during this
period? Is this the only client activity against the server?
Patrick
On Wed, Oct 19, 2011 at 10:18 AM, Martin Serrano <ma...@attivio.com> wrote:
> Patrick,
>
> Thanks. I know about the negotiated timeout and how the maximum is specified. We start up our server so that it allows a greater timeout. In the logs I attached you can see that the negotiated timeout is 600000ms, but I still get the session expired message at 40s.
>
> -Martin
>
>> -----Original Message-----
>> From: Patrick Hunt [mailto:phunt@apache.org]
>> Sent: Wednesday, October 19, 2011 12:57 PM
>> To: user@zookeeper.apache.org
>> Subject: Re: is there a 40s connection timeout that expires a session?
>>
>> The actual session timeout is negotiated btw the client and server, there is
>> both a min and a max enforced by the server.
>>
>> See this section on session details:
>> http://zookeeper.apache.org/doc/r3.3.3/zookeeperProgrammers.html#ch_
>> zkSessions
>> "One of the parameters to the ZooKeeper client library call to create a
>> ZooKeeper session is the session timeout in milliseconds. The client sends a
>> requested timeout, the server responds with the timeout that it can give the
>> client. The current implementation requires that the timeout be a minimum
>> of 2 times the tickTime (as set in the server
>> configuration) and a maximum of 20 times the tickTime. The ZooKeeper
>> client API allows access to the negotiated timeout."
>>
>> You're seeing the default (20*ticktime, which is typically 2 sec, so 40sec max)
>>
>> See here: (maxSessionTimeout)
>> http://zookeeper.apache.org/doc/r3.3.3/zookeeperAdmin.html#sc_advanc
>> edConfiguration
>>
>>
>> btw, setting a 10min timeout will probably cause you problems down the
>> road - as things that depend on ephemeral nodes (e.g. leader failover) will
>> take too long to be effective. (typically)
>>
>> Patrick
>>
>> On Wed, Oct 19, 2011 at 8:48 AM, Martin Serrano <ma...@attivio.com>
>> wrote:
>> > I'm seeing something a bit weird. In our environment we've upped the
>> session timeout to 10 minutes. I see that the client connections successfully
>> negotiate the 10 minute timeout. However I've seen a case where the client
>> session gets timed out in 40s if it is unable to ever initiate the session. Is
>> there a separate timeout somewhere?
>> >
>> > Thanks,
>> > Martin
>> >
>> > Log excerpts below (unfortunately the server-side logs are not available):
>> >
>> > 2011-10-18 21:38:59,218 INFO ClientCnxn
>> > [ZooKeeperClientCnxn--SendThread()-0] - Opening socket connection to
>> > server localhost/0:0:0:0:0:0:0:1:16015
>> > 2011-10-18 21:38:59,220 WARN ClientCnxn
>> > [ZooKeeperClientCnxn--SendThread(localhost:16015)-0] - Session 0x0 for
>> > server null, unexpected error, closing socket connection and
>> > attempting reconnect
>> > 2011-10-18 21:39:00,181 INFO ClientCnxn
>> > [ZooKeeperClientCnxn--SendThread(localhost:16015)-0] - Opening socket
>> > connection to server localhost/127.0.0.1:16015
>> > 2011-10-18 21:39:00,184 INFO ClientCnxn
>> > [ZooKeeperClientCnxn--SendThread(localhost:16015)-0] - Socket
>> > connection established to localhost/127.0.0.1:16015, initiating
>> > session
>> > 2011-10-18 21:39:00,241 INFO ClientCnxn
>> > [ZooKeeperClientCnxn--SendThread-13319d4a8c3000c] - Session
>> > establishment complete on server localhost/127.0.0.1:16015, sessionid
>> > = 0x13319d4a8c3000c, negotiated timeout = 600000
>> > 2011-10-18 21:39:00,326 INFO ZooKeeper [main] - Initiating client
>> > connection, connectString=localhost:16015 sessionTimeout=600000
>> > watcher=com.attivio.global.AieZooKeeper@45490eb5
>> > 2011-10-18 21:39:00,329 INFO ClientCnxn
>> > [ZooKeeperClientCnxn--SendThread()-0] - Opening socket connection to
>> > server localhost/0:0:0:0:0:0:0:1:16015
>> > 2011-10-18 21:39:00,329 WARN ClientCnxn
>> > [ZooKeeperClientCnxn--SendThread(localhost:16015)-0] - Session 0x0 for
>> > server null, unexpected error, closing socket connection and
>> > attempting reconnect
>> > 2011-10-18 21:39:00,665 INFO ClientCnxn
>> > [ZooKeeperClientCnxn--SendThread(localhost:16015)-0] - Opening socket
>> > connection to server localhost/127.0.0.1:16015
>> > 2011-10-18 21:39:00,666 INFO ClientCnxn
>> > [ZooKeeperClientCnxn--SendThread(localhost:16015)-0] - Socket
>> > connection established to localhost/127.0.0.1:16015, initiating
>> > session
>> > 2011-10-18 21:39:00,670 INFO ClientCnxn
>> > [ZooKeeperClientCnxn--SendThread-13319d4a8c3000d] - Session
>> > establishment complete on server localhost/127.0.0.1:16015, sessionid
>> > = 0x13319d4a8c3000d, negotiated timeout = 600000
>> > 2011-10-18 21:39:02,125 INFO ClientCnxn
>> > [ZooKeeperClientCnxn--SendThread-13319d4a8c3000d] - Unable to read
>> > additional data from server sessionid 0x13319d4a8c3000d, likely server
>> > has closed socket, closing socket connection and attempting reconnect
>> > 2011-10-18 21:39:02,125 INFO ClientCnxn
>> > [ZooKeeperClientCnxn--SendThread-13319d4a8c3000c] - Unable to read
>> > additional data from server sessionid 0x13319d4a8c3000c, likely server
>> > has closed socket, closing socket connection and attempting reconnect
>> > 2011-10-18 21:39:02,295 INFO ClientCnxn
>> > [ZooKeeperClientCnxn--SendThread-13319d4a8c3000d] - Opening socket
>> > connection to server localhost/0:0:0:0:0:0:0:1:16015
>> > 2011-10-18 21:39:02,295 WARN ClientCnxn
>> > [ZooKeeperClientCnxn--SendThread-13319d4a8c3000d] - Session
>> > 0x13319d4a8c3000d for server null, unexpected error, closing socket
>> > connection and attempting reconnect
>> > 2011-10-18 21:39:02,873 INFO ClientCnxn
>> > [ZooKeeperClientCnxn--SendThread-13319d4a8c3000c] - Opening socket
>> > connection to server localhost/0:0:0:0:0:0:0:1:16015
>> > 2011-10-18 21:39:02,873 WARN ClientCnxn
>> > [ZooKeeperClientCnxn--SendThread-13319d4a8c3000c] - Session
>> > 0x13319d4a8c3000c for server null, unexpected error, closing socket
>> > connection and attempting reconnect
>> > 2011-10-18 21:39:03,676 INFO ClientCnxn
>> > [ZooKeeperClientCnxn--SendThread-13319d4a8c3000d] - Opening socket
>> > connection to server localhost/127.0.0.1:16015
>> > 2011-10-18 21:39:03,677 INFO ClientCnxn
>> > [ZooKeeperClientCnxn--SendThread-13319d4a8c3000d] - Socket
>> connection
>> > established to localhost/127.0.0.1:16015, initiating session
>> > 2011-10-18 21:39:03,678 WARN ClientCnxn
>> > [ZooKeeperClientCnxn--SendThread-13319d4a8c3000d] - Session
>> > 0x13319d4a8c3000d for server localhost/127.0.0.1:16015, unexpected
>> > error, closing socket connection and attempting reconnect
>> > 2011-10-18 21:39:04,027 INFO ClientCnxn
>> > [ZooKeeperClientCnxn--SendThread-13319d4a8c3000d] - Opening socket
>> > connection to server localhost/0:0:0:0:0:0:0:1:16015
>> > 2011-10-18 21:39:04,027 WARN ClientCnxn
>> > [ZooKeeperClientCnxn--SendThread-13319d4a8c3000d] - Session
>> > 0x13319d4a8c3000d for server null, unexpected error, closing socket
>> > connection and attempting reconnect
>> > 2011-10-18 21:39:04,416 INFO ClientCnxn
>> > [ZooKeeperClientCnxn--SendThread-13319d4a8c3000c] - Opening socket
>> > connection to server localhost/127.0.0.1:16015
>> > 2011-10-18 21:39:04,417 INFO ClientCnxn
>> > [ZooKeeperClientCnxn--SendThread-13319d4a8c3000c] - Socket
>> connection
>> > established to localhost/127.0.0.1:16015, initiating session
>> > 2011-10-18 21:39:04,417 INFO ClientCnxn
>> > [ZooKeeperClientCnxn--SendThread-13319d4a8c3000c] - Unable to read
>> > additional data from server sessionid 0x13319d4a8c3000c, likely server
>> > has closed socket, closing socket connection and attempting reconnect
>> > 2011-10-18 21:39:04,705 INFO ClientCnxn
>> > [ZooKeeperClientCnxn--SendThread-13319d4a8c3000c] - Opening socket
>> > connection to server localhost/0:0:0:0:0:0:0:1:16015
>> > 2011-10-18 21:39:04,705 WARN ClientCnxn
>> > [ZooKeeperClientCnxn--SendThread-13319d4a8c3000c] - Session
>> > 0x13319d4a8c3000c for server null, unexpected error, closing socket
>> > connection and attempting reconnect
>> > 2011-10-18 21:39:05,447 INFO ClientCnxn
>> > [ZooKeeperClientCnxn--SendThread-13319d4a8c3000d] - Opening socket
>> > connection to server localhost/127.0.0.1:16015
>> > 2011-10-18 21:39:05,448 INFO ClientCnxn
>> > [ZooKeeperClientCnxn--SendThread-13319d4a8c3000d] - Socket
>> connection
>> > established to localhost/127.0.0.1:16015, initiating session
>> > 2011-10-18 21:39:05,449 INFO ClientCnxn
>> > [ZooKeeperClientCnxn--SendThread-13319d4a8c3000d] - Unable to read
>> > additional data from server sessionid 0x13319d4a8c3000d, likely server
>> > has closed socket, closing socket connection and attempting reconnect
>> >
>> > Lots more of those, then:
>> >
>> > 2011-10-18 21:39:39,387 INFO ClientCnxn
>> > [ZooKeeperClientCnxn--SendThread-13319d4a8c3000c] - Opening socket
>> > connection to server localhost/127.0.0.1:16015
>> > 2011-10-18 21:39:39,388 INFO ClientCnxn
>> > [ZooKeeperClientCnxn--SendThread-13319d4a8c3000c] - Socket
>> connection
>> > established to localhost/127.0.0.1:16015, initiating session
>> > 2011-10-18 21:39:39,388 INFO ClientCnxn
>> > [ZooKeeperClientCnxn--SendThread-13319d4a8c3000c] - Unable to read
>> > additional data from server sessionid 0x13319d4a8c3000c, likely server
>> > has closed socket, closing socket connection and attempting reconnect
>> > 2011-10-18 21:39:39,592 INFO ClientCnxn
>> > [ZooKeeperClientCnxn--SendThread-13319d4a8c3000d] - Opening socket
>> > connection to server localhost/0:0:0:0:0:0:0:1:16015
>> > 2011-10-18 21:39:39,592 WARN ClientCnxn
>> > [ZooKeeperClientCnxn--SendThread-13319d4a8c3000d] - Session
>> > 0x13319d4a8c3000d for server null, unexpected error, closing socket
>> > connection and attempting reconnect
>> > 2011-10-18 21:39:39,735 INFO ClientCnxn
>> > [ZooKeeperClientCnxn--SendThread-13319d4a8c3000c] - Opening socket
>> > connection to server localhost/0:0:0:0:0:0:0:1:16015
>> > 2011-10-18 21:39:39,735 WARN ClientCnxn
>> > [ZooKeeperClientCnxn--SendThread-13319d4a8c3000c] - Session
>> > 0x13319d4a8c3000c for server null, unexpected error, closing socket
>> > connection and attempting reconnect
>> > 2011-10-18 21:39:41,400 INFO ClientCnxn
>> > [ZooKeeperClientCnxn--SendThread-13319d4a8c3000d] - Opening socket
>> > connection to server localhost/127.0.0.1:16015
>> > 2011-10-18 21:39:41,401 INFO ClientCnxn
>> > [ZooKeeperClientCnxn--SendThread-13319d4a8c3000d] - Socket
>> connection
>> > established to localhost/127.0.0.1:16015, initiating session
>> > 2011-10-18 21:39:41,402 INFO ClientCnxn
>> > [ZooKeeperClientCnxn--SendThread-13319d4a8c3000d] - Unable to
>> > reconnect to ZooKeeper service, session 0x13319d4a8c3000d has expired,
>> > closing socket connection
>> >
>
RE: is there a 40s connection timeout that expires a session?
Posted by Martin Serrano <ma...@attivio.com>.
Patrick,
Thanks. I know about the negotiated timeout and how the maximum is specified. We start up our server so that it allows a greater timeout. In the logs I attached you can see that the negotiated timeout is 600000ms, but I still get the session expired message at 40s.
-Martin
> -----Original Message-----
> From: Patrick Hunt [mailto:phunt@apache.org]
> Sent: Wednesday, October 19, 2011 12:57 PM
> To: user@zookeeper.apache.org
> Subject: Re: is there a 40s connection timeout that expires a session?
>
> The actual session timeout is negotiated btw the client and server, there is
> both a min and a max enforced by the server.
>
> See this section on session details:
> http://zookeeper.apache.org/doc/r3.3.3/zookeeperProgrammers.html#ch_
> zkSessions
> "One of the parameters to the ZooKeeper client library call to create a
> ZooKeeper session is the session timeout in milliseconds. The client sends a
> requested timeout, the server responds with the timeout that it can give the
> client. The current implementation requires that the timeout be a minimum
> of 2 times the tickTime (as set in the server
> configuration) and a maximum of 20 times the tickTime. The ZooKeeper
> client API allows access to the negotiated timeout."
>
> You're seeing the default (20*ticktime, which is typically 2 sec, so 40sec max)
>
> See here: (maxSessionTimeout)
> http://zookeeper.apache.org/doc/r3.3.3/zookeeperAdmin.html#sc_advanc
> edConfiguration
>
>
> btw, setting a 10min timeout will probably cause you problems down the
> road - as things that depend on ephemeral nodes (e.g. leader failover) will
> take too long to be effective. (typically)
>
> Patrick
>
> On Wed, Oct 19, 2011 at 8:48 AM, Martin Serrano <ma...@attivio.com>
> wrote:
> > I'm seeing something a bit weird. In our environment we've upped the
> session timeout to 10 minutes. I see that the client connections successfully
> negotiate the 10 minute timeout. However I've seen a case where the client
> session gets timed out in 40s if it is unable to ever initiate the session. Is
> there a separate timeout somewhere?
> >
> > Thanks,
> > Martin
> >
> > Log excerpts below (unfortunately the server-side logs are not available):
> >
> > 2011-10-18 21:38:59,218 INFO ClientCnxn
> > [ZooKeeperClientCnxn--SendThread()-0] - Opening socket connection to
> > server localhost/0:0:0:0:0:0:0:1:16015
> > 2011-10-18 21:38:59,220 WARN ClientCnxn
> > [ZooKeeperClientCnxn--SendThread(localhost:16015)-0] - Session 0x0 for
> > server null, unexpected error, closing socket connection and
> > attempting reconnect
> > 2011-10-18 21:39:00,181 INFO ClientCnxn
> > [ZooKeeperClientCnxn--SendThread(localhost:16015)-0] - Opening socket
> > connection to server localhost/127.0.0.1:16015
> > 2011-10-18 21:39:00,184 INFO ClientCnxn
> > [ZooKeeperClientCnxn--SendThread(localhost:16015)-0] - Socket
> > connection established to localhost/127.0.0.1:16015, initiating
> > session
> > 2011-10-18 21:39:00,241 INFO ClientCnxn
> > [ZooKeeperClientCnxn--SendThread-13319d4a8c3000c] - Session
> > establishment complete on server localhost/127.0.0.1:16015, sessionid
> > = 0x13319d4a8c3000c, negotiated timeout = 600000
> > 2011-10-18 21:39:00,326 INFO ZooKeeper [main] - Initiating client
> > connection, connectString=localhost:16015 sessionTimeout=600000
> > watcher=com.attivio.global.AieZooKeeper@45490eb5
> > 2011-10-18 21:39:00,329 INFO ClientCnxn
> > [ZooKeeperClientCnxn--SendThread()-0] - Opening socket connection to
> > server localhost/0:0:0:0:0:0:0:1:16015
> > 2011-10-18 21:39:00,329 WARN ClientCnxn
> > [ZooKeeperClientCnxn--SendThread(localhost:16015)-0] - Session 0x0 for
> > server null, unexpected error, closing socket connection and
> > attempting reconnect
> > 2011-10-18 21:39:00,665 INFO ClientCnxn
> > [ZooKeeperClientCnxn--SendThread(localhost:16015)-0] - Opening socket
> > connection to server localhost/127.0.0.1:16015
> > 2011-10-18 21:39:00,666 INFO ClientCnxn
> > [ZooKeeperClientCnxn--SendThread(localhost:16015)-0] - Socket
> > connection established to localhost/127.0.0.1:16015, initiating
> > session
> > 2011-10-18 21:39:00,670 INFO ClientCnxn
> > [ZooKeeperClientCnxn--SendThread-13319d4a8c3000d] - Session
> > establishment complete on server localhost/127.0.0.1:16015, sessionid
> > = 0x13319d4a8c3000d, negotiated timeout = 600000
> > 2011-10-18 21:39:02,125 INFO ClientCnxn
> > [ZooKeeperClientCnxn--SendThread-13319d4a8c3000d] - Unable to read
> > additional data from server sessionid 0x13319d4a8c3000d, likely server
> > has closed socket, closing socket connection and attempting reconnect
> > 2011-10-18 21:39:02,125 INFO ClientCnxn
> > [ZooKeeperClientCnxn--SendThread-13319d4a8c3000c] - Unable to read
> > additional data from server sessionid 0x13319d4a8c3000c, likely server
> > has closed socket, closing socket connection and attempting reconnect
> > 2011-10-18 21:39:02,295 INFO ClientCnxn
> > [ZooKeeperClientCnxn--SendThread-13319d4a8c3000d] - Opening socket
> > connection to server localhost/0:0:0:0:0:0:0:1:16015
> > 2011-10-18 21:39:02,295 WARN ClientCnxn
> > [ZooKeeperClientCnxn--SendThread-13319d4a8c3000d] - Session
> > 0x13319d4a8c3000d for server null, unexpected error, closing socket
> > connection and attempting reconnect
> > 2011-10-18 21:39:02,873 INFO ClientCnxn
> > [ZooKeeperClientCnxn--SendThread-13319d4a8c3000c] - Opening socket
> > connection to server localhost/0:0:0:0:0:0:0:1:16015
> > 2011-10-18 21:39:02,873 WARN ClientCnxn
> > [ZooKeeperClientCnxn--SendThread-13319d4a8c3000c] - Session
> > 0x13319d4a8c3000c for server null, unexpected error, closing socket
> > connection and attempting reconnect
> > 2011-10-18 21:39:03,676 INFO ClientCnxn
> > [ZooKeeperClientCnxn--SendThread-13319d4a8c3000d] - Opening socket
> > connection to server localhost/127.0.0.1:16015
> > 2011-10-18 21:39:03,677 INFO ClientCnxn
> > [ZooKeeperClientCnxn--SendThread-13319d4a8c3000d] - Socket
> connection
> > established to localhost/127.0.0.1:16015, initiating session
> > 2011-10-18 21:39:03,678 WARN ClientCnxn
> > [ZooKeeperClientCnxn--SendThread-13319d4a8c3000d] - Session
> > 0x13319d4a8c3000d for server localhost/127.0.0.1:16015, unexpected
> > error, closing socket connection and attempting reconnect
> > 2011-10-18 21:39:04,027 INFO ClientCnxn
> > [ZooKeeperClientCnxn--SendThread-13319d4a8c3000d] - Opening socket
> > connection to server localhost/0:0:0:0:0:0:0:1:16015
> > 2011-10-18 21:39:04,027 WARN ClientCnxn
> > [ZooKeeperClientCnxn--SendThread-13319d4a8c3000d] - Session
> > 0x13319d4a8c3000d for server null, unexpected error, closing socket
> > connection and attempting reconnect
> > 2011-10-18 21:39:04,416 INFO ClientCnxn
> > [ZooKeeperClientCnxn--SendThread-13319d4a8c3000c] - Opening socket
> > connection to server localhost/127.0.0.1:16015
> > 2011-10-18 21:39:04,417 INFO ClientCnxn
> > [ZooKeeperClientCnxn--SendThread-13319d4a8c3000c] - Socket
> connection
> > established to localhost/127.0.0.1:16015, initiating session
> > 2011-10-18 21:39:04,417 INFO ClientCnxn
> > [ZooKeeperClientCnxn--SendThread-13319d4a8c3000c] - Unable to read
> > additional data from server sessionid 0x13319d4a8c3000c, likely server
> > has closed socket, closing socket connection and attempting reconnect
> > 2011-10-18 21:39:04,705 INFO ClientCnxn
> > [ZooKeeperClientCnxn--SendThread-13319d4a8c3000c] - Opening socket
> > connection to server localhost/0:0:0:0:0:0:0:1:16015
> > 2011-10-18 21:39:04,705 WARN ClientCnxn
> > [ZooKeeperClientCnxn--SendThread-13319d4a8c3000c] - Session
> > 0x13319d4a8c3000c for server null, unexpected error, closing socket
> > connection and attempting reconnect
> > 2011-10-18 21:39:05,447 INFO ClientCnxn
> > [ZooKeeperClientCnxn--SendThread-13319d4a8c3000d] - Opening socket
> > connection to server localhost/127.0.0.1:16015
> > 2011-10-18 21:39:05,448 INFO ClientCnxn
> > [ZooKeeperClientCnxn--SendThread-13319d4a8c3000d] - Socket
> connection
> > established to localhost/127.0.0.1:16015, initiating session
> > 2011-10-18 21:39:05,449 INFO ClientCnxn
> > [ZooKeeperClientCnxn--SendThread-13319d4a8c3000d] - Unable to read
> > additional data from server sessionid 0x13319d4a8c3000d, likely server
> > has closed socket, closing socket connection and attempting reconnect
> >
> > Lots more of those, then:
> >
> > 2011-10-18 21:39:39,387 INFO ClientCnxn
> > [ZooKeeperClientCnxn--SendThread-13319d4a8c3000c] - Opening socket
> > connection to server localhost/127.0.0.1:16015
> > 2011-10-18 21:39:39,388 INFO ClientCnxn
> > [ZooKeeperClientCnxn--SendThread-13319d4a8c3000c] - Socket
> connection
> > established to localhost/127.0.0.1:16015, initiating session
> > 2011-10-18 21:39:39,388 INFO ClientCnxn
> > [ZooKeeperClientCnxn--SendThread-13319d4a8c3000c] - Unable to read
> > additional data from server sessionid 0x13319d4a8c3000c, likely server
> > has closed socket, closing socket connection and attempting reconnect
> > 2011-10-18 21:39:39,592 INFO ClientCnxn
> > [ZooKeeperClientCnxn--SendThread-13319d4a8c3000d] - Opening socket
> > connection to server localhost/0:0:0:0:0:0:0:1:16015
> > 2011-10-18 21:39:39,592 WARN ClientCnxn
> > [ZooKeeperClientCnxn--SendThread-13319d4a8c3000d] - Session
> > 0x13319d4a8c3000d for server null, unexpected error, closing socket
> > connection and attempting reconnect
> > 2011-10-18 21:39:39,735 INFO ClientCnxn
> > [ZooKeeperClientCnxn--SendThread-13319d4a8c3000c] - Opening socket
> > connection to server localhost/0:0:0:0:0:0:0:1:16015
> > 2011-10-18 21:39:39,735 WARN ClientCnxn
> > [ZooKeeperClientCnxn--SendThread-13319d4a8c3000c] - Session
> > 0x13319d4a8c3000c for server null, unexpected error, closing socket
> > connection and attempting reconnect
> > 2011-10-18 21:39:41,400 INFO ClientCnxn
> > [ZooKeeperClientCnxn--SendThread-13319d4a8c3000d] - Opening socket
> > connection to server localhost/127.0.0.1:16015
> > 2011-10-18 21:39:41,401 INFO ClientCnxn
> > [ZooKeeperClientCnxn--SendThread-13319d4a8c3000d] - Socket
> connection
> > established to localhost/127.0.0.1:16015, initiating session
> > 2011-10-18 21:39:41,402 INFO ClientCnxn
> > [ZooKeeperClientCnxn--SendThread-13319d4a8c3000d] - Unable to
> > reconnect to ZooKeeper service, session 0x13319d4a8c3000d has expired,
> > closing socket connection
> >
Re: is there a 40s connection timeout that expires a session?
Posted by Patrick Hunt <ph...@apache.org>.
The actual session timeout is negotiated btw the client and server,
there is both a min and a max enforced by the server.
See this section on session details:
http://zookeeper.apache.org/doc/r3.3.3/zookeeperProgrammers.html#ch_zkSessions
"One of the parameters to the ZooKeeper client library call to create
a ZooKeeper session is the session timeout in milliseconds. The client
sends a requested timeout, the server responds with the timeout that
it can give the client. The current implementation requires that the
timeout be a minimum of 2 times the tickTime (as set in the server
configuration) and a maximum of 20 times the tickTime. The ZooKeeper
client API allows access to the negotiated timeout."
You're seeing the default (20*ticktime, which is typically 2 sec, so 40sec max)
See here: (maxSessionTimeout)
http://zookeeper.apache.org/doc/r3.3.3/zookeeperAdmin.html#sc_advancedConfiguration
btw, setting a 10min timeout will probably cause you problems down the
road - as things that depend on ephemeral nodes (e.g. leader failover)
will take too long to be effective. (typically)
Patrick
On Wed, Oct 19, 2011 at 8:48 AM, Martin Serrano <ma...@attivio.com> wrote:
> I'm seeing something a bit weird. In our environment we've upped the session timeout to 10 minutes. I see that the client connections successfully negotiate the 10 minute timeout. However I've seen a case where the client session gets timed out in 40s if it is unable to ever initiate the session. Is there a separate timeout somewhere?
>
> Thanks,
> Martin
>
> Log excerpts below (unfortunately the server-side logs are not available):
>
> 2011-10-18 21:38:59,218 INFO ClientCnxn [ZooKeeperClientCnxn--SendThread()-0] - Opening socket connection to server localhost/0:0:0:0:0:0:0:1:16015
> 2011-10-18 21:38:59,220 WARN ClientCnxn [ZooKeeperClientCnxn--SendThread(localhost:16015)-0] - Session 0x0 for server null, unexpected error, closing socket connection and attempting reconnect
> 2011-10-18 21:39:00,181 INFO ClientCnxn [ZooKeeperClientCnxn--SendThread(localhost:16015)-0] - Opening socket connection to server localhost/127.0.0.1:16015
> 2011-10-18 21:39:00,184 INFO ClientCnxn [ZooKeeperClientCnxn--SendThread(localhost:16015)-0] - Socket connection established to localhost/127.0.0.1:16015, initiating session
> 2011-10-18 21:39:00,241 INFO ClientCnxn [ZooKeeperClientCnxn--SendThread-13319d4a8c3000c] - Session establishment complete on server localhost/127.0.0.1:16015, sessionid = 0x13319d4a8c3000c, negotiated timeout = 600000
> 2011-10-18 21:39:00,326 INFO ZooKeeper [main] - Initiating client connection, connectString=localhost:16015 sessionTimeout=600000 watcher=com.attivio.global.AieZooKeeper@45490eb5
> 2011-10-18 21:39:00,329 INFO ClientCnxn [ZooKeeperClientCnxn--SendThread()-0] - Opening socket connection to server localhost/0:0:0:0:0:0:0:1:16015
> 2011-10-18 21:39:00,329 WARN ClientCnxn [ZooKeeperClientCnxn--SendThread(localhost:16015)-0] - Session 0x0 for server null, unexpected error, closing socket connection and attempting reconnect
> 2011-10-18 21:39:00,665 INFO ClientCnxn [ZooKeeperClientCnxn--SendThread(localhost:16015)-0] - Opening socket connection to server localhost/127.0.0.1:16015
> 2011-10-18 21:39:00,666 INFO ClientCnxn [ZooKeeperClientCnxn--SendThread(localhost:16015)-0] - Socket connection established to localhost/127.0.0.1:16015, initiating session
> 2011-10-18 21:39:00,670 INFO ClientCnxn [ZooKeeperClientCnxn--SendThread-13319d4a8c3000d] - Session establishment complete on server localhost/127.0.0.1:16015, sessionid = 0x13319d4a8c3000d, negotiated timeout = 600000
> 2011-10-18 21:39:02,125 INFO ClientCnxn [ZooKeeperClientCnxn--SendThread-13319d4a8c3000d] - Unable to read additional data from server sessionid 0x13319d4a8c3000d, likely server has closed socket, closing socket connection and attempting reconnect
> 2011-10-18 21:39:02,125 INFO ClientCnxn [ZooKeeperClientCnxn--SendThread-13319d4a8c3000c] - Unable to read additional data from server sessionid 0x13319d4a8c3000c, likely server has closed socket, closing socket connection and attempting reconnect
> 2011-10-18 21:39:02,295 INFO ClientCnxn [ZooKeeperClientCnxn--SendThread-13319d4a8c3000d] - Opening socket connection to server localhost/0:0:0:0:0:0:0:1:16015
> 2011-10-18 21:39:02,295 WARN ClientCnxn [ZooKeeperClientCnxn--SendThread-13319d4a8c3000d] - Session 0x13319d4a8c3000d for server null, unexpected error, closing socket connection and attempting reconnect
> 2011-10-18 21:39:02,873 INFO ClientCnxn [ZooKeeperClientCnxn--SendThread-13319d4a8c3000c] - Opening socket connection to server localhost/0:0:0:0:0:0:0:1:16015
> 2011-10-18 21:39:02,873 WARN ClientCnxn [ZooKeeperClientCnxn--SendThread-13319d4a8c3000c] - Session 0x13319d4a8c3000c for server null, unexpected error, closing socket connection and attempting reconnect
> 2011-10-18 21:39:03,676 INFO ClientCnxn [ZooKeeperClientCnxn--SendThread-13319d4a8c3000d] - Opening socket connection to server localhost/127.0.0.1:16015
> 2011-10-18 21:39:03,677 INFO ClientCnxn [ZooKeeperClientCnxn--SendThread-13319d4a8c3000d] - Socket connection established to localhost/127.0.0.1:16015, initiating session
> 2011-10-18 21:39:03,678 WARN ClientCnxn [ZooKeeperClientCnxn--SendThread-13319d4a8c3000d] - Session 0x13319d4a8c3000d for server localhost/127.0.0.1:16015, unexpected error, closing socket connection and attempting reconnect
> 2011-10-18 21:39:04,027 INFO ClientCnxn [ZooKeeperClientCnxn--SendThread-13319d4a8c3000d] - Opening socket connection to server localhost/0:0:0:0:0:0:0:1:16015
> 2011-10-18 21:39:04,027 WARN ClientCnxn [ZooKeeperClientCnxn--SendThread-13319d4a8c3000d] - Session 0x13319d4a8c3000d for server null, unexpected error, closing socket connection and attempting reconnect
> 2011-10-18 21:39:04,416 INFO ClientCnxn [ZooKeeperClientCnxn--SendThread-13319d4a8c3000c] - Opening socket connection to server localhost/127.0.0.1:16015
> 2011-10-18 21:39:04,417 INFO ClientCnxn [ZooKeeperClientCnxn--SendThread-13319d4a8c3000c] - Socket connection established to localhost/127.0.0.1:16015, initiating session
> 2011-10-18 21:39:04,417 INFO ClientCnxn [ZooKeeperClientCnxn--SendThread-13319d4a8c3000c] - Unable to read additional data from server sessionid 0x13319d4a8c3000c, likely server has closed socket, closing socket connection and attempting reconnect
> 2011-10-18 21:39:04,705 INFO ClientCnxn [ZooKeeperClientCnxn--SendThread-13319d4a8c3000c] - Opening socket connection to server localhost/0:0:0:0:0:0:0:1:16015
> 2011-10-18 21:39:04,705 WARN ClientCnxn [ZooKeeperClientCnxn--SendThread-13319d4a8c3000c] - Session 0x13319d4a8c3000c for server null, unexpected error, closing socket connection and attempting reconnect
> 2011-10-18 21:39:05,447 INFO ClientCnxn [ZooKeeperClientCnxn--SendThread-13319d4a8c3000d] - Opening socket connection to server localhost/127.0.0.1:16015
> 2011-10-18 21:39:05,448 INFO ClientCnxn [ZooKeeperClientCnxn--SendThread-13319d4a8c3000d] - Socket connection established to localhost/127.0.0.1:16015, initiating session
> 2011-10-18 21:39:05,449 INFO ClientCnxn [ZooKeeperClientCnxn--SendThread-13319d4a8c3000d] - Unable to read additional data from server sessionid 0x13319d4a8c3000d, likely server has closed socket, closing socket connection and attempting reconnect
>
> Lots more of those, then:
>
> 2011-10-18 21:39:39,387 INFO ClientCnxn [ZooKeeperClientCnxn--SendThread-13319d4a8c3000c] - Opening socket connection to server localhost/127.0.0.1:16015
> 2011-10-18 21:39:39,388 INFO ClientCnxn [ZooKeeperClientCnxn--SendThread-13319d4a8c3000c] - Socket connection established to localhost/127.0.0.1:16015, initiating session
> 2011-10-18 21:39:39,388 INFO ClientCnxn [ZooKeeperClientCnxn--SendThread-13319d4a8c3000c] - Unable to read additional data from server sessionid 0x13319d4a8c3000c, likely server has closed socket, closing socket connection and attempting reconnect
> 2011-10-18 21:39:39,592 INFO ClientCnxn [ZooKeeperClientCnxn--SendThread-13319d4a8c3000d] - Opening socket connection to server localhost/0:0:0:0:0:0:0:1:16015
> 2011-10-18 21:39:39,592 WARN ClientCnxn [ZooKeeperClientCnxn--SendThread-13319d4a8c3000d] - Session 0x13319d4a8c3000d for server null, unexpected error, closing socket connection and attempting reconnect
> 2011-10-18 21:39:39,735 INFO ClientCnxn [ZooKeeperClientCnxn--SendThread-13319d4a8c3000c] - Opening socket connection to server localhost/0:0:0:0:0:0:0:1:16015
> 2011-10-18 21:39:39,735 WARN ClientCnxn [ZooKeeperClientCnxn--SendThread-13319d4a8c3000c] - Session 0x13319d4a8c3000c for server null, unexpected error, closing socket connection and attempting reconnect
> 2011-10-18 21:39:41,400 INFO ClientCnxn [ZooKeeperClientCnxn--SendThread-13319d4a8c3000d] - Opening socket connection to server localhost/127.0.0.1:16015
> 2011-10-18 21:39:41,401 INFO ClientCnxn [ZooKeeperClientCnxn--SendThread-13319d4a8c3000d] - Socket connection established to localhost/127.0.0.1:16015, initiating session
> 2011-10-18 21:39:41,402 INFO ClientCnxn [ZooKeeperClientCnxn--SendThread-13319d4a8c3000d] - Unable to reconnect to ZooKeeper service, session 0x13319d4a8c3000d has expired, closing socket connection
>