No topics returned on successive refreshing of full metadata on versions >= 0_10_0_0

[Preylien]

Versions

Sarama Version: commit on master: 5cd4d86
Kafka Version: 0.10.1.0 & 1.1.0
Go Version: 1.10.3

Configuration

config.Consumer.Return.Errors = true
config.ClientID = "consumer-test"
config.Metadata.RefreshFrequency = time.Duration(2) * time.Second
config.Metadata.Full = true
config.Version = sarama.V0_10_0_0

Logs

[Sarama] 2018/07/13 11:05:19.935931 client.go:120: Initializing new client
[Sarama] 2018/07/13 11:05:19.936136 client.go:701: client/metadata fetching metadata for all topics from broker localhost:9092
[Sarama] 2018/07/13 11:05:19.939979 broker.go:148: Connected to broker at localhost:9092 (unregistered)
[Sarama] 2018/07/13 11:05:19.948910 client.go:477: client/brokers registered new broker #0 at localhost:9092
[Sarama] 2018/07/13 11:05:19.948945 client.go:167: Successfully initialized new client
client.Topics() [test2 test1 test3]
[Sarama] 2018/07/13 11:05:21.949261 client.go:701: client/metadata fetching metadata for all topics from broker localhost:9092
client.Topics() [test2 test1 test3]
client.Topics() []
[Sarama] 2018/07/13 11:05:23.952187 client.go:701: client/metadata fetching metadata for all topics from broker localhost:9092
client.Topics() []
client.Topics() []
client.Topics() []
[Sarama] 2018/07/13 11:05:25.951132 client.go:701: client/metadata fetching metadata for all topics from broker localhost:9092

Problem Description

Consuming using Kafka version 0_10_0_0 and above I've noticed that refreshing metadata does not seem to be returning a correct list of topics.

I'm calling client.Topics() in a loop about twice every refresh period and the first few calls return a list of all my topics. After the next refresh the topic list becomes empty from then on, as shown in my provided logs

I do not see these problems when using V0_9_0_1 and below and client.Topics() always returns the full list.

Trying to debug this issue I saw this code: https://github.com/Shopify/sarama/blob/master/client.go#L705
I commented out this IF statement for testing and the data returned correctly.
I don't know enough about kafka's versions so I can't seem to pinpoint why this might be causing this problem.

I can provide more info if needed.

[Preylien]

I accidentally fat fingered the close issue button, my bad

I wanted to add details about the kafka instance. I'm using this docker image with none of the settings in it changed: https://hub.docker.com/r/spotify/kafka/

[eapache]

I can't imagine this is causing the bug, but refreshing the metadata every two seconds is massive overkill, the kafka metadata isn't going to change nearly that often.

Otherwise, I'd suggest putting some more logging in updateMetadata in client.go. That's the place I would expect something to be going wrong, unless this is strictly an upstream kafka bug.

[Preylien]

@eapache I did some more debugging and was looking into the request that is sent to kafka.

I noticed that the metadata requests looked similar but after looking at the encoded bytes here they differed between the first and all subsequent requests.
https://github.com/Shopify/sarama/blob/5cd4d8675b3b11c08e71529e7280c45f9fc3dafe/broker.go#L570

I dug into the encode functions and found this IF statement:

https://github.com/Shopify/sarama/blob/5cd4d8675b3b11c08e71529e7280c45f9fc3dafe/metadata_request.go#L13

On kafka version 0_10_0_0 and above version for the metadata requests is set to 1 as seen here:
https://github.com/Shopify/sarama/blob/5cd4d8675b3b11c08e71529e7280c45f9fc3dafe/client.go#L705

While testing, it looks like the topic list is nil for the first request. For all other requests, the topic list is not nil, just empty, so it enters this IF and that sets the last values in the encoded []byte differently from the first request that is sent.

I changed the statement locally to this:
if r.Version == 0 || (r.Topics != nil && len(r.Topics) > 0)

running it for about 30 minutes (with a refresh time of 5 minutes) the list seems to update correctly each time, and it even picks up new topics that are created since the application started.

I don't know enough about this code to determine what the purpose of this IF statement is and if my change actually fixes the root issue. If someone could chime in about the intended behavior of this IF statement that would great.

A note about the 2 second refresh time:
I don't use this as a production value, I was using it for my test instance to reproduce this bug, and make it faster to get log data. Normally it is 10 or 20 minutes a refresh.

[eapache]

I think this is correct, thanks for digging!