iotedge: Automatic provisioning with DPS using X.509 not working using iotedge v1.0.9.3

Expected Behavior

Device is automatically provisioned.

Current Behavior

iotedge fails to start (iotedge.service: Failed with result 'exit-code'.)

Steps to Reproduce

I have tried to follow https://docs.microsoft.com/en-us/azure/iot-edge/how-to-auto-provision-x509-certs to do a Group Enrollment using an Intermediate Certificate . I’ve use certGen.sh to create the certs (after having slightly modified some variables to have the data and expiry I’m looking for). Details below.

Context (Environment)

Output of `iotedge check`

sudo iotedge check --iothub-hostname my-iot-hub.azure-devices.net --verbose

user@my-device:~ $ sudo iotedge check --iothub-hostname my-iot-hub.azure-devices.net --verbose
Configuration checks
--------------------
√ config.yaml is well-formed - OK
√ config.yaml has well-formed connection string - OK
√ container engine is installed and functional - OK
√ config.yaml has correct hostname - OK
× config.yaml has correct URIs for daemon mgmt endpoint - Error
    Error: could not execute list-modules request: an error occurred trying to connect: Connection refused (os error 111)
        caused by: docker returned exit code: 1, stderr = Error: could not execute list-modules request: an error occurred trying to connect: Connection refused (os error 111)
‼ latest security daemon - Warning
    Installed IoT Edge daemon has version 1.0.9.3 but 1.0.9.4 is the latest stable version available.
    Please see https://aka.ms/iotedge-update-runtime for update instructions.
√ host time is close to real time - OK
√ container time is close to host time - OK
√ DNS server - OK
√ production readiness: identity certificates expiry - OK
√ production readiness: certificates - OK
√ production readiness: container engine - OK
‼ 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 - Error
    Could not check current state of edgeAgent container
        caused by: docker returned exit code: 1, stderr = Error: No such object: edgeAgent
× production readiness: Edge Hub's storage directory is persisted on the host filesystem - Error
    Could not check current state of edgeHub container
        caused by: docker returned exit code: 1, stderr = Error: No such object: edgeHub

Connectivity checks
-------------------
√ host can connect to and perform TLS handshake with DPS endpoint - OK
√ host can connect to and perform TLS handshake with IoT Hub AMQP port - OK
√ host can connect to and perform TLS handshake with IoT Hub HTTPS / WebSockets port - OK
√ host can connect to and perform TLS handshake with IoT Hub MQTT port - OK
√ container on the default network can connect to IoT Hub AMQP port - OK
√ container on the default network can connect to IoT Hub HTTPS / WebSockets port - OK
√ container on the default network can connect to IoT Hub MQTT port - OK
× container on the IoT Edge module network can connect to IoT Hub AMQP port - Error
    Container on the azure-iot-edge network could not connect to my-iot-hub.azure-devices.net:5671
        caused by: docker returned exit code: 125, stderr = docker: Error response from daemon: network azure-iot-edge not found.
× container on the IoT Edge module network can connect to IoT Hub HTTPS / WebSockets port - Error
    Container on the azure-iot-edge network could not connect to my-iot-hub.azure-devices.net:443
        caused by: docker returned exit code: 125, stderr = docker: Error response from daemon: network azure-iot-edge not found.
× container on the IoT Edge module network can connect to IoT Hub MQTT port - Error
    Container on the azure-iot-edge network could not connect to my-iot-hub.azure-devices.net:8883
        caused by: docker returned exit code: 125, stderr = docker: Error response from daemon: network azure-iot-edge not found.

17 check(s) succeeded.
2 check(s) raised warnings.
6 check(s) raised errors.

Device Information

Host OS: Raspian Buster
Architecture: arm64
Container OS: Linux containers

Runtime Versions

iotedged [run iotedge version]: iotedge 1.0.9.3
Edge Agent [image tag (e.g. 1.0.0)]:
Edge Hub [image tag (e.g. 1.0.0)]:
Docker/Moby [run docker version]: 3.0.13+azure

Logs

Attempting to use a chain cert and device key…

provisioning:
  source: "dps"
  global_endpoint: "https://global.azure-devices-provisioning.net"
  scope_id: "[redacted id]"
  attestation:
    method: "x509"
#     registration_id: "<OPTIONAL REGISTRATION ID. LEAVE COMMENTED OUT TO REGISTER WITH CN OF identity_cert>"
    identity_cert: "file:///home/pi/my-cert.chain.ca.cert.pem" # contains intermediate and device certs (in that order)
    identity_pk:   "file:///home/pi/new-edge-device.key.pem"

…results in…

user@my-device:~ $ journalctl -u iotedge
Jul 21 19:02:43 my-device systemd[1]: Started Azure IoT Edge daemon.
Jul 21 19:02:43 my-device iotedged[886]: 2020-07-21T18:02:43Z [INFO] - Starting Azure IoT Edge Security Daemon
Jul 21 19:02:43 my-device iotedged[886]: 2020-07-21T18:02:43Z [INFO] - Version - 1.0.9.3
Jul 21 19:02:43 my-device iotedged[886]: 2020-07-21T18:02:43Z [INFO] - Using config file: /etc/iotedge/config.yaml
Jul 21 19:02:43 my-device iotedged[886]: 2020-07-21T18:02:43Z [INFO] - Configuring /var/lib/iotedge as the home directory.
Jul 21 19:02:43 my-device iotedged[886]: 2020-07-21T18:02:43Z [INFO] - Configuring certificates...
Jul 21 19:02:43 my-device iotedged[886]: 2020-07-21T18:02:43Z [INFO] - Transparent gateway certificates not found, operating in quick start mode...
Jul 21 19:02:43 my-device iotedged[886]: 2020-07-21T18:02:43Z [INFO] - Finished configuring provisioning environment variables and certificates.
Jul 21 19:02:43 my-device iotedged[886]: 2020-07-21T18:02:43Z [INFO] - Initializing hsm...
Jul 21 19:02:43 my-device iotedged[886]: 2020-07-21T18:02:43Z [INFO] - Finished initializing hsm.
Jul 21 19:02:43 my-device iotedged[886]: 2020-07-21T18:02:43Z [INFO] - Initializing hsm X509 interface...
Jul 21 19:02:43 my-device iotedged[886]: 2020-07-21T18:02:43Z [ERR!] - The daemon could not start up successfully: Could not initialize HTTP client
Jul 21 19:02:43 my-device iotedged[886]: 2020-07-21T18:02:43Z [ERR!] -         caused by: Could not initialize
Jul 21 19:02:43 my-device iotedged[886]: 2020-07-21T18:02:43Z [ERR!] -         caused by: An error occurred obtaining the client identity certificate
Jul 21 19:02:43 my-device iotedged[886]: 2020-07-21T18:02:43Z [ERR!] -         caused by: error:0B080074:x509 certificate routines:X509_check_private_key:key values mismatch:../crypto/x509/x509_cmp.c:294:
Jul 21 19:02:43 my-device systemd[1]: iotedge.service: Main process exited, code=exited, status=1/FAILURE
Jul 21 19:02:43 my-device systemd[1]: iotedge.service: Failed with result 'exit-code'.

Attempting to use device cert and key…

provisioning:
  source: "dps"
  global_endpoint: "https://global.azure-devices-provisioning.net"
  scope_id: "[redacted id]"
  attestation:
    method: "x509"
#     registration_id: "<OPTIONAL REGISTRATION ID. LEAVE COMMENTED OUT TO REGISTER WITH CN OF identity_cert>"
    identity_cert: "file:///home/pi/new-edge-device.cert.pem"
    identity_pk:   "file:///home/pi/new-edge-device.key.pem"

…results in…

Jul 21 19:13:31 my-device systemd[1]: Started Azure IoT Edge daemon.
Jul 21 19:13:31 my-device iotedged[927]: 2020-07-21T18:13:31Z [INFO] - Starting Azure IoT Edge Security Daemon
Jul 21 19:13:31 my-device iotedged[927]: 2020-07-21T18:13:31Z [INFO] - Version - 1.0.9.3
Jul 21 19:13:31 my-device iotedged[927]: 2020-07-21T18:13:31Z [INFO] - Using config file: /etc/iotedge/config.yaml
Jul 21 19:13:31 my-device iotedged[927]: 2020-07-21T18:13:31Z [INFO] - Configuring /var/lib/iotedge as the home directory.
Jul 21 19:13:31 my-device iotedged[927]: 2020-07-21T18:13:31Z [INFO] - Configuring certificates...
Jul 21 19:13:31 my-device iotedged[927]: 2020-07-21T18:13:31Z [INFO] - Transparent gateway certificates not found, operating in quick start mode...
Jul 21 19:13:31 my-device iotedged[927]: 2020-07-21T18:13:31Z [INFO] - Finished configuring provisioning environment variables and certificates.
Jul 21 19:13:31 my-device iotedged[927]: 2020-07-21T18:13:31Z [INFO] - Initializing hsm...
Jul 21 19:13:31 my-device iotedged[927]: 2020-07-21T18:13:31Z [INFO] - Finished initializing hsm.
Jul 21 19:13:31 my-device iotedged[927]: 2020-07-21T18:13:31Z [INFO] - Initializing hsm X509 interface...
Jul 21 19:13:31 my-device iotedged[927]: 2020-07-21T18:13:31Z [INFO] - Finished initializing hsm X509 interface...
Jul 21 19:13:31 my-device iotedged[927]: 2020-07-21T18:13:31Z [INFO] - Provisioning edge device...
Jul 21 19:13:31 my-device iotedged[927]: 2020-07-21T18:13:31Z [INFO] - Starting provisioning edge device via X509 provisioning...
Jul 21 19:13:31 my-device iotedged[927]: 2020-07-21T18:13:31Z [INFO] - Starting DPS registration with scope_id "[redacted id]]", registration_id "[redacted-uuid].ca"
Jul 21 19:13:31 my-device iotedged[927]: 2020-07-21T18:13:31Z [WARN] - Could not provision device
Jul 21 19:13:31 my-device iotedged[927]: 2020-07-21T18:13:31Z [WARN] -         caused by: X509 certificate based registration failed
Jul 21 19:13:31 my-device iotedged[927]: 2020-07-21T18:13:31Z [WARN] -         caused by: HTTP request failed: [401 Unauthorized] {"errorCode":401002,"trackingId":"0e32a5e7-5214-4ef8-bf68-7620bcee1d5b","message":"Unauthorized","timestampUtc":"2020-07-21T18:13:31.7129299Z"}
Jul 21 19:13:31 my-device iotedged[927]: 2020-07-21T18:13:31Z [ERR!] - The daemon could not start up successfully: Could not initialize DPS provisioning client
Jul 21 19:13:31 my-device iotedged[927]: 2020-07-21T18:13:31Z [ERR!] -         caused by: Could not restore previous provisioning result
Jul 21 19:13:31 my-device iotedged[927]: 2020-07-21T18:13:31Z [ERR!] -         caused by: No such file or directory (os error 2)
Jul 21 19:13:31 my-device systemd[1]: iotedge.service: Main process exited, code=exited, status=1/FAILURE
Jul 21 19:13:31 my-device systemd[1]: iotedge.service: Failed with result 'exit-code'.

Additional Information

I have also tried to have the DPS set to use a “CA Certificate” Certificate Type, using a verified root cert as a primary cert.

I also tried adding the root cert into the my-cert.chain.ca.cert.pem.

About this issue

Original URL
State: closed
Created 4 years ago
Comments: 19 (6 by maintainers)

Most upvoted comments

Oops. I have updated.

and-rewsmith on Jul 23, 2020

I was able to reproduce your problem from my end following the tutorial. I have been talking to others on the team to get more context.

It is still possible this is a configuration issue on both our ends. Our DPS tests currently pass, so I’m trying to figure out what the difference is in the tutorial steps. Also this issue was opened, for which they were also using dps with group enrollment. He was at least able to get an edge device identity from dps so I doubt our problem is a Hub/DPS service issue.

and-rewsmith on Jul 22, 2020

They seem to be where they’re expected. Here’s the references in the config.yaml:

    identity_cert: "file:///home/pi/iot-edge-device-stanCA-full-chain.cert.pem"
    identity_pk:   "file:///home/pi/iot-edge-device-stanCA.key.pem"

And here’s me being able to access them (they opened as expected in nano):

pi@my-device:~ $ sudo nano /etc/iotedge/config.yaml
pi@my-device:~ $ nano /home/pi/iot-edge-device-stanCA-full-chain.cert.pem
pi@my-device:~ $ nano /home/pi/iot-edge-device-stanCA.key.pem
pi@my-device:~ $ pwd
/home/pi
pi@my-device:~ $ ls -ltras
...
 8 -rwxrwxrwx 1 iotedge iotedge 5879 Jul 22 00:31 iot-edge-device-stanCA-full-chain.cert.pem
 4 -rwxrwxrwx 1 iotedge iotedge 3243 Jul 22 00:32 iot-edge-device-stanCA.key.pem

You can also see that I tried to make the files widely readable (777 and iotedge:iotedge).

kpm-at-hfi on Jul 22, 2020

Yeah, I did begin to suspect that I might have chosen the wrong keys or generated them poorly, so that’s why I reworked the whole setup “by the book” this evening (above a few comments ago)… sadly I still wasn’t getting joy.

Basically, the HTTP request failed: [401 Unauthorized] {"errorCode":401002... error in there is what I was seeing most. I suspect the other errors are self inflicted from various thrashing.