zookeeper-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Yan Fitterer (JIRA)" <j...@apache.org>
Subject [jira] [Commented] (ZOOKEEPER-2230) Connections fo ZooKeeper server becomes slow over time with native GSSAPI
Date Wed, 23 Nov 2016 15:38:59 GMT

    [ https://issues.apache.org/jira/browse/ZOOKEEPER-2230?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15690439#comment-15690439
] 

Yan Fitterer commented on ZOOKEEPER-2230:
-----------------------------------------

 I have hit this issue too, but the proposed patch did not work (caused the server to fail
to authenticate all connections). The reason is that in my case, upon instantiation of the
subject, it gets an initial (invalid, I believe) entry in the Private Credentials list that
stringifies to:

/path/to/keytab/file for username/host.name@DOMAIN.COM

so the isEmpty() check never evaluates to true. I had to allow it to add one additional cred
(which looks like this in the logs):

 [GSSCredential: \nusername@host.name.com 1.2.840.113554.1.2.2 Accept [class sun.security.jgss.wrapper.GSSCredElement]]

It then works a charm.

> 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)

Mime
View raw message