[
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 12:46 AM:
----------------------------------------------------------------
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)
was (Author: mohitanchlia):
I enabled debug and still not much info:
[2016-01-14 19:36:40,052] ERROR An error:
(java.security.PrivilegedActionException: javax.security.sasl.SaslException:
GSS initiate failed [Caused by GSSException: No valid credentials provided
(Mechanism level: Server not found in Kerberos database (7) - UNKNOWN_SERVER)])
occurred when evaluating Zookeeper Quorum Member's received SASL token. This
may be caused by Java's being unable to resolve the Zookeeper Quorum Member's
hostname correctly. You may want to try to adding
'-Dsun.net.spi.nameservice.provider.1=dns,sun' to your client's JVMFLAGS
environment. Zookeeper Client will go to AUTH_FAILED state.
(org.apache.zookeeper.client.ZooKeeperSaslClient)
[2016-01-14 19:36:40,052] ERROR SASL authentication with Zookeeper Quorum
member failed: javax.security.sasl.SaslException: An error:
(java.security.PrivilegedActionException: javax.security.sasl.SaslException:
GSS initiate failed [Caused by GSSException: No valid credentials provided
(Mechanism level: Server not found in Kerberos database (7) - UNKNOWN_SERVER)])
occurred when evaluating Zookeeper Quorum Member's received SASL token. This
may be caused by Java's being unable to resolve the Zookeeper Quorum Member's
hostname correctly. You may want to try to adding
'-Dsun.net.spi.nameservice.provider.1=dns,sun' to your client's JVMFLAGS
environment. Zookeeper Client will go to AUTH_FAILED state.
(org.apache.zookeeper.ClientCnxn)
[2016-01-14 19:36:40,052] DEBUG Received event: WatchedEvent state:AuthFailed
type:None path:null (org.I0Itec.zkclient.ZkClient)
[2016-01-14 19:36:40,052] INFO zookeeper state changed (AuthFailed)
(org.I0Itec.zkclient.ZkClient)
[2016-01-14 19:36:40,052] DEBUG Leaving process event
(org.I0Itec.zkclient.ZkClient)
[2016-01-14 19:36:44,057] WARN caught end of stream exception
(org.apache.zookeeper.server.NIOServerCnxn)
EndOfStreamException: Unable to read additional data from client sessionid
0x15242b64cf80000, likely client has closed socket
at
org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:228)
at
org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCnxnFactory.java:208)
at java.lang.Thread.run(Thread.java:745)
[2016-01-14 12:52:47,541] DEBUG sessionid:0x1524142e5c20000 type:closeSession
cxid:0x1 zxid:0x2 txntype:-11 reqpath:n/a
(org.apache.zookeeper.server.FinalRequestProcessor)
[2016-01-14 12:52:47,543] INFO Closed socket connection for client
/0:0:0:0:0:0:0:1:52904 which had sessionid 0x1524142e5c20000
(org.apache.zookeeper.server.NIOServerCnxn)
[2016-01-14 12:52:47,543] DEBUG Reading reply sessionid:0x1524142e5c20000,
packet:: clientPath:null serverPath:null finished:false header:: 1,-11
replyHeader:: 1,2,0 request:: null response:: null
(org.apache.zookeeper.ClientCnxn)
[2016-01-14 12:52:47,543] DEBUG Disconnecting client for session:
0x1524142e5c20000 (org.apache.zookeeper.ClientCnxn)
[2016-01-14 12:52:47,544] INFO Session: 0x1524142e5c20000 closed
(org.apache.zookeeper.ZooKeeper)
[2016-01-14 12:52:47,544] DEBUG Closing ZkClient...done
(org.I0Itec.zkclient.ZkClient)
[2016-01-14 12:52:47,544] DEBUG ignoring event '{None | null}' since shutdown
triggered (org.I0Itec.zkclient.ZkClient)
[2016-01-14 12:52:47,544] DEBUG Leaving process event
(org.I0Itec.zkclient.ZkClient)
[2016-01-14 12:52:47,544] DEBUG Received event: WatchedEvent
state:SyncConnected type:None path:null (org.I0Itec.zkclient.ZkClient)
[2016-01-14 12:52:47,544] DEBUG ignoring event '{None | null}' since shutdown
triggered (org.I0Itec.zkclient.ZkClient)
[2016-01-14 12:52:47,544] DEBUG Leaving process event
(org.I0Itec.zkclient.ZkClient)
[2016-01-14 12:52:47,544] INFO EventThread shut down
(org.apache.zookeeper.ClientCnxn)
[2016-01-14 12:52:47,545] 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)
> 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)
