Using latest SDK release LTS_08_2024 and MQTT over websockets protocol
When authenticating using x509 certificate in the MQTT over websockets protocol we use certificates with a limited duration that expire and need to be rotated every once in a while.
However, if the device is still using the old certificate after the current certificate expires it is expected that the SDK client will disconnect and report relevant credential/authentication errors.
What I have observed is that instead the device client will call the connection state callbacks with multiple different error reasons:
<- 01:02:55 PINGRESP
-> 01:03:55 PINGREQ
<- 01:03:55 PINGRESP
-> 01:04:55 PINGREQ
<- 01:04:55 PINGRESP
Error: Time:Mon Sep 30 01:05:36 2024 File:src/iothubtransport_mqtt_common.c Func:processErrorCallback Line:2305 Disconnecting MQTT connection because of an MQTT protocol error (MQTT_CLIENT_PARSE_ERROR).
Error: Time:Mon Sep 30 01:05:36 2024 File:src/uws_client.c Func:uws_client_close_async Line:1809 close has been called when already CLOSED
Error: Time:Mon Sep 30 01:05:36 2024 File:adapters/tlsio_openssl.c Func:decode_ssl_received_bytes Line:896 SSL channel closed in decode_ssl_received_bytes.
Error: Time:Mon Sep 30 01:05:36 2024 File:adapters/tlsio_openssl.c Func:on_underlying_io_bytes_received Line:945 Error in decode_ssl_received_bytes.
20240930T010536.0970Z [[33mWarning[39m]:IoTHubLib DeviceClient The device client has been disconnected due to reason IOTHUB_CLIENT_CONNECTION_NO_NETWORK
20240930T010536.0971Z [[31mError[39m]:IoTHubLib DeviceClient No connection_state_changed_callback
-> 01:05:37 CONNECT | VER: 4 | KEEPALIVE: 60 | FLAGS: 128 | USERNAME: iq-shared-0-38d07.azure-devices.net/52c1852c-14a0-11ed-98a3-000d3a46ad5a/?api-version=2020-09-30&DeviceClientType=iothubclient%2f1.13.0%20(native%3b%20Linux%3b%20armv7l) | CLEAN: 0
<- 01:05:37 CONNACK | SESSION_PRESENT: false | RETURN_CODE: 0x5
Error: Time:Mon Sep 30 01:05:37 2024 File:src/iothubtransport_mqtt_common.c Func:mqttOperationCompleteCallback Line:2142 Connection Not Accepted: 0x5: Not Authorized
Error: Time:Mon Sep 30 01:05:37 2024 File:src/uws_client.c Func:uws_client_close_async Line:1809 close has been called when already CLOSED
Error: Time:Mon Sep 30 01:05:37 2024 File:adapters/tlsio_openssl.c Func:decode_ssl_received_bytes Line:896 SSL channel closed in decode_ssl_received_bytes.
Error: Time:Mon Sep 30 01:05:37 2024 File:adapters/tlsio_openssl.c Func:on_underlying_io_bytes_received Line:945 Error in decode_ssl_received_bytes.
20240930T010537.0491Z [[33mWarning[39m]:IoTHubLib DeviceClient The device client has been disconnected due to reason IOTHUB_CLIENT_CONNECTION_BAD_CREDENTIAL
20240930T010537.0492Z [[31mError[39m]:IoTHubLib DeviceClient No connection_state_changed_callback
20240930T010537.0492Z [[33mWarning[39m]:IoTHubLib DeviceClient The device client has been disconnected due to reason IOTHUB_CLIENT_CONNECTION_NO_NETWORK
20240930T010537.0493Z [[31mError[39m]:IoTHubLib DeviceClient No connection_state_changed_callback
Error: Time:Mon Sep 30 01:05:37 2024 File:src/mqtt_client.c Func:sendPacketItem Line:393 Failure sending control packet data
Error: Time:Mon Sep 30 01:05:37 2024 File:src/mqtt_client.c Func:mqtt_client_disconnect Line:1350 Error: mqtt_client_disconnect send failed
-> 01:05:37 CONNECT | VER: 4 | KEEPALIVE: 60 | FLAGS: 128 | USERNAME: iq-shared-0-38d07.azure-devices.net/52c1852c-14a0-11ed-98a3-000d3a46ad5a/?api-version=2020-09-30&DeviceClientType=iothubclient%2f1.13.0%20(native%3b%20Linux%3b%20armv7l) | CLEAN: 0
<- 01:05:38 CONNACK | SESSION_PRESENT: false | RETURN_CODE: 0x5
Error: Time:Mon Sep 30 01:05:38 2024 File:src/iothubtransport_mqtt_common.c Func:mqttOperationCompleteCallback Line:2142 Connection Not Accepted: 0x5: Not Authorized
Error: Time:Mon Sep 30 01:05:38 2024 File:src/uws_client.c Func:uws_client_close_async Line:1809 close has been called when already CLOSED
Error: Time:Mon Sep 30 01:05:38 2024 File:adapters/tlsio_openssl.c Func:decode_ssl_received_bytes Line:896 SSL channel closed in decode_ssl_received_bytes.
Error: Time:Mon Sep 30 01:05:38 2024 File:adapters/tlsio_openssl.c Func:on_underlying_io_bytes_received Line:945 Error in decode_ssl_received_bytes.
20240930T010538.0027Z [[33mWarning[39m]:IoTHubLib DeviceClient The device client has been disconnected due to reason IOTHUB_CLIENT_CONNECTION_BAD_CREDENTIAL
20240930T010538.0028Z [[31mError[39m]:IoTHubLib DeviceClient No connection_state_changed_callback
20240930T010538.0029Z [[33mWarning[39m]:IoTHubLib DeviceClient The device client has been disconnected due to reason IOTHUB_CLIENT_CONNECTION_NO_NETWORK
20240930T010538.0029Z [[31mError[39m]:IoTHubLib DeviceClient No connection_state_changed_callback
udhcpc: broadcasting discover
Error: Time:Mon Sep 30 01:05:38 2024 File:src/mqtt_client.c Func:sendPacketItem Line:393 Failure sending control packet data
Error: Time:Mon Sep 30 01:05:38 2024 File:src/mqtt_client.c Func:mqtt_client_disconnect Line:1350 Error: mqtt_client_disconnect send failed
-> 01:05:39 CONNECT | VER: 4 | KEEPALIVE: 60 | FLAGS: 128 | USERNAME: iq-shared-0-38d07.azure-devices.net/52c1852c-14a0-11ed-98a3-000d3a46ad5a/?api-version=2020-09-30&DeviceClientType=iothubclient%2f1.13.0%20(native%3b%20Linux%3b%20armv7l) | CLEAN: 0
<- 01:05:39 CONNACK | SESSION_PRESENT: false | RETURN_CODE: 0x5
Error: Time:Mon Sep 30 01:05:39 2024 File:src/iothubtransport_mqtt_common.c Func:mqttOperationCompleteCallback Line:2142 Connection Not Accepted: 0x5: Not Authorized
Error: Time:Mon Sep 30 01:05:39 2024 File:src/uws_client.c Func:uws_client_close_async Line:1809 close has been called when already CLOSED
Error: Time:Mon Sep 30 01:05:39 2024 File:adapters/tlsio_openssl.c Func:decode_ssl_received_bytes Line:896 SSL channel closed in decode_ssl_received_bytes.
Error: Time:Mon Sep 30 01:05:39 2024 File:adapters/tlsio_openssl.c Func:on_underlying_io_bytes_received Line:945 Error in decode_ssl_received_bytes.
20240930T010539.0885Z [[33mWarning[39m]:IoTHubLib DeviceClient The device client has been disconnected due to reason IOTHUB_CLIENT_CONNECTION_BAD_CREDENTIAL
20240930T010539.0885Z [[31mError[39m]:IoTHubLib DeviceClient No connection_state_changed_callback
20240930T010539.0887Z [[33mWarning[39m]:IoTHubLib DeviceClient The device client has been disconnected due to reason IOTHUB_CLIENT_CONNECTION_NO_NETWORK
20240930T010539.0887Z [[31mError[39m]:IoTHubLib DeviceClient No connection_state_changed_callback
I would expect to get the IOTHUB_CLIENT_CONNECTION_BAD_CREDENTIAL error, however it is always followed by another IOTHUB_CLIENT_CONNECTION_NO_NETWORK a couple of milliseconds after, even if the device internet connection is fine, which makes it really hard to do any error handling over the state. Is this the expected behavior from the SDK or is there something wrong with it?
Using latest SDK release LTS_08_2024 and MQTT over websockets protocol
When authenticating using x509 certificate in the MQTT over websockets protocol we use certificates with a limited duration that expire and need to be rotated every once in a while.
However, if the device is still using the old certificate after the current certificate expires it is expected that the SDK client will disconnect and report relevant credential/authentication errors.
What I have observed is that instead the device client will call the connection state callbacks with multiple different error reasons:
<- 01:02:55 PINGRESP -> 01:03:55 PINGREQ <- 01:03:55 PINGRESP -> 01:04:55 PINGREQ <- 01:04:55 PINGRESP Error: Time:Mon Sep 30 01:05:36 2024 File:src/iothubtransport_mqtt_common.c Func:processErrorCallback Line:2305 Disconnecting MQTT connection because of an MQTT protocol error (MQTT_CLIENT_PARSE_ERROR). Error: Time:Mon Sep 30 01:05:36 2024 File:src/uws_client.c Func:uws_client_close_async Line:1809 close has been called when already CLOSED Error: Time:Mon Sep 30 01:05:36 2024 File:adapters/tlsio_openssl.c Func:decode_ssl_received_bytes Line:896 SSL channel closed in decode_ssl_received_bytes. Error: Time:Mon Sep 30 01:05:36 2024 File:adapters/tlsio_openssl.c Func:on_underlying_io_bytes_received Line:945 Error in decode_ssl_received_bytes. 20240930T010536.0970Z [[33mWarning[39m]:IoTHubLib DeviceClient The device client has been disconnected due to reason IOTHUB_CLIENT_CONNECTION_NO_NETWORK 20240930T010536.0971Z [[31mError[39m]:IoTHubLib DeviceClient No connection_state_changed_callback -> 01:05:37 CONNECT | VER: 4 | KEEPALIVE: 60 | FLAGS: 128 | USERNAME: iq-shared-0-38d07.azure-devices.net/52c1852c-14a0-11ed-98a3-000d3a46ad5a/?api-version=2020-09-30&DeviceClientType=iothubclient%2f1.13.0%20(native%3b%20Linux%3b%20armv7l) | CLEAN: 0 <- 01:05:37 CONNACK | SESSION_PRESENT: false | RETURN_CODE: 0x5 Error: Time:Mon Sep 30 01:05:37 2024 File:src/iothubtransport_mqtt_common.c Func:mqttOperationCompleteCallback Line:2142 Connection Not Accepted: 0x5: Not Authorized Error: Time:Mon Sep 30 01:05:37 2024 File:src/uws_client.c Func:uws_client_close_async Line:1809 close has been called when already CLOSED Error: Time:Mon Sep 30 01:05:37 2024 File:adapters/tlsio_openssl.c Func:decode_ssl_received_bytes Line:896 SSL channel closed in decode_ssl_received_bytes. Error: Time:Mon Sep 30 01:05:37 2024 File:adapters/tlsio_openssl.c Func:on_underlying_io_bytes_received Line:945 Error in decode_ssl_received_bytes. 20240930T010537.0491Z [[33mWarning[39m]:IoTHubLib DeviceClient The device client has been disconnected due to reason IOTHUB_CLIENT_CONNECTION_BAD_CREDENTIAL 20240930T010537.0492Z [[31mError[39m]:IoTHubLib DeviceClient No connection_state_changed_callback 20240930T010537.0492Z [[33mWarning[39m]:IoTHubLib DeviceClient The device client has been disconnected due to reason IOTHUB_CLIENT_CONNECTION_NO_NETWORK 20240930T010537.0493Z [[31mError[39m]:IoTHubLib DeviceClient No connection_state_changed_callback Error: Time:Mon Sep 30 01:05:37 2024 File:src/mqtt_client.c Func:sendPacketItem Line:393 Failure sending control packet data Error: Time:Mon Sep 30 01:05:37 2024 File:src/mqtt_client.c Func:mqtt_client_disconnect Line:1350 Error: mqtt_client_disconnect send failed -> 01:05:37 CONNECT | VER: 4 | KEEPALIVE: 60 | FLAGS: 128 | USERNAME: iq-shared-0-38d07.azure-devices.net/52c1852c-14a0-11ed-98a3-000d3a46ad5a/?api-version=2020-09-30&DeviceClientType=iothubclient%2f1.13.0%20(native%3b%20Linux%3b%20armv7l) | CLEAN: 0 <- 01:05:38 CONNACK | SESSION_PRESENT: false | RETURN_CODE: 0x5 Error: Time:Mon Sep 30 01:05:38 2024 File:src/iothubtransport_mqtt_common.c Func:mqttOperationCompleteCallback Line:2142 Connection Not Accepted: 0x5: Not Authorized Error: Time:Mon Sep 30 01:05:38 2024 File:src/uws_client.c Func:uws_client_close_async Line:1809 close has been called when already CLOSED Error: Time:Mon Sep 30 01:05:38 2024 File:adapters/tlsio_openssl.c Func:decode_ssl_received_bytes Line:896 SSL channel closed in decode_ssl_received_bytes. Error: Time:Mon Sep 30 01:05:38 2024 File:adapters/tlsio_openssl.c Func:on_underlying_io_bytes_received Line:945 Error in decode_ssl_received_bytes. 20240930T010538.0027Z [[33mWarning[39m]:IoTHubLib DeviceClient The device client has been disconnected due to reason IOTHUB_CLIENT_CONNECTION_BAD_CREDENTIAL 20240930T010538.0028Z [[31mError[39m]:IoTHubLib DeviceClient No connection_state_changed_callback 20240930T010538.0029Z [[33mWarning[39m]:IoTHubLib DeviceClient The device client has been disconnected due to reason IOTHUB_CLIENT_CONNECTION_NO_NETWORK 20240930T010538.0029Z [[31mError[39m]:IoTHubLib DeviceClient No connection_state_changed_callback udhcpc: broadcasting discover Error: Time:Mon Sep 30 01:05:38 2024 File:src/mqtt_client.c Func:sendPacketItem Line:393 Failure sending control packet data Error: Time:Mon Sep 30 01:05:38 2024 File:src/mqtt_client.c Func:mqtt_client_disconnect Line:1350 Error: mqtt_client_disconnect send failed -> 01:05:39 CONNECT | VER: 4 | KEEPALIVE: 60 | FLAGS: 128 | USERNAME: iq-shared-0-38d07.azure-devices.net/52c1852c-14a0-11ed-98a3-000d3a46ad5a/?api-version=2020-09-30&DeviceClientType=iothubclient%2f1.13.0%20(native%3b%20Linux%3b%20armv7l) | CLEAN: 0 <- 01:05:39 CONNACK | SESSION_PRESENT: false | RETURN_CODE: 0x5 Error: Time:Mon Sep 30 01:05:39 2024 File:src/iothubtransport_mqtt_common.c Func:mqttOperationCompleteCallback Line:2142 Connection Not Accepted: 0x5: Not Authorized Error: Time:Mon Sep 30 01:05:39 2024 File:src/uws_client.c Func:uws_client_close_async Line:1809 close has been called when already CLOSED Error: Time:Mon Sep 30 01:05:39 2024 File:adapters/tlsio_openssl.c Func:decode_ssl_received_bytes Line:896 SSL channel closed in decode_ssl_received_bytes. Error: Time:Mon Sep 30 01:05:39 2024 File:adapters/tlsio_openssl.c Func:on_underlying_io_bytes_received Line:945 Error in decode_ssl_received_bytes. 20240930T010539.0885Z [[33mWarning[39m]:IoTHubLib DeviceClient The device client has been disconnected due to reason IOTHUB_CLIENT_CONNECTION_BAD_CREDENTIAL 20240930T010539.0885Z [[31mError[39m]:IoTHubLib DeviceClient No connection_state_changed_callback 20240930T010539.0887Z [[33mWarning[39m]:IoTHubLib DeviceClient The device client has been disconnected due to reason IOTHUB_CLIENT_CONNECTION_NO_NETWORK 20240930T010539.0887Z [[31mError[39m]:IoTHubLib DeviceClient No connection_state_changed_callback
I would expect to get the IOTHUB_CLIENT_CONNECTION_BAD_CREDENTIAL error, however it is always followed by another IOTHUB_CLIENT_CONNECTION_NO_NETWORK a couple of milliseconds after, even if the device internet connection is fine, which makes it really hard to do any error handling over the state. Is this the expected behavior from the SDK or is there something wrong with it?