Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

iotedge 1.2: provisioning of module identities on a downstream device #5155

Open
mlilien opened this issue Jun 24, 2021 · 28 comments
Open

iotedge 1.2: provisioning of module identities on a downstream device #5155

mlilien opened this issue Jun 24, 2021 · 28 comments

Comments

@mlilien
Copy link

mlilien commented Jun 24, 2021

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 70bc14c)
  • 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"]

@ValOlson
Copy link

@varunpuranik
Copy link
Contributor

Hi @mlilien -

We don't currently support module identities on leaf (non-edge) devices. We will work on fixing this limitation, but I don't have a timeline yet on that yet.

Here are answers to your questions above:
Re #1: Module identities are not provisioned automatically by IoT Hub, but you can use the device credentials to provision modules on the device. Are you creating the module identities on the device explicitly, using the device credentials?
The log error you see is because the issue I mentioned above. Once that is fixed, the error should go away.

Re #2: EdgeHub does support a Registry API which allows downstream devices to create module identities, but currently it works only for IoT Edge devices. So you won't be able to create module identities for your leaf IoT Edge device via EdgeHub, yet.

Re #3: I am not sure what you mean here... one application uses device identity and is able to connect properly. Other application is not provisioned, and not able to connect (which seems expected). Am I missing something?

Hope this clarifies your questions.

@mlilien
Copy link
Author

mlilien commented Jul 7, 2021

Hi @varunpuranik
thank you for the clarification.

  1. The module identities get created implicitly via iot-identity-service configuration.

  2. That means explicitly iotedge modules, right? The module has to run in the container runtime then?

  3. I meant that it is possible to provision via device identity behind a gateway, but not as module and also not if there is a mixed configuration with device and module identity. Your answer that there currently is no support for module identites on leaf (non-edge) devices confirmes my oberservation.

@github-actions
Copy link

This issue is being marked as stale because it has been open for 30 days with no activity.

kodiakhq bot pushed a commit that referenced this issue Aug 18, 2021
Fixing #5155, it is now possible to connect device module through edgeHub as well as creating new modules.

Test:
Connected module through edgeHub using SAS token
Created new module through edgeHub.
huguesBouvier added a commit to huguesBouvier/iotedge that referenced this issue Sep 1, 2021
Fixing Azure#5155, it is now possible to connect device module through edgeHub as well as creating new modules.

Test:
Connected module through edgeHub using SAS token
Created new module through edgeHub.
@JanZachmann
Copy link

JanZachmann commented Sep 1, 2021

Hi @huguesBouvier

Since my colleague @mlilien is on holidays for another 2 weeks I try to give some feedback on your fix. From my understanding the fix focuses on the 1st scenario described by @mlilien with the corresponding logs: "suspicious edgehub logs".

The use case we are struggling with is scenario 2.) where two module identities on a leaf device (non-edge iot device) behind an edge gateway are not provisioned due to permission errors. After testing with a local build of the fixed edgehub module on our side this setup is still not running with the same logs already provided in the issue: "edgeHub logs scenario 2 - two module identities - unauthorized".

So my question is if the fix was supposed to fix 2nd scenario as well from your side?

kodiakhq bot pushed a commit that referenced this issue Sep 1, 2021
Fixing #5155, it is now possible to connect device module through edgeHub as well as creating new modules.

Test:
Connected module through edgeHub using SAS token
Created new module through edgeHub.
@huguesBouvier
Copy link
Contributor

huguesBouvier commented Sep 1, 2021

Hi @JanZachmann,

This also should fix scenario 2. I was able to create a module trough edgeHub. This is the code I used in C#:

string connectionString = "HostName=xxx;DeviceId=leaf;SharedAccessKey=xxxx;GatewayHostname=xxxx";       
string deviceName = "leaf";

var transportSettings = new AmqpTransportSettings(Microsoft.Azure.Devices.Client.TransportType.Amqp_Tcp_Only);
transportSettings.RemoteCertificateValidationCallback = (sender, certificate, chain, sslPolicyErrors) => { return true; };
transportSettings.OpenTimeout = TimeSpan.FromMinutes(60);
transportSettings.OperationTimeout = TimeSpan.FromMinutes(60);
transportSettings.IdleTimeout = TimeSpan.FromMinutes(60);

Console.WriteLine("Opening upstream connection...");
Console.Write(connectionString);
var client = DeviceClient.CreateFromConnectionString(connectionString, new[] { transportSettings });

Console.Write("Module Name: ");
string moduleName = Console.ReadLine();
await AddModuleAsync(connectionString, deviceName, moduleName);

I was able to establish a connection through edgeHub and create a new module with this code.
You are using IS to get the key but aside from that the process should be similar.

Could you please give me more details/code on what you are doing in #2?

@JanZachmann
Copy link

@huguesBouvier Thanks for your feedback!

Our setup on the leaf device is as follows:

  1. two module identities
    1.1. AducIotAgent in order to make FW updates via "device update for iothub"
    1.2. A custom module identity
  2. Both modules are coded in C using azure-iot-sdk-c SDK LTS_01_2021_Ref01
  3. Both modules use iot-identity-service 1.2.2 to create the connection string. The modules are created by iot-identity-service. They are not manually created by iothub before!
  4. MQTT as transport protocol
  5. We can say that both modules work when not behind an edge gateway

What we tested today:

  • without iot-identity-service but with a connection string from an already created module we are also able to connect successfully.

The following questions come to my mind:

  • Your example doesn't use iot-identity-service. Thus you create the module first in iothub to obtain the connection string. With iot-identity-service the module is supposed to be created implicitly (by edgehub?). Maybe that goes wrong? But our tests also fail if the modules are created manually before.
  • In your last comment you write "I was able to create a module trough edgeHub." Do you really mean create a module or do you mean connect the module?
  • Can you confirm that AduIotAgent as module plus IS is tested on a leaf device?
  • Can you test a setup close to ours and maybe suggest what we could test next on our side?

@huguesBouvier
Copy link
Contributor

huguesBouvier commented Sep 2, 2021

Hello!

I think I understand the confusion. There are 2 connection strings:
The main connection string is the device connection string. This is what you will use to create new module. This connection string, you have to provision yourself:
image
Then you have the modules connection string:
image
Those you can create from your leaf using the device connection string.

This is how I was able to create new modules. The device connection string is used to authenticate.

  • Can you confirm that AduIotAgent as module plus IS is tested on a leaf device? I am sorry I don't understand the question.

Whether you use IS or connection string directly like I did is the same. IS is used as a mean to safely store connection string.
You get back the connection string by doing first: GET /identities/identity?api-version=2020-09-01
Then use the key handle to generate a token and access iotHub (through edgeHub) to create new modules.

What the C# is doing is identical. It uses the Device Connection string to generate a token and access IoTHub.

@JanZachmann
Copy link

Thanks for explaining details regarding module creation.

Since we got leaf device modules working with connection string but not with IS we're pretty sure it must be sth. releated to the eis_utils of ADU: https://github.com/Azure/iot-hub-device-update/tree/main/src/utils/eis_utils

That's what I meant in my last comment when I asked if you can confirm that the adu agent was ever successfully running as module identity on a leaf device?

@ValOlson
Copy link

ValOlson commented Sep 3, 2021

@JanZachmann I am adding members of the Device Update team here to verify if there is a reason eis_utils of ADU: https://github.com/Azure/iot-hub-device-update/tree/main/src/utils/eis_utils causing leaf modules not to connect for the AduIotAgent as module using the IoT Identity service. It should have just worked if it works with the connection string and the fix that @varunpuranik added to IoT Identity service.

@huguesBouvier
Copy link
Contributor

"That's what I meant in my last comment when I asked if you can confirm that the adu agent was ever successfully running as module identity on a leaf device?" Not to my knowledge but I didn't work much with ADU, I see you added the ADU team. They would be ale to provide an answer, let's have them confirm first.

@huguesBouvier
Copy link
Contributor

Should I close the ticket for now? Let's re-open it if there is a follow up.

@JanZachmann
Copy link

Please don't close yet. Next week @mlilien is back from holydays. Since he is the initiator of the issue and he is testing the setup with our yocto linux distribution (I just used ubuntu), I would like to wait for his analysis and feedback first.

@ValOlson Do you think you ADU guys could provide some feedback on testing our setup on your side next week?

@huguesBouvier
Copy link
Contributor

Ok! I will be also on vacation next week, maybe someone else from the team will pick it up but otherwise it possible you'll get answers only when I get back

@mlilien
Copy link
Author

mlilien commented Sep 16, 2021

Hi, I build the edge-hub 1.2.4 from release/1.2 branch for target aarch64.

I can verify that in case 1 I don't see the suspicious log entries in edge-Hub anymore.
For case 2 I can not verify that it works.

edge-hub log for case 2
2021-09-16 13:45:14 +00:00 Starting Edge Hub
Sep 16 13:45:14.085  INFO watchdog: Starting Watchdog
Sep 16 13:45:14.085  INFO watchdog: Registering shutdown signal listener
Sep 16 13:45:14.087  INFO watchdog: MQTT broker is disabled
Sep 16 13:45:14.087  INFO watchdog::child: Launched Edge Hub process with pid 9
2021-09-16 13:45:14.627 +00:00 Edge Hub Main()
<6> 2021-09-16 13:45:19.879 +00:00 [INF] - Installing certificates [CN=dc-a6-32-55-90-ca.ca:10/14/2021 12:22:19],[CN=Azure_IoT_Hub_Intermediate_Cert_Test_Only:10/14/2021 12:18:44],[CN=Azure_IoT_Hub_CA_Cert_Test_Only:10/14/2021 12:18:44] to Root
<6> 2021-09-16 13:45:20.177 +00:00 [INF] - Installing certificates [CN=dc-a6-32-55-90-ca.ca:10/14/2021 12:22:19],[CN=Azure_IoT_Hub_Intermediate_Cert_Test_Only:10/14/2021 12:18:44],[CN=Azure_IoT_Hub_CA_Cert_Test_Only:10/14/2021 12:18:44] to Root
<6> 2021-09-16 13:45:20.252 +00:00 [INF] - Enabling SSL protocols: Tls, Tls11, Tls12
<6> 2021-09-16 13:45:20.875 +00:00 [INF] - Experimental features configuration: {"Enabled":false,"DisableCloudSubscriptions":false,"DisableConnectivityCheck":false,"EnableMqttBroker":false}
<6> 2021-09-16 13:45:23.299 +00:00 [INF] - Created persistent store at /tmp/edgeHub
<6> 2021-09-16 13:45:23.521 +00:00 [INF] - Created device scope identities cache
<6> 2021-09-16 13:45:23.533 +00:00 [INF] - Initializing Edge Hub
<6> 2021-09-16 13:45:23.534 +00:00 [INF] -
        █████╗ ███████╗██╗   ██╗██████╗ ███████╗
       ██╔══██╗╚══███╔╝██║   ██║██╔══██╗██╔════╝
       ███████║  ███╔╝ ██║   ██║██████╔╝█████╗
       ██╔══██║ ███╔╝  ██║   ██║██╔══██╗██╔══╝
       ██║  ██║███████╗╚██████╔╝██║  ██║███████╗
       ╚═╝  ╚═╝╚══════╝ ╚═════╝ ╚═╝  ╚═╝╚══════╝

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

<6> 2021-09-16 13:45:23.542 +00:00 [INF] - Version - 1.2.4
<6> 2021-09-16 13:45:23.543 +00:00 [INF] - OptimizeForPerformance=False
<6> 2021-09-16 13:45:23.543 +00:00 [INF] - MessageAckTimeoutSecs=30
<6> 2021-09-16 13:45:23.558 +00:00 [INF] - Starting refresh of device scope identities cache
<6> 2021-09-16 13:45:23.547 +00:00 [INF] - Loaded server certificate with expiration date of "2021-10-14T12:22:19.0000000+00:00"
<6> 2021-09-16 13:45:23.594 +00:00 [INF] - Using Asp Net server for metrics
<6> 2021-09-16 13:45:23.857 +00:00 [INF] - Started task to cleanup processed and stale messages
<6> 2021-09-16 13:45:23.860 +00:00 [INF] - Created new message store
<6> 2021-09-16 13:45:24.202 +00:00 [INF] - Created DeviceConnectivityManager with connected check frequency 00:05:00 and disconnected check frequency 00:02:00
<6> 2021-09-16 13:45:24.342 +00:00 [INF] - Initialized storing twin manager
<6> 2021-09-16 13:45:24.437 +00:00 [INF] - Add node: dc:a6:32:55:90:ca/$edgeHub
<6> 2021-09-16 13:45:24.437 +00:00 [INF] - Initializing configuration
<6> 2021-09-16 13:45:24.520 +00:00 [INF] - New device connection for device dc:a6:32:55:90:ca/$edgeHub
<6> 2021-09-16 13:45:24.582 +00:00 [INF] - Client dc:a6:32:55:90:ca/$edgeHub connected to edgeHub, processing existing subscriptions.
<6> 2021-09-16 13:45:24.825 +00:00 [INF] - Attempting to connect to IoT Hub for client dc:a6:32:55:90:ca/$edgeHub via AMQP...
<6> 2021-09-16 13:45:25.546 +00:00 [INF] - Processing pending subscriptions for dc:a6:32:55:90:ca/$edgeHub
<6> 2021-09-16 13:45:26.025 +00:00 [INF] - Add node: mlilien-rpi3
<6> 2021-09-16 13:45:26.341 +00:00 [INF] - Add node: dc:a6:32:55:90:ca
<6> 2021-09-16 13:45:26.464 +00:00 [INF] - Add node: dc:a6:32:55:90:ca/$edgeAgent
<6> 2021-09-16 13:45:26.641 +00:00 [INF] - Updated node: dc:a6:32:55:90:ca/$edgeHub
<6> 2021-09-16 13:45:26.760 +00:00 [INF] - Add node: dc:a6:32:55:90:ca/AducIotAgent
<6> 2021-09-16 13:45:26.851 +00:00 [INF] - Experimental features configuration: {"Enabled":false,"DisableCloudSubscriptions":false,"DisableConnectivityCheck":false,"EnableMqttBroker":false}
<6> 2021-09-16 13:45:26.913 +00:00 [INF] - Add node: dc:a6:32:55:90:ca/iot-module-template
<6> 2021-09-16 13:45:26.975 +00:00 [INF] - Starting timer to authenticate connections with a period of 300 seconds
<4> 2021-09-16 13:45:27.139 +00:00 [WRN] - Empty edge hub configuration received. Ignoring...
<6> 2021-09-16 13:45:27.141 +00:00 [INF] - Done refreshing device scope identities cache. Waiting for 60 minutes.
<6> 2021-09-16 13:45:27.396 +00:00 [INF] - Scheduling server certificate renewal for "2021-10-14T12:19:49.0009831Z".
<6> 2021-09-16 13:45:28.060 +00:00 [INF] - Exiting disconnected state
<6> 2021-09-16 13:45:28.138 +00:00 [INF] - Received device connected callback
<6> 2021-09-16 13:45:28.161 +00:00 [INF] - Device connected to cloud, processing subscriptions for connected clients.
<6> 2021-09-16 13:45:28.172 +00:00 [INF] - Processing subscriptions for client dc:a6:32:55:90:ca/$edgeHub on device connected to cloud.
<6> 2021-09-16 13:45:28.175 +00:00 [INF] - Skipping dc:a6:32:55:90:ca/$edgeHub for subscription processing, as it is currently being processed.
<6> 2021-09-16 13:45:28.182 +00:00 [INF] - Skipping cache refresh, waiting 118 seconds until refreshing again.
<6> 2021-09-16 13:45:28.232 +00:00 [INF] - Entering connected state
<6> 2021-09-16 13:45:28.252 +00:00 [INF] - Cloud connection for dc:a6:32:55:90:ca/$edgeHub is True
<6> 2021-09-16 13:45:28.274 +00:00 [INF] - Connection status for dc:a6:32:55:90:ca/$edgeHub changed to ConnectionEstablished
<6> 2021-09-16 13:45:28.283 +00:00 [INF] - Client dc:a6:32:55:90:ca/$edgeHub connected to cloud, processing existing subscriptions.
<6> 2021-09-16 13:45:28.284 +00:00 [INF] - Skipping dc:a6:32:55:90:ca/$edgeHub for subscription processing, as it is currently being processed.
<6> 2021-09-16 13:45:28.291 +00:00 [INF] - Created cloud proxy for client dc:a6:32:55:90:ca/$edgeHub via AMQP, with client operation timeout 20 seconds.
<6> 2021-09-16 13:45:28.312 +00:00 [INF] - Initialized cloud proxy 3cc6ae4f-037f-4d0c-8a5f-c0b8c4a60fb4 for dc:a6:32:55:90:ca/$edgeHub
<6> 2021-09-16 13:45:28.321 +00:00 [INF] - Created cloud connection for client dc:a6:32:55:90:ca/$edgeHub
<6> 2021-09-16 13:45:28.905 +00:00 [INF] - Processing pending subscriptions for dc:a6:32:55:90:ca/$edgeHub
<6> 2021-09-16 13:45:28.929 +00:00 [INF] - Updated reported properties for dc:a6:32:55:90:ca/$edgeHub
<6> 2021-09-16 13:45:29.428 +00:00 [INF] - Done syncing reported properties for dc:a6:32:55:90:ca/$edgeHub
<6> 2021-09-16 13:45:30.031 +00:00 [INF] - Created cloud endpoint iothub with max batch size 10 and fan-out factor of 10.
<6> 2021-09-16 13:45:30.497 +00:00 [INF] - Obtained edge hub config from module twin
<6> 2021-09-16 13:45:31.114 +00:00 [INF] - Set the following 1 route(s) in edge hub
<6> 2021-09-16 13:45:31.116 +00:00 [INF] - route: FROM /messages/* INTO $upstream
<6> 2021-09-16 13:45:31.125 +00:00 [INF] - Updated message store TTL to 7200 seconds
<6> 2021-09-16 13:45:31.129 +00:00 [INF] - Updated the edge hub store and forward configuration
<6> 2021-09-16 13:45:31.146 +00:00 [INF] - Started operation Get EdgeHub config
<6> 2021-09-16 13:45:31.148 +00:00 [INF] - Initialized edge hub configuration
<6> 2021-09-16 13:45:31.158 +00:00 [INF] - Starting protocol heads - (MQTT, AMQP, HTTP)
<6> 2021-09-16 13:45:31.173 +00:00 [INF] - Starting MQTT head
<6> 2021-09-16 13:45:31.312 +00:00 [INF] - Initializing TLS endpoint on port 8883 for MQTT head.
<6> 2021-09-16 13:45:31.613 +00:00 [INF] - Starting AMQP head
<6> 2021-09-16 13:45:31.671 +00:00 [INF] - Started MQTT head
<6> 2021-09-16 13:45:32.023 +00:00 [INF] - Started AMQP head
<6> 2021-09-16 13:45:32.032 +00:00 [INF] - Starting HTTP head
<4> 2021-09-16 13:45:33.019 +00:00 [WRN] - Overriding address(es) '"http://+:80"'. Binding to endpoints defined in "UseKestrel()" instead.
<6> 2021-09-16 13:45:33.051 +00:00 [INF] - Started HTTP head
<6> 2021-09-16 13:45:34.862 +00:00 [INF] - Updated reported properties for dc:a6:32:55:90:ca/$edgeHub
<6> 2021-09-16 13:46:15.408 +00:00 [INF] - Request starting HTTP/2 GET https://raspberrypi4-64/devices/mlilien-rpi3/modules?api-version=2017-11-08-preview
<6> 2021-09-16 13:46:15.699 +00:00 [INF] - Executing endpoint '"Microsoft.Azure.Devices.Edge.Hub.Http.Controllers.RegistryController.ListModulesAsync (Microsoft.Azure.Devices.Edge.Hub.Http)"'
<6> 2021-09-16 13:46:16.026 +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-09-16 13:46:16.139 +00:00 [INF] - Received request in ListModulesAsync: deviceId=mlilien-rpi3, moduleId=
<6> 2021-09-16 13:46:16.401 +00:00 [INF] - Client mlilien-rpi3 in device scope authenticated locally.
<6> 2021-09-16 13:46:16.421 +00:00 [INF] - Authenticated: deviceId=mlilien-rpi3, moduleId=
<6> 2021-09-16 13:46:16.778 +00:00 [INF] - CompleteRequest in ListModulesAsync: deviceId=dc:a6:32:55:90:ca, authChain=mlilien-rpi3;dc:a6:32:55:90:ca, status=Unauthorized
<6> 2021-09-16 13:46:16.848 +00:00 [INF] - Executed action "Microsoft.Azure.Devices.Edge.Hub.Http.Controllers.RegistryController.ListModulesAsync (Microsoft.Azure.Devices.Edge.Hub.Http)" in 779.0046ms
<6> 2021-09-16 13:46:16.857 +00:00 [INF] - Executed endpoint '"Microsoft.Azure.Devices.Edge.Hub.Http.Controllers.RegistryController.ListModulesAsync (Microsoft.Azure.Devices.Edge.Hub.Http)"'
<6> 2021-09-16 13:46:16.900 +00:00 [INF] - Request finished in 1503.6813ms 401 application/json; charset=utf-8
<6> 2021-09-16 13:46:16.962 +00:00 [INF] - Request starting HTTP/2 GET https://raspberrypi4-64/devices/mlilien-rpi3/modules?api-version=2017-11-08-preview
<6> 2021-09-16 13:46:16.970 +00:00 [INF] - Executing endpoint '"Microsoft.Azure.Devices.Edge.Hub.Http.Controllers.RegistryController.ListModulesAsync (Microsoft.Azure.Devices.Edge.Hub.Http)"'
<6> 2021-09-16 13:46:16.973 +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-09-16 13:46:16.979 +00:00 [INF] - Received request in ListModulesAsync: deviceId=mlilien-rpi3, moduleId=
<6> 2021-09-16 13:46:16.982 +00:00 [INF] - Client mlilien-rpi3 in device scope authenticated locally.
<6> 2021-09-16 13:46:16.983 +00:00 [INF] - Authenticated: deviceId=mlilien-rpi3, moduleId=
<6> 2021-09-16 13:46:17.181 +00:00 [INF] - CompleteRequest in ListModulesAsync: deviceId=dc:a6:32:55:90:ca, authChain=mlilien-rpi3;dc:a6:32:55:90:ca, status=Unauthorized
<6> 2021-09-16 13:46:17.186 +00:00 [INF] - Executed action "Microsoft.Azure.Devices.Edge.Hub.Http.Controllers.RegistryController.ListModulesAsync (Microsoft.Azure.Devices.Edge.Hub.Http)" in 210.6351ms
<6> 2021-09-16 13:46:17.189 +00:00 [INF] - Executed endpoint '"Microsoft.Azure.Devices.Edge.Hub.Http.Controllers.RegistryController.ListModulesAsync (Microsoft.Azure.Devices.Edge.Hub.Http)"'
<6> 2021-09-16 13:46:17.196 +00:00 [INF] - Request finished in 232.3347ms 401 application/json; charset=utf-8
<6> 2021-09-16 13:46:22.580 +00:00 [INF] - Request starting HTTP/2 GET https://raspberrypi4-64/devices/mlilien-rpi3/modules?api-version=2017-11-08-preview
<6> 2021-09-16 13:46:22.584 +00:00 [INF] - Executing endpoint '"Microsoft.Azure.Devices.Edge.Hub.Http.Controllers.RegistryController.ListModulesAsync (Microsoft.Azure.Devices.Edge.Hub.Http)"'
<6> 2021-09-16 13:46:22.587 +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-09-16 13:46:22.594 +00:00 [INF] - Received request in ListModulesAsync: deviceId=mlilien-rpi3, moduleId=
<6> 2021-09-16 13:46:22.598 +00:00 [INF] - Client mlilien-rpi3 in device scope authenticated locally.
<6> 2021-09-16 13:46:22.600 +00:00 [INF] - Authenticated: deviceId=mlilien-rpi3, moduleId=
<6> 2021-09-16 13:46:22.809 +00:00 [INF] - CompleteRequest in ListModulesAsync: deviceId=dc:a6:32:55:90:ca, authChain=mlilien-rpi3;dc:a6:32:55:90:ca, status=Unauthorized
<6> 2021-09-16 13:46:22.814 +00:00 [INF] - Executed action "Microsoft.Azure.Devices.Edge.Hub.Http.Controllers.RegistryController.ListModulesAsync (Microsoft.Azure.Devices.Edge.Hub.Http)" in 224.1184ms
<6> 2021-09-16 13:46:22.820 +00:00 [INF] - Executed endpoint '"Microsoft.Azure.Devices.Edge.Hub.Http.Controllers.RegistryController.ListModulesAsync (Microsoft.Azure.Devices.Edge.Hub.Http)"'
<6> 2021-09-16 13:46:22.831 +00:00 [INF] - Request finished in 249.3469ms 401 application/json; charset=utf-8
<6> 2021-09-16 13:46:22.914 +00:00 [INF] - Request starting HTTP/2 GET https://raspberrypi4-64/devices/mlilien-rpi3/modules?api-version=2017-11-08-preview
<6> 2021-09-16 13:46:22.916 +00:00 [INF] - Executing endpoint '"Microsoft.Azure.Devices.Edge.Hub.Http.Controllers.RegistryController.ListModulesAsync (Microsoft.Azure.Devices.Edge.Hub.Http)"'
<6> 2021-09-16 13:46:22.917 +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-09-16 13:46:22.921 +00:00 [INF] - Received request in ListModulesAsync: deviceId=mlilien-rpi3, moduleId=
<6> 2021-09-16 13:46:22.924 +00:00 [INF] - Client mlilien-rpi3 in device scope authenticated locally.
<6> 2021-09-16 13:46:22.924 +00:00 [INF] - Authenticated: deviceId=mlilien-rpi3, moduleId=
<6> 2021-09-16 13:46:23.137 +00:00 [INF] - CompleteRequest in ListModulesAsync: deviceId=dc:a6:32:55:90:ca, authChain=mlilien-rpi3;dc:a6:32:55:90:ca, status=Unauthorized
<6> 2021-09-16 13:46:23.139 +00:00 [INF] - Executed action "Microsoft.Azure.Devices.Edge.Hub.Http.Controllers.RegistryController.ListModulesAsync (Microsoft.Azure.Devices.Edge.Hub.Http)" in 221.0039ms
<6> 2021-09-16 13:46:23.140 +00:00 [INF] - Executed endpoint '"Microsoft.Azure.Devices.Edge.Hub.Http.Controllers.RegistryController.ListModulesAsync (Microsoft.Azure.Devices.Edge.Hub.Http)"'
<6> 2021-09-16 13:46:23.142 +00:00 [INF] - Request finished in 228.7271ms 401 application/json; charset=utf-8

Could you please give me more details/code on what you are doing in #2?

Basically the same as in case 1. The difference is that the leaf device never was connected directly to iothub before. I have an iot device with iot-identity-service and two applications configured with module identity behind an edge-gw. The authentication type is SaS.

What also doesnt work and is a simpler setup:
An iot device with iot-identity-service and iothub-device-update configured as module identity behind an edge-gw. The authentication type is SaS.

@huguesBouvier
Copy link
Contributor

The patch made for edgeHub now allows module identity to be created from leaf devices, even when never connected directly to iotHub. So case 2 should work. I tested case2 (create module identity while never connecting directly to iothub) with the C# SDK and by creating my own project.

If it still doesn't work, then there is probably an issue with how the tokens are generated, let's explore that.
Did you get answers from ADU team? Otherwise, let's generate a token differently (with a script or C#) to isolate the issue.

@mlilien
Copy link
Author

mlilien commented Sep 21, 2021

Hi Hugues,

I did not get any answers from ADU team yet.
I understand that you did not test a scenario with iotedge 1.2 and a leaf device which uses iot-identity-service with a module identity yet.
Can you please test such a szenario? Here are logs from iot-identity-service on our leaf client.
Both module applications are not running at time of this log. The log is captured after aziotctl config apply.

leaf aziot system logs
Sep 21 16:55:29 mlilien-rpi3 systemd[1]: Started Azure IoT Identity Service.
Sep 21 16:55:29 mlilien-rpi3 aziot-identityd[6604]: 2021-09-21T16:55:29Z [INFO] - Starting service...
Sep 21 16:55:29 mlilien-rpi3 aziot-identityd[6604]: 2021-09-21T16:55:29Z [INFO] - Version - dev build
Sep 21 16:55:29 mlilien-rpi3 aziot-identityd[6604]: 2021-09-21T16:55:29Z [INFO] - Provisioning starting. Reason: Startup
Sep 21 16:55:29 mlilien-rpi3 aziot-identityd[6604]: 2021-09-21T16:55:29Z [INFO] - Updated device info for mlilien-rpi3.
Sep 21 16:55:29 mlilien-rpi3 aziot-identityd[6604]: 2021-09-21T16:55:29Z [INFO] - Provisioning complete.
Sep 21 16:55:29 mlilien-rpi3 aziot-identityd[6604]: 2021-09-21T16:55:29Z [INFO] - Identity reconciliation started. Reason: Startup
Sep 21 16:55:29 mlilien-rpi3 aziot-identityd[6604]: 2021-09-21T16:55:29Z [DBUG] - [hyper::proto::h1::io] flushed 71 bytes
Sep 21 16:55:29 mlilien-rpi3 aziot-keyd[6588]: 2021-09-21T16:55:29Z [DBUG] - [hyper::proto::h1::io] parsed 1 headers
Sep 21 16:55:29 mlilien-rpi3 aziot-keyd[6588]: 2021-09-21T16:55:29Z [DBUG] - [hyper::proto::h1::conn] incoming body is empty
Sep 21 16:55:29 mlilien-rpi3 aziot-keyd[6588]: 2021-09-21T16:55:29Z [INFO] - <-- GET /key/device-id?api-version=2020-09-01 {"host": "keyd.sock"}
Sep 21 16:55:29 mlilien-rpi3 aziot-keyd[6588]: 2021-09-21T16:55:29Z [INFO] - --> 200 {"content-type": "application/json"}
Sep 21 16:55:29 mlilien-rpi3 aziot-keyd[6588]: 2021-09-21T16:55:29Z [DBUG] - [hyper::proto::h1::io] flushed 349 bytes
Sep 21 16:55:29 mlilien-rpi3 aziot-keyd[6588]: 2021-09-21T16:55:29Z [DBUG] - [hyper::proto::h1::io] parsed 3 headers
Sep 21 16:55:29 mlilien-rpi3 aziot-keyd[6588]: 2021-09-21T16:55:29Z [DBUG] - [hyper::proto::h1::conn] incoming body is content-length (382 bytes)
Sep 21 16:55:29 mlilien-rpi3 aziot-keyd[6588]: 2021-09-21T16:55:29Z [INFO] - <-- POST /sign?api-version=2020-09-01 {"content-type": "application/json", "host": "keyd.sock", "content-length": "382"}
Sep 21 16:55:29 mlilien-rpi3 aziot-keyd[6588]: 2021-09-21T16:55:29Z [DBUG] - [hyper::proto::h1::conn] incoming body completed
Sep 21 16:55:29 mlilien-rpi3 aziot-keyd[6588]: 2021-09-21T16:55:29Z [INFO] - --> 200 {"content-type": "application/json"}
Sep 21 16:55:29 mlilien-rpi3 aziot-keyd[6588]: 2021-09-21T16:55:29Z [DBUG] - [hyper::proto::h1::io] flushed 168 bytes
Sep 21 16:55:29 mlilien-rpi3 aziot-identityd[6604]: 2021-09-21T16:55:29Z [DBUG] - [hyper::proto::h1::io] parsed 3 headers
Sep 21 16:55:29 mlilien-rpi3 aziot-identityd[6604]: 2021-09-21T16:55:29Z [DBUG] - [hyper::proto::h1::conn] incoming body is content-length (240 bytes)
Sep 21 16:55:29 mlilien-rpi3 aziot-identityd[6604]: 2021-09-21T16:55:29Z [DBUG] - [hyper::proto::h1::conn] incoming body completed
Sep 21 16:55:29 mlilien-rpi3 aziot-identityd[6604]: 2021-09-21T16:55:29Z [DBUG] - [hyper::client::pool] pooling idle connection for ("http", keyd.sock)
Sep 21 16:55:29 mlilien-rpi3 aziot-identityd[6604]: 2021-09-21T16:55:29Z [DBUG] - [hyper::client::pool] reuse idle connection for ("http", keyd.sock)
Sep 21 16:55:29 mlilien-rpi3 aziot-identityd[6604]: 2021-09-21T16:55:29Z [DBUG] - [hyper::proto::h1::io] flushed 498 bytes
Sep 21 16:55:29 mlilien-rpi3 aziot-identityd[6604]: 2021-09-21T16:55:29Z [DBUG] - [hyper::proto::h1::io] parsed 3 headers
Sep 21 16:55:29 mlilien-rpi3 aziot-identityd[6604]: 2021-09-21T16:55:29Z [DBUG] - [hyper::proto::h1::conn] incoming body is content-length (60 bytes)
Sep 21 16:55:29 mlilien-rpi3 aziot-identityd[6604]: 2021-09-21T16:55:29Z [DBUG] - [hyper::proto::h1::conn] incoming body completed
Sep 21 16:55:29 mlilien-rpi3 aziot-identityd[6604]: 2021-09-21T16:55:29Z [DBUG] - [hyper::client::pool] pooling idle connection for ("http", keyd.sock)
Sep 21 16:55:29 mlilien-rpi3 aziot-identityd[6604]: 2021-09-21T16:55:29Z [DBUG] - [hyper::client::connect::dns] resolving host="raspberrypi4-64"
Sep 21 16:55:29 mlilien-rpi3 aziot-identityd[6604]: 2021-09-21T16:55:29Z [DBUG] - [hyper::client::connect::http] connecting to [fd00::dea6:32ff:fe55:90ca]:443
Sep 21 16:55:29 mlilien-rpi3 aziot-identityd[6604]: 2021-09-21T16:55:29Z [DBUG] - [hyper::client::connect::http] connected to [fd00::dea6:32ff:fe55:90ca]:443
Sep 21 16:55:29 mlilien-rpi3 aziot-identityd[6604]: 2021-09-21T16:55:29Z [DBUG] - [h2::client] binding client connection
Sep 21 16:55:29 mlilien-rpi3 aziot-identityd[6604]: 2021-09-21T16:55:29Z [DBUG] - [h2::client] client connection bound
Sep 21 16:55:29 mlilien-rpi3 aziot-identityd[6604]: 2021-09-21T16:55:29Z [DBUG] - [h2::codec::framed_write] send frame=Settings { flags: (0x0), enable_push: 0, initial_window_size: 2097152, max_frame_size: 16384 }
Sep 21 16:55:29 mlilien-rpi3 aziot-identityd[6604]: 2021-09-21T16:55:29Z [DBUG] - [h2::proto::connection] Connection; peer=Client
Sep 21 16:55:29 mlilien-rpi3 aziot-identityd[6604]: 2021-09-21T16:55:29Z [DBUG] - [h2::codec::framed_write] send frame=WindowUpdate { stream_id: StreamId(0), size_increment: 5177345 }
Sep 21 16:55:29 mlilien-rpi3 aziot-identityd[6604]: 2021-09-21T16:55:29Z [DBUG] - [hyper::client::pool] pooling idle connection for ("https", raspberrypi4-64)
Sep 21 16:55:29 mlilien-rpi3 aziot-identityd[6604]: 2021-09-21T16:55:29Z [DBUG] - [h2::codec::framed_read] received frame=Settings { flags: (0x0), max_concurrent_streams: 100, initial_window_size: 98304, max_header_list_size: 32768 }
Sep 21 16:55:29 mlilien-rpi3 aziot-identityd[6604]: 2021-09-21T16:55:29Z [DBUG] - [h2::codec::framed_write] send frame=Settings { flags: (0x1: ACK) }
Sep 21 16:55:29 mlilien-rpi3 aziot-identityd[6604]: 2021-09-21T16:55:29Z [DBUG] - [h2::codec::framed_read] received frame=WindowUpdate { stream_id: StreamId(0), size_increment: 65537 }
Sep 21 16:55:29 mlilien-rpi3 aziot-identityd[6604]: 2021-09-21T16:55:29Z [DBUG] - [h2::codec::framed_write] send frame=Headers { stream_id: StreamId(1), flags: (0x5: END_HEADERS | END_STREAM) }
Sep 21 16:55:29 mlilien-rpi3 aziot-identityd[6604]: 2021-09-21T16:55:29Z [DBUG] - [h2::codec::framed_read] received frame=Settings { flags: (0x1: ACK) }
Sep 21 16:55:29 mlilien-rpi3 aziot-identityd[6604]: 2021-09-21T16:55:29Z [DBUG] - [h2::proto::settings] received settings ACK; applying Settings { flags: (0x0), enable_push: 0, initial_window_size: 2097152, max_frame_size: 16384 }
Sep 21 16:55:29 mlilien-rpi3 aziot-identityd[6604]: 2021-09-21T16:55:29Z [DBUG] - [h2::codec::framed_read] received frame=Headers { stream_id: StreamId(1), flags: (0x4: END_HEADERS) }
Sep 21 16:55:29 mlilien-rpi3 aziot-identityd[6604]: 2021-09-21T16:55:29Z [DBUG] - [h2::codec::framed_read] received frame=Data { stream_id: StreamId(1) }
Sep 21 16:55:29 mlilien-rpi3 aziot-identityd[6604]: 2021-09-21T16:55:29Z [DBUG] - [aziot_hub_client_async] IoTHub response status 401
Sep 21 16:55:29 mlilien-rpi3 aziot-identityd[6604]: 2021-09-21T16:55:29Z [DBUG] - [aziot_hub_client_async] IoTHub response headers{"date": "Tue, 21 Sep 2021 16:55:29 GMT", "content-type": "application/json; charset=utf-8", "server": "Kestrel", "content-length": "161", "x-content-type-options": "nosniff"}
Sep 21 16:55:29 mlilien-rpi3 aziot-identityd[6604]: 2021-09-21T16:55:29Z [DBUG] - [h2::codec::framed_read] received frame=Data { stream_id: StreamId(1), flags: (0x1: END_STREAM) }
Sep 21 16:55:29 mlilien-rpi3 aziot-identityd[6604]: 2021-09-21T16:55:29Z [INFO] - Could not reconcile Identities with current device data. Reprovisioning.
Sep 21 16:55:29 mlilien-rpi3 aziot-identityd[6604]: 2021-09-21T16:55:29Z [INFO] - Updated device info for mlilien-rpi3.
Sep 21 16:55:29 mlilien-rpi3 aziot-identityd[6604]: 2021-09-21T16:55:29Z [DBUG] - [hyper::client::pool] reuse idle connection for ("http", keyd.sock)
Sep 21 16:55:29 mlilien-rpi3 aziot-identityd[6604]: 2021-09-21T16:55:29Z [DBUG] - [h2::codec::framed_write] send frame=GoAway { error_code: NO_ERROR, last_stream_id: StreamId(0) }
Sep 21 16:55:29 mlilien-rpi3 aziot-identityd[6604]: 2021-09-21T16:55:29Z [DBUG] - [h2::proto::connection] Connection::poll; connection error error=NO_ERROR
Sep 21 16:55:29 mlilien-rpi3 aziot-identityd[6604]: 2021-09-21T16:55:29Z [DBUG] - [hyper::proto::h1::io] flushed 71 bytes
Sep 21 16:55:29 mlilien-rpi3 aziot-keyd[6588]: 2021-09-21T16:55:29Z [DBUG] - [hyper::proto::h1::io] parsed 1 headers
Sep 21 16:55:29 mlilien-rpi3 aziot-keyd[6588]: 2021-09-21T16:55:29Z [DBUG] - [hyper::proto::h1::conn] incoming body is empty
Sep 21 16:55:29 mlilien-rpi3 aziot-keyd[6588]: 2021-09-21T16:55:29Z [INFO] - <-- GET /key/device-id?api-version=2020-09-01 {"host": "keyd.sock"}
Sep 21 16:55:29 mlilien-rpi3 aziot-keyd[6588]: 2021-09-21T16:55:29Z [INFO] - --> 200 {"content-type": "application/json"}
Sep 21 16:55:29 mlilien-rpi3 aziot-keyd[6588]: 2021-09-21T16:55:29Z [DBUG] - [hyper::proto::h1::io] flushed 349 bytes
Sep 21 16:55:29 mlilien-rpi3 aziot-identityd[6604]: 2021-09-21T16:55:29Z [DBUG] - [hyper::proto::h1::io] parsed 3 headers
Sep 21 16:55:29 mlilien-rpi3 aziot-identityd[6604]: 2021-09-21T16:55:29Z [DBUG] - [hyper::proto::h1::conn] incoming body is content-length (240 bytes)
Sep 21 16:55:29 mlilien-rpi3 aziot-identityd[6604]: 2021-09-21T16:55:29Z [DBUG] - [hyper::proto::h1::conn] incoming body completed
Sep 21 16:55:29 mlilien-rpi3 aziot-identityd[6604]: 2021-09-21T16:55:29Z [DBUG] - [hyper::client::pool] pooling idle connection for ("http", keyd.sock)
Sep 21 16:55:29 mlilien-rpi3 aziot-identityd[6604]: 2021-09-21T16:55:29Z [DBUG] - [hyper::client::pool] reuse idle connection for ("http", keyd.sock)
Sep 21 16:55:29 mlilien-rpi3 aziot-identityd[6604]: 2021-09-21T16:55:29Z [DBUG] - [hyper::proto::h1::io] flushed 498 bytes
Sep 21 16:55:29 mlilien-rpi3 aziot-identityd[6604]: 2021-09-21T16:55:29Z [DBUG] - [hyper::proto::h1::io] parsed 3 headers
Sep 21 16:55:29 mlilien-rpi3 aziot-identityd[6604]: 2021-09-21T16:55:29Z [DBUG] - [hyper::proto::h1::conn] incoming body is content-length (60 bytes)
Sep 21 16:55:29 mlilien-rpi3 aziot-identityd[6604]: 2021-09-21T16:55:29Z [DBUG] - [hyper::proto::h1::conn] incoming body completed
Sep 21 16:55:29 mlilien-rpi3 aziot-identityd[6604]: 2021-09-21T16:55:29Z [DBUG] - [hyper::client::pool] pooling idle connection for ("http", keyd.sock)
Sep 21 16:55:29 mlilien-rpi3 aziot-keyd[6588]: 2021-09-21T16:55:29Z [DBUG] - [hyper::proto::h1::io] parsed 3 headers
Sep 21 16:55:29 mlilien-rpi3 aziot-keyd[6588]: 2021-09-21T16:55:29Z [DBUG] - [hyper::proto::h1::conn] incoming body is content-length (382 bytes)
Sep 21 16:55:29 mlilien-rpi3 aziot-keyd[6588]: 2021-09-21T16:55:29Z [INFO] - <-- POST /sign?api-version=2020-09-01 {"content-type": "application/json", "host": "keyd.sock", "content-length": "382"}
Sep 21 16:55:29 mlilien-rpi3 aziot-keyd[6588]: 2021-09-21T16:55:29Z [DBUG] - [hyper::proto::h1::conn] incoming body completed
Sep 21 16:55:29 mlilien-rpi3 aziot-keyd[6588]: 2021-09-21T16:55:29Z [INFO] - --> 200 {"content-type": "application/json"}
Sep 21 16:55:29 mlilien-rpi3 aziot-keyd[6588]: 2021-09-21T16:55:29Z [DBUG] - [hyper::proto::h1::io] flushed 168 bytes
Sep 21 16:55:29 mlilien-rpi3 aziot-identityd[6604]: 2021-09-21T16:55:29Z [DBUG] - [hyper::client::connect::dns] resolving host="raspberrypi4-64"
Sep 21 16:55:29 mlilien-rpi3 aziot-identityd[6604]: 2021-09-21T16:55:29Z [DBUG] - [hyper::client::connect::http] connecting to [fd00::dea6:32ff:fe55:90ca]:443
Sep 21 16:55:29 mlilien-rpi3 aziot-identityd[6604]: 2021-09-21T16:55:29Z [DBUG] - [hyper::client::connect::http] connected to [fd00::dea6:32ff:fe55:90ca]:443
Sep 21 16:55:29 mlilien-rpi3 aziot-identityd[6604]: 2021-09-21T16:55:29Z [DBUG] - [h2::client] binding client connection
Sep 21 16:55:29 mlilien-rpi3 aziot-identityd[6604]: 2021-09-21T16:55:29Z [DBUG] - [h2::client] client connection bound
Sep 21 16:55:29 mlilien-rpi3 aziot-identityd[6604]: 2021-09-21T16:55:29Z [DBUG] - [h2::codec::framed_write] send frame=Settings { flags: (0x0), enable_push: 0, initial_window_size: 2097152, max_frame_size: 16384 }
Sep 21 16:55:29 mlilien-rpi3 aziot-identityd[6604]: 2021-09-21T16:55:29Z [DBUG] - [h2::proto::connection] Connection; peer=Client
Sep 21 16:55:29 mlilien-rpi3 aziot-identityd[6604]: 2021-09-21T16:55:29Z [DBUG] - [h2::codec::framed_write] send frame=WindowUpdate { stream_id: StreamId(0), size_increment: 5177345 }
Sep 21 16:55:29 mlilien-rpi3 aziot-identityd[6604]: 2021-09-21T16:55:29Z [DBUG] - [hyper::client::pool] pooling idle connection for ("https", raspberrypi4-64)
Sep 21 16:55:29 mlilien-rpi3 aziot-identityd[6604]: 2021-09-21T16:55:29Z [DBUG] - [h2::codec::framed_write] send frame=Headers { stream_id: StreamId(1), flags: (0x5: END_HEADERS | END_STREAM) }
Sep 21 16:55:29 mlilien-rpi3 aziot-identityd[6604]: 2021-09-21T16:55:29Z [DBUG] - [h2::codec::framed_read] received frame=Settings { flags: (0x0), max_concurrent_streams: 100, initial_window_size: 98304, max_header_list_size: 32768 }
Sep 21 16:55:29 mlilien-rpi3 aziot-identityd[6604]: 2021-09-21T16:55:29Z [DBUG] - [h2::codec::framed_write] send frame=Settings { flags: (0x1: ACK) }
Sep 21 16:55:29 mlilien-rpi3 aziot-identityd[6604]: 2021-09-21T16:55:29Z [DBUG] - [h2::codec::framed_read] received frame=WindowUpdate { stream_id: StreamId(0), size_increment: 65537 }
Sep 21 16:55:29 mlilien-rpi3 aziot-identityd[6604]: 2021-09-21T16:55:29Z [DBUG] - [h2::codec::framed_read] received frame=Settings { flags: (0x1: ACK) }
Sep 21 16:55:29 mlilien-rpi3 aziot-identityd[6604]: 2021-09-21T16:55:29Z [DBUG] - [h2::proto::settings] received settings ACK; applying Settings { flags: (0x0), enable_push: 0, initial_window_size: 2097152, max_frame_size: 16384 }
Sep 21 16:55:30 mlilien-rpi3 aziot-identityd[6604]: 2021-09-21T16:55:30Z [DBUG] - [h2::codec::framed_read] received frame=Headers { stream_id: StreamId(1), flags: (0x4: END_HEADERS) }
Sep 21 16:55:30 mlilien-rpi3 aziot-identityd[6604]: 2021-09-21T16:55:30Z [DBUG] - [h2::codec::framed_read] received frame=Data { stream_id: StreamId(1) }
Sep 21 16:55:30 mlilien-rpi3 aziot-identityd[6604]: 2021-09-21T16:55:30Z [DBUG] - [aziot_hub_client_async] IoTHub response status 401
Sep 21 16:55:30 mlilien-rpi3 aziot-identityd[6604]: 2021-09-21T16:55:30Z [DBUG] - [aziot_hub_client_async] IoTHub response headers{"date": "Tue, 21 Sep 2021 16:55:29 GMT", "content-type": "application/json; charset=utf-8", "server": "Kestrel", "content-length": "161", "x-content-type-options": "nosniff"}
Sep 21 16:55:30 mlilien-rpi3 aziot-identityd[6604]: 2021-09-21T16:55:30Z [DBUG] - [h2::codec::framed_read] received frame=Data { stream_id: StreamId(1), flags: (0x1: END_STREAM) }
Sep 21 16:55:30 mlilien-rpi3 aziot-identityd[6604]: 2021-09-21T16:55:30Z [DBUG] - [h2::codec::framed_write] send frame=GoAway { error_code: NO_ERROR, last_stream_id: StreamId(0) }
Sep 21 16:55:30 mlilien-rpi3 aziot-identityd[6604]: 2021-09-21T16:55:30Z [DBUG] - [h2::proto::connection] Connection::poll; connection error error=NO_ERROR
Sep 21 16:55:30 mlilien-rpi3 aziot-identityd[6604]: 2021-09-21T16:55:30Z [ERR!] - Failed to provision with IoT Hub, and no valid device backup was found: Hub client error
Sep 21 16:55:30 mlilien-rpi3 aziot-keyd[6588]: 2021-09-21T16:55:30Z [DBUG] - [hyper::proto::h1::conn] read eof
Sep 21 16:55:30 mlilien-rpi3 aziot-identityd[6604]: 2021-09-21T16:55:30Z [ERR!] - service encountered an error
Sep 21 16:55:30 mlilien-rpi3 aziot-identityd[6604]: 2021-09-21T16:55:30Z [ERR!] - caused by: Hub client error
Sep 21 16:55:30 mlilien-rpi3 aziot-identityd[6604]: 2021-09-21T16:55:30Z [ERR!] - caused by: ErrorCode:IotHubUnauthorizedAccess;Unauthorized
Sep 21 16:55:30 mlilien-rpi3 aziot-identityd[6604]: 2021-09-21T16:55:30Z [ERR!] -    0: <unknown>
Sep 21 16:55:30 mlilien-rpi3 aziot-identityd[6604]:    1: <unknown>
Sep 21 16:55:30 mlilien-rpi3 aziot-identityd[6604]:    2: <unknown>
Sep 21 16:55:30 mlilien-rpi3 aziot-identityd[6604]:    3: <unknown>
Sep 21 16:55:30 mlilien-rpi3 aziot-identityd[6604]:    4: <unknown>
Sep 21 16:55:30 mlilien-rpi3 aziot-identityd[6604]:    5: <unknown>
Sep 21 16:55:30 mlilien-rpi3 aziot-identityd[6604]:    6: <unknown>
Sep 21 16:55:30 mlilien-rpi3 aziot-identityd[6604]:    7: <unknown>
Sep 21 16:55:30 mlilien-rpi3 aziot-identityd[6604]:    8: <unknown>
Sep 21 16:55:30 mlilien-rpi3 aziot-identityd[6604]:    9: <unknown>
Sep 21 16:55:30 mlilien-rpi3 aziot-identityd[6604]:   10: <unknown>
Sep 21 16:55:30 mlilien-rpi3 aziot-identityd[6604]:   11: <unknown>
Sep 21 16:55:30 mlilien-rpi3 aziot-identityd[6604]:   12: <unknown>
Sep 21 16:55:30 mlilien-rpi3 aziot-identityd[6604]:   13: <unknown>
Sep 21 16:55:30 mlilien-rpi3 aziot-identityd[6604]:   14: __libc_start_main
Sep 21 16:55:30 mlilien-rpi3 systemd[1]: aziot-identityd.service: Main process exited, code=exited, status=1/FAILURE
Sep 21 16:55:30 mlilien-rpi3 systemd[1]: aziot-identityd.service: Failed with result 'exit-code'.

I tested case2 (create module identity while never connecting directly to iothub) with the C# SDK and by creating my own project.

Can you verify that iot-identity-service is supposed to do that in our described scenario?

Otherwise, let's generate a token differently (with a script or C#) to isolate the issue.

Is there an existing script/application which I can use for that?

@huguesBouvier
Copy link
Contributor

huguesBouvier commented Sep 21, 2021

Hi!

You're right, I didn't use IS but it doesn't matter, IS is just safe keeping the secret key. In using C# I just put the key directly in plain text using in the code (see the xxx below). The important part is the API call to edgeHub and that API call is identical.
That's what I meant by "If it still doesn't work, then there is probably an issue with how the tokens are generated"
The token is probably wrong, that's why it is not getting recognized by edgeHub.

Is there some piece of code that you can share, in how you use IS to generate token?

This is the code I used:

  string connectionString = "HostName=xxxxx;DeviceId=leaf;SharedAccessKey=xxxxx;GatewayHostname=20.51.236.46";       
  string deviceName = "leaf";

  var transportSettings = new AmqpTransportSettings(Microsoft.Azure.Devices.Client.TransportType.Amqp_Tcp_Only);
  transportSettings.RemoteCertificateValidationCallback = (sender, certificate, chain, sslPolicyErrors) => { return true; };
  transportSettings.OpenTimeout = TimeSpan.FromMinutes(60);
  transportSettings.OperationTimeout = TimeSpan.FromMinutes(60);
  transportSettings.IdleTimeout = TimeSpan.FromMinutes(60);

  Console.WriteLine("Opening upstream connection...");
  Console.Write(connectionString);
  var client = DeviceClient.CreateFromConnectionString(connectionString, new[] { transportSettings });

  client.SetConnectionStatusChangesHandler(ConnectionStatusChangedCallback);
  await client.OpenAsync();
  await client.SetMethodDefaultHandlerAsync(DirectMethodHandler, null);
  await client.SetDesiredPropertyUpdateCallbackAsync(DesiredPropertyhandler, null);

  Console.Write("Module Name: ");
  string moduleName = Console.ReadLine();
  string input = string.Empty;
  await AddModuleAsync(connectionString, deviceName, moduleName);
static async Task AddModuleAsync(string connectionString, string deviceName, string moduleName)
        {
            RegistryManager registryManager =
              RegistryManager.CreateFromConnectionString(connectionString);
            Microsoft.Azure.Devices.Module module;

            try
            {
                module =
                  await registryManager.AddModuleAsync(new Microsoft.Azure.Devices.Module(deviceName, moduleName));
            }
            catch (ModuleAlreadyExistsException)
            {
                module = await registryManager.GetModuleAsync(deviceName, moduleName);
            }

            Console.WriteLine("Generated module key: {0}", module.Authentication.SymmetricKey.PrimaryKey);
        }

I'll test with IS. I'll post the code when I am done.

@ValOlson
Copy link

@JanZachmann / @huguesBouvier: Can you confirm if you have the ADU agent working on the downstream device? ADU use IS to retrieve or create the provisioning information for the agents connection to the IOT Hub, so if you are not using IS then did you manually update ADU's config.txt file with the connection string? Is there open question do you have for the ADU team?

@JanZachmann
Copy link

@ValOlson Yes I can confirm that our downstream/leaf device has ADU running as module identity using IS. This causes the same misbehaviour as described by @mlilien and what we also see with other module identities behind a gateway.
We would now wait for @huguesBouvier to come back with some test results.

@huguesBouvier
Copy link
Contributor

I am going to try with IS tomorrow. I'll let you know the result.

@huguesBouvier
Copy link
Contributor

huguesBouvier commented Sep 23, 2021

Hey!

So some results from the test.
It looks like you are right, the SDK seems to be ignoring the gateway parameter and connecting to IoT Hub.
This is the script I used:


# Call IS as the root user to skip the need to add my user to the requisite security groups for IS/KS/CS. 
identity="$(sudo curl --unix-socket '/run/aziot/identityd.sock' 'http://identityd.sock/identities/identity?api-version=2020-09-01')" 

# From the response, retrieve the hubName, gatewayHost, device and module identity, authentication type, and the key handle.
hub_name="$(<<< "$identity" jq -r '.spec.hubName')"
gateway_host="$(<<< "$identity" jq -r '.spec.gatewayHost')"
device_id="$(<<< "$identity" jq -r '.spec.deviceId')"
module_id="$(<<< "$identity" jq -r '.spec.moduleId // ""')"
auth_type="$(<<< "$identity" jq -r '.spec.auth.type')"
key_handle="$(<<< "$identity" jq -r '.spec.auth.keyHandle')"

module_id="mymodule"
# URL-encode the resource of hub + device + module
# If we were doing this for the device identity, the resource_uri wouldn't include the '/modules/%s'
resource_uri="$(printf '%s/devices/%s' "$hub_name" "$device_id" | jq -sRr @uri)"

# Expiry of 1 day from today in Unix epoch time
expiry="$(bc <<< "$(date +%s) + 60 * 60 * 24")"

# Full string to be signed is a base64-encoded string containing the URL-encoded resource URI and the expiry
signature_data="$(printf '%s\n%s' "$resource_uri" "$expiry" | base64 -w 0)"

# Parse and URL-decode the 'signature' from the response
signature="$(
    sudo curl --unix-socket '/run/aziot/keyd.sock' \
        -X POST -H 'content-type: application/json' --data-raw "$(
            jq -cn --arg 'keyHandle' "$key_handle" --arg 'message' "$signature_data" '{
                "keyHandle": $keyHandle,
                "algorithm": "HMAC-SHA256",
                "parameters": {
                    "message": $message,
                },
            }'
        )" 'http://keyd.sock/sign?api-version=2020-09-01' |
        jq '.signature' -r |
        sed -e 's|+|%2b|g' -e 's|/|%2f|g' -e 's|=|%3d|g'
)"

# Construct the full SaS token
sas_token="$(printf 'sr=%s&se=%s&sig=%s' "$resource_uri" "$expiry" "$signature")"

# Note that the 'SharedAccessSignature' appears both in the connection string and in the value for it.
sas="SharedAccessSignature $sas_token"

body="{'moduleId':'${module_id}',"deviceId":'${device_id}'}"
echo "$(curl -v --insecure --request PUT  --url "https://10.1.0.5/devices/${device_id}/modules/${module_id}?api-version=2017-11-08-preview" --header "Connection: close" --header "Host: edgehub" --header "Content-Type: application/json" --header "Authorization: $sas" -d "${body}")"
echo ${device_id}
body="{'moduleId':'${module_id}','deviceId':'${device_id}','authentication':{'symmetricKey':{'primaryKey':'xxxx','secondaryKey':'xxxxx'},'type':'sas'}}"
echo "$(curl -v --insecure --request PUT  --url "https://10.1.0.5/devices/${device_id}/modules/${module_id}?api-version=2017-11-08-preview" --header "Connection: close" --header "Host: edgehub" --header "Content-Type: application/json" --header "if-match: *" --header "Authorization: $sas" -d "${body}")"

And the result I got was the edgeHub is ok with the token, but actually iothub is not:

Request starting HTTP/1.1 PUT https://edgehub/devices/leaf/modules/mymodule?api-version=2017-11-08-preview application/json 212
Executing endpoint '"Microsoft.Azure.Devices.Edge.Hub.Http.Controllers.RegistryController.CreateOrUpdateModuleAsync (Microsoft.Azure.Devices.Edge.Hub.Http)"'
Route matched with "{action = \"CreateOrUpdateModule\", controller = \"Registry\"}". Executing controller action with signature "System.Threading.Tasks.Task CreateOrUpdateModuleAsync(System.String, System.String, System.String, Microsoft.Azure.Devices.Module)" on controller "Microsoft.Azure.Devices.Edge.Hub.Http.Controllers.RegistryController" ("Microsoft.Azure.Devices.Edge.Hub.Http").
Received request in CreateOrUpdateModuleAsync: deviceId=leaf, moduleId=mymodule
Client leaf in device scope authenticated locally.
Authenticated: deviceId=leaf, moduleId=
 CompleteRequest in CreateOrUpdateModuleAsync: deviceId=top-layer, authChain=leaf;top-layer, status=Unauthorized

Can you confirm that you observe the same thing (edgeHub is ok but iotHub return status=unauthorized?)

The "status=Unauthorized" seems to be the response from iotHub. The token is correctly validated by edgeHub though. I tried tampering the token and then edgeHub is unhappy:
Error authenticating token for leaf because the token did not match the primary or the secondary key. Error - The specified SAS token has an invalid signature. It does not match either the primary or secondary key

It looks like iothub doesn't like that edgeHub module on behalf of the leaf. I'll reach out to iotHub and let you know.

@huguesBouvier
Copy link
Contributor

Using Kusto and looking at the IoTHub code we have confirmed that some changes needs to be made on IoTHub side:
image

I have created a ticket with the IoTHub though I don't have an ETA as to when it will be fixed.

FYI: I also have created a ticket with the IoT SDK team to request support for gateway hostname in the SDK too: Azure/azure-iot-sdk-csharp#2175

@JanZachmann
Copy link

Hello @huguesBouvier
I guess you don't have news about the state of the IoTHub ticket? Is there a way for us to track that ticket? We don't want to miss the fix (-;
@ValOlson do you track the issue as well since ADU also depends on a fix?
Regards Jan

@huguesBouvier
Copy link
Contributor

@JanZachmann I can only say we are discussing with them. It might take a while.

@shaeussler
Copy link

I think I see the same error when I'm using AMQP in the following command line program with a module identity and no gateway:

./ConsoleApp23 "Amqp_Tcp_Only" "HostName=XXXXXXXXXXXX.azure-devices.net;DeviceId=testdevice;ModuleId=mymodule;SharedAccessSignature=SharedAccessSignature sr=XXXXXXXXXXXX.azure-devices.net%2fdevices%2ftestdevice&se=1639072929&sig=kAkcKWxdFVvm7ulVj8zaEhAhnPLiGaDEoqsRLy6zdnU%3d"
TransportType: Amqp_Tcp_Only
ConnectionString: HostName=XXXXXXXXXXXX.azure-devices.net;DeviceId=testdevice;ModuleId=mymodule;SharedAccessSignature=SharedAccessSignature sr=XXXXXXXXXXXX.azure-devices.net%2fdevices%2ftestdevice&se=1639072929&sig=kAkcKWxdFVvm7ulVj8zaEhAhnPLiGaDEoqsRLy6zdnU%3d
Unhandled exception. Microsoft.Azure.Devices.Client.Exceptions.UnauthorizedException: error(condition:amqp:unauthorized-access,description:Put token failed. status-code: 401, status-description: The specified SAS token has an invalid signature. It does not match either the primary or secondary key..)
 ---> Microsoft.Azure.Amqp.AmqpException: Put token failed. status-code: 401, status-description: The specified SAS token has an invalid signature. It does not match either the primary or secondary key..
   at Microsoft.Azure.Amqp.ExceptionDispatcher.Throw(Exception exception)
   at Microsoft.Azure.Amqp.AsyncResult.End[TAsyncResult](IAsyncResult result)
   at Microsoft.Azure.Amqp.AsyncResult`1.End(IAsyncResult asyncResult)
   at Microsoft.Azure.Amqp.AmqpCbsLink.EndSendToken(IAsyncResult result)
   at Microsoft.Azure.Amqp.AmqpCbsLink.<>c__DisplayClass4_0.<SendTokenAsync>b__1(IAsyncResult a)
   at System.Threading.Tasks.TaskFactory`1.FromAsyncCoreLogic(IAsyncResult , Func`2 , Action`1 , Task`1 , Boolean )
--- End of stack trace from previous location ---
   at Microsoft.Azure.Devices.Client.Transport.AmqpIot.AmqpIotCbsLink.SendTokenAsync(ICbsTokenProvider tokenProvider, Uri namespaceAddress, String audience, String resource, String[] requiredClaims, TimeSpan timeout)
   --- End of inner exception stack trace ---
   at Microsoft.Azure.Devices.Client.Transport.AmqpIot.AmqpIotCbsLink.SendTokenAsync(ICbsTokenProvider tokenProvider, Uri namespaceAddress, String audience, String resource, String[] requiredClaims, TimeSpan timeout)
   at Microsoft.Azure.Devices.Client.Transport.Amqp.AmqpAuthenticationRefresher.InitLoopAsync(TimeSpan timeout)
   at Microsoft.Azure.Devices.Client.Transport.AmqpIot.AmqpIotConnection.CreateRefresherAsync(DeviceIdentity deviceIdentity, TimeSpan timeout)
   at Microsoft.Azure.Devices.Client.Transport.Amqp.AmqpConnectionHolder.CreateRefresherAsync(DeviceIdentity deviceIdentity, TimeSpan timeout)
   at Microsoft.Azure.Devices.Client.Transport.AmqpIot.AmqpUnit.EnsureSessionIsOpenAsync(TimeSpan timeout)
   at Microsoft.Azure.Devices.Client.Transport.AmqpIot.AmqpUnit.OpenAsync(TimeSpan timeout)
   at Microsoft.Azure.Devices.Client.Transport.Amqp.AmqpTransportHandler.OpenAsync(CancellationToken cancellationToken)
   at Microsoft.Azure.Devices.Client.Transport.ProtocolRoutingDelegatingHandler.OpenAsync(CancellationToken cancellationToken)
   at Microsoft.Azure.Devices.Client.Transport.ErrorDelegatingHandler.<>c__DisplayClass27_0.<<ExecuteWithErrorHandlingAsync>b__0>d.MoveNext()
--- End of stack trace from previous location ---
   at Microsoft.Azure.Devices.Client.Transport.ErrorDelegatingHandler.ExecuteWithErrorHandlingAsync[T](Func`1 asyncOperation)
   at Microsoft.Azure.Devices.Client.Transport.RetryDelegatingHandler.<>c__DisplayClass38_0.<<OpenInternalAsync>b__0>d.MoveNext()
--- End of stack trace from previous location ---
   at Microsoft.Azure.Devices.Client.Transport.RetryDelegatingHandler.OpenInternalAsync(Boolean withRetry, CancellationToken cancellationToken)
   at Microsoft.Azure.Devices.Client.Transport.RetryDelegatingHandler.EnsureOpenedAsync(Boolean withRetry, CancellationToken cancellationToken)
   at Microsoft.Azure.Devices.Client.InternalClient.OpenAsync()
   at echo.Program.Init(String connectionString, ITransportSettings settings)
   at echo.Program.Main(String[] args)
   at echo.Program.<Main>(String[] args)
Aborted (core dumped)

./ConsoleApp23 "Mqtt_Tcp_Only" "HostName=XXXXXXXXXXXX.azure-devices.net;DeviceId=testdevice;ModuleId=mymodule;SharedAccessSignature=SharedAccessSignature sr=XXXXXXXXXXXX.azure-devices.net%2fdevices%2ftestdevice&se=1639072929&sig=kAkcKWxdFVvm7ulVj8zaEhAhnPLiGaDEoqsRLy6zdnU%3d"
TransportType: Mqtt_Tcp_Only
ConnectionString: HostName=XXXXXXXXXXXX.azure-devices.net;DeviceId=testdevice;ModuleId=mymodule;SharedAccessSignature=SharedAccessSignature sr=XXXXXXXXXXXX.azure-devices.net%2fdevices%2ftestdevice&se=1639072929&sig=kAkcKWxdFVvm7ulVj8zaEhAhnPLiGaDEoqsRLy6zdnU%3d
IoT Hub module client initialized.
using Microsoft.Azure.Devices.Client;
using Microsoft.Azure.Devices.Client.Transport.Mqtt;
using Microsoft.Azure.Devices.Shared;
using System.Runtime.Loader;

namespace echo
{
   public static class Program
   {
      public static async Task Main(string[] args)
      {
         // Wait until the app unloads or is cancelled
         using var cts = new CancellationTokenSource();
         AssemblyLoadContext.Default.Unloading += (ctx) => cts.Cancel();
         Console.CancelKeyPress += (sender, cpe) => cts.Cancel();

         ITransportSettings settings;

         if (args[0] == "Mqtt_Tcp_Only")
         {
            var mqttSetting = new MqttTransportSettings(TransportType.Mqtt_Tcp_Only);
            mqttSetting.RemoteCertificateValidationCallback = (sender, certificate, chain, sslPolicyErrors) => true;
            settings = mqttSetting;
         }
         else
         {
            var amqpSetting = new AmqpTransportSettings(TransportType.Amqp_Tcp_Only);
            amqpSetting.RemoteCertificateValidationCallback = (sender, certificate, chain, sslPolicyErrors) => true;
            settings = amqpSetting;
         }

         Console.WriteLine($"TransportType: { settings.GetTransportType()}");

         var connectionString = args[1];

         Console.WriteLine($"ConnectionString: {connectionString}");

         await Init(connectionString, settings);

         WhenCancelled(cts.Token).Wait();
      }

      /// <summary>
      /// Handles cleanup operations when app is cancelled or unloads
      /// </summary>
      public static Task WhenCancelled(CancellationToken cancellationToken)
      {
         var tcs = new TaskCompletionSource<bool>();
         _ = cancellationToken.Register(s => ((TaskCompletionSource<bool>)s).SetResult(true), tcs);
         return tcs.Task;
      }

      /// <summary>
      /// Initializes the ModuleClient and sets up the callback to receive
      /// messages containing temperature information
      /// </summary>
      private static async Task Init(string connectionString, ITransportSettings settings)
      {

         // Open a connection to the Edge runtime
         ModuleClient ioTHubModuleClient = ModuleClient.CreateFromConnectionString(connectionString, new ITransportSettings[] { settings });
         await ioTHubModuleClient.OpenAsync();
         Console.WriteLine("IoT Hub module client initialized.");

         ioTHubModuleClient.SetConnectionStatusChangesHandler((status, reason) =>
         {
            Console.WriteLine($"Connection status change registered - status={status}, reason={reason}.");
         });

         _ = ioTHubModuleClient.SetMethodDefaultHandlerAsync((request, client) =>
         {
            Console.WriteLine($"{request.Name}: {request.DataAsJson}");
            return Task.FromResult(new MethodResponse(Array.Empty<byte>(), 200));
         }, ioTHubModuleClient);

         await ioTHubModuleClient.SetDesiredPropertyUpdateCallbackAsync(DesiredPropertyUpdateCallback, null);
      }

      private async static Task DesiredPropertyUpdateCallback(TwinCollection desiredProperties, object userContext)
      {
         Console.WriteLine($"Received desired updates [{desiredProperties.ToJson()}]");

         await Task.Delay(100);
      }
   }
}

@shaeussler
Copy link

Are there any plan for a bug fix?

@huguesBouvier
Copy link
Contributor

There is a plan but It will take a while. It is not a simple fix. This involves edge, SDK and IoTHub.
It is not a bug, IoTEdge was designed originally to be the one to support module, this entails lot's of change to be done, especially on IoTHub side. This will months at least before a fix is out.

damonbarry pushed a commit to damonbarry/iotedge that referenced this issue Apr 15, 2022
Fixing Azure#5155, it is now possible to connect device module through edgeHub as well as creating new modules.

Test:
Connected module through edgeHub using SAS token
Created new module through edgeHub.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

8 participants