Connecting fails (Unexpected Kafka request during SASL handshake)

[weeco]

Hi,
even though I already succeeded to connect to some Kafka clusters with franz-go now I have a case where the connection or the metadata request fails. I turned on debug logs in the client but I couldn't tell what exactly is wrong.

I'm trying to connect against a remote Kafka cluster that is protected with SASL_SSL (plain mechanism). It fails right at the first request I try to send (which is a metadata request). This fails because the 20s context expires at some point.

Franz-go v0.6.1

func (s *Service) GetMetadata(ctx context.Context) (*kmsg.MetadataResponse, error) {
	req := kmsg.MetadataRequest{
		Topics: nil,
	}

	return req.RequestWith(ctx, s.KafkaClient)
}

Client logs:

(The client logs indicate a succesful connection however the metadata request never returns until the context is exceeded):

{"level":"info","ts":"2020-11-24T11:41:05.369+0100","msg":"initializing customer service","service":"customer_service"}
{"level":"debug","ts":"2020-11-24T11:41:05.369+0100","msg":"opening connection to broker","source":"kafka_client","addr":"bootstrap.redacted-kafka-dns.company.com:9094","id":-2147483648}
{"level":"debug","ts":"2020-11-24T11:41:05.600+0100","msg":"connection opened to broker","source":"kafka_client","addr":"bootstrap.redacted-kafka-dns.company.com:9094","id":-2147483648}
{"level":"debug","ts":"2020-11-24T11:41:05.600+0100","msg":"issuing api versions request","source":"kafka_client","version":3}
{"level":"debug","ts":"2020-11-24T11:41:05.625+0100","msg":"initialized api versions","source":"kafka_client","versions":[8,11,5,9,4,3,6,3,8,7,3,7,4,4,5,5,4,1,3,5,4,2,3,3,1,1,1,0,3,2,2,2,3,1,1,2,2,2,2,2,2,2,2,2,1,0,0,0,0,0,-1,-1,-1,-1,-1,-1,-1,-1]}
{"level":"debug","ts":"2020-11-24T11:41:05.625+0100","msg":"connection initialized successfully","source":"kafka_client","addr":"bootstrap.redacted-kafka-dns.company.com:9094","id":-2147483648}
{"level":"debug","ts":"2020-11-24T11:41:06.045+0100","msg":"opening connection to broker","source":"kafka_client","addr":"bootstrap.redacted-kafka-dns.company.com:9094","id":-2147483648}
{"level":"debug","ts":"2020-11-24T11:41:06.169+0100","msg":"connection opened to broker","source":"kafka_client","addr":"bootstrap.redacted-kafka-dns.company.com:9094","id":-2147483648}
{"level":"debug","ts":"2020-11-24T11:41:06.169+0100","msg":"issuing api versions request","source":"kafka_client","version":3}
{"level":"debug","ts":"2020-11-24T11:41:06.194+0100","msg":"initialized api versions","source":"kafka_client","versions":[8,11,5,9,4,3,6,3,8,7,3,7,4,4,5,5,4,1,3,5,4,2,3,3,1,1,1,0,3,2,2,2,3,1,1,2,2,2,2,2,2,2,2,2,1,0,0,0,0,0,-1,-1,-1,-1,-1,-1,-1,-1]}
{"level":"debug","ts":"2020-11-24T11:41:06.194+0100","msg":"connection initialized successfully","source":"kafka_client","addr":"bootstrap.redacted-kafka-dns.company.com:9094","id":-2147483648}
{"level":"debug","ts":"2020-11-24T11:41:06.702+0100","msg":"opening connection to broker","source":"kafka_client","addr":"bootstrap.redacted-kafka-dns.company.com:9094","id":-2147483648}
{"level":"debug","ts":"2020-11-24T11:41:06.810+0100","msg":"connection opened to broker","source":"kafka_client","addr":"bootstrap.redacted-kafka-dns.company.com:9094","id":-2147483648}
{"level":"debug","ts":"2020-11-24T11:41:06.810+0100","msg":"issuing api versions request","source":"kafka_client","version":3}
{"level":"debug","ts":"2020-11-24T11:41:06.835+0100","msg":"initialized api versions","source":"kafka_client","versions":[8,11,5,9,4,3,6,3,8,7,3,7,4,4,5,5,4,1,3,5,4,2,3,3,1,1,1,0,3,2,2,2,3,1,1,2,2,2,2,2,2,2,2,2,1,0,0,0,0,0,-1,-1,-1,-1,-1,-1,-1,-1]}
{"level":"debug","ts":"2020-11-24T11:41:06.835+0100","msg":"connection initialized successfully","source":"kafka_client","addr":"bootstrap.redacted-kafka-dns.company.com:9094","id":-2147483648}
{"level":"debug","ts":"2020-11-24T11:41:07.580+0100","msg":"opening connection to broker","source":"kafka_client","addr":"bootstrap.redacted-kafka-dns.company.com:9094","id":-2147483648}
{"level":"debug","ts":"2020-11-24T11:41:07.684+0100","msg":"connection opened to broker","source":"kafka_client","addr":"bootstrap.redacted-kafka-dns.company.com:9094","id":-2147483648}
{"level":"debug","ts":"2020-11-24T11:41:07.684+0100","msg":"issuing api versions request","source":"kafka_client","version":3}
{"level":"debug","ts":"2020-11-24T11:41:07.709+0100","msg":"initialized api versions","source":"kafka_client","versions":[8,11,5,9,4,3,6,3,8,7,3,7,4,4,5,5,4,1,3,5,4,2,3,3,1,1,1,0,3,2,2,2,3,1,1,2,2,2,2,2,2,2,2,2,1,0,0,0,0,0,-1,-1,-1,-1,-1,-1,-1,-1]}
{"level":"debug","ts":"2020-11-24T11:41:07.709+0100","msg":"connection initialized successfully","source":"kafka_client","addr":"bootstrap.redacted-kafka-dns.company.com:9094","id":-2147483648}
{"level":"debug","ts":"2020-11-24T11:41:08.988+0100","msg":"opening connection to broker","source":"kafka_client","addr":"bootstrap.redacted-kafka-dns.company.com:9094","id":-2147483648}
{"level":"debug","ts":"2020-11-24T11:41:09.092+0100","msg":"connection opened to broker","source":"kafka_client","addr":"bootstrap.redacted-kafka-dns.company.com:9094","id":-2147483648}
{"level":"debug","ts":"2020-11-24T11:41:09.092+0100","msg":"issuing api versions request","source":"kafka_client","version":3}
{"level":"debug","ts":"2020-11-24T11:41:09.117+0100","msg":"initialized api versions","source":"kafka_client","versions":[8,11,5,9,4,3,6,3,8,7,3,7,4,4,5,5,4,1,3,5,4,2,3,3,1,1,1,0,3,2,2,2,3,1,1,2,2,2,2,2,2,2,2,2,1,0,0,0,0,0,-1,-1,-1,-1,-1,-1,-1,-1]}
{"level":"debug","ts":"2020-11-24T11:41:09.117+0100","msg":"connection initialized successfully","source":"kafka_client","addr":"bootstrap.redacted-kafka-dns.company.com:9094","id":-2147483648}
{"level":"debug","ts":"2020-11-24T11:41:10.442+0100","msg":"opening connection to broker","source":"kafka_client","addr":"bootstrap.redacted-kafka-dns.company.com:9094","id":-2147483648}
{"level":"debug","ts":"2020-11-24T11:41:10.562+0100","msg":"connection opened to broker","source":"kafka_client","addr":"bootstrap.redacted-kafka-dns.company.com:9094","id":-2147483648}
{"level":"debug","ts":"2020-11-24T11:41:10.563+0100","msg":"issuing api versions request","source":"kafka_client","version":3}
{"level":"debug","ts":"2020-11-24T11:41:10.588+0100","msg":"initialized api versions","source":"kafka_client","versions":[8,11,5,9,4,3,6,3,8,7,3,7,4,4,5,5,4,1,3,5,4,2,3,3,1,1,1,0,3,2,2,2,3,1,1,2,2,2,2,2,2,2,2,2,1,0,0,0,0,0,-1,-1,-1,-1,-1,-1,-1,-1]}
{"level":"debug","ts":"2020-11-24T11:41:10.588+0100","msg":"connection initialized successfully","source":"kafka_client","addr":"bootstrap.redacted-kafka-dns.company.com:9094","id":-2147483648}
{"level":"debug","ts":"2020-11-24T11:41:11.927+0100","msg":"opening connection to broker","source":"kafka_client","addr":"bootstrap.redacted-kafka-dns.company.com:9094","id":-2147483648}
{"level":"debug","ts":"2020-11-24T11:41:12.055+0100","msg":"connection opened to broker","source":"kafka_client","addr":"bootstrap.redacted-kafka-dns.company.com:9094","id":-2147483648}
{"level":"debug","ts":"2020-11-24T11:41:12.056+0100","msg":"issuing api versions request","source":"kafka_client","version":3}
{"level":"debug","ts":"2020-11-24T11:41:12.081+0100","msg":"initialized api versions","source":"kafka_client","versions":[8,11,5,9,4,3,6,3,8,7,3,7,4,4,5,5,4,1,3,5,4,2,3,3,1,1,1,0,3,2,2,2,3,1,1,2,2,2,2,2,2,2,2,2,1,0,0,0,0,0,-1,-1,-1,-1,-1,-1,-1,-1]}
{"level":"debug","ts":"2020-11-24T11:41:12.081+0100","msg":"connection initialized successfully","source":"kafka_client","addr":"bootstrap.redacted-kafka-dns.company.com:9094","id":-2147483648}

Broker logs (broker id: 0)

[2020-11-24 10:33:55,065] INFO (data-plane-kafka-network-thread-0-ListenerName(EXTERNAL)-SASL_SSL-7:Selector) [SocketServer brokerId=0] Failed authentication with gke-clustername-misc-v1-91481fd4-bdx7.c.redacted-project.internal/172.24.127.216 (Unexpected Kafka request of type METADATA during SASL handshake.)
[2020-11-24 10:33:56,525] INFO (data-plane-kafka-network-thread-0-ListenerName(EXTERNAL)-SASL_SSL-8:Selector) [SocketServer brokerId=0] Failed authentication with gke-clustername-zoo-plat-sandbox-v1-5bb0c044-rfwi.c.redacted-project.internal/172.24.127.24 (Unexpected Kafka request of type METADATA during SASL handshake.)
[2020-11-24 10:33:56,525] INFO (data-plane-kafka-network-thread-0-ListenerName(EXTERNAL)-SASL_SSL-8:Selector) [SocketServer brokerId=0] Failed authentication with gke-clustername-zoo-plat-sandbox-v1-5bb0c044-rfwi.c.redacted-project.internal/172.24.127.24 (Unexpected Kafka request of type METADATA during SASL handshake.)
[2020-11-24 10:34:00,943] INFO (data-plane-kafka-network-thread-0-ListenerName(EXTERNAL)-SASL_SSL-6:Selector) [SocketServer brokerId=0] Failed authentication with gke-clustername-kafka-plat-sandbox-v1-d0cad066-qurw.c.redacted-project.internal/172.24.127.4 (Unexpected Kafka request of type METADATA during SASL handshake.)
[2020-11-24 10:34:00,943] INFO (data-plane-kafka-network-thread-0-ListenerName(EXTERNAL)-SASL_SSL-6:Selector) [SocketServer brokerId=0] Failed authentication with gke-clustername-kafka-plat-sandbox-v1-d0cad066-qurw.c.redacted-project.internal/172.24.127.4 (Unexpected Kafka request of type METADATA during SASL handshake.)

[weeco]

I forgot to set the SASL mechanism which caused that behaviour. Is it maybe possible to improve the debug log messages for this? If that's not possible this issue can be closed I think.