Could not get identity $edgeAgent

dme-development commented 1 week ago

We noticed yesterday that our IoT devices could not download their modules anymore. It all started with the message: Unable to process module xxxxxx add or update as the module identity could not be obtained.

What we already did:

removed the device from the IoT Hub and had it provision again -> DPS provisioning seems to work fine, the device is recognized and gets added to the IoT Hub.
removed all modules (docker image prune -f -a) so that the edgeAgent would start downloading again -> This fails because now even the edgeAgent will not start anymore. The logs show: HTTP request failed: [401 Unauthorized] errorCode:401002, but how can this be happening while the device gets registered correctly?

IoT Edge version on the device is: 1.0.10 and 1.1.15, because we cannot upgrade remote to 1.4 or 1.5.

iotedged logs

``` Okt 09 09:45:50 S360N12011023C82HU iotedged[12003]: 2024-10-09T07:45:50Z [INFO] - Configuring certificates... Okt 09 09:45:50 S360N12011023C82HU iotedged[12003]: 2024-10-09T07:45:50Z [INFO] - Transparent gateway certificates not found, operating in quick start mode... Okt 09 09:45:50 S360N12011023C82HU iotedged[12003]: 2024-10-09T07:45:50Z [INFO] - Finished configuring provisioning environment variables and certificates. Okt 09 09:45:50 S360N12011023C82HU iotedged[12003]: 2024-10-09T07:45:50Z [INFO] - Initializing hsm... Okt 09 09:45:50 S360N12011023C82HU iotedged[12003]: 2024-10-09T07:45:50Z [INFO] - Finished initializing hsm. Okt 09 09:45:50 S360N12011023C82HU iotedged[12003]: 2024-10-09T07:45:50Z [INFO] - Initializing hsm X509 interface... Okt 09 09:45:50 S360N12011023C82HU iotedged[12003]: 2024-10-09T07:45:50Z [INFO] - Finished initializing hsm X509 interface... Okt 09 09:45:50 S360N12011023C82HU iotedged[12003]: 2024-10-09T07:45:50Z [INFO] - Provisioning edge device... Okt 09 09:45:50 S360N12011023C82HU iotedged[12003]: 2024-10-09T07:45:50Z [INFO] - Starting provisioning edge device via X509 provisioning... Okt 09 09:45:50 S360N12011023C82HU iotedged[12003]: 2024-10-09T07:45:50Z [INFO] - Starting DPS registration with scope_id "0ne00xxxxxx", registration_id "S360N12011023C82HU" Okt 09 09:46:01 S360N12011023C82HU iotedged[12003]: 2024-10-09T07:46:01Z [INFO] - DPS registration assigned device "S360N12011023C82HU" in hub "xxx.azure-devices.net" Okt 09 09:46:01 S360N12011023C82HU iotedged[12003]: 2024-10-09T07:46:01Z [INFO] - Successful DPS provisioning. Okt 09 09:46:01 S360N12011023C82HU iotedged[12003]: 2024-10-09T07:46:01Z [INFO] - Finished provisioning edge device. Okt 09 09:46:01 S360N12011023C82HU iotedged[12003]: 2024-10-09T07:46:01Z [INFO] - Initializing the module runtime... Okt 09 09:46:01 S360N12011023C82HU iotedged[12003]: 2024-10-09T07:46:01Z [INFO] - Initializing module runtime... Okt 09 09:46:01 S360N12011023C82HU iotedged[12003]: 2024-10-09T07:46:01Z [INFO] - Using runtime network id azure-iot-edge Okt 09 09:46:01 S360N12011023C82HU iotedged[12003]: 2024-10-09T07:46:01Z [INFO] - Successfully initialized module runtime Okt 09 09:46:01 S360N12011023C82HU iotedged[12003]: 2024-10-09T07:46:01Z [INFO] - Finished initializing the module runtime. Okt 09 09:46:01 S360N12011023C82HU iotedged[12003]: 2024-10-09T07:46:01Z [INFO] - Stopping all modules... Okt 09 09:46:01 S360N12011023C82HU iotedged[12003]: 2024-10-09T07:46:01Z [INFO] - Finished stopping modules. Okt 09 09:46:01 S360N12011023C82HU iotedged[12003]: 2024-10-09T07:46:01Z [INFO] - Reprovisioning status InitialAssignment will trigger reconfiguration of modules. Okt 09 09:46:01 S360N12011023C82HU iotedged[12003]: 2024-10-09T07:46:01Z [INFO] - Detecting if configuration file has changed... Okt 09 09:46:01 S360N12011023C82HU iotedged[12003]: 2024-10-09T07:46:01Z [INFO] - No change to configuration file detected. Okt 09 09:46:01 S360N12011023C82HU iotedged[12003]: 2024-10-09T07:46:01Z [INFO] - Edge issuer CA expiration date: 2041-03-14T06:54:01Z Okt 09 09:46:01 S360N12011023C82HU iotedged[12003]: 2024-10-09T07:46:01Z [INFO] - Obtaining workload CA succeeded. Okt 09 09:46:01 S360N12011023C82HU iotedged[12003]: 2024-10-09T07:46:01Z [INFO] - Starting management API... Okt 09 09:46:01 S360N12011023C82HU iotedged[12003]: 2024-10-09T07:46:01Z [INFO] - Starting workload API... Okt 09 09:46:01 S360N12011023C82HU iotedged[12003]: 2024-10-09T07:46:01Z [INFO] - Starting watchdog with 60 second frequency... Okt 09 09:46:01 S360N12011023C82HU iotedged[12003]: 2024-10-09T07:46:01Z [INFO] - Listening on fd://iotedge.mgmt.socket/ with 1 thread for management API. Okt 09 09:46:01 S360N12011023C82HU iotedged[12003]: 2024-10-09T07:46:01Z [INFO] - Listening on fd://iotedge.socket/ with 1 thread for workload API. Okt 09 09:46:01 S360N12011023C82HU iotedged[12003]: 2024-10-09T07:46:01Z [INFO] - Checking edge runtime status Okt 09 09:46:01 S360N12011023C82HU iotedged[12003]: 2024-10-09T07:46:01Z [INFO] - Creating and starting edge runtime module edgeAgent Okt 09 09:46:01 S360N12011023C82HU iotedged[12003]: 2024-10-09T07:46:01Z [WARN] - Error in watchdog when checking for edge runtime status: Okt 09 09:46:01 S360N12011023C82HU iotedged[12003]: 2024-10-09T07:46:01Z [WARN] - A module runtime error occurred. Okt 09 09:46:01 S360N12011023C82HU iotedged[12003]: 2024-10-09T07:46:01Z [WARN] - caused by: Could not get identity $edgeAgent Okt 09 09:46:01 S360N12011023C82HU iotedged[12003]: 2024-10-09T07:46:01Z [WARN] - caused by: Could not get module $edgeAgent Okt 09 09:46:01 S360N12011023C82HU iotedged[12003]: 2024-10-09T07:46:01Z [WARN] - caused by: HTTP request failed: [401 Unauthorized] {"Message":"{\"errorCode\":401002,\"message\":\"Unauthorized access\",\"trackingId\":\"9AF43B5BAC6B47C38DDE1AD6CF64AECB-G2:-TimeStamp:2024-10-09T07:46:01.963158726Z\",\"timestampUtc\":\"2024-10-09T07:46:01.963158726Z\",\"info\":null}","ExceptionMessage":""} ```

dperez83 commented 4 days ago

Hello @dme-development

I am having the same problem since yesterday. I just opened a support ticket on Azure and I advise you to do the same. I don't think this github will be able to provide a solution for us.

Module name is redacted.

iotedge logs edgeAgent

<6> 2024-10-16 11:24:01.378 -04:00 [INF] - Plan execution started for deployment 242
<6> 2024-10-16 11:24:01.378 -04:00 [INF] - Executing command: "Saving xxxx to store"
<6> 2024-10-16 11:24:01.378 -04:00 [INF] - Plan execution ended for deployment 242
<6> 2024-10-16 11:24:20.708 -04:00 [INF] - Unable to process module xxxx add or update as the module identity could not be obtained

iotedged

TimeCreated : 2024-10-16 10:51:52
Message     : info: edgelet_http::logging -- [mgmt] - - - [2024-10-16 14:51:52.807863200 UTC] "GET 
              /identities/?api-version=2020-07-07 HTTP/1.1" 500 Internal Server Error 468 "-" "-" auth_id(-)

TimeCreated : 2024-10-16 10:51:52
Message     : error: edgelet_http_mgmt::error -- Internal server error: Could not list identities
                caused by: Could not list identities
                caused by: Could not list modules
                caused by: HTTP request failed: [401 Unauthorized] 
              {"Message":"{\"errorCode\":401002,\"message\":\"Unauthorized access\",\"trackingId\":\"76CA4DD4C56F4B3C9A
              7C0FD4B234CFED-G2:-TimeStamp:2024-10-16T14:51:52.751062776Z\",\"timestampUtc\":\"2024-10-16T14:51:52.7510
              62776Z\",\"info\":null}","ExceptionMessage":""}

BTW how did you got iotedged logs in that format?

dme-development commented 4 days ago

Hi @dperez83 ,

I already have an open case with Microsoft, but since its 1.0 and 1.1, it's hard getting support. Now we know that multiple users are affected, we might be able to convince them looking into it. Do you mind sharing your case number, so I can pass it in mine as a reference?

Regarding the logs, we get them from journalctl: journalctl -u iotedge

Azure / iotedge

Could not get identity $edgeAgent #7380