Sarama: ConsumerGroup flooding logs with client/metadata update req

[damiannolan]

Versions

Sarama: 1.24.1 - latest
Kafka: 2.2.1 - Yolean K8s
Go: 1.12

Configuration

What configuration values are you using for Sarama and Kafka?

version, err := sarama.ParseKafkaVersion("2.2.1")
if err != nil {
    log.WithError(err).Fatal("unsupported Kafka version")
}

saramaCfg := sarama.NewConfig()
saramaCfg.ClientID = "example-client"
saramaCfg.Consumer.Return.Errors = true
saramaCfg.Consumer.Offsets.Initial = sarama.OffsetOldest
saramaCfg.Metadata.Retry.Max = 15
saramaCfg.Metadata.Retry.Backoff = 1 * time.Second
saramaCfg.Version = version

Logs

logs: CLICK ME

time="2019-11-20T16:11:56.431401361Z" level=info msg="client/metadata fetching metadata for [test-topic-1 test-topic-2] from broker kafka-0.broker:9092\n"
time="2019-11-20T16:11:57.588379421Z" level=info msg="client/metadata fetching metadata for [test-topic-1 test-topic-2] from broker kafka-0.broker:9092\n"
time="2019-11-20T16:11:57.687529037Z" level=info msg="client/metadata fetching metadata for [test-topic-1 test-topic-2] from broker kafka-1.broker:9092\n"
time="2019-11-20T16:11:57.850933212Z" level=info msg="client/metadata fetching metadata for [test-topic-1 test-topic-2] from broker kafka-2.broker:9092\n"
time="2019-11-20T16:12:01.051368937Z" level=info msg="client/metadata fetching metadata for [test-topic-1 test-topic-2] from broker kafka-0.broker:9092\n"
time="2019-11-20T16:12:02.431277644Z" level=info msg="client/metadata fetching metadata for [test-topic-1 test-topic-2] from broker kafka-0.broker:9092\n"
time="2019-11-20T16:12:03.589721503Z" level=info msg="client/metadata fetching metadata for [test-topic-1 test-topic-2] from broker kafka-0.broker:9092\n"
time="2019-11-20T16:12:03.687584739Z" level=info msg="client/metadata fetching metadata for [test-topic-1 test-topic-2] from broker kafka-0.broker:9092\n"
time="2019-11-20T16:12:03.853433486Z" level=info msg="client/metadata fetching metadata for [test-topic-1 test-topic-2] from broker kafka-0.broker:9092\n"
time="2019-11-20T16:12:07.048928473Z" level=info msg="client/metadata fetching metadata for [test-topic-1 test-topic-2] from broker kafka-0.broker:9092\n"
time="2019-11-20T16:12:08.431699295Z" level=info msg="client/metadata fetching metadata for [test-topic-1 test-topic-2] from broker kafka-0.broker:9092\n"
time="2019-11-20T16:12:09.588683399Z" level=info msg="client/metadata fetching metadata for [test-topic-1 test-topic-2] from broker kafka-0.broker:9092\n"
time="2019-11-20T16:12:09.68754314Z" level=info msg="client/metadata fetching metadata for [test-topic-1 test-topic-2] from broker kafka-0.broker:9092\n"
time="2019-11-20T16:12:09.850933636Z" level=info msg="client/metadata fetching metadata for [test-topic-1 test-topic-2] from broker kafka-2.broker:9092\n"
time="2019-11-20T16:12:13.048623027Z" level=info msg="client/metadata fetching metadata for [test-topic-1 test-topic-2] from broker kafka-0.broker:9092\n"
time="2019-11-20T16:12:14.431404684Z" level=info msg="client/metadata fetching metadata for [test-topic-1 test-topic-2] from broker kafka-0.broker:9092\n"
time="2019-11-20T16:12:15.587790239Z" level=info msg="client/metadata fetching metadata for [test-topic-1 test-topic-2] from broker kafka-0.broker:9092\n"

Problem Description

Since the addition of #1525 the ConsumerGroup implementation starts a loop which checks partition count on topics

• https://github.com/Shopify/sarama/blob/bb74e49545653206693c03ce785366a3e928f43d/consumer_group.go#L450

This is calling c.Client.RefreshMetadata(topics...) which is flooding logs with metadata fetch requests to brokers.

Question: Is this working as intended or can something be done to reduce these logs? With default configuration it's fetching metadata at c.config.Consumer.Group.Heartbeat.Interval * 2 which I believe to be every 6 seconds.

I've stumbled across this old issue https://github.com/edenhill/librdkafka/issues/363 opened by @eapache which suggests it is probably is a fairly aggressive refresh interval.

[antsbean]

Sorry, I will submit a PR to solve this problem later

[dnwe]

@antsbean what did you plan to do to solve the problem? I happened to stumble upon this issue today after rebasing on the latest Sarama. It isn't obvious to me what the changes in #1525 were doing when there is the (similar to Java) backgroundMetadataUpdater() in client.go that is already periodically refreshing metadata on a 10 minute interval (by default). Whereas in PR #1525, a separate background metadata refresh was added just for the consumer that is refreshing on a more aggressive interval.

[antsbean]

@dnwe please see pr(#1578), just only use Metadata.RefreshFrequency params instead of Group.HeartBeat.Interval

[d1egoaz]

closed by https://github.com/Shopify/sarama/pull/1578