Heartbeat failed for group xxxWorker because it is rebalancing

[ealfatt]

Hi all
I'm facing this problem that is driving to me crazy with 1.4.1 version of Kafka python
the instruction that i perform are:

• create a consumer in this way
  KafkaConsumer(bootstrap_servers=kafka_multi_hosts,
  auto_offset_reset=earliest,
  enable_auto_commit=False,
  group_id=group_name,
  reconnect_backoff_ms=1,
  consumer_timeout_ms=5000)
• subscribe on a topics
• finally the consumer.poll(500)

no problem till now but then in the log i see:

[INFO] 03/08/2018 02:52:53 PM Subscribe executed.
[INFO] 03/08/2018 02:52:53 PM Initialization pool executed.
[INFO] 03/08/2018 02:52:53 PM Subscribed to topic: event
[INFO] 03/08/2018 02:52:53 PM eventHandle connected
[WARNING] 03/08/2018 02:53:23 PM Heartbeat failed for group emsWorker because it is rebalancing
[WARNING] 03/08/2018 02:53:26 PM Heartbeat failed for group emsWorker because it is rebalancing
[WARNING] 03/08/2018 02:53:29 PM Heartbeat failed for group emsWorker because it is rebalancing
[WARNING] 03/08/2018 02:53:32 PM Heartbeat failed for group emsWorker because it is rebalancing
......
......
......
[WARNING] 03/08/2018 02:57:48 PM Heartbeat failed for group emsWorker because it is rebalancing
[WARNING] 03/08/2018 02:57:51 PM Heartbeat failed for group emsWorker because it is rebalancing
[INFO] 03/08/2018 02:57:53 PM Leaving consumer group (group_name).

why?

I've also added the option max_poll_records=50 in the kafkaConsumer definition but nothing is changed

@dpkp can you help me?
do you know if the 1.4.1 version presents some problem about that? Because in the previous version I can not see this problem.

thanks in advance

[andrewkowalik]

@ealfatt Yeah this is definitely newer behavior since there was not a background heartbeat thread so it basically happened during polling.

I am guessing after the last message your worker is not rejoining?

[dpkp]

kafka-python 1.4 changes heartbeats to a background thread, and it enables additional timeout configurations in max_poll_interval_ms and session_timeout_ms . It is certainly possible there is a bug in the code, but all of our tests pass so I'm not aware of anything obvious. Can you enable debug logs and see if anything looks strange?

[ealfatt]

@infecto yes, after the last message my worker was not rejoining (thanks for the response)
Hi @dpkp, thanks for the response. I'll try to play with those two parameter and try to enable the debug logs (how i can do that? is it explained in the documentation?)

[ealfatt]

Hi @dpkp
below 2 logs of what i can see when the issue above happen.

log1.txt
log2.txt

could yo give a look and let me know your feedback?
thanks a lot in advance

[dpkp]

This log entry: Heartbeat poll expired, leaving group means that your consumer application is not processing messages fast enough. What is your max_poll_interval_ms configuration? Is there something that might block your poll loop for longer than that amount?

[slash31]

After upgrading to 1.4.3 from 1.3.5 a couple of weeks ago, I started seeing my consumer groups constantly rebalancing at the session timeout setting, no matter what I set it to. I tried:

• adjusting the poll/heartbeat/session timers, as well as max recs polled
• setting the assignment algorithm deterministically to round robin
• turning off auto-commit and manually committing
• upgrading Kafka to the latest available parcel

Eventually, I ended up writing a handler into the application where it would kill the consumer if the commit failed, then reincarnate it in the job queue and start it back up. You can imagine that with the default settings it was effectively in a perpetual loop of rebalancing, then reading a high volume of messages - the broker traffic graph looked like a perfect sawtooth.

I see heartbeat requests and successful responses, but commit responses with an Error 25 just before the error's thrown that the consumer can't commit successfully:

2018-10-28 20:35:06,563 kafka.conn DEBUG <BrokerConnection node_id=772 host=xvda-c14.xv.dc.openx.org:9092 [IPv4 ('10.11.3.14', 9092)]> Response 103 (0.808000564575 ms): OffsetCommitResponse_v2(topics=[(topic=u'netflow.raw', partitions=[(partition=0, error_code=25), (partition=5, error_code=25), (partition=10, error_code=25)])])
2018-10-28 20:35:06,563 kafka.conn DEBUG <BrokerConnection node_id=772 host=xvda-c14.xv.dc.openx.org:9092 [IPv4 ('10.11.3.14', 9092)]> Response 103 (0.808000564575 ms): OffsetCommitResponse_v2(topics=[(topic=u'netflow.raw', partitions=[(partition=0, error_code=25), (partition=5, error_code=25), (partition=10, error_code=25)])])
2018-10-28 20:35:06,563 kafka.coordinator.consumer DEBUG OffsetCommit for group netflow_raw failed: [Error 25] UnknownMemberIdError: netflow_raw
2018-10-28 20:35:06,563 kafka.coordinator.consumer DEBUG OffsetCommit for group netflow_raw failed: [Error 25] UnknownMemberIdError: netflow_raw

I downgraded the version to 1.3.5 again and everything is happy, all consumers have been running smoothly for hours now with no issue and the broker traffic graphs are flat. One other thing I noticed is a lot of wow/flutter on graphs of this data (netflow) when using 1.4.3, which smoothed out again after downgrading. The setup for each of my clusters is 10 consumers running on one host via multiprocess, consuming single topic with 10 partitions on three brokers. The application is very simple/lightweight; it reads 2k-4k messages per second depending on time of day, formats/augments some of the data, and then dumps it to CrateDB. With the 1.3.5 client, I can easily get > 20MBps throughput with this application (average is ~2MBps in production when the consumers are caught up), with each db write of 5k rows taking < 1s.

If you're interested in any of the other logs/graphs from either kafka-python or my brokers, I'd be happy to share.

[julienaubert]

I see this as well.

I have a set of consumers, each polling 500 records at a time, being part of group generation N

Another consumer joins. Causing a rebalance. Generation N+1

I can see in the logs that a consumer, while processing the 500 records that it got at generation N, will log that the heart beat failed due to rebalancing. But the processing code does not learn this, so it continues processing.. (I should fix so that the processing checks for this case and aborts. Not sure how?)

I can see that the broker does not include this consumer in the rebalanced group (at N+1). I wonder why, as it was sending heart-beats? Is this considered a bug?

I only quickly glimpsed at the code. It seems that this could happen: HeartBeat ends up in a state "do not send more heartbeats" due to rebalancing and the broker taking sufficiently long time to perform the rebalancing. So the consumer has stopped sending heartbeats, and is subsequently not included. It seems some special-case handling would be needed (eg reset timeouts) when rebalancing occurs?

(The rebalancing keeps happening as when this consumer that did not become part of generation N+1 later tries to join again, the same thing will happen, this time some other consumer will be busy processing and not become part of generation N+2... and so on and so on.)

[88manpreet]

We have also started seeing this error quite frequently with the upgrade to 1.4.3. So far none of tuning has turned out to be helpful.

[dpkp]

Can you try 1.4.4 ? There are some fixes included that may help.

…

On Wed, Nov 21, 2018, 3:30 PM Manpreet Singh ***@***.*** wrote: We have also started seeing this error quite frequently with the upgrade to 1.4.3. So far none of tuning has turned out to be helpful. — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#1418 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AAzetC4CfcGRGl2q5Ktv8GI10HysmoIxks5uxeIAgaJpZM4Si39s> .

[rafenden]

It happens to me as well, I'm running 1.4.4

[goern]

I can see it on 1.4.4 too.

[rabindrakm]

Has there been a solution for this ?