[KAFKA-7457] AbstractCoordinator struck in Discover

• Type: Bug
• Status: Open
• Priority: Minor
• Resolution: Unresolved
• Affects Version/s: 0.10.1.1
• Component/s: clients
• Environment: Linux
• Assignee: Unassigned
• Reporter: Joseph Aliase
• Created: 28/Sep/18 20:18
• Updated: 28/Sep/18 20:19

Description

AbstractCoordinator in kafka-client is stuck in discover and never rejoins the group. Post restart application is able to join the consumer group and consume from the topic.

We see below logs every 10 minute. The sequence of events are:

a) NetworkClient complains that connection is idle and closes the connection.

b) Consumer client tries to determine co-ordinator by sending request to Node 2.

c) Node 2 responds by saying Node 3 is group co-ordinator.

d) Consumer client connects to group co-ordinator.

e) There is radio silence for 10 minutes and the sequence gets repeated. 

 

2018-09-28 16:35:59.771 TRACE org.apache.kafka.common.network.Selector [pool-4-thread-50] [active] [wc] About to close the idle connection from 2147483644 due to being idle for 540140 millis
2018-09-28 16:35:59.771 DEBUG org.apache.kafka.clients.NetworkClient [pool-4-thread-50] [active] [wc] Node 2147483644 disconnected.
2018-09-28 16:35:59.771 INFO org.apache.kafka.clients.consumer.internals.AbstractCoordinator [pool-4-thread-50] [active] [wc] Marking the coordinator kafka03-wc.net:9092 (id: 2147483644 rack: null) dead for group test
2018-09-28 16:35:59.771 DEBUG org.apache.kafka.clients.consumer.internals.AbstractCoordinator [pool-4-thread-50] [active] [wc] Sending coordinator request for group test to broker kafka02-wc.net:9092 (id: 2 rack: null)
2018-09-28 16:35:59.771 DEBUG org.apache.kafka.clients.NetworkClient [pool-4-thread-50] [active] [wc] Sending metadata request {topics=[address]} to node 2
2018-09-28 16:35:59.796 DEBUG org.apache.kafka.clients.Metadata [pool-4-thread-50] [active] [wc] Updated cluster metadata version 401 to Cluster(id = oC0BPXfOT42WqN7-v6b5Gw, nodes = [kafka02-wc.net:9092 (id: 2 rack: null), kafka03-wc.net:9092 (id: 3 rack: null), kafka05-wc.net:9092 (id: 5 rack: null), kafka01-wc.net:9092 (id: 1 rack: null), kafka04-wc.net:9092 (id: 4 rack: null)], partitions = [Partition(topic = address, partition = 2, leader = 1, replicas = [1,5,4,], isr = [5,1,4,]), Partition(topic = address, partition = 1, leader = 5, replicas = [5,3,4,], isr = [5,3,4,]), Partition(topic = address, partition = 0, leader = 4, replicas = [2,3,4,], isr = [4,3,2,]), Partition(topic = address, partition = 6, leader = 5, replicas = [1,5,4,], isr = [5,1,4,]), Partition(topic = address, partition = 5, leader = 4, replicas = [5,3,4,], isr = [5,4,3,]), Partition(topic = address, partition = 4, leader = 3, replicas = [1,2,3,], isr = [1,3,2,]), Partition(topic = address, partition = 3, leader = 2, replicas = [1,5,2,], isr = [5,1,2,]), Partition(topic = address, partition = 16, leader = 5, replicas = [5,2,3,], isr = [5,3,2,]), Partition(topic = address, partition = 15, leader = 4, replicas = [1,2,4,], isr = [1,4,2,]), Partition(topic = address, partition = 10, leader = 4, replicas = [1,5,4,], isr = [5,1,4,]), Partition(topic = address, partition = 9, leader = 3, replicas = [2,3,4,], isr = [3,4,2,]), Partition(topic = address, partition = 8, leader = 2, replicas = [1,2,3,], isr = [1,3,2,]), Partition(topic = address, partition = 7, leader = 1, replicas = [1,5,2,], isr = [5,1,2,]), Partition(topic = address, partition = 14, leader = 3, replicas = [5,3,4,], isr = [5,4,3,]), Partition(topic = address, partition = 13, leader = 2, replicas = [2,3,4,], isr = [3,4,2,]), Partition(topic = address, partition = 12, leader = 1, replicas = [1,2,3,], isr = [1,3,2,]), Partition(topic = address, partition = 11, leader = 5, replicas = [1,5,2,], isr = [5,1,2,])])
2018-09-28 16:35:59.797 DEBUG org.apache.kafka.clients.consumer.internals.AbstractCoordinator [pool-4-thread-50] [active] [wc] Received group coordinator response ClientResponse(receivedTimeMs=1538152559797, disconnected=false, request=ClientRequest(expectResponse=true, callback=org.apache.kafka.clients.consumer.internals.ConsumerNetworkClient$RequestFutureCompletionHandler@2531ff5f, request=RequestSend(header={api_key=10,api_version=0,correlation_id=8354,client_id=active-wc-1-256}, body={group_id=test}), createdTimeMs=1538152559771, sendTimeMs=1538152559771), responseBody={error_code=0,coordinator={node_id=3,host=kafka03-wc.net,port=9092}})
2018-09-28 16:35:59.797 INFO org.apache.kafka.clients.consumer.internals.AbstractCoordinator [pool-4-thread-50] [active] [wc] Discovered coordinator kafka03-wc.net:9092 (id: 2147483644 rack: null) for group test.
2018-09-28 16:35:59.797 INFO org.apache.kafka.clients.consumer.internals.AbstractCoordinator [pool-4-thread-50] [active] [wc] Marking the coordinator kafka03-wc.net:9092 (id: 2147483644 rack: null) dead for group test
2018-09-28 16:36:09.797 DEBUG org.apache.kafka.clients.consumer.internals.AbstractCoordinator [pool-4-thread-50] [active] [wc] Sending coordinator request for group test to broker kafka02-wc.net:9092 (id: 2 rack: null)
2018-09-28 16:36:09.822 DEBUG org.apache.kafka.clients.consumer.internals.AbstractCoordinator [pool-4-thread-50] [active] [wc] Received group coordinator response ClientResponse(receivedTimeMs=1538152569822, disconnected=false, request=ClientRequest(expectResponse=true, callback=org.apache.kafka.clients.consumer.internals.ConsumerNetworkClient$RequestFutureCompletionHandler@773b5447, request=RequestSend(header={api_key=10,api_version=0,correlation_id=8356,client_id=active-wc-1-256}, body={group_id=test}), createdTimeMs=1538152569797, sendTimeMs=1538152569797), responseBody={error_code=0,coordinator={node_id=3,host=kafka03-wc.net,port=9092}})
2018-09-28 16:36:09.822 INFO org.apache.kafka.clients.consumer.internals.AbstractCoordinator [pool-4-thread-50] [active] [wc] Discovered coordinator kafka03-wc.net:9092 (id: 2147483644 rack: null) for group test.
2018-09-28 16:36:09.822 DEBUG org.apache.kafka.clients.NetworkClient [pool-4-thread-50] [active] [wc] Initiating connection to node 2147483644 at kafka03-wc.net:9092.
2018-09-28 16:36:09.846 DEBUG org.apache.kafka.common.network.Selector [pool-4-thread-50] [active] [wc] Created socket with SO_RCVBUF = 65536, SO_SNDBUF = 131072, SO_TIMEOUT = 0 to node 2147483644
2018-09-28 16:36:09.846 DEBUG org.apache.kafka.clients.NetworkClient [pool-4-thread-50] [active] [wc] Completed connection to node 2147483644