SaslAuthenticateRequest timeouts

[jordaniversen]

Hello,
I have a Go program running in AWS Lambda that uses this library to produce messages to our AWS MSK cluster with 3 brokers. I experience frequent errors like below (ex. 240 per 12 hour period). Curious what I can do to avoid this? Or can I safely ignore them if I'm seeing no other issues?

Thank you!

%5|1667584607.329|REQTMOUT|rdkafka#producer-1| [thrd:sasl_ssl://<host redacted>]: sasl_ssl://<host redacted>:9096/bootstrap: Timed out SaslAuthenticateRequest in flight (after 129668ms, timeout #0)
%3|1667584607.330|FAIL|rdkafka#producer-1| [thrd:sasl_ssl://<host redacted>]: sasl_ssl://<host redacted>:9096/bootstrap: SASL authentication error: SaslAuthenticateRequest failed: Local: Timed out (after 129668ms in state AUTH_REQ)

[edenhill]

Broker requests timing out are typically indicative of problems with your Kafka service provider or network.

[jordaniversen]

Thanks. I see similar frequency of errors regarding the ApiVersionRequests, which include a hint that those timeouts may be due to an older broker version which doesn't seem to be my case. It's curious that I don't see similar frequent timeout issues for any other requests than these two types. Is that because other requests/writes have retries and these dont, or are the above two type of requests fundamentally different somehow? Thanks again

…

On Thu., Dec. 1, 2022, 4:22 a.m. Magnus Edenhill, ***@***.***> wrote: Broker requests timing out are typically indicative of problems with your Kafka service provider or network. — Reply to this email directly, view it on GitHub <#4086 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AHJO2GCLP34GXAMK3VVND7LWLBU4RANCNFSM6AAAAAASQKBK3Q> . You are receiving this because you authored the thread.Message ID: ***@***.***>

[edenhill]

ApiVersionRequest, SaslHandshakeRequest and SaslAuthenticateRequest are all part of the initial connection handshake.

[jordaniversen]

Thanks. Any idea what I can do for troubleshooting either side? It seems odd to me that I see so many of these errors but don't see errors when actually producing messages to our MSK cluster. If it is something like such a poor network connection, I assume I would consistently see errors with all requests. Of course please excuse my ignorance if this is a strange assumption, I certainly am no expert with this :)

Thanks again

[edenhill]

If there are frequent timeouts for these requests it has got something to do with the network or Kafka service provider.

[jordaniversen]

Thanks @edenhill. Ive created a support ticket for the AWS MSK cluster.

In the mean time, I've added some logs below for when we first initialize our Go kafka producer client.

%7|1669993111.817|SASL|rdkafka#producer-1| [thrd:app]: Selected provider SCRAM (builtin) for SASL mechanism SCRAM-SHA-512
%7|1669993111.817|OPENSSL|rdkafka#producer-1| [thrd:app]: Using statically linked OpenSSL version OpenSSL 1.1.1q  5 Jul 2022 (0x1010111f, librdkafka built with 0x1010111f)
%7|1669993111.820|CACERTS|rdkafka#producer-1| [thrd:app]: Setting default CA certificate location to /etc/pki/tls/certs/ca-bundle.crt, override with ssl.ca.location
%7|1669993111.835|BRKMAIN|rdkafka#producer-1| [thrd::0/internal]: :0/internal: Enter main broker thread
%7|1669993111.835|BROKER|rdkafka#producer-1| [thrd:app]: sasl_ssl://<host 1 redacted>:9096/bootstrap: Added new broker with NodeId -1
%7|1669993111.835|BROKER|rdkafka#producer-1| [thrd:app]: sasl_ssl://<host 2 redacted>:9096/bootstrap: Added new broker with NodeId -1
%7|1669993111.835|BROKER|rdkafka#producer-1| [thrd:app]: sasl_ssl://<host 3 redacted>:9096/bootstrap: Added new broker with NodeId -1
%7|1669993111.835|CONNECT|rdkafka#producer-1| [thrd:app]: sasl_ssl://<host 1 redacted>:9096/bootstrap: Selected for cluster connection: bootstrap servers added (broker has 0 connection attempt(s))
%7|1669993111.835|INIT|rdkafka#producer-1| [thrd:app]: librdkafka v1.9.2 (0x10902ff) rdkafka#producer-1 initialized (builtin.features gzip,snappy,ssl,sasl,regex,lz4,sasl_plain,sasl_scram,plugins,zstd,sasl_oauthbearer,http,oidc, STRIP STATIC_LINKING CC GXX PKGCONFIG INSTALL GNULD LDS LIBDL PLUGINS ZLIB SSL ZSTD CURL HDRHISTOGRAM SYSLOG SNAPPY SOCKEM SASL_SCRAM SASL_OAUTHBEARER OAUTHBEARER_OIDC CRC32C_HW, debug 0x24e)
%7|1669993111.835|BRKMAIN|rdkafka#producer-1| [thrd:sasl_ssl://<host 1 redacted>]: sasl_ssl://<host 1 redacted>:9096/bootstrap: Enter main broker thread
%7|1669993111.835|CONNECT|rdkafka#producer-1| [thrd:sasl_ssl://<host 1 redacted>]: sasl_ssl://<host 1 redacted>:9096/bootstrap: Received CONNECT op
%7|1669993111.835|STATE|rdkafka#producer-1| [thrd:sasl_ssl://<host 1 redacted>]: sasl_ssl://<host 1 redacted>:9096/bootstrap: Broker changed state INIT -> TRY_CONNECT
%7|1669993111.835|CONNECT|rdkafka#producer-1| [thrd:sasl_ssl://<host 1 redacted>]: sasl_ssl://<host 1 redacted>:9096/bootstrap: broker in state TRY_CONNECT connecting
%7|1669993111.835|STATE|rdkafka#producer-1| [thrd:sasl_ssl://<host 1 redacted>]: sasl_ssl://<host 1 redacted>:9096/bootstrap: Broker changed state TRY_CONNECT -> CONNECT
%7|1669993111.836|BRKMAIN|rdkafka#producer-1| [thrd:sasl_ssl://<host 3 redacted>]: sasl_ssl://<host 3 redacted>:9096/bootstrap: Enter main broker thread
%7|1669993111.836|BRKMAIN|rdkafka#producer-1| [thrd:sasl_ssl://<host 2 redacted>]: sasl_ssl://<host 2 redacted>:9096/bootstrap: Enter main broker thread
%7|1669993111.842|CONNECT|rdkafka#producer-1| [thrd:sasl_ssl://<host 1 redacted>]: sasl_ssl://<host 1 redacted>:9096/bootstrap: Connecting to ipv4#10.0.233.51:9096 (sasl_ssl) with socket 17
%7|1669993111.846|CONNECT|rdkafka#producer-1| [thrd:sasl_ssl://<host 1 redacted>]: sasl_ssl://<host 1 redacted>:9096/bootstrap: Connected to ipv4#10.0.233.51:9096
%7|1669993111.846|STATE|rdkafka#producer-1| [thrd:sasl_ssl://<host 1 redacted>]: sasl_ssl://<host 1 redacted>:9096/bootstrap: Broker changed state CONNECT -> SSL_HANDSHAKE
%7|1669993111.860|SSLVERIFY|rdkafka#producer-1| [thrd:sasl_ssl://<host 1 redacted>]: sasl_ssl://<host 1 redacted>:9096/bootstrap: Broker SSL certificate verified
%7|1669993111.860|CONNECTED|rdkafka#producer-1| [thrd:sasl_ssl://<host 1 redacted>]: sasl_ssl://<host 1 redacted>:9096/bootstrap: Connected (#1)
%7|1669993111.860|FEATURE|rdkafka#producer-1| [thrd:sasl_ssl://<host 1 redacted>]: sasl_ssl://<host 1 redacted>:9096/bootstrap: Updated enabled protocol features +ApiVersion to ApiVersion
%7|1669993111.860|STATE|rdkafka#producer-1| [thrd:sasl_ssl://<host 1 redacted>]: sasl_ssl://<host 1 redacted>:9096/bootstrap: Broker changed state SSL_HANDSHAKE -> APIVERSION_QUERY
%7|1669993203.053|CONNECT|rdkafka#producer-1| [thrd:main]: sasl_ssl://<host 3 redacted>:9096/bootstrap: Selected for cluster connection: no cluster connection (broker has 0 connection attempt(s))
%7|1669993203.053|CONNECT|rdkafka#producer-1| [thrd:sasl_ssl://<host 3 redacted>]: sasl_ssl://<host 3 redacted>:9096/bootstrap: Received CONNECT op
%7|1669993203.053|STATE|rdkafka#producer-1| [thrd:sasl_ssl://<host 3 redacted>]: sasl_ssl://<host 3 redacted>:9096/bootstrap: Broker changed state INIT -> TRY_CONNECT
%7|1669993203.053|CONNECT|rdkafka#producer-1| [thrd:sasl_ssl://<host 3 redacted>]: sasl_ssl://<host 3 redacted>:9096/bootstrap: broker in state TRY_CONNECT connecting
%7|1669993203.053|STATE|rdkafka#producer-1| [thrd:sasl_ssl://<host 3 redacted>]: sasl_ssl://<host 3 redacted>:9096/bootstrap: Broker changed state TRY_CONNECT -> CONNECT
%5|1669993203.053|REQTMOUT|rdkafka#producer-1| [thrd:sasl_ssl://<host 1 redacted>]: sasl_ssl://<host 1 redacted>:9096/bootstrap: Timed out ApiVersionRequest in flight (after 91191ms, timeout #0)
%7|1669993203.053|FAIL|rdkafka#producer-1| [thrd:sasl_ssl://<host 1 redacted>]: sasl_ssl://<host 1 redacted>:9096/bootstrap: ApiVersionRequest failed: Local: Timed out: probably due to broker version < 0.10 (see api.version.request configuration) (after 91192ms in state APIVERSION_QUERY) (_TRANSPORT)
%4|1669993203.053|FAIL|rdkafka#producer-1| [thrd:sasl_ssl://<host 1 redacted>]: sasl_ssl://<host 1 redacted>:9096/bootstrap: ApiVersionRequest failed: Local: Timed out: probably due to broker version < 0.10 (see api.version.request configuration) (after 91192ms in state APIVERSION_QUERY)
%7|1669993203.053|FEATURE|rdkafka#producer-1| [thrd:sasl_ssl://<host 1 redacted>]: sasl_ssl://<host 1 redacted>:9096/bootstrap: Updated enabled protocol features -ApiVersion to 
%7|1669993203.053|STATE|rdkafka#producer-1| [thrd:sasl_ssl://<host 1 redacted>]: sasl_ssl://<host 1 redacted>:9096/bootstrap: Broker changed state APIVERSION_QUERY -> DOWN
%4|1669993203.053|REQTMOUT|rdkafka#producer-1| [thrd:sasl_ssl://<host 1 redacted>]: sasl_ssl://<host 1 redacted>:9096/bootstrap: Timed out 1 in-flight, 0 retry-queued, 0 out-queue, 0 partially-sent requests
%7|1669993203.054|STATE|rdkafka#producer-1| [thrd:sasl_ssl://<host 1 redacted>]: sasl_ssl://<host 1 redacted>:9096/bootstrap: Broker changed state DOWN -> INIT
%7|1669993203.054|STATE|rdkafka#producer-1| [thrd:sasl_ssl://<host 1 redacted>]: sasl_ssl://<host 1 redacted>:9096/bootstrap: Broker changed state INIT -> TRY_CONNECT
%7|1669993203.054|CONNECT|rdkafka#producer-1| [thrd:sasl_ssl://<host 1 redacted>]: sasl_ssl://<host 1 redacted>:9096/bootstrap: broker in state TRY_CONNECT connecting
%7|1669993203.054|STATE|rdkafka#producer-1| [thrd:sasl_ssl://<host 1 redacted>]: sasl_ssl://<host 1 redacted>:9096/bootstrap: Broker changed state TRY_CONNECT -> CONNECT

In particular the following lines seem odd, as the duration between them is not "91191ms" like the log below says. The difference is 91.193, so perhaps it's just a logging error and it should read "91.193ms"? In my client/producer configuration I set "api.version.request.timeout.ms" to the max (300000) and I still see similar errors way under the timeout.

%7|1669993111.860|STATE|rdkafka#producer-1| [thrd:sasl_ssl://<host 1 redacted>]: sasl_ssl://<host 1 redacted>:9096/bootstrap: Broker changed state SSL_HANDSHAKE -> APIVERSION_QUERY
%5|1669993203.053|REQTMOUT|rdkafka#producer-1| [thrd:sasl_ssl://<host 1 redacted>]: sasl_ssl://<host 1 redacted>:9096/bootstrap: Timed out ApiVersionRequest in flight (after 91191ms, timeout #0)
%7|1669993203.053|FAIL|rdkafka#producer-1| [thrd:sasl_ssl://<host 1 redacted>]: sasl_ssl://<host 1 redacted>:9096/bootstrap: ApiVersionRequest failed: Local: Timed out: probably due to broker version < 0.10 (see api.version.request configuration) (after 91192ms in state APIVERSION_QUERY) (_TRANSPORT)

Another thing to note is that this is executed in an AWS Lambda. So I wonder if there is some "leftover" state between Lambda environments being reused. But the above log snippet is from the very beginning of a Lambda Log Group (which should mean Lambda invocation).

[edenhill]

The timing looks correct, it's 91 seconds, which is the logged 91191 milliseconds.

[mayankag24]

Hi
@edenhill
I have been facing a similar issue with MSK brokers using a Go client application with librdkafka.
However the only difference is I am using a NLB to route my SASL traffic via port 9000 to the 9096 broker endpoints. (Doing this to resolve custom DNS endpoint). The SASL SCRAM-SHA-512 protocol is enabled on the cluster and all other client apps are working fine with the NLB setup.

Only for the particular go client using librdkafka, I am facing below error:

REQTMOUT|>rdkafka#producer-3| [thrd:<custom_dns>:9000/bootstrap]: <custom_dns>:9000/bootstrap: Timed out ApiVersionRequest in flight (after 10010ms, timeout #0)
|FAIL|>rdkafka#producer-3| [thrd:<custom_dns>:9000/bootstrap]: <custom_dns>:9000/bootstrap: ApiVersionRequest failed: Local: Timed out: probably due to broker version < 0.10 (see api.version.request configuration) (after 10010ms in state APIVERSION_QUERY, 3 identical error(s) suppressed)

Below is the config yaml I am using -
kafka-producer-conf:
queue.buffering.max.messages: 300000
queue.buffering.max.ms: 1
message.send.max.retries: 30
retry.backoff.ms: 2000
batch.num.messages: 1000
compression.codec: snappy
go.produce.channel.size: 100000
go.delivery.reports: true
go.events.channel.size: 100000
log.connection.close: false
api.version.request: false
acks: -1
security.protocol: SASL_SSL
sasl.mechanism: SCRAM-SHA-512
sasl.username: ""
sasl.password: ""
message.timeout.ms: 2
max.in.flight.requests.per.connection: 1
statistics.interval.ms: 5000
default.topic.config:
partitioner: murmur2_random
acks: -1
dev:
bootstrap.servers: <custom_dns>:9000

I have tried changing api.version.request.timeout values and passing api.version.request as true/false, the error still persists.
Also note, this error is resolved as soon as I pass direct MSK broker endpoints to the bootstrap server instead of custom DNS enpoints.

bootstrap.servers: b-1..amazonaws.com:9096,b-4..amazonaws.com:9096,b-5..ap-south-1.amazonaws.com:9096

Could you please provide any insights on this?