[jira] [Comment Edited] (KAFKA-1029) Zookeeper leader election stuck in ephemeral node retry loop
[
https://issues.apache.org/jira/browse/KAFKA-1029?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13943920#comment-13943920
]
Jason Rosenberg edited comment on KAFKA-1029 at 3/22/14 5:29 AM:
-
I'm seeing this happening now (we are running 0.8). Should this have been
fixed?
It appears to only happen every once in a while, but when it does, it seems
persist and repeat indefinitely. Sometimes restarting the consumer app can fix
the problem, but not always.
was (Author: jbrosenb...@gmail.com):
I'm seeing this happening now (we are running 0.8). Should this have been
fixed?
> Zookeeper leader election stuck in ephemeral node retry loop
>
>
> Key: KAFKA-1029
> URL: https://issues.apache.org/jira/browse/KAFKA-1029
> Project: Kafka
> Issue Type: Bug
> Components: controller
>Affects Versions: 0.8.0
>Reporter: Sam Meder
>Assignee: Sam Meder
>Priority: Blocker
> Fix For: 0.8.0
>
> Attachments:
> 0002-KAFKA-1029-Use-brokerId-instead-of-leaderId-when-tri.patch
>
>
> We're seeing the following log statements (over and over):
> [2013-08-27 07:21:49,538] INFO conflict in /controller data: { "brokerid":3,
> "timestamp":"1377587945206", "version":1 } stored data: { "brokerid":2,
> "timestamp":"1377587460904", "version":1 } (kafka.utils.ZkUtils$)
> [2013-08-27 07:21:49,559] INFO I wrote this conflicted ephemeral node [{
> "brokerid":3, "timestamp":"1377587945206", "version":1 }] at /controller a
> while back in a different session, hence I will backoff for this node to be
> deleted by Zookeeper and retry (kafka.utils.ZkUtils$)
> where the broker is essentially stuck in the loop that is trying to deal with
> left-over ephemeral nodes. The code looks a bit racy to me. In particular:
> ZookeeperLeaderElector:
> def elect: Boolean = {
> controllerContext.zkClient.subscribeDataChanges(electionPath,
> leaderChangeListener)
> val timestamp = SystemTime.milliseconds.toString
> val electString = ...
> try {
>
> createEphemeralPathExpectConflictHandleZKBug(controllerContext.zkClient,
> electionPath, electString, leaderId,
> (controllerString : String, leaderId : Any) =>
> KafkaController.parseControllerId(controllerString) ==
> leaderId.asInstanceOf[Int],
> controllerContext.zkSessionTimeout)
> leaderChangeListener is registered before the create call (by the way, it
> looks like a new registration will be added every elect call - shouldn't it
> register in startup()?) so can update leaderId to the current leader before
> the call to create. If that happens then we will continuously get node exists
> exceptions and the checker function will always return true, i.e. we will
> never get out of the while(true) loop.
> I think the right fix here is to pass brokerId instead of leaderId when
> calling create, i.e.
> createEphemeralPathExpectConflictHandleZKBug(controllerContext.zkClient,
> electionPath, electString, brokerId,
> (controllerString : String, leaderId : Any) =>
> KafkaController.parseControllerId(controllerString) ==
> leaderId.asInstanceOf[Int],
> controllerContext.zkSessionTimeout)
> The loop dealing with the ephemeral node bug is now only triggered for the
> broker that owned the node previously, although I am still not 100% sure if
> that is sufficient.
--
This message was sent by Atlassian JIRA
(v6.2#6252)
[jira] [Comment Edited] (KAFKA-1029) Zookeeper leader election stuck in ephemeral node retry loop
[
https://issues.apache.org/jira/browse/KAFKA-1029?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13944775#comment-13944775
]
Jason Rosenberg edited comment on KAFKA-1029 at 3/24/14 6:25 AM:
-
Perhaps this should be re-opened a separate ticket?
The issue seems to have started when we had a network outage. Several
high-level consumers could not communicate at all with zookeeper (or kafka) for
several minutes. When the network was restarted, these continual "I wrote this
conlicted ephemeral node" log messages have been running steadily, e.g.:
2014-03-19 00:13:14,165 INFO [ZkClient-EventThread-51-myzkserver]
utils.ZkUtils$ - conflict in
/consumers/myapp/ids/myapp_myhost-1394905418548-e159fc25 data: {
"pattern":"white_list", "subscription":{ "(^\\Qmy.event\\E(\\.[\\w-]+)*$)" : 1
}, "timestamp":"1395187970147", "version":1 } stored data: {
"pattern":"white_list", "subscription":{ "(^\\Qmy.event\\E(\\.[\\w-]+)*$)" : 1
}, "timestamp":"1395187967170", "version":1 }
2014-03-19 00:13:14,166 INFO [ZkClient-EventThread-51-myzkserver]
utils.ZkUtils$ - I wrote this conflicted ephemeral node [{
"pattern":"white_list", "subscription":{ "(^\\Qmy.event\\E(\\.[\\w-]+)*$)" : 1
}, "timestamp":"1395187970147", "version":1 }] at
/consumers/myapp/ids/myapp_awa60.sjc1b.square-1394905418548-e159fc25 a while
back in a different session, hence I will backoff for this node to be deleted
by Zookeeper and retry
These are happening continuously. We have tried doing a rolling restart of our
consumer apps, and even a rolling restart of zk. We are using zk 3.3.6, in
this case, but will try upgrading to 3.4.5 shortly.
It seems that these ephemeral node errors always happen right after a consumer
rebalance occurs.
was (Author: jbrosenb...@gmail.com):
Perhaps this should be re-opened a separate ticket?
The issue seems to have started when we had a network outage. Several
high-level consumers could not communicate at all with zookeeper (or kafka) for
several minutes. When the network was restarted, these continual "I wrote this
conlicted ephemeral node" log messages have been running steadily, e.g.:
2014-03-19 00:13:14,165 INFO [ZkClient-EventThread-51-myzkserver]
utils.ZkUtils$ - conflict in
/consumers/myapp/ids/myapp_myhost-1394905418548-e159fc25 data: {
"pattern":"white_list", "subscription":{ "(^\\Qmy.event\\E(\\.[\\w-]+)*$)" : 1
}, "timestamp":"1395187970147", "version":1 } stored data: {
"pattern":"white_list", "subscription":{ "(^\\Qmy.event\\E(\\.[\\w-]+)*$)" : 1
}, "timestamp":"1395187967170", "version":1 }
2014-03-19 00:13:14,166 INFO [ZkClient-EventThread-51-myzkserver]
utils.ZkUtils$ - I wrote this conflicted ephemeral node [{
"pattern":"white_list", "subscription":{ "(^\\Qmy.event\\E(\\.[\\w-]+)*$)" : 1
}, "timestamp":"1395187970147", "version":1 }] at
/consumers/myapp/ids/myapp_awa60.sjc1b.square-1394905418548-e159fc25 a while
back in a different session, hence I will backoff for this node to be deleted
by Zookeeper and retry
These are happening continuously. We have tried doing a rolling restart of our
consumer apps, and even a rolling restart of zk. We are using zk 3.3.6, in
this case, but will try upgrading to 3.4.5 shortly.
It seems that there are repeated consumer rebalances, as well.
> Zookeeper leader election stuck in ephemeral node retry loop
>
>
> Key: KAFKA-1029
> URL: https://issues.apache.org/jira/browse/KAFKA-1029
> Project: Kafka
> Issue Type: Bug
> Components: controller
>Affects Versions: 0.8.0
>Reporter: Sam Meder
>Assignee: Sam Meder
>Priority: Blocker
> Fix For: 0.8.0
>
> Attachments:
> 0002-KAFKA-1029-Use-brokerId-instead-of-leaderId-when-tri.patch
>
>
> We're seeing the following log statements (over and over):
> [2013-08-27 07:21:49,538] INFO conflict in /controller data: { "brokerid":3,
> "timestamp":"1377587945206", "version":1 } stored data: { "brokerid":2,
> "timestamp":"1377587460904", "version":1 } (kafka.utils.ZkUtils$)
> [2013-08-27 07:21:49,559] INFO I wrote this conflicted ephemeral node [{
> "brokerid":3, "timestamp":"1377587945206", "version":1 }] at /controller a
> while back in a different session, hence I will backoff for this node to be
> deleted by Zookeeper and retry (kafka.utils.ZkUtils$)
> where the broker is essentially stuck in the loop that is trying to deal with
> left-over ephemeral nodes. The code looks a bit racy to me. In particular:
> ZookeeperLeaderElector:
> def elect: Boolean = {
> controllerContext.zkClient.subscribeDataChanges(electionPath,
> leaderChangeListener)
> val timestamp = SystemTime.milliseconds.toString
> val electString = ...
> try {
>
> createEphemeralPathExpectConflictHand
[jira] [Comment Edited] (KAFKA-1029) Zookeeper leader election stuck in ephemeral node retry loop
[
https://issues.apache.org/jira/browse/KAFKA-1029?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13984265#comment-13984265
]
Michael Noll edited comment on KAFKA-1029 at 4/29/14 12:59 PM:
---
Interestingly I ran into the very same issue while doing basic validation of
Kafka 0.8.1.1. Note that unlike Jason Rosenberg's case I was only using
code/tools/scripts that are shipped with Kafka (e.g. console producer and
console consumer).
Here is an example log message, which was repeated indefinitely:
{code}
[2014-04-29 09:48:27,207] INFO conflict in /controller data:
{"version":1,"brokerid":0,"timestamp":"1398764901156"} stored data:
{"version":1,"brokerid":0,"timestamp":"1398764894941"} (kafka.utils.ZkUtils$)
[2014-04-29 09:48:27,218] INFO I wrote this conflicted ephemeral node
[{"version":1,"brokerid":0,"timestamp":"1398764901156"}] at /controller a while
back in a different session, hence I will backoff for this node to be deleted
by Zookeeper and retry (kafka.utils.ZkUtils$)
{code}
*How to reproduce (unsolved)*
Unfortunately I cannot consistently reproduce the issue and, to be honest, I am
still not sure what actually triggers the bug. As such I can only summarize
what I did before and around the time when this bug was triggered, which I
could observe through errors in log files and through errors being displayed
after running certain commands. So yes, it's a bit like shooting in the dark.
Here's an overview of my test setup:
- I deployed Kafka 0.8.1.1 to one machine {{kafka1}} and ZooKeeper 3.4.5 to a
second machine {{zookeeper1}}.
- I followed the Kafka 0.8.1 quick start guide to create a topic "test" with 1
partition and a replication factor of 1.
- I sent test messages to the topic "test" via the console producer.
- I read test messages from the topic "test" via the console consumer.
- Apart from producing and consuming a handful of test messages I also ran some
supposedly read-only admin commands such as "describing" the topic, and running
the consumer offset checker tool.
- At "some" point, Kafka was caught in an indefinite loop complaining about
"conflicted ephemeral node".
The following paragraphs list in more detail what I did before the error popped
up.
Producer:
{code}
$ sudo su - kafka
$ cd /opt/kafka
# This command returned no topics at this point = worked as expected
$ bin/kafka-topics.sh --list --zookeeper zookeeper1
# I created a topic, worked as expected
$ bin/kafka-topics.sh --create --zookeeper zookeeper1 --replication-factor 1
--partitions 1 --topic test
# I requested details of topic "test", worked as expected
$ bin/kafka-topics.sh --zookeeper zookeeper1 --describe --topic test
# I started a console producer and manually send a handful of test messages,
worked as expected (see consumer below)
$ bin/kafka-console-producer.sh --broker-list localhost:9092 --topic test
{code}
Consumer:
{code}
$ sudo su - kafka
$ cd /opt/kafka
# I started a console consumer, worked as expected (i.e. could read messages
sent by producer, see above)
$ bin/kafka-console-consumer.sh --zookeeper zookeeper1 --topic test
--from-beginning
{code}
Up to that point, everything worked. But then the Kafka broker went the way of
the dodo. As I said I can't pinpoint the cause, and re-running the same
commands on a fresh Kafka/ZooKeeper deployment (fresh VMs etc.) didn't
consistently trigger the issue like I hoped.
Here's what I did after the commands above, and at some point I eventually did
observe the original error described in this JIRA ticket. Again, at the moment
I cannot tell what actually triggered the bug.
Producer:
{code}
# Test-driving the consumer offset checker
$ bin/kafka-run-class.sh kafka.tools.ConsumerOffsetChecker --zkconnect
zookeeper1
# At this point consumer "foo" was not expected to exist.
$ bin/kafka-run-class.sh kafka.tools.ConsumerOffsetChecker --zkconnect
zookeeper1 --broker-info --group foo
#
# I then re-started the console producer (see below), now configured to use the
group id "foo".
#
{code}
Consumer:
{code}
# I re-started the console consumer, now configured to use the group id "foo".
$ bin/kafka-console-consumer.sh --zookeeper zookeeper1 --topic test
--from-beginning --group foo
{code}
At this point "describing" the topic gave the following info, indicating that
there was a problem (e.g. no leader for partition):
{code}
$ bin/kafka-topics.sh --zookeeper zookeeper1 --describe --topic testTopic:test
PartitionCount:1ReplicationFactor:1 Configs:
Topic: test Partition: 0Leader: -1 Replicas: 0 Isr:
{code}
Log files such as {{state-change.log}} showed these error messages:
{code}
[2014-04-29 07:44:47,816] TRACE Broker 0 cached leader info
(LeaderAndIsrInfo:(Leader:0,ISR:0,LeaderEpoch:0,ControllerEp
och:1),ReplicationFactor:1),AllReplicas:0) for partition [test,0] in response
to UpdateM
[jira] [Comment Edited] (KAFKA-1029) Zookeeper leader election stuck in ephemeral node retry loop
[
https://issues.apache.org/jira/browse/KAFKA-1029?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13984265#comment-13984265
]
Michael Noll edited comment on KAFKA-1029 at 4/29/14 1:02 PM:
--
Interestingly I ran into the very same issue while doing basic validation of
Kafka 0.8.1.1. Note that unlike Jason Rosenberg's case I was only using
code/tools/scripts that are shipped with Kafka (e.g. console producer and
console consumer).
Here is an example log message, which was repeated indefinitely:
{code}
[2014-04-29 09:48:27,207] INFO conflict in /controller data:
{"version":1,"brokerid":0,"timestamp":"1398764901156"} stored data:
{"version":1,"brokerid":0,"timestamp":"1398764894941"} (kafka.utils.ZkUtils$)
[2014-04-29 09:48:27,218] INFO I wrote this conflicted ephemeral node
[{"version":1,"brokerid":0,"timestamp":"1398764901156"}] at /controller a while
back in a different session, hence I will backoff for this node to be deleted
by Zookeeper and retry (kafka.utils.ZkUtils$)
{code}
*How to reproduce (unsolved)*
Unfortunately I cannot consistently reproduce the issue and, to be honest, I am
still not sure what actually triggers the bug. As such I can only summarize
what I did before and around the time when this bug was triggered, which I
could observe through errors in log files and through errors being displayed
after running certain commands. So yes, it's a bit like shooting in the dark.
Here's an overview of my test setup:
- I deployed Kafka 0.8.1.1 to one machine {{kafka1}} and ZooKeeper 3.4.5 to a
second machine {{zookeeper1}}.
- I followed the Kafka 0.8.1 quick start guide to create a topic "test" with 1
partition and a replication factor of 1.
- I sent test messages to the topic "test" via the console producer.
- I read test messages from the topic "test" via the console consumer.
- Apart from producing and consuming a handful of test messages I also ran some
supposedly read-only admin commands such as "describing" the topic, and running
the consumer offset checker tool.
- At "some" point, Kafka was caught in an indefinite loop complaining about
"conflicted ephemeral node".
The following paragraphs list in more detail what I did before the error popped
up.
Producer:
{code}
$ sudo su - kafka
$ cd /opt/kafka
# This command returned no topics at this point = worked as expected
$ bin/kafka-topics.sh --list --zookeeper zookeeper1
# I created a topic, worked as expected
$ bin/kafka-topics.sh --create --zookeeper zookeeper1 --replication-factor 1
--partitions 1 --topic test
# I requested details of topic "test", worked as expected
$ bin/kafka-topics.sh --zookeeper zookeeper1 --describe --topic test
# I started a console producer and manually send a handful of test messages,
worked as expected (see consumer below)
$ bin/kafka-console-producer.sh --broker-list localhost:9092 --topic test
{code}
Consumer:
{code}
$ sudo su - kafka
$ cd /opt/kafka
# I started a console consumer, worked as expected (i.e. could read messages
sent by producer, see above)
$ bin/kafka-console-consumer.sh --zookeeper zookeeper1 --topic test
--from-beginning
{code}
Up to that point, everything worked. But then the Kafka broker went the way of
the dodo. As I said I can't pinpoint the cause, and re-running the same
commands on a fresh Kafka/ZooKeeper deployment (fresh VMs etc.) didn't
consistently trigger the issue like I hoped.
Here's what I did after the commands above, and at some point I eventually did
observe the original error described in this JIRA ticket. Again, at the moment
I cannot tell what actually triggered the bug.
Producer:
{code}
# Test-driving the consumer offset checker
$ bin/kafka-run-class.sh kafka.tools.ConsumerOffsetChecker --zkconnect
zookeeper1
# At this point consumer "foo" was not expected to exist.
$ bin/kafka-run-class.sh kafka.tools.ConsumerOffsetChecker --zkconnect
zookeeper1 --broker-info --group foo
#
# I then re-started the console producer (see below), now configured to use the
group id "foo".
#
{code}
Consumer:
{code}
# I re-started the console consumer, now configured to use the group id "foo".
$ bin/kafka-console-consumer.sh --zookeeper zookeeper1 --topic test
--from-beginning --group foo
{code}
At this point "describing" the topic gave the following info, indicating that
there was a problem (e.g. no leader for partition):
{code}
$ bin/kafka-topics.sh --zookeeper zookeeper1 --describe --topic testTopic:test
PartitionCount:1ReplicationFactor:1 Configs:
Topic: test Partition: 0Leader: -1 Replicas: 0 Isr:
{code}
Log files such as {{state-change.log}} showed these error messages:
{code}
[2014-04-29 07:44:47,816] TRACE Broker 0 cached leader info
(LeaderAndIsrInfo:(Leader:0,ISR:0,LeaderEpoch:0,ControllerEp
och:1),ReplicationFactor:1),AllReplicas:0) for partition [test,0] in response
to UpdateMet
[jira] [Comment Edited] (KAFKA-1029) Zookeeper leader election stuck in ephemeral node retry loop
[
https://issues.apache.org/jira/browse/KAFKA-1029?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13984265#comment-13984265
]
Michael Noll edited comment on KAFKA-1029 at 4/29/14 1:12 PM:
--
Interestingly I ran into the very same issue while doing basic validation of
Kafka 0.8.1.1. Note that unlike Jason Rosenberg's case I was only using
code/tools/scripts that are shipped with Kafka (e.g. console producer and
console consumer).
Here is an example log message, which was repeated indefinitely:
{code}
[2014-04-29 09:48:27,207] INFO conflict in /controller data:
{"version":1,"brokerid":0,"timestamp":"1398764901156"} stored data:
{"version":1,"brokerid":0,"timestamp":"1398764894941"} (kafka.utils.ZkUtils$)
[2014-04-29 09:48:27,218] INFO I wrote this conflicted ephemeral node
[{"version":1,"brokerid":0,"timestamp":"1398764901156"}] at /controller a while
back in a different session, hence I will backoff for this node to be deleted
by Zookeeper and retry (kafka.utils.ZkUtils$)
{code}
*How to reproduce (unsolved)*
Unfortunately I cannot consistently reproduce the issue and, to be honest, I am
still not sure what actually triggers the bug. As such I can only summarize
what I did before and around the time when this bug was triggered, which I
could observe through errors in log files and through errors being displayed
after running certain commands. So yes, it's a bit like shooting in the dark.
Here's an overview of my test setup:
- I deployed Kafka 0.8.1.1 to one machine {{kafka1}} and ZooKeeper 3.4.5 to a
second machine {{zookeeper1}}.
- I followed the Kafka 0.8.1 quick start guide to create a topic "test" with 1
partition and a replication factor of 1.
- I sent test messages to the topic "test" via the console producer.
- I read test messages from the topic "test" via the console consumer.
- Apart from producing and consuming a handful of test messages I also ran some
supposedly read-only admin commands such as "describing" the topic, and running
the consumer offset checker tool.
- At "some" point, Kafka was caught in an indefinite loop complaining about
"conflicted ephemeral node".
The following paragraphs list in more detail what I did before the error popped
up.
Producer:
{code}
$ sudo su - kafka
$ cd /opt/kafka
# This command returned no topics at this point = worked as expected
$ bin/kafka-topics.sh --list --zookeeper zookeeper1
# I created a topic, worked as expected
$ bin/kafka-topics.sh --create --zookeeper zookeeper1 --replication-factor 1
--partitions 1 --topic test
# I requested details of topic "test", worked as expected
$ bin/kafka-topics.sh --zookeeper zookeeper1 --describe --topic test
# I started a console producer and manually send a handful of test messages,
worked as expected (see consumer below)
$ bin/kafka-console-producer.sh --broker-list localhost:9092 --topic test
{code}
Consumer:
{code}
$ sudo su - kafka
$ cd /opt/kafka
# I started a console consumer, worked as expected (i.e. could read messages
sent by producer, see above)
$ bin/kafka-console-consumer.sh --zookeeper zookeeper1 --topic test
--from-beginning
{code}
Up to that point, everything worked. But then the Kafka broker went the way of
the dodo. As I said I can't pinpoint the cause, and re-running the same
commands on a fresh Kafka/ZooKeeper deployment (fresh VMs etc.) didn't
consistently trigger the issue like I hoped.
Here's what I did after the commands above, and at some point I eventually did
observe the original error described in this JIRA ticket. Again, at the moment
I cannot tell what actually triggered the bug.
Producer:
{code}
# Test-driving the consumer offset checker
$ bin/kafka-run-class.sh kafka.tools.ConsumerOffsetChecker --zkconnect
zookeeper1
# At this point consumer "foo" was not expected to exist.
$ bin/kafka-run-class.sh kafka.tools.ConsumerOffsetChecker --zkconnect
zookeeper1 --broker-info --group foo
#
# I then re-started the console producer (see below), now configured to use the
group id "foo".
#
{code}
Consumer:
{code}
# I re-started the console consumer, now configured to use the group id "foo".
$ bin/kafka-console-consumer.sh --zookeeper zookeeper1 --topic test
--from-beginning --group foo
{code}
At this point "describing" the topic gave the following info, indicating that
there was a problem (e.g. no leader for partition):
{code}
$ bin/kafka-topics.sh --zookeeper zookeeper1 --describe --topic testTopic:test
PartitionCount:1ReplicationFactor:1 Configs:
Topic: test Partition: 0Leader: -1 Replicas: 0 Isr:
{code}
Log files such as {{state-change.log}} showed these error messages:
{code}
[2014-04-29 07:44:47,816] TRACE Broker 0 cached leader info
(LeaderAndIsrInfo:(Leader:0,ISR:0,LeaderEpoch:0,ControllerEp
och:1),ReplicationFactor:1),AllReplicas:0) for partition [test,0] in response
to UpdateMet
[jira] [Comment Edited] (KAFKA-1029) Zookeeper leader election stuck in ephemeral node retry loop
[
https://issues.apache.org/jira/browse/KAFKA-1029?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13984265#comment-13984265
]
Michael Noll edited comment on KAFKA-1029 at 4/29/14 1:22 PM:
--
Interestingly I ran into a very similar issue while doing basic validation of
Kafka 0.8.1.1. Note that unlike Jason Rosenberg's case I was only using
code/tools/scripts that are shipped with Kafka (e.g. console producer and
console consumer).
Here is an example log message, which was repeated indefinitely:
{code}
[2014-04-29 09:48:27,207] INFO conflict in /controller data:
{"version":1,"brokerid":0,"timestamp":"1398764901156"} stored data:
{"version":1,"brokerid":0,"timestamp":"1398764894941"} (kafka.utils.ZkUtils$)
[2014-04-29 09:48:27,218] INFO I wrote this conflicted ephemeral node
[{"version":1,"brokerid":0,"timestamp":"1398764901156"}] at /controller a while
back in a different session, hence I will backoff for this node to be deleted
by Zookeeper and retry (kafka.utils.ZkUtils$)
{code}
*How to reproduce (unsolved)*
Unfortunately I cannot consistently reproduce the issue and, to be honest, I am
still not sure what actually triggers the bug. As such I can only summarize
what I did before and around the time when this bug was triggered, which I
could observe through errors in log files and through errors being displayed
after running certain commands. So yes, it's a bit like shooting in the dark.
Here's an overview of my test setup:
- I deployed Kafka 0.8.1.1 to one machine {{kafka1}} and ZooKeeper 3.4.5 to a
second machine {{zookeeper1}}.
- I followed the Kafka 0.8.1 quick start guide to create a topic "test" with 1
partition and a replication factor of 1.
- I sent test messages to the topic "test" via the console producer.
- I read test messages from the topic "test" via the console consumer.
- Apart from producing and consuming a handful of test messages I also ran some
supposedly read-only admin commands such as "describing" the topic, and running
the consumer offset checker tool.
- At "some" point, Kafka was caught in an indefinite loop complaining about
"conflicted ephemeral node".
The following paragraphs list in more detail what I did before the error popped
up.
Producer:
{code}
$ sudo su - kafka
$ cd /opt/kafka
# This command returned no topics at this point = worked as expected
$ bin/kafka-topics.sh --list --zookeeper zookeeper1
# I created a topic, worked as expected
$ bin/kafka-topics.sh --create --zookeeper zookeeper1 --replication-factor 1
--partitions 1 --topic test
# I requested details of topic "test", worked as expected
$ bin/kafka-topics.sh --zookeeper zookeeper1 --describe --topic test
# I started a console producer and manually send a handful of test messages,
worked as expected (see consumer below)
$ bin/kafka-console-producer.sh --broker-list localhost:9092 --topic test
{code}
Consumer:
{code}
$ sudo su - kafka
$ cd /opt/kafka
# I started a console consumer, worked as expected (i.e. could read messages
sent by producer, see above)
$ bin/kafka-console-consumer.sh --zookeeper zookeeper1 --topic test
--from-beginning
{code}
Up to that point, everything worked. But then the Kafka broker went the way of
the dodo. As I said I can't pinpoint the cause, and re-running the same
commands on a fresh Kafka/ZooKeeper deployment (fresh VMs etc.) didn't
consistently trigger the issue like I hoped.
Here's what I did after the commands above, and at some point I eventually did
observe the original error described in this JIRA ticket. Again, at the moment
I cannot tell what actually triggered the bug.
Producer:
{code}
# Test-driving the consumer offset checker
$ bin/kafka-run-class.sh kafka.tools.ConsumerOffsetChecker --zkconnect
zookeeper1
# At this point consumer "foo" was not expected to exist.
$ bin/kafka-run-class.sh kafka.tools.ConsumerOffsetChecker --zkconnect
zookeeper1 --broker-info --group foo
#
# I then re-started the console producer (see below), now configured to use the
group id "foo".
#
{code}
Consumer:
{code}
# I re-started the console consumer, now configured to use the group id "foo".
$ bin/kafka-console-consumer.sh --zookeeper zookeeper1 --topic test
--from-beginning --group foo
{code}
At this point "describing" the topic gave the following info, indicating that
there was a problem (e.g. no leader for partition):
{code}
$ bin/kafka-topics.sh --zookeeper zookeeper1 --describe --topic testTopic:test
PartitionCount:1ReplicationFactor:1 Configs:
Topic: test Partition: 0Leader: -1 Replicas: 0 Isr:
{code}
Log files such as {{state-change.log}} showed these error messages:
{code}
[2014-04-29 07:44:47,816] TRACE Broker 0 cached leader info
(LeaderAndIsrInfo:(Leader:0,ISR:0,LeaderEpoch:0,ControllerEp
och:1),ReplicationFactor:1),AllReplicas:0) for partition [test,0] in response
to UpdateMe
[jira] [Comment Edited] (KAFKA-1029) Zookeeper leader election stuck in ephemeral node retry loop
[
https://issues.apache.org/jira/browse/KAFKA-1029?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13984265#comment-13984265
]
Michael Noll edited comment on KAFKA-1029 at 4/29/14 1:27 PM:
--
Interestingly I ran into a very similar issue while doing basic validation of
Kafka 0.8.1.1. Note that unlike Jason Rosenberg's case I was only using
code/tools/scripts that are shipped with Kafka (e.g. console producer and
console consumer).
Here is an example log message, which was repeated indefinitely:
{code}
[2014-04-29 09:48:27,207] INFO conflict in /controller data:
{"version":1,"brokerid":0,"timestamp":"1398764901156"} stored data:
{"version":1,"brokerid":0,"timestamp":"1398764894941"} (kafka.utils.ZkUtils$)
[2014-04-29 09:48:27,218] INFO I wrote this conflicted ephemeral node
[{"version":1,"brokerid":0,"timestamp":"1398764901156"}] at /controller a while
back in a different session, hence I will backoff for this node to be deleted
by Zookeeper and retry (kafka.utils.ZkUtils$)
{code}
*How to reproduce (unsolved)*
Unfortunately I cannot consistently reproduce the issue and, to be honest, I am
still not sure what actually triggers the bug. As such I can only summarize
what I did before and around the time when this bug was triggered, which I
could observe through errors in log files and through errors being displayed
after running certain commands. So yes, it's a bit like shooting in the dark.
Here's an overview of my test setup:
- I deployed Kafka 0.8.1.1 to one machine {{kafka1}} and ZooKeeper 3.4.5 to a
second machine {{zookeeper1}}.
- I followed the Kafka 0.8.1 quick start guide to create a topic "test" with 1
partition and a replication factor of 1.
- I sent test messages to the topic "test" via the console producer.
- I read test messages from the topic "test" via the console consumer.
- Apart from producing and consuming a handful of test messages I also ran some
supposedly read-only admin commands such as "describing" the topic, and running
the consumer offset checker tool.
- At "some" point, Kafka was caught in an indefinite loop complaining about
"conflicted ephemeral node".
The following paragraphs list in more detail what I did before the error popped
up.
Producer:
{code}
$ sudo su - kafka
$ cd /opt/kafka
# This command returned no topics at this point = worked as expected
$ bin/kafka-topics.sh --list --zookeeper zookeeper1
# I created a topic, worked as expected
$ bin/kafka-topics.sh --create --zookeeper zookeeper1 --replication-factor 1
--partitions 1 --topic test
# I requested details of topic "test", worked as expected
$ bin/kafka-topics.sh --zookeeper zookeeper1 --describe --topic test
# I started a console producer and manually send a handful of test messages,
worked as expected (see consumer below)
$ bin/kafka-console-producer.sh --broker-list localhost:9092 --topic test
{code}
Consumer:
{code}
$ sudo su - kafka
$ cd /opt/kafka
# I started a console consumer, worked as expected (i.e. could read messages
sent by producer, see above)
$ bin/kafka-console-consumer.sh --zookeeper zookeeper1 --topic test
--from-beginning
{code}
Up to that point, everything worked. But then the Kafka broker went the way of
the dodo. As I said I can't pinpoint the cause, and re-running the same
commands on a fresh Kafka/ZooKeeper deployment (fresh VMs etc.) didn't
consistently trigger the issue like I hoped.
Here's what I did after the commands above, and at some point I eventually did
observe the original error described in this JIRA ticket. Again, at the moment
I cannot tell what actually triggered the bug.
Producer:
{code}
# Test-driving the consumer offset checker
$ bin/kafka-run-class.sh kafka.tools.ConsumerOffsetChecker --zkconnect
zookeeper1
# At this point consumer "foo" was not expected to exist.
$ bin/kafka-run-class.sh kafka.tools.ConsumerOffsetChecker --zkconnect
zookeeper1 --broker-info --group foo
#
# I then re-started the console producer (see below), now configured to use the
group id "foo".
#
{code}
Consumer:
{code}
# I re-started the console consumer, now configured to use the group id "foo".
$ bin/kafka-console-consumer.sh --zookeeper zookeeper1 --topic test
--from-beginning --group foo
{code}
At this point "describing" the topic gave the following info, indicating that
there was a problem (e.g. no leader for partition):
{code}
$ bin/kafka-topics.sh --zookeeper zookeeper1 --describe --topic testTopic:test
PartitionCount:1ReplicationFactor:1 Configs:
Topic: test Partition: 0Leader: -1 Replicas: 0 Isr:
{code}
Log files such as {{state-change.log}} showed these error messages:
{code}
[2014-04-29 07:44:47,816] TRACE Broker 0 cached leader info
(LeaderAndIsrInfo:(Leader:0,ISR:0,LeaderEpoch:0,ControllerEp
och:1),ReplicationFactor:1),AllReplicas:0) for partition [test,0] in response
to UpdateMe
[jira] [Comment Edited] (KAFKA-1029) Zookeeper leader election stuck in ephemeral node retry loop
[
https://issues.apache.org/jira/browse/KAFKA-1029?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13984265#comment-13984265
]
Michael Noll edited comment on KAFKA-1029 at 4/29/14 1:27 PM:
--
Interestingly I ran into a very similar issue while doing basic validation of
Kafka 0.8.1.1. Note that unlike Jason Rosenberg's case I was only using
code/tools/scripts that are shipped with Kafka (e.g. console producer and
console consumer).
Here is an example log message, which was repeated indefinitely:
{code}
[2014-04-29 09:48:27,207] INFO conflict in /controller data:
{"version":1,"brokerid":0,"timestamp":"1398764901156"} stored data:
{"version":1,"brokerid":0,"timestamp":"1398764894941"} (kafka.utils.ZkUtils$)
[2014-04-29 09:48:27,218] INFO I wrote this conflicted ephemeral node
[{"version":1,"brokerid":0,"timestamp":"1398764901156"}] at /controller a while
back in a different session, hence I will backoff for this node to be deleted
by Zookeeper and retry (kafka.utils.ZkUtils$)
{code}
*How to reproduce (unsolved)*
Unfortunately I cannot consistently reproduce the issue and, to be honest, I am
still not sure what actually triggers the bug. As such I can only summarize
what I did before and around the time when this bug was triggered, which I
could observe through errors in log files and through errors being displayed
after running certain commands. So yes, it's a bit like shooting in the dark.
Here's an overview of my test setup:
- I deployed Kafka 0.8.1.1 to one machine {{kafka1}} and ZooKeeper 3.4.5 to a
second machine {{zookeeper1}}.
- I followed the Kafka 0.8.1 quick start guide to create a topic "test" with 1
partition and a replication factor of 1.
- I sent test messages to the topic "test" via the console producer.
- I read test messages from the topic "test" via the console consumer.
- Apart from producing and consuming a handful of test messages I also ran some
supposedly read-only admin commands such as "describing" the topic, and running
the consumer offset checker tool.
- At "some" point, Kafka was caught in an indefinite loop complaining about
"conflicted ephemeral node".
The following paragraphs list in more detail what I did before the error popped
up.
Producer:
{code}
$ sudo su - kafka
$ cd /opt/kafka
# This command returned no topics at this point = worked as expected
$ bin/kafka-topics.sh --list --zookeeper zookeeper1
# I created a topic, worked as expected
$ bin/kafka-topics.sh --create --zookeeper zookeeper1 --replication-factor 1
--partitions 1 --topic test
# I requested details of topic "test", worked as expected
$ bin/kafka-topics.sh --zookeeper zookeeper1 --describe --topic test
# I started a console producer and manually send a handful of test messages,
worked as expected (see consumer below)
$ bin/kafka-console-producer.sh --broker-list localhost:9092 --topic test
{code}
Consumer:
{code}
$ sudo su - kafka
$ cd /opt/kafka
# I started a console consumer, worked as expected (i.e. could read messages
sent by producer, see above)
$ bin/kafka-console-consumer.sh --zookeeper zookeeper1 --topic test
--from-beginning
{code}
Up to that point, everything worked. But then the Kafka broker went the way of
the dodo. As I said I can't pinpoint the cause, and re-running the same
commands on a fresh Kafka/ZooKeeper deployment (fresh VMs etc.) didn't
consistently trigger the issue like I hoped.
Here's what I did after the commands above, and at some point I eventually did
observe the original error described in this JIRA ticket. Again, at the moment
I cannot tell what actually triggered the bug.
Producer:
{code}
# Test-driving the consumer offset checker
$ bin/kafka-run-class.sh kafka.tools.ConsumerOffsetChecker --zkconnect
zookeeper1
# At this point consumer "foo" was not expected to exist.
$ bin/kafka-run-class.sh kafka.tools.ConsumerOffsetChecker --zkconnect
zookeeper1 --broker-info --group foo
#
# I then re-started the console producer (see below), now configured to use the
group id "foo".
#
{code}
Consumer:
{code}
# I re-started the console consumer, now configured to use the group id "foo".
$ bin/kafka-console-consumer.sh --zookeeper zookeeper1 --topic test
--from-beginning --group foo
{code}
At this point "describing" the topic gave the following info, indicating that
there was a problem (e.g. no leader for partition):
{code}
$ bin/kafka-topics.sh --zookeeper zookeeper1 --describe --topic testTopic:test
PartitionCount:1ReplicationFactor:1 Configs:
Topic: test Partition: 0Leader: -1 Replicas: 0 Isr:
{code}
Log files such as {{state-change.log}} showed these error messages:
{code}
[2014-04-29 07:44:47,816] TRACE Broker 0 cached leader info
(LeaderAndIsrInfo:(Leader:0,ISR:0,LeaderEpoch:0,ControllerEp
och:1),ReplicationFactor:1),AllReplicas:0) for partition [test,0] in response
to UpdateMe
[jira] [Comment Edited] (KAFKA-1029) Zookeeper leader election stuck in ephemeral node retry loop
[
https://issues.apache.org/jira/browse/KAFKA-1029?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13984265#comment-13984265
]
Michael Noll edited comment on KAFKA-1029 at 4/29/14 1:30 PM:
--
Interestingly I ran into a very similar issue while doing basic validation of
Kafka 0.8.1.1. Note that unlike Jason Rosenberg's case I was only using
code/tools/scripts that are shipped with Kafka (e.g. console producer and
console consumer).
Here is an example log message, which was repeated indefinitely:
{code}
[2014-04-29 09:48:27,207] INFO conflict in /controller data:
{"version":1,"brokerid":0,"timestamp":"1398764901156"} stored data:
{"version":1,"brokerid":0,"timestamp":"1398764894941"} (kafka.utils.ZkUtils$)
[2014-04-29 09:48:27,218] INFO I wrote this conflicted ephemeral node
[{"version":1,"brokerid":0,"timestamp":"1398764901156"}] at /controller a while
back in a different session, hence I will backoff for this node to be deleted
by Zookeeper and retry (kafka.utils.ZkUtils$)
{code}
*How to reproduce (unsolved)*
Unfortunately I cannot consistently reproduce the issue and, to be honest, I am
still not sure what actually triggers the bug. As such I can only summarize
what I did before and around the time when this bug was triggered, which I
could observe through errors in log files and through errors being displayed
after running certain commands. So yes, it's a bit like shooting in the dark.
Here's an overview of my test setup:
- I deployed Kafka 0.8.1.1 to one machine {{kafka1}} and ZooKeeper 3.4.5 to a
second machine {{zookeeper1}}.
- I followed the Kafka 0.8.1 quick start guide to create a topic "test" with 1
partition and a replication factor of 1.
- I sent test messages to the topic "test" via the console producer.
- I read test messages from the topic "test" via the console consumer.
- Apart from producing and consuming a handful of test messages I also ran some
supposedly read-only admin commands such as "describing" the topic, and running
the consumer offset checker tool.
- At "some" point, Kafka was caught in an indefinite loop complaining about
"conflict in {{/controller}} data".
The following paragraphs list in more detail what I did before the error popped
up.
Producer:
{code}
$ sudo su - kafka
$ cd /opt/kafka
# This command returned no topics at this point = worked as expected
$ bin/kafka-topics.sh --list --zookeeper zookeeper1
# I created a topic, worked as expected
$ bin/kafka-topics.sh --create --zookeeper zookeeper1 --replication-factor 1
--partitions 1 --topic test
# I requested details of topic "test", worked as expected
$ bin/kafka-topics.sh --zookeeper zookeeper1 --describe --topic test
# I started a console producer and manually send a handful of test messages,
worked as expected (see consumer below)
$ bin/kafka-console-producer.sh --broker-list localhost:9092 --topic test
{code}
Consumer:
{code}
$ sudo su - kafka
$ cd /opt/kafka
# I started a console consumer, worked as expected (i.e. could read messages
sent by producer, see above)
$ bin/kafka-console-consumer.sh --zookeeper zookeeper1 --topic test
--from-beginning
{code}
Up to that point, everything worked. But then the Kafka broker went the way of
the dodo. As I said I can't pinpoint the cause, and re-running the same
commands on a fresh Kafka/ZooKeeper deployment (fresh VMs etc.) didn't
consistently trigger the issue like I hoped.
Here's what I did after the commands above, and at some point I eventually did
observe the original error described in this JIRA ticket. Again, at the moment
I cannot tell what actually triggered the bug.
Producer:
{code}
# Test-driving the consumer offset checker
$ bin/kafka-run-class.sh kafka.tools.ConsumerOffsetChecker --zkconnect
zookeeper1
# At this point consumer "foo" was not expected to exist.
$ bin/kafka-run-class.sh kafka.tools.ConsumerOffsetChecker --zkconnect
zookeeper1 --broker-info --group foo
#
# I then re-started the console producer (see below), now configured to use the
group id "foo".
#
{code}
Consumer:
{code}
# I re-started the console consumer, now configured to use the group id "foo".
$ bin/kafka-console-consumer.sh --zookeeper zookeeper1 --topic test
--from-beginning --group foo
{code}
At this point "describing" the topic gave the following info, indicating that
there was a problem (e.g. no leader for partition):
{code}
$ bin/kafka-topics.sh --zookeeper zookeeper1 --describe --topic testTopic:test
PartitionCount:1ReplicationFactor:1 Configs:
Topic: test Partition: 0Leader: -1 Replicas: 0 Isr:
{code}
Log files such as {{state-change.log}} showed these error messages:
{code}
[2014-04-29 07:44:47,816] TRACE Broker 0 cached leader info
(LeaderAndIsrInfo:(Leader:0,ISR:0,LeaderEpoch:0,ControllerEp
och:1),ReplicationFactor:1),AllReplicas:0) for partition [test,0] in response
to U
[jira] [Comment Edited] (KAFKA-1029) Zookeeper leader election stuck in ephemeral node retry loop
[
https://issues.apache.org/jira/browse/KAFKA-1029?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13984265#comment-13984265
]
Michael Noll edited comment on KAFKA-1029 at 4/29/14 1:35 PM:
--
Interestingly I ran into a very similar issue while doing basic validation of
Kafka 0.8.1.1. Note that unlike Jason Rosenberg's case I was only using
code/tools/scripts that are shipped with Kafka (e.g. console producer and
console consumer).
Here is an example log message, which was repeated indefinitely:
{code}
[2014-04-29 09:48:27,207] INFO conflict in /controller data:
{"version":1,"brokerid":0,"timestamp":"1398764901156"} stored data:
{"version":1,"brokerid":0,"timestamp":"1398764894941"} (kafka.utils.ZkUtils$)
[2014-04-29 09:48:27,218] INFO I wrote this conflicted ephemeral node
[{"version":1,"brokerid":0,"timestamp":"1398764901156"}] at /controller a while
back in a different session, hence I will backoff for this node to be deleted
by Zookeeper and retry (kafka.utils.ZkUtils$)
{code}
*How to reproduce (unsolved)*
Unfortunately I cannot consistently reproduce the issue and, to be honest, I am
still not sure what actually triggers the bug. As such I can only summarize
what I did before and around the time when this bug was triggered, which I
could observe through errors in log files and through errors being displayed
after running certain commands. So yes, it's a bit like shooting in the dark.
Here's an overview of my test setup:
- I deployed Kafka 0.8.1.1 to one machine {{kafka1}} and ZooKeeper 3.4.5 to a
second machine {{zookeeper1}}.
- I followed the Kafka 0.8.1 quick start guide to create a topic "test" with 1
partition and a replication factor of 1.
- I sent test messages to the topic "test" via the console producer.
- I read test messages from the topic "test" via the console consumer.
- Apart from producing and consuming a handful of test messages I also ran some
supposedly read-only admin commands such as "describing" the topic, and running
the consumer offset checker tool.
- At "some" point, Kafka was caught in an indefinite loop complaining about
"conflict in {{/controller}} data".
The following paragraphs list in more detail what I did before the error popped
up.
Producer:
{code}
$ sudo su - kafka
$ cd /opt/kafka
# This command returned no topics at this point = worked as expected
$ bin/kafka-topics.sh --list --zookeeper zookeeper1
# I created a topic, worked as expected
$ bin/kafka-topics.sh --create --zookeeper zookeeper1 --replication-factor 1
--partitions 1 --topic test
# I requested details of topic "test", worked as expected
$ bin/kafka-topics.sh --zookeeper zookeeper1 --describe --topic test
Topic:test PartitionCount:1ReplicationFactor:1 Configs:
Topic: test Partition: 0Leader: 0 Replicas: 0 Isr: 0
# I started a console producer and manually send a handful of test messages,
worked as expected (see consumer below)
$ bin/kafka-console-producer.sh --broker-list localhost:9092 --topic test
{code}
Consumer:
{code}
$ sudo su - kafka
$ cd /opt/kafka
# I started a console consumer, worked as expected (i.e. could read messages
sent by producer, see above)
$ bin/kafka-console-consumer.sh --zookeeper zookeeper1 --topic test
--from-beginning
{code}
Up to that point, everything worked. But then the Kafka broker went the way of
the dodo. As I said I can't pinpoint the cause, and re-running the same
commands on a fresh Kafka/ZooKeeper deployment (fresh VMs etc.) didn't
consistently trigger the issue like I hoped.
Here's what I did after the commands above, and at some point I eventually did
observe the original error described in this JIRA ticket. Again, at the moment
I cannot tell what actually triggered the bug.
Producer:
{code}
# Test-driving the consumer offset checker
$ bin/kafka-run-class.sh kafka.tools.ConsumerOffsetChecker --zkconnect
zookeeper1
# At this point consumer "foo" was not expected to exist.
$ bin/kafka-run-class.sh kafka.tools.ConsumerOffsetChecker --zkconnect
zookeeper1 --broker-info --group foo
#
# I then re-started the console producer (see below), now configured to use the
group id "foo".
#
{code}
Consumer:
{code}
# I re-started the console consumer, now configured to use the group id "foo".
$ bin/kafka-console-consumer.sh --zookeeper zookeeper1 --topic test
--from-beginning --group foo
{code}
At this point "describing" the topic gave the following info, indicating that
there was a problem (e.g. no leader for partition):
{code}
$ bin/kafka-topics.sh --zookeeper zookeeper1 --describe --topic testTopic:test
PartitionCount:1ReplicationFactor:1 Configs:
Topic: test Partition: 0Leader: -1 Replicas: 0 Isr:
{code}
Log files such as {{state-change.log}} showed these error messages:
{code}
[2014-04-29 07:44:47,816] TRACE Broker 0 cached leade
[jira] [Comment Edited] (KAFKA-1029) Zookeeper leader election stuck in ephemeral node retry loop
[
https://issues.apache.org/jira/browse/KAFKA-1029?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13984265#comment-13984265
]
Michael Noll edited comment on KAFKA-1029 at 4/29/14 1:35 PM:
--
Interestingly I ran into a very similar issue while doing basic validation of
Kafka 0.8.1.1. Note that unlike Jason Rosenberg's case I was only using
code/tools/scripts that are shipped with Kafka (e.g. console producer and
console consumer).
Here is an example log message, which was repeated indefinitely:
{code}
[2014-04-29 09:48:27,207] INFO conflict in /controller data:
{"version":1,"brokerid":0,"timestamp":"1398764901156"} stored data:
{"version":1,"brokerid":0,"timestamp":"1398764894941"} (kafka.utils.ZkUtils$)
[2014-04-29 09:48:27,218] INFO I wrote this conflicted ephemeral node
[{"version":1,"brokerid":0,"timestamp":"1398764901156"}] at /controller a while
back in a different session, hence I will backoff for this node to be deleted
by Zookeeper and retry (kafka.utils.ZkUtils$)
{code}
*How to reproduce (unsolved)*
Unfortunately I cannot consistently reproduce the issue and, to be honest, I am
still not sure what actually triggers the bug. As such I can only summarize
what I did before and around the time when this bug was triggered, which I
could observe through errors in log files and through errors being displayed
after running certain commands. So yes, it's a bit like shooting in the dark.
Here's an overview of my test setup:
- I deployed Kafka 0.8.1.1 to one machine {{kafka1}} and ZooKeeper 3.4.5 to a
second machine {{zookeeper1}}.
- I followed the Kafka 0.8.1 quick start guide to create a topic "test" with 1
partition and a replication factor of 1.
- I sent test messages to the topic "test" via the console producer.
- I read test messages from the topic "test" via the console consumer.
- Apart from producing and consuming a handful of test messages I also ran some
supposedly read-only admin commands such as "describing" the topic, and running
the consumer offset checker tool.
- At "some" point, Kafka was caught in an indefinite loop complaining about
"conflict in {{/controller}} data".
The following paragraphs list in more detail what I did before the error popped
up.
Producer:
{code}
$ sudo su - kafka
$ cd /opt/kafka
# This command returned no topics at this point = worked as expected
$ bin/kafka-topics.sh --list --zookeeper zookeeper1
# I created a topic, worked as expected
$ bin/kafka-topics.sh --create --zookeeper zookeeper1 --replication-factor 1
--partitions 1 --topic test
# I requested details of topic "test", worked as expected
$ bin/kafka-topics.sh --zookeeper zookeeper1 --describe --topic test
Topic:test PartitionCount:1ReplicationFactor:1 Configs:
Topic: test Partition: 0Leader: 0 Replicas: 0 Isr: 0
# I started a console producer and manually send a handful of test messages,
worked as expected (see consumer below)
$ bin/kafka-console-producer.sh --broker-list localhost:9092 --topic test
{code}
Consumer:
{code}
$ sudo su - kafka
$ cd /opt/kafka
# I started a console consumer, worked as expected (i.e. could read messages
sent by producer, see above)
$ bin/kafka-console-consumer.sh --zookeeper zookeeper1 --topic test
--from-beginning
{code}
Up to that point, everything worked. But then the Kafka broker went the way of
the dodo. As I said I can't pinpoint the cause, and re-running the same
commands on a fresh Kafka/ZooKeeper deployment (fresh VMs etc.) didn't
consistently trigger the issue like I hoped.
Here's what I did after the commands above, and at some point I eventually did
observe the original error described in this JIRA ticket. Again, at the moment
I cannot tell what actually triggered the bug.
Producer:
{code}
# Test-driving the consumer offset checker
$ bin/kafka-run-class.sh kafka.tools.ConsumerOffsetChecker --zkconnect
zookeeper1
# At this point consumer "foo" was not expected to exist.
$ bin/kafka-run-class.sh kafka.tools.ConsumerOffsetChecker --zkconnect
zookeeper1 --broker-info --group foo
#
# I then re-started the console producer (see below), now configured to use the
group id "foo".
#
{code}
Consumer:
{code}
# I re-started the console consumer, now configured to use the group id "foo".
$ bin/kafka-console-consumer.sh --zookeeper zookeeper1 --topic test
--from-beginning --group foo
{code}
At this point "describing" the topic gave the following info, indicating that
there was a problem (e.g. no leader for partition):
{code}
$ bin/kafka-topics.sh --zookeeper zookeeper1 --describe --topic test
Topic:test PartitionCount:1ReplicationFactor:1 Configs:
Topic: test Partition: 0Leader: -1 Replicas: 0 Isr:
{code}
Log files such as {{state-change.log}} showed these error messages:
{code}
[2014-04-29 07:44:47,816] TRACE Broker 0 cached l
[jira] [Comment Edited] (KAFKA-1029) Zookeeper leader election stuck in ephemeral node retry loop
[
https://issues.apache.org/jira/browse/KAFKA-1029?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13984265#comment-13984265
]
Michael Noll edited comment on KAFKA-1029 at 4/29/14 1:36 PM:
--
Interestingly I ran into a very similar issue while doing basic validation of
Kafka 0.8.1.1. Note that unlike Jason Rosenberg's case I was only using
code/tools/scripts that are shipped with Kafka (e.g. console producer and
console consumer).
Here is an example log message, which was repeated indefinitely:
{code}
[2014-04-29 09:48:27,207] INFO conflict in /controller data:
{"version":1,"brokerid":0,"timestamp":"1398764901156"} stored data:
{"version":1,"brokerid":0,"timestamp":"1398764894941"} (kafka.utils.ZkUtils$)
[2014-04-29 09:48:27,218] INFO I wrote this conflicted ephemeral node
[{"version":1,"brokerid":0,"timestamp":"1398764901156"}] at /controller a while
back in a different session, hence I will backoff for this node to be deleted
by Zookeeper and retry (kafka.utils.ZkUtils$)
{code}
*How to reproduce (unsolved)*
Unfortunately I cannot consistently reproduce the issue and, to be honest, I am
still not sure what actually triggers the bug. As such I can only summarize
what I did before and around the time when this bug was triggered, which I
could observe through errors in log files and through errors being displayed
after running certain commands. So yes, it's a bit like shooting in the dark.
Here's an overview of my test setup:
- I deployed Kafka 0.8.1.1 to one machine {{kafka1}} and ZooKeeper 3.4.5 to a
second machine {{zookeeper1}}.
- I followed the Kafka 0.8.1 quick start guide to create a topic "test" with 1
partition and a replication factor of 1.
- I sent test messages to the topic "test" via the console producer.
- I read test messages from the topic "test" via the console consumer.
- Apart from producing and consuming a handful of test messages I also ran some
supposedly read-only admin commands such as "describing" the topic, and running
the consumer offset checker tool.
- At "some" point, Kafka was caught in an indefinite loop complaining about
"conflict in {{/controller}} data".
The following paragraphs list in more detail what I did before the error popped
up.
Producer:
{code}
$ sudo su - kafka
$ cd /opt/kafka
# This command returned no topics at this point = worked as expected
$ bin/kafka-topics.sh --list --zookeeper zookeeper1
# I created a topic, worked as expected
$ bin/kafka-topics.sh --create --zookeeper zookeeper1 --replication-factor 1
--partitions 1 --topic test
# I requested details of topic "test", worked as expected
$ bin/kafka-topics.sh --zookeeper zookeeper1 --describe --topic test
Topic:test PartitionCount:1ReplicationFactor:1 Configs:
Topic: test Partition: 0Leader: 0 Replicas: 0 Isr: 0
# I started a console producer and manually send a handful of test messages,
worked as expected (see consumer below)
$ bin/kafka-console-producer.sh --broker-list localhost:9092 --topic test
{code}
Consumer:
{code}
$ sudo su - kafka
$ cd /opt/kafka
# I started a console consumer, worked as expected (i.e. could read messages
sent by producer, see above)
$ bin/kafka-console-consumer.sh --zookeeper zookeeper1 --topic test
--from-beginning
{code}
Up to that point, everything worked. But then the Kafka broker went the way of
the dodo. As I said I can't pinpoint the cause, and re-running the same
commands on a fresh Kafka/ZooKeeper deployment (fresh VMs etc.) didn't
consistently trigger the issue like I hoped.
Here's what I did after the commands above, and at some point I eventually did
observe the original error described in this JIRA ticket. Again, at the moment
I cannot tell what actually triggered the bug.
Producer:
{code}
# Test-driving the consumer offset checker
$ bin/kafka-run-class.sh kafka.tools.ConsumerOffsetChecker --zkconnect
zookeeper1
# At this point consumer "foo" was not expected to exist.
$ bin/kafka-run-class.sh kafka.tools.ConsumerOffsetChecker --zkconnect
zookeeper1 --broker-info --group foo
#
# I then re-started the console producer (see below), now configured to use the
group id "foo".
#
{code}
Consumer:
{code}
# I re-started the console consumer, now configured to use the group id "foo".
$ bin/kafka-console-consumer.sh --zookeeper zookeeper1 --topic test
--from-beginning --group foo
{code}
At this point "describing" the topic gave the following info, indicating that
there was a problem (e.g. no leader for partition, no ISR available):
{code}
$ bin/kafka-topics.sh --zookeeper zookeeper1 --describe --topic test
Topic:test PartitionCount:1ReplicationFactor:1 Configs:
Topic: test Partition: 0Leader: -1 Replicas: 0 Isr:
{code}
Log files such as {{state-change.log}} showed these error messages:
{code}
[2014-04-29 07:44:47,816] TRACE
[jira] [Comment Edited] (KAFKA-1029) Zookeeper leader election stuck in ephemeral node retry loop
[
https://issues.apache.org/jira/browse/KAFKA-1029?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13984265#comment-13984265
]
Michael Noll edited comment on KAFKA-1029 at 4/29/14 1:45 PM:
--
Interestingly I ran into a very similar issue while doing basic validation of
Kafka 0.8.1.1. Note that unlike Jason Rosenberg's case I was only using
code/tools/scripts that are shipped with Kafka (e.g. console producer and
console consumer).
Here is an example log message, which was repeated indefinitely:
{code}
[2014-04-29 09:48:27,207] INFO conflict in /controller data:
{"version":1,"brokerid":0,"timestamp":"1398764901156"} stored data:
{"version":1,"brokerid":0,"timestamp":"1398764894941"} (kafka.utils.ZkUtils$)
[2014-04-29 09:48:27,218] INFO I wrote this conflicted ephemeral node
[{"version":1,"brokerid":0,"timestamp":"1398764901156"}] at /controller a while
back in a different session, hence I will backoff for this node to be deleted
by Zookeeper and retry (kafka.utils.ZkUtils$)
{code}
*How to reproduce (unsolved)*
Unfortunately I cannot consistently reproduce the issue and, to be honest, I am
still not sure what actually triggers the bug. As such I can only summarize
what I did before and around the time when this bug was triggered, which I
could observe through errors in log files and through errors being displayed
after running certain commands. So yes, it's a bit like shooting in the dark.
Here's an overview of my test setup:
- I deployed Kafka 0.8.1.1 to one machine {{kafka1}} and ZooKeeper 3.4.5 to a
second machine {{zookeeper1}}.
- I followed the Kafka 0.8.1 quick start guide to create a topic "test" with 1
partition and a replication factor of 1.
- I sent test messages to the topic "test" via the console producer.
- I read test messages from the topic "test" via the console consumer.
- Apart from producing and consuming a handful of test messages I also ran some
supposedly read-only admin commands such as "describing" the topic, and running
the consumer offset checker tool.
- At "some" point, Kafka was caught in an indefinite loop complaining about
"conflict in {{/controller}} data".
The following paragraphs list in more detail what I did before the error popped
up.
Producer:
{code}
$ sudo su - kafka
$ cd /opt/kafka
# This command returned no topics at this point = worked as expected
$ bin/kafka-topics.sh --list --zookeeper zookeeper1
# I created a topic, worked as expected
$ bin/kafka-topics.sh --create --zookeeper zookeeper1 --replication-factor 1
--partitions 1 --topic test
# I requested details of topic "test", worked as expected
$ bin/kafka-topics.sh --zookeeper zookeeper1 --describe --topic test
Topic:test PartitionCount:1ReplicationFactor:1 Configs:
Topic: test Partition: 0Leader: 0 Replicas: 0 Isr: 0
# I started a console producer and manually send a handful of test messages,
worked as expected (see consumer below)
$ bin/kafka-console-producer.sh --broker-list localhost:9092 --topic test
{code}
Consumer:
{code}
$ sudo su - kafka
$ cd /opt/kafka
# I started a console consumer, worked as expected (i.e. could read messages
sent by producer, see above)
$ bin/kafka-console-consumer.sh --zookeeper zookeeper1 --topic test
--from-beginning
{code}
Up to that point, everything worked. But then the Kafka broker went the way of
the dodo. As I said I can't pinpoint the cause, and re-running the same
commands on a fresh Kafka/ZooKeeper deployment (fresh VMs etc.) didn't
consistently trigger the issue like I hoped.
Here's what I did after the commands above, and at some point I eventually did
observe the original error described in this JIRA ticket. Again, at the moment
I cannot tell what actually triggered the bug.
Producer:
{code}
# Test-driving the consumer offset checker
$ bin/kafka-run-class.sh kafka.tools.ConsumerOffsetChecker --zkconnect
zookeeper1
# At this point consumer "foo" was not expected to exist.
$ bin/kafka-run-class.sh kafka.tools.ConsumerOffsetChecker --zkconnect
zookeeper1 --broker-info --group foo
#
# I then re-started the console producer (see below), now configured to use the
group id "foo".
#
{code}
Consumer:
{code}
# I re-started the console consumer, now configured to use the group id "foo".
$ bin/kafka-console-consumer.sh --zookeeper zookeeper1 --topic test
--from-beginning --group foo
{code}
At this point "describing" the topic gave the following info, indicating that
there was a problem (e.g. no leader for partition, no ISR available):
{code}
$ bin/kafka-topics.sh --zookeeper zookeeper1 --describe --topic test
Topic:test PartitionCount:1ReplicationFactor:1 Configs:
Topic: test Partition: 0Leader: -1 Replicas: 0 Isr:
{code}
Log files such as {{state-change.log}} showed these error messages:
{code}
[2014-04-29 07:44:47,673] TRA
[jira] [Comment Edited] (KAFKA-1029) Zookeeper leader election stuck in ephemeral node retry loop
[
https://issues.apache.org/jira/browse/KAFKA-1029?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13984265#comment-13984265
]
Michael Noll edited comment on KAFKA-1029 at 4/29/14 1:45 PM:
--
Interestingly I ran into a very similar issue while doing basic validation of
Kafka 0.8.1.1. Note that unlike Jason Rosenberg's case I was only using
code/tools/scripts that are shipped with Kafka (e.g. console producer and
console consumer).
Here is an example log message, which was repeated indefinitely:
{code}
[2014-04-29 09:48:27,207] INFO conflict in /controller data:
{"version":1,"brokerid":0,"timestamp":"1398764901156"} stored data:
{"version":1,"brokerid":0,"timestamp":"1398764894941"} (kafka.utils.ZkUtils$)
[2014-04-29 09:48:27,218] INFO I wrote this conflicted ephemeral node
[{"version":1,"brokerid":0,"timestamp":"1398764901156"}] at /controller a while
back in a different session, hence I will backoff for this node to be deleted
by Zookeeper and retry (kafka.utils.ZkUtils$)
{code}
*How to reproduce (unsolved)*
Unfortunately I cannot consistently reproduce the issue and, to be honest, I am
still not sure what actually triggers the bug. As such I can only summarize
what I did before and around the time when this bug was triggered, which I
could observe through errors in log files and through errors being displayed
after running certain commands. So yes, it's a bit like shooting in the dark.
Here's an overview of my test setup:
- I deployed Kafka 0.8.1.1 to one machine {{kafka1}} and ZooKeeper 3.4.5 to a
second machine {{zookeeper1}}.
- I followed the Kafka 0.8.1 quick start guide to create a topic "test" with 1
partition and a replication factor of 1.
- I sent test messages to the topic "test" via the console producer.
- I read test messages from the topic "test" via the console consumer.
- Apart from producing and consuming a handful of test messages I also ran some
supposedly read-only admin commands such as "describing" the topic, and running
the consumer offset checker tool.
- At "some" point, Kafka was caught in an indefinite loop complaining about
"conflict in {{/controller}} data".
The following paragraphs list in more detail what I did before the error popped
up.
Producer:
{code}
$ sudo su - kafka
$ cd /opt/kafka
# This command returned no topics at this point = worked as expected
$ bin/kafka-topics.sh --list --zookeeper zookeeper1
# I created a topic, worked as expected
$ bin/kafka-topics.sh --create --zookeeper zookeeper1 --replication-factor 1
--partitions 1 --topic test
# I requested details of topic "test", worked as expected
$ bin/kafka-topics.sh --zookeeper zookeeper1 --describe --topic test
Topic:test PartitionCount:1ReplicationFactor:1 Configs:
Topic: test Partition: 0Leader: 0 Replicas: 0 Isr: 0
# I started a console producer and manually send a handful of test messages,
worked as expected (see consumer below)
$ bin/kafka-console-producer.sh --broker-list localhost:9092 --topic test
{code}
Consumer:
{code}
$ sudo su - kafka
$ cd /opt/kafka
# I started a console consumer, worked as expected (i.e. could read messages
sent by producer, see above)
$ bin/kafka-console-consumer.sh --zookeeper zookeeper1 --topic test
--from-beginning
{code}
Up to that point, everything worked. But then the Kafka broker went the way of
the dodo. As I said I can't pinpoint the cause, and re-running the same
commands on a fresh Kafka/ZooKeeper deployment (fresh VMs etc.) didn't
consistently trigger the issue like I hoped.
Here's what I did after the commands above, and at some point I eventually did
observe the original error described in this JIRA ticket. Again, at the moment
I cannot tell what actually triggered the bug.
Producer:
{code}
# Test-driving the consumer offset checker
$ bin/kafka-run-class.sh kafka.tools.ConsumerOffsetChecker --zkconnect
zookeeper1
# At this point consumer "foo" was not expected to exist.
$ bin/kafka-run-class.sh kafka.tools.ConsumerOffsetChecker --zkconnect
zookeeper1 --broker-info --group foo
#
# I then re-started the console producer (see below), now configured to use the
group id "foo".
#
{code}
Consumer:
{code}
# I re-started the console consumer, now configured to use the group id "foo".
$ bin/kafka-console-consumer.sh --zookeeper zookeeper1 --topic test
--from-beginning --group foo
{code}
At this point "describing" the topic gave the following info, indicating that
there was a problem (e.g. no leader for partition, no ISR available):
{code}
$ bin/kafka-topics.sh --zookeeper zookeeper1 --describe --topic test
Topic:test PartitionCount:1ReplicationFactor:1 Configs:
Topic: test Partition: 0Leader: -1 Replicas: 0 Isr:
{code}
Log files such as {{state-change.log}} showed these error messages:
{code}
[2014-04-29 07:44:47,673] TRA
[jira] [Comment Edited] (KAFKA-1029) Zookeeper leader election stuck in ephemeral node retry loop
[
https://issues.apache.org/jira/browse/KAFKA-1029?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13985617#comment-13985617
]
Michael Noll edited comment on KAFKA-1029 at 4/30/14 3:27 PM:
--
I could finally reproduce the bug again, though still not consistently yet.
And I think I have an idea what the root cause might be: I was test-driving
Kafka in several VMs locally on a Mac MBP laptop, and the energy saver settings
(or sth similar) might be responsible for triggering the problem when the
laptop was idle. (In the test run below I intentionally let the laptop idle
for 2-3 hours after creating a "test" topic and sending/consuming a few test
massages.) The timestamp of when the problem was triggered (11:01) correlates
with me unlocking the laptop (user screen). What's strange is that the laptop
is configured not to go to sleep when idle, the hard disk is not asked to sleep
either (and even if you did enable that setting in Mac OS X it does not have an
effect on SSD's, which is the only disk installed in the laptop I was using),
etc. -- only the display is allowed to turn off after 10 minutes. So even
though the laptop is configured to be "always on" there apparently is something
that throws off Kafka/ZooKeeper. Also, as I said in my earlier comment I still
cannot reproduce the issue consistently, i.e. sometimes Kafka/ZK work correctly
after idling/unlocking; still I think the root cause has ultimately to do with
idling on Mac OS X.
FWIW I still list further log messages and details just in case that
information may be useful in the future.
@Jun Rao: Yes, I did see ZK expiration in {{controller.log}}:
{code}
INFO [SessionExpirationListener on 0], ZK expired; shut down all controller
components and try to re-elect
(kafka.controller.KafkaController$SessionExpirationListener)
{code}
Below are some further details. Things turn bad at 11:01.
*kafka1 (Kafka broker)*
{{server.log}}
{code}
[2014-04-30 07:18:56,481] INFO Completed load of log test-0 with log end offset
0 (kafka.log.Log)
[2014-04-30 07:18:56,485] INFO Created log for partition [test,0] in
/app/kafka/log with properties {segment.index.bytes -> 10485760,
file.delete.delay.ms -> 6, segment.bytes -> 1073741824, flush.ms ->
9223372036854775807, delete.retention.ms -> 8640, index.interval.bytes ->
4096, retention.bytes -> -1, cleanup.policy -> delete, segment.ms -> 17280,
max.message.bytes -> 112, flush.messages -> 9223372036854775807,
min.cleanable.dirty.ratio -> 0.5, retention.ms -> 17280}.
(kafka.log.LogManager)
[2014-04-30 07:18:56,486] WARN Partition [test,0] on broker 0: No checkpointed
highwatermark is found for partition [test,0] (kafka.cluster.Partition)
[2014-04-30 07:19:32,637] INFO Closing socket connection to /127.0.1.1.
(kafka.network.Processor)
[2014-04-30 07:19:37,328] INFO Closing socket connection to /127.0.0.1.
(kafka.network.Processor)
[2014-04-30 07:19:56,356] INFO Closing socket connection to /127.0.1.1.
(kafka.network.Processor)
[2014-04-30 07:20:52,090] ERROR Closing socket for /127.0.1.1 because of error
(kafka.network.Processor)
java.io.IOException: Connection reset by peer
at sun.nio.ch.FileDispatcher.read0(Native Method)
at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:39)
at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:251)
at sun.nio.ch.IOUtil.read(IOUtil.java:224)
at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:254)
at kafka.utils.Utils$.read(Utils.scala:375)
at
kafka.network.BoundedByteBufferReceive.readFrom(BoundedByteBufferReceive.scala:54)
at kafka.network.Processor.read(SocketServer.scala:347)
at kafka.network.Processor.run(SocketServer.scala:245)
at java.lang.Thread.run(Thread.java:701)
[2014-04-30 07:21:02,805] INFO Closing socket connection to /127.0.1.1.
(kafka.network.Processor)
[2014-04-30 07:21:05,803] INFO Closing socket connection to /127.0.0.1.
(kafka.network.Processor)
[2014-04-30 11:01:57,138] INFO Closing socket connection to /127.0.1.1.
(kafka.network.Processor)
[2014-04-30 11:01:59,561] INFO Closing socket connection to /127.0.1.1.
(kafka.network.Processor)
[2014-04-30 11:01:59,648] INFO 0 successfully elected as leader
(kafka.server.ZookeeperLeaderElector)
[2014-04-30 11:01:59,692] INFO conflict in /controller data:
{"version":1,"brokerid":0,"timestamp":"1398855719690"} stored data:
{"version":1,"brokerid":0,"timestamp":"1398855719646"} (kafka.utils.ZkUtils$)
[2014-04-30 11:01:59,699] INFO I wrote this conflicted ephemeral node
[{"version":1,"brokerid":0,"timestamp":"1398855719690"}] at /controller 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-04-30 11:02:05,704] INFO conflict in /controller data:
{"version":1,"brokerid":
[jira] [Comment Edited] (KAFKA-1029) Zookeeper leader election stuck in ephemeral node retry loop
[
https://issues.apache.org/jira/browse/KAFKA-1029?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13985617#comment-13985617
]
Michael Noll edited comment on KAFKA-1029 at 4/30/14 3:32 PM:
--
I could finally reproduce the bug again, though still not consistently yet.
And I think I have an idea what the root cause might be: I was test-driving
Kafka in several VMs locally on a Mac MBP laptop, and the energy saver settings
(or sth similar) might be responsible for triggering the problem when the
laptop was idle. (In the test run below I intentionally let the laptop idle
for 2-3 hours after creating a "test" topic and sending/consuming a few test
massages.) The timestamp of when the problem was triggered (11:01) correlates
with me unlocking the laptop (user screen). What's strange is that the laptop
is configured not to go to sleep when idle, the hard disk is not asked to sleep
either (and even if you did enable that setting in Mac OS X it does not have an
effect on SSD's, which is the only disk installed in the laptop I was using),
etc. -- only the display is allowed to turn off after 10 minutes. So even
though the laptop is configured to be "always on" there apparently is something
that throws off Kafka/ZooKeeper. Also, as I said in my earlier comment I still
cannot reproduce the issue consistently, i.e. sometimes Kafka/ZK work correctly
after idling/unlocking; still I think the root cause has ultimately to do with
idling on Mac OS X.
Lastly, I don't know what the expected failure handling of Kafka/ZK is in such
a scenario. From what I can read from the logs below my setup seems to have
simulated what could happen during a network partitioning (Kafka broker could
not talk to ZooKeeper for a long time, hence ZK session expired, then things
turned bad).
FWIW I still list further log messages and details just in case that
information may be useful in the future.
@Jun Rao: Yes, I did see ZK expiration in {{controller.log}}:
{code}
INFO [SessionExpirationListener on 0], ZK expired; shut down all controller
components and try to re-elect
(kafka.controller.KafkaController$SessionExpirationListener)
{code}
Below are some further details. Things turn bad at 11:01.
*kafka1 (Kafka broker)*
{{server.log}}
{code}
[2014-04-30 07:18:56,481] INFO Completed load of log test-0 with log end offset
0 (kafka.log.Log)
[2014-04-30 07:18:56,485] INFO Created log for partition [test,0] in
/app/kafka/log with properties {segment.index.bytes -> 10485760,
file.delete.delay.ms -> 6, segment.bytes -> 1073741824, flush.ms ->
9223372036854775807, delete.retention.ms -> 8640, index.interval.bytes ->
4096, retention.bytes -> -1, cleanup.policy -> delete, segment.ms -> 17280,
max.message.bytes -> 112, flush.messages -> 9223372036854775807,
min.cleanable.dirty.ratio -> 0.5, retention.ms -> 17280}.
(kafka.log.LogManager)
[2014-04-30 07:18:56,486] WARN Partition [test,0] on broker 0: No checkpointed
highwatermark is found for partition [test,0] (kafka.cluster.Partition)
[2014-04-30 07:19:32,637] INFO Closing socket connection to /127.0.1.1.
(kafka.network.Processor)
[2014-04-30 07:19:37,328] INFO Closing socket connection to /127.0.0.1.
(kafka.network.Processor)
[2014-04-30 07:19:56,356] INFO Closing socket connection to /127.0.1.1.
(kafka.network.Processor)
[2014-04-30 07:20:52,090] ERROR Closing socket for /127.0.1.1 because of error
(kafka.network.Processor)
java.io.IOException: Connection reset by peer
at sun.nio.ch.FileDispatcher.read0(Native Method)
at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:39)
at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:251)
at sun.nio.ch.IOUtil.read(IOUtil.java:224)
at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:254)
at kafka.utils.Utils$.read(Utils.scala:375)
at
kafka.network.BoundedByteBufferReceive.readFrom(BoundedByteBufferReceive.scala:54)
at kafka.network.Processor.read(SocketServer.scala:347)
at kafka.network.Processor.run(SocketServer.scala:245)
at java.lang.Thread.run(Thread.java:701)
[2014-04-30 07:21:02,805] INFO Closing socket connection to /127.0.1.1.
(kafka.network.Processor)
[2014-04-30 07:21:05,803] INFO Closing socket connection to /127.0.0.1.
(kafka.network.Processor)
[2014-04-30 11:01:57,138] INFO Closing socket connection to /127.0.1.1.
(kafka.network.Processor)
[2014-04-30 11:01:59,561] INFO Closing socket connection to /127.0.1.1.
(kafka.network.Processor)
[2014-04-30 11:01:59,648] INFO 0 successfully elected as leader
(kafka.server.ZookeeperLeaderElector)
[2014-04-30 11:01:59,692] INFO conflict in /controller data:
{"version":1,"brokerid":0,"timestamp":"1398855719690"} stored data:
{"version":1,"brokerid":0,"timestamp":"1398855719646"} (kafka.utils.ZkUtils$)
[2014-04-30 11:01:59,699] INFO I w
[jira] [Comment Edited] (KAFKA-1029) Zookeeper leader election stuck in ephemeral node retry loop
[
https://issues.apache.org/jira/browse/KAFKA-1029?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13985617#comment-13985617
]
Michael Noll edited comment on KAFKA-1029 at 4/30/14 3:33 PM:
--
I could finally reproduce the bug again, though still not consistently yet.
And I think I have an idea what the root cause might be: I was test-driving
Kafka in several VMs locally on a Mac MBP laptop, and the energy saver settings
(or sth similar) might be responsible for triggering the problem when the
laptop was idle. (In the test run below I intentionally let the laptop idle
for 2-3 hours after creating a "test" topic and sending/consuming a few test
massages.) The timestamp of when the problem was triggered (11:01) correlates
with me unlocking the laptop (user screen). What's strange is that the laptop
is configured not to go to sleep when idle, the hard disk is not asked to sleep
either (and even if you did enable that setting in Mac OS X it does not have an
effect on SSD's, which is the only disk installed in the laptop I was using),
etc. -- only the display is allowed to turn off after 10 minutes. So even
though the laptop is configured to be "always on" there apparently is something
that throws off Kafka/ZooKeeper. Also, as I said in my earlier comment I still
cannot reproduce the issue consistently, i.e. sometimes Kafka/ZK work correctly
after idling/unlocking; still I think the root cause has ultimately to do with
idling on Mac OS X.
Lastly, I don't know what the expected failure handling of Kafka/ZK is in such
a scenario. From what I can read from the logs below my setup seems to have
simulated what could happen during a network partitioning (Kafka broker could
not talk to ZooKeeper for a long time, hence ZK session expired, then Kafka
could talk again to ZK, but couldn't fully recover).
FWIW I still list further log messages and details just in case that
information may be useful in the future.
@Jun Rao: Yes, I did see ZK expiration in {{controller.log}}:
{code}
INFO [SessionExpirationListener on 0], ZK expired; shut down all controller
components and try to re-elect
(kafka.controller.KafkaController$SessionExpirationListener)
{code}
Below are some further details. Things turn bad at 11:01.
*kafka1 (Kafka broker)*
{{server.log}}
{code}
[2014-04-30 07:18:56,481] INFO Completed load of log test-0 with log end offset
0 (kafka.log.Log)
[2014-04-30 07:18:56,485] INFO Created log for partition [test,0] in
/app/kafka/log with properties {segment.index.bytes -> 10485760,
file.delete.delay.ms -> 6, segment.bytes -> 1073741824, flush.ms ->
9223372036854775807, delete.retention.ms -> 8640, index.interval.bytes ->
4096, retention.bytes -> -1, cleanup.policy -> delete, segment.ms -> 17280,
max.message.bytes -> 112, flush.messages -> 9223372036854775807,
min.cleanable.dirty.ratio -> 0.5, retention.ms -> 17280}.
(kafka.log.LogManager)
[2014-04-30 07:18:56,486] WARN Partition [test,0] on broker 0: No checkpointed
highwatermark is found for partition [test,0] (kafka.cluster.Partition)
[2014-04-30 07:19:32,637] INFO Closing socket connection to /127.0.1.1.
(kafka.network.Processor)
[2014-04-30 07:19:37,328] INFO Closing socket connection to /127.0.0.1.
(kafka.network.Processor)
[2014-04-30 07:19:56,356] INFO Closing socket connection to /127.0.1.1.
(kafka.network.Processor)
[2014-04-30 07:20:52,090] ERROR Closing socket for /127.0.1.1 because of error
(kafka.network.Processor)
java.io.IOException: Connection reset by peer
at sun.nio.ch.FileDispatcher.read0(Native Method)
at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:39)
at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:251)
at sun.nio.ch.IOUtil.read(IOUtil.java:224)
at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:254)
at kafka.utils.Utils$.read(Utils.scala:375)
at
kafka.network.BoundedByteBufferReceive.readFrom(BoundedByteBufferReceive.scala:54)
at kafka.network.Processor.read(SocketServer.scala:347)
at kafka.network.Processor.run(SocketServer.scala:245)
at java.lang.Thread.run(Thread.java:701)
[2014-04-30 07:21:02,805] INFO Closing socket connection to /127.0.1.1.
(kafka.network.Processor)
[2014-04-30 07:21:05,803] INFO Closing socket connection to /127.0.0.1.
(kafka.network.Processor)
[2014-04-30 11:01:57,138] INFO Closing socket connection to /127.0.1.1.
(kafka.network.Processor)
[2014-04-30 11:01:59,561] INFO Closing socket connection to /127.0.1.1.
(kafka.network.Processor)
[2014-04-30 11:01:59,648] INFO 0 successfully elected as leader
(kafka.server.ZookeeperLeaderElector)
[2014-04-30 11:01:59,692] INFO conflict in /controller data:
{"version":1,"brokerid":0,"timestamp":"1398855719690"} stored data:
{"version":1,"brokerid":0,"timestamp":"1398855719646"} (kafka.utils.ZkUti
