Timing of ConnectAsync

[FipLub]

Hi everyone

I realized the client takes ~200ms to connect to my remote broker, which seems very slow to me.
If I disconnect the client, instantiate, and connect a new one, connecting takes only 14ms instead of 200ms.
I can reproduce this behavior and am wondering if this is related to the client or any other network-related issue? Has anyone observed similar behavior?

Approach:
To evaluate timing, I create a new StreamWriter for each client and write to a file on each LogMessagePublished

StreamWriter _stream = new StreamWriter($"{ClientId}.log", false);
MqttNetEventLogger _logger = new MqttNetEventLogger(ClientId);
_logger.LogMessagePublished += Logger_LogMessagePublished;

MqttFactory _factory = new MqttFactory(_logger);
MqttClientOptions _clientOptions = new MqttClientOptionsBuilder()
    .WithTcpServer(ServerAddress, ServerPort)
    .WithTimeout(Timeout)
    .WithProtocolVersion(MqttProtocolVersion.V500)
    .WithCleanSession(true) // CleanSession: With no existing subscriptions at start-up
    .Build();
IMqttClient _client = _factory.CreateMqttClient();
_client.ConnectAsync(_clientOptions, CancellationToken.None).Wait(5000);

[...]

private void Logger_LogMessagePublished(object sender, MqttNetLogMessagePublishedEventArgs e)
{
      _stream.WriteLine(String.Format("{0}\t{1}\t{2}", e.LogMessage.Timestamp.ToString("HH:mm:ss.ffffff"), ClientId, e.LogMessage.Message));
}

Output Logfile

07:47:31.058276 JEN-TS007.0a9499dc-4639-4f33-b6dd-3966d0d28b6e Trying to connect with server '10.10.101.43:1883'
07:47:31.167276 JEN-TS007.0a9499dc-4639-4f33-b6dd-3966d0d28b6e Connection with server established
07:47:31.200276 JEN-TS007.0a9499dc-4639-4f33-b6dd-3966d0d28b6e TX (61 bytes) >>> Connect: [ClientId=JEN-TS007.0a9499dc-4639-4f33-b6dd-3966d0d28b6e] [Username=] [Password=] [KeepAlivePeriod=15] [CleanSession=True]
07:47:31.255276 JEN-TS007.0a9499dc-4639-4f33-b6dd-3966d0d28b6e RX (11 bytes) <<< ConnAck: [ReturnCode=ConnectionAccepted] [ReasonCode=Success] [IsSessionPresent=False]
07:47:31.257276 JEN-TS007.0a9499dc-4639-4f33-b6dd-3966d0d28b6e Authenticated MQTT connection with server established.
07:47:31.257276 JEN-TS007.0a9499dc-4639-4f33-b6dd-3966d0d28b6e Connected
07:47:31.276276 JEN-TS007.0a9499dc-4639-4f33-b6dd-3966d0d28b6e Start receiving packets
07:47:31.282276 JEN-TS007.0a9499dc-4639-4f33-b6dd-3966d0d28b6e Start sending keep alive packets
07:47:31.284276 JEN-TS007.0a9499dc-4639-4f33-b6dd-3966d0d28b6e TX (53 bytes) >>> Subscribe: [PacketIdentifier=1] [TopicFilters=2940524/+/+@Atleastonce]
07:47:31.302276 JEN-TS007.0a9499dc-4639-4f33-b6dd-3966d0d28b6e RX (6 bytes) <<< SubAck: [PacketIdentifier=1] [ReasonCode=GrantedQoS1]
07:47:31.314276 JEN-TS007.0a9499dc-4639-4f33-b6dd-3966d0d28b6e RX (811 bytes) <<< Publish: [Topic=2940524/2940524-000001/00b9423f-12a8-47b3-8e50-e3784ba40740] [PayloadLength=656] [QoSLevel=AtLeastOnce] [Dup=False] [Retain=True] [PacketIdentifier=1]
07:47:31.318276 JEN-TS007.0a9499dc-4639-4f33-b6dd-3966d0d28b6e RX (811 bytes) <<< Publish: [Topic=2940524/2940524-000002/d78febb9-354b-4c12-8072-7542d4895f71] [PayloadLength=656] [QoSLevel=AtLeastOnce] [Dup=False] [Retain=True] [PacketIdentifier=2]
[...]
07:47:39.571276 JEN-TS007.0a9499dc-4639-4f33-b6dd-3966d0d28b6e TX (6 bytes) >>> PubAck: [PacketIdentifier=19996] [ReasonCode=Success]
07:47:39.572276 JEN-TS007.0a9499dc-4639-4f33-b6dd-3966d0d28b6e TX (6 bytes) >>> PubAck: [PacketIdentifier=19997] [ReasonCode=Success]
07:47:39.572276 JEN-TS007.0a9499dc-4639-4f33-b6dd-3966d0d28b6e TX (6 bytes) >>> PubAck: [PacketIdentifier=19998] [ReasonCode=Success]
07:47:45.367276 JEN-TS007.0a9499dc-4639-4f33-b6dd-3966d0d28b6e TX (52 bytes) >>> Unsubscribe: [PacketIdentifier=2] [TopicFilters=2940524/+/+]
07:47:45.377276 JEN-TS007.0a9499dc-4639-4f33-b6dd-3966d0d28b6e RX (6 bytes) <<< UnsubAck: [PacketIdentifier=2] [ReasonCodes=Success] [ReasonString=]
07:47:45.390276 JEN-TS007.0a9499dc-4639-4f33-b6dd-3966d0d28b6e TX (4 bytes) >>> Disconnect: [ReasonCode=NormalDisconnection] [ReasonString=] [ServerReference=] [SessionExpiryInterval=0]
07:47:45.392276 JEN-TS007.0a9499dc-4639-4f33-b6dd-3966d0d28b6e Stopped receiving packets
07:47:45.397276 JEN-TS007.0a9499dc-4639-4f33-b6dd-3966d0d28b6e Stopped sending keep alive packets
07:47:45.398276 JEN-TS007.0a9499dc-4639-4f33-b6dd-3966d0d28b6e Disconnecting [Timeout=00:00:05]
07:47:45.404276 JEN-TS007.0a9499dc-4639-4f33-b6dd-3966d0d28b6e Disconnected from adapter.
07:47:45.411276 JEN-TS007.0a9499dc-4639-4f33-b6dd-3966d0d28b6e Disconnected.

Details:

• MQTTnet: v4.3.3.952
• Target Framework: .Net Framework 4.7
• Mosquitto: v2.0.14 (located in my local network, and accessible via IP address)

Many thanks and looking forward to your hints/ideas
Filip

[FipLub]

I digged a bit deeper into the log and found the following:
After ClientA subscribes to a topic (log message "TX >>> Subscribe" + acknowledge "RX <<< SubAck"), messages start coming in (RX <<< Publish). This takes roughly 20ms from issuing the subscription to receiving the first message. To acknowledge the first message's reception, it takes 200ms to reply with "TX >>> PubAck". Where does this rather long delay come from?

After ClientA received all available messages on this topic, I disconnected it and created a second instance of MqttNet's client (ClientB) and subscribed it to another topic. The log entry here looks quite similar despite the small difference that the first message is acknowledged after 10ms instead of 200ms.

**Important: ** This all happened within one process. This means I can instantiate as many clients after each other as I want to, all of them (except the first one) take 10ms instead of 200ms to acknowledge their first received message.
If I restart the process, this behavior keeps repeating.

Here the raw logs:
Client A:

08:27:57.912080 ClientA Trying to connect with server '10.10.101.43:1883'
08:27:57.978080 ClientA Connection with server established
08:27:57.996080 ClientA TX (77 bytes) >>> Connect: [ClientId=ClientA] [Username=] [Password=] [KeepAlivePeriod=15] [CleanSession=True]
08:27:58.028080 ClientA RX (11 bytes) <<< ConnAck: [ReturnCode=ConnectionAccepted] [ReasonCode=Success] [IsSessionPresent=False]
08:27:58.029080 ClientA Authenticated MQTT connection with server established.
08:27:58.030080 ClientA Connected
08:27:58.035080 ClientA Start sending keep alive packets
08:27:58.038080 ClientA Start receiving packets
08:27:58.048080 ClientA TX (121 bytes) >>> Subscribe: [PacketIdentifier=1] [TopicFilters=2940524/#@Atleastonce]
08:27:58.061080 ClientA RX (6 bytes) <<< SubAck: [PacketIdentifier=1] [ReasonCode=GrantedQoS1]
08:27:58.068080 ClientA RX (811 bytes) <<< Publish: [Topic=2940524/00b9423f-12a8-47b3-8e50-e3784ba40740] [PayloadLength=656] [QoSLevel=AtLeastOnce] [Dup=False] [Retain=True] [PacketIdentifier=1]
08:27:58.070080 ClientA RX (811 bytes) <<< Publish: [Topic=2940524/d78febb9-354b-4c12-8072-7542d4895f71] [PayloadLength=656] [QoSLevel=AtLeastOnce] [Dup=False] [Retain=True] [PacketIdentifier=2]
08:27:58.256080 ClientA TX (6 bytes) >>> PubAck: [PacketIdentifier=1] [ReasonCode=Success]
08:27:58.256080 ClientA TX (6 bytes) >>> PubAck: [PacketIdentifier=2] [ReasonCode=Success]
08:28:00.071080 ClientA TX (120 bytes) >>> Unsubscribe: [PacketIdentifier=2] [TopicFilters=2940524/#]
08:28:00.083080 ClientA RX (6 bytes) <<< UnsubAck: [PacketIdentifier=2] [ReasonCodes=Success] [ReasonString=]
08:28:00.091080 ClientA TX (4 bytes) >>> Disconnect: [ReasonCode=NormalDisconnection] [ReasonString=] [ServerReference=] [SessionExpiryInterval=0]
08:28:00.095080 ClientA Stopped sending keep alive packets
08:28:00.099080 ClientA Disconnecting [Timeout=00:00:05]
08:28:00.099080 ClientA Stopped receiving packets
08:28:00.100080 ClientA Disconnected from adapter.
08:28:00.102080 ClientA Disconnected.

Client B:

08:28:10.105080 ClientB Trying to connect with server '10.10.101.43:1883'
08:28:10.112080 ClientB Connection with server established
08:28:10.112080 ClientB TX (77 bytes) >>> Connect: [ClientId=ClientB] [Username=] [Password=] [KeepAlivePeriod=15] [CleanSession=True]
08:28:10.120080 ClientB RX (11 bytes) <<< ConnAck: [ReturnCode=ConnectionAccepted] [ReasonCode=Success] [IsSessionPresent=False]
08:28:10.120080 ClientB Authenticated MQTT connection with server established.
08:28:10.120080 ClientB Connected
08:28:10.120080 ClientB Start sending keep alive packets
08:28:10.120080 ClientB Start receiving packets
08:28:10.120080 ClientB TX (121 bytes) >>> Subscribe: [PacketIdentifier=1] [TopicFilters=2940525/#@Atleastonce]
08:28:10.127080 ClientB RX (6 bytes) <<< SubAck: [PacketIdentifier=1] [ReasonCode=GrantedQoS1]
08:28:10.127080 ClientB RX (811 bytes) <<< Publish: [Topic=2940525/ae87c06a-6f54-4f1a-8c01-b08fab427e77] [PayloadLength=656] [QoSLevel=AtLeastOnce] [Dup=False] [Retain=True] [PacketIdentifier=1]
08:28:10.128080 ClientB RX (811 bytes) <<< Publish: [Topic=2940525/0c1dda27-abc0-48df-9220-641ee7c715a6] [PayloadLength=656] [QoSLevel=AtLeastOnce] [Dup=False] [Retain=True] [PacketIdentifier=2]
08:28:10.128080 ClientB TX (6 bytes) >>> PubAck: [PacketIdentifier=1] [ReasonCode=Success]
08:28:10.128080 ClientB TX (6 bytes) >>> PubAck: [PacketIdentifier=2] [ReasonCode=Success]
08:28:12.127080 ClientB TX (120 bytes) >>> Unsubscribe: [PacketIdentifier=2] [TopicFilters=2940525/#]
08:28:12.135080 ClientB RX (6 bytes) <<< UnsubAck: [PacketIdentifier=2] [ReasonCodes=Success] [ReasonString=]
08:28:12.135080 ClientB TX (4 bytes) >>> Disconnect: [ReasonCode=NormalDisconnection] [ReasonString=] [ServerReference=] [SessionExpiryInterval=0]
08:28:12.135080 ClientB Stopped sending keep alive packets
08:28:12.136080 ClientB Disconnecting [Timeout=00:00:05]
08:28:12.136080 ClientB Disconnected from adapter.
08:28:12.136080 ClientB Stopped receiving packets
08:28:12.137080 ClientB Disconnected.

Any idea where this delay comes from and how to mitigate it?

Many thanks
Filip