Connection callback is never called after Internet access is restored (MQTT)

[Morozov-5F]

• OS and version used: MIPS Linux OpenWrt 3.18.29

• SDK version used: IoT Hub SDK for C, version 1.2.9 (2018-09-11)

Description of the issue:

After device startup, Wi-Fi is not available yet and IoT SDK reports connection status as OFFLINE (NO NETWORK). After a while, the connection is restored and SDK logs communication with IoT Hub, but connection callback is never called with status ONLINE.

Code sample exhibiting the issue:

This is a extensive modified x509 sample. Sample code is available here: azure.c.

Console log of the issue:

• Label "1" indicates last confirmation callback call
• Label "2" shows first successful data exchange between IoT Hub and SDK

  ct 12 17:40:27 OpenWrt local1.info 23 Lynx: fw: [490] azure/azure.c:3497: s_azure_ctx_init: Azure: Logging setup
  Oct 12 17:40:27 OpenWrt local1.info 23 Lynx: fw: [490] azure/azure.c:553: s_azure_find_host_by_alias: Azure host for 'prod': <IOT_HUB_HOSTNAME>
  Oct 12 17:40:30 OpenWrt local1.err 25 Lynx: fw: [490] advanced_diag.c:768: s_send_ad_message_to_async_local_channels: Unable to send diagnostic message to Azure
  Oct 12 17:40:30 OpenWrt local1.err 25 Lynx: fw: [490] azure/azure.c:3927: cat_azure_send_initial_twin_properties: Unable to get temporary logging frequency
  Oct 12 17:40:30 OpenWrt local1.err 25 Lynx: fw: [490] azure/azure.c:3939: cat_azure_send_initial_twin_properties: Unable to get temporary polling frequency
  Oct 12 17:40:30 OpenWrt local1.info 25 Lynx: fw: [50E] iceman_azure_worker.c:801: s_azw_worker_thread: Started azure events worker thread
  Oct 12 17:40:30 OpenWrt local1.info 25 Lynx: fw: [526] azure/azure.c:3623: cat_azure_module_start: Starting Azure IoT Module UV loop
  Oct 12 17:40:30 OpenWrt local1.info 25 Lynx: fw: [526] azure/azure.c:2691: s_azure_main_loop: TELEMETRY: sending a message to Azure
  Oct 12 17:40:30 OpenWrt local1.err 25 Lynx: fw: [526] socketio_berkeley.c:282: iot_sdk_lookup_address_and_initiate_socket_connection: Failure: getaddrinfo failure -2.
  Oct 12 17:40:30 OpenWrt local1.err 25 Lynx: fw: [526] socketio_berkeley.c:765: iot_sdk_socketio_open: lookup_address_and_connect_socket failed
  Oct 12 17:40:30 OpenWrt local1.info 25 Lynx: fw: [526] azure/azure.c:1237: s_azure_client_connection_status_cb: Azure connection status: OFFLINE; reason: NO NETWORK
  Oct 12 17:40:30 OpenWrt local1.err 25 Lynx: fw: [526] tlsio_openssl.c:760: iot_sdk_on_underlying_io_open_complete: Invalid tlsio_state. Expected state is TLSIO_STATE_OPENING_UNDERLYING_IO.
  Oct 12 17:40:30 OpenWrt local1.err 25 Lynx: fw: [526] tlsio_openssl.c:1258: iot_sdk_tlsio_openssl_open: Failed opening the underlying I/O.
  Oct 12 17:40:30 OpenWrt local1.err 25 Lynx: fw: [526] mqtt_client.c:1000: iot_sdk_mqtt_client_connect: Error: io_open failed
  Oct 12 17:40:30 OpenWrt local1.err 25 Lynx: fw: [526] iothubtransport_mqtt_common.c:2122: iot_sdk_SendMqttConnectMsg: failure connecting to address <IOT_HUB_HOSTNAME>.
  Oct 12 17:40:35 OpenWrt local1.err 30 Lynx: fw: [526] socketio_berkeley.c:282: iot_sdk_lookup_address_and_initiate_socket_connection: Failure: getaddrinfo failure -2.
  Oct 12 17:40:35 OpenWrt local1.err 30 Lynx: fw: [526] socketio_berkeley.c:765: iot_sdk_socketio_open: lookup_address_and_connect_socket failed
  1---> Oct 12 17:40:35 OpenWrt local1.info 30 Lynx: fw: [526] azure/azure.c:1237: s_azure_client_connection_status_cb: Azure connection status: OFFLINE; reason: NO NETWORK
  Oct 12 17:40:35 OpenWrt local1.err 30 Lynx: fw: [526] tlsio_openssl.c:760: iot_sdk_on_underlying_io_open_complete: Invalid tlsio_state. Expected state is TLSIO_STATE_OPENING_UNDERLYING_IO.
  Oct 12 17:40:35 OpenWrt local1.err 30 Lynx: fw: [526] tlsio_openssl.c:1258: iot_sdk_tlsio_openssl_open: Failed opening the underlying I/O.
  Oct 12 17:40:35 OpenWrt local1.err 30 Lynx: fw: [526] mqtt_client.c:1000: iot_sdk_mqtt_client_connect: Error: io_open failed
  Oct 12 17:40:35 OpenWrt local1.err 30 Lynx: fw: [526] iothubtransport_mqtt_common.c:2122: iot_sdk_SendMqttConnectMsg: failure connecting to address <IOT_HUB_HOSTNAME>.
  2----> Oct 15 14:05:51 OpenWrt local1.info 41 Lynx: fw: [526] mqtt_client.c:270: iot_sdk_log_outgoing_trace: -> 14:05:51 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_MOST_ONCE | TOPIC_NAME: $iothub/twin/GET/?$rid=4
  Oct 15 14:05:51 OpenWrt local1.info 41 Lynx: fw: [526] mqtt_client.c:297: iot_sdk_log_incoming_trace: <- 14:05:51 PUBACK | PACKET_ID: 3
  Oct 15 14:05:51 OpenWrt local1.info 41 Lynx: fw: [526] azure/azure.c:1091: s_azure_send_confirmation_cb: TELEMETRY: message is delivered
  Oct 15 14:05:52 OpenWrt local1.info 41 Lynx: fw: [526] azure/azure.c:2691: s_azure_main_loop: TELEMETRY: sending a message to Azure
  Oct 15 14:05:52 OpenWrt local1.info 41 Lynx: fw: [526] mqtt_client.c:270: iot_sdk_log_outgoing_trace: -> 14:05:52 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_LEAST_ONCE | TOPIC_NAME: devices/<DEVICE_ID>4/messages/events/name=common.puma_upgrade | PACKET_ID: 5
  Oct 15 14:05:52 OpenWrt local1.info 41 Lynx: fw: [526] mqtt_client.c:297: iot_sdk_log_incoming_trace: <- 14:05:52 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_MOST_ONCE = 0x00 | TOPIC_NAME: $iothub/twin/res/200/?$rid=4 | PAYLOAD_LEN: 994
  Oct 15 14:05:52 OpenWrt local1.info 41 Lynx: fw: [526] azure/azure.c:2599: s_azure_device_twin_cb: TWIN-GENERAL: twin update received. Status: 0
  Oct 15 14:05:52 OpenWrt local1.info 41 Lynx: fw: [526] azure/azure.c:1982: s_azure_device_twin_process_desired_property: TWIN-DESIRED: processing property 'temp_polling_frequency' (value '"45"')
  Oct 15 14:05:52 OpenWrt local1.info 41 Lynx: fw: [526] azure/azure.c:1953: s_azure_device_twin_process_desired_property: TWIN-DESIRED: ignore property '$version' - callback not set
  Oct 15 14:05:52 OpenWrt local1.info 41 Lynx: fw: [526] mqtt_client.c:270: iot_sdk_log_outgoing_trace: -> 14:05:52 SUBSCRIBE | PACKET_ID: 6 | TOPIC_NAME: $iothub/twin/PATCH/properties/desired/# | QOS: 0
  Oct 15 14:05:52 OpenWrt local1.info 41 Lynx: fw: [526] mqtt_client.c:297: iot_sdk_log_incoming_trace: <- 14:05:52 PUBACK | PACKET_ID: 5
  Oct 15 14:05:52 OpenWrt local1.info 41 Lynx: fw: [526] azure/azure.c:1091: s_azure_send_confirmation_cb: TELEMETRY: message is delivered
  # And so on...

[jebrando]

In your log I am unable to see the CONNECT packet being sent from the device to the service. I see a few PUBLISH packets being sent and received. Can you resend a log with the connect packets included, it will give us a clue as to what's happening. The connect package should look similar to the following:

->XX:XX:XX CONNECT | VER: 4 | KEEPALIVE: 240 | FLAGS: 192 | USERNAME: XXX ...

[vdcow]

@jebrando

In your log I am unable to see the CONNECT packet being sent from the device to the service.

The problem is that with our current logging configuration we don't see CONNECT packet in log. We use xlogging_set_log_function() to setup logging. Is it right way to configure IoT SDK logging?

I am not sure if it is useful but when SDK could normally connect we see following log entry with CONNACK

mqtt_client.c:297: iot_sdk_log_incoming_trace: <- 16:46:39 CONNACK | SESSION_PRESENT: true | RETURN_CODE: 0x0

As you see above there is no such message when issue happens.

[massand]

This code snippet (which you have used in reporting #652) would help spew those out -

// Turn on Log
bool trace = true;
(void)IoTHubClient_SetOption(iotHubClientHandle, "logtrace", &trace);

[vdcow]

@massand

This code snippet (which you have used in reporting #652) would help spew those out

We already use this option. But don't see CONNECT packet. Only CONNACK.

[jebrando]

@Morozov-5F With MQTT the CONNECT packet is how it connects to the service. Without this message there is no CONNACK. We see the CONNACK so there must be a CONNECT packet. Finding that CONNECT packet will help in finding the callback. Is it consistent with the same logging, does the CONNECT never show up?

[Morozov-5F]

@jebrando I'm not sure about it, but I don't recall seeing that packet in our logs. I'll review logs and try different logging, then I'll let you know.

[bikamani]

Hi @Morozov-5F Following up on this issue, I used a telemetry sample with MQTT protocol to verify. With network disconnected and after it is restored, I see callbacks as expected. Feel free to reopen the issue if the issue still exist and you have more questions. Also, these are my logs with highlighted callbacks, CONNECT , CONNACK, PUBLISH and PUBACK below:

Creating IoTHub Device handle Sending message 1 to IoTHub Error: Time:Wed Feb 6 14:19:03 2019 File:D:\iot\azure-iot-sdk-c\c-utility\adapters\socketio_win32.c Func:_lookup_address_and_initiate_socket_connection Line:299 Failure: getaddrinfo failure 11001. Error: Time:Wed Feb 6 14:19:03 2019 File:D:\iot\azure-iot-sdk-c\c-utility\adapters\socketio_win32.c Func:_socketio_open Line:390 lookup_address_and_connect_socket failed The device client has been disconnected CONNECTION STATUS REPORTED (result=IOTHUB_CLIENT_CONNECTION_UNAUTHENTICATED; reason=IOTHUB_CLIENT_CONNECTION_NO_NETWORK)Error: Time:Wed Feb 6 14:19:03 2019 File:D:\iot\azure-iot-sdk-c\c-utility\adapters\tlsio_schannel.c Func:_tlsio_schannel_open Line:1248 xio_open failed Error: Time:Wed Feb 6 14:19:03 2019 File:D:\iot\azure-iot-sdk-c\umqtt\src\mqtt_client.c Func:_mqtt_client_connect Line:1001 Error: io_open failed Error: Time:Wed Feb 6 14:19:03 2019 File:D:\iot\azure-iot-sdk-c\iothub_client\src\iothubtransport_mqtt_common.c Func:_SendMqttConnectMsg Line:2261 failure connecting to address TestHub.azure-devices.net. Error: Time:Wed Feb 6 14:19:04 2019 File:D:\iot\azure-iot-sdk-c\c-utility\adapters\socketio_win32.c Func:_lookup_address_and_initiate_socket_connection Line:299 Failure: getaddrinfo failure 11001. Error: Time:Wed Feb 6 14:19:04 2019 File:D:\iot\azure-iot-sdk-c\c-utility\adapters\socketio_win32.c Func:_socketio_open Line:390 lookup_address_and_connect_socket failed The device client has been disconnected CONNECTION STATUS REPORTED (result=IOTHUB_CLIENT_CONNECTION_UNAUTHENTICATED; reason=IOTHUB_CLIENT_CONNECTION_NO_NETWORK)Error: Time:Wed Feb 6 14:19:04 2019 File:D:\iot\azure-iot-sdk-c\c-utility\adapters\tlsio_schannel.c Func:_tlsio_schannel_open Line:1248 xio_open failed Error: Time:Wed Feb 6 14:19:04 2019 File:D:\iot\azure-iot-sdk-c\umqtt\src\mqtt_client.c Func:_mqtt_client_connect Line:1001 Error: io_open failed Error: Time:Wed Feb 6 14:19:04 2019 File:D:\iot\azure-iot-sdk-c\iothub_client\src\iothubtransport_mqtt_common.c Func:_SendMqttConnectMsg Line:2261 failure connecting to address TestHub.azure-devices.net. Error: Time:Wed Feb 6 14:19:06 2019 File:D:\iot\azure-iot-sdk-c\c-utility\adapters\socketio_win32.c Func:_lookup_address_and_initiate_socket_connection Line:299 Failure: getaddrinfo failure 11001. Error: Time:Wed Feb 6 14:19:06 2019 File:D:\iot\azure-iot-sdk-c\c-utility\adapters\socketio_win32.c Func:_socketio_open Line:390 lookup_address_and_connect_socket failed The device client has been disconnected CONNECTION STATUS REPORTED (result=IOTHUB_CLIENT_CONNECTION_UNAUTHENTICATED; reason=IOTHUB_CLIENT_CONNECTION_NO_NETWORK) Error: Time:Wed Feb 6 14:19:06 2019 File:D:\iot\azure-iot-sdk-c\c-utility\adapters\tlsio_schannel.c Func:_tlsio_schannel_open Line:1248 xio_open failed Error: Time:Wed Feb 6 14:19:06 2019 File:D:\iot\azure-iot-sdk-c\umqtt\src\mqtt_client.c Func:_mqtt_client_connect Line:1001 Error: io_open failed Error: Time:Wed Feb 6 14:19:06 2019 File:D:\iot\azure-iot-sdk-c\iothub_client\src\iothubtransport_mqtt_common.c Func:_SendMqttConnectMsg Line:2261 failure connecting to address TestHub.azure-devices.net. -> 14:19:12 CONNECT | VER: 4 | KEEPALIVE: 240 | FLAGS: 192 | USERNAME: TestHub.azure-devices.net/test_dev1/?api-version=2017-11-08-preview&DeviceClientType=iothubclient%* PWD: XXXX | CLEAN: 0 <- 14:19:12 CONNACK | SESSION_PRESENT: false | RETURN_CODE: 0x0 The device client is connected to iothub CONNECTION STATUS REPORTED (result=IOTHUB_CLIENT_CONNECTION_AUTHENTICATED; reason=IOTHUB_CLIENT_CONNECTION_OK) -> 14:19:12 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_LEAST_ONCE | TOPIC_NAME: devices/test_dev1/messages/events/property_key=property_value | PACKET_ID: 2 | PAYLOAD_LEN: 12 <- 14:19:12 PUBACK | PACKET_ID: 2 Confirmation callback received for message 1 with result IOTHUB_CLIENT_CONFIRMATION_OK Sending message 2 to IoTHub -> 14:19:16 PUBLISH | IS_DUP: false | RETAIN: 0 | QOS: DELIVER_AT_LEAST_ONCE | TOPIC_NAME: devices/test_dev1/messages/events/property_key=property_value | PACKET_ID: 3 | PAYLOAD_LEN: 12 <- 14:19:16 PUBACK** | PACKET_ID: 3 Confirmation callback received for message 2 with result IOTHUB_CLIENT_CONFIRMATION_OK

[az-iot-builder-01]

@jebrando, @vladimir-didenko, @massand, @Morozov-5F, @bikamani, thank you for your contribution to our open-sourced project! Please help us improve by filling out this 2-minute customer satisfaction survey