SASL handshake takes too long

[majzayer]

Description

Authentication using SASL/SCRAM or SASL/PLAINTEXT takes around 9 seconds to complete. Is this normal?

How to reproduce

• One Kafka broker instance
• One C# producer that does the following:

static void Main(string[] args)
        {
            var producerConfig = PropertiesUtils.ReadPropertiesFile("producer.properties");

            using (var producer = new Producer<Null, string>(producerConfig, null, new StringSerializer(Encoding.UTF8)))
            {
                while (true)
                {
                    Console.Write("message: ");
                    string msg = Console.ReadLine();

                    producer.ProduceAsync("test-topic", null, msg);
                }
            }
        }

• One C# consumer that does the following:

static void Main(string[] args)
        {
            var config = PropertiesUtils.ReadPropertiesFile("consumer.properties");

            using (var consumer = new Consumer<Null, string>(config, null, new StringDeserializer(Encoding.UTF8)))
            {
                consumer.OnMessage += (_, msg)
                      =>
                {
                    Console.WriteLine(msg.Value);
                };

                consumer.OnError += (_, error)
                  => Console.WriteLine($"Error: {error}");

                consumer.OnConsumeError += (_, msg)
                  => Console.WriteLine($"Consume error ({msg.TopicPartitionOffset}): {msg.Error}");

                consumer.Subscribe("test-topic");

                while (true)
                {
                    try
                    {
                        consumer.Poll(TimeSpan.FromMilliseconds(1000));
                    }
                    catch(Exception e)
                    {
                        Console.WriteLine(e.Message);
                    }
                }
            }
        }

• server.properties:

# The id of the broker
broker.id=0

############################# Socket Server Settings #############################
num.network.threads=3
num.io.threads=8
socket.send.buffer.bytes=102400
socket.receive.buffer.bytes=102400
socket.request.max.bytes=104857600
session.timeout.ms=1000
group.initial.rebalance.delay.ms=0

### AUTHENTICATION AND ENCRYPTION  ###
listeners=SASL_SSL://localhost:9093

# Keystore configs
ssl.keystore.type =JKS
ssl.keystore.location=...
ssl.keystore.password=...
ssl.key.password=...

# Trust store configs
ssl.truststore.type=JKS
ssl.truststore.location=...
ssl.truststore.password=...

# List the accepted TLS protocols
ssl.protocol=TLS
ssl.enabled.protocols=TLSv1.2,TLSv1.1,TLSv1
ssl.client.auth=required

# Enable SSL for inter-broker communication
security.inter.broker.protocol=SASL_SSL

# Enforce using a non-default pseudo-random generator for better performance
ssl.secure.random.implementation=SHA1PRNG

# Enable SASL support
sasl.enabled.mechanisms=PLAIN,SCRAM-SHA-256
sasl.mechanism.inter.broker.protocol=PLAIN
#sasl.mechanism.inter.broker.protocol=PLAINTEXT

############################# Log Basics ############################
log.dirs=...
num.partitions=1
num.recovery.threads.per.data.dir=1

############################# Internal Topic Settings  #############################
offsets.topic.replication.factor=1
transaction.state.log.replication.factor=1
transaction.state.log.min.isr=1

############################# Log Retention Policy #############################
log.retention.hours=168
log.retention.bytes=1073741824
log.segment.bytes=1073741824
log.retention.check.interval.ms=300000
num.replica.fetchers=1
############################# Zookeeper #############################
zookeeper.connect=localhost:2181

# Timeout in ms for connecting to zookeeper
zookeeper.connection.timeout.ms=6000

############################# Group Coordinator Settings #############################
group.initial.rebalance.delay.ms=0

• consumer.properties

bootstrap.servers=localhost:9093
group.id=test-consumer-group
fetch.min.bytes=1
fetch.wait.max.ms=1
auto.offset.reset=latest
socket.blocking.max.ms=1
fetch.error.backoff.ms=1
############################# Security Configuration #############################
ssl.ca.location=...
ssl.certificate.location=...
ssl.key.location=...
ssl.key.password=..
security.protocol=SASL_SSL
sasl.mechanisms=PLAIN
sasl.username=...
sasl.password=...

• producer.properties

############################# Producer Basics #############################
bootstrap.servers=localhost:9093
compression.type=none
linger.ms=0
retries=0
acks=0

############################# Security Configuration #############################
ssl.ca.location=...
ssl.certificate.location=...
ssl.key.location=...
ssl.key.password=...

# SASL configs
security.protocol=SASL_SSL
sasl.mechanisms=PLAIN
sasl.username=...
sasl.password=...

• Run the consumer. It takes approximately 9 seconds to finish the SASL handshake from request to completion. Here's the log:

.
.
.
[2018-07-06 17:03:37,673] DEBUG Set SASL server state to HANDSHAKE_OR_VERSIONS_REQUEST (org.apache.kafka.common.security.authenticator.SaslServerAuthenticator)
[2018-07-06 17:03:37,673] DEBUG Handling Kafka request API_VERSIONS (org.apache.kafka.common.security.authenticator.SaslServerAuthenticator)
[2018-07-06 17:03:37,673] DEBUG Set SASL server state to HANDSHAKE_REQUEST (org.apache.kafka.common.security.authenticator.SaslServerAuthenticator)
[2018-07-06 17:03:37,673] DEBUG Handling Kafka request SASL_HANDSHAKE (org.apache.kafka.common.security.authenticator.SaslServerAuthenticator)
[2018-07-06 17:03:37,674] DEBUG Using SASL mechanism 'PLAIN' provided by client (org.apache.kafka.common.security.authenticator.SaslServerAuthenticator)
[2018-07-06 17:03:46,805] DEBUG Set SASL server state to AUTHENTICATE (org.apache.kafka.common.security.authenticator.SaslServerAuthenticator)
[2018-07-06 17:03:46,807] DEBUG Set SASL server state to COMPLETE (org.apache.kafka.common.security.authenticator.SaslServerAuthenticator)

• It takes the same duration to authenticate the producer as well.

Checklist

Please provide the following information:

• Confluent.Kafka nuget version: 0.11.4
• Apache Kafka version: 1.1.0
• Client configuration:
• Operating system: Windows 10 Pro
• Provide logs (with "debug" : "..." as necessary in configuration)
• Provide broker log excerpts
• Critical issue

[edenhill]

Run the client with the "debug" config property set to "broker,protocol,security" and see if you can work out where the delays are adding up

[majzayer]

Thanks @edenhill. I enabled borker, protocol, and security debugging on the consumer and I see that the delay is caused by

• SSL handshake (~ 9 seconds)
• SASL authentication (~ 9 seconds)

Is this a normal delay? If not, how can it be reduced?

Debug lines that cause the delay are in bold:

7|2018-07-17 09:12:51.685|rdkafka#consumer-1|SASL| [thrd:app]: Selected provider PLAIN (builtin) for SASL mechanism PLAIN
7|2018-07-17 09:12:51.835|rdkafka#consumer-1|SSL| [thrd:app]: Loading CA certificate(s) from file [...]/cert/ca-cert
7|2018-07-17 09:12:51.835|rdkafka#consumer-1|SSL| [thrd:app]: Loading certificate from file [...]/cert/client_localhost_client.pem
7|2018-07-17 09:12:51.835|rdkafka#consumer-1|SSL| [thrd:app]: Loading private key file from [...]/cert/client_localhost_client.key
7|2018-07-17 09:12:51.835|rdkafka#consumer-1|SSLPASSWD| [thrd:app]: Private key file "[...]/cert/client_localhost_client.key" requires password
7|2018-07-17 09:12:51.835|rdkafka#consumer-1|BROKER| [thrd:app]: sasl_ssl://localhost:9093/bootstrap: Added new broker with NodeId -1
7|2018-07-17 09:12:51.835|rdkafka#consumer-1|BRKMAIN| [thrd::0/internal]: :0/internal: Enter main broker thread
7|2018-07-17 09:12:51.835|rdkafka#consumer-1|STATE| [thrd::0/internal]: :0/internal: Broker changed state INIT -> UP
7|2018-07-17 09:12:51.835|rdkafka#consumer-1|BRKMAIN| [thrd:sasl_ssl://localhost:9093/bootstrap]: sasl_ssl://localhost:9093/bootstrap: Enter main broker thread
7|2018-07-17 09:12:51.835|rdkafka#consumer-1|CONNECT| [thrd:sasl_ssl://localhost:9093/bootstrap]: sasl_ssl://localhost:9093/bootstrap: broker in state INIT connecting
7|2018-07-17 09:12:51.845|rdkafka#consumer-1|CONNECT| [thrd:sasl_ssl://localhost:9093/bootstrap]: sasl_ssl://localhost:9093/bootstrap: Connecting to ipv4#localhost:9093 (sasl_ssl) with socket 1144
7|2018-07-17 09:12:51.845|rdkafka#consumer-1|STATE| [thrd:sasl_ssl://localhost:9093/bootstrap]: sasl_ssl://localhost:9093/bootstrap: Broker changed state INIT -> CONNECT
7|2018-07-17 09:12:51.845|rdkafka#consumer-1|CONNECT| [thrd:sasl_ssl://localhost:9093/bootstrap]: sasl_ssl://localhost:9093/bootstrap: Connected to ipv4#localhost:9093
7|2018-07-17 09:13:01.181|rdkafka#consumer-1|SSLVERIFY| [thrd:sasl_ssl://localhost:9093/bootstrap]: sasl_ssl://localhost:9093/bootstrap: Broker SSL certificate verified
7|2018-07-17 09:13:01.181|rdkafka#consumer-1|CONNECTED| [thrd:sasl_ssl://localhost:9093/bootstrap]: sasl_ssl://localhost:9093/bootstrap: Connected (#1)
7|2018-07-17 09:13:01.181|rdkafka#consumer-1|FEATURE| [thrd:sasl_ssl://localhost:9093/bootstrap]: sasl_ssl://localhost:9093/bootstrap: Updated enabled protocol features +ApiVersion to ApiVersion
7|2018-07-17 09:13:01.181|rdkafka#consumer-1|STATE| [thrd:sasl_ssl://localhost:9093/bootstrap]: sasl_ssl://localhost:9093/bootstrap: Broker changed state CONNECT -> APIVERSION_QUERY
7|2018-07-17 09:13:01.181|rdkafka#consumer-1|SEND| [thrd:sasl_ssl://localhost:9093/bootstrap]: sasl_ssl://localhost:9093/bootstrap: Sent ApiVersionRequest (v0, 25 bytes @ 0, CorrId 1)
7|2018-07-17 09:13:01.191|rdkafka#consumer-1|RECV| [thrd:sasl_ssl://localhost:9093/bootstrap]: sasl_ssl://localhost:9093/bootstrap: Received ApiVersionResponse (v0, 264 bytes, CorrId 1, rtt 16.00ms)
7|2018-07-17 09:13:01.191|rdkafka#consumer-1|FEATURE| [thrd:sasl_ssl://localhost:9093/bootstrap]: sasl_ssl://localhost:9093/bootstrap: Updated enabled protocol features to MsgVer1,ApiVersion,BrokerBalancedConsumer,ThrottleTime,Sasl,SaslHandshake,BrokerGroupCoordinator,LZ4,OffsetTime,MsgVer2
7|2018-07-17 09:13:01.191|rdkafka#consumer-1|AUTH| [thrd:sasl_ssl://localhost:9093/bootstrap]: sasl_ssl://localhost:9093/bootstrap: Auth in state APIVERSION_QUERY (handshake supported)
7|2018-07-17 09:13:01.191|rdkafka#consumer-1|STATE| [thrd:sasl_ssl://localhost:9093/bootstrap]: sasl_ssl://localhost:9093/bootstrap: Broker changed state APIVERSION_QUERY -> AUTH_HANDSHAKE
7|2018-07-17 09:13:01.191|rdkafka#consumer-1|SEND| [thrd:sasl_ssl://localhost:9093/bootstrap]: sasl_ssl://localhost:9093/bootstrap: Sent SaslHandshakeRequest (v0, 28 bytes @ 0, CorrId 2)
7|2018-07-17 09:13:01.191|rdkafka#consumer-1|RECV| [thrd:sasl_ssl://localhost:9093/bootstrap]: sasl_ssl://localhost:9093/bootstrap: Received SaslHandshakeResponse (v0, 28 bytes, CorrId 2, rtt 0.00ms)
7|2018-07-17 09:13:01.191|rdkafka#consumer-1|SASLMECHS| [thrd:sasl_ssl://localhost:9093/bootstrap]: sasl_ssl://localhost:9093/bootstrap: Broker supported SASL mechanisms: PLAIN,SCRAM-SHA-256
7|2018-07-17 09:13:01.191|rdkafka#consumer-1|AUTH| [thrd:sasl_ssl://localhost:9093/bootstrap]: sasl_ssl://localhost:9093/bootstrap: Auth in state AUTH_HANDSHAKE (handshake supported)
7|2018-07-17 09:13:01.191|rdkafka#consumer-1|STATE| [thrd:sasl_ssl://localhost:9093/bootstrap]: sasl_ssl://localhost:9093/bootstrap: Broker changed state AUTH_HANDSHAKE -> AUTH
7|2018-07-17 09:13:01.191|rdkafka#consumer-1|SASL| [thrd:sasl_ssl://localhost:9093/bootstrap]: sasl_ssl://localhost:9093/bootstrap: Initializing SASL client: service name kafka, hostname localhost, mechanisms PLAIN, provider PLAIN (builtin)
7|2018-07-17 09:13:01.191|rdkafka#consumer-1|SASLPLAIN| [thrd:sasl_ssl://localhost:9093/bootstrap]: sasl_ssl://localhost:9093/bootstrap: Sending SASL PLAIN (builtin) authentication token
7|2018-07-17 09:13:01.191|rdkafka#consumer-1|SASL| [thrd:sasl_ssl://localhost:9093/bootstrap]: sasl_ssl://localhost:9093/bootstrap: Send SASL frame to broker (15 bytes)
7|2018-07-17 09:13:10.516|rdkafka#consumer-1|SASL| [thrd:sasl_ssl://localhost:9093/bootstrap]: sasl_ssl://localhost:9093/bootstrap: Received SASL frame from broker (4 bytes)
7|2018-07-17 09:13:10.516|rdkafka#consumer-1|SASLPLAIN| [thrd:sasl_ssl://localhost:9093/bootstrap]: sasl_ssl://localhost:9093/bootstrap: Received non-empty SASL PLAIN (builtin) response from broker (4 bytes)
7|2018-07-17 09:13:10.516|rdkafka#consumer-1|STATE| [thrd:sasl_ssl://localhost:9093/bootstrap]: sasl_ssl://localhost:9093/bootstrap: Broker changed state AUTH -> UP
7|2018-07-17 09:13:10.516|rdkafka#consumer-1|SEND| [thrd:sasl_ssl://localhost:9093/bootstrap]: sasl_ssl://localhost:9093/bootstrap: Sent MetadataRequest (v2, 25 bytes @ 0, CorrId 3)
7|2018-07-17 09:13:10.516|rdkafka#consumer-1|RECV| [thrd:sasl_ssl://localhost:9093/bootstrap]: sasl_ssl://localhost:9093/bootstrap: Received MetadataResponse (v2, 63 bytes, CorrId 3, rtt 0.00ms)
7|2018-07-17 09:13:10.516|rdkafka#consumer-1|CLUSTERID| [thrd:main]: sasl_ssl://localhost:9093/bootstrap: ClusterId update "" -> "_NFkQXRvQoOjbl4iFxxD8Q"
7|2018-07-17 09:13:10.526|rdkafka#consumer-1|UPDATE| [thrd:sasl_ssl://localhost:9093/bootstrap]: sasl_ssl://localhost:9093/bootstrap: NodeId changed from -1 to 0
7|2018-07-17 09:13:10.526|rdkafka#consumer-1|UPDATE| [thrd:sasl_ssl://localhost:9093/bootstrap]: sasl_ssl://localhost:9093/0: Name changed from sasl_ssl://localhost:9093/bootstrap to sasl_ssl://localhost:9093/0
7|2018-07-17 09:13:10.526|rdkafka#consumer-1|LEADER| [thrd:sasl_ssl://localhost:9093/bootstrap]: sasl_ssl://localhost:9093/0: Mapped 0 partition(s) to broker
7|2018-07-17 09:13:10.526|rdkafka#consumer-1|STATE| [thrd:sasl_ssl://localhost:9093/bootstrap]: sasl_ssl://localhost:9093/0: Broker changed state UP -> UPDATE

[edenhill]

Ouch, no, SSL handshake should be much faster than that, well below 1s. And SASL PLAIN Auth should be pretty much instant.

Do other clients or other platforms (linux, osx) show the same problem?

[mhowlett]

please re-open if you have further information. this looks to me like an issue outside the scope of this client (but we can still comment on further information).

[majzayer]

When I setup the broker on an Ubuntu virtual machine and connected the clients from Windows, the latency is no longer observed. I wonder why the SSL handshake and SASL authentication each take 10 seconds on Windows!

Thanks @edenhill for the useful tip.