NodeNotReadyError with manual commits

[fglass]

Simple Kafka consumer where I manually commit records (enable_auto_commit=False):

for record in consumer:
    ...
    consumer.commit()

I often encounter Error sending OffsetCommitRequest_v2 to node coordinator-1 [NodeNotReadyError: coordinator-1]. It seemingly does not have any functionality consequences but it does pollute the logs. Any idea why this may be happening and/or could this be a raised exception so that I may handle it myself?

Using latest version. Related issues: #1354, #1572

Full debug log of the event:

2019-11-04 12:07:46,605 INFO 8/MainThread: Consuming record 1571 from topic TOPIC
2019-11-04 12:07:46,607 DEBUG 8/MainThread: Sending offset-commit request with {TopicPartition(topic='TOPIC', partition=0): OffsetAndMetadata(offset=1572, metadata='')} for group SERVICE to coordinator-1
2019-11-04 12:07:46,607 ERROR 8/MainThread: Error sending OffsetCommitRequest_v2 to node coordinator-1 [NodeNotReadyError: coordinator-1]
2019-11-04 12:07:46,608 DEBUG 8/MainThread: Initiating connection to node coordinator-1 at kafka1:9092
2019-11-04 12:07:46,614 DEBUG 8/MainThread: <BrokerConnection node_id=coordinator-1 host=kafka1:9092 <disconnected> [unspecified None]>: creating new socket
2019-11-04 12:07:46,615 DEBUG 8/MainThread: <BrokerConnection node_id=coordinator-1 host=kafka1:9092 <disconnected> [IPv4 ('10.0.9.173', 9092)]>: setting socket option (6, 1, 1)
2019-11-04 12:07:46,615 INFO 8/MainThread: <BrokerConnection node_id=coordinator-1 host=kafka1:9092 <connecting> [IPv4 ('10.0.9.173', 9092)]>: connecting to kafka1:9092 [('10.0.9.173', 9092) IPv4]
2019-11-04 12:07:46,716 DEBUG 8/MainThread: Sending offset-commit request with {TopicPartition(topic='TOPIC', partition=0): OffsetAndMetadata(offset=1572, metadata='')} for group SERVICE  to coordinator-1
2019-11-04 12:07:46,716 ERROR 8/MainThread: Error sending OffsetCommitRequest_v2 to node coordinator-1 [NodeNotReadyError: coordinator-1]
2019-11-04 12:07:46,716 DEBUG 8/MainThread: <BrokerConnection node_id=coordinator-1 host=kafka1:9092 <connecting> [IPv4 ('10.0.9.173', 9092)]>: established TCP connection
2019-11-04 12:07:46,716 INFO 8/MainThread: <BrokerConnection node_id=coordinator-1 host=kafka1:9092 <connecting> [IPv4 ('10.0.9.173', 9092)]>: Connection complete.
2019-11-04 12:07:46,716 DEBUG 8/MainThread: Node coordinator-1 connected

[amdrozdov]

We have the same problem, it happens after a few hours after consumer start, but very rarely

[dpkp]

Yea, these log messages shouldn't be errors. I'll put up a PR to move to debug logging. NodeNotReady gets handled internally w/ retries. It just means that the BrokerConnection isn't connected yet.