[ https://issues.apache.org/jira/browse/ZOOKEEPER-2230?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15709434#comment-15709434 ]
Yan Fitterer edited comment on ZOOKEEPER-2230 at 11/30/16 7:03 PM: ------------------------------------------------------------------- [~deepeshreja]: sure. See below. I am working on a different patch that should be more compatible though. When using native Kerberos, the subject.doAs() is entirely unnecessary. The required SaslServer can be simply created and returned. The native libs will do the right thing, and find the correct principal from the available tickets (or request one if necessary). Invocation line: {quote} /path/to/jdk_1_8_0_91/bin/java -Dzookeeper.log.dir=/path/to/logfile -Dzookeeper.root.logger=INFO,CONSOLE -cp /path/to/jars:/more/jars: -Dvisualvm.display.name=friendly_name -Xmx4G -XX:+UseG1GC -Dcom.sun.management.jmxremote.port=<jmxport> -Dcom.sun.management.jmxremote.authenticate=false -Dcom.sun.management.jmxremote.rmi.port=<port> -Dcom.sun.management.jmxremote.ssl=false -Dlog4j.configuration=file:/path/to/log4j.properties -Dzookeeper.superUser=user/this.host....@kerb.dom -Dzookeeper.DigestAuthenticationProvider.superDigest=user:<DIGEST>= -Dcom.sun.management.jmxremote -Dcom.sun.management.jmxremote.local.only=false org.apache.zookeeper.server.quorum.QuorumPeerMain /path/to/zoo.cfg {quote} Relevant envvars: {quote} KRB5_KTNAME="/path/to/keytab/file" KRB5_TRACE=/dev/stdout {quote} Jaas config file: {quote} Server \{ com.sun.security.auth.module.Krb5LoginModule required useKeyTab=true storeKey=true isInitiator=false keyTab="/path/to/keytab/file" principal="user/qualifited.hostname.com@KERB_REALM"; \}; Client \{ com.sun.security.auth.module.Krb5LoginModule required useTicketCache=true; \}; {quote} was (Author: fittey): [~deepeshreja]: sure. See below. I am working on a different patch that should be more compatible though. When using native Kerberos, the subject.doAs() is entirely unnecessary. The required SaslServer can be simply created and returned. The native libs will do the right thing, and find the correct principal from the available tickets (or request one if necessary). Invocation line: {quote} /path/to/jdk_1_8_0_91/bin/java -Dzookeeper.log.dir=/path/to/logfile -Dzookeeper.root.logger=INFO,CONSOLE -cp /path/to/jars:/more/jars: -Dvisualvm.display.name=friendly_name -Xmx4G -XX:+UseG1GC -Dcom.sun.management.jmxremote.port=<jmxport> -Dcom.sun.management.jmxremote.authenticate=false -Dcom.sun.management.jmxremote.rmi.port=<port> -Dcom.sun.management.jmxremote.ssl=false -Dlog4j.configuration=file:/path/to/log4j.properties -Dzookeeper.superUser=user/this.host....@kerb.dom -Dzookeeper.DigestAuthenticationProvider.superDigest=user:<DIGEST>= -Dcom.sun.management.jmxremote -Dcom.sun.management.jmxremote.local.only=false org.apache.zookeeper.server.quorum.QuorumPeerMain /path/to/zoo.cfg {quote} Relevant envvars: {quote} KRB5_KTNAME="/path/to/keytab/file" KRB5_TRACE=/dev/stdout {quote} Jaas config file: {quote} Server { com.sun.security.auth.module.Krb5LoginModule required useKeyTab=true storeKey=true isInitiator=false keyTab="/path/to/keytab/file" principal="user/qualifited.hostname.com@KERB_REALM"; }; Client { com.sun.security.auth.module.Krb5LoginModule required useTicketCache=true; }; {quote} > 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)