iotedge 1.2: provisioning of module identities on a downstream device

## Expected Behavior
Hi, I'm trying to follow the transparent gateway documentation with iotedge 1.2 (https://docs.microsoft.com/en-us/azure/iot-edge/how-to-create-transparent-gateway?view=iotedge-2020-11).

1.) I have an iot device with iot-identity-service and two applications configured with module identity. The authentication type is SaS.
If I connect this device directly with the iothub, the two module identities get provisioned.
If I use this iot device afterwards as a downstream device behind a gateway the two module identites get provisioned as well.
The edgehub log looks suspicous though. See in the log section below.

2.) If I use another iot device as a downstream device behind a gateway, that never was connected to the iothub, the provisioning of the module identites doesnt work. I get permission denied errors from the edgehub. The authentication type is Sas as well.

3.) If I use this device and configure one application as device identity. Only this application gets provisioned. The other application still gets an access denied error from the edgehub.

My goal is to achieve the provisioning of multiple module identities on a downstream iot device, without connecting this device directly to the iothub. The authentication type is Sas. Is that possible?

### Output of `iotedge check`

Click here

```

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 - OK
√ preloaded certificates are valid - OK
√ keyd is running - OK
√ certd is running - OK
√ tpmd 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
√ 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 - Warning
Could not retrieve iothub_hostname from provisioning file.
Please specify the backing IoT Hub name using --iothub-hostname switch if you have that information.
Since no hostname is provided, all hub connectivity tests will be skipped.
‼ host can connect to and perform TLS handshake with iothub HTTPS / WebSockets port - Warning
Could not retrieve iothub_hostname from provisioning file.
Please specify the backing IoT Hub name using --iothub-hostname switch if you have that information.
Since no hostname is provided, all hub connectivity tests will be skipped.
‼ host can connect to and perform TLS handshake with iothub MQTT port - Warning
Could not retrieve iothub_hostname from provisioning file.
Please specify the backing IoT Hub name using --iothub-hostname switch if you have that information.
Since no hostname is provided, all hub connectivity tests will be skipped.
√ 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 - Error
Unable to find image 'mcr.microsoft.com/azureiotedge-diagnostics:1.2.2' locally
docker: Error response from daemon: manifest for mcr.microsoft.com/azureiotedge-diagnostics:1.2.2 not found: manifest unknown: manifest tagged by "1.2.2" is not found.
See 'docker run --help'.
√ aziot-edge package is up-to-date - OK
× container time is close to host time - Error
Could not query local time inside container
‼ DNS server - Warning
Container engine is not configured with DNS server setting, which may impact connectivity to IoT Hub.
Please see https://aka.ms/iotedge-prod-checklist-dns for best practices.
You can ignore this warning if you are setting DNS server per module in the Edge deployment.
‼ production readiness: container engine - Warning
Device is not using a production-supported container engine (moby-engine).
Please see https://aka.ms/iotedge-prod-checklist-moby for details.
‼ production readiness: logs policy - Warning
Container engine is not configured to rotate module logs which may cause it run out of disk space.
Please see https://aka.ms/iotedge-prod-checklist-logs for best practices.
You can ignore this warning if you are setting log policy per module in the Edge deployment.
‼ 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

Connectivity checks
-------------------
22 check(s) succeeded.
8 check(s) raised warnings. Re-run with --verbose for more details.
2 check(s) raised errors. Re-run with --verbose for more details.
6 check(s) were skipped due to errors from other checks. Re-run with --verbose for more details

* The container engine seems to be misdetected. Is is indeed a moby-engine.

```

### Device Information
* Host OS: yocto dunfell 3.1.8
* Architecture: aarch64
* Container OS: linux containers

### Runtime Versions
* aziot-edged [run `iotedge version`]: iotedge 1.2.2 (git revision is 70bc14cb7884bda857688c93ff179821bb6c9061)
* Edge Agent [image tag (e.g. 1.0.0)]: 1.2
* Edge Hub [image tag (e.g. 1.0.0)]: 1.2.1
* Docker/Moby [run `docker version`]:
Client:
Version: 19.03.15
API version: 1.40
Go version: go1.14.15
Git commit: eb310fca49
Built: Tue Jun 22 12:08:06 2021
OS/Arch: linux/arm64
Experimental: false

Server:
Engine:
Version: 19.03.15
API version: 1.40 (minimum version 1.12)
Go version: go1.14.15
Git commit: 420b1d36250f9cfdc561f086f25a213ecb669b6f
Built: Tue Jun 22 12:07:16 2021
OS/Arch: linux/arm64
Experimental: false
containerd:
Version: v1.2.14-3-g3b3e9d5f6.m
GitCommit: 3b3e9d5f62a114153829f9fbe2781d27b0a2ddac.m
runc:
Version: 1.0.0-rc8
GitCommit: 425e105d5a03fabd737a126ad93d62a9eeede87f-dirty
docker-init:
Version: 0.18.0
GitCommit: fec3683-dirty
* iot-identity-service on downstream device and gateway: git revision 3f82e7b565bf4a46479707ddc72fd3f43c8cadf9

## Logs

suspicous edgehub logs for working scenario 1.)

```

2021-06-24 16:31:39 +00:00 Starting Edge Hub
Jun 24 16:31:39.900 INFO watchdog: Starting Watchdog
Jun 24 16:31:39.900 INFO watchdog: Registering shutdown signal listener
Jun 24 16:31:40.198 INFO watchdog: MQTT broker is disabled
Jun 24 16:31:40.198 INFO watchdog::child: Launched Edge Hub process with pid 9
2021-06-24 16:31:40.636 +00:00 Edge Hub Main()
<6> 2021-06-24 16:31:46.848 +00:00 [INF] - Installing certificates [CN=damn.ca:07/10/2021 20:28:46],[CN=Azure_IoT_Hub_Intermediate_Cert_Test_Only:07/10/2021 06:14:27],[CN=Azure_IoT_Hub_CA_Cert_Test_Only:07/10/2021 06:14:26] to Root
<6> 2021-06-24 16:31:47.095 +00:00 [INF] - Installing certificates [CN=damn.ca:07/10/2021 20:28:46],[CN=Azure_IoT_Hub_Intermediate_Cert_Test_Only:07/10/2021 06:14:27],[CN=Azure_IoT_Hub_CA_Cert_Test_Only:07/10/2021 06:14:26],[CN=Azure_IoT_Hub_CA_Cert_Test_Only:07/10/2021 06:14:26] to Root
<6> 2021-06-24 16:31:47.149 +00:00 [INF] - Enabling SSL protocols: Tls, Tls11, Tls12
<6> 2021-06-24 16:31:47.989 +00:00 [INF] - Experimental features configuration: {"Enabled":false,"DisableCloudSubscriptions":false,"DisableConnectivityCheck":false,"EnableMqttBroker":false}
<6> 2021-06-24 16:31:50.738 +00:00 [INF] - Created persistent store at /tmp/edgeHub
<6> 2021-06-24 16:31:50.984 +00:00 [INF] - Initializing Edge Hub
<6> 2021-06-24 16:31:50.986 +00:00 [INF] -
█████╗ ███████╗██╗ ██╗██████╗ ███████╗
██╔══██╗╚══███╔╝██║ ██║██╔══██╗██╔════╝
███████║ ███╔╝ ██║ ██║██████╔╝█████╗
██╔══██║ ███╔╝ ██║ ██║██╔══██╗██╔══╝
██║ ██║███████╗╚██████╔╝██║ ██║███████╗
╚═╝ ╚═╝╚══════╝ ╚═════╝ ╚═╝ ╚═╝╚══════╝

██╗ ██████╗ ████████╗ ███████╗██████╗ ██████╗ ███████╗
██║██╔═══██╗╚══██╔══╝ ██╔════╝██╔══██╗██╔════╝ ██╔════╝
██║██║ ██║ ██║ █████╗ ██║ ██║██║ ███╗█████╗
██║██║ ██║ ██║ ██╔══╝ ██║ ██║██║ ██║██╔══╝
██║╚██████╔╝ ██║ ███████╗██████╔╝╚██████╔╝███████╗
╚═╝ ╚═════╝ ╚═╝ ╚══════╝╚═════╝ ╚═════╝ ╚══════╝

<6> 2021-06-24 16:31:50.993 +00:00 [INF] - Version - 1.2.1.43175312 (f0e7486e3fd527515999b9449313e55b733516c9)
<6> 2021-06-24 16:31:50.995 +00:00 [INF] - OptimizeForPerformance=False
<6> 2021-06-24 16:31:50.996 +00:00 [INF] - MessageAckTimeoutSecs=30
<6> 2021-06-24 16:31:51.004 +00:00 [INF] - Loaded server certificate with expiration date of "2021-07-10T20:28:46.0000000+00:00"
<6> 2021-06-24 16:31:51.061 +00:00 [INF] - Using Asp Net server for metrics
<6> 2021-06-24 16:31:51.373 +00:00 [INF] - Started task to cleanup processed and stale messages
<6> 2021-06-24 16:31:51.374 +00:00 [INF] - Created new message store
<6> 2021-06-24 16:31:51.801 +00:00 [INF] - Created DeviceConnectivityManager with connected check frequency 00:05:00 and disconnected check frequency 00:02:00
<6> 2021-06-24 16:31:51.995 +00:00 [INF] - Add node: dc:a6:32:55:90:cb
<6> 2021-06-24 16:31:52.010 +00:00 [INF] - Add node: dc:a6:32:55:90:cb/$edgeAgent
<6> 2021-06-24 16:31:52.011 +00:00 [INF] - Add node: dc:a6:32:55:90:cb/$edgeHub
<6> 2021-06-24 16:31:52.012 +00:00 [INF] - Add node: dc:a6:32:55:90:cb/AducIotAgent
<6> 2021-06-24 16:31:52.012 +00:00 [INF] - Add node: dc:a6:32:55:90:cb/iot-module-template
<6> 2021-06-24 16:31:52.021 +00:00 [INF] - Add node: mlilien-rpi3
<6> 2021-06-24 16:31:52.038 +00:00 [INF] - Created device scope identities cache
<6> 2021-06-24 16:31:52.096 +00:00 [INF] - Starting refresh of device scope identities cache
<6> 2021-06-24 16:31:52.125 +00:00 [INF] - Initialized storing twin manager
<6> 2021-06-24 16:31:52.179 +00:00 [INF] - Updated node: dc:a6:32:55:90:cb/$edgeHub
<6> 2021-06-24 16:31:52.197 +00:00 [INF] - Initializing configuration
<6> 2021-06-24 16:31:52.285 +00:00 [INF] - New device connection for device dc:a6:32:55:90:cb/$edgeHub
<6> 2021-06-24 16:31:52.358 +00:00 [INF] - Client dc:a6:32:55:90:cb/$edgeHub connected to edgeHub, processing existing subscriptions.
<6> 2021-06-24 16:31:52.648 +00:00 [INF] - Attempting to connect to IoT Hub for client dc:a6:32:55:90:cb/$edgeHub via AMQP...
<6> 2021-06-24 16:31:52.741 +00:00 [INF] - Processing pending subscriptions for dc:a6:32:55:90:cb/$edgeHub
<6> 2021-06-24 16:31:54.022 +00:00 [INF] - Experimental features configuration: {"Enabled":false,"DisableCloudSubscriptions":false,"DisableConnectivityCheck":false,"EnableMqttBroker":false}
<6> 2021-06-24 16:31:54.156 +00:00 [INF] - Starting timer to authenticate connections with a period of 300 seconds
<6> 2021-06-24 16:31:54.537 +00:00 [INF] - Scheduling server certificate renewal for "2021-07-10T20:26:16.0006687Z".
<6> 2021-06-24 16:31:54.605 +00:00 [INF] - Not changed node: dc:a6:32:55:90:cb
<6> 2021-06-24 16:31:54.606 +00:00 [INF] - Not changed node: mlilien-rpi3
<6> 2021-06-24 16:31:54.607 +00:00 [INF] - Not changed node: dc:a6:32:55:90:cb/$edgeAgent
<6> 2021-06-24 16:31:54.607 +00:00 [INF] - Updated node: dc:a6:32:55:90:cb/$edgeHub
<6> 2021-06-24 16:31:54.807 +00:00 [INF] - Service identity for dc:a6:32:55:90:cb/$edgeHub in device scope was updated.
<6> 2021-06-24 16:31:54.812 +00:00 [INF] - Not changed node: dc:a6:32:55:90:cb/AducIotAgent
<6> 2021-06-24 16:31:54.814 +00:00 [INF] - Not changed node: dc:a6:32:55:90:cb/iot-module-template
<6> 2021-06-24 16:31:54.837 +00:00 [INF] - Done refreshing device scope identities cache. Waiting for 60 minutes.
<6> 2021-06-24 16:31:55.318 +00:00 [INF] - Created cloud endpoint iothub with max batch size 10 and fan-out factor of 10.
<6> 2021-06-24 16:31:56.028 +00:00 [INF] - Set the following 1 route(s) in edge hub
<6> 2021-06-24 16:31:56.029 +00:00 [INF] - route: FROM /messages/* INTO $upstream
<6> 2021-06-24 16:31:56.039 +00:00 [INF] - Updated message store TTL to 60 seconds
<6> 2021-06-24 16:31:56.041 +00:00 [INF] - Updated the edge hub store and forward configuration
<6> 2021-06-24 16:31:56.136 +00:00 [INF] - Started operation Get EdgeHub config
<6> 2021-06-24 16:31:56.139 +00:00 [INF] - Initialized edge hub configuration
<6> 2021-06-24 16:31:56.147 +00:00 [INF] - Starting protocol heads - (MQTT, AMQP, HTTP)
<6> 2021-06-24 16:31:56.168 +00:00 [INF] - Starting MQTT head
<6> 2021-06-24 16:31:56.321 +00:00 [INF] - Initializing TLS endpoint on port 8883 for MQTT head.
<6> 2021-06-24 16:31:56.365 +00:00 [INF] - Exiting disconnected state
<6> 2021-06-24 16:31:56.487 +00:00 [INF] - Device connected to cloud, processing subscriptions for connected clients.
<6> 2021-06-24 16:31:56.497 +00:00 [INF] - Processing subscriptions for client dc:a6:32:55:90:cb/$edgeHub on device connected to cloud.
<6> 2021-06-24 16:31:56.499 +00:00 [INF] - Skipping dc:a6:32:55:90:cb/$edgeHub for subscription processing, as it is currently being processed.
<6> 2021-06-24 16:31:56.522 +00:00 [INF] - Received device connected callback
<6> 2021-06-24 16:31:56.562 +00:00 [INF] - Skipping cache refresh, waiting 118 seconds until refreshing again.
<6> 2021-06-24 16:31:56.621 +00:00 [INF] - Entering connected state
<6> 2021-06-24 16:31:56.649 +00:00 [INF] - Cloud connection for dc:a6:32:55:90:cb/$edgeHub is True
<6> 2021-06-24 16:31:56.669 +00:00 [INF] - Connection status for dc:a6:32:55:90:cb/$edgeHub changed to ConnectionEstablished
<6> 2021-06-24 16:31:56.677 +00:00 [INF] - Client dc:a6:32:55:90:cb/$edgeHub connected to cloud, processing existing subscriptions.
<6> 2021-06-24 16:31:56.677 +00:00 [INF] - Skipping dc:a6:32:55:90:cb/$edgeHub for subscription processing, as it is currently being processed.
<6> 2021-06-24 16:31:56.695 +00:00 [INF] - Created cloud proxy for client dc:a6:32:55:90:cb/$edgeHub via AMQP, with client operation timeout 20 seconds.
<6> 2021-06-24 16:31:56.719 +00:00 [INF] - Initialized cloud proxy 95d76186-fd77-4651-b3a1-903341dd1fcd for dc:a6:32:55:90:cb/$edgeHub
<6> 2021-06-24 16:31:56.729 +00:00 [INF] - Created cloud connection for client dc:a6:32:55:90:cb/$edgeHub
<6> 2021-06-24 16:31:56.775 +00:00 [INF] - Starting AMQP head
<6> 2021-06-24 16:31:56.879 +00:00 [INF] - Started MQTT head
<6> 2021-06-24 16:31:57.332 +00:00 [INF] - Started AMQP head
<6> 2021-06-24 16:31:57.341 +00:00 [INF] - Starting HTTP head
<6> 2021-06-24 16:31:57.774 +00:00 [INF] - Processing pending subscriptions for dc:a6:32:55:90:cb/$edgeHub
<6> 2021-06-24 16:31:57.801 +00:00 [INF] - Updated reported properties for dc:a6:32:55:90:cb/$edgeHub
<6> 2021-06-24 16:31:58.540 +00:00 [INF] - Obtained edge hub config from module twin
<4> 2021-06-24 16:31:58.671 +00:00 [WRN] - Overriding address(es) '"http://+:80"'. Binding to endpoints defined in "UseKestrel()" instead.
<6> 2021-06-24 16:31:58.703 +00:00 [INF] - Started HTTP head
<6> 2021-06-24 16:31:58.804 +00:00 [INF] - Set the following 1 route(s) in edge hub
<6> 2021-06-24 16:31:58.805 +00:00 [INF] - route: FROM /messages/* INTO $upstream
<6> 2021-06-24 16:31:58.805 +00:00 [INF] - Updated message store TTL to 60 seconds
<6> 2021-06-24 16:31:58.806 +00:00 [INF] - Updated the edge hub store and forward configuration
<6> 2021-06-24 16:32:03.730 +00:00 [INF] - Updated reported properties for dc:a6:32:55:90:cb/$edgeHub
<6> 2021-06-24 16:32:21.011 +00:00 [INF] - Unable to authenticate client mlilien-rpi3/AducIotAgent with cached service identity mlilien-rpi3/AducIotAgent (Found: False). Resyncing service identity...
<6> 2021-06-24 16:32:21.045 +00:00 [INF] - Refreshing service identity for mlilien-rpi3/AducIotAgent
<6> 2021-06-24 16:32:21.080 +00:00 [INF] - Unable to authenticate client mlilien-rpi3/iot-module-template with cached service identity mlilien-rpi3/iot-module-template (Found: False). Resyncing service identity...
<6> 2021-06-24 16:32:21.081 +00:00 [INF] - Refreshing service identity for mlilien-rpi3/iot-module-template
<4> 2021-06-24 16:32:22.207 +00:00 [WRN] - Error while refreshing the service identity: mlilien-rpi3/iot-module-template OnBehalfOf: dc:a6:32:55:90:cb
System.ArgumentException: mlilien-rpi3 is not an Edge device, only Edge devices can have children
at Microsoft.Azure.Devices.Edge.Hub.Core.ServiceIdentityTree.ServiceIdentityTreeNode.AddChild(ServiceIdentityTreeNode childNode) in /home/vsts/work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/ServiceIdentityTree.cs:line 365
at Microsoft.Azure.Devices.Edge.Hub.Core.ServiceIdentityTree.InsertModuleIdentity(ServiceIdentity module) in /home/vsts/work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/ServiceIdentityTree.cs:line 244
at Microsoft.Azure.Devices.Edge.Hub.Core.ServiceIdentityTree.AddOrUpdate(ServiceIdentity identity) in /home/vsts/work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/ServiceIdentityTree.cs:line 59
at Microsoft.Azure.Devices.Edge.Hub.Core.DeviceScopeIdentitiesCache.HandleNewServiceIdentity(ServiceIdentity serviceIdentity) in /home/vsts/work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/DeviceScopeIdentitiesCache.cs:line 466
at Microsoft.Azure.Devices.Edge.Hub.Core.DeviceScopeIdentitiesCache.RefreshServiceIdentityInternal(String refreshTarget, String onBehalfOfDevice, Boolean invokeServiceIdentitiesUpdated) in /home/vsts/work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/DeviceScopeIdentitiesCache.cs:line 171
<4> 2021-06-24 16:32:22.190 +00:00 [WRN] - Error while refreshing the service identity: mlilien-rpi3/AducIotAgent OnBehalfOf: dc:a6:32:55:90:cb
System.ArgumentException: mlilien-rpi3 is not an Edge device, only Edge devices can have children
at Microsoft.Azure.Devices.Edge.Hub.Core.ServiceIdentityTree.ServiceIdentityTreeNode.AddChild(ServiceIdentityTreeNode childNode) in /home/vsts/work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/ServiceIdentityTree.cs:line 365
at Microsoft.Azure.Devices.Edge.Hub.Core.ServiceIdentityTree.InsertModuleIdentity(ServiceIdentity module) in /home/vsts/work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/ServiceIdentityTree.cs:line 244
at Microsoft.Azure.Devices.Edge.Hub.Core.ServiceIdentityTree.AddOrUpdate(ServiceIdentity identity) in /home/vsts/work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/ServiceIdentityTree.cs:line 59
at Microsoft.Azure.Devices.Edge.Hub.Core.DeviceScopeIdentitiesCache.HandleNewServiceIdentity(ServiceIdentity serviceIdentity) in /home/vsts/work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/DeviceScopeIdentitiesCache.cs:line 466
at Microsoft.Azure.Devices.Edge.Hub.Core.DeviceScopeIdentitiesCache.RefreshServiceIdentityInternal(String refreshTarget, String onBehalfOfDevice, Boolean invokeServiceIdentitiesUpdated) in /home/vsts/work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/DeviceScopeIdentitiesCache.cs:line 171
<6> 2021-06-24 16:32:22.462 +00:00 [INF] - Client mlilien-rpi3/iot-module-template in device scope authenticated locally.
<6> 2021-06-24 16:32:22.462 +00:00 [INF] - Client mlilien-rpi3/AducIotAgent in device scope authenticated locally.
<6> 2021-06-24 16:32:22.502 +00:00 [INF] - Successfully generated identity for clientId mlilien-rpi3/AducIotAgent and username my-iothub.azure-devices.net/mlilien-rpi3/AducIotAgent/?api-version=2020-09-30&DeviceClientType=iothubclient%2f1.6.0%20(native%3b%20Linux%3b%20armv7l)&model-id=dtmi%3aAzureDeviceUpdate%3b1
<6> 2021-06-24 16:32:22.502 +00:00 [INF] - Successfully generated identity for clientId mlilien-rpi3/iot-module-template and username my-iothub.azure-devices.net/mlilien-rpi3/iot-module-template/?api-version=2020-09-30&DeviceClientType=iothubclient%2f1.6.0%20(native%3b%20Linux%3b%20armv7l)
<6> 2021-06-24 16:32:22.537 +00:00 [INF] - ClientAuthenticated, mlilien-rpi3/AducIotAgent, 78c27f86
<6> 2021-06-24 16:32:22.537 +00:00 [INF] - ClientAuthenticated, mlilien-rpi3/iot-module-template, 5a521d03
<6> 2021-06-24 16:32:22.766 +00:00 [INF] - New device connection for device mlilien-rpi3/AducIotAgent
<6> 2021-06-24 16:32:22.768 +00:00 [INF] - New device connection for device mlilien-rpi3/iot-module-template
<6> 2021-06-24 16:32:22.768 +00:00 [INF] - Client mlilien-rpi3/AducIotAgent connected to edgeHub, processing existing subscriptions.
<6> 2021-06-24 16:32:22.769 +00:00 [INF] - Client mlilien-rpi3/iot-module-template connected to edgeHub, processing existing subscriptions.
<4> 2021-06-24 16:32:22.785 +00:00 [WRN] - Error creating cloud connection for client mlilien-rpi3/AducIotAgent
Microsoft.Azure.Devices.Edge.Hub.Core.DeviceInvalidStateException: Device is out of scope.
at Microsoft.Azure.Devices.Edge.Util.Try`1.get_Value() in /home/vsts/work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Util/Try.cs:line 29
at Microsoft.Azure.Devices.Edge.Hub.Core.DeviceScopeIdentitiesCache.VerifyServiceIdentityAuthChainState(String id, Boolean refreshCachedIdentity) in /home/vsts/work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/DeviceScopeIdentitiesCache.cs:line 260
at Microsoft.Azure.Devices.Edge.Hub.Core.DeviceScopeIdentitiesCache.VerifyServiceIdentityAuthChainState(String id, Boolean isNestedEdgeEnabled, Boolean refreshCachedIdentity) in /home/vsts/work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/DeviceScopeIdentitiesCache.cs:line 224
at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudConnectionProvider.ConnectInternalWithDeviceStateTracking(IIdentity identity, Action`2 connectionStatusChangedHandler, Boolean refreshCachedIdentity) in /home/vsts/work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/CloudConnectionProvider.cs:line 248
<6> 2021-06-24 16:32:22.798 +00:00 [INF] - Refreshing service identity for mlilien-rpi3/AducIotAgent
<6> 2021-06-24 16:32:22.877 +00:00 [INF] - Bind device proxy for device mlilien-rpi3/iot-module-template
<6> 2021-06-24 16:32:22.881 +00:00 [INF] - Binding message channel for device Id mlilien-rpi3/iot-module-template
<6> 2021-06-24 16:32:22.890 +00:00 [INF] - Processing pending subscriptions for mlilien-rpi3/AducIotAgent
<6> 2021-06-24 16:32:22.893 +00:00 [INF] - Bind device proxy for device mlilien-rpi3/AducIotAgent
<6> 2021-06-24 16:32:22.893 +00:00 [INF] - Binding message channel for device Id mlilien-rpi3/AducIotAgent
<6> 2021-06-24 16:32:22.914 +00:00 [INF] - Refreshing service identity for mlilien-rpi3/AducIotAgent
<4> 2021-06-24 16:32:22.913 +00:00 [WRN] - Error creating cloud connection for client mlilien-rpi3/iot-module-template
Microsoft.Azure.Devices.Edge.Hub.Core.DeviceInvalidStateException: Device is out of scope.
at Microsoft.Azure.Devices.Edge.Util.Try`1.get_Value() in /home/vsts/work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Util/Try.cs:line 29
at Microsoft.Azure.Devices.Edge.Hub.Core.DeviceScopeIdentitiesCache.VerifyServiceIdentityAuthChainState(String id, Boolean refreshCachedIdentity) in /home/vsts/work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/DeviceScopeIdentitiesCache.cs:line 260
at Microsoft.Azure.Devices.Edge.Hub.Core.DeviceScopeIdentitiesCache.VerifyServiceIdentityAuthChainState(String id, Boolean isNestedEdgeEnabled, Boolean refreshCachedIdentity) in /home/vsts/work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/DeviceScopeIdentitiesCache.cs:line 224
at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudConnectionProvider.ConnectInternalWithDeviceStateTracking(IIdentity identity, Action`2 connectionStatusChangedHandler, Boolean refreshCachedIdentity) in /home/vsts/work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/CloudConnectionProvider.cs:line 248
<6> 2021-06-24 16:32:22.917 +00:00 [INF] - Refreshing service identity for mlilien-rpi3/iot-module-template
<6> 2021-06-24 16:32:22.917 +00:00 [INF] - Refreshing service identity for mlilien-rpi3/iot-module-template
<6> 2021-06-24 16:32:23.082 +00:00 [INF] - Processing subscriptions TwinResponse, DesiredPropertyUpdates for client mlilien-rpi3/AducIotAgent.
<6> 2021-06-24 16:32:23.132 +00:00 [INF] - Set subscriptions from session state for mlilien-rpi3/AducIotAgent
<6> 2021-06-24 16:32:23.141 +00:00 [INF] - Processing subscriptions TwinResponse, DesiredPropertyUpdates for client mlilien-rpi3/iot-module-template.
<6> 2021-06-24 16:32:23.150 +00:00 [INF] - Not changed node: mlilien-rpi3/iot-module-template
<6> 2021-06-24 16:32:23.155 +00:00 [INF] - Not changed node: mlilien-rpi3/AducIotAgent

```

edgeHub logs scenario 2 - two module identities - unauthorized

```

2021-06-24 17:22:09 +00:00 Starting Edge Hub
Jun 24 17:22:09.609 INFO watchdog: Starting Watchdog
Jun 24 17:22:09.609 INFO watchdog: Registering shutdown signal listener
Jun 24 17:22:09.611 INFO watchdog: MQTT broker is disabled
Jun 24 17:22:09.611 INFO watchdog::child: Launched Edge Hub process with pid 9
2021-06-24 17:22:09.941 +00:00 Edge Hub Main()
<6> 2021-06-24 17:22:14.679 +00:00 [INF] - Installing certificates [CN=damn.ca:07/10/2021 20:28:46],[CN=Azure_IoT_Hub_Intermediate_Cert_Test_Only:07/10/2021 06:14:27],[CN=Azure_IoT_Hub_CA_Cert_Test_Only:07/10/2021 06:14:26] to Root
<6> 2021-06-24 17:22:14.964 +00:00 [INF] - Installing certificates [CN=damn.ca:07/10/2021 20:28:46],[CN=Azure_IoT_Hub_Intermediate_Cert_Test_Only:07/10/2021 06:14:27],[CN=Azure_IoT_Hub_CA_Cert_Test_Only:07/10/2021 06:14:26],[CN=Azure_IoT_Hub_CA_Cert_Test_Only:07/10/2021 06:14:26] to Root
<6> 2021-06-24 17:22:15.058 +00:00 [INF] - Enabling SSL protocols: Tls, Tls11, Tls12
<6> 2021-06-24 17:22:15.686 +00:00 [INF] - Experimental features configuration: {"Enabled":false,"DisableCloudSubscriptions":false,"DisableConnectivityCheck":false,"EnableMqttBroker":false}
<6> 2021-06-24 17:22:18.268 +00:00 [INF] - Created persistent store at /tmp/edgeHub
<6> 2021-06-24 17:22:18.520 +00:00 [INF] - Initializing Edge Hub
<6> 2021-06-24 17:22:18.521 +00:00 [INF] -
█████╗ ███████╗██╗ ██╗██████╗ ███████╗
██╔══██╗╚══███╔╝██║ ██║██╔══██╗██╔════╝
███████║ ███╔╝ ██║ ██║██████╔╝█████╗
██╔══██║ ███╔╝ ██║ ██║██╔══██╗██╔══╝
██║ ██║███████╗╚██████╔╝██║ ██║███████╗
╚═╝ ╚═╝╚══════╝ ╚═════╝ ╚═╝ ╚═╝╚══════╝

██╗ ██████╗ ████████╗ ███████╗██████╗ ██████╗ ███████╗
██║██╔═══██╗╚══██╔══╝ ██╔════╝██╔══██╗██╔════╝ ██╔════╝
██║██║ ██║ ██║ █████╗ ██║ ██║██║ ███╗█████╗
██║██║ ██║ ██║ ██╔══╝ ██║ ██║██║ ██║██╔══╝
██║╚██████╔╝ ██║ ███████╗██████╔╝╚██████╔╝███████╗
╚═╝ ╚═════╝ ╚═╝ ╚══════╝╚═════╝ ╚═════╝ ╚══════╝

<6> 2021-06-24 17:22:18.529 +00:00 [INF] - Version - 1.2.1.43175312 (f0e7486e3fd527515999b9449313e55b733516c9)
<6> 2021-06-24 17:22:18.530 +00:00 [INF] - OptimizeForPerformance=False
<6> 2021-06-24 17:22:18.531 +00:00 [INF] - MessageAckTimeoutSecs=30
<6> 2021-06-24 17:22:18.550 +00:00 [INF] - Created device scope identities cache
<6> 2021-06-24 17:22:18.535 +00:00 [INF] - Loaded server certificate with expiration date of "2021-07-10T20:28:46.0000000+00:00"
<6> 2021-06-24 17:22:18.584 +00:00 [INF] - Using Asp Net server for metrics
<6> 2021-06-24 17:22:18.645 +00:00 [INF] - Starting refresh of device scope identities cache
<6> 2021-06-24 17:22:18.840 +00:00 [INF] - Created new message store
<6> 2021-06-24 17:22:18.849 +00:00 [INF] - Started task to cleanup processed and stale messages
<6> 2021-06-24 17:22:19.193 +00:00 [INF] - Created DeviceConnectivityManager with connected check frequency 00:05:00 and disconnected check frequency 00:02:00
<6> 2021-06-24 17:22:19.353 +00:00 [INF] - Initialized storing twin manager
<6> 2021-06-24 17:22:19.449 +00:00 [INF] - Add node: dc:a6:32:55:90:cb/$edgeHub
<6> 2021-06-24 17:22:19.449 +00:00 [INF] - Initializing configuration
<6> 2021-06-24 17:22:19.535 +00:00 [INF] - New device connection for device dc:a6:32:55:90:cb/$edgeHub
<6> 2021-06-24 17:22:19.596 +00:00 [INF] - Client dc:a6:32:55:90:cb/$edgeHub connected to edgeHub, processing existing subscriptions.
<6> 2021-06-24 17:22:19.847 +00:00 [INF] - Attempting to connect to IoT Hub for client dc:a6:32:55:90:cb/$edgeHub via AMQP...
<6> 2021-06-24 17:22:19.941 +00:00 [INF] - Processing pending subscriptions for dc:a6:32:55:90:cb/$edgeHub
<6> 2021-06-24 17:22:21.054 +00:00 [INF] - Add node: mlilien-rpi3-2
<6> 2021-06-24 17:22:21.278 +00:00 [INF] - Experimental features configuration: {"Enabled":false,"DisableCloudSubscriptions":false,"DisableConnectivityCheck":false,"EnableMqttBroker":false}
<6> 2021-06-24 17:22:21.411 +00:00 [INF] - Starting timer to authenticate connections with a period of 300 seconds
<6> 2021-06-24 17:22:21.463 +00:00 [INF] - Add node: dc:a6:32:55:90:cb
<4> 2021-06-24 17:22:21.529 +00:00 [WRN] - Empty edge hub configuration received. Ignoring...
<6> 2021-06-24 17:22:21.577 +00:00 [INF] - Add node: dc:a6:32:55:90:cb/$edgeAgent
<6> 2021-06-24 17:22:21.713 +00:00 [INF] - Updated node: dc:a6:32:55:90:cb/$edgeHub
<6> 2021-06-24 17:22:21.806 +00:00 [INF] - Scheduling server certificate renewal for "2021-07-10T20:26:16.0013538Z".
<6> 2021-06-24 17:22:21.825 +00:00 [INF] - Service identity for dc:a6:32:55:90:cb/$edgeHub in device scope was updated.
<6> 2021-06-24 17:22:21.826 +00:00 [INF] - Add node: dc:a6:32:55:90:cb/AducIotAgent
<6> 2021-06-24 17:22:21.912 +00:00 [INF] - Add node: dc:a6:32:55:90:cb/iot-module-template
<6> 2021-06-24 17:22:22.030 +00:00 [INF] - Done refreshing device scope identities cache. Waiting for 60 minutes.
<6> 2021-06-24 17:22:23.006 +00:00 [INF] - Exiting disconnected state
<6> 2021-06-24 17:22:23.092 +00:00 [INF] - Received device connected callback
<6> 2021-06-24 17:22:23.125 +00:00 [INF] - Device connected to cloud, processing subscriptions for connected clients.
<6> 2021-06-24 17:22:23.135 +00:00 [INF] - Processing subscriptions for client dc:a6:32:55:90:cb/$edgeHub on device connected to cloud.
<6> 2021-06-24 17:22:23.137 +00:00 [INF] - Skipping dc:a6:32:55:90:cb/$edgeHub for subscription processing, as it is currently being processed.
<6> 2021-06-24 17:22:23.143 +00:00 [INF] - Skipping cache refresh, waiting 118 seconds until refreshing again.
<6> 2021-06-24 17:22:23.192 +00:00 [INF] - Entering connected state
<6> 2021-06-24 17:22:23.216 +00:00 [INF] - Cloud connection for dc:a6:32:55:90:cb/$edgeHub is True
<6> 2021-06-24 17:22:23.233 +00:00 [INF] - Connection status for dc:a6:32:55:90:cb/$edgeHub changed to ConnectionEstablished
<6> 2021-06-24 17:22:23.240 +00:00 [INF] - Client dc:a6:32:55:90:cb/$edgeHub connected to cloud, processing existing subscriptions.
<6> 2021-06-24 17:22:23.241 +00:00 [INF] - Skipping dc:a6:32:55:90:cb/$edgeHub for subscription processing, as it is currently being processed.
<6> 2021-06-24 17:22:23.254 +00:00 [INF] - Created cloud proxy for client dc:a6:32:55:90:cb/$edgeHub via AMQP, with client operation timeout 20 seconds.
<6> 2021-06-24 17:22:23.277 +00:00 [INF] - Initialized cloud proxy 7fc18cbb-b8d0-4469-86bc-aa9d0fbf263d for dc:a6:32:55:90:cb/$edgeHub
<6> 2021-06-24 17:22:23.284 +00:00 [INF] - Created cloud connection for client dc:a6:32:55:90:cb/$edgeHub
<6> 2021-06-24 17:22:23.989 +00:00 [INF] - Processing pending subscriptions for dc:a6:32:55:90:cb/$edgeHub
<6> 2021-06-24 17:22:23.998 +00:00 [INF] - Updated reported properties for dc:a6:32:55:90:cb/$edgeHub
<6> 2021-06-24 17:22:24.470 +00:00 [INF] - Done syncing reported properties for dc:a6:32:55:90:cb/$edgeHub
<6> 2021-06-24 17:22:25.133 +00:00 [INF] - Created cloud endpoint iothub with max batch size 10 and fan-out factor of 10.
<6> 2021-06-24 17:22:25.590 +00:00 [INF] - Obtained edge hub config from module twin
<6> 2021-06-24 17:22:26.349 +00:00 [INF] - Set the following 1 route(s) in edge hub
<6> 2021-06-24 17:22:26.350 +00:00 [INF] - route: FROM /messages/* INTO $upstream
<6> 2021-06-24 17:22:26.361 +00:00 [INF] - Updated message store TTL to 60 seconds
<6> 2021-06-24 17:22:26.363 +00:00 [INF] - Updated the edge hub store and forward configuration
<6> 2021-06-24 17:22:26.402 +00:00 [INF] - Started operation Get EdgeHub config
<6> 2021-06-24 17:22:26.404 +00:00 [INF] - Initialized edge hub configuration
<6> 2021-06-24 17:22:26.412 +00:00 [INF] - Starting protocol heads - (MQTT, AMQP, HTTP)
<6> 2021-06-24 17:22:26.426 +00:00 [INF] - Starting MQTT head
<6> 2021-06-24 17:22:26.567 +00:00 [INF] - Initializing TLS endpoint on port 8883 for MQTT head.
<6> 2021-06-24 17:22:26.875 +00:00 [INF] - Starting AMQP head
<6> 2021-06-24 17:22:26.964 +00:00 [INF] - Started MQTT head
<6> 2021-06-24 17:22:27.308 +00:00 [INF] - Started AMQP head
<6> 2021-06-24 17:22:27.329 +00:00 [INF] - Starting HTTP head
<4> 2021-06-24 17:22:28.334 +00:00 [WRN] - Overriding address(es) '"http://+:80"'. Binding to endpoints defined in "UseKestrel()" instead.
<6> 2021-06-24 17:22:28.367 +00:00 [INF] - Started HTTP head
<6> 2021-06-24 17:22:29.817 +00:00 [INF] - Updated reported properties for dc:a6:32:55:90:cb/$edgeHub
<6> 2021-06-24 17:22:56.498 +00:00 [INF] - Request starting HTTP/2 GET https://mlilien-rpi4/devices/mlilien-rpi3-2/modules/iot-module-template?api-version=2017-11-08-preview
<6> 2021-06-24 17:22:56.814 +00:00 [INF] - Executing endpoint '"Microsoft.Azure.Devices.Edge.Hub.Http.Controllers.RegistryController.GetModuleAsync (Microsoft.Azure.Devices.Edge.Hub.Http)"'
<6> 2021-06-24 17:22:57.131 +00:00 [INF] - Route matched with "{action = \"GetModule\", controller = \"Registry\"}". Executing controller action with signature "System.Threading.Tasks.Task GetModuleAsync(System.String, System.String)" on controller "Microsoft.Azure.Devices.Edge.Hub.Http.Controllers.RegistryController" ("Microsoft.Azure.Devices.Edge.Hub.Http").
<6> 2021-06-24 17:22:57.245 +00:00 [INF] - Received request in GetModuleAsync: deviceId=mlilien-rpi3-2, moduleId=iot-module-template
<6> 2021-06-24 17:22:57.484 +00:00 [INF] - Client mlilien-rpi3-2 in device scope authenticated locally.
<6> 2021-06-24 17:22:57.503 +00:00 [INF] - Authenticated: deviceId=mlilien-rpi3-2, moduleId=
<6> 2021-06-24 17:22:57.827 +00:00 [INF] - CompleteRequest in GetModuleAsync: deviceId=dc:a6:32:55:90:cb, authChain=mlilien-rpi3-2;dc:a6:32:55:90:cb, status=NotFound
<6> 2021-06-24 17:22:57.895 +00:00 [INF] - Executed action "Microsoft.Azure.Devices.Edge.Hub.Http.Controllers.RegistryController.GetModuleAsync (Microsoft.Azure.Devices.Edge.Hub.Http)" in 721.0495ms
<6> 2021-06-24 17:22:57.903 +00:00 [INF] - Executed endpoint '"Microsoft.Azure.Devices.Edge.Hub.Http.Controllers.RegistryController.GetModuleAsync (Microsoft.Azure.Devices.Edge.Hub.Http)"'
<6> 2021-06-24 17:22:57.940 +00:00 [INF] - Request finished in 1462.4832ms 404 application/json; charset=utf-8
<6> 2021-06-24 17:22:58.020 +00:00 [INF] - Request starting HTTP/2 GET https://mlilien-rpi4/devices/mlilien-rpi3-2/modules/AducIotAgent?api-version=2017-11-08-preview
<6> 2021-06-24 17:22:58.031 +00:00 [INF] - Executing endpoint '"Microsoft.Azure.Devices.Edge.Hub.Http.Controllers.RegistryController.GetModuleAsync (Microsoft.Azure.Devices.Edge.Hub.Http)"'
<6> 2021-06-24 17:22:58.076 +00:00 [INF] - Route matched with "{action = \"GetModule\", controller = \"Registry\"}". Executing controller action with signature "System.Threading.Tasks.Task GetModuleAsync(System.String, System.String)" on controller "Microsoft.Azure.Devices.Edge.Hub.Http.Controllers.RegistryController" ("Microsoft.Azure.Devices.Edge.Hub.Http").
<6> 2021-06-24 17:22:58.080 +00:00 [INF] - Received request in GetModuleAsync: deviceId=mlilien-rpi3-2, moduleId=AducIotAgent
<6> 2021-06-24 17:22:58.084 +00:00 [INF] - Client mlilien-rpi3-2 in device scope authenticated locally.
<6> 2021-06-24 17:22:58.085 +00:00 [INF] - Authenticated: deviceId=mlilien-rpi3-2, moduleId=
<6> 2021-06-24 17:22:58.318 +00:00 [INF] - CompleteRequest in GetModuleAsync: deviceId=dc:a6:32:55:90:cb, authChain=mlilien-rpi3-2;dc:a6:32:55:90:cb, status=NotFound
<6> 2021-06-24 17:22:58.329 +00:00 [INF] - Executed action "Microsoft.Azure.Devices.Edge.Hub.Http.Controllers.RegistryController.GetModuleAsync (Microsoft.Azure.Devices.Edge.Hub.Http)" in 247.8985ms
<6> 2021-06-24 17:22:58.333 +00:00 [INF] - Executed endpoint '"Microsoft.Azure.Devices.Edge.Hub.Http.Controllers.RegistryController.GetModuleAsync (Microsoft.Azure.Devices.Edge.Hub.Http)"'
<6> 2021-06-24 17:22:58.343 +00:00 [INF] - Request finished in 322.3987ms 404 application/json; charset=utf-8

```

edge-hub logs szenario 3 - one device identity, one module identity - module unauthorized

```

2021-06-24 17:29:10 +00:00 Starting Edge Hub
Jun 24 17:29:10.062 INFO watchdog: Starting Watchdog
Jun 24 17:29:10.062 INFO watchdog: Registering shutdown signal listener
Jun 24 17:29:10.065 INFO watchdog: MQTT broker is disabled
Jun 24 17:29:10.065 INFO watchdog::child: Launched Edge Hub process with pid 9
2021-06-24 17:29:10.384 +00:00 Edge Hub Main()
<6> 2021-06-24 17:29:15.746 +00:00 [INF] - Installing certificates [CN=damn.ca:07/10/2021 20:28:46],[CN=Azure_IoT_Hub_Intermediate_Cert_Test_Only:07/10/2021 06:14:27],[CN=Azure_IoT_Hub_CA_Cert_Test_Only:07/10/2021 06:14:26] to Root
<6> 2021-06-24 17:29:16.039 +00:00 [INF] - Installing certificates [CN=damn.ca:07/10/2021 20:28:46],[CN=Azure_IoT_Hub_Intermediate_Cert_Test_Only:07/10/2021 06:14:27],[CN=Azure_IoT_Hub_CA_Cert_Test_Only:07/10/2021 06:14:26],[CN=Azure_IoT_Hub_CA_Cert_Test_Only:07/10/2021 06:14:26] to Root
<6> 2021-06-24 17:29:16.128 +00:00 [INF] - Enabling SSL protocols: Tls, Tls11, Tls12
<6> 2021-06-24 17:29:16.723 +00:00 [INF] - Experimental features configuration: {"Enabled":false,"DisableCloudSubscriptions":false,"DisableConnectivityCheck":false,"EnableMqttBroker":false}
<6> 2021-06-24 17:29:19.124 +00:00 [INF] - Created persistent store at /tmp/edgeHub
<6> 2021-06-24 17:29:19.378 +00:00 [INF] - Initializing Edge Hub
<6> 2021-06-24 17:29:19.379 +00:00 [INF] -
█████╗ ███████╗██╗ ██╗██████╗ ███████╗
██╔══██╗╚══███╔╝██║ ██║██╔══██╗██╔════╝
███████║ ███╔╝ ██║ ██║██████╔╝█████╗
██╔══██║ ███╔╝ ██║ ██║██╔══██╗██╔══╝
██║ ██║███████╗╚██████╔╝██║ ██║███████╗
╚═╝ ╚═╝╚══════╝ ╚═════╝ ╚═╝ ╚═╝╚══════╝

██╗ ██████╗ ████████╗ ███████╗██████╗ ██████╗ ███████╗
██║██╔═══██╗╚══██╔══╝ ██╔════╝██╔══██╗██╔════╝ ██╔════╝
██║██║ ██║ ██║ █████╗ ██║ ██║██║ ███╗█████╗
██║██║ ██║ ██║ ██╔══╝ ██║ ██║██║ ██║██╔══╝
██║╚██████╔╝ ██║ ███████╗██████╔╝╚██████╔╝███████╗
╚═╝ ╚═════╝ ╚═╝ ╚══════╝╚═════╝ ╚═════╝ ╚══════╝

<6> 2021-06-24 17:29:19.388 +00:00 [INF] - Version - 1.2.1.43175312 (f0e7486e3fd527515999b9449313e55b733516c9)
<6> 2021-06-24 17:29:19.389 +00:00 [INF] - OptimizeForPerformance=False
<6> 2021-06-24 17:29:19.390 +00:00 [INF] - MessageAckTimeoutSecs=30
<6> 2021-06-24 17:29:19.397 +00:00 [INF] - Created device scope identities cache
<6> 2021-06-24 17:29:19.394 +00:00 [INF] - Loaded server certificate with expiration date of "2021-07-10T20:28:46.0000000+00:00"
<6> 2021-06-24 17:29:19.458 +00:00 [INF] - Using Asp Net server for metrics
<6> 2021-06-24 17:29:19.476 +00:00 [INF] - Starting refresh of device scope identities cache
<6> 2021-06-24 17:29:19.691 +00:00 [INF] - Started task to cleanup processed and stale messages
<6> 2021-06-24 17:29:19.691 +00:00 [INF] - Created new message store
<6> 2021-06-24 17:29:20.038 +00:00 [INF] - Created DeviceConnectivityManager with connected check frequency 00:05:00 and disconnected check frequency 00:02:00
<6> 2021-06-24 17:29:20.189 +00:00 [INF] - Initialized storing twin manager
<6> 2021-06-24 17:29:20.281 +00:00 [INF] - Add node: dc:a6:32:55:90:cb/$edgeHub
<6> 2021-06-24 17:29:20.282 +00:00 [INF] - Initializing configuration
<6> 2021-06-24 17:29:20.365 +00:00 [INF] - New device connection for device dc:a6:32:55:90:cb/$edgeHub
<6> 2021-06-24 17:29:20.422 +00:00 [INF] - Client dc:a6:32:55:90:cb/$edgeHub connected to edgeHub, processing existing subscriptions.
<6> 2021-06-24 17:29:20.671 +00:00 [INF] - Attempting to connect to IoT Hub for client dc:a6:32:55:90:cb/$edgeHub via AMQP...
<6> 2021-06-24 17:29:20.786 +00:00 [INF] - Processing pending subscriptions for dc:a6:32:55:90:cb/$edgeHub
<6> 2021-06-24 17:29:22.015 +00:00 [INF] - Add node: mlilien-rpi3-2
<6> 2021-06-24 17:29:22.065 +00:00 [INF] - Experimental features configuration: {"Enabled":false,"DisableCloudSubscriptions":false,"DisableConnectivityCheck":false,"EnableMqttBroker":false}
<6> 2021-06-24 17:29:22.206 +00:00 [INF] - Starting timer to authenticate connections with a period of 300 seconds
<4> 2021-06-24 17:29:22.290 +00:00 [WRN] - Empty edge hub configuration received. Ignoring...
<6> 2021-06-24 17:29:22.343 +00:00 [INF] - Add node: dc:a6:32:55:90:cb
<6> 2021-06-24 17:29:22.461 +00:00 [INF] - Add node: dc:a6:32:55:90:cb/$edgeAgent
<6> 2021-06-24 17:29:22.587 +00:00 [INF] - Updated node: dc:a6:32:55:90:cb/$edgeHub
<6> 2021-06-24 17:29:22.590 +00:00 [INF] - Scheduling server certificate renewal for "2021-07-10T20:26:16.0008743Z".
<6> 2021-06-24 17:29:22.709 +00:00 [INF] - Service identity for dc:a6:32:55:90:cb/$edgeHub in device scope was updated.
<6> 2021-06-24 17:29:22.710 +00:00 [INF] - Add node: dc:a6:32:55:90:cb/AducIotAgent
<6> 2021-06-24 17:29:22.823 +00:00 [INF] - Add node: dc:a6:32:55:90:cb/iot-module-template
<6> 2021-06-24 17:29:22.934 +00:00 [INF] - Done refreshing device scope identities cache. Waiting for 60 minutes.
<6> 2021-06-24 17:29:23.832 +00:00 [INF] - Exiting disconnected state
<6> 2021-06-24 17:29:23.916 +00:00 [INF] - Received device connected callback
<6> 2021-06-24 17:29:23.948 +00:00 [INF] - Device connected to cloud, processing subscriptions for connected clients.
<6> 2021-06-24 17:29:23.958 +00:00 [INF] - Processing subscriptions for client dc:a6:32:55:90:cb/$edgeHub on device connected to cloud.
<6> 2021-06-24 17:29:23.960 +00:00 [INF] - Skipping dc:a6:32:55:90:cb/$edgeHub for subscription processing, as it is currently being processed.
<6> 2021-06-24 17:29:23.966 +00:00 [INF] - Skipping cache refresh, waiting 118 seconds until refreshing again.
<6> 2021-06-24 17:29:24.015 +00:00 [INF] - Entering connected state
<6> 2021-06-24 17:29:24.034 +00:00 [INF] - Cloud connection for dc:a6:32:55:90:cb/$edgeHub is True
<6> 2021-06-24 17:29:24.050 +00:00 [INF] - Connection status for dc:a6:32:55:90:cb/$edgeHub changed to ConnectionEstablished
<6> 2021-06-24 17:29:24.059 +00:00 [INF] - Client dc:a6:32:55:90:cb/$edgeHub connected to cloud, processing existing subscriptions.
<6> 2021-06-24 17:29:24.060 +00:00 [INF] - Skipping dc:a6:32:55:90:cb/$edgeHub for subscription processing, as it is currently being processed.
<6> 2021-06-24 17:29:24.071 +00:00 [INF] - Created cloud proxy for client dc:a6:32:55:90:cb/$edgeHub via AMQP, with client operation timeout 20 seconds.
<6> 2021-06-24 17:29:24.094 +00:00 [INF] - Initialized cloud proxy caaa5fb7-de4d-4b1e-b519-2151c3d356ae for dc:a6:32:55:90:cb/$edgeHub
<6> 2021-06-24 17:29:24.101 +00:00 [INF] - Created cloud connection for client dc:a6:32:55:90:cb/$edgeHub
<6> 2021-06-24 17:29:24.788 +00:00 [INF] - Updated reported properties for dc:a6:32:55:90:cb/$edgeHub
<6> 2021-06-24 17:29:24.789 +00:00 [INF] - Processing pending subscriptions for dc:a6:32:55:90:cb/$edgeHub
<6> 2021-06-24 17:29:25.283 +00:00 [INF] - Done syncing reported properties for dc:a6:32:55:90:cb/$edgeHub
<6> 2021-06-24 17:29:25.951 +00:00 [INF] - Created cloud endpoint iothub with max batch size 10 and fan-out factor of 10.
<6> 2021-06-24 17:29:26.501 +00:00 [INF] - Obtained edge hub config from module twin
<6> 2021-06-24 17:29:27.207 +00:00 [INF] - Set the following 1 route(s) in edge hub
<6> 2021-06-24 17:29:27.208 +00:00 [INF] - route: FROM /messages/* INTO $upstream
<6> 2021-06-24 17:29:27.217 +00:00 [INF] - Updated message store TTL to 60 seconds
<6> 2021-06-24 17:29:27.220 +00:00 [INF] - Updated the edge hub store and forward configuration
<6> 2021-06-24 17:29:27.260 +00:00 [INF] - Started operation Get EdgeHub config
<6> 2021-06-24 17:29:27.261 +00:00 [INF] - Initialized edge hub configuration
<6> 2021-06-24 17:29:27.268 +00:00 [INF] - Starting protocol heads - (MQTT, AMQP, HTTP)
<6> 2021-06-24 17:29:27.283 +00:00 [INF] - Starting MQTT head
<6> 2021-06-24 17:29:27.415 +00:00 [INF] - Initializing TLS endpoint on port 8883 for MQTT head.
<6> 2021-06-24 17:29:27.721 +00:00 [INF] - Starting AMQP head
<6> 2021-06-24 17:29:27.785 +00:00 [INF] - Started MQTT head
<6> 2021-06-24 17:29:28.153 +00:00 [INF] - Started AMQP head
<6> 2021-06-24 17:29:28.172 +00:00 [INF] - Starting HTTP head
<4> 2021-06-24 17:29:29.166 +00:00 [WRN] - Overriding address(es) '"http://+:80"'. Binding to endpoints defined in "UseKestrel()" instead.
<6> 2021-06-24 17:29:29.221 +00:00 [INF] - Started HTTP head
<6> 2021-06-24 17:29:30.630 +00:00 [INF] - Updated reported properties for dc:a6:32:55:90:cb/$edgeHub
<6> 2021-06-24 17:29:35.949 +00:00 [INF] - Client mlilien-rpi3-2 in device scope authenticated locally.
<6> 2021-06-24 17:29:36.046 +00:00 [INF] - Successfully generated identity for clientId mlilien-rpi3-2 and username my-iothub.azure-devices.net/mlilien-rpi3-2/?api-version=2020-09-30&DeviceClientType=iothubclient%2f1.6.0%20(native%3b%20Linux%3b%20armv7l)&model-id=dtmi%3aAzureDeviceUpdate%3b1
<6> 2021-06-24 17:29:36.082 +00:00 [INF] - ClientAuthenticated, mlilien-rpi3-2, 5639586a
<6> 2021-06-24 17:29:36.234 +00:00 [INF] - New device connection for device mlilien-rpi3-2
<6> 2021-06-24 17:29:36.238 +00:00 [INF] - Client mlilien-rpi3-2 connected to edgeHub, processing existing subscriptions.
<6> 2021-06-24 17:29:36.325 +00:00 [INF] - Bind device proxy for device mlilien-rpi3-2
<6> 2021-06-24 17:29:36.329 +00:00 [INF] - Binding message channel for device Id mlilien-rpi3-2
<6> 2021-06-24 17:29:36.353 +00:00 [INF] - Attempting to connect to IoT Hub for client mlilien-rpi3-2 via AMQP with modelId dtmi:AzureDeviceUpdate;1...
<6> 2021-06-24 17:29:36.578 +00:00 [INF] - Processing subscriptions TwinResponse for client mlilien-rpi3-2.
<6> 2021-06-24 17:29:36.582 +00:00 [INF] - Processing pending subscriptions for mlilien-rpi3-2
<6> 2021-06-24 17:29:36.703 +00:00 [INF] - Set subscriptions from session state for mlilien-rpi3-2
<6> 2021-06-24 17:29:36.724 +00:00 [INF] - Cloud connection for mlilien-rpi3-2 is True
<6> 2021-06-24 17:29:36.724 +00:00 [INF] - Connection status for mlilien-rpi3-2 changed to ConnectionEstablished
<6> 2021-06-24 17:29:36.725 +00:00 [INF] - Client mlilien-rpi3-2 connected to cloud, processing existing subscriptions.
<6> 2021-06-24 17:29:36.725 +00:00 [INF] - Skipping mlilien-rpi3-2 for subscription processing, as it is currently being processed.
<6> 2021-06-24 17:29:36.725 +00:00 [INF] - Created cloud proxy for client mlilien-rpi3-2 via AMQP, with client operation timeout 20 seconds.
<6> 2021-06-24 17:29:36.726 +00:00 [INF] - Initialized cloud proxy 8657fed4-6886-41a5-b670-a2e40686788b for mlilien-rpi3-2
<6> 2021-06-24 17:29:36.726 +00:00 [INF] - Created cloud connection for client mlilien-rpi3-2
<6> 2021-06-24 17:29:37.543 +00:00 [INF] - Processing subscriptions TwinResponse, DesiredPropertyUpdates for client mlilien-rpi3-2.
<6> 2021-06-24 17:29:37.561 +00:00 [INF] - Processing pending subscriptions for mlilien-rpi3-2
<6> 2021-06-24 17:29:37.571 +00:00 [INF] - Set subscriptions from session state for mlilien-rpi3-2
<6> 2021-06-24 17:29:41.272 +00:00 [INF] - Updated reported properties for dc:a6:32:55:90:cb/$edgeHub
<6> 2021-06-24 17:29:41.967 +00:00 [INF] - Updated reported properties for mlilien-rpi3-2
<6> 2021-06-24 17:30:27.154 +00:00 [INF] - Request starting HTTP/2 GET https://mlilien-rpi4/devices/mlilien-rpi3-2/modules?api-version=2017-11-08-preview
<6> 2021-06-24 17:30:27.441 +00:00 [INF] - Executing endpoint '"Microsoft.Azure.Devices.Edge.Hub.Http.Controllers.RegistryController.ListModulesAsync (Microsoft.Azure.Devices.Edge.Hub.Http)"'
<6> 2021-06-24 17:30:27.760 +00:00 [INF] - Route matched with "{action = \"ListModules\", controller = \"Registry\"}". Executing controller action with signature "System.Threading.Tasks.Task ListModulesAsync(System.String)" on controller "Microsoft.Azure.Devices.Edge.Hub.Http.Controllers.RegistryController" ("Microsoft.Azure.Devices.Edge.Hub.Http").
<6> 2021-06-24 17:30:27.868 +00:00 [INF] - Received request in ListModulesAsync: deviceId=mlilien-rpi3-2, moduleId=
<6> 2021-06-24 17:30:27.945 +00:00 [INF] - Client mlilien-rpi3-2 in device scope authenticated locally.
<6> 2021-06-24 17:30:27.963 +00:00 [INF] - Authenticated: deviceId=mlilien-rpi3-2, moduleId=
<6> 2021-06-24 17:30:28.280 +00:00 [INF] - CompleteRequest in ListModulesAsync: deviceId=dc:a6:32:55:90:cb, authChain=mlilien-rpi3-2;dc:a6:32:55:90:cb, status=Unauthorized
<6> 2021-06-24 17:30:28.348 +00:00 [INF] - Executed action "Microsoft.Azure.Devices.Edge.Hub.Http.Controllers.RegistryController.ListModulesAsync (Microsoft.Azure.Devices.Edge.Hub.Http)" in 545.4579ms
<6> 2021-06-24 17:30:28.355 +00:00 [INF] - Executed endpoint '"Microsoft.Azure.Devices.Edge.Hub.Http.Controllers.RegistryController.ListModulesAsync (Microsoft.Azure.Devices.Edge.Hub.Http)"'
<6> 2021-06-24 17:30:28.387 +00:00 [INF] - Request finished in 1238.0804ms 401 application/json; charset=utf-8

```

identity principal configuration

```

adu.toml:
[[principal]]
uid = 987
name = "AducIotAgent"
idtype = ["module"]

iot-module-template.toml:
[[principal]]
uid = 988
name = "iot-module-template"
idtype = ["module"]

```