search

Azure / iotedge-lorawan-starterkit

Sample implementation of LoRaWAN components to connect LoRaWAN antenna gateway running IoT Edge directly with Azure IoT.
https://azure.github.io/iotedge-lorawan-starterkit/2.2.1
Other
181 stars 60 forks source link

edgeHub: Error getting device scope result from IoTHub (IotHubUnauthorizedAccess) #2124

Open Metal-Mighty opened 3 months ago

Metal-Mighty commented 3 months ago

Expected Behavior

When the LNS receives payloads from IoT devices, the edgeHub connects to the IoT Hub and, from my understanding, updates metadata regarding the device that communicated with the LNS module.

Current Behavior

When the LNS receives a payload, the edgeHub tries to contact our IoT Hub to refresh the device's "service identity", but the query fails with a DeviceScopeApiException: 

<7> 2024-03-21 12:57:05.879 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.IDeviceScopeIdentitiesCache] - Getting service identity for <IoT Device name>
<6> 2024-03-21 12:57:05.879 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.DeviceScopeAuthenticator] - Unable to authenticate client <IoT Device name> with cached service identity <IoT Device name> (Found: False). Resyncing service identity...
<6> 2024-03-21 12:57:05.879 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.IDeviceScopeIdentitiesCache] - Refreshing service identity for <IoT Device name>
<7> 2024-03-21 12:57:06.159 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.DeviceScopeApiClient] - Error getting device scope result from the cloud
Microsoft.Azure.Devices.Edge.Hub.CloudProxy.DeviceScopeApiException: Message: Error getting device scope result from IoTHub, HttpStatusCode: Unauthorized, Content: {"Message":"ErrorCode:IotHubUnauthorizedAccess;Unauthorized","ExceptionMessage":"Tracking ID:a6aa55646e2b474cb07b2ac8153e7642-G:0-TimeStamp:03/21/2024 12:57:06"}
   at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.DeviceScopeApiClient.GetIdentitiesInScope(Uri uri) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/DeviceScopeApiClient.cs:line 137
   at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.DeviceScopeApiClient.GetIdentitiesInScopeWithRetry(Uri uri) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/DeviceScopeApiClient.cs:line 112
<7> 2024-03-21 12:57:06.160 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ServiceProxy] - Received scope result for <IoT Device name> with status code Unauthorized.
<4> 2024-03-21 12:57:06.160 +00:00 [WRN] [Microsoft.Azure.Devices.Edge.Hub.Core.IDeviceScopeIdentitiesCache] - Error while refreshing the service identity: <IoT Device name> OnBehalfOf: <IoT Edge name>
Microsoft.Azure.Devices.Edge.Hub.Core.DeviceInvalidStateException: Device not in scope: [Unauthorized: Message: Error getting device scope result from IoTHub, HttpStatusCode: Unauthorized, Content: {"Message":"ErrorCode:IotHubUnauthorizedAccess;Unauthorized","ExceptionMessage":"Tracking ID:a6aa55646e2b474cb07b2ac8153e7642-G:0-TimeStamp:03/21/2024 12:57:06"}].
 ---> Microsoft.Azure.Devices.Edge.Hub.CloudProxy.DeviceScopeApiException: Message: Error getting device scope result from IoTHub, HttpStatusCode: Unauthorized, Content: {"Message":"ErrorCode:IotHubUnauthorizedAccess;Unauthorized","ExceptionMessage":"Tracking ID:a6aa55646e2b474cb07b2ac8153e7642-G:0-TimeStamp:03/21/2024 12:57:06"}
   at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.DeviceScopeApiClient.GetIdentitiesInScope(Uri uri) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/DeviceScopeApiClient.cs:line 137
   at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.DeviceScopeApiClient.GetIdentitiesInScopeWithRetry(Uri uri) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/DeviceScopeApiClient.cs:line 112
   at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ServiceProxy.GetServiceIdentity(String deviceId, String onBehalfOfDevice) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/ServiceProxy.cs:line 101
   --- End of inner exception stack trace ---
   at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ServiceProxy.GetServiceIdentity(String deviceId, String onBehalfOfDevice) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/ServiceProxy.cs:line 101
   at Microsoft.Azure.Devices.Edge.Hub.Core.DeviceScopeIdentitiesCache.RefreshServiceIdentityInternal(String refreshTarget, String onBehalfOfDevice, Boolean invokeServiceIdentitiesUpdated) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/DeviceScopeIdentitiesCache.cs:line 201

This does not block our ability to receive payloads and handle them: The LNS is able to redirect the payload according to the IoT device's configuration set in its Azure IoT Hub Device Twin, so that means that the connection is properly authenticated somehow.

The Edge Device is authenticated with a symmetric key provided in /etc/aziot/config.toml

However since it spams the edgeHub logs, it makes it tough to troubleshoot other issues we are encountering and provide support to our end users.

Steps to Reproduce

  1. Deploy the edgeHub with an IoT Edge module connected to it and an Azure IoT Hub
  2. Declare your Edge Device and IoT Device in the IoT Hub, all devices are properly authenticated and receive data
  3. Receive a payload on the IoT Edge module

Context (Environment)

Device (Host) Operating System

Ubuntu 20.04

Architecture

amd64

Container Operating System

Linux containers

LoRaWAN Module Version

v2.2.2

Docker

v24.0.9-1

Logs

aziot-edged logs ``` [...] Mar 21 12:54:47 aziot-keyd[280702]: 2024-03-21T12:54:47Z [INFO] - <-- POST /key?api-version=2020-09-01 {"content-type": "application/json", "host": "keyd.sock", "content-length": "74"} Mar 21 12:54:47 aziot-keyd[280702]: 2024-03-21T12:54:47Z [INFO] - --> 200 {"content-type": "application/json"} Mar 21 12:54:47 aziot-keyd[280702]: 2024-03-21T12:54:47Z [INFO] - <-- POST /decrypt?api-version=2020-09-01 {"content-type": "application/json", "host": "keyd.sock", "content-length": "2159"} Mar 21 12:54:47 aziot-keyd[280702]: 2024-03-21T12:54:47Z [INFO] - --> 200 {"content-type": "application/json"} Mar 21 12:54:47 aziot-keyd[280702]: 2024-03-21T12:54:47Z [INFO] - <-- POST /key?api-version=2020-09-01 {"content-type": "application/json", "host": "keyd.sock", "content-length": "74"} Mar 21 12:54:47 aziot-keyd[280702]: 2024-03-21T12:54:47Z [INFO] - --> 200 {"content-type": "application/json"} Mar 21 12:54:47 aziot-keyd[280702]: 2024-03-21T12:54:47Z [INFO] - <-- POST /decrypt?api-version=2020-09-01 {"content-type": "application/json", "host": "keyd.sock", "content-length": "2159"} Mar 21 12:54:47 aziot-keyd[280702]: 2024-03-21T12:54:47Z [INFO] - --> 200 {"content-type": "application/json"} Mar 21 12:54:47 aziot-keyd[280702]: 2024-03-21T12:54:47Z [INFO] - <-- POST /key?api-version=2020-09-01 {"content-type": "application/json", "host": "keyd.sock", "content-length": "74"} Mar 21 12:54:47 aziot-keyd[280702]: 2024-03-21T12:54:47Z [INFO] - --> 200 {"content-type": "application/json"} Mar 21 12:54:47 aziot-keyd[280702]: 2024-03-21T12:54:47Z [INFO] - <-- POST /decrypt?api-version=2020-09-01 {"content-type": "application/json", "host": "keyd.sock", "content-length": "2159"} Mar 21 12:54:47 aziot-keyd[280702]: 2024-03-21T12:54:47Z [INFO] - --> 200 {"content-type": "application/json"} Mar 21 12:54:47 aziot-keyd[280702]: 2024-03-21T12:54:47Z [INFO] - <-- POST /key?api-version=2020-09-01 {"content-type": "application/json", "host": "keyd.sock", "content-length": "74"} Mar 21 12:54:47 aziot-keyd[280702]: 2024-03-21T12:54:47Z [INFO] - --> 200 {"content-type": "application/json"} Mar 21 12:54:47 aziot-keyd[280702]: 2024-03-21T12:54:47Z [INFO] - <-- POST /encrypt?api-version=2020-09-01 {"content-type": "application/json", "host": "keyd.sock", "content-length": "1798"} Mar 21 12:54:47 aziot-keyd[280702]: 2024-03-21T12:54:47Z [INFO] - --> 200 {"content-type": "application/json"} Mar 21 12:54:47 aziot-keyd[280702]: 2024-03-21T12:54:47Z [INFO] - <-- POST /key?api-version=2020-09-01 {"content-type": "application/json", "host": "keyd.sock", "content-length": "74"} Mar 21 12:54:47 aziot-keyd[280702]: 2024-03-21T12:54:47Z [INFO] - --> 200 {"content-type": "application/json"} Mar 21 12:54:47 aziot-keyd[280702]: 2024-03-21T12:54:47Z [INFO] - <-- POST /decrypt?api-version=2020-09-01 {"content-type": "application/json", "host": "keyd.sock", "content-length": "1823"} Mar 21 12:54:47 aziot-keyd[280702]: 2024-03-21T12:54:47Z [INFO] - --> 200 {"content-type": "application/json"} Mar 21 12:57:07 aziot-keyd[280702]: 2024-03-21T12:57:07Z [INFO] - <-- POST /key?api-version=2020-09-01 {"content-type": "application/json", "host": "keyd.sock", "content-length": "74"} Mar 21 12:57:07 aziot-keyd[280702]: 2024-03-21T12:57:07Z [INFO] - --> 200 {"content-type": "application/json"} Mar 21 12:57:07 aziot-keyd[280702]: 2024-03-21T12:57:07Z [INFO] - <-- POST /encrypt?api-version=2020-09-01 {"content-type": "application/json", "host": "keyd.sock", "content-length": "1090"} Mar 21 12:57:07 aziot-keyd[280702]: 2024-03-21T12:57:07Z [INFO] - --> 200 {"content-type": "application/json"} Mar 21 12:57:07 aziot-keyd[280702]: 2024-03-21T12:57:07Z [INFO] - <-- POST /key?api-version=2020-09-01 {"content-type": "application/json", "host": "keyd.sock", "content-length": "74"} Mar 21 12:57:07 aziot-keyd[280702]: 2024-03-21T12:57:07Z [INFO] - --> 200 {"content-type": "application/json"} Mar 21 12:57:07 aziot-keyd[280702]: 2024-03-21T12:57:07Z [INFO] - <-- POST /encrypt?api-version=2020-09-01 {"content-type": "application/json", "host": "keyd.sock", "content-length": "1034"} Mar 21 12:57:07 aziot-keyd[280702]: 2024-03-21T12:57:07Z [INFO] - --> 200 {"content-type": "application/json"} Mar 21 12:57:07 aziot-keyd[280702]: 2024-03-21T12:57:07Z [INFO] - <-- POST /key?api-version=2020-09-01 {"content-type": "application/json", "host": "keyd.sock", "content-length": "74"} Mar 21 12:57:07 aziot-keyd[280702]: 2024-03-21T12:57:07Z [INFO] - --> 200 {"content-type": "application/json"} Mar 21 12:57:07 aziot-keyd[280702]: 2024-03-21T12:57:07Z [INFO] - <-- POST /encrypt?api-version=2020-09-01 {"content-type": "application/json", "host": "keyd.sock", "content-length": "1026"} Mar 21 12:57:07 aziot-keyd[280702]: 2024-03-21T12:57:07Z [INFO] - --> 200 {"content-type": "application/json"} Mar 21 12:57:07 aziot-keyd[280702]: 2024-03-21T12:57:07Z [INFO] - <-- POST /key?api-version=2020-09-01 {"content-type": "application/json", "host": "keyd.sock", "content-length": "74"} Mar 21 12:57:07 aziot-keyd[280702]: 2024-03-21T12:57:07Z [INFO] - --> 200 {"content-type": "application/json"} Mar 21 12:57:07 aziot-keyd[280702]: 2024-03-21T12:57:07Z [INFO] - <-- POST /encrypt?api-version=2020-09-01 {"content-type": "application/json", "host": "keyd.sock", "content-length": "1042"} Mar 21 12:57:07 aziot-keyd[280702]: 2024-03-21T12:57:07Z [INFO] - --> 200 {"content-type": "application/json"} Mar 21 12:57:07 aziot-keyd[280702]: 2024-03-21T12:57:07Z [INFO] - <-- POST /key?api-version=2020-09-01 {"content-type": "application/json", "host": "keyd.sock", "content-length": "74"} Mar 21 12:57:07 aziot-keyd[280702]: 2024-03-21T12:57:07Z [INFO] - --> 200 {"content-type": "application/json"} Mar 21 12:57:07 aziot-keyd[280702]: 2024-03-21T12:57:07Z [INFO] - <-- POST /encrypt?api-version=2020-09-01 {"content-type": "application/json", "host": "keyd.sock", "content-length": "1050"} Mar 21 12:57:07 aziot-keyd[280702]: 2024-03-21T12:57:07Z [INFO] - --> 200 {"content-type": "application/json"} Mar 21 12:57:07 aziot-keyd[280702]: 2024-03-21T12:57:07Z [INFO] - <-- POST /key?api-version=2020-09-01 {"content-type": "application/json", "host": "keyd.sock", "content-length": "74"} Mar 21 12:57:07 aziot-keyd[280702]: 2024-03-21T12:57:07Z [INFO] - --> 200 {"content-type": "application/json"} Mar 21 12:57:07 aziot-keyd[280702]: 2024-03-21T12:57:07Z [INFO] - <-- POST /encrypt?api-version=2020-09-01 {"content-type": "application/json", "host": "keyd.sock", "content-length": "1050"} Mar 21 12:57:07 aziot-keyd[280702]: 2024-03-21T12:57:07Z [INFO] - --> 200 {"content-type": "application/json"} Mar 21 12:57:07 aziot-keyd[280702]: 2024-03-21T12:57:07Z [INFO] - <-- POST /key?api-version=2020-09-01 {"content-type": "application/json", "host": "keyd.sock", "content-length": "74"} Mar 21 12:57:07 aziot-keyd[280702]: 2024-03-21T12:57:07Z [INFO] - --> 200 {"content-type": "application/json"} Mar 21 12:57:07 aziot-keyd[280702]: 2024-03-21T12:57:07Z [INFO] - <-- POST /encrypt?api-version=2020-09-01 {"content-type": "application/json", "host": "keyd.sock", "content-length": "1054"} Mar 21 12:57:07 aziot-keyd[280702]: 2024-03-21T12:57:07Z [INFO] - --> 200 {"content-type": "application/json"} Mar 21 12:57:07 aziot-keyd[280702]: 2024-03-21T12:57:07Z [INFO] - <-- POST /key?api-version=2020-09-01 {"content-type": "application/json", "host": "keyd.sock", "content-length": "74"} Mar 21 12:57:07 aziot-keyd[280702]: 2024-03-21T12:57:07Z [INFO] - --> 200 {"content-type": "application/json"} Mar 21 12:57:07 aziot-keyd[280702]: 2024-03-21T12:57:07Z [INFO] - <-- POST /encrypt?api-version=2020-09-01 {"content-type": "application/json", "host": "keyd.sock", "content-length": "1058"} Mar 21 12:57:07 aziot-keyd[280702]: 2024-03-21T12:57:07Z [INFO] - --> 200 {"content-type": "application/json"} Mar 21 12:57:07 aziot-keyd[280702]: 2024-03-21T12:57:07Z [INFO] - <-- POST /key?api-version=2020-09-01 {"content-type": "application/json", "host": "keyd.sock", "content-length": "74"} Mar 21 12:57:07 aziot-keyd[280702]: 2024-03-21T12:57:07Z [INFO] - --> 200 {"content-type": "application/json"} Mar 21 12:57:07 aziot-keyd[280702]: 2024-03-21T12:57:07Z [INFO] - <-- POST /encrypt?api-version=2020-09-01 {"content-type": "application/json", "host": "keyd.sock", "content-length": "1026"} Mar 21 12:57:07 aziot-keyd[280702]: 2024-03-21T12:57:07Z [INFO] - --> 200 {"content-type": "application/json"} ```

Abstract of the edgeAgent container on startup until it starts the modules from our deployment manifest hosted on the Azure IoT Hub. Some repetitive parts and names have been redacted.

edge-agent logs ``` 2024-03-21 10:10:31 Starting Edge Agent 2024-03-21 10:10:31 Creating UID 13622 as edgeagentuser 2024-03-21 10:10:31 Creating storage folder: /tmp/edgeAgent 2024-03-21 10:10:31 Creating backup folder: /tmp/edgeAgent_backup 2024-03-21 10:10:31 Changing ownership of management socket: /var/run/iotedge/mgmt.sock 2024-03-21 10:10:31 Completed necessary setup. Starting Edge Agent. 2024-03-21 10:10:31.546 +00:00 Edge Agent Main() <6> 2024-03-21 10:10:31.852 +00:00 [INF] - Initializing Edge Agent. <6> 2024-03-21 10:10:32.101 +00:00 [INF] - Version - 1.4.33.89334537 (71f4974213cfab7447117af13a30319ba2c40357) <6> 2024-03-21 10:10:32.102 +00:00 [INF] - █████╗ ███████╗██╗ ██╗██████╗ ███████╗ ██╔══██╗╚══███╔╝██║ ██║██╔══██╗██╔════╝ ███████║ ███╔╝ ██║ ██║██████╔╝█████╗ ██╔══██║ ███╔╝ ██║ ██║██╔══██╗██╔══╝ ██║ ██║███████╗╚██████╔╝██║ ██║███████╗ ╚═╝ ╚═╝╚══════╝ ╚═════╝ ╚═╝ ╚═╝╚══════╝ ██╗ ██████╗ ████████╗ ███████╗██████╗ ██████╗ ███████╗ ██║██╔═══██╗╚══██╔══╝ ██╔════╝██╔══██╗██╔════╝ ██╔════╝ ██║██║ ██║ ██║ █████╗ ██║ ██║██║ ███╗█████╗ ██║██║ ██║ ██║ ██╔══╝ ██║ ██║██║ ██║██╔══╝ ██║╚██████╔╝ ██║ ███████╗██████╔╝╚██████╔╝███████╗ ╚═╝ ╚═════╝ ╚═╝ ╚══════╝╚═════╝ ╚═════╝ ╚══════╝ <6> 2024-03-21 10:10:32.107 +00:00 [INF] - ModuleUpdateMode: NonBlocking <6> 2024-03-21 10:10:32.214 +00:00 [INF] - Experimental features configuration: {"Enabled":false,"DisableCloudSubscriptions":false} <6> 2024-03-21 10:10:32.481 +00:00 [INF] - Installing certificates [CN=aziot-edge CA :05/27/2024 19:33:36] to Root <6> 2024-03-21 10:10:32.775 +00:00 [INF] - Starting metrics listener on Host: *, Port: 9600, Suffix: metrics <6> 2024-03-21 10:10:32.809 +00:00 [INF] - Updating performance metrics every 05m:00s <6> 2024-03-21 10:10:32.819 +00:00 [INF] - Started operation Get system resources <6> 2024-03-21 10:10:32.822 +00:00 [INF] - Collecting metadata metrics <6> 2024-03-21 10:10:32.942 +00:00 [INF] - Set metadata metrics: 1.4.33.89334537 (71f4974213cfab7447117af13a30319ba2c40357), {"Enabled":false,"DisableCloudSubscriptions":false}, {"OperatingSystemType":"Linux","Architecture":"x86_64","Version":"1.4.33","Provisioning":{"Type":"ProvisioningType","DynamicReprovisioning":false,"AlwaysReprovisionOnStartup":false},"ServerVersion":"24.0.9-1","KernelVersion":"#191-Ubuntu SMP Fri Feb 2 13:55:07 UTC 2024","OperatingSystem":"ubuntu","NumCpus":4,"TotalMemory":6216835072,"Virtualized":"yes"}, True <6> 2024-03-21 10:10:32.972 +00:00 [INF] - Started operation Checkpoint Availability <6> 2024-03-21 10:10:32.977 +00:00 [INF] - Started operation refresh twin config <6> 2024-03-21 10:10:33.003 +00:00 [INF] - Edge agent attempting to connect to IoT Hub via Amqp_WebSocket_Only... <6> 2024-03-21 10:10:33.520 +00:00 [INF] - Created persistent store at /tmp/edgeAgent <6> 2024-03-21 10:10:33.620 +00:00 [INF] - Started operation Metrics Scrape <6> 2024-03-21 10:10:33.621 +00:00 [INF] - Started operation Metrics Upload Scraping frequency: 01:00:00 Upload Frequency: 1.00:00:00 <6> 2024-03-21 10:10:34.548 +00:00 [INF] - Registering request handler UploadModuleLogs <6> 2024-03-21 10:10:34.549 +00:00 [INF] - Registering request handler GetModuleLogs <6> 2024-03-21 10:10:34.549 +00:00 [INF] - Registering request handler UploadSupportBundle <6> 2024-03-21 10:10:34.549 +00:00 [INF] - Registering request handler RestartModule <6> 2024-03-21 10:10:35.032 +00:00 [INF] - Edge agent connected to IoT Hub via Amqp_WebSocket_Only. <6> 2024-03-21 10:10:35.200 +00:00 [INF] - Initialized new module client with subscriptions enabled <6> 2024-03-21 10:10:35.302 +00:00 [INF] - Obtained Edge agent twin from IoTHub with desired properties version 94 and reported properties version 540. <6> 2024-03-21 10:10:39.544 +00:00 [INF] - Plan execution started for deployment 94 <6> 2024-03-21 10:10:39.549 +00:00 [INF] - Executing command: "[Null]" [...] <6> 2024-03-21 10:10:39.556 +00:00 [INF] - Executing command: "Stop module " [...] <6> 2024-03-21 10:10:55.592 +00:00 [INF] - Executing command: "Remove module " [...] <6> 2024-03-21 10:10:56.243 +00:00 [INF] - Executing command: "Saving to store" [...] <6> 2024-03-21 10:10:56.276 +00:00 [INF] - Executing command: "Command Group: (\n [Command Group: (\n [Prepare module ]\n [Command Group: (\n [Stop module ]\n [Update module ]\n)]\n)]\n [Start module ]\n)" [...] <6> 2024-03-21 12:42:00.569 +00:00 [INF] - Initiating streaming logs for edgeAgent <6> 2024-03-21 12:42:00.849 +00:00 [INF] - Received 514 bytes of logs for edgeAgent <6> 2024-03-21 12:42:00.856 +00:00 [INF] - Successfully handled request GetModuleLogs <6> 2024-03-21 12:42:04.063 +00:00 [INF] - Received direct method call - GetModuleLogs <6> 2024-03-21 12:42:04.063 +00:00 [INF] - Received request GetModuleLogs with payload <6> 2024-03-21 12:42:04.064 +00:00 [INF] - Processing request to get logs for {"schemaVersion":"1.0","items":{"id":"\\bLoRaWanNetworkSrvModule\\b","filter":{"tail":1500,"since":"15m","until":null,"loglevel":null,"regex":""}},"encoding":1,"contentType":1} <6> 2024-03-21 12:42:04.092 +00:00 [INF] - Initiating streaming logs for LoRaWanNetworkSrvModule <6> 2024-03-21 12:42:04.105 +00:00 [INF] - Received 1644 bytes of logs for LoRaWanNetworkSrvModule <6> 2024-03-21 12:42:04.105 +00:00 [INF] - Successfully handled request GetModuleLogs <6> 2024-03-21 12:42:25.793 +00:00 [INF] - Received direct method call - GetModuleLogs <6> 2024-03-21 12:42:25.793 +00:00 [INF] - Received request GetModuleLogs with payload <6> 2024-03-21 12:42:25.793 +00:00 [INF] - Processing request to get logs for {"schemaVersion":"1.0","items":{"id":"\\bLoRaWanNetworkSrvModule\\b","filter":{"tail":1500,"since":"15m","until":null,"loglevel":null,"regex":""}},"encoding":1,"contentType":1} <6> 2024-03-21 12:42:25.822 +00:00 [INF] - Initiating streaming logs for LoRaWanNetworkSrvModule <6> 2024-03-21 12:42:25.834 +00:00 [INF] - Received 339 bytes of logs for LoRaWanNetworkSrvModule <6> 2024-03-21 12:42:25.835 +00:00 [INF] - Successfully handled request GetModuleLogs <6> 2024-03-21 12:42:28.345 +00:00 [INF] - Received direct method call - GetModuleLogs <6> 2024-03-21 12:42:28.345 +00:00 [INF] - Received request GetModuleLogs with payload <6> 2024-03-21 12:42:28.346 +00:00 [INF] - Processing request to get logs for {"schemaVersion":"1.0","items":{"id":"\\bLoRaWanNetworkSrvModule\\b","filter":{"tail":1500,"since":"60m","until":null,"loglevel":null,"regex":""}},"encoding":1,"contentType":1} [...] ```

Abstract of the edgeHub logs before to after the error in debug mode. Some repetitive lines have been removed to fit in Github's comment size limit.

edge-hub logs ``` <6> 2024-03-21 12:57:05.877 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionReauthenticator] - Entering periodic task to reauthenticate connected clients <7> 2024-03-21 12:57:05.878 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.IDeviceScopeIdentitiesCache] - Getting service identity for /LoRaWanNetworkSrvModule <7> 2024-03-21 12:57:05.878 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.DeviceScopeAuthenticator] - Client /LoRaWanNetworkSrvModule in device scope reauthenticated locally. <7> 2024-03-21 12:57:05.878 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Authenticator] - Client /LoRaWanNetworkSrvModule re-authentication successful <7> 2024-03-21 12:57:05.878 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionReauthenticator] - Reauthenticated client /LoRaWanNetworkSrvModule successfully <7> 2024-03-21 12:57:05.878 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.IDeviceScopeIdentitiesCache] - Getting service identity for / <7> 2024-03-21 12:57:05.878 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.DeviceScopeAuthenticator] - Client / in device scope reauthenticated locally. <7> 2024-03-21 12:57:05.878 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Authenticator] - Client / re-authentication successful <7> 2024-03-21 12:57:05.879 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionReauthenticator] - Reauthenticated client / successfully <7> 2024-03-21 12:57:05.879 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.IDeviceScopeIdentitiesCache] - Getting service identity for <6> 2024-03-21 12:57:05.879 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.DeviceScopeAuthenticator] - Unable to authenticate client with cached service identity (Found: False). Resyncing service identity... <6> 2024-03-21 12:57:05.879 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.IDeviceScopeIdentitiesCache] - Refreshing service identity for <7> 2024-03-21 12:57:06.159 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.DeviceScopeApiClient] - Error getting device scope result from the cloud Microsoft.Azure.Devices.Edge.Hub.CloudProxy.DeviceScopeApiException: Message: Error getting device scope result from IoTHub, HttpStatusCode: Unauthorized, Content: {"Message":"ErrorCode:IotHubUnauthorizedAccess;Unauthorized","ExceptionMessage":"Tracking ID:a6aa55646e2b474cb07b2ac8153e7642-G:0-TimeStamp:03/21/2024 12:57:06"} at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.DeviceScopeApiClient.GetIdentitiesInScope(Uri uri) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/DeviceScopeApiClient.cs:line 137 at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.DeviceScopeApiClient.GetIdentitiesInScopeWithRetry(Uri uri) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/DeviceScopeApiClient.cs:line 112 <7> 2024-03-21 12:57:06.160 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ServiceProxy] - Received scope result for with status code Unauthorized. <4> 2024-03-21 12:57:06.160 +00:00 [WRN] [Microsoft.Azure.Devices.Edge.Hub.Core.IDeviceScopeIdentitiesCache] - Error while refreshing the service identity: OnBehalfOf: Microsoft.Azure.Devices.Edge.Hub.Core.DeviceInvalidStateException: Device not in scope: [Unauthorized: Message: Error getting device scope result from IoTHub, HttpStatusCode: Unauthorized, Content: {"Message":"ErrorCode:IotHubUnauthorizedAccess;Unauthorized","ExceptionMessage":"Tracking ID:a6aa55646e2b474cb07b2ac8153e7642-G:0-TimeStamp:03/21/2024 12:57:06"}]. ---> Microsoft.Azure.Devices.Edge.Hub.CloudProxy.DeviceScopeApiException: Message: Error getting device scope result from IoTHub, HttpStatusCode: Unauthorized, Content: {"Message":"ErrorCode:IotHubUnauthorizedAccess;Unauthorized","ExceptionMessage":"Tracking ID:a6aa55646e2b474cb07b2ac8153e7642-G:0-TimeStamp:03/21/2024 12:57:06"} at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.DeviceScopeApiClient.GetIdentitiesInScope(Uri uri) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/DeviceScopeApiClient.cs:line 137 at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.DeviceScopeApiClient.GetIdentitiesInScopeWithRetry(Uri uri) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/DeviceScopeApiClient.cs:line 112 at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ServiceProxy.GetServiceIdentity(String deviceId, String onBehalfOfDevice) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/ServiceProxy.cs:line 101 --- End of inner exception stack trace --- at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ServiceProxy.GetServiceIdentity(String deviceId, String onBehalfOfDevice) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/ServiceProxy.cs:line 101 at Microsoft.Azure.Devices.Edge.Hub.Core.DeviceScopeIdentitiesCache.RefreshServiceIdentityInternal(String refreshTarget, String onBehalfOfDevice, Boolean invokeServiceIdentitiesUpdated) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/DeviceScopeIdentitiesCache.cs:line 201 <7> 2024-03-21 12:57:06.161 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.IDeviceScopeIdentitiesCache] - is not in device scope, removing from cache. <7> 2024-03-21 12:57:06.161 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.IDeviceScopeIdentitiesCache] - Getting service identity for <7> 2024-03-21 12:57:06.161 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.IDeviceScopeIdentitiesCache] - Received request to refresh cache. <6> 2024-03-21 12:57:06.162 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.IDeviceScopeIdentitiesCache] - Device scope identities refresh is ready because a refresh was signalled. <6> 2024-03-21 12:57:06.162 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.IDeviceScopeIdentitiesCache] - Starting refresh of device scope identities cache <7> 2024-03-21 12:57:06.162 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ServiceProxy] - Created iterator to iterate all service identities in the scope of this IoT Edge device <7> 2024-03-21 12:57:07.652 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint //input1_Pri9 starting from 11 with batch size 10. <7> 2024-03-21 12:57:07.652 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint //input1_Pri9 with batch size 0. Next start offset = 11. <7> 2024-03-21 12:57:07.737 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.DeviceScopeApiClient] - Got valid device scope result <7> 2024-03-21 12:57:07.737 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ServiceProxy] - Received scope result with 1 devices, 15 modules and null continuation link <7> 2024-03-21 12:57:07.737 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.IDeviceScopeIdentitiesCache] - is in device scope, adding to cache. <7> 2024-03-21 12:57:07.738 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Edged.WorkloadClient] - Making a Http call to unix:///var/run/iotedge/workload.sock to Encrypt <7> 2024-03-21 12:57:07.738 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Connecting socket /var/run/iotedge/workload.sock <7> 2024-03-21 12:57:07.738 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Connected socket /var/run/iotedge/workload.sock <7> 2024-03-21 12:57:07.738 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Sending request http://workload.sock/modules/%24edgeHub/genid/638090505311001746/encrypt?api-version=2020-07-07 <7> 2024-03-21 12:57:07.769 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Response received OK <7> 2024-03-21 12:57:07.769 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Edged.WorkloadClient] - Received a valid Http response from unix:///var/run/iotedge/workload.sock for Encrypt <6> 2024-03-21 12:57:07.769 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionReauthenticator] - Service identity for in device scope was updated. <7> 2024-03-21 12:57:07.769 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionReauthenticator] - Service identity for in device scope was updated, but is not connected to EdgeHub <7> 2024-03-21 12:57:07.769 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.IDeviceScopeIdentitiesCache] - /$edgeAgent is in device scope, adding to cache. <7> 2024-03-21 12:57:07.769 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Edged.WorkloadClient] - Making a Http call to unix:///var/run/iotedge/workload.sock to Encrypt <7> 2024-03-21 12:57:07.769 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Connecting socket /var/run/iotedge/workload.sock <7> 2024-03-21 12:57:07.770 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Connected socket /var/run/iotedge/workload.sock <7> 2024-03-21 12:57:07.770 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Sending request http://workload.sock/modules/%24edgeHub/genid/638090505311001746/encrypt?api-version=2020-07-07 <7> 2024-03-21 12:57:07.794 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Response received OK <7> 2024-03-21 12:57:07.794 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Edged.WorkloadClient] - Received a valid Http response from unix:///var/run/iotedge/workload.sock for Encrypt <6> 2024-03-21 12:57:07.794 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionReauthenticator] - Service identity for /$edgeAgent in device scope was updated. <7> 2024-03-21 12:57:07.794 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionReauthenticator] - Service identity for /$edgeAgent in device scope was updated, but /$edgeAgent is not connected to EdgeHub <7> 2024-03-21 12:57:07.794 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.IDeviceScopeIdentitiesCache] - /$edgeHub is in device scope, adding to cache. <7> 2024-03-21 12:57:07.795 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Edged.WorkloadClient] - Making a Http call to unix:///var/run/iotedge/workload.sock to Encrypt <7> 2024-03-21 12:57:07.795 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Connecting socket /var/run/iotedge/workload.sock <7> 2024-03-21 12:57:07.795 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Connected socket /var/run/iotedge/workload.sock <7> 2024-03-21 12:57:07.795 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Sending request http://workload.sock/modules/%24edgeHub/genid/638090505311001746/encrypt?api-version=2020-07-07 <7> 2024-03-21 12:57:07.819 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Response received OK <7> 2024-03-21 12:57:07.820 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Edged.WorkloadClient] - Received a valid Http response from unix:///var/run/iotedge/workload.sock for Encrypt <6> 2024-03-21 12:57:07.820 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionReauthenticator] - Service identity for /$edgeHub in device scope was updated. <7> 2024-03-21 12:57:07.820 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.IDeviceScopeIdentitiesCache] - / is in device scope, adding to cache. <7> 2024-03-21 12:57:07.820 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Edged.WorkloadClient] - Making a Http call to unix:///var/run/iotedge/workload.sock to Encrypt <7> 2024-03-21 12:57:07.820 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Connecting socket /var/run/iotedge/workload.sock <7> 2024-03-21 12:57:07.820 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Connected socket /var/run/iotedge/workload.sock <7> 2024-03-21 12:57:07.820 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Sending request http://workload.sock/modules/%24edgeHub/genid/638090505311001746/encrypt?api-version=2020-07-07 <7> 2024-03-21 12:57:07.848 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Response received OK <7> 2024-03-21 12:57:07.848 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Edged.WorkloadClient] - Received a valid Http response from unix:///var/run/iotedge/workload.sock for Encrypt <6> 2024-03-21 12:57:07.849 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionReauthenticator] - Service identity for / in device scope was updated. <7> 2024-03-21 12:57:07.849 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionReauthenticator] - Service identity for / in device scope was updated, but / is not connected to EdgeHub <7> 2024-03-21 12:57:07.849 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.IDeviceScopeIdentitiesCache] - / is in device scope, adding to cache. <7> 2024-03-21 12:57:07.849 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Edged.WorkloadClient] - Making a Http call to unix:///var/run/iotedge/workload.sock to Encrypt <7> 2024-03-21 12:57:07.849 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Connecting socket /var/run/iotedge/workload.sock <7> 2024-03-21 12:57:07.850 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Connected socket /var/run/iotedge/workload.sock <7> 2024-03-21 12:57:07.850 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Sending request http://workload.sock/modules/%24edgeHub/genid/638090505311001746/encrypt?api-version=2020-07-07 <7> 2024-03-21 12:57:07.878 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Response received OK <7> 2024-03-21 12:57:07.878 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Edged.WorkloadClient] - Received a valid Http response from unix:///var/run/iotedge/workload.sock for Encrypt <6> 2024-03-21 12:57:07.879 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionReauthenticator] - Service identity for / in device scope was updated. <7> 2024-03-21 12:57:07.879 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.IDeviceScopeIdentitiesCache] - Getting service identity for / <7> 2024-03-21 12:57:07.879 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.DeviceScopeAuthenticator] - Client / in device scope reauthenticated locally. <7> 2024-03-21 12:57:07.879 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Authenticator] - Client / re-authentication successful <7> 2024-03-21 12:57:07.879 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionReauthenticator] - Service identity for / in device scope was updated, client connection was re-validated. <7> 2024-03-21 12:57:07.879 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.IDeviceScopeIdentitiesCache] - / is in device scope, adding to cache. <7> 2024-03-21 12:57:07.879 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Edged.WorkloadClient] - Making a Http call to unix:///var/run/iotedge/workload.sock to Encrypt <7> 2024-03-21 12:57:07.879 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Connecting socket /var/run/iotedge/workload.sock <7> 2024-03-21 12:57:07.879 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Connected socket /var/run/iotedge/workload.sock <7> 2024-03-21 12:57:07.879 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Sending request http://workload.sock/modules/%24edgeHub/genid/638090505311001746/encrypt?api-version=2020-07-07 <7> 2024-03-21 12:57:07.905 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Response received OK <7> 2024-03-21 12:57:07.905 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Edged.WorkloadClient] - Received a valid Http response from unix:///var/run/iotedge/workload.sock for Encrypt <6> 2024-03-21 12:57:07.905 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionReauthenticator] - Service identity for / in device scope was updated. <7> 2024-03-21 12:57:07.905 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionReauthenticator] - Service identity for / in device scope was updated, but / is not connected to EdgeHub <7> 2024-03-21 12:57:07.905 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.IDeviceScopeIdentitiesCache] - / is in device scope, adding to cache. <7> 2024-03-21 12:57:07.905 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Edged.WorkloadClient] - Making a Http call to unix:///var/run/iotedge/workload.sock to Encrypt <7> 2024-03-21 12:57:07.906 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Connecting socket /var/run/iotedge/workload.sock <7> 2024-03-21 12:57:07.906 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Connected socket /var/run/iotedge/workload.sock <7> 2024-03-21 12:57:07.906 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Sending request http://workload.sock/modules/%24edgeHub/genid/638090505311001746/encrypt?api-version=2020-07-07 <7> 2024-03-21 12:57:07.929 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Response received OK <7> 2024-03-21 12:57:07.930 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Edged.WorkloadClient] - Received a valid Http response from unix:///var/run/iotedge/workload.sock for Encrypt <6> 2024-03-21 12:57:07.930 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionReauthenticator] - Service identity for / in device scope was updated. <7> 2024-03-21 12:57:07.930 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionReauthenticator] - Service identity for / in device scope was updated, but / is not connected to EdgeHub <7> 2024-03-21 12:57:07.987 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.IDeviceScopeIdentitiesCache] - /LoRaWanNetworkSrvModule is in device scope, adding to cache. <7> 2024-03-21 12:57:07.987 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Edged.WorkloadClient] - Making a Http call to unix:///var/run/iotedge/workload.sock to Encrypt <7> 2024-03-21 12:57:07.987 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Connecting socket /var/run/iotedge/workload.sock <7> 2024-03-21 12:57:07.987 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Connected socket /var/run/iotedge/workload.sock <7> 2024-03-21 12:57:07.987 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Sending request http://workload.sock/modules/%24edgeHub/genid/638090505311001746/encrypt?api-version=2020-07-07 <7> 2024-03-21 12:57:08.014 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Response received OK <7> 2024-03-21 12:57:08.014 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Edged.WorkloadClient] - Received a valid Http response from unix:///var/run/iotedge/workload.sock for Encrypt <6> 2024-03-21 12:57:08.014 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionReauthenticator] - Service identity for /LoRaWanNetworkSrvModule in device scope was updated. <7> 2024-03-21 12:57:08.014 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.IDeviceScopeIdentitiesCache] - Getting service identity for /LoRaWanNetworkSrvModule <7> 2024-03-21 12:57:08.014 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.DeviceScopeAuthenticator] - Client /LoRaWanNetworkSrvModule in device scope reauthenticated locally. <7> 2024-03-21 12:57:08.014 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Authenticator] - Client /LoRaWanNetworkSrvModule re-authentication successful <7> 2024-03-21 12:57:08.014 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionReauthenticator] - Service identity for /LoRaWanNetworkSrvModule in device scope was updated, client connection was re-validated. <7> 2024-03-21 12:57:08.014 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.IDeviceScopeIdentitiesCache] - / is in device scope, adding to cache. <7> 2024-03-21 12:57:08.015 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Edged.WorkloadClient] - Making a Http call to unix:///var/run/iotedge/workload.sock to Encrypt <7> 2024-03-21 12:57:08.015 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Connecting socket /var/run/iotedge/workload.sock <7> 2024-03-21 12:57:08.015 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Connected socket /var/run/iotedge/workload.sock <7> 2024-03-21 12:57:08.015 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Sending request http://workload.sock/modules/%24edgeHub/genid/638090505311001746/encrypt?api-version=2020-07-07 <7> 2024-03-21 12:57:08.044 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Response received OK <7> 2024-03-21 12:57:08.044 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Edged.WorkloadClient] - Received a valid Http response from unix:///var/run/iotedge/workload.sock for Encrypt <6> 2024-03-21 12:57:08.044 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionReauthenticator] - Service identity for / in device scope was updated. <7> 2024-03-21 12:57:08.044 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionReauthenticator] - Service identity for / in device scope was updated, but / is not connected to EdgeHub <7> 2024-03-21 12:57:08.044 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.IDeviceScopeIdentitiesCache] - / is in device scope, adding to cache. <7> 2024-03-21 12:57:08.044 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Edged.WorkloadClient] - Making a Http call to unix:///var/run/iotedge/workload.sock to Encrypt <7> 2024-03-21 12:57:08.044 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Connecting socket /var/run/iotedge/workload.sock <7> 2024-03-21 12:57:08.044 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Connected socket /var/run/iotedge/workload.sock <7> 2024-03-21 12:57:08.044 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Sending request http://workload.sock/modules/%24edgeHub/genid/638090505311001746/encrypt?api-version=2020-07-07 <7> 2024-03-21 12:57:08.073 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Response received OK <7> 2024-03-21 12:57:08.073 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Edged.WorkloadClient] - Received a valid Http response from unix:///var/run/iotedge/workload.sock for Encrypt <6> 2024-03-21 12:57:08.074 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionReauthenticator] - Service identity for / in device scope was updated. <7> 2024-03-21 12:57:08.074 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionReauthenticator] - Service identity for / in device scope was updated, but / is not connected to EdgeHub <7> 2024-03-21 12:57:08.074 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.IDeviceScopeIdentitiesCache] - /DefenderIotMicroAgent is in device scope, adding to cache. <7> 2024-03-21 12:57:08.074 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Edged.WorkloadClient] - Making a Http call to unix:///var/run/iotedge/workload.sock to Encrypt <7> 2024-03-21 12:57:08.074 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Connecting socket /var/run/iotedge/workload.sock <7> 2024-03-21 12:57:08.074 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Connected socket /var/run/iotedge/workload.sock <7> 2024-03-21 12:57:08.074 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Sending request http://workload.sock/modules/%24edgeHub/genid/638090505311001746/encrypt?api-version=2020-07-07 <7> 2024-03-21 12:57:08.101 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Response received OK <7> 2024-03-21 12:57:08.101 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Edged.WorkloadClient] - Received a valid Http response from unix:///var/run/iotedge/workload.sock for Encrypt <6> 2024-03-21 12:57:08.101 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionReauthenticator] - Service identity for /DefenderIotMicroAgent in device scope was updated. <7> 2024-03-21 12:57:08.101 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionReauthenticator] - Service identity for /DefenderIotMicroAgent in device scope was updated, but /DefenderIotMicroAgent is not connected to EdgeHub <6> 2024-03-21 12:57:08.194 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.IDeviceScopeIdentitiesCache] - Done refreshing device scope identities cache. Waiting for 60 minutes. <7> 2024-03-21 12:57:08.194 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.IDeviceScopeIdentitiesCache] - Getting service identity for <7> 2024-03-21 12:57:08.194 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.DeviceScopeAuthenticator] - Client in device scope not reauthenticated locally. <7> 2024-03-21 12:57:08.194 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.DeviceScopeAuthenticator] - Service identity for not found. Using underlying authenticator to authenticate <7> 2024-03-21 12:57:08.194 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.Authenticators.CloudTokenAuthenticator] - Reauthenticating with IotHub succeeded <7> 2024-03-21 12:57:08.194 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Authenticator] - Client re-authentication successful <7> 2024-03-21 12:57:08.194 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionReauthenticator] - Reauthenticated client successfully <7> 2024-03-21 12:57:17.653 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint //input1_Pri9 starting from 11 with batch size 10. <7> 2024-03-21 12:57:17.654 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint //input1_Pri9 with batch size 0. Next start offset = 11. <7> 2024-03-21 12:57:27.656 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint //input1_Pri9 starting from 11 with batch size 10. <7> 2024-03-21 12:57:27.656 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint //input1_Pri9 with batch size 0. Next start offset = 11. <7> 2024-03-21 12:57:37.655 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint //input1_Pri9 starting from 11 with batch size 10. <7> 2024-03-21 12:57:37.655 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint //input1_Pri9 with batch size 0. Next start offset = 11. <7> 2024-03-21 12:57:47.656 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint //input1_Pri9 starting from 11 with batch size 10. <7> 2024-03-21 12:59:47.214 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.DeviceConnectivityManager] - Calling IotHub to test connectivity <7> 2024-03-21 12:59:47.215 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionManager] - Obtained cloud connection for device /$edgeHub <7> 2024-03-21 12:59:47.363 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.DeviceConnectivityManager] - IotHub call succeeded <7> 2024-03-21 12:59:47.364 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient] - Operation UpdateReportedPropertiesAsync succeeded for /$edgeHub <7> 2024-03-21 12:59:47.364 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy] - Updating reported properties for /$edgeHub <7> 2024-03-21 12:59:47.659 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint //input1_Pri9 starting from 11 with batch size 10. <7> 2024-03-21 12:59:47.659 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint //input1_Pri9 with batch size 0. Next start offset = 11. <7> 2024-03-21 12:59:56.110 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.RoutingEdgeHub] - Received 1 message(s) from <7> 2024-03-21 12:59:56.112 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Amqp.LinkHandlers.EventsLinkHandler] - EventsLinkHandler processed 1 messages for <7> 2024-03-21 12:59:56.112 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint //input1_Pri9 starting from 11 with batch size 10. <7> 2024-03-21 12:59:56.113 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint //input1_Pri9 with batch size 1. Next start offset = 12. <7> 2024-03-21 12:59:56.113 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint //input1_Pri9 starting from 12 with batch size 9. <7> 2024-03-21 12:59:56.113 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint //input1_Pri9 with batch size 0. Next start offset = 12. <7> 2024-03-21 12:59:56.114 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.ModuleEndpoint] - Sending 1 message(s) to module /. <7> 2024-03-21 12:59:56.114 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Device.DeviceMessageHandler] - Sent message with correlation ID 23335ba9-f24b-4221-804d-105d11a7ed29 to / <7> 2024-03-21 12:59:56.114 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Amqp.ClientConnectionHandler] - Sending telemetry message to / <7> 2024-03-21 12:59:56.114 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Amqp.LinkHandlers.SendingLinkHandler] - Sent message with id 23335ba9-f24b-4221-804d-105d11a7ed29 to device / <7> 2024-03-21 12:59:56.122 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.SubscriptionProcessor] - Adding subscription C2D for client . <6> 2024-03-21 12:59:56.122 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Amqp.LinkHandlers.LinkHandler] - Opened link C2D for <6> 2024-03-21 12:59:56.124 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.SubscriptionProcessor] - Processing pending subscriptions for <7> 2024-03-21 12:59:56.125 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionManager] - Obtained cloud connection for device <7> 2024-03-21 12:59:56.125 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.SubscriptionProcessor] - Processing subscription C2D for client . <6> 2024-03-21 12:59:56.125 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy] - Start listening for C2D messages for <7> 2024-03-21 12:59:57.277 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Device.DeviceMessageHandler] - Received feedback Complete for message 23335ba9-f24b-4221-804d-105d11a7ed29 from device/module / <7> 2024-03-21 12:59:57.278 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint //input1_Pri9 starting from 12 with batch size 10. <7> 2024-03-21 12:59:57.278 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint //input1_Pri9 with batch size 0. Next start offset = 12. <7> 2024-03-21 13:00:07.278 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint //input1_Pri9 starting from 12 with batch size 10. <7> 2024-03-21 13:00:07.278 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint //input1_Pri9 with batch size 0. Next start offset = 12. ```

Additional Information

This issue has originally been reported in https://github.com/Azure/iotedge/issues/7247 and we were told to open the issue in this repo instead. We are in a strictly controlled network environment, which means we only have the necessary ports and target hosts allowed. Our server is only able to communicate with the Azure IoT Hub and DPS on port HTTPS TCP/443. We communicate with Azure in Amqp_Ws

Mandur commented 3 months ago

Hello @Metal-Mighty, could we quickly discuss the issue over voice? i think you have my credentials