KafkaConsumer stuck in infinite loop on connection error

[zackdever]

It seems to be stuck in this loop

kafka-python/kafka/conn.py

Line 294 in 34dc9dd

error = 'Unable to connect to any of the names for {0}:{1}'.format(

The consumer filled up ~1TB logs over the course of 3 days, but did not throw an exception. Example logs:

kafka.cluster INFO     Group coordinator for my-group is BrokerMetadata(nodeId=102, host=u'kafka-2-broker.example.com', port=9092, rack=None)
kafka.cluster INFO     Group coordinator for my-group is BrokerMetadata(nodeId=102, host=u'kafka-2-broker.example.com', port=9092, rack=None)
kafka.conn   ERROR    Unable to connect to any of the names for kafka-4-broker.example.com:9092
kafka.conn   WARNING  <BrokerConnection node_id=104 host=kafka-4-broker.example.com/kafka-4-broker.example.com port=9092>: close() called on disconnected connection with error: ConnectionError: Unable to connect to any of the names for kafka-4-broker.example.com:9092
kafka.cluster INFO     Group coordinator for my-group is BrokerMetadata(nodeId=102, host=u'kafka-2-broker.example.com', port=9092, rack=None)
kafka.cluster INFO     Group coordinator for my-group is BrokerMetadata(nodeId=102, host=u'kafka-2-broker.example.com', port=9092, rack=None)
kafka.coordinator INFO     Discovered coordinator 102 for group my-group
kafka.conn   ERROR    Unable to connect to any of the names for kafka-1-broker.example.com:9092
kafka.coordinator INFO     Discovered coordinator 102 for group my-group
kafka.cluster INFO     Group coordinator for my-group is BrokerMetadata(nodeId=102, host=u'kafka-2-broker.example.com', port=9092, rack=None)
kafka.conn   ERROR    Unable to connect to any of the names for kafka-2-broker.example.com:9092
kafka.conn   WARNING  <BrokerConnection node_id=104 host=kafka-4-broker.example.com/kafka-4-broker.example.com port=9092>: close() called on disconnected connection with error: ConnectionError: Unable to connect to any of the names for kafka-4-broker.example.com:9092
kafka.cluster INFO     Group coordinator for my-group is BrokerMetadata(nodeId=102, host=u'kafka-2-broker.example.com', port=9092, rack=None)
kafka.conn   WARNING  <BrokerConnection node_id=101 host=kafka-1-broker.example.com/kafka-1-broker.example.com port=9092>: close() called on disconnected connection with error: ConnectionError: Unable to connect to any of the names for kafka-1-broker.example.com:9092
kafka.conn   ERROR    Unable to connect to any of the names for kafka-2-broker.example.com:9092
kafka.conn   ERROR    Unable to connect to any of the names for kafka-2-broker.example.com:9092
kafka.coordinator INFO     Discovered coordinator 102 for group my-group
kafka.conn   ERROR    Unable to connect to any of the names for kafka-3-broker.example.com:9092
kafka.coordinator INFO     Discovered coordinator 102 for group my-group
kafka.conn   WARNING  <BrokerConnection node_id=102 host=kafka-2-broker.example.com/kafka-2-broker.example.com port=9092>: close() called on disconnected connection with error: ConnectionError: Unable to connect to any of the names for kafka-2-broker.example.com:9092
kafka.conn   WARNING  <BrokerConnection node_id=103 host=kafka-3-broker.example.com/kafka-3-broker.example.com port=9092>: close() called on disconnected connection with error: ConnectionError: Unable to connect to any of the names for kafka-3-broker.example.com:9092
kafka.coordinator INFO     Discovered coordinator 102 for group my-group
kafka.coordinator INFO     Discovered coordinator 102 for group my-group
kafka.conn   WARNING  <BrokerConnection node_id=102 host=kafka-2-broker.example.com/kafka-2-broker.example.com port=9092>: close() called on disconnected connection with error: ConnectionError: Unable to connect to any of the names for kafka-2-broker.example.com:9092

[jeffwidman]

Are you running master or 1.3.5 or another version?

Also I doubt it matters, but just in case, what broker version?

[zackdever]

We're on 1.3.5 and the broker is 0.10.1.1.

[aptiko]

Apparently I'm having the same problem. It usually (but not always) appears if Kafka goes down (therefore disconnecting clients) and then comes up again. Sometimes clients will reconnect alright, sometimes they will be stuck in this loop. Here's a log extract with a traceback:

2017-11-24 13:31:11,192 - ERROR - conn.connect(289) Unable to connect to any of the names for kafka:9092
2017-11-24 13:31:11,192 - WARNING - conn.close(623) <BrokerConnection node_id=0 host=kafka/kafka port=9092>: close() called on disconnected connection with error: ConnectionError: Unable to connect to any of the names for kafka:9092                                               
Stack (most recent call last):                                                                          
  File "/usr/lib/python3.5/threading.py", line 882, in _bootstrap                                                                                     
    self._bootstrap_inner()                                   
  File "/usr/lib/python3.5/threading.py", line 914, in _bootstrap_inner               
    self.run()                                                                                               
  File "/tmp/virtualenv/lib/python3.5/site-packages/kafka/producer/sender.py", line 60, in run          
    self.run_once()                                                    
  File "/tmp/virtualenv/lib/python3.5/site-packages/kafka/producer/sender.py", line 108, in run_once
    if not self._client.ready(node):                                                          
  File "/tmp/virtualenv/lib/python3.5/site-packages/kafka/client_async.py", line 385, in ready
    self._maybe_connect(node_id)                                                                    
  File "/tmp/virtualenv/lib/python3.5/site-packages/kafka/client_async.py", line 371, in _maybe_connect
    conn.connect()                                                                           
  File "/tmp/virtualenv/lib/python3.5/site-packages/kafka/conn.py", line 290, in connect
    self.close(Errors.ConnectionError(error))
  File "/tmp/virtualenv/lib/python3.5/site-packages/kafka/conn.py", line 623, in close
    log.warning('%s: close() called on disconnected connection with error: %s', self, error, stack_info=True)
2017-11-24 13:31:11,193 - ERROR - conn.connect(289) Unable to connect to any of the names for kafka:9092
2017-11-24 13:31:11,193 - WARNING - conn.close(623) <BrokerConnection node_id=0 host=kafka/kafka port=9092>: close() called on disconnected connection with error: ConnectionError: Unable to connect to any of the names for kafka:9092

This is 1.3.5 on Python 3.5.1 on Ubuntu 16.04 (on a Docker image, with Kafka on another Docker image).

[aptiko]

It also happens on 1.3.4.1, but not on 1.3.3.

With 1.3.3, again behavior doesn't seem to be deterministic. Sometimes it reconnects, sometimes it raises socket.gaierror (likewise, 1.3.5 sometimes reconnects, sometimes it goes into the endless loop).

[jeffwidman]

I hit this earlier today on one of our development environments with a KafkaProducer.

The Kafka cluster had completely crashed, then after the brokers were restarted, the producer never recovered. It just continually spouted these logs:

2017-12-01 21:40:49,873 ERROR           conn                    connect:289     4983    139743082212240 Unable to connect to any of the names for kafka03.anon.local:9092
2017-12-01 21:40:49,873 WARNING         conn                    close:625       4983    139743082212240 <BrokerConnection node_id=3 host=kafka03.anon.local/kafka03.anon.lo
cal port=9092>: close() called on disconnected connection with error: ConnectionError: Unable to connect to any of the names for kafka03.anon.local:9092
2017-12-01 21:40:49,875 ERROR           conn                    connect:289     4983    139743082212240 Unable to connect to any of the names for kafka03.anon.local:9092
2017-12-01 21:40:49,875 WARNING         conn                    close:625       4983    139743082212240 <BrokerConnection node_id=3 host=kafka03.anon.local/kafka03.anon.lo
cal port=9092>: close() called on disconnected connection with error: ConnectionError: Unable to connect to any of the names for kafka03.anon.local:9092

Given that it's a BrokerConnection class error, not really a surprise it's showing up with both KafkaConsumer and KafkaProducer.

I watched the tcp stream and verified that nothing was being sent over port 9092, so it's not even trying to talk to Kafka.

Once I restarted the producer it worked fine.

[jeffwidman]

@zackdever do you know if the broker had gone away when this was triggered?

[zackdever]

Ah I wish I knew for sure or had the logs to check, but I can't confirm. I think a broker had gone down when this happened.

[dpkp]

I believe the error here is caused by cached DNS results that are not cleared on failure. My hunch is that this is triggered by dynamic DNS entries causing a failure at the broker level to cause a DNS failure. I put up a PR w/ unit test that should fix (if my diagnosis is correct).

[jeffwidman]

That may be true. I suspect the reason Kafka crashed in our case because the underlying VM was shutdown and moved, so the IP address would have changed.

[aptiko]

This might explain what I'm having. I'm actually using a group of Docker containers for an integration test, and I'm testing resilience by shutting down the Kafka container and bringing it up again. I'm not certain what Docker does in this case, but if sometimes it gives the restarted container the same (internal) ip address and sometimes a different one, this could be the reason why sometimes I get different behavior than other times.

[jeffwidman]

Thanks @aptiko. Also, it sounds like you're the only person here with a reproducible setup.

1. Do you mind pinning the IP of the Kafka containers in your Docker compose setup to see if this goes away? I'd just like to see if there's any other issue in addition to DNS that might be triggering this.
2. Would you be willing to open-source some of your test setup? It'd save time while cobbling things together for Figure out a way to test against constantly cycling Kafka cluster #1311. Even if it's very hacky, just stick it in a gist or something, and add a link at Figure out a way to test against constantly cycling Kafka cluster #1311