[
https://issues.apache.org/jira/browse/ZOOKEEPER-2230?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15526214#comment-15526214
]
Deepesh Reja commented on ZOOKEEPER-2230:
-----------------------------------------
Hi [~rgs],
I've figured out the issue and the came up with the attached patch. Can you
please review it and push it further?
Thanks,
Deepesh
> 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, 3.4.7, 3.4.8, 3.5.0
> Environment: OS: RHEL6
> Java: 1.8.0_40
> Configuration:
> java.env:
> {noformat}
> 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"
> {noformat}
> jaas-server.conf:
> {noformat}
> Server {
> com.sun.security.auth.module.Krb5LoginModule required
> useKeyTab=true
> isInitiator=false
> principal="zookeeper/<hostname>@<REALM>";
> };
> {noformat}
> Process environment:
> {noformat}
> KRB5_KTNAME=/local/apps/zookeeper-test1/conf/keytab
> ZOO_LOG_DIR=/local/apps/zookeeper-test1/log
> ZOOCFGDIR=/local/apps/zookeeper-test1/conf
> {noformat}
> Reporter: Deepesh Reja
> Assignee: Enis Soztutar
> Labels: patch
> Fix For: 3.4.6, 3.4.7, 3.4.8, 3.5.2
>
> Attachments: ZOOKEEPER-2230.patch
>
>
> 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)
