[ZOOKEEPER-2230] Connections fo ZooKeeper server becomes slow over time with native GSSAPI

• Type: Bug
• Status: Patch Available
• Priority: Major
• Resolution: Unresolved
• Affects Version/s: 3.4.6, 3.4.7, 3.4.8, 3.5.0
• Fix Version/s: 3.4.6, 3.4.7, 3.4.8, 3.5.2
• Component/s: server
• Labels: patch pull-request-available

Environment

OS: RHEL6
Java: 1.8.0_40
Configuration:

java.env:

SERVER_JVMFLAGS="$SERVER_JVMFLAGS -Xmx5120m"
SERVER_JVMFLAGS="$SERVER_JVMFLAGS -Djava.security.auth.login.config=/local/apps/zookeeper-test1/conf/jaas-server.conf"
SERVER_JVMFLAGS="$SERVER_JVMFLAGS -Dsun.security.jgss.native=true"

jaas-server.conf:

Server {
    com.sun.security.auth.module.Krb5LoginModule required
    useKeyTab=true
    isInitiator=false
    principal="zookeeper/<hostname>@<REALM>";
};

Process environment:

KRB5_KTNAME=/local/apps/zookeeper-test1/conf/keytab
ZOO_LOG_DIR=/local/apps/zookeeper-test1/log
ZOOCFGDIR=/local/apps/zookeeper-test1/conf

• Release Note: Fix slowness in connections when setup with native GSSAPI.
• Tags: kerberos, native-gssapi
• Assignee: Enis Soztutar
• Reporter: Deepesh Reja
• Created: 02/Jul/15 06:13
• Updated: 04/Oct/23 21:06

Description

ZooKeeper server becomes slow over time when native GSSAPI is used. The connection to the server starts taking upto 10 seconds.
This is happening with ZooKeeper-3.4.6 and is fairly reproducible.

Debug logs:

2015-07-02 00:58:49,318 [myid:] - INFO  [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:42405:NIOServerCnxnFactory@197] - Accepted socket connection from /<client_ip>:47942
2015-07-02 00:58:49,318 [myid:] - DEBUG [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:42405:ZooKeeperSaslServer@78] - serviceHostname is '<zookeeper-server>'
2015-07-02 00:58:49,318 [myid:] - DEBUG [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:42405:ZooKeeperSaslServer@79] - servicePrincipalName is 'zookeeper'
2015-07-02 00:58:49,318 [myid:] - DEBUG [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:42405:ZooKeeperSaslServer@80] - SASL mechanism(mech) is 'GSSAPI'
2015-07-02 00:58:49,324 [myid:] - DEBUG [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:42405:ZooKeeperSaslServer@106] - Added private credential to subject: [GSSCredential: 
zookeeper@<zookeeper-server> 1.2.840.113554.1.2.2 Accept [class sun.security.jgss.wrapper.GSSCredElement]]
2015-07-02 00:58:59,441 [myid:] - DEBUG [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:42405:ZooKeeperServer@810] - Session establishment request from client /<client_ip>:47942 client's lastZxid is 0x0
2015-07-02 00:58:59,441 [myid:] - INFO  [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:42405:ZooKeeperServer@868] - Client attempting to establish new session at /<client_ip>:47942
2015-07-02 00:58:59,448 [myid:] - DEBUG [SyncThread:0:FinalRequestProcessor@88] - Processing request:: sessionid:0x14e486028785c81 type:createSession cxid:0x0 zxid:0x110e79 txntype:-10 reqpath:n/a
2015-07-02 00:58:59,448 [myid:] - DEBUG [SyncThread:0:FinalRequestProcessor@160] - sessionid:0x14e486028785c81 type:createSession cxid:0x0 zxid:0x110e79 txntype:-10 reqpath:n/a
2015-07-02 00:58:59,448 [myid:] - INFO  [SyncThread:0:ZooKeeperServer@617] - Established session 0x14e486028785c81 with negotiated timeout 10000 for client /<client_ip>:47942
2015-07-02 00:58:59,452 [myid:] - DEBUG [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:42405:ZooKeeperServer@949] - Responding to client SASL token.
2015-07-02 00:58:59,452 [myid:] - DEBUG [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:42405:ZooKeeperServer@953] - Size of client SASL token: 706
2015-07-02 00:58:59,460 [myid:] - DEBUG [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:42405:ZooKeeperServer@984] - Size of server SASL response: 161
2015-07-02 00:58:59,462 [myid:] - DEBUG [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:42405:ZooKeeperServer@949] - Responding to client SASL token.
2015-07-02 00:58:59,462 [myid:] - DEBUG [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:42405:ZooKeeperServer@953] - Size of client SASL token: 0
2015-07-02 00:58:59,462 [myid:] - DEBUG [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:42405:ZooKeeperServer@984] - Size of server SASL response: 32
2015-07-02 00:58:59,463 [myid:] - DEBUG [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:42405:ZooKeeperServer@949] - Responding to client SASL token.
2015-07-02 00:58:59,463 [myid:] - DEBUG [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:42405:ZooKeeperServer@953] - Size of client SASL token: 32
2015-07-02 00:58:59,464 [myid:] - INFO  [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:42405:SaslServerCallbackHandler@118] - Successfully authenticated client: authenticationID=<user_principal>;  authorizationID=<user_principal>.
2015-07-02 00:58:59,464 [myid:] - INFO  [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:42405:ZooKeeperServer@964] - adding SASL authorization for authorizationID: <user_principal>
2015-07-02 00:58:59,465 [myid:] - INFO  [ProcessThread(sid:0 cport:-1)::PrepRequestProcessor@494] - Processed session termination for sessionid: 0x14e486028785c81
2015-07-02 00:58:59,467 [myid:] - DEBUG [SyncThread:0:FinalRequestProcessor@88] - Processing request:: sessionid:0x14e486028785c81 type:closeSession cxid:0x1 zxid:0x110e7a txntype:-11 reqpath:n/a
2015-07-02 00:58:59,467 [myid:] - DEBUG [SyncThread:0:FinalRequestProcessor@160] - sessionid:0x14e486028785c81 type:closeSession cxid:0x1 zxid:0x110e7a txntype:-11 reqpath:n/a
2015-07-02 00:58:59,467 [myid:] - INFO  [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:42405:NIOServerCnxn@1007] - Closed socket connection for client /<client_ip>:47942 which had sessionid 0x14e486028785c81

If you see, after adding the credentials to privateCredential set, it takes roughly 10 seconds to reach to session establishment request. From the code it looks like Subject.doAs() is taking a lot of time.

I connected it to jdb while it was waiting and got following stacktrace:

NIOServerCxn.Factory:0.0.0.0/0.0.0.0:58909:
  [1] java.util.HashMap$TreeNode.find (HashMap.java:1,865)
  [2] java.util.HashMap$TreeNode.find (HashMap.java:1,861)
  [3] java.util.HashMap$TreeNode.find (HashMap.java:1,861)
  [4] java.util.HashMap$TreeNode.find (HashMap.java:1,861)
  [5] java.util.HashMap$TreeNode.find (HashMap.java:1,861)
  [6] java.util.HashMap$TreeNode.find (HashMap.java:1,861)
  [7] java.util.HashMap$TreeNode.find (HashMap.java:1,861)
  [8] java.util.HashMap$TreeNode.putTreeVal (HashMap.java:1,981)
  [9] java.util.HashMap.putVal (HashMap.java:637)
  [10] java.util.HashMap.put (HashMap.java:611)
  [11] java.util.HashSet.add (HashSet.java:219)
  [12] javax.security.auth.Subject$ClassSet.populateSet (Subject.java:1,418)
  [13] javax.security.auth.Subject$ClassSet.<init> (Subject.java:1,372)
  [14] javax.security.auth.Subject.getPrivateCredentials (Subject.java:767)
  [15] sun.security.jgss.GSSUtil$1.run (GSSUtil.java:340)
  [16] sun.security.jgss.GSSUtil$1.run (GSSUtil.java:332)
  [17] java.security.AccessController.doPrivileged (native method)
  [18] sun.security.jgss.GSSUtil.searchSubject (GSSUtil.java:332)
  [19] sun.security.jgss.wrapper.NativeGSSFactory.getCredFromSubject (NativeGSSFactory.java:53)
  [20] sun.security.jgss.wrapper.NativeGSSFactory.getCredentialElement (NativeGSSFactory.java:116)
  [21] sun.security.jgss.GSSManagerImpl.getCredentialElement (GSSManagerImpl.java:193)
  [22] sun.security.jgss.GSSCredentialImpl.add (GSSCredentialImpl.java:427)
  [23] sun.security.jgss.GSSCredentialImpl.<init> (GSSCredentialImpl.java:62)
  [24] sun.security.jgss.GSSManagerImpl.createCredential (GSSManagerImpl.java:154)
  [25] com.sun.security.sasl.gsskerb.GssKrb5Server.<init> (GssKrb5Server.java:108)
  [26] com.sun.security.sasl.gsskerb.FactoryImpl.createSaslServer (FactoryImpl.java:85)
  [27] javax.security.sasl.Sasl.createSaslServer (Sasl.java:524)
  [28] org.apache.zookeeper.server.ZooKeeperSaslServer$1.run (ZooKeeperSaslServer.java:118)
  [29] org.apache.zookeeper.server.ZooKeeperSaslServer$1.run (ZooKeeperSaslServer.java:114)
  [30] java.security.AccessController.doPrivileged (native method)
  [31] javax.security.auth.Subject.doAs (Subject.java:422)
  [32] org.apache.zookeeper.server.ZooKeeperSaslServer.createSaslServer (ZooKeeperSaslServer.java:114)
  [33] org.apache.zookeeper.server.ZooKeeperSaslServer.<init> (ZooKeeperSaslServer.java:48)
  [34] org.apache.zookeeper.server.NIOServerCnxn.<init> (NIOServerCnxn.java:100)
  [35] org.apache.zookeeper.server.NIOServerCnxnFactory.createConnection (NIOServerCnxnFactory.java:161)
  [36] org.apache.zookeeper.server.NIOServerCnxnFactory.run (NIOServerCnxnFactory.java:202)
  [37] java.lang.Thread.run (Thread.java:745)

This doesn't happen when we use JGSS, I think because adding credential to privateCredential set for every connection is causing Subject.doAS() to take much longer time.

Issue Links

• is cloned by: ZOOKEEPER-2670 CLONE - Connections fo ZooKeeper server becomes slow over time with native GSSAPI
• links to: GitHub Pull Request #166
• links to: GitHub Pull Request #166
• links to: GitHub Pull Request #1117