Deepesh Reja created ZOOKEEPER-2230:
---------------------------------------
Summary: Connections fo ZooKeeper server becomes slow over time
with native GSSAPI
Key: ZOOKEEPER-2230
URL: https://issues.apache.org/jira/browse/ZOOKEEPER-2230
Project: ZooKeeper
Issue Type: Bug
Components: server
Affects Versions: 3.4.6
Environment: OS: RHEL6
Java: 1.8.0_40
Configuration:
java.env:
{quote}
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"
{quote}
jaas-server.conf:
{quote}
Server {
com.sun.security.auth.module.Krb5LoginModule required
useKeyTab=true
isInitiator=false
principal="zookeeper/<hostname>@UNIX.DESHAW.COM";
};
{quote}
Process environment:
{quote}
KRB5_KTNAME=/local/apps/zookeeper-test1/conf/keytab
ZOO_LOG_DIR=/local/apps/zookeeper-test1/log
ZOOCFGDIR=/local/apps/zookeeper-test1/conf
{quote}
Reporter: Deepesh Reja
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:
{noformat}
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
{noformat}
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:
{noformat}
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)
{noformat}
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.
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
