Connection status callback isn't executed on disconnect (CA-29)

[nrmka]

esp-azure: 5f421bbd7ef8e6f5502204e9cd7a5f494070b39a

I'm using ESP32 and iothub_client_sample_mqtt example. Set message count to 0 and time interval to 10000 ms.

I wait for connection and delivery two messages. Connection status callback is executed and I can see corresponding print: Connection Status result:IOTHUB_CLIENT_CONNECTION_AUTHENTICATED, Connection Status reason: IOTHUB_CLIENT_CONNECTION_OK

Then turn off data transfer on a smartphone which is used as a wi-fi hotspot. Wait for two minutes till the undelivered message is expired. Get log message: -> XX:XX:XX DISCONNECT

However, connection status callback isn't executed. I wait one more minute and turn data transfer on. Connection is re-established and callback is executed: Connection Status result:IOTHUB_CLIENT_CONNECTION_AUTHENTICATED, Connection Status reason: IOTHUB_CLIENT_CONNECTION_OK

The log:

Initializing SNTP
ESP platform sntp inited!
Time is not set yet. Connecting to WiFi and getting time over NTP. timeinfo.tm_year:70
Waiting for system time to be set... tm_year:0[times:1]
I (7310) platform: The current date/time is: Tue Jul  9 08:37:19 2019
IoTHubClient_LL_SetMessageCallback...successful.
IoTHubClient_LL_SendEventAsync accepted message [0] for transmission to IoT Hub.
-> 08:37:22 CONNECT | VER: 4 | KEEPALIVE: 240 | FLAGS: 192 | USERNAME:XXX | PWD: XXXX | CLEAN: 0
<- 08:37:23 CONNACK | SESSION_PRESENT: true | RETURN_CODE: 0x0


Connection Status result:IOTHUB_CLIENT_CONNECTION_AUTHENTICATED, Connection Status reason: IOTHUB_CLIENT_CONNECTION_OK

-> 08:37:23 SUBSCRIBE | PACKET_ID: 2 | TOPIC_NAME: devices/XXX/messages/devicebound/# | QOS: 1
-> 08:37:23 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_LEAST_ONCE | TOPIC_NAME: devices/XXX/messages/events/temperatureAlert=false | PACKET_ID: 3 | PAYLOAD_LEN: 83
<- 08:37:23 SUBACK | PACKET_ID: 2 | RETURN_CODE: 1
<- 08:37:23 PUBACK | PACKET_ID: 3
Confirmation[0] received for message tracking id = 0 with result = IOTHUB_CLIENT_CONFIRMATION_OK
IoTHubClient_LL_SendEventAsync accepted message [1] for transmission to IoT Hub.
-> 08:37:30 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_LEAST_ONCE | TOPIC_NAME: devices/XXX/messages/events/temperatureAlert=false | PACKET_ID: 4 | PAYLOAD_LEN: 83
<- 08:37:30 PUBACK | PACKET_ID: 4
Confirmation[1] received for message tracking id = 1 with result = IOTHUB_CLIENT_CONFIRMATION_OK
IoTHubClient_LL_SendEventAsync accepted message [2] for transmission to IoT Hub.
-> 08:37:41 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_LEAST_ONCE | TOPIC_NAME: devices/XXX/messages/events/temperatureAlert=false | PACKET_ID: 5 | PAYLOAD_LEN: 83
<- 08:37:41 PUBACK | PACKET_ID: 5
Confirmation[2] received for message tracking id = 2 with result = IOTHUB_CLIENT_CONFIRMATION_OK
IoTHubClient_LL_SendEventAsync accepted message [3] for transmission to IoT Hub.
-> 08:37:52 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_LEAST_ONCE | TOPIC_NAME: devices/XXX/messages/events/temperatureAlert=true | PACKET_ID: 6 | PAYLOAD_LEN: 83
-> 08:38:53 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_LEAST_ONCE | TOPIC_NAME: devices/XXX/messages/events/temperatureAlert=true | PACKET_ID: 6 | PAYLOAD_LEN: 83
-> 08:39:54 DISCONNECT
E (162320) esp-tls: couldn't get hostname for :XXX:
Error: Time:Tue Jul  9 08:40:25 2019 File:/esp-azure/azure-iot-sdk-c/iothub_client/src/iothubtransport_mqtt_common.c Func:InitializeConnection Line:2355 mqtt_client timed out waiting for CONNACK
Error: Time:Tue Jul  9 08:40:25 2019 File:/esp-azure/port/src/tlsio_esp_tls.c Func:tlsio_esp_tls_destroy Line:152 tlsio_esp_tls_destroy called while not in TLSIO_STATE_CLOSED.
E (193180) esp-tls: couldn't get hostname for :XXX:
Error: Time:Tue Jul  9 08:40:56 2019 File:/esp-azure/azure-iot-sdk-c/iothub_client/src/iothubtransport_mqtt_common.c Func:InitializeConnection Line:2355 mqtt_client timed out waiting for CONNACK
Error: Time:Tue Jul  9 08:40:56 2019 File:/esp-azure/port/src/tlsio_esp_tls.c Func:tlsio_esp_tls_destroy Line:152 tlsio_esp_tls_destroy called while not in TLSIO_STATE_CLOSED.
-> 08:40:58 CONNECT | VER: 4 | KEEPALIVE: 240 | FLAGS: 192 | USERNAME: XXX | PWD: XXXX | CLEAN: 0
<- 08:40:59 CONNACK | SESSION_PRESENT: true | RETURN_CODE: 0x0


Connection Status result:IOTHUB_CLIENT_CONNECTION_AUTHENTICATED, Connection Status reason: IOTHUB_CLIENT_CONNECTION_OK```

[nrmka]

I think this can fix the issue:

$ git diff port/src/tlsio_esp_tls.c
diff --git a/components/azure_iot/port/src/tlsio_esp_tls.c b/components/azure_iot/port/src/tlsio_esp_tls.c
index 2928053..c368b49 100644
--- a/components/azure_iot/port/src/tlsio_esp_tls.c
+++ b/components/azure_iot/port/src/tlsio_esp_tls.c
@@ -484,6 +484,7 @@ static void tlsio_esp_tls_dowork(CONCRETE_IO_HANDLE tls_io)
                 tls_io_instance->on_open_complete(tls_io_instance->on_open_complete_context, IO_OPEN_OK);
             } else if (result == -1) {
                 tls_io_instance->tlsio_state = TLSIO_STATE_ERROR;
+                tls_io_instance->on_open_complete(tls_io_instance->on_open_complete_context, IO_OPEN_ERROR);
             }
             }
             break;

[shahpiyushv]

@nrmka , thanks for reporting the bug and also providing a probable fix. We will check and get this merged.

[sagar448]

Hi this is not an issue, but can someone help? I am new to this, how do I even use this repo? Do I build it with cmake? Any help would be greatly appreciated!

[JayEnaR]

I too have the same error:

• Func:InitializeConnection Line:2355 mqtt_client timed out waiting for CONNACK
• Func:tlsio_esp_tls_destroy Line:152 tlsio_esp_tls_destroy called while not in TLSIO_STATE_CLOSED

[shahpiyushv]

@JayEnaR are you using the latest esp-azure pushed yesterday? Is your scenario same as mentioned in the original issue wherein the disconnect event isn't received, or is this issue seen at the first connection itself?

[JayEnaR]

@shahpiyushv I just cloned the latest now and I still DO NOT get the "Connection Status Callback" on first connection. Only after numerous message attempts to send (with message "accept message for transmission to IoT Hub"), I would get the "CONNECT" message and "Connection Status result:IOTHUB_CLIENT_CONNECTION_AUTHENTICATED, Connection Status reason: IOTHUB_CLIENT_CONNECTION_OK".

The connection would only occur after about 5 minutes, then suddenly all message send through.

The following errors occur on start and message send attempt:

• esp-azure/azure-iot-sdk-c/iothub_client/src/iothubtransport_mqtt_common.c Func:InitializeConnection Line:2424 mqtt_client timed out waiting for CONNACK
• esp-azure/azure-iot-sdk-c/umqtt/src/mqtt_client.c Func:onOpenComplete Line:454 Error: failure opening connection to endpoint
• esp-azure/port/src/tlsio_esp_tls.c Func:tlsio_esp_tls_destroy Line:153 tlsio_esp_tls_destroy called while not in TLSIO_STATE_CLOSED

[rtheil-growlink]

I'm having this issue occur as well, however it only happened here this morning when I had issues with internet connectivity. Connection was very flaky this morning (25% packet loss) and suddenly I received a couple errors where the confirmation callback method was triggered from a call to IoTHubDeviceClient_LL_SendEventAsync. Immediately after that I'd get these errors:

Error: Time:Mon Jan 10 15:36:44 2022 File:../lib/azure-iot-sdk-c/iothub_client/src/iothubtransport_mqtt_common.c Func:InitializeConnection Line:2428 mqtt_client timed out waiting for CONNACK Error: Time:Mon Jan 10 15:34:07 2022 File:../port/src/tlsio_esp_tls.c Func:tlsio_esp_tls_destroy Line:153 tlsio_esp_tls_destroy called while not in TLSIO_STATE_CLOSED.

Even after connectivity improved, without a reset of the controller I could not get connectivity established again. These errors resulted in a host of other issues, such as:

Error: Time:Mon Jan 10 15:36:00 2022 File:../lib/azure-iot-sdk-c/c-utility/pal/tlsio_options.c Func:tlsio_options_clone_option Line:117 unable to mallocAndStrcpy_s option value Error: Time:Mon Jan 10 15:36:00 2022 File:../lib/azure-iot-sdk-c/c-utility/pal/tlsio_options.c Func:local_clone_option Line:229 Unexpected local_clone_option failure Error: Time:Mon Jan 10 15:36:00 2022 File:../lib/azure-iot-sdk-c/c-utility/src/optionhandler.c Func:AddOptionInternal Line:76 unable to clone value Error: Time:Mon Jan 10 15:36:00 2022 File:../lib/azure-iot-sdk-c/c-utility/pal/tlsio_options.c Func:tlsio_options_retrieve_options_ex Line:272 unable to save TrustedCerts option Error: Time:Mon Jan 10 15:36:00 2022 File:../lib/azure-iot-sdk-c/c-utility/src/xio.c Func:xio_retrieveoptions Line:279 unable to concrete_io_retrieveoptions Error: Time:Mon Jan 10 15:36:00 2022 File:../port/src/tlsio_esp_tls.c Func:tlsio_esp_tls_destroy Line:153 tlsio_esp_tls_destroy called while not in TLSIO_STATE_CLOSED.