[ https://issues.apache.org/jira/browse/ZOOKEEPER-2230?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16950698#comment-16950698 ]
Brian Nixon commented on ZOOKEEPER-2230: ---------------------------------------- [~rajsura], I cloned the patch so it is applied against the 3.5 branch so you can test. See [https://github.com/apache/zookeeper/pull/1117] . > 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 > Priority: Major > Labels: patch, pull-request-available > Fix For: 3.4.6, 3.4.7, 3.4.8, 3.5.2 > > Attachments: ZOOKEEPER-2230.patch > > Time Spent: 0.5h > Remaining Estimate: 0h > > 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 (v8.3.4#803005)