Errors after reboot on single node setup

2014-10-22 Thread Ciprian Hacman
Hi,

First of all, I am new to Kafka and more of a user than a developer. I will
try to clarify things as much as possible though.

We are using Kafka as a message system for our apps and works nicely in our
SaaS cluster.
I am trying to make the apps also work on a single node for demo purposes.
I set up Zookeeper, Kafka and our apps on a node and things were ok until
rebooting the node. After that I see the following messages in Kafka log:

[2014-10-22 16:37:22,206] INFO [Controller 0]: Controller starting up
(kafka.controller.KafkaController)
[2014-10-22 16:37:22,419] INFO [Controller 0]: Controller startup complete
(kafka.controller.KafkaController)
[2014-10-22 16:37:22,554] INFO conflict in /brokers/ids/0 data:
{jmx_port:-1,timestamp:1413995842465,host:ip-10-91-142-54.eu-west-1.compute.internal,version:1,port:9092}
stored data:
{jmx_port:-1,timestamp:1413994171579,host:ip-10-91-142-54.eu-west-1.compute.internal,version:1,port:9092}
(kafka.utils.ZkUtils$)
[2014-10-22 16:37:22,736] INFO I wrote this conflicted ephemeral node
[{jmx_port:-1,timestamp:1413995842465,host:ip-10-91-142-54.eu-west-1.compute.internal,version:1,port:9092}]
at /brokers/ids/0 a while back in a different session, hence I will backoff
for this node to be deleted by Zookeeper and retry (kafka.utils.ZkUtils$)
[2014-10-22 16:37:25,010] ERROR Error handling event ZkEvent[Data of
/controller changed sent to
kafka.server.ZookeeperLeaderElector$LeaderChangeListener@a6af882]
(org.I0Itec.zkclient.ZkEventThread)
java.lang.IllegalStateException: Kafka scheduler has not been started
at
kafka.utils.KafkaScheduler.ensureStarted(KafkaScheduler.scala:114)
at kafka.utils.KafkaScheduler.shutdown(KafkaScheduler.scala:86)
at
kafka.controller.KafkaController.onControllerResignation(KafkaController.scala:350)
at
kafka.controller.KafkaController$$anonfun$2.apply$mcV$sp(KafkaController.scala:162)
at
kafka.server.ZookeeperLeaderElector$LeaderChangeListener$$anonfun$handleDataDeleted$1.apply$mcZ$sp(ZookeeperLeaderElector.scala:138)
at
kafka.server.ZookeeperLeaderElector$LeaderChangeListener$$anonfun$handleDataDeleted$1.apply(ZookeeperLeaderElector.scala:134)
at
kafka.server.ZookeeperLeaderElector$LeaderChangeListener$$anonfun$handleDataDeleted$1.apply(ZookeeperLeaderElector.scala:134)
at kafka.utils.Utils$.inLock(Utils.scala:535)
at
kafka.server.ZookeeperLeaderElector$LeaderChangeListener.handleDataDeleted(ZookeeperLeaderElector.scala:134)
at org.I0Itec.zkclient.ZkClient$6.run(ZkClient.java:549)
at org.I0Itec.zkclient.ZkEventThread.run(ZkEventThread.java:71)
[2014-10-22 16:37:28,757] INFO Registered broker 0 at path /brokers/ids/0
with address ip-10-91-142-54.eu-west-1.compute.internal:9092.
(kafka.utils.ZkUtils$)
[2014-10-22 16:37:28,849] INFO [Kafka Server 0], started
(kafka.server.KafkaServer)
[2014-10-22 16:38:56,718] INFO Closing socket connection to /127.0.0.1.
(kafka.network.Processor)
[2014-10-22 16:38:56,850] INFO Closing socket connection to /127.0.0.1.
(kafka.network.Processor)
[2014-10-22 16:38:56,985] INFO Closing socket connection to /127.0.0.1.
(kafka.network.Processor)


The last log line repeats forever and is correlated with errors on the app
side.
Restarting Kafka fixes the errors.

I am using Kafka 0.8.2 from github to avoid
https://issues.apache.org/jira/browse/KAFKA-1451.

Does anyone have any idea why this happens and how it can be fixed?

Thanks,
Ciprian
--
Performance Monitoring * Log Analytics * Search Analytics
Solr  Elasticsearch Support * http://sematext.com/


Re: Errors after reboot on single node setup

2014-10-22 Thread Ciprian Hacman
Thank you for the *very* quick replies Neha, Harsha. I opened a Jira for
this issue:
https://issues.apache.org/jira/browse/KAFKA-1724

Ciprian
--
Performance Monitoring * Log Analytics * Search Analytics
Solr  Elasticsearch Support * http://sematext.com/


On Wed, Oct 22, 2014 at 8:27 PM, Harsha ka...@harsha.io wrote:

 This can reproduced with trunk.

 start zookeeper
 start kafka-broker
 create topic or start a producer writing to a topic
 stop zookeeper
 stop kafka-broker( kafka broker shutdown goes into  WARN Session
 0x14938d9dc010001 for server null, unexpected error, closing socket
 connection and attempting reconn
 ect (org.apache.zookeeper.ClientCnxn)
 java.net.ConnectException: Connection refused)
 kill -9 kafka-broker
 restart zookeeper and than kafka-broker leads into the the error posted
 by Ciprian.

 Ciprian,
   Can you open a jira for this.

 Thanks,
 Harsha

 On Wed, Oct 22, 2014, at 10:03 AM, Neha Narkhede wrote:
  Can you provide steps to reproduce this? I'm not sure I understand how
  you
  run into this. It does look like a bug.
 
  On Wed, Oct 22, 2014 at 9:55 AM, Ciprian Hacman
  ciprian.hac...@sematext.com
   wrote:
 
   Hi,
  
   First of all, I am new to Kafka and more of a user than a developer. I
 will
   try to clarify things as much as possible though.
  
   We are using Kafka as a message system for our apps and works nicely
 in our
   SaaS cluster.
   I am trying to make the apps also work on a single node for demo
 purposes.
   I set up Zookeeper, Kafka and our apps on a node and things were ok
 until
   rebooting the node. After that I see the following messages in Kafka
 log:
  
   [2014-10-22 16:37:22,206] INFO [Controller 0]: Controller starting up
   (kafka.controller.KafkaController)
   [2014-10-22 16:37:22,419] INFO [Controller 0]: Controller startup
 complete
   (kafka.controller.KafkaController)
   [2014-10-22 16:37:22,554] INFO conflict in /brokers/ids/0 data:
  
  
 {jmx_port:-1,timestamp:1413995842465,host:ip-10-91-142-54.eu-west-1.compute.internal,version:1,port:9092}
   stored data:
  
  
 {jmx_port:-1,timestamp:1413994171579,host:ip-10-91-142-54.eu-west-1.compute.internal,version:1,port:9092}
   (kafka.utils.ZkUtils$)
   [2014-10-22 16:37:22,736] INFO I wrote this conflicted ephemeral node
  
  
 [{jmx_port:-1,timestamp:1413995842465,host:ip-10-91-142-54.eu-west-1.compute.internal,version:1,port:9092}]
   at /brokers/ids/0 a while back in a different session, hence I will
 backoff
   for this node to be deleted by Zookeeper and retry
 (kafka.utils.ZkUtils$)
   [2014-10-22 16:37:25,010] ERROR Error handling event ZkEvent[Data of
   /controller changed sent to
   kafka.server.ZookeeperLeaderElector$LeaderChangeListener@a6af882]
   (org.I0Itec.zkclient.ZkEventThread)
   java.lang.IllegalStateException: Kafka scheduler has not been started
   at
   kafka.utils.KafkaScheduler.ensureStarted(KafkaScheduler.scala:114)
   at kafka.utils.KafkaScheduler.shutdown(KafkaScheduler.scala:86)
   at
  
  
 kafka.controller.KafkaController.onControllerResignation(KafkaController.scala:350)
   at
  
  
 kafka.controller.KafkaController$$anonfun$2.apply$mcV$sp(KafkaController.scala:162)
   at
  
  
 kafka.server.ZookeeperLeaderElector$LeaderChangeListener$$anonfun$handleDataDeleted$1.apply$mcZ$sp(ZookeeperLeaderElector.scala:138)
   at
  
  
 kafka.server.ZookeeperLeaderElector$LeaderChangeListener$$anonfun$handleDataDeleted$1.apply(ZookeeperLeaderElector.scala:134)
   at
  
  
 kafka.server.ZookeeperLeaderElector$LeaderChangeListener$$anonfun$handleDataDeleted$1.apply(ZookeeperLeaderElector.scala:134)
   at kafka.utils.Utils$.inLock(Utils.scala:535)
   at
  
  
 kafka.server.ZookeeperLeaderElector$LeaderChangeListener.handleDataDeleted(ZookeeperLeaderElector.scala:134)
   at org.I0Itec.zkclient.ZkClient$6.run(ZkClient.java:549)
   at org.I0Itec.zkclient.ZkEventThread.run(ZkEventThread.java:71)
   [2014-10-22 16:37:28,757] INFO Registered broker 0 at path
 /brokers/ids/0
   with address ip-10-91-142-54.eu-west-1.compute.internal:9092.
   (kafka.utils.ZkUtils$)
   [2014-10-22 16:37:28,849] INFO [Kafka Server 0], started
   (kafka.server.KafkaServer)
   [2014-10-22 16:38:56,718] INFO Closing socket connection to /127.0.0.1
 .
   (kafka.network.Processor)
   [2014-10-22 16:38:56,850] INFO Closing socket connection to /127.0.0.1
 .
   (kafka.network.Processor)
   [2014-10-22 16:38:56,985] INFO Closing socket connection to /127.0.0.1
 .
   (kafka.network.Processor)
  
  
   The last log line repeats forever and is correlated with errors on the
 app
   side.
   Restarting Kafka fixes the errors.
  
   I am using Kafka 0.8.2 from github to avoid
   https://issues.apache.org/jira/browse/KAFKA-1451.
  
   Does anyone have any idea why this happens and how it can be fixed?
  
   Thanks,
   Ciprian
   --
   Performance Monitoring * Log Analytics * Search Analytics
   Solr  Elasticsearch Support