[
https://issues.apache.org/jira/browse/KAFKA-3102?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15098512#comment-15098512
]
Mohit Anchlia edited comment on KAFKA-3102 at 1/15/16 9:11 PM:
---------------------------------------------------------------
I enabled debug and still not much info:
Forwardable Ticket true
Forwarded Ticket false
Proxiable Ticket false
Proxy Ticket false
Postdated Ticket false
Renewable Ticket false
Initial Ticket false
Auth Time = Thu Jan 14 19:44:43 EST 2016
Start Time = Thu Jan 14 19:44:43 EST 2016
End Time = Fri Jan 15 19:44:43 EST 2016
Renew Till = null
Client Addresses Null . (org.apache.zookeeper.Login)
[2016-01-14 19:44:28,212] INFO TGT valid starting at: Thu Jan 14
19:44:43 EST 2016 (org.apache.zookeeper.Login)
[2016-01-14 19:44:28,212] INFO TGT expires: Fri Jan 15
19:44:43 EST 2016 (org.apache.zookeeper.Login)
[2016-01-14 19:44:28,213] INFO TGT refresh sleeping until: Fri Jan 15 15:53:07
EST 2016 (org.apache.zookeeper.Login)
[2016-01-14 19:44:28,223] INFO Opening socket connection to server
localhost/127.0.0.1:2181. Will attempt to SASL-authenticate using Login Context
section 'Client' (org.apache.zookeeper.ClientCnxn)
[2016-01-14 19:44:28,231] INFO Socket connection established to
localhost/127.0.0.1:2181, initiating session (org.apache.zookeeper.ClientCnxn)
[2016-01-14 19:44:28,232] INFO Accepted socket connection from /127.0.0.1:53042
(org.apache.zookeeper.server.NIOServerCnxnFactory)
[2016-01-14 19:44:28,233] DEBUG Session establishment request sent on
localhost/127.0.0.1:2181 (org.apache.zookeeper.ClientCnxn)
[2016-01-14 19:44:28,242] DEBUG Session establishment request from client
/127.0.0.1:53042 client's lastZxid is 0x0
(org.apache.zookeeper.server.ZooKeeperServer)
[2016-01-14 19:44:28,244] INFO Client attempting to establish new session at
/127.0.0.1:53042 (org.apache.zookeeper.server.ZooKeeperServer)
[2016-01-14 19:44:28,248] INFO Creating new log file: log.1
(org.apache.zookeeper.server.persistence.FileTxnLog)
[2016-01-14 19:44:28,255] DEBUG Processing request::
sessionid:0x15242bd63420000 type:createSession cxid:0x0 zxid:0x1 txntype:-10
reqpath:n/a (org.apache.zookeeper.server.FinalRequestProcessor)
[2016-01-14 19:44:28,261] DEBUG sessionid:0x15242bd63420000 type:createSession
cxid:0x0 zxid:0x1 txntype:-10 reqpath:n/a
(org.apache.zookeeper.server.FinalRequestProcessor)
[2016-01-14 19:44:28,267] INFO Established session 0x15242bd63420000 with
negotiated timeout 6000 for client /127.0.0.1:53042
(org.apache.zookeeper.server.ZooKeeperServer)
[2016-01-14 19:44:28,270] INFO Session establishment complete on server
localhost/127.0.0.1:2181, sessionid = 0x15242bd63420000, negotiated timeout =
6000 (org.apache.zookeeper.ClientCnxn)
[2016-01-14 19:44:28,272] DEBUG ClientCnxn:sendSaslPacket:length=0
(org.apache.zookeeper.client.ZooKeeperSaslClient)
[2016-01-14 19:44:28,273] DEBUG Received event: WatchedEvent
state:SyncConnected type:None path:null (org.I0Itec.zkclient.ZkClient)
[2016-01-14 19:44:28,273] INFO zookeeper state changed (SyncConnected)
(org.I0Itec.zkclient.ZkClient)
[2016-01-14 19:44:28,273] DEBUG Leaving process event
(org.I0Itec.zkclient.ZkClient)
[2016-01-14 19:44:28,274] DEBUG saslClient.evaluateChallenge(len=0)
(org.apache.zookeeper.client.ZooKeeperSaslClient)
[2016-01-14 19:44:28,301] DEBUG Responding to client SASL token.
(org.apache.zookeeper.server.ZooKeeperServer)
[2016-01-14 19:44:28,302] DEBUG Size of client SASL token: 611
(org.apache.zookeeper.server.ZooKeeperServer)
[2016-01-14 19:44:28,302] ERROR cnxn.saslServer is null: cnxn object did not
initialize its saslServer properly.
(org.apache.zookeeper.server.ZooKeeperServer)
[2016-01-14 19:44:28,304] ERROR SASL authentication failed using login context
'Client'. (org.apache.zookeeper.client.ZooKeeperSaslClient)
---
kerberos server seems to show a successful exchange of the ticket:
Jan 15 15:39:44 ip-10-241-251-175.us-west-2.compute.internal
krb5kdc[9767](info): AS_REQ (6 etypes {18 17 16 23 1 3}) 10.241.251.217: ISSUE:
authtime 1452890384, etypes {rep=18 tkt=18 ses=18},
kafka/10.241.251....@example.com for krbtgt/example....@example.com
Jan 15 15:39:44 ip-10-241-251-175.us-west-2.compute.internal
krb5kdc[9767](info): TGS_REQ (6 etypes {18 17 16 23 1 3}) 10.241.251.217:
ISSUE: authtime 1452890384, etypes {rep=18 tkt=18 ses=18},
kafka/10.241.251....@example.com for zookeeper/localh...@example.com
was (Author: mohitanchlia):
I enabled debug and still not much info:
Forwardable Ticket true
Forwarded Ticket false
Proxiable Ticket false
Proxy Ticket false
Postdated Ticket false
Renewable Ticket false
Initial Ticket false
Auth Time = Thu Jan 14 19:44:43 EST 2016
Start Time = Thu Jan 14 19:44:43 EST 2016
End Time = Fri Jan 15 19:44:43 EST 2016
Renew Till = null
Client Addresses Null . (org.apache.zookeeper.Login)
[2016-01-14 19:44:28,212] INFO TGT valid starting at: Thu Jan 14
19:44:43 EST 2016 (org.apache.zookeeper.Login)
[2016-01-14 19:44:28,212] INFO TGT expires: Fri Jan 15
19:44:43 EST 2016 (org.apache.zookeeper.Login)
[2016-01-14 19:44:28,213] INFO TGT refresh sleeping until: Fri Jan 15 15:53:07
EST 2016 (org.apache.zookeeper.Login)
[2016-01-14 19:44:28,223] INFO Opening socket connection to server
localhost/127.0.0.1:2181. Will attempt to SASL-authenticate using Login Context
section 'Client' (org.apache.zookeeper.ClientCnxn)
[2016-01-14 19:44:28,231] INFO Socket connection established to
localhost/127.0.0.1:2181, initiating session (org.apache.zookeeper.ClientCnxn)
[2016-01-14 19:44:28,232] INFO Accepted socket connection from /127.0.0.1:53042
(org.apache.zookeeper.server.NIOServerCnxnFactory)
[2016-01-14 19:44:28,233] DEBUG Session establishment request sent on
localhost/127.0.0.1:2181 (org.apache.zookeeper.ClientCnxn)
[2016-01-14 19:44:28,242] DEBUG Session establishment request from client
/127.0.0.1:53042 client's lastZxid is 0x0
(org.apache.zookeeper.server.ZooKeeperServer)
[2016-01-14 19:44:28,244] INFO Client attempting to establish new session at
/127.0.0.1:53042 (org.apache.zookeeper.server.ZooKeeperServer)
[2016-01-14 19:44:28,248] INFO Creating new log file: log.1
(org.apache.zookeeper.server.persistence.FileTxnLog)
[2016-01-14 19:44:28,255] DEBUG Processing request::
sessionid:0x15242bd63420000 type:createSession cxid:0x0 zxid:0x1 txntype:-10
reqpath:n/a (org.apache.zookeeper.server.FinalRequestProcessor)
[2016-01-14 19:44:28,261] DEBUG sessionid:0x15242bd63420000 type:createSession
cxid:0x0 zxid:0x1 txntype:-10 reqpath:n/a
(org.apache.zookeeper.server.FinalRequestProcessor)
[2016-01-14 19:44:28,267] INFO Established session 0x15242bd63420000 with
negotiated timeout 6000 for client /127.0.0.1:53042
(org.apache.zookeeper.server.ZooKeeperServer)
[2016-01-14 19:44:28,270] INFO Session establishment complete on server
localhost/127.0.0.1:2181, sessionid = 0x15242bd63420000, negotiated timeout =
6000 (org.apache.zookeeper.ClientCnxn)
[2016-01-14 19:44:28,272] DEBUG ClientCnxn:sendSaslPacket:length=0
(org.apache.zookeeper.client.ZooKeeperSaslClient)
[2016-01-14 19:44:28,273] DEBUG Received event: WatchedEvent
state:SyncConnected type:None path:null (org.I0Itec.zkclient.ZkClient)
[2016-01-14 19:44:28,273] INFO zookeeper state changed (SyncConnected)
(org.I0Itec.zkclient.ZkClient)
[2016-01-14 19:44:28,273] DEBUG Leaving process event
(org.I0Itec.zkclient.ZkClient)
[2016-01-14 19:44:28,274] DEBUG saslClient.evaluateChallenge(len=0)
(org.apache.zookeeper.client.ZooKeeperSaslClient)
[2016-01-14 19:44:28,301] DEBUG Responding to client SASL token.
(org.apache.zookeeper.server.ZooKeeperServer)
[2016-01-14 19:44:28,302] DEBUG Size of client SASL token: 611
(org.apache.zookeeper.server.ZooKeeperServer)
[2016-01-14 19:44:28,302] ERROR cnxn.saslServer is null: cnxn object did not
initialize its saslServer properly.
(org.apache.zookeeper.server.ZooKeeperServer)
[2016-01-14 19:44:28,304] ERROR SASL authentication failed using login context
'Client'. (org.apache.zookeeper.client.ZooKeeperSaslClient)
> Kafka server unable to connect to zookeeper
> -------------------------------------------
>
> Key: KAFKA-3102
> URL: https://issues.apache.org/jira/browse/KAFKA-3102
> Project: Kafka
> Issue Type: Bug
> Components: security
> Environment: RHEL 6
> Reporter: Mohit Anchlia
>
> Server disconnects from the zookeeper with the following log, and logs are
> not indicative of any problem. It works without the security setup however.
> I followed the security configuration steps from this site:
> http://docs.confluent.io/2.0.0/kafka/sasl.html
> In here find the list of principals, logs and Jaas file:
> 1) Jaas file
> KafkaServer {
> com.sun.security.auth.module.Krb5LoginModule required
> useKeyTab=true
> storeKey=true
> keyTab="/mnt/kafka/kafka/kafka.keytab"
> principal="kafka/10.24.251....@example.com";
> };
> Client {
> com.sun.security.auth.module.Krb5LoginModule required
> useKeyTab=true
> storeKey=true
> keyTab="/mnt/kafka/kafka/kafka.keytab"
> principal="kafka/10.24.251....@example.com";
> };
> 2) Principles from krb admin
> kadmin.local: list_principals
> K/m...@example.com
> kadmin/ad...@example.com
> kadmin/chang...@example.com
> kadmin/ip-10-24-251-175.us-west-2.compute.inter...@example.com
> kafka/10.24.251....@example.com
> krbtgt/example....@example.com
> [2016-01-13 16:26:00,551] INFO starting (kafka.server.KafkaServer)
> [2016-01-13 16:26:00,557] INFO Connecting to zookeeper on localhost:2181
> (kafka.server.KafkaServer)
> [2016-01-13 16:27:30,718] FATAL Fatal error during KafkaServer startup.
> Prepare to shutdown (kafka.server.KafkaServer)
> org.I0Itec.zkclient.exception.ZkTimeoutException: Unable to connect to
> zookeeper server within timeout: 6000
> at org.I0Itec.zkclient.ZkClient.connect(ZkClient.java:1223)
> at org.I0Itec.zkclient.ZkClient.<init>(ZkClient.java:155)
> at org.I0Itec.zkclient.ZkClient.<init>(ZkClient.java:129)
> at kafka.utils.ZkUtils$.createZkClientAndConnection(ZkUtils.scala:89)
> at kafka.utils.ZkUtils$.apply(ZkUtils.scala:71)
> at kafka.server.KafkaServer.initZk(KafkaServer.scala:278)
> at kafka.server.KafkaServer.startup(KafkaServer.scala:168)
> at
> kafka.server.KafkaServerStartable.startup(KafkaServerStartable.scala:37)
> at kafka.Kafka$.main(Kafka.scala:67)
> at kafka.Kafka.main(Kafka.scala)
> [2016-01-13 16:27:30,721] INFO shutting down (kafka.server.KafkaServer)
> [2016-01-13 16:27:30,727] INFO shut down completed (kafka.server.KafkaServer)
> [2016-01-13 16:27:30,728] FATAL Fatal error during KafkaServerStartable
> startup. Prepare to shutdown (kafka.server.KafkaServerStartable)
> org.I0Itec.zkclient.exception.ZkTimeoutException: Unable to connect to
> zookeeper server within timeout: 6000
> at org.I0Itec.zkclient.ZkClient.connect(ZkClient.java:1223)
> at org.I0Itec.zkclient.ZkClient.<init>(ZkClient.java:155)
> at org.I0Itec.zkclient.ZkClient.<init>(ZkClient.java:129)
> at kafka.utils.ZkUtils$.createZkClientAndConnection(ZkUtils.scala:89)
> at kafka.utils.ZkUtils$.apply(ZkUtils.scala:71)
> at kafka.server.KafkaServer.initZk(KafkaServer.scala:278)
> at kafka.server.KafkaServer.startup(KafkaServer.scala:168)
> at
> kafka.server.KafkaServerStartable.startup(KafkaServerStartable.scala:37)
> at kafka.Kafka$.main(Kafka.scala:67)
> at kafka.Kafka.main(Kafka.scala)
> [2016-01-13 16:27:30,729] INFO shutting down (kafka.server.KafkaServer)
> "server.log" 156L, 6404C
>
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
