Azure / iotedge

The IoT Edge OSS project
MIT License
1.45k stars 457 forks source link

Error getting device scope result from IoTHub (IotHubUnauthorizedAccess) #7247

Closed Metal-Mighty closed 3 months ago

Metal-Mighty commented 3 months ago

Expected Behavior

I am using the LoRaNetworkSrvModule (LNS) from the iotedge-lorawan-starterkit project. 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: Our LNS module 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

Provide a detailed set of steps to reproduce the bug.

  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)

Output of iotedge check

iotedge check --diagnostics-image-name /azureiotedge-diagnostics:1.4.33 --iothub-hostname .azure-devices.net --expected-aziot-edged-version 1.4.33 --expected-aziot-version 1.4.8 ``` Configuration checks (aziot-identity-service) --------------------------------------------- √ keyd configuration is well-formed - OK √ certd configuration is well-formed - OK √ tpmd configuration is well-formed - OK √ identityd configuration is well-formed - OK √ daemon configurations up-to-date with config.toml - OK √ identityd config toml file specifies a valid hostname - OK √ aziot-identity-service package is up-to-date - OK ‼ host time is close to reference time - Warning Could not query NTP server √ preloaded certificates are valid - OK √ keyd is running - OK √ certd is running - OK √ identityd is running - OK √ read all preloaded certificates from the Certificates Service - OK √ read all preloaded key pairs from the Keys Service - OK √ check all EST server URLs utilize HTTPS - OK √ ensure all preloaded certificates match preloaded private keys with the same ID - OK Connectivity checks (aziot-identity-service) -------------------------------------------- × host can connect to and perform TLS handshake with iothub AMQP port - Error Failed to do TLS Handshake, Connection Attempt Timed out in 70 Seconds √ host can connect to and perform TLS handshake with iothub HTTPS / WebSockets port - OK × host can connect to and perform TLS handshake with iothub MQTT port - Error Failed to do TLS Handshake, Connection Attempt Timed out in 70 Seconds √ host can connect to and perform TLS handshake with DPS endpoint - OK Configuration checks -------------------- √ aziot-edged configuration is well-formed - OK √ configuration up-to-date with config.toml - OK √ container engine is installed and functional - OK √ configuration has correct URIs for daemon mgmt endpoint - OK √ aziot-edge package is up-to-date - OK √ container time is close to host time - OK √ DNS server - OK √ production readiness: logs policy - OK ‼ production readiness: Edge Agent's storage directory is persisted on the host filesystem - Warning The edgeAgent module is not configured to persist its /tmp/edgeAgent directory on the host filesystem. Data might be lost if the module is deleted or updated. Please see https://aka.ms/iotedge-storage-host for best practices. ‼ production readiness: Edge Hub's storage directory is persisted on the host filesystem - Warning The edgeHub module is not configured to persist its /tmp/edgeHub directory on the host filesystem. Data might be lost if the module is deleted or updated. Please see https://aka.ms/iotedge-storage-host for best practices. √ Agent image is valid and can be pulled from upstream - OK √ proxy settings are consistent in aziot-edged, aziot-identityd, moby daemon and config.toml - OK Connectivity checks ------------------- × container on the default network can connect to upstream AMQP port - Error Container on the default network could not connect to .azure-devices.net:5671 √ container on the default network can connect to upstream HTTPS / WebSockets port - OK × container on the default network can connect to upstream MQTT port - Error Container on the default network could not connect to .azure-devices.net:8883 × container on the IoT Edge module network can connect to upstream AMQP port - Error Container on the azure-iot-edge network could not connect to .azure-devices.net:5671 √ container on the IoT Edge module network can connect to upstream HTTPS / WebSockets port - OK × container on the IoT Edge module network can connect to upstream MQTT port - Error Container on the azure-iot-edge network could not connect to .azure-devices.net:8883 29 check(s) succeeded. 3 check(s) raised warnings. Re-run with --verbose for more details. 6 check(s) raised errors. Re-run with --verbose for more details. ```

Device Information

Runtime Versions

Daemon configuration

/etc/aziot/config.toml ``` [provisioning] iothub_hostname = ".azure-devices.net" source = "dps" global_endpoint = "https://.azure-devices-provisioning.net" id_scope = "" [provisioning.attestation] method = "symmetric_key" registration_id = "" symmetric_key = { value = "" } trust_bundle_cert = "file://" cert = "file://" key = "file://" auto_reprovisioning_mode = "Dynamic" [edge_ca] auto_generated_edge_ca_expiry_days = 365 [edge_ca.auto_renew] rotate_key = true threshold = "70%" retry = "2%" [agent] name = "edgeAgent" type = "docker" [agent.config] image = "/azureiotedge-agent:1.4" ```

Logs

Abstract of the logs when the error above occurs.

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

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 This issue is a follow-up to #6936, I preferred opening a new ticket with up to date information and releases of the whole stack. I am working with @adcoly on that topic.

veyalla commented 3 months ago

Hello, iotedge-lorawan-starterkit is not supported as part of the core IoT Edge runtime. Please open an issue in the lorawan repo.

Metal-Mighty commented 3 months ago

Hi, I thought the connections to the IoT Hub would be handled by the edgeHub module directly. I'll move my issue there, thanks