[KAFKA-3296] All consumer reads hang indefinately

• Type: Bug
• Status: Open
• Priority: Critical
• Resolution: Unresolved
• Affects Version/s: 0.9.0.0, 0.9.0.1
• Component/s: consumer
• Assignee: Unassigned
• Reporter: Simon Cooper
• Created: 26/Feb/16 12:46
• Updated: 03/Aug/18 21:34

Description

We've got several integration tests that bring up systems on VMs for testing. We've recently upgraded to 0.9, and very occasionally we occasionally see an issue where every consumer that tries to read from the broker hangs, spamming the following in their logs:

2016-02-26T12:25:37,856 | DEBUG | o.a.k.c.NetworkClient [pool-10-thread-1] | Sending metadata request ClientRequest(expectResponse=true, callback=null, request=RequestSend(header={api_key=3,api_version=0,correlation_id=21905,client_id=consumer-1}, body={topics=[Topic1]}), isInitiatedByNetworkClient, createdTimeMs=1456489537856, sendTimeMs=0) to node 1
2016-02-26T12:25:37,856 | DEBUG | o.a.k.c.Metadata [pool-10-thread-1] | Updated cluster metadata version 10954 to Cluster(nodes = [Node(1, server.internal, 9092)], partitions = [Partition(topic = Topic1, partition = 0, leader = 1, replicas = [1,], isr = [1,]])
2016-02-26T12:25:37,856 | DEBUG | o.a.k.c.c.i.AbstractCoordinator [pool-10-thread-1] | Issuing group metadata request to broker 1
2016-02-26T12:25:37,857 | DEBUG | o.a.k.c.c.i.AbstractCoordinator [pool-10-thread-1] | Group metadata response ClientResponse(receivedTimeMs=1456489537857, disconnected=false, request=ClientRequest(expectResponse=true, callback=org.apache.kafka.clients.consumer.internals.ConsumerNetworkClient$RequestFutureCompletionHandler@28edb273, request=RequestSend(header={api_key=10,api_version=0,correlation_id=21906,client_id=consumer-1}, body={group_id=}), createdTimeMs=1456489537856, sendTimeMs=1456489537856), responseBody={error_code=15,coordinator={node_id=-1,host=,port=-1}})
2016-02-26T12:25:37,956 | DEBUG | o.a.k.c.NetworkClient [pool-10-thread-1] | Sending metadata request ClientRequest(expectResponse=true, callback=null, request=RequestSend(header={api_key=3,api_version=0,correlation_id=21907,client_id=consumer-1}, body={topics=[Topic1]}), isInitiatedByNetworkClient, createdTimeMs=1456489537956, sendTimeMs=0) to node 1
2016-02-26T12:25:37,956 | DEBUG | o.a.k.c.Metadata [pool-10-thread-1] | Updated cluster metadata version 10955 to Cluster(nodes = [Node(1, server.internal, 9092)], partitions = [Partition(topic = Topic1, partition = 0, leader = 1, replicas = [1,], isr = [1,]])
2016-02-26T12:25:37,956 | DEBUG | o.a.k.c.c.i.AbstractCoordinator [pool-10-thread-1] | Issuing group metadata request to broker 1
2016-02-26T12:25:37,957 | DEBUG | o.a.k.c.c.i.AbstractCoordinator [pool-10-thread-1] | Group metadata response ClientResponse(receivedTimeMs=1456489537957, disconnected=false, request=ClientRequest(expectResponse=true, callback=org.apache.kafka.clients.consumer.internals.ConsumerNetworkClient$RequestFutureCompletionHandler@40cee8cc, request=RequestSend(header={api_key=10,api_version=0,correlation_id=21908,client_id=consumer-1}, body={group_id=}), createdTimeMs=1456489537956, sendTimeMs=1456489537956), responseBody={error_code=15,coordinator={node_id=-1,host=,port=-1}})
2016-02-26T12:25:38,056 | DEBUG | o.a.k.c.NetworkClient [pool-10-thread-1] | Sending metadata request ClientRequest(expectResponse=true, callback=null, request=RequestSend(header={api_key=3,api_version=0,correlation_id=21909,client_id=consumer-1}, body={topics=[Topic1]}), isInitiatedByNetworkClient, createdTimeMs=1456489538056, sendTimeMs=0) to node 1
2016-02-26T12:25:38,056 | DEBUG | o.a.k.c.Metadata [pool-10-thread-1] | Updated cluster metadata version 10956 to Cluster(nodes = [Node(1, server.internal, 9092)], partitions = [Partition(topic = Topic1, partition = 0, leader = 1, replicas = [1,], isr = [1,]])
2016-02-26T12:25:38,056 | DEBUG | o.a.k.c.c.i.AbstractCoordinator [pool-10-thread-1] | Issuing group metadata request to broker 1
2016-02-26T12:25:38,057 | DEBUG | o.a.k.c.c.i.AbstractCoordinator [pool-10-thread-1] | Group metadata response ClientResponse(receivedTimeMs=1456489538057, disconnected=false, request=ClientRequest(expectResponse=true, callback=org.apache.kafka.clients.consumer.internals.ConsumerNetworkClient$RequestFutureCompletionHandler@439e25fb, request=RequestSend(header={api_key=10,api_version=0,correlation_id=21910,client_id=consumer-1}, body={group_id=}), createdTimeMs=1456489538056, sendTimeMs=1456489538056), responseBody={error_code=15,coordinator={node_id=-1,host=,port=-1}})

This persists for any 0.9 consumer trying to read from the topic (we haven't confirmed if this is for a single topic or for any topic on the broker). 0.8 consumers can read from the broker without issues. This is fixed by a broker restart.

This was observed on a single-broker cluster. There were no suspicious log messages on the server.