[
https://issues.apache.org/jira/browse/ZOOKEEPER-4275?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17317753#comment-17317753
]
Ravi Kishore Valeti commented on ZOOKEEPER-4275:
------------------------------------------------
[~symat]
I was able to reproduce the same on 3.5 branch by inducing a 1 second delay
right before Subject.doAs() in SecurityUtils#createSaslClient() method.
The bug - ZK client starts connection timer much ahead (which includes Sasl
client creation) of sending a connection request to ZK Server and falsely
assuming that it's timing out on ZK server and goes for retries.
Fix: ZK client should start the connection timer right before sending a
connection request to ZK server.
I will provide a patch for this on 3.5 first and then we can port it to
relevant branches.
2021-04-09 12:50:26,264 INFO [main] zookeeper.ClientCnxnSocket -
jute.maxbuffer value is 4194304 Bytes
2021-04-09 12:50:26,272 INFO [main] zookeeper.ClientCnxn -
zookeeper.request.timeout value is 0. feature enabled=
2021-04-09 12:50:26,822 INFO [main-SendThread(xxxxx:2181)] zookeeper.Login -
Client successfully logged in.
2021-04-09 12:50:26,824 INFO [Thread-1] zookeeper.Login - TGT refresh thread
started.
2021-04-09 12:50:26,824 INFO [Thread-1] zookeeper.Login - TGT valid starting
at: xxx Apr xx 12:50:26 IST 2021
2021-04-09 12:50:26,824 INFO [Thread-1] zookeeper.Login - TGT expires:
xxx Apr xx 12:50:26 IST 2021
2021-04-09 12:50:26,824 INFO [Thread-1] zookeeper.Login - TGT refresh sleeping
until: xxx Apr xx 08:15:07 IST 2021
2021-04-09 12:50:26,828 INFO [main-SendThread(xxxxx:2181)]
client.ZooKeeperSaslClient - *Sleeping for 1000*
2021-04-09 12:50:27,835 INFO [main-SendThread(xxxxx:2181)]
client.ZooKeeperSaslClient - Client will use GSSAPI as SASL mechanism.
2021-04-09 12:50:27,845 INFO [main-SendThread(xxxxx:2181)]
zookeeper.ClientCnxn - *Opening socket connection to server* xxxxx/xxxxx:2181.
Will attempt to SASL-authenticate using Login Context section 'Client'
2021-04-09 12:50:27,861 WARN [main-SendThread(xxxxx:2181)]
zookeeper.ClientCnxn - *Client session timed out, have not heard from server in
1589ms* for sessionid 0x0
2021-04-09 12:50:27,861 INFO [main-SendThread(xxxxx:2181)]
zookeeper.ClientCnxn - Client session timed out, have not heard from server in
1589ms for sessionid 0x0, closing socket connection and attempting reconnect
*Falsely times out ZK server and starts getting in to unnecessary continuous
retries*
2021-04-09 12:50:27,972 WARN [Thread-1] zookeeper.Login - TGT renewal thread
has been interrupted and will exit.
2021-04-09 12:50:28,514 INFO [main-SendThread(xxxxx:2181)] zookeeper.Login -
Client successfully logged in.
2021-04-09 12:50:28,514 INFO [Thread-2] zookeeper.Login - TGT refresh thread
started.
2021-04-09 12:50:28,514 INFO [main-SendThread(xxxxx:2181)]
client.ZooKeeperSaslClient - *Sleeping for 1000*
2021-04-09 12:50:28,514 INFO [Thread-2] zookeeper.Login - TGT valid starting
at: xxx Apr xx 12:50:28 IST 2021
2021-04-09 12:50:28,514 INFO [Thread-2] zookeeper.Login - TGT expires:
xxx Apr xx 12:50:28 IST 2021
2021-04-09 12:50:28,515 INFO [Thread-2] zookeeper.Login - TGT refresh sleeping
until: xxx Apr xx 08:39:46 IST 2021
2021-04-09 12:50:29,519 INFO [main-SendThread(xxxxx:2181)]
client.ZooKeeperSaslClient - Client will use GSSAPI as SASL mechanism.
2021-04-09 12:50:29,520 INFO [main-SendThread(xxxxx:2181)]
zookeeper.ClientCnxn - *Opening socket connection to server* xxxxx/xxxxx:2181.
Will attempt to SASL-authenticate using Login Context section 'Client'
2021-04-09 12:50:29,522 WARN [main-SendThread(xxxxx:2181)]
zookeeper.ClientCnxn - *Client session timed out, have not heard from server in
1551ms* for sessionid 0x0
2021-04-09 12:50:29,522 INFO [main-SendThread(xxxxx:2181)]
zookeeper.ClientCnxn - Client session timed out, have not heard from server in
1551ms for sessionid 0x0, closing socket connection and attempting reconnect
> Slowness in sasl login or subject.doAs() causes zk client to falsely assume
> that the server did not respond, closes connection and multiple retries
> ---------------------------------------------------------------------------------------------------------------------------------------------------
>
> Key: ZOOKEEPER-4275
> URL: https://issues.apache.org/jira/browse/ZOOKEEPER-4275
> Project: ZooKeeper
> Issue Type: Bug
> Components: java client
> Affects Versions: 3.5.9
> Reporter: Ravi Kishore Valeti
> Priority: Minor
> Fix For: 3.5.10
>
>
> Zookeeper client does sasl auth (login and subject.doAs())as a preset before
> attempting a connection to server.
> If there is a delay in sasl auth (possibly due to slow Kerberos
> communication), ZK client falsely assumes that the zk server did not respond
> and runs in to unnecessary multiple retries.
> Client configuration:
> "zookeeper.session.timeout" = "3000"
> "zookeeper.recovery.retry" = "1"
> "zookeeper.recovery.retry.intervalmill" = "500"
> This configuration translates to
> connect timeout as 1000ms
> Read Timeout as 2000ms
> Example: There was a 3 second delay in logging in the user as seen from the
> logs below. The connection attempt was made later. However, zk client did not
> wait for server response but logged a timeout (3 seconds > 1 sec connect
> timeout), closed the connection and went to retries. Since there was a
> consistent delay at Kerberos master, we had seen this retries go as long as
> 10 mins causing requests to timeout/fail.
> Logs:
> 3/23/21 4:15:*32.389* AM jute.maxbuffer value is xxxxx Bytes
> 3/23/21 4:15:*35.395* AM Client successfully logged in.
> 3/23/21 4:15:35.396 AM TGT refresh sleeping until: Wed Mar 24 00:34:31 GMT
> 2021
> 3/23/21 4:15:35.396 AM TGT refresh thread started.
> 3/23/21 4:15:35.396 AM Client will use GSSAPI as SASL mechanism.
> 3/23/21 4:15:35.396 AM TGT expires: xxx Mar xx 04:15:35 GMT
> 2021
> 3/23/21 4:15:35.396 AM TGT valid starting at: xxx Mar xx 04:15:35 GMT
> 2021
> 3/23/21 4:15:*35.397* AM *Opening socket connection* to server xxxxx:2181.
> Will attempt to SASL-authenticate using Login Context section 'Client'
> 3/23/21 4:15:*35.397* AM *Client session timed out, have not heard from
> server in* *3008ms* for sessionid 0x0
> 3/23/21 4:15:35.397 AM Client session timed out, have not heard from server
> in 3008ms for sessionid 0x0, closing socket connection and attempting
> reconnect
> 3/23/21 4:15:35.498 AM TGT renewal thread has been interrupted and will exit.
> 3/23/21 4:15:38.503 AM Client successfully logged in.
> 3/23/21 4:15:38.503 AM TGT expires: xxx Mar xx 04:15:38 GMT
> 2021
> 3/23/21 4:15:38.503 AM Client will use GSSAPI as SASL mechanism.
> 3/23/21 4:15:38.503 AM TGT valid starting at: xxx Mar xx 04:15:38 GMT
> 2021
> 3/23/21 4:15:38.503 AM TGT refresh thread started.
> 3/23/21 4:15:38.503 AM TGT refresh sleeping until: Wed Mar 24 00:10:10 GMT
> 2021
> 3/23/21 4:15:38.506 AM Opening socket connection to server xxxxx:2181. Will
> attempt to SASL-authenticate using Login Context section 'Client'
> 3/23/21 4:15:38.506 AM Client session timed out, have not heard from server
> in 3009ms for sessionid 0x0, closing socket connection and attempting
> reconnect
> 3/23/21 4:15:38.506 AM Client session timed out, have not heard from server
> in 3009ms for sessionid 0x0
> 3/23/21 4:15:38.606 AM TGT renewal thread has been interrupted and will exit.
> 3/23/21 4:15:41.610 AM Client successfully logged in.
> 3/23/21 4:15:41.611 AM TGT refresh sleeping until: xxx Mar xx 23:42:03 GMT
> 2021
> 3/23/21 4:15:41.611 AM Client will use GSSAPI as SASL mechanism.
> 3/23/21 4:15:41.611 AM TGT valid starting at: xxx Mar xx 04:15:41 GMT
> 2021
> 3/23/21 4:15:41.611 AM TGT expires: xxx Mar xx 04:15:41 GMT
> 2021
> 3/23/21 4:15:41.611 AM TGT refresh thread started.
> 3/23/21 4:15:41.612 AM Opening socket connection to server xxxxx:2181. Will
> attempt to SASL-authenticate using Login Context section 'Client'
> 3/23/21 4:15:41.613 AM Client session timed out, have not heard from server
> in 3006ms for sessionid 0x0
> 3/23/21 4:15:41.613 AM Client session timed out, have not heard from server
> in 3006ms for sessionid 0x0, closing socket connection and attempting
> reconnect
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
