search

Azure / iot-hub-device-update

Device Update for IoT Hub agent
MIT License
53 stars 41 forks source link

ADU deviceupdate-agnet 1.0.2 is unable to connect to the IoT Hub, Connection Not Accepted: 0x5: Not Authorized #660

Open FinitelyFailed opened 2 weeks ago

FinitelyFailed commented 2 weeks ago

Expected Behavior

deviceupdate-agent should connect to the IoT hub, using the azure identity service to get a connection string.

Current Behavior

This happened on one of our test devices. We have multiple devices running, the other ones work fine. But this one stopped working about a week ago. deviceupdate-agent can not connect to the IoT hub as it gets a "Connection Not Accepted" error.

Oct 02 05:59:02 raspberrypi4-64 AducIotAgent[335]: .c Func:mqttOperationCompleteCallback Line:2072 Connection Not Accepted: 0x5: Not Authorized
Oct 02 05:59:02 raspberrypi4-64 AducIotAgent[335]: -> 05:57:33 CONNECT | VER: 4 | KEEPALIVE: 240 | FLAGS: 192 | USERNAME: syscomiotedgehubtest.azure-devices.net/e6dc8d96-50a0-4eaf-bb9b-4ba6fff80658-gptedge/DeviceUpdate/?api-version=2020-09-30&DeviceClientType=iothubclient%2f1.9.0%20(native%3b%20Linux%3b%20aarch64)>
Oct 02 05:59:02 raspberrypi4-64 AducIotAgent[335]: <- 05:57:33 CONNACK | SESSION_PRESENT: false | RETURN_CODE: 0x5
Oct 02 05:59:02 raspberrypi4-64 AducIotAgent[335]: 2024-10-02T05:57:33.4330Z 335[335] [D] IotHub connection status: 1, reason: 2 [IoTHub_CommunicationManager_ConnectionStatus_Callback]
Oct 02 05:59:02 raspberrypi4-64 AducIotAgent[335]: Error: Time:Wed Oct  2 05:57:33 2024 File:/usr/src/debug/azure-iot-sdk-c/1.0+gitAUTOINC+7329f70906-r0/git/iothub_client/src/iothubtransport_mqtt_common.c Func:mqttOperationCompleteCallback Line:2072 Connection Not Accepted: 0x5: Not Authorized
Oct 02 05:59:02 raspberrypi4-64 AducIotAgent[335]: -> 05:57:37 CONNECT | VER: 4 | KEEPALIVE: 240 | FLAGS: 192 | USERNAME: syscomiotedgehubtest.azure-devices.net/e6dc8d96-50a0-4eaf-bb9b-4ba6fff80658-gptedge/DeviceUpdate/?api-version=2020-09-30&DeviceClientType=iothubclient%2f1.9.0%20(native%3b%20Linux%3b%20aarch64)>
Oct 02 05:59:02 raspberrypi4-64 AducIotAgent[335]: <- 05:57:37 CONNACK | SESSION_PRESENT: false | RETURN_CODE: 0x5
Oct 02 05:59:02 raspberrypi4-64 AducIotAgent[335]: 2024-10-02T05:57:37.4011Z 335[335] [D] IotHub connection status: 1, reason: 2 [IoTHub_CommunicationManager_ConnectionStatus_Callback]
Oct 02 05:59:02 raspberrypi4-64 AducIotAgent[335]: Error: Time:Wed Oct  2 05:57:37 2024 File:/usr/src/debug/azure-iot-sdk-c/1.0+gitAUTOINC+7329f70906-r0/git/iothub_client/src/iothubtransport_mqtt_common.c Func:mqttOperationCompleteCallback Line:2072 Connection Not Accepted: 0x5: Not Authorized
Oct 02 05:59:02 raspberrypi4-64 AducIotAgent[335]: -> 05:57:45 CONNECT | VER: 4 | KEEPALIVE: 240 | FLAGS: 192 | USERNAME: syscomiotedgehubtest.azure-devices.net/e6dc8d96-50a0-4eaf-bb9b-4ba6fff80658-gptedge/DeviceUpdate/?api-version=2020-09-30&DeviceClientType=iothubclient%2f1.9.0%20(native%3b%20Linux%3b%20aarch64)>
Oct 02 05:59:02 raspberrypi4-64 AducIotAgent[335]: <- 05:57:45 CONNACK | SESSION_PRESENT: false | RETURN_CODE: 0x5
Oct 02 05:59:02 raspberrypi4-64 AducIotAgent[335]: 2024-10-02T05:57:45.4150Z 335[335] [D] IotHub connection status: 1, reason: 2 [IoTHub_CommunicationManager_ConnectionStatus_Callback]
Oct 02 05:59:02 raspberrypi4-64 AducIotAgent[335]: Error: Time:Wed Oct  2 05:57:45 2024 File:/usr/src/debug/azure-iot-sdk-c/1.0+gitAUTOINC+7329f70906-r0/git/iothub_client/src/iothubtransport_mqtt_common.c Func:mqttOperationCompleteCallback Line:2072 Connection Not Accepted: 0x5: Not Authorized
Oct 02 05:59:02 raspberrypi4-64 AducIotAgent[335]: -> 05:58:01 CONNECT | VER: 4 | KEEPALIVE: 240 | FLAGS: 192 | USERNAME: syscomiotedgehubtest.azure-devices.net/e6dc8d96-50a0-4eaf-bb9b-4ba6fff80658-gptedge/DeviceUpdate/?api-version=2020-09-30&DeviceClientType=iothubclient%2f1.9.0%20(native%3b%20Linux%3b%20aarch64)>
Oct 02 05:59:02 raspberrypi4-64 AducIotAgent[335]: <- 05:58:01 CONNACK | SESSION_PRESENT: false | RETURN_CODE: 0x5
Oct 02 05:59:02 raspberrypi4-64 AducIotAgent[335]: 2024-10-02T05:58:01.4152Z 335[335] [D] IotHub connection status: 1, reason: 2 [IoTHub_CommunicationManager_ConnectionStatus_Callback]
Oct 02 05:59:02 raspberrypi4-64 AducIotAgent[335]: Error: Time:Wed Oct  2 05:58:01 2024 File:/usr/src/debug/azure-iot-sdk-c/1.0+gitAUTOINC+7329f70906-r0/git/iothub_client/src/iothubtransport_mqtt_common.c Func:mqttOperationCompleteCallback Line:2072 Connection Not Accepted: 0x5: Not Authorized
Oct 02 05:59:02 raspberrypi4-64 AducIotAgent[335]: -> 05:58:32 CONNECT | VER: 4 | KEEPALIVE: 240 | FLAGS: 192 | USERNAME: syscomiotedgehubtest.azure-devices.net/e6dc8d96-50a0-4eaf-bb9b-4ba6fff80658-gptedge/DeviceUpdate/?api-version=2020-09-30&DeviceClientType=iothubclient%2f1.9.0%20(native%3b%20Linux%3b%20aarch64)>
Oct 02 05:59:02 raspberrypi4-64 AducIotAgent[335]: <- 05:58:32 CONNACK | SESSION_PRESENT: false | RETURN_CODE: 0x5
Oct 02 05:59:02 raspberrypi4-64 AducIotAgent[335]: 2024-10-02T05:58:32.4416Z 335[335] [D] IotHub connection status: 1, reason: 2 [IoTHub_CommunicationManager_ConnectionStatus_Callback]
Oct 02 05:59:02 raspberrypi4-64 AducIotAgent[335]: Error: Time:Wed Oct  2 05:58:32 2024 File:/usr/src/debug/azure-iot-sdk-c/1.0+gitAUTOINC+7329f70906-r0/git/iothub_client/src/iothubtransport_mqtt_common.c Func:mqttOperationCompleteCallback Line:2072 Connection Not Accepted: 0x5: Not Authorized
Oct 02 05:59:02 raspberrypi4-64 AducIotAgent[335]: -> 05:59:02 CONNECT | VER: 4 | KEEPALIVE: 240 | FLAGS: 192 | USERNAME: syscom2024-10-02T05:59:02.4834Z 335[335] [E] IoTHub connection is broken for 418419 seconds (will retry in 455 seconds) [IoTHub_CommunicationManager_ConnectionStatus_Callback]
Oct 02 05:59:32 raspberrypi4-64 AducIotAgent[335]: 2024-10-02T05:59:32.4069Z 335[335] [E] IoTHub connection is broken for 418449 seconds (will retry in 425 seconds) [IoTHub_CommunicationManager_ConnectionStatus_Callback]
Oct 02 06:00:02 raspberrypi4-64 AducIotAgent[335]: 2024-10-02T06:00:02.4371Z 335[335] [E] IoTHub connection is broken for 418479 seconds (will retry in 395 seconds) [IoTHub_CommunicationManager_ConnectionStatus_Callback]
Oct 02 06:00:32 raspberrypi4-64 AducIotAgent[335]: 2024-10-02T06:00:32.4771Z 335[335] [E] IoTHub connection is broken for 418509 seconds (will retry in 365 seconds) [IoTHub_CommunicationManager_ConnectionStatus_Callback]
Oct 02 06:01:02 raspberrypi4-64 AducIotAgent[335]: 2024-10-02T06:01:02.4203Z 335[335] [E] IoTHub connection is broken for 418539 seconds (will retry in 335 seconds) [IoTHub_CommunicationManager_ConnectionStatus_Callback]

Device Information

Logs

Oct 02 05:59:02 raspberrypi4-64 AducIotAgent[335]: .c Func:mqttOperationCompleteCallback Line:2072 Connection Not Accepted: 0x5: Not Authorized
Oct 02 05:59:02 raspberrypi4-64 AducIotAgent[335]: -> 05:57:33 CONNECT | VER: 4 | KEEPALIVE: 240 | FLAGS: 192 | USERNAME: syscomiotedgehubtest.azure-devices.net/e6dc8d96-50a0-4eaf-bb9b-4ba6fff80658-gptedge/DeviceUpdate/?api-version=2020-09-30&DeviceClientType=iothubclient%2f1.9.0%20(native%3b%20Linux%3b%20aarch64)>
Oct 02 05:59:02 raspberrypi4-64 AducIotAgent[335]: <- 05:57:33 CONNACK | SESSION_PRESENT: false | RETURN_CODE: 0x5
Oct 02 05:59:02 raspberrypi4-64 AducIotAgent[335]: 2024-10-02T05:57:33.4330Z 335[335] [D] IotHub connection status: 1, reason: 2 [IoTHub_CommunicationManager_ConnectionStatus_Callback]
Oct 02 05:59:02 raspberrypi4-64 AducIotAgent[335]: Error: Time:Wed Oct  2 05:57:33 2024 File:/usr/src/debug/azure-iot-sdk-c/1.0+gitAUTOINC+7329f70906-r0/git/iothub_client/src/iothubtransport_mqtt_common.c Func:mqttOperationCompleteCallback Line:2072 Connection Not Accepted: 0x5: Not Authorized
Oct 02 05:59:02 raspberrypi4-64 AducIotAgent[335]: -> 05:57:37 CONNECT | VER: 4 | KEEPALIVE: 240 | FLAGS: 192 | USERNAME: syscomiotedgehubtest.azure-devices.net/e6dc8d96-50a0-4eaf-bb9b-4ba6fff80658-gptedge/DeviceUpdate/?api-version=2020-09-30&DeviceClientType=iothubclient%2f1.9.0%20(native%3b%20Linux%3b%20aarch64)>
Oct 02 05:59:02 raspberrypi4-64 AducIotAgent[335]: <- 05:57:37 CONNACK | SESSION_PRESENT: false | RETURN_CODE: 0x5
Oct 02 05:59:02 raspberrypi4-64 AducIotAgent[335]: 2024-10-02T05:57:37.4011Z 335[335] [D] IotHub connection status: 1, reason: 2 [IoTHub_CommunicationManager_ConnectionStatus_Callback]
Oct 02 05:59:02 raspberrypi4-64 AducIotAgent[335]: Error: Time:Wed Oct  2 05:57:37 2024 File:/usr/src/debug/azure-iot-sdk-c/1.0+gitAUTOINC+7329f70906-r0/git/iothub_client/src/iothubtransport_mqtt_common.c Func:mqttOperationCompleteCallback Line:2072 Connection Not Accepted: 0x5: Not Authorized
Oct 02 05:59:02 raspberrypi4-64 AducIotAgent[335]: -> 05:57:45 CONNECT | VER: 4 | KEEPALIVE: 240 | FLAGS: 192 | USERNAME: syscomiotedgehubtest.azure-devices.net/e6dc8d96-50a0-4eaf-bb9b-4ba6fff80658-gptedge/DeviceUpdate/?api-version=2020-09-30&DeviceClientType=iothubclient%2f1.9.0%20(native%3b%20Linux%3b%20aarch64)>
Oct 02 05:59:02 raspberrypi4-64 AducIotAgent[335]: <- 05:57:45 CONNACK | SESSION_PRESENT: false | RETURN_CODE: 0x5
Oct 02 05:59:02 raspberrypi4-64 AducIotAgent[335]: 2024-10-02T05:57:45.4150Z 335[335] [D] IotHub connection status: 1, reason: 2 [IoTHub_CommunicationManager_ConnectionStatus_Callback]
Oct 02 05:59:02 raspberrypi4-64 AducIotAgent[335]: Error: Time:Wed Oct  2 05:57:45 2024 File:/usr/src/debug/azure-iot-sdk-c/1.0+gitAUTOINC+7329f70906-r0/git/iothub_client/src/iothubtransport_mqtt_common.c Func:mqttOperationCompleteCallback Line:2072 Connection Not Accepted: 0x5: Not Authorized
Oct 02 05:59:02 raspberrypi4-64 AducIotAgent[335]: -> 05:58:01 CONNECT | VER: 4 | KEEPALIVE: 240 | FLAGS: 192 | USERNAME: syscomiotedgehubtest.azure-devices.net/e6dc8d96-50a0-4eaf-bb9b-4ba6fff80658-gptedge/DeviceUpdate/?api-version=2020-09-30&DeviceClientType=iothubclient%2f1.9.0%20(native%3b%20Linux%3b%20aarch64)>
Oct 02 05:59:02 raspberrypi4-64 AducIotAgent[335]: <- 05:58:01 CONNACK | SESSION_PRESENT: false | RETURN_CODE: 0x5
Oct 02 05:59:02 raspberrypi4-64 AducIotAgent[335]: 2024-10-02T05:58:01.4152Z 335[335] [D] IotHub connection status: 1, reason: 2 [IoTHub_CommunicationManager_ConnectionStatus_Callback]
Oct 02 05:59:02 raspberrypi4-64 AducIotAgent[335]: Error: Time:Wed Oct  2 05:58:01 2024 File:/usr/src/debug/azure-iot-sdk-c/1.0+gitAUTOINC+7329f70906-r0/git/iothub_client/src/iothubtransport_mqtt_common.c Func:mqttOperationCompleteCallback Line:2072 Connection Not Accepted: 0x5: Not Authorized
Oct 02 05:59:02 raspberrypi4-64 AducIotAgent[335]: -> 05:58:32 CONNECT | VER: 4 | KEEPALIVE: 240 | FLAGS: 192 | USERNAME: syscomiotedgehubtest.azure-devices.net/e6dc8d96-50a0-4eaf-bb9b-4ba6fff80658-gptedge/DeviceUpdate/?api-version=2020-09-30&DeviceClientType=iothubclient%2f1.9.0%20(native%3b%20Linux%3b%20aarch64)>
Oct 02 05:59:02 raspberrypi4-64 AducIotAgent[335]: <- 05:58:32 CONNACK | SESSION_PRESENT: false | RETURN_CODE: 0x5
Oct 02 05:59:02 raspberrypi4-64 AducIotAgent[335]: 2024-10-02T05:58:32.4416Z 335[335] [D] IotHub connection status: 1, reason: 2 [IoTHub_CommunicationManager_ConnectionStatus_Callback]
Oct 02 05:59:02 raspberrypi4-64 AducIotAgent[335]: Error: Time:Wed Oct  2 05:58:32 2024 File:/usr/src/debug/azure-iot-sdk-c/1.0+gitAUTOINC+7329f70906-r0/git/iothub_client/src/iothubtransport_mqtt_common.c Func:mqttOperationCompleteCallback Line:2072 Connection Not Accepted: 0x5: Not Authorized
Oct 02 05:59:02 raspberrypi4-64 AducIotAgent[335]: -> 05:59:02 CONNECT | VER: 4 | KEEPALIVE: 240 | FLAGS: 192 | USERNAME: syscom2024-10-02T05:59:02.4834Z 335[335] [E] IoTHub connection is broken for 418419 seconds (will retry in 455 seconds) [IoTHub_CommunicationManager_ConnectionStatus_Callback]
Oct 02 05:59:32 raspberrypi4-64 AducIotAgent[335]: 2024-10-02T05:59:32.4069Z 335[335] [E] IoTHub connection is broken for 418449 seconds (will retry in 425 seconds) [IoTHub_CommunicationManager_ConnectionStatus_Callback]
Oct 02 06:00:02 raspberrypi4-64 AducIotAgent[335]: 2024-10-02T06:00:02.4371Z 335[335] [E] IoTHub connection is broken for 418479 seconds (will retry in 395 seconds) [IoTHub_CommunicationManager_ConnectionStatus_Callback]
Oct 02 06:00:32 raspberrypi4-64 AducIotAgent[335]: 2024-10-02T06:00:32.4771Z 335[335] [E] IoTHub connection is broken for 418509 seconds (will retry in 365 seconds) [IoTHub_CommunicationManager_ConnectionStatus_Callback]
Oct 02 06:01:02 raspberrypi4-64 AducIotAgent[335]: 2024-10-02T06:01:02.4203Z 335[335] [E] IoTHub connection is broken for 418539 seconds (will retry in 335 seconds) [IoTHub_CommunicationManager_ConnectionStatus_Callback]

Additional Information

I have rebooted the computer, restarted the deviceupdate-agent, with no change in behavior.

The deviceupdate-agent is setup as a "Module Identity" on the device in the IoT hub.

# cat /etc/aziot/identityd/config.d/adu.toml 
[[principal]]
uid = 800
name = "DeviceUpdate"

We have a parallel connection to the device in the IoT hub for our software, which is able to connect to the IoT hub without an problems.

FinitelyFailed commented 4 days ago

I'm still having this issue. It this repo abandoned? Should I look for answers elsewhere?

jw-msft commented 4 days ago

Seems like the version of azure-iot-sdk-c is 1.9 from the hash in the logs providerd, 7329f70906, which is not an LTS release.

The version of azure-iot-sdk for c supported by iot-hub-device-update ver 1.0.2 was the older LTS_07_2021_Ref01 as can be seen here: https://github.com/Azure/iot-hub-device-update/blob/2d1f03671d45be1e55b89c940514ffe91b3227e0/scripts/install-deps.sh#L46C15-L46C32

Was the DU agent installed from 1.2 debian package, or built from sources?

Anyways, this is error 0x5 Not Authorized coming back from iot-hub MQTT server in the CONACK MQTT packet, so whatever cred received from AIS and sent to the MQTT server is not considered authorized by iothub MQTT server

Is this use of AIS based on symmetric keys or x509.certs? If the former, something may be going on with the token generation in AIS, or a bug in the version of the iothub sdk.

This is troubleshooting issue with AIS and iot-hub-sdk-for-c, so you could get faster support opening an issue at https://github.com/Azure/azure-iot-sdk-c/issues and/or https://github.com/Azure/iot-identity-service

FinitelyFailed commented 3 days ago

Hi,

Thanks for your answer!

Seems like the version of azure-iot-sdk-c is 1.9 from the hash in the logs providerd, 7329f70906, which is not an LTS release.

The version of azure-iot-sdk for c supported by iot-hub-device-update ver 1.0.2 was the older LTS_07_2021_Ref01 as can be seen here: https://github.com/Azure/iot-hub-device-update/blob/2d1f03671d45be1e55b89c940514ffe91b3227e0/scripts/install-deps.sh#L46C15-L46C32

Was the DU agent installed from 1.2 debian package, or built from sources?

We build from source. As we build our own Linux based OS with the help of Yocto, we use recepices from https://github.com/GaiaSystem/meta-azure-device-update (which is a fork of https://github.com/Azure/meta-azure-device-update). We have OS:s based on Dunfell and Kirkstone at the moment, both seems to be running 1.0.2 of ADU. It seems that we use code from this repo from the commits:

Anyways, this is error 0x5 Not Authorized coming back from iot-hub MQTT server in the CONACK MQTT packet, so whatever cred received from AIS and sent to the MQTT server is not considered authorized by iothub MQTT server

Is this use of AIS based on symmetric keys or x509.certs? If the former, something may be going on with the token generation in AIS, or a bug in the version of the iothub sdk.

This is troubleshooting issue with AIS and iot-hub-sdk-for-c, so you could get faster support opening an issue at https://github.com/Azure/azure-iot-sdk-c/issues and/or https://github.com/Azure/iot-identity-service

We use symmetric keys. And we use AIS to get credentials to connect our own software to the IoT hub, which is seems to be very stable. I do not think that AIS is the problem.

The problem is that we do not know which version of ADU (in our case which commit) that should be used. I find it hard to find any info about LTS versions etc.

And what is bit worrying is that I can't get our device to work. The one which got the "error 0x5 Not Authorized" error. If I could clear some cache, restart something etc. etc. to get DU on device to work again I would feel a bit better, as we have a bunch of devices in production running the same version of DU.