MSK rebalancing with OAUTHBEARER: IllegalSaslStateError

[Lasall]

I encounter following error on MSK-Broker setup:

2025-03-27 12:39:45,837 DEBUG kafka.protocol.parser:58 Sending request SaslHandshakeRequest_v1(mechanism='OAUTHBEARER')
2025-03-27 12:39:45,837 DEBUG kafka.conn:998 <BrokerConnection client_id=kafka-python-2.1.3, node_id=3 host=b-3.host.amazonaws.com:9098 <authenticating> [IPv4 ('10.10.10.10', 9098)]> Request 1 (timeout_ms 30000): SaslHandshakeRequest_v1(mechanism='OAUTHBEARER')
2025-03-27 12:39:45,839 INFO kafka.conn:806 <BrokerConnection client_id=kafka-python-2.1.3, node_id=1 host=b-1.host.amazonaws.com:9098 <authenticating> [IPv4 ('10.10.10.11', 9098)]>: Authenticated via SASL / OAuth
2025-03-27 12:39:45,839 INFO kafka.conn:461 <BrokerConnection client_id=kafka-python-2.1.3, node_id=1 host=b-1.host.amazonaws.com:9098 <authenticating> [IPv4 ('10.10.10.11', 9098)]>: Connection complete.
2025-03-27 12:39:45,839 DEBUG kafka.client:338 Node 1 connected
2025-03-27 12:39:45,939 DEBUG kafka.coordinator:692 Sending group coordinator request for group MYGROUP to broker 1
2025-03-27 12:39:45,939 DEBUG kafka.protocol.parser:58 Sending request FindCoordinatorRequest_v2(coordinator_key='MYGROUP', coordinator_type=0)
2025-03-27 12:39:45,939 DEBUG kafka.conn:998 <BrokerConnection client_id=kafka-python-2.1.3, node_id=1 host=b-1.host.amazonaws.com:9098 <connected> [IPv4 ('10.10.10.11', 9098)]> Request 2 (timeout_ms 30000): FindCoordinatorRequest_v2(coordinator_key='MYGROUP', coordinator_type=0)
2025-03-27 12:39:45,939 DEBUG kafka.client:676 Timeouts: user inf, metadata inf, idle connection 239973.000000, request 29897.692919
2025-03-27 12:39:45,940 DEBUG kafka.protocol.parser:142 Received correlation id: 1
2025-03-27 12:39:45,940 DEBUG kafka.protocol.parser:160 Processing response SaslHandshakeResponse_v1
2025-03-27 12:39:45,940 DEBUG kafka.conn:1121 <BrokerConnection client_id=kafka-python-2.1.3, node_id=3 host=b-3.host.amazonaws.com:9098 <authenticating> [IPv4 ('10.10.10.10', 9098)]> Response 1 (102.69665718078613 ms): SaslHandshakeResponse_v1(error_code=0, enabled_mechanisms=['OAUTHBEARER', 'AWS_MSK_IAM'])
2025-03-27 12:39:45,940 DEBUG kafka.conn:436 <BrokerConnection client_id=kafka-python-2.1.3, node_id=2 host=b-2.host.amazonaws.com:9098 <handshake> [IPv4 ('10.10.10.12', 9098)]>: completed SSL handshake.
2025-03-27 12:39:45,940 DEBUG kafka.conn:437 <BrokerConnection client_id=kafka-python-2.1.3, node_id=2 host=b-2.host.amazonaws.com:9098 <handshake> [IPv4 ('10.10.10.12', 9098)]>: checking broker Api Versions
2025-03-27 12:39:45,940 DEBUG kafka.conn:544 <BrokerConnection client_id=kafka-python-2.1.3, node_id=2 host=b-2.host.amazonaws.com:9098 <checking_api_versions_send> [IPv4 ('10.10.10.12', 9098)]>: Using pre-configured api_version (2, 8) for ApiVersions
2025-03-27 12:39:45,940 DEBUG kafka.conn:446 <BrokerConnection client_id=kafka-python-2.1.3, node_id=2 host=b-2.host.amazonaws.com:9098 <checking_api_versions_send> [IPv4 ('10.10.10.12', 9098)]>: initiating SASL authentication
2025-03-27 12:39:45,940 DEBUG kafka.protocol.parser:58 Sending request SaslHandshakeRequest_v1(mechanism='OAUTHBEARER')
2025-03-27 12:39:45,940 DEBUG kafka.conn:998 <BrokerConnection client_id=kafka-python-2.1.3, node_id=2 host=b-2.host.amazonaws.com:9098 <authenticating> [IPv4 ('10.10.10.12', 9098)]> Request 1 (timeout_ms 30000): SaslHandshakeRequest_v1(mechanism='OAUTHBEARER')
2025-03-27 12:39:45,940 INFO kafka.conn:806 <BrokerConnection client_id=kafka-python-2.1.3, node_id=3 host=b-3.host.amazonaws.com:9098 <authenticating> [IPv4 ('10.10.10.10', 9098)]>: Authenticated via SASL / OAuth
2025-03-27 12:39:45,941 INFO kafka.conn:461 <BrokerConnection client_id=kafka-python-2.1.3, node_id=3 host=b-3.host.amazonaws.com:9098 <authenticating> [IPv4 ('10.10.10.10', 9098)]>: Connection complete.
2025-03-27 12:39:45,941 DEBUG kafka.client:338 Node 3 connected
2025-03-27 12:39:45,941 DEBUG kafka.client:987 Sending metadata request MetadataRequest_v7(topics=['topic1', 'topic2'], allow_auto_topic_creation=True) to node 3
2025-03-27 12:39:45,941 DEBUG kafka.protocol.parser:58 Sending request MetadataRequest_v7(topics=['topic1', 'topic2'], allow_auto_topic_creation=True)
2025-03-27 12:39:45,941 DEBUG kafka.conn:998 <BrokerConnection client_id=kafka-python-2.1.3, node_id=3 host=b-3.host.amazonaws.com:9098 <connected> [IPv4 ('10.10.10.10', 9098)]> Request 2 (timeout_ms 30000): MetadataRequest_v7(topics=['topic1', 'topic2'], allow_auto_topic_creation=True)
2025-03-27 12:39:45,941 DEBUG kafka.client:676 Timeouts: user inf, metadata 30000.000000, idle connection 239972.000000, request 29998.381615
2025-03-27 12:39:45,941 DEBUG kafka.client:676 Timeouts: user inf, metadata 30000.000000, idle connection 239972.000000, request 29998.190403
2025-03-27 12:39:45,941 DEBUG kafka.protocol.parser:142 Received correlation id: 1
2025-03-27 12:39:45,941 DEBUG kafka.protocol.parser:160 Processing response SaslHandshakeResponse_v1
2025-03-27 12:39:45,941 DEBUG kafka.conn:1121 <BrokerConnection client_id=kafka-python-2.1.3, node_id=2 host=b-2.host.amazonaws.com:9098 <authenticating> [IPv4 ('10.10.10.12', 9098)]> Response 1 (1.2080669403076172 ms): SaslHandshakeResponse_v1(error_code=0, enabled_mechanisms=['OAUTHBEARER', 'AWS_MSK_IAM'])
2025-03-27 12:39:45,942 INFO kafka.conn:806 <BrokerConnection client_id=kafka-python-2.1.3, node_id=2 host=b-2.host.amazonaws.com:9098 <authenticating> [IPv4 ('10.10.10.12', 9098)]>: Authenticated via SASL / OAuth
2025-03-27 12:39:45,942 INFO kafka.conn:461 <BrokerConnection client_id=kafka-python-2.1.3, node_id=2 host=b-2.host.amazonaws.com:9098 <authenticating> [IPv4 ('10.10.10.12', 9098)]>: Connection complete.
2025-03-27 12:39:45,942 DEBUG kafka.client:338 Node 2 connected
2025-03-27 12:39:45,942 DEBUG kafka.client:676 Timeouts: user inf, metadata 30000.000000, idle connection 239971.000000, request 29997.489929
2025-03-27 12:39:46,078 ERROR kafka.conn:1144 <BrokerConnection client_id=kafka-python-2.1.3, node_id=1 host=b-1.host.amazonaws.com:9098 <connected> [IPv4 ('10.10.10.11', 9098)]>: socket disconnected
2025-03-27 12:39:46,078 ERROR kafka.conn:929 <BrokerConnection client_id=kafka-python-2.1.3, node_id=1 host=b-1.host.amazonaws.com:9098 <connected> [IPv4 ('10.10.10.11', 9098)]>: Closing connection. KafkaConnectionError: socket disconnected
2025-03-27 12:39:46,078 DEBUG kafka.conn:906 <BrokerConnection client_id=kafka-python-2.1.3, node_id=1 host=b-1.host.amazonaws.com:9098 <connected> [IPv4 ('10.10.10.11', 9098)]>: reconnect backoff 0.04823697762777096 after 1 failures
2025-03-27 12:39:46,078 WARNING kafka.client:388 Node 1 connection failed -- refreshing metadata
2025-03-27 12:39:46,079 ERROR kafka.coordinator:517 Error sending FindCoordinatorRequest_v2 to node 1 [KafkaConnectionError: socket disconnected]
2025-03-27 12:39:46,079 DEBUG kafka.coordinator:273 Requesting metadata for group coordinator request: KafkaConnectionError: socket disconnected
2025-03-27 12:39:46,079 DEBUG kafka.client:676 Timeouts: user inf, metadata 30000.000000, idle connection 239834.000000, request 29862.027645
2025-03-27 12:39:46,100 ERROR kafka.conn:1144 <BrokerConnection client_id=kafka-python-2.1.3, node_id=3 host=b-3.host.amazonaws.com:9098 <connected> [IPv4 ('10.10.10.10', 9098)]>: socket disconnected
2025-03-27 12:39:46,100 ERROR kafka.conn:929 <BrokerConnection client_id=kafka-python-2.1.3, node_id=3 host=b-3.host.amazonaws.com:9098 <connected> [IPv4 ('10.10.10.10', 9098)]>: Closing connection. KafkaConnectionError: socket disconnected
2025-03-27 12:39:46,100 DEBUG kafka.conn:906 <BrokerConnection client_id=kafka-python-2.1.3, node_id=3 host=b-3.host.amazonaws.com:9098 <connected>
2025-03-27 12:39:46,100 WARNING kafka.client:388 Node 3 connection failed -- refreshing metadata
2025-03-27 12:39:46,100 DEBUG kafka.coordinator:692 Sending group coordinator request for group MYGROUP to broker 2
2025-03-27 12:39:46,100 DEBUG kafka.protocol.parser:58 Sending request FindCoordinatorRequest_v2(coordinator_key='MYGROUP', coordinator_type=0)
2025-03-27 12:39:46,100 DEBUG kafka.conn:998 <BrokerConnection client_id=kafka-python-2.1.3, node_id=2 host=b-2.host.amazonaws.com:9098 <connected> [IPv4 ('10.10.10.12', 9098)]> Request 2 (timeout_ms 30000): FindCoordinatorRequest_v2(coordinator_key='MYGROUP', coordinator_type=0)
2025-03-27 12:39:46,100 DEBUG kafka.client:676 Timeouts: user inf, metadata 99.689453, idle connection 239812.000000, request 29999.951363
2025-03-27 12:39:46,100 DEBUG kafka.client:676 Timeouts: user inf, metadata 99.486816, idle connection 239812.000000, request 29999.751806
2025-03-27 12:39:46,201 DEBUG kafka.client:963 Initializing connection to node 1 for metadata request
2025-03-27 12:39:46,201 DEBUG kafka.conn:371 <BrokerConnection client_id=kafka-python-2.1.3, node_id=1 host=b-1.host.amazonaws.com:9098 <disconnected> [IPv4 ('10.10.10.11', 9098)]>: creating new socket
2025-03-27 12:39:46,201 DEBUG kafka.conn:385 <BrokerConnection client_id=kafka-python-2.1.3, node_id=1 host=b-1.host.amazonaws.com:9098 <disconnected> [IPv4 ('10.10.10.11', 9098)]>: setting socket option (6, 1, 1)
2025-03-27 12:39:46,201 INFO kafka.conn:391 <BrokerConnection client_id=kafka-python-2.1.3, node_id=1 host=b-1.host.amazonaws.com:9098 <connecting> [IPv4 ('10.10.10.11', 9098)]>: connecting to b-1.host.amazonaws.com:9098 [('10.109.2.13', 9098) IPv4]
2025-03-27 12:39:46,201 DEBUG kafka.client:676 Timeouts: user inf, metadata inf, idle connection 239711.000000, request 29898.923635
2025-03-27 12:39:46,202 DEBUG kafka.conn:408 <BrokerConnection client_id=kafka-python-2.1.3, node_id=1 host=b-1.host.amazonaws.com:9098 <connecting> [IPv4 ('10.10.10.11', 9098)]>: established TCP connection
2025-03-27 12:39:46,202 DEBUG kafka.conn:411 <BrokerConnection client_id=kafka-python-2.1.3, node_id=1 host=b-1.host.amazonaws.com:9098 <connecting> [IPv4 ('10.10.10.11', 9098)]>: initiating SSL handshake
2025-03-27 12:39:46,202 DEBUG kafka.conn:511 <BrokerConnection client_id=kafka-python-2.1.3, node_id=1 host=b-1.host.amazonaws.com:9098 <handshake> [IPv4 ('10.10.10.11', 9098)]>: wrapping socket in ssl context
2025-03-27 12:39:46,203 DEBUG kafka.client:676 Timeouts: user inf, metadata inf, idle connection 239710.000000, request 29897.448540
...
2025-03-27 12:39:46,210 DEBUG kafka.client:676 Timeouts: user inf, metadata inf, idle connection 239703.000000, request 29890.283823
2025-03-27 12:39:46,210 DEBUG kafka.client:676 Timeouts: user inf, metadata inf, idle connection 239703.000000, request 29890.190363
2025-03-27 12:39:46,210 DEBUG kafka.client:676 Timeouts: user inf, metadata inf, idle connection 239703.000000, request 29890.084505
2025-03-27 12:39:46,210 DEBUG kafka.client:676 Timeouts: user inf, metadata inf, idle connection 239702.000000, request 29890.000820
2025-03-27 12:39:46,210 DEBUG kafka.client:676 Timeouts: user inf, metadata inf, idle connection 239702.000000, request 29889.918089
2025-03-27 12:39:46,210 DEBUG kafka.client:676 Timeouts: user inf, metadata inf, idle connection 239702.000000, request 29889.770746
2025-03-27 12:39:46,210 DEBUG kafka.client:676 Timeouts: user inf, metadata inf, idle connection 239702.000000, request 29889.672518
2025-03-27 12:39:46,211 DEBUG kafka.conn:436 <BrokerConnection client_id=kafka-python-2.1.3, node_id=1 host=b-1.host.amazonaws.com:9098 <handshake> [IPv4 ('10.10.10.11', 9098)]>: completed SSL handshake.
2025-03-27 12:39:46,211 DEBUG kafka.conn:437 <BrokerConnection client_id=kafka-python-2.1.3, node_id=1 host=b-1.host.amazonaws.com:9098 <handshake> [IPv4 ('10.10.10.11', 9098)]>: checking broker Api Versions
2025-03-27 12:39:46,211 DEBUG kafka.conn:544 <BrokerConnection client_id=kafka-python-2.1.3, node_id=1 host=b-1.host.amazonaws.com:9098 <checking
2025-03-27 12:39:46,211 DEBUG kafka.conn:446 <BrokerConnection client_id=kafka-python-2.1.3, node_id=1 host=b-1.host.amazonaws.com:9098 <checking_api_versions_send> [IPv4 ('10.10.10.11', 9098)]>: initiating SASL authentication
2025-03-27 12:39:46,211 DEBUG kafka.protocol.parser:58 Sending request SaslHandshakeRequest_v1(mechanism='OAUTHBEARER')
2025-03-27 12:39:46,211 DEBUG kafka.conn:998 <BrokerConnection client_id=kafka-python-2.1.3, node_id=1 host=b-1.host.amazonaws.com:9098 <authenticating> [IPv4 ('10.10.10.11', 9098)]> Request 1 (timeout_ms 30000): SaslHandshakeRequest_v1(mechanism='OAUTHBEARER')
2025-03-27 12:39:46,211 DEBUG kafka.client:676 Timeouts: user inf, metadata inf, idle connection 239702.000000, request 29889.039755
2025-03-27 12:39:46,212 DEBUG kafka.protocol.parser:142 Received correlation id: 1
2025-03-27 12:39:46,212 DEBUG kafka.protocol.parser:160 Processing response SaslHandshakeResponse_v1
2025-03-27 12:39:46,212 DEBUG kafka.conn:1121 <BrokerConnection client_id=kafka-python-2.1.3, node_id=1 host=b-1.host.amazonaws.com:9098 <authenticating> [IPv4 ('10.10.10.11', 9098)]> Response 1 (0.8687973022460938 ms): SaslHandshakeResponse_v1(error_code=0, enabled_mechanisms=['OAUTHBEARER', 'AWS_MSK_IAM'])
2025-03-27 12:39:46,212 INFO kafka.conn:806 <BrokerConnection client_id=kafka-python-2.1.3, node_id=1 host=b-1.host.amazonaws.com:9098 <authenticating> [IPv4 ('10.10.10.11', 9098)]>: Authenticated via SASL / OAuth
2025-03-27 12:39:46,212 INFO kafka.conn:461 <BrokerConnection client_id=kafka-python-2.1.3, node_id=1 host=b-1.host.amazonaws.com:9098 <authenticating> [IPv4 ('10.10.10.11', 9098)]>: Connection complete.
2025-03-27 12:39:46,212 DEBUG kafka.client:338 Node 1 connected
2025-03-27 12:39:46,212 DEBUG kafka.client:987 Sending metadata request MetadataRequest_v7(topics=['topic1', 'topic2'], allow_auto_topic_creation=True) to node 1
2025-03-27 12:39:46,212 DEBUG kafka.protocol.parser:58 Sending request MetadataRequest_v7(topics=['topic1', 'topic2'], allow_auto_topic_creation=True)
2025-03-27 12:39:46,212 DEBUG kafka.conn:998 <BrokerConnection client_id=kafka-python-2.1.3, node_id=1 host=b-1.host.amazonaws.com:9098 <connected> [IPv4 ('10.10.10.11', 9098)]> Request 2 (timeout_ms 30000): MetadataRequest_v7(topics=['topic1', 'topic2'], allow_auto_topic_creation=True)
2025-03-27 12:39:46,212 DEBUG kafka.client:676 Timeouts: user inf, metadata 30000.000000, idle connection 239700.000000, request 29887.857676
2025-03-27 12:39:46,212 DEBUG kafka.client:676 Timeouts: user inf, metadata 30000.000000, idle connection 239700.000000, request 29887.689114
2025-03-27 12:39:46,330 ERROR kafka.conn:1144 <BrokerConnection client_id=kafka-python-2.1.3, node_id=1 host=b-1.host.amazonaws.com:9098 <connected> [IPv4 ('10.10.10.11', 9098)]>: socket disconnected
2025-03-27 12:39:46,330 ERROR kafka.conn:929 <BrokerConnection client_id=kafka-python-2.1.3, node_id=1 host=b-1.host.amazonaws.com:9098 <connected> [IPv4 ('10.10.10.11', 9098)]>: Closing connection. KafkaConnectionError: socket disconnected
2025-03-27 12:39:46,330 DEBUG kafka.conn:906 <BrokerConnection client_id=kafka-python-2.1.3, node_id=1 host=b-1.host.amazonaws.com:9098 <connected> [IPv4 ('10.10.10.11', 9098)]>: reconnect backoff 0.05904325717270622 after 1 failures
2025-03-27 12:39:46,330 WARNING kafka.client:388 Node 1 connection failed -- refreshing metadata
2025-03-27 12:39:46,330 DEBUG kafka.client:676 Timeouts: user inf, metadata 99.965820, idle connection 239582.000000, request 29769.862890
2025-03-27 12:39:46,342 ERROR kafka.conn:1144 <BrokerConnection client_id=kafka-python-2.1.3, node_id=2 host=b-2.host.amazonaws.com:9098 <connected> [IPv4 ('10.10.10.12', 9098)]>: socket disconnected
2025-03-27 12:39:46,342 ERROR kafka.conn:929 <BrokerConnection client_id=kafka-python-2.1.3, node_id=2 host=b-2.host.amazonaws.com:9098 <connected> [IPv4 ('10.10.10.12', 9098)]>: Closing connection. KafkaConnectionError: socket disconnected
2025-03-27 12:39:46,342 DEBUG kafka.conn:906 <BrokerConnection client_id=kafka-python-2.1.3, node_id=2 host=b-2.host.amazonaws.com:9098 <connected> [IPv4 ('10.10.10.12', 9098)]>: reconnect backoff 0.047846076306507945 after 1 failures
2025-03-27 12:39:46,343 WARNING kafka.client:388 Node 2 connection failed -- refreshing metadata
2025-03-27 12:39:46,343 ERROR kafka.coordinator:517 Error sending FindCoordinatorRequest_v2 to node 2 [KafkaConnectionError: socket disconnected]
2025-03-27 12:39:46,343 DEBUG kafka.coordinator:273 Requesting metadata for group coordinator request: KafkaConnectionError: socket disconnected
2025-03-27 12:39:46,343 DEBUG kafka.client:676 Timeouts: user inf, metadata 87.431885, idle connection inf, request inf
2025-03-27 12:39:46,431 DEBUG kafka.client:963 Initializing connection to node 3 for metadata request
2025-03-27 12:39:46,432 DEBUG kafka.conn:371 <BrokerConnection client_id=kafka-python-2.1.3, node_id=3 host=b-3.host.amazonaws.com:9098 <disconnected> [IPv4 ('10.10.10.10', 9098)]>: creating new socket
2025-03-27 12:39:46,432 DEBUG kafka.conn:385 <BrokerConnection client_id=kafka-python-2.1.3, node_id=3 host=b-3.host.amazonaws.com:9098 <disconnected> [IPv4 ('10.10.10.10', 9098)]>: setting socket option (6, 1, 1)
2025-03-27 12:39:46,432 INFO kafka.conn:391 <BrokerConnection client_id=kafka-python-2.1.3, node_id=3 host=b-3.host.amazonaws.com:9098 <connecting> [IPv4 ('10.10.10.10', 9098)]>: connecting to b-3.host.amazonaws.com:9098 [('10.10.10.10', 9098) IPv4]
2025-03-27 12:39:46,432 DEBUG kafka.client:676 Timeouts: user inf, metadata inf, idle connection inf, request inf
2025-03-27 12:39:46,434 DEBUG kafka.conn:408 <BrokerConnection client_id=kafka-python-2.1.3, node_id=3 host=b-3.host.amazonaws.com:9098 <connecting> [IPv4 ('10.10.10.10', 9098)]>: established TCP connection
2025-03-27 12:39:46,434 DEBUG kafka.conn:411 <BrokerConnection client_id=kafka-python-2.1.3, node_id=3 host=b-3.host.amazonaws.com:9098 <connecting> [IPv4 ('10.10.10.10', 9098)]>: initiating SSL handshake
2025-03-27 12:39:46,434 DEBUG kafka.conn:511 <BrokerConnection client_id=kafka-python-2.1.3, node_id=3 host=b-3.host.amazonaws.com:9098 <handshake
2025-03-27 12:39:46,440 DEBUG kafka.client:676 Timeouts: user inf, metadata inf, idle connection inf, request inf
2025-03-27 12:39:46,440 DEBUG kafka.client:676 Timeouts: user inf, metadata inf, idle connection inf, request inf
2025-03-27 12:39:46,440 DEBUG kafka.client:676 Timeouts: user inf, metadata inf, idle connection inf, request inf
2025-03-27 12:39:46,440 DEBUG kafka.client:676 Timeouts: user inf, metadata inf, idle connection inf, request inf
2025-03-27 12:39:46,440 DEBUG kafka.client:676 Timeouts: user inf, metadata inf, idle connection inf, request inf
2025-03-27 12:39:46,440 DEBUG kafka.client:676 Timeouts: user inf, metadata inf, idle connection inf, request inf
2025-03-27 12:39:46,440 DEBUG kafka.client:676 Timeouts: user inf, metadata inf, idle connection inf, request inf
2025-03-27 12:39:46,440 DEBUG kafka.client:676 Timeouts: user inf, metadata inf, idle connection inf, request inf
2025-03-27 12:39:46,440 DEBUG kafka.client:676 Timeouts: user inf, metadata inf, idle connection inf, request inf
2025-03-27 12:39:46,440 DEBUG kafka.client:676 Timeouts: user inf, metadata inf, idle connection inf, request inf
2025-03-27 12:39:46,441 DEBUG kafka.client:676 Timeouts: user inf, metadata inf, idle connection inf, request inf
2025-03-27 12:39:46,441 DEBUG kafka.client:676 Timeouts: user inf, metadata inf, idle connection inf, request inf
2025-03-27 12:39:46,441 DEBUG kafka.client:676 Timeouts: user inf, metadata inf, idle connection inf, request inf
2025-03-27 12:39:46,441 DEBUG kafka.client:676 Timeouts: user inf, metadata inf, idle connection inf, request inf
2025-03-27 12:39:46,441 DEBUG kafka.client:676 Timeouts: user inf, metadata inf, idle connection inf, request inf
2025-03-27 12:39:46,441 DEBUG kafka.client:676 Timeouts: user inf, metadata inf, idle connection inf, request inf
2025-03-27 12:39:46,441 DEBUG kafka.client:676 Timeouts: user inf, metadata inf, idle connection inf, request inf
2025-03-27 12:39:46,441 DEBUG kafka.client:676 Timeouts: user inf, metadata inf, idle connection inf, request inf
2025-03-27 12:39:46,441 DEBUG kafka.client:676 Timeouts: user inf, metadata inf, idle connection inf, request inf
...
2025-03-27 12:39:47,512 DEBUG kafka.conn:436 <BrokerConnection client_id=kafka-python-2.1.3, node_id=3 host=b-3.host.amazonaws.com:9098 <handshake>
2025-03-27 12:39:47,512 DEBUG kafka.conn:437 <BrokerConnection client_id=kafka-python-2.1.3, node_id=3 host=b-3.host.amazonaws.com:9098 <handshake> [IPv4 ('10.10.10.10', 9098)]>: checking broker Api Versions
2025-03-27 12:39:47,512 DEBUG kafka.conn:544 <BrokerConnection client_id=kafka-python-2.1.3, node_id=3 host=b-3.host.amazonaws.com:9098 <checking_api_versions_send> [IPv4 ('10.10.10.10', 9098)]>: Using pre-configured api_version (2, 8) for ApiVersions
2025-03-27 12:39:47,512 DEBUG kafka.conn:446 <BrokerConnection client_id=kafka-python-2.1.3, node_id=3 host=b-3.host.amazonaws.com:9098 <checking_api_versions_send> [IPv4 ('10.10.10.10', 9098)]>: initiating SASL authentication
2025-03-27 12:39:47,512 DEBUG kafka.protocol.parser:58 Sending request SaslHandshakeRequest_v1(mechanism='OAUTHBEARER')
2025-03-27 12:39:47,513 DEBUG kafka.conn:998 <BrokerConnection client_id=kafka-python-2.1.3, node_id=3 host=b-3.host.amazonaws.com:9098 <authenticating> [IPv4 ('10.10.10.10', 9098)]> Request 1 (timeout_ms 30000): SaslHandshakeRequest_v1(mechanism='OAUTHBEARER')
2025-03-27 12:39:47,513 DEBUG kafka.client:676 Timeouts: user inf, metadata inf, idle connection 238400.000000, request 29890.324354
2025-03-27 12:39:47,514 DEBUG kafka.protocol.parser:142 Received correlation id: 1
2025-03-27 12:39:47,514 DEBUG kafka.protocol.parser:160 Processing response SaslHandshakeResponse_v1
2025-03-27 12:39:47,514 DEBUG kafka.conn:1121 <BrokerConnection client_id=kafka-python-2.1.3, node_id=3 host=b-3.host.amazonaws.com:9098 <authenticating> [IPv4 ('10.10.10.10', 9098)]> Response 1 (1.1398792266845703 ms): SaslHandshakeResponse_v1(error_code=0, enabled_mechanisms=['OAUTHBEARER', 'AWS_MSK_IAM'])
2025-03-27 12:39:47,514 INFO kafka.conn:806 <BrokerConnection client_id=kafka-python-2.1.3, node_id=3 host=b-3.host.amazonaws.com:9098 <authenticating> [IPv4 ('10.10.10.10', 9098)]>: Authenticated via SASL / OAuth
2025-03-27 12:39:47,514 INFO kafka.conn:461 <BrokerConnection client_id=kafka-python-2.1.3, node_id=3 host=b-3.host.amazonaws.com:9098 <authenticating> [IPv4 ('10.10.10.10', 9098)]>: Connection complete.
2025-03-27 12:39:47,514 DEBUG kafka.client:338 Node 3 connected
2025-03-27 12:39:47,514 DEBUG kafka.client:987 Sending metadata request MetadataRequest_v7(topics=['topic1', 'topic2'], allow_auto_topic_creation=True) to node 3
2025-03-27 12:39:47,514 DEBUG kafka.protocol.parser:58 Sending request MetadataRequest_v7(topics=['topic1', 'topic2'], allow_auto_topic_creation=True)
2025-03-27 12:39:47,514 DEBUG kafka.conn:998 <BrokerConnection client_id=kafka-python-2.1.3, node_id=3 host=b-3.host.amazonaws.com:9098 <connected> [IPv4 ('10.10.10.10', 9098)]> Request 2 (timeout_ms 30000): MetadataRequest_v7(topics=['topic1', 'topic2'], allow_auto_topic_creation=True)
2025-03-27 12:39:47,514 DEBUG kafka.client:676 Timeouts: user inf, metadata 30000.000000, idle connection 238398.000000, request 29888.864756
2025-03-27 12:39:47,514 DEBUG kafka.client:676 Timeouts: user inf, metadata 30000.000000, idle connection 238398.000000, request 29888.695002
2025-03-27 12:39:47,575 DEBUG kafka.protocol.parser:142 Received correlation id: 2
2025-03-27 12:39:47,575 DEBUG kafka.protocol.parser:160 Processing response FindCoordinatorResponse_v2
2025-03-27 12:39:47,575 DEBUG kafka.conn:1121 <BrokerConnection client_id=kafka-python-2.1.3, node_id=1 host=b-1.host.amazonaws.com:9098 <connected> [IPv4 ('10.10.10.11', 9098)]> Response 2 (171.59223556518555 ms): FindCoordinatorResponse_v2(throttle_time_ms=0, error_code=34, error_message='Request is not valid given the current SASL state.', coordinator_id=-1, host='', port=-1)
2025-03-27 12:39:47,575 DEBUG kafka.coordinator:706 Received group coordinator response FindCoordinatorResponse_v2(throttle_time_ms=0, error_code=34, error_message='Request is not valid given the current SASL state.', coordinator_id=-1, host='', port=-1)
2025-03-27 12:39:47,575 ERROR kafka.coordinator:734 Group coordinator lookup for group MYGROUP failed: [Error 34] IllegalSaslStateError

These errors might happen on rebalancing. With 2.0.6 I seem to not encounter this problem. At least starting with 2.1.2 I run into this problem.

Generally the connection (consumer/producer) is working. As far as I can see, all messages are still correctly consumed/sent.

[dpkp]

Thanks for the notes. Your debug logs show IllegalSaslStateError for node_id=1, but most/all of the debug logs are for a different connection to node_id=3. Can you replicate and post debug logs for the failing connection (here, node_id=1)?

[Lasall]

Will do, the logs look very similar for all nodes.

[dpkp]

Ok, one thing that jumps out from node_id=3 is that it jumps directly from SaslHandshake to Metadata, without sending SaslAuthenticate. That seems like it would also trigger an ILLEGAL_SASL_STATE error, similar to what we see on node_id=1. Have these connections disconnected previously? It looks like we are not resetting SASL state correctly on disconnect. So perhaps your initial connection works, but then after an error or timeout you disconnect and then reconnection fails w/ illegal sasl state ?

[dpkp]

Take a look at PR #2571 - are you able to test w/ master and/or pull requests?

[dpkp]

Also put up #2572 , though I don't think it is the cause of your errors. If it were I'd expect to see a SaslAuthenticateResponse w/ non-zero auth_bytes.

[Lasall]

I extended the log a little bit, let me know if you need more. I will deploy 2571+2572 tomorrow and report back.

[dpkp]

Thanks. I think #2571 is the fix for this.

[Lasall]

With the current master (2571) I no longer run into the Sasl errors. Thank you so much for the lightning fast fix <3

I still get socket disconnects (similar to the logs above), which output ERROR messages (around every hour, maybe related to IAM token lifetime), but they don't lead to tracebacks. This behavior works for me, if you want me to help investigate the disconnects, I can support you with logs (probably best in a new issue?).

[dpkp]

Great, yea feel free to open another issue re: unexpected disconnects!