Iotedge: Problems when initializing with -Dps -X509IdentityCertificate

[LarsKemmann]

I've been trying to set up X.509 provisioning (group enrollment) with DPS and IoT Edge 1.0.9-rc5, and after running Deploy-IoTEdge (using the rc5 version of the _IotEdgeSecurityDaemon.ps1_ script) I have the following files in my _Downloads_ folder on the Windows Server 2019 VM:

• _iotedge.cer_ -- the public key (certificate is signed by a root CA that was generated via in-house PKI)
• _iotedge.pem_ -- the .cer file re-exported as a base-64 encoded file
• _iotedge.pfx_ -- the signed certificate w/ private key (downloaded from Key Vault; the password is an empty string)

I then run Initialize-IoTEdge -Dps -ScopeId MY_SCOPE_ID -ContainerOs Windows -X509IdentityCertificate file:///C:/Users/MY_USER/Downloads/iotedge.cer -X509IdentityPrivateKey file:///C:/Users/MY_USER/Downloads/iotedge.pfx and get the following error message:

The container host is on supported build version 17763.
System PATH does not require an update.
Generating config.yaml...

Identity certificate file file:///C:/Users/MY_USER/Downloads/iotedge.pem not found.
Initialize-IoTEdge : Exception calling "Invoke" with "1" argument(s): "ScriptHalted"
At line:1 char:1
+ Initialize-IoTEdge -Dps -ScopeId MY_SCOPE_ID -ContainerOs Windows -X5 ...
+ ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
    + CategoryInfo          : NotSpecified: (:) [Initialize-IoTEdge], MethodInvocationException
    + FullyQualifiedErrorId : RuntimeException,Initialize-IoTEdge

I've also tried this with those files sitting in _C:_ and the results are the same. And using the _.pem_ file vs. _.cer_ for the -X509IdentityCertificate argument, or using regular file paths (like C:\iotedge2.cer), makes no difference either.

Any suggestions?

[LarsKemmann]

So it turns out that if I specify the paths as C:/Users/MY_USER/Downloads/iotedge.cer then it works. The one combination that I hadn't tried... It would be good if the documentation around this could be clarified. Also, it appears that my _.pfx_ file with the blank password on it isn't working either, so some guidance on converting _.pfx_ private keys to _.pem_ might be good to include in the documentation when this is released. That's assuming that you can't just update the Initialize-IoTEdge cmdlet to accept a path (in normal formats :)) to a _.pfx_ file -- standard on Windows -- and use that for both the identity certificate and the identity private key parameters.

[lfitchett]

You are correct, we currently do not support file uris from the install scripts. We are unlikely to support .pfx pks.

Thanks for the feedback on the documentation. Tagging @kgremban for awareness.

Is everything working correctly now?

[LarsKemmann]

Thanks for following up! Actually no, things don't quite seem to be working... I'm not sure. The DPS registration worked, I can see the device in my IoT Hub, so I'm assuming it was provisioned with the certificate I provided. However, I see this in the logs:

PS C:\Users\lars> Get-IoTEdgeLog

TimeCreated          Message
-----------          -------
2/25/2020 9:35:11 PM info: iotedged::windows -- Initializing iotedged service.
2/25/2020 9:35:11 PM info: iotedged::app -- Using config file: C:\ProgramData\iotedge\config.yaml
2/25/2020 9:35:11 PM info: iotedged::app -- Version - 1.0.9~rc5 (97a4d2322f28e64dac2b214ce96bd65c5fa192c4)
2/25/2020 9:35:11 PM info: iotedged::app -- Starting Azure IoT Edge Security Daemon
2/25/2020 9:35:11 PM info: iotedged::windows -- Starting iotedged service.
2/25/2020 9:35:11 PM info: iotedged -- Configuring C:\ProgramData\iotedge as the home directory.
2/25/2020 9:35:11 PM info: iotedged -- Configuring certificates...
2/25/2020 9:35:11 PM info: iotedged -- Initializing hsm...
2/25/2020 9:35:11 PM info: iotedged -- Finished configuring provisioning environment variables and certificates.
2/25/2020 9:35:11 PM info: iotedged -- Transparent gateway certificates not found, operating in quick start mode...
2/25/2020 9:35:14 PM info: iotedged -- Initializing hsm X509 interface...
2/25/2020 9:35:14 PM info: iotedged -- Finished initializing hsm.
>>>>>>>>>>>>>>>> Error seen here -- what is causing this?
2/25/2020 9:35:14 PM info: iotedged -- Error loading the hybrid identity key. Re-creating a new key. The daemon could
                     not start up successfully: Could not load the hybrid identity key.
2/25/2020 9:35:14 PM info: iotedged -- Provisioning edge device...
2/25/2020 9:35:14 PM info: iotedged -- Finished initializing hsm X509 interface...
2/25/2020 9:35:14 PM info: iotedged -- Starting provisioning edge device via X509 provisioning...
2/25/2020 9:35:14 PM info: dps::registration -- Starting DPS registration with scope_id "0ne000B90D0", registration_id
                     "iotedge2"
2/25/2020 9:35:14 PM warn: edgelet_utils::logging --    caused by: Could not perform HTTP request                       
2/25/2020 9:35:14 PM warn: edgelet_utils::logging --    caused by: an error occurred trying to connect: The credentials 
                     supplied to the package were not recognized (os error -2146893043)
2/25/2020 9:35:14 PM warn: edgelet_utils::logging -- Could not provision device
2/25/2020 9:35:14 PM warn: edgelet_utils::logging --    caused by: X509 certificate based registration failed           
2/25/2020 9:35:14 PM error: edgelet_utils::logging --   caused by: Could not restore previous provisioning result
2/25/2020 9:35:14 PM error: edgelet_utils::logging --   caused by: The system cannot find the file specified. (os error
                     2)
2/25/2020 9:35:14 PM error: iotedged::windows -- Error while running service. Quitting.
2/25/2020 9:35:14 PM error: edgelet_utils::logging -- The daemon could not start up successfully: Could not initialize
                     DPS provisioning client
2/25/2020 9:35:15 PM info: iotedged -- Configuring certificates...
2/25/2020 9:35:15 PM info: iotedged -- Configuring C:\ProgramData\iotedge as the home directory.
2/25/2020 9:35:15 PM info: iotedged -- Transparent gateway certificates not found, operating in quick start mode...
2/25/2020 9:35:15 PM info: iotedged -- Initializing hsm...
2/25/2020 9:35:15 PM info: iotedged -- Finished configuring provisioning environment variables and certificates.
2/25/2020 9:35:15 PM info: iotedged::app -- Starting Azure IoT Edge Security Daemon
2/25/2020 9:35:15 PM info: iotedged::windows -- Initializing iotedged service.
2/25/2020 9:35:15 PM info: iotedged::app -- Version - 1.0.9~rc5 (97a4d2322f28e64dac2b214ce96bd65c5fa192c4)
2/25/2020 9:35:15 PM info: iotedged::windows -- Starting iotedged service.
2/25/2020 9:35:15 PM info: iotedged::app -- Using config file: C:\ProgramData\iotedge\config.yaml
2/25/2020 9:35:15 PM info: iotedged -- Initializing hsm X509 interface...
2/25/2020 9:35:15 PM info: iotedged -- Finished initializing hsm.
2/25/2020 9:35:15 PM info: iotedged -- Finished initializing hsm X509 interface...
2/25/2020 9:35:15 PM info: dps::registration -- Starting DPS registration with scope_id "0ne000B90D0", registration_id
                     "iotedge2"
2/25/2020 9:35:15 PM info: iotedged -- Starting provisioning edge device via X509 provisioning...
2/25/2020 9:35:15 PM info: iotedged -- Provisioning edge device...
2/25/2020 9:35:26 PM info: provisioning::provisioning -- DPS registration assigned device "iotedge2" in hub
                     "worksense-dev.azure-devices.net"
2/25/2020 9:35:26 PM info: iotedged -- Initializing the module runtime...
2/25/2020 9:35:26 PM info: iotedged -- Finished provisioning edge device.
2/25/2020 9:35:26 PM info: iotedged -- Successful DPS provisioning.
2/25/2020 9:35:26 PM info: edgelet_docker::runtime -- Initializing module runtime...
2/25/2020 9:35:26 PM info: edgelet_docker::runtime -- Using runtime network id nat
2/25/2020 9:35:26 PM info: iotedged -- Reprovisioning status InitialAssignment will trigger reconfiguration of modules.
2/25/2020 9:35:26 PM info: iotedged -- Finished initializing the module runtime.
2/25/2020 9:35:26 PM info: edgelet_docker::runtime -- Successfully initialized module runtime
2/25/2020 9:35:26 PM info: iotedged -- Removing all modules...
2/25/2020 9:35:26 PM info: iotedged -- Change to configuration file detected.
2/25/2020 9:35:26 PM info: iotedged -- Detecting if configuration file has changed...
2/25/2020 9:35:26 PM info: iotedged -- Finished removing modules.
2/25/2020 9:35:26 PM info: iotedged -- Edge issuer CA expiration date: 2020-05-25T21:35:13Z
2/25/2020 9:35:27 PM info: iotedged -- Listening on unix:///C:/ProgramData/iotedge/mgmt/sock with 1 thread for
                     management API.
2/25/2020 9:35:27 PM info: iotedged -- Listening on unix:///C:/ProgramData/iotedge/workload/sock with 1 thread for
                     workload API.
2/25/2020 9:35:27 PM info: edgelet_core::watchdog -- Checking edge runtime status
2/25/2020 9:35:27 PM info: iotedged -- Starting management API...
2/25/2020 9:35:27 PM info: iotedged -- Starting workload API...
2/25/2020 9:35:27 PM info: edgelet_core::watchdog -- Starting watchdog with 60 second frequency...
2/25/2020 9:35:27 PM info: edgelet_core::watchdog -- Creating and starting edge runtime module edgeAgent
2/25/2020 9:35:27 PM info: edgelet_core::watchdog -- Updating identity for module $edgeAgent
2/25/2020 9:35:27 PM info: edgelet_docker::runtime -- Pulling image mcr.microsoft.com/azureiotedge-agent:1.0.9-rc5...
2/25/2020 9:35:31 PM info: edgelet_http::logging -- [mgmt] - - - [2020-02-25 21:35:31.452752100 UTC] "GET
                     /modules?api-version=2019-11-05 HTTP/1.1" 200 OK 14 "-" "iotedge/0.1.0" auth_id(-)
2/25/2020 9:35:33 PM info: edgelet_http::logging -- [mgmt] - - - [2020-02-25 21:35:33.522251100 UTC] "GET
                     /modules?api-version=2019-11-05 HTTP/1.1" 200 OK 14 "-" "iotedge/0.1.0" auth_id(-)
2/25/2020 9:35:37 PM info: edgelet_http::logging -- [mgmt] - - - [2020-02-25 21:35:37.524685600 UTC] "GET
                     /modules?api-version=2019-11-05 HTTP/1.1" 200 OK 14 "-" "iotedge/0.1.0" auth_id(-)
2/25/2020 9:35:41 PM info: edgelet_http::logging -- [mgmt] - - - [2020-02-25 21:35:41.522822300 UTC] "GET
                     /modules?api-version=2019-11-05 HTTP/1.1" 200 OK 14 "-" "iotedge/0.1.0" auth_id(-)
2/25/2020 9:36:16 PM info: edgelet_docker::runtime -- Successfully pulled image
                     mcr.microsoft.com/azureiotedge-agent:1.0.9-rc5
2/25/2020 9:36:16 PM info: edgelet_docker::runtime -- Creating module edgeAgent...
2/25/2020 9:36:16 PM info: edgelet_docker::runtime -- Successfully created module edgeAgent
2/25/2020 9:36:16 PM info: edgelet_docker::runtime -- Starting module edgeAgent...
2/25/2020 9:36:19 PM info: edgelet_docker::runtime -- Successfully started module edgeAgent
2/25/2020 9:36:20 PM info: edgelet_http::logging -- [work] - - - [2020-02-25 21:36:20.757830 UTC] "GET
                     /trust-bundle?api-version=2019-01-30 HTTP/1.1" 200 OK 1936 "-" "-" auth_id(-)
2/25/2020 9:36:22 PM info: edgelet_docker::runtime -- Querying system info...
2/25/2020 9:36:22 PM info: edgelet_http::logging -- [mgmt] - - - [2020-02-25 21:36:22.693116100 UTC] "GET
                     /systeminfo?api-version=2019-11-05 HTTP/1.1" 200 OK 109 "-" "-" auth_id(-)
2/25/2020 9:36:22 PM info: edgelet_docker::runtime -- Successfully queried system info
2/25/2020 9:36:23 PM info: edgelet_http::logging -- [mgmt] - - - [2020-02-25 21:36:23.136731800 UTC] "GET
                     /modules?api-version=2019-11-05 HTTP/1.1" 200 OK 455 "-" "-" auth_id(-)
2/25/2020 9:36:23 PM info: edgelet_http::logging -- [work] - - - [2020-02-25 21:36:23.612759500 UTC] "POST
                     /modules/%24edgeAgent/genid/637182633166369917/sign?api-version=2018-06-28 HTTP/1.1" 200 OK 57
                     "-" "-" auth_id(-)
2/25/2020 9:36:27 PM info: edgelet_core::watchdog -- Checking edge runtime status
2/25/2020 9:36:27 PM info: edgelet_core::watchdog -- Edge runtime is running.
2/25/2020 9:36:29 PM info: edgelet_http::logging -- [mgmt] - - - [2020-02-25 21:36:29.407906700 UTC] "GET
                     /modules?api-version=2019-11-05 HTTP/1.1" 200 OK 455 "-" "-" auth_id(-)
2/25/2020 9:36:34 PM info: edgelet_http::logging -- [mgmt] - - - [2020-02-25 21:36:34.420292700 UTC] "GET
                     /modules?api-version=2019-11-05 HTTP/1.1" 200 OK 455 "-" "-" auth_id(-)
2/25/2020 9:36:39 PM info: edgelet_http::logging -- [mgmt] - - - [2020-02-25 21:36:39.437992400 UTC] "GET
                     /modules?api-version=2019-11-05 HTTP/1.1" 200 OK 455 "-" "-" auth_id(-)
2/25/2020 9:36:44 PM info: edgelet_http::logging -- [mgmt] - - - [2020-02-25 21:36:44.455098800 UTC] "GET
                     /modules?api-version=2019-11-05 HTTP/1.1" 200 OK 455 "-" "-" auth_id(-)
2/25/2020 9:36:49 PM info: edgelet_http::logging -- [mgmt] - - - [2020-02-25 21:36:49.463449700 UTC] "GET
                     /modules?api-version=2019-11-05 HTTP/1.1" 200 OK 455 "-" "-" auth_id(-)
2/25/2020 9:36:54 PM info: edgelet_http::logging -- [mgmt] - - - [2020-02-25 21:36:54.475097900 UTC] "GET
                     /modules?api-version=2019-11-05 HTTP/1.1" 200 OK 455 "-" "-" auth_id(-)
2/25/2020 9:36:59 PM info: edgelet_http::logging -- [mgmt] - - - [2020-02-25 21:36:59.486906900 UTC] "GET
                     /modules?api-version=2019-11-05 HTTP/1.1" 200 OK 455 "-" "-" auth_id(-)
2/25/2020 9:37:04 PM info: edgelet_http::logging -- [mgmt] - - - [2020-02-25 21:37:04.505425900 UTC] "GET
                     /modules?api-version=2019-11-05 HTTP/1.1" 200 OK 455 "-" "-" auth_id(-)
2/25/2020 9:37:09 PM info: edgelet_http::logging -- [mgmt] - - - [2020-02-25 21:37:09.522121 UTC] "GET
                     /modules?api-version=2019-11-05 HTTP/1.1" 200 OK 455 "-" "-" auth_id(-)
2/25/2020 9:37:14 PM info: edgelet_http::logging -- [mgmt] - - - [2020-02-25 21:37:14.536144800 UTC] "GET
                     /modules?api-version=2019-11-05 HTTP/1.1" 200 OK 455 "-" "-" auth_id(-)


PS C:\Users\lars> iotedge list
NAME             STATUS           DESCRIPTION      CONFIG
edgeAgent        running          Up a minute      mcr.microsoft.com/azureiotedge-agent:1.0.9-rc5

So something is not quite right. Moreover, the _C:Program Filesiotedgeconfig.yaml_ file is not updating with the X.509 information (or anything else I provided), which I expected the install scripts to do. It's still set to the default manual provisioning configuration with a placeholder "".

[kkdawkins]

Hello!

A couple of questions:

1. Did you use the 1.0.9-rc5 IoTEdgeSecurityDaemon.ps1 when you ran Initialize-IoTEdge or did you source it from aka.ms?
2. Did you export your pfx as a pem file from Windows cert-manager dialog? I believe that in this case, your pem file will have a password (even if you did not give one, it is an empty string). In IoTEdge, we only support pem files without any passwords. You can export the pem file using the openssl CLI instead. See here for details.

[LarsKemmann]

Hi @kkdawkins,

1. Yes, I used the 1.0.9-rc5 script.
2. I did use OpenSSL to convert the file. The leaf certificate and key files were both in PEM format with no password. The leaf certificate did not have the full certificate chain in it (in my case, the "full chain" would be the root and leaf), just the leaf certificate. The root certificate is installed to the trusted root CAs store on the server.

[LarsKemmann]

I tried another variant where the identity certificate PEM file contained both the leaf and root CA certificates, but got a similar result. Again, it looks like everything is provisioning correctly, but the errors in the log are concerning to me and I want to make sure that I address any underlying issue.

Error loading the hybrid identity key. Re-creating a new key. The daemon could not start up successfully: Could not load the hybrid identity key.

What would cause the error in the logs above?

And secondly, the difference in the result this second time is that I did not get the following errors in the logs. Would that be because the identity certificate file contained the root certificate as well?

2/25/2020 9:35:14 PM warn: edgelet_utils::logging --    caused by: Could not perform HTTP request                       
2/25/2020 9:35:14 PM warn: edgelet_utils::logging --    caused by: an error occurred trying to connect: The credentials 
                     supplied to the package were not recognized (os error -2146893043)
2/25/2020 9:35:14 PM warn: edgelet_utils::logging -- Could not provision device
2/25/2020 9:35:14 PM warn: edgelet_utils::logging --    caused by: X509 certificate based registration failed           
2/25/2020 9:35:14 PM error: edgelet_utils::logging --   caused by: Could not restore previous provisioning result
2/25/2020 9:35:14 PM error: edgelet_utils::logging --   caused by: The system cannot find the file specified. (os error
                     2)
2/25/2020 9:35:14 PM error: iotedged::windows -- Error while running service. Quitting.
2/25/2020 9:35:14 PM error: edgelet_utils::logging -- The daemon could not start up successfully: Could not initialize
                     DPS provisioning client

[LarsKemmann]

And one quick update, the _config.yaml_ file is being configured correctly after all. I had been looking at the one in Program Files by mistake -- and not realized I wasn't looking at the one in ProgramData. My bad. :)

So after all that, is the only issue that the runtime is now (per the logs) not able to generate the hybrid identity key that it needs in order to work with leaf devices when operating as a transparent gateway? Because that raises two questions for me:

1. How is that hybrid identity key being generated? Am I losing the chain-of-trust guarantees that I had when my identity certificate was signed by my root CA?
2. If I don't need the transparent gateway functionality, is there a way to turn that off?

[kkdawkins]

So, what is the error that you are seeing now?

If you see a single instance of the "hybrid identity" error then it is not a problem as that is just saying that the key doesnt already exist and will be created. Is the DPS provisioning succeeding or not? If not, is some other error causing EdgeD to exit?

[LarsKemmann]

Hi @kkdawkins, the DPS provisioning is succeeding. I will be testing this a bit more over the next few days to make sure, but EdgeD was not exiting when I tested yesterday. I just wanted to make sure that the hybrid identity key being auto-generated by IoT Edge is not a problem at this point. It sounds like that error message is part of the intended behavior?

[kkdawkins]

Correct - as long as it shows only once, it's fine. Edge will generate the needed key and move forward.

[kkdawkins]

I'll go ahead and close this - feel free to reopen if you run into trouble again!

[arsing]

Also, note that the hybrid identity key has nothing to do with leaf devices or transparent gateways. It is used for deriving module identities.

[LarsKemmann]

Thanks for clarifying @arsing - that's helpful!