[jira] [Commented] (ZOOKEEPER-2230) Connections fo ZooKeeper server becomes slow over time with native GSSAPI
[ https://issues.apache.org/jira/browse/ZOOKEEPER-2230?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15751226#comment-15751226 ] Deepesh Reja commented on ZOOKEEPER-2230: - [~fittey] I think you are seeing different behavior because of setting "storeKey" to true which adds principal's key in the Subject's private credentials set. Due to this, there is always an entry in the set. I'll see if I can come up with something so that this also work when "storeKey" is set to True. Also, please let me know if you have something or need help on the patch you are working on. > 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/@"; > }; > {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 /: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 '' > 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@ 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 /: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 /: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 1 for > client /: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/
[jira] [Commented] (ZOOKEEPER-2230) Connections fo ZooKeeper server becomes slow over time with native GSSAPI
[ https://issues.apache.org/jira/browse/ZOOKEEPER-2230?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15707509#comment-15707509 ] Deepesh Reja commented on ZOOKEEPER-2230: - [~fittey] Can you provide us your zookeeper configurations like jaas.conf, Java properties set while starting ZooKeeper, etc.? I'll try to reproduce it in my environment and see if I can come to a conclusion. > 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/@"; > }; > {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 /: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 '' > 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@ 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 /: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 /: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 1 for > client /: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
[jira] [Commented] (ZOOKEEPER-2230) Connections fo ZooKeeper server becomes slow over time with native GSSAPI
[ https://issues.apache.org/jira/browse/ZOOKEEPER-2230?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15692157#comment-15692157 ] Deepesh Reja commented on ZOOKEEPER-2230: - I am not sure why the first credential in Private Credentials set is keytab file name. We are running proposed patch in Production and we are not seeing any issues. > 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/@"; > }; > {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 /: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 '' > 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@ 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 /: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 /: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 1 for > client /: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:
[jira] [Commented] (ZOOKEEPER-2230) Connections fo ZooKeeper server becomes slow over time with native GSSAPI
[ https://issues.apache.org/jira/browse/ZOOKEEPER-2230?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15608199#comment-15608199 ] Deepesh Reja commented on ZOOKEEPER-2230: - Hi [~ekoontz]/[~mahadev], >From ZOOKEEPER-938, I feel that you might be interested in this patch. Can you >please review and merge this? 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/@"; > }; > {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 /: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 '' > 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@ 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 /: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 /: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 1 for > client /: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 [m
[jira] [Commented] (ZOOKEEPER-2230) Connections fo ZooKeeper server becomes slow over time with native GSSAPI
[ https://issues.apache.org/jira/browse/ZOOKEEPER-2230?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15562377#comment-15562377 ] Deepesh Reja commented on ZOOKEEPER-2230: - Hi [~rgs], Can you please review the patch and merge it? > 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/@"; > }; > {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 /: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 '' > 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@ 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 /: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 /: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 1 for > client /: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] - > Suc
[jira] [Commented] (ZOOKEEPER-2230) Connections fo ZooKeeper server becomes slow over time with native GSSAPI
[ https://issues.apache.org/jira/browse/ZOOKEEPER-2230?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15526223#comment-15526223 ] Deepesh Reja commented on ZOOKEEPER-2230: - >> -1 tests included. The patch doesn't appear to include any new or modified >> tests. I don't think this needs a new tests because it doesn't really include a new function/class or change a lot in the function. > 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/@"; > }; > {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 /: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 '' > 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@ 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 /: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 /: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 1 for > client /: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
[jira] [Commented] (ZOOKEEPER-2230) Connections fo ZooKeeper server becomes slow over time with native GSSAPI
[ 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/@"; > }; > {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 /: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 '' > 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@ 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 /: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 /: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 1 for > client /: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
[jira] [Updated] (ZOOKEEPER-2230) Connections fo ZooKeeper server becomes slow over time with native GSSAPI
[ https://issues.apache.org/jira/browse/ZOOKEEPER-2230?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ] Deepesh Reja updated ZOOKEEPER-2230: Attachment: ZOOKEEPER-2230.patch > 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/@"; > }; > {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 /: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 '' > 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@ 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 /: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 /: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 1 for > client /: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=; > authorizationID=. > 2015
[jira] [Issue Comment Deleted] (ZOOKEEPER-2230) Connections fo ZooKeeper server becomes slow over time with native GSSAPI
[ https://issues.apache.org/jira/browse/ZOOKEEPER-2230?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ] Deepesh Reja updated ZOOKEEPER-2230: Comment: was deleted (was: For every connection to the server, a new ZooKeeperSaslServer is instantiated and when we use native GSSAPI, the credentials are added to the subject's private credential set. These credentials are nothing but credentials of server principal and for every connection it remains the same because servicePrincipalName and serviceHostName doesn't change. The private credential set allows addition of same object to the set because equals() method of GSSCredential doesn't adhere to the RFC and returns False unless both objects are same. The patch checks if there is no credential in the private credential set, the credential is added to the set otherwise not. References: http://grepcode.com/file/repository.grepcode.com/java/root/jdk/openjdk/8u40-b25/sun/security/jgss/GSSCredentialImpl.java#GSSCredentialImpl.equals%28java.lang.Object%29 http://stackoverflow.com/questions/10285421/java-gssapi-compare-two-gsscredential-instances ) > 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 > 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/@"; > }; > {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 > > > 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 /: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 '' > 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@ 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 /: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 /: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 1 for > client /: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.Fa
[jira] [Updated] (ZOOKEEPER-2230) Connections fo ZooKeeper server becomes slow over time with native GSSAPI
[ https://issues.apache.org/jira/browse/ZOOKEEPER-2230?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ] Deepesh Reja updated ZOOKEEPER-2230: Release Note: (was: Add credential to private credential set only once) > 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 > 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/@"; > }; > {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 > > > 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 /: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 '' > 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@ 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 /: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 /: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 1 for > client /: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=; > authorizationID=. > 2015-07-02 00:58:59,464
[jira] [Updated] (ZOOKEEPER-2230) Connections fo ZooKeeper server becomes slow over time with native GSSAPI
[ https://issues.apache.org/jira/browse/ZOOKEEPER-2230?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ] Deepesh Reja updated ZOOKEEPER-2230: 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/@"; }; {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} was: 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/@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} > 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: > {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/@"; > }; > {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 > > 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 /: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 '' > 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@ 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 /: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 /: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 1 for > client /: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:ZooKee
[jira] [Created] (ZOOKEEPER-2230) Connections fo ZooKeeper server becomes slow over time with native GSSAPI
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/@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 /: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 '' 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@ 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 /: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 /: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 1 for client /: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=; authorizationID=. 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: 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]