Confluent Kafka ProduceAsync Method takes 1 min when connecting to Eventhub to get a response

[ksdvishnukumarcse]

Hi @edenhill and Team,

Am using the Confluent Kafka Package with version 1.8.2 to connect to Eventhub.

I have a producer with the below configuration

BootstrapServers = <EH-NAMESPACE>.servicebus.windows.net:9093,
MessageMaxBytes = 20971520,
MessageCopyMaxBytes = 20971520,
LogConnectionClose = false,
BrokerAddressFamily = BrokerAddressFamily.V4,
ConnectionsMaxIdleMs = 180000,


//https://github.com/Azure/azure-event-hubs-for-kafka/issues/139
SocketKeepaliveEnable = true,
MetadataMaxAgeMs = 180000,

//https://learn.microsoft.com/en-us/azure/event-hubs/apache-kafka-configurations
RequestTimeoutMs = 60000,

SaslUsername = "$ConnectionString",
SaslPassword = <EH-SHARED_ACCESS-POLICY-PRIMARY-CONNETCION-STRING>,
SaslMechanism = SaslMechanism.Plain,
SecurityProtocol = SecurityProtocol.SaslSsl,

Acks = Acks.Leader,
BatchSize = 200000,
LingerMs = 0, (To achieve low latency)
CompressionType = CompressionType.None,
SocketNagleDisable = true,
Debug ="msg,protocol"

The below is the application logs

Log Message1

11/21/2022, 10:42:57.1148930 PM
Transformation : Processing the message with Topic=<TOPIC-NAME> Offset=514711 from Partition=[0], CorrelationId=9c46c420-5394-49b9-b23a-7fa4ec9f9fc2

Log Message2

11/21/2022, 10:42:57.1149930 PM
Message publish starting to Timestamp=21-11-2022T10:42:57.1149930Z, CorrelationId=9c46c420-5394-49b9-b23a-7fa4ec9f9fc2

Log Message3

11/21/2022, 10:43:57.9031493 PM
Message published to Topic <TOPIC-NAME> Partition [0] Offset 61032 Timestamp=21-11-2022T10:43:57.9031493Z, CorrelationId=9c46c420-5394-49b9-b23a-7fa4ec9f9fc2

Log Message2 and Log Message3 message are getting logged immediately before and after calling the await ProduceAsync Method. And i could see that its having 1 min delay. (Not really sure why :( )

And i have verified the RTT by enabling the protocol between the above specified time. Its not exceeding 9 ms.

I understand that between Log Message2 and Log Message3 the below messages are getting generated internally from Kafka Library

I see that from the Kafka logs, for some reasons messages are getting batched and taking more time (1 Minute) to get the response back from ProduceAsync method. But this is not happening often.

Below are logs for reference

Timestamp [UTC]					Message

11/21/2022, 10:43:56.624 AM	- Producer Log Handler : DEBUG|21-11-2022T10:43:56.6249081Z|PRODUCE|rdkafka#producer-1|[[thrd:sasl_ssl://<EH_NAMESPACE>.servicebus.windows.net:9093/]: sasl_ssl://<EH-NAMESPACE>.servicebus.windows.net:9093/9: <TOPIC-NAME> [7]: Produce MessageSet with 12 message(s) (15311 bytes, ApiVersion 7, MsgVersion 2, MsgId 0, BaseSeq -1, PID{Invalid}, uncompressed)]

11/21/2022, 10:43:56.704 AM	- Producer Log Handler : DEBUG|21-11-2022T10:43:56.7046023Z|PRODUCE|rdkafka#producer-1|[[thrd:sasl_ssl://<EH_NAMESPACE>.servicebus.windows.net:9093/]: sasl_ssl://<EH-NAMESPACE>.servicebus.windows.net:9093/1: <TOPIC-NAME> [4]: Produce MessageSet with 1 message(s) (1338 bytes, ApiVersion 7, MsgVersion 2, MsgId 0, BaseSeq -1, PID{Invalid}, uncompressed)]

11/21/2022, 10:43:57.030 AM	- Producer Log Handler : DEBUG|21-11-2022T10:43:57.0299721Z|PRODUCE|rdkafka#producer-1|[[thrd:sasl_ssl://<EH_NAMESPACE>.servicebus.windows.net:9093/]: sasl_ssl://<EH-NAMESPACE>.servicebus.windows.net:9093/7: <TOPIC-NAME> [3]: Produce MessageSet with 3 message(s) (3849 bytes, ApiVersion 7, MsgVersion 2, MsgId 0, BaseSeq -1, PID{Invalid}, uncompressed)]

11/21/2022, 10:43:57.030 AM	- Producer Log Handler : DEBUG|21-11-2022T10:43:57.0308009Z|PRODUCE|rdkafka#producer-1|[[thrd:sasl_ssl://<EH_NAMESPACE>.servicebus.windows.net:9093/]: sasl_ssl://<EH-NAMESPACE>.servicebus.windows.net:9093/7: <TOPIC-NAME> [3]: Produce MessageSet with 8 message(s) (10233 bytes, ApiVersion 7, MsgVersion 2, MsgId 0, BaseSeq -1, PID{Invalid}, uncompressed)]

11/21/2022, 10:43:57.031 AM	- Producer Log Handler : DEBUG|21-11-2022T10:43:57.0310823Z|PRODUCE|rdkafka#producer-1|[[thrd:sasl_ssl://<EH_NAMESPACE>.servicebus.windows.net:9093/]: sasl_ssl://<EH-NAMESPACE>.servicebus.windows.net:9093/7: <TOPIC-NAME> [3]: Produce MessageSet with 6 message(s) (7672 bytes, ApiVersion 7, MsgVersion 2, MsgId 0, BaseSeq -1, PID{Invalid}, uncompressed)]

11/21/2022, 10:43:57.032 AM	- Producer Log Handler : DEBUG|21-11-2022T10:43:57.0323336Z|PRODUCE|rdkafka#producer-1|[[thrd:sasl_ssl://<EH_NAMESPACE>.servicebus.windows.net:9093/]: sasl_ssl://<EH-NAMESPACE>.servicebus.windows.net:9093/7: <TOPIC-NAME> [3]: Produce MessageSet with 9 message(s) (11501 bytes, ApiVersion 7, MsgVersion 2, MsgId 0, BaseSeq -1, PID{Invalid}, uncompressed)]

11/21/2022, 10:43:57.112 AM	- Producer Log Handler : DEBUG|21-11-2022T10:43:57.1127658Z|PRODUCE|rdkafka#producer-1|[[thrd:sasl_ssl://<EH_NAMESPACE>.servicebus.windows.net:9093/]: sasl_ssl://<EH-NAMESPACE>.servicebus.windows.net:9093/3: <TOPIC-NAME> [8]: Produce MessageSet with 12 message(s) (15308 bytes, ApiVersion 7, MsgVersion 2, MsgId 0, BaseSeq -1, PID{Invalid}, uncompressed)]

11/21/2022, 10:43:57.290 AM	- Producer Log Handler : DEBUG|21-11-2022T10:43:57.2904593Z|PRODUCE|rdkafka#producer-1|[[thrd:sasl_ssl://<EH_NAMESPACE>.servicebus.windows.net:9093/]: sasl_ssl://<EH-NAMESPACE>.servicebus.windows.net:9093/6: <TOPIC-NAME> [1]: Produce MessageSet with 27 message(s) (34411 bytes, ApiVersion 7, MsgVersion 2, MsgId 0, BaseSeq -1, PID{Invalid}, uncompressed)]

11/21/2022, 10:43:57.290 AM	- Producer Log Handler : DEBUG|21-11-2022T10:43:57.2908342Z|PRODUCE|rdkafka#producer-1|[[thrd:sasl_ssl://<EH_NAMESPACE>.servicebus.windows.net:9093/]: sasl_ssl://<EH-NAMESPACE>.servicebus.windows.net:9093/4: <TOPIC-NAME> [9]: Produce MessageSet with 21 message(s) (26733 bytes, ApiVersion 7, MsgVersion 2, MsgId 0, BaseSeq -1, PID{Invalid}, uncompressed)]

11/21/2022, 10:43:57.512 AM	- Producer Log Handler : DEBUG|21-11-2022T10:43:57.5119459Z|PRODUCE|rdkafka#producer-1|[[thrd:sasl_ssl://<EH_NAMESPACE>.servicebus.windows.net:9093/]: sasl_ssl://<EH-NAMESPACE>.servicebus.windows.net:9093/6: <TOPIC-NAME> [1]: Produce MessageSet with 1 message(s) (1335 bytes, ApiVersion 7, MsgVersion 2, MsgId 0, BaseSeq -1, PID{Invalid}, uncompressed)]

11/21/2022, 10:43:57.894 AM	- Producer Log Handler : DEBUG|21-11-2022T10:43:57.8945333Z|PRODUCE|rdkafka#producer-1|[[thrd:sasl_ssl://<EH_NAMESPACE>.servicebus.windows.net:9093/]: sasl_ssl://<EH-NAMESPACE>.servicebus.windows.net:9093/5: <TOPIC-NAME> [0]: Produce MessageSet with 19 message(s) (24197 bytes, ApiVersion 7, MsgVersion 2, MsgId 0, BaseSeq -1, PID{Invalid}, uncompressed)]

11/21/2022, 10:43:57.990 AM	- Producer Log Handler : DEBUG|21-11-2022T10:43:57.9908668Z|PRODUCE|rdkafka#producer-1|[[thrd:sasl_ssl://<EH_NAMESPACE>.servicebus.windows.net:9093/]: sasl_ssl://<EH-NAMESPACE>.servicebus.windows.net:9093/9: <TOPIC-NAME> [7]: Produce MessageSet with 1 message(s) (1328 bytes, ApiVersion 7, MsgVersion 2, MsgId 0, BaseSeq -1, PID{Invalid}, uncompressed)]

11/21/2022, 10:44:00.118 AM	- Producer Log Handler : DEBUG|21-11-2022T10:44:00.1184970Z|PRODUCE|rdkafka#producer-1|[[thrd:sasl_ssl://<EH_NAMESPACE>.servicebus.windows.net:9093/]: sasl_ssl://<EH-NAMESPACE>.servicebus.windows.net:9093/1: <TOPIC-NAME> [4]: Produce MessageSet with 12 message(s) (15345 bytes, ApiVersion 7, MsgVersion 2, MsgId 0, BaseSeq -1, PID{Invalid}, uncompressed)]

11/21/2022, 10:44:00.378 AM	- Producer Log Handler : DEBUG|21-11-2022T10:44:00.3786142Z|PRODUCE|rdkafka#producer-1|[[thrd:sasl_ssl://<EH_NAMESPACE>.servicebus.windows.net:9093/]: sasl_ssl://<EH-NAMESPACE>.servicebus.windows.net:9093/2: <TOPIC-NAME> [6]: Produce MessageSet with 2 message(s) (2608 bytes, ApiVersion 7, MsgVersion 2, MsgId 0, BaseSeq -1, PID{Invalid}, uncompressed)]

11/21/2022, 10:44:00.379 AM	- Producer Log Handler : DEBUG|21-11-2022T10:44:00.3796250Z|PRODUCE|rdkafka#producer-1|[[thrd:sasl_ssl://<EH_NAMESPACE>.servicebus.windows.net:9093/]: sasl_ssl://<EH-NAMESPACE>.servicebus.windows.net:9093/2: <TOPIC-NAME> [6]: Produce MessageSet with 11 message(s) (14055 bytes, ApiVersion 7, MsgVersion 2, MsgId 0, BaseSeq -1, PID{Invalid}, uncompressed)]

11/21/2022, 10:44:00.380 AM	- Producer Log Handler : DEBUG|21-11-2022T10:44:00.3799805Z|PRODUCE|rdkafka#producer-1|[[thrd:sasl_ssl://<EH_NAMESPACE>.servicebus.windows.net:9093/]: sasl_ssl://<EH-NAMESPACE>.servicebus.windows.net:9093/2: <TOPIC-NAME> [6]: Produce MessageSet with 8 message(s) (10210 bytes, ApiVersion 7, MsgVersion 2, MsgId 0, BaseSeq -1, PID{Invalid}, uncompressed)]

11/21/2022, 10:44:00.448 AM	- Producer Log Handler : DEBUG|21-11-2022T10:44:00.4482552Z|PRODUCE|rdkafka#producer-1|[[thrd:sasl_ssl://<EH_NAMESPACE>.servicebus.windows.net:9093/]: sasl_ssl://<EH-NAMESPACE>.servicebus.windows.net:9093/7: <TOPIC-NAME> [3]: Produce MessageSet with 1 message(s) (1337 bytes, ApiVersion 7, MsgVersion 2, MsgId 0, BaseSeq -1, PID{Invalid}, uncompressed)]

Any help much appreciated.