sarama - rebalancing issue - subscription to topic closed

[Shweta Sureshkumar]

Hi All,

I am using sarama library to perform kafka operations from my go application.

Kafka version - 2.2.1

Go version- 1.16

Sarama library - v1.30.0

I have a topic - testtopic with 3 partitions and 1 consumer.

This topic is not receiving any messages at the moment.

I have overriden the below config -

config.Consumer.Group.Session.Timeout = 30 * time.Second

Observing rebalance for this topic every 30 seconds.

Kafka logs:

kafka.coordinator.group.GroupCoordinator: [GroupCoordinator 37]: Preparing to rebalance group testtopic in state PreparingRebalance with old generation 55849 (__consumer_offsets-37) (reason: Updating metadata for member sarama-xxx)

2021-11-29 08:29:15,334 INFO kafka.coordinator.group.GroupCoordinator: [GroupCoordinator 37]: Stabilized group testtopic generation 55850 (__consumer_offsets-37)

2021-11-29 08:29:15,335 INFO kafka.coordinator.group.GroupCoordinator: [GroupCoordinator 37]: Assignment received from leader for group testtopic for generation 55850

Client logs:

consumer.go:830: consumer/broker/37 closed dead subscription to testtopic_delay1/2

2021/11/29 10:40:30.597481 consumer_group.go:510: loop check partition number coroutine will exit, topics [testtopic_delay1]

2021/11/29 10:40:30.597545 sarama.go:122: client/metadata fetching metadata for [[testtopic_delay1] kaas-dev:9092] from broker %!s(MISSING)

2021/11/29 10:40:30.629409 consumer.go:830: consumer/broker/41 closed dead subscription to testtopic/0

2021/11/29 10:40:30.629519 consumer_group.go:510: loop check partition number coroutine will exit, topics [testtopic]

2021/11/29 10:40:30.632287 consumer.go:830: consumer/broker/43 closed dead subscription to testtopic/1

2021/11/29 10:40:30.665543 consumer.go:830: consumer/broker/43 closed dead subscription to testtopic_delay1/0

2021/11/29 10:40:30.665599 sarama.go:122: client/metadata fetching metadata for [[testtopic_delay1] ec2-instance.compute-1.amazonaws.com:9092] from broker %!s(MISSING)

2021/11/29 10:40:30.665650 consumer_group.go:510: loop check partition number coroutine will exit, topics [testtopic_delay1]

2021/11/29 10:40:30.725432 consumer.go:830: consumer/broker/62 closed dead subscription to testtopic_delay1/1

2021/11/29 10:40:30.725503 sarama.go:122: client/metadata fetching metadata for [[testtopic_delay1] kaas-dev:9092] from broker %!s(MISSING)

2021/11/29 10:40:30.725575 consumer_group.go:510: loop check partition number coroutine will exit, topics [testtopic_delay1]

2021/11/29 10:40:30.742642 consumer.go:830: consumer/broker/62 closed dead subscription to testtopic/2

2021/11/29 10:40:30.742892 sarama.go:122: client/metadata fetching metadata for [[testtopic] kaas-dev:9092] from broker %!s(MISSING)

2021/11/29 10:40:33.583386 sarama.go:122: client/metadata fetching metadata for [[testtopic_delay1] kaas-dev:9092] from broker %!s(MISSING)

2021/11/29 10:40:33.583397 consumer_group.go:510: loop check partition number coroutine will exit, topics [testtopic_delay1]

2021/11/29 10:40:33.598433 sarama.go:122: client/coordinator requesting coordinator for consumergroup [testtopic kaas-dev:9092] from %!s(MISSING)

2021/11/29 10:40:33.598441 sarama.go:122: client/coordinator requesting coordinator for consumergroup [testtopic kaas-dev:9092] from %!s(MISSING)

2021/11/29 10:40:33.598516 sarama.go:122: client/coordinator requesting coordinator for consumergroup [testtopic ec2-instance.compute-1.amazonaws.com:9092] from %!s(MISSING)

2021/11/29 10:40:33.598952 sarama.go:122: client/coordinator requesting coordinator for consumergroup [testtopic kaas-dev:9092] from %!s(MISSING)

2021/11/29 10:40:33.600286 sarama.go:122: client/coordinator coordinator for consumergroup [testtopic %!s(int32=37) ec2-3-209-69-46.compute-1.amazonaws.com:9092] is #%!d(MISSING) (%!s(MISSING))

2021/11/29 10:40:33.600485 sarama.go:122: client/coordinator coordinator for consumergroup [testtopic %!s(int32=37) ec2-3-209-69-46.compute-1.amazonaws.com:9092] is #%!d(MISSING) (%!s(MISSING))

2021/11/29 10:40:33.600548 sarama.go:122: client/coordinator coordinator for consumergroup [testtopic %!s(int32=37) ec2-3-209-69-46.compute-1.amazonaws.com:9092] is #%!d(MISSING) (%!s(MISSING))

2021/11/29 10:40:33.600628 sarama.go:122: client/coordinator coordinator for consumergroup [testtopic %!s(int32=37) ec2-3-209-69-46.compute-1.amazonaws.com:9092] is #%!d(MISSING) (%!s(MISSING))

2021/11/29 10:40:33.602044 consumer.go:824: consumer/broker/43 added subscription to testtopic_delay1/0

2021/11/29 10:40:33.602143 consumer.go:824: consumer/broker/62 added subscription to testtopic_delay1/1

2021/11/29 10:40:33.602461 consumer.go:824: consumer/broker/37 added subscription to testtopic_delay1/2

2021/11/29 10:40:33.603159 consumer.go:824: consumer/broker/41 added subscription to testtopic/0

2021/11/29 10:40:33.603394 consumer.go:824: consumer/broker/62 added subscription to testtopic/2

2021/11/29 10:40:33.603755 consumer.go:824: consumer/broker/43 added subscription to testtopic/1

From the client logs, we see that the subscription to the topic is getting closed and added again every 30 seconds. This is happening even when the topic is not receiving any messages. Why is the rebalance happening then?

Has anybody faced similar issue? 

Please help understand.

Thanks,

Shweta