[
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:00 AM:
----------------------------------------------------------------
I enabled debug and still not much info:
[2016-01-14 18:57:25,346] DEBUG JAAS loginContext is: Client
(org.apache.zookeeper.client.ZooKeeperSaslClient)
[2016-01-14 18:57:25,445] WARN SASL configuration failed:
javax.security.auth.login.LoginException: Checksum failed Will continue
connection to Zookeeper server without SASL authentication, if Zookeeper server
allows it. (org.apache.zookeeper.ClientCnxn)
[2016-01-14 18:57:25,447] INFO Opening socket connection to server
localhost/127.0.0.1:2181 (org.apache.zookeeper.ClientCnxn)
[2016-01-14 18:57:25,447] DEBUG Received event: WatchedEvent state:AuthFailed
type:None path:null (org.I0Itec.zkclient.ZkClient)
[2016-01-14 18:57:25,447] INFO zookeeper state changed (AuthFailed)
(org.I0Itec.zkclient.ZkClient)
[2016-01-14 18:57:25,447] DEBUG Leaving process event
(org.I0Itec.zkclient.ZkClient)
[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)
was (Author: mohitanchlia):
I enabled debug and still not much info:
[2016-01-14 12:51:17,404] DEBUG zookeeper.disableAutoWatchReset is false
(org.apache.zookeeper.ClientCnxn)
[2016-01-14 12:51:17,418] DEBUG Awaiting connection to Zookeeper server
(org.I0Itec.zkclient.ZkClient)
[2016-01-14 12:51:17,418] INFO Waiting for keeper state SaslAuthenticated
(org.I0Itec.zkclient.ZkClient)
[2016-01-14 12:51:17,420] DEBUG JAAS loginContext is: Client
(org.apache.zookeeper.client.ZooKeeperSaslClient)
[2016-01-14 12:51:23,419] DEBUG Closing ZkClient...
(org.I0Itec.zkclient.ZkClient)
[2016-01-14 12:51:23,419] INFO Terminate ZkClient event thread.
(org.I0Itec.zkclient.ZkEventThread)
[2016-01-14 12:51:23,419] DEBUG Closing ZooKeeper connected to localhost:2181
(org.I0Itec.zkclient.ZkConnection)
[2016-01-14 12:51:23,419] DEBUG Closing session: 0x0
(org.apache.zookeeper.ZooKeeper)
[2016-01-14 12:51:23,419] DEBUG Closing client for session: 0x0
(org.apache.zookeeper.ClientCnxn)
[2016-01-14 12:52:47,501] WARN SASL configuration failed:
javax.security.auth.login.LoginException: Receive timed out Will continue
connection to Zookeeper server without SASL authentication, if Zookeeper server
allows it. (org.apache.zookeeper.ClientCnxn)
[2016-01-14 12:52:47,503] INFO Opening socket connection to server
localhost/0:0:0:0:0:0:0:1:2181 (org.apache.zookeeper.ClientCnxn)
[2016-01-14 12:52:47,503] DEBUG Received event: WatchedEvent state:AuthFailed
type:None path:null (org.I0Itec.zkclient.ZkClient)
[2016-01-14 12:52:47,509] INFO Accepted socket connection from
/0:0:0:0:0:0:0:1:52904 (org.apache.zookeeper.server.NIOServerCnxnFactory)
[2016-01-14 12:52:47,514] INFO Socket connection established to
localhost/0:0:0:0:0:0:0:1:2181, initiating session
(org.apache.zookeeper.ClientCnxn)
[2016-01-14 12:52:47,515] DEBUG Session establishment request sent on
localhost/0:0:0:0:0:0:0:1:2181 (org.apache.zookeeper.ClientCnxn)
[2016-01-14 12:52:47,519] DEBUG Session establishment request from client
/0:0:0:0:0:0:0:1:52904 client's lastZxid is 0x0
(org.apache.zookeeper.server.ZooKeeperServer)
[2016-01-14 12:52:47,521] INFO Client attempting to establish new session at
/0:0:0:0:0:0:0:1:52904 (org.apache.zookeeper.server.ZooKeeperServer)
[2016-01-14 12:52:47,524] INFO Creating new log file: log.1
(org.apache.zookeeper.server.persistence.FileTxnLog)
[2016-01-14 12:52:47,528] DEBUG Processing request::
sessionid:0x1524142e5c20000 type:createSession cxid:0x0 zxid:0x1 txntype:-10
reqpath:n/a (org.apache.zookeeper.server.FinalRequestProcessor)
[2016-01-14 12:52:47,533] DEBUG sessionid:0x1524142e5c20000 type:createSession
cxid:0x0 zxid:0x1 txntype:-10 reqpath:n/a
(org.apache.zookeeper.server.FinalRequestProcessor)
[2016-01-14 12:52:47,537] INFO Established session 0x1524142e5c20000 with
negotiated timeout 6000 for client /0:0:0:0:0:0:0:1:52904
(org.apache.zookeeper.server.ZooKeeperServer)
[2016-01-14 12:52:47,539] INFO Session establishment complete on server
localhost/0:0:0:0:0:0:0:1:2181, sessionid = 0x1524142e5c20000, negotiated
timeout = 6000 (org.apache.zookeeper.ClientCnxn)
[2016-01-14 12:52:47,541] INFO Processed session termination for sessionid:
0x1524142e5c20000 (org.apache.zookeeper.server.PrepRequestProcessor)
[2016-01-14 12:52:47,541] DEBUG Processing request::
sessionid:0x1524142e5c20000 type:closeSession cxid:0x1 zxid:0x2 txntype:-11
reqpath:n/a (org.apache.zookeeper.server.FinalRequestProcessor)
[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,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)
