Too many reqs on kafka not available

[lud4ik]

I have code with simple consumer. I undestand that most of time at least 1 of nodes will be available. But on kafka stop it send too many requests and uses up to 100% cpu

2019-04-11 12:06:55,732 Unable connect to node with id 0: [Errno 111] Connect call failed ('10.0.3.2', 9092)
2019-04-11 12:06:55,732 Unable to update metadata from [0]
2019-04-11 12:06:55,732 Unable connect to node with id 0: [Errno 111] Connect call failed ('10.0.3.2', 9092)
2019-04-11 12:06:55,732 Failed fetch messages from 0: NodeNotReadyError: Attempt to send a request to node which is not ready (node id 0).
1
2019-04-11 12:06:55,733 Unable connect to node with id 0: [Errno 111] Connect call failed ('10.0.3.2', 9092)
2019-04-11 12:06:55,733 Unable to update metadata from [0]
2019-04-11 12:06:55,734 Unable connect to node with id 0: [Errno 111] Connect call failed ('10.0.3.2', 9092)
2019-04-11 12:06:55,734 Failed fetch messages from 0: NodeNotReadyError: Attempt to send a request to node which is not ready (node id 0).
1
2019-04-11 12:06:55,734 Unable connect to node with id 0: [Errno 111] Connect call failed ('10.0.3.2', 9092)
2019-04-11 12:06:55,734 Unable to update metadata from [0]
2019-04-11 12:06:55,735 Unable connect to node with id 0: [Errno 111] Connect call failed ('10.0.3.2', 9092)
2019-04-11 12:06:55,735 Failed fetch messages from 0: NodeNotReadyError: Attempt to send a request to node which is not ready (node id 0).
1
2019-04-11 12:06:55,736 Unable connect to node with id 0: [Errno 111] Connect call failed ('10.0.3.2', 9092)
2019-04-11 12:06:55,736 Unable to update metadata from [0]
2019-04-11 12:06:55,736 Unable connect to node with id 0: [Errno 111] Connect call failed ('10.0.3.2', 9092)
2019-04-11 12:06:55,736 Failed fetch messages from 0: NodeNotReadyError: Attempt to send a request to node which is not ready (node id 0).
1
2019-04-11 12:06:55,737 Unable connect to node with id 0: [Errno 111] Connect call failed ('10.0.3.2', 9092)
2019-04-11 12:06:55,737 Unable to update metadata from [0]
2019-04-11 12:06:55,737 Unable connect to node with id 0: [Errno 111] Connect call failed ('10.0.3.2', 9092)
2019-04-11 12:06:55,737 Failed fetch messages from 0: NodeNotReadyError: Attempt to send a request to node which is not ready (node id 0).
1
2019-04-11 12:06:55,738 Unable connect to node with id 0: [Errno 111] Connect call failed ('10.0.3.2', 9092)
2019-04-11 12:06:55,738 Unable to update metadata from [0]
2019-04-11 12:06:55,738 Unable connect to node with id 0: [Errno 111] Connect call failed ('10.0.3.2', 9092)
2019-04-11 12:06:55,738 Failed fetch messages from 0: NodeNotReadyError: Attempt to send a request to node which is not ready (node id 0).

Isn't retry_backoff_ms param meant for this case? Is it used on production systems?

[tvoinarovskyi]

Hmm, seems like a bug. Will try to ckeck once I get back from pto. The case definitely deserves an integration test.

[nikitagashkov]

I'm facing the same issue using Docker and Docker Compose.

There're two containers, namely python and kafka. If kafka container dies, python container endlessly tries to connect. A relevant code snippet from a python container:

import aiokafka
import asyncio


async def main():
    
    producer = aiokafka.AIOKafkaProducer(
        loop=asyncio.get_event_loop(),
        bootstrap_servers='kafka:9092',
    )
    
    await producer.start()
    
    try:
        while True:
            await asyncio.sleep(1)
            await producer.send('test', b'test-data')
    finally:
        await producer.stop()


if __name__ == '__main__':
    loop = asyncio.get_event_loop()
    loop.run_until_complete(main())

After killing kafka...

$ docker-compose stop kafka

...endless reconnect loop occures in a python container:

ERROR:aiokafka:Unable connect to node with id 1001: [Errno 111] Connect call failed ('172.28.0.3', 9092)
ERROR:aiokafka:Unable to update metadata from [1001]
ERROR:aiokafka:Unable connect to node with id 1001: [Errno 111] Connect call failed ('172.28.0.3', 9092)
WARNING:aiokafka.producer.sender:Got error produce response: NodeNotReadyError: Attempt to send a request to node which is not ready (node id 1001).
ERROR:aiokafka:Unable connect to node with id 1001: [Errno 111] Connect call failed ('172.28.0.3', 9092)
ERROR:aiokafka:Unable to update metadata from [1001]
ERROR:aiokafka:Unable connect to node with id 1001: [Errno 111] Connect call failed ('172.28.0.3', 9092)
WARNING:aiokafka.producer.sender:Got error produce response: NodeNotReadyError: Attempt to send a request to node which is not ready (node id 1001).
ERROR:aiokafka:Unable connect to node with id 1001: [Errno 111] Connect call failed ('172.28.0.3', 9092)
ERROR:aiokafka:Unable to update metadata from [1001]
ERROR:aiokafka:Unable connect to node with id 1001: [Errno 111] Connect call failed ('172.28.0.3', 9092)
WARNING:aiokafka.producer.sender:Got error produce response: NodeNotReadyError: Attempt to send a request to node which is not ready (node id 1001).
ERROR:aiokafka:Unable connect to node with id 1001: [Errno 111] Connect call failed ('172.28.0.3', 9092)

[tvoinarovskyi]

Will try to find time for this on 0.6.0, as it's a bad one. We can't have logs filling like crazy.

[arvindjangra1996]

hey, can we catch "NodeNotReadyError" exception while consuming from Kafka. So that we can take any action at this situation. Like sending alert.

[tvoinarovskyi]

@arvindjangra1996 Will answer in #612

[tvoinarovskyi]

Merge and released as part of 0.6.0. Hope it solves the issue.

[Olegt0rr]

@tvoinarovskyi, looks like this issue become actual again :(

Please, help to review PR, that should help to avoid reconnect cpu flooding
#1014

Look at CPU throttling on kafka become unavailable: