Iotedge: IoTedge release 1.0.10 custom certificates edgeAgent Failes

Created on 27 Oct 2020  ยท  47Comments  ยท  Source: Azure/iotedge

Expected Behavior

We are upgrading the IoT edge runtime on some of our devices from 1.0.9.5 to 1.0.10 and everything should work like before where the device can onboard through DPS (with certificates) and running with production certificates

Current Behavior

Currently edgeAgent is not starting up because of an Hsm failure. We use custom production certificates which are valid according to iotedge check. DPS seems to work as expected. Downgrading to version 1.0.9.5 or using the self generated test certificates by Iot Edge solves the problem.

Steps to Reproduce

Provide a detailed set of steps to reproduce the bug.

  1. Install lasted version of IoT edge on Raspbian (sudo install -y iotedge)
  2. Install production certificates
  3. Edit config.yaml to use the production certificates
  4. Restart iotedge

Context (Environment)

Output of iotedge check


Click here

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 - OK
โˆš latest security daemon - OK
โˆš 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 - OK
โ€ผ production readiness: Edge Agent's storage directory is persisted on the host filesystem - Warning
    The edgeAgent module is not configured to persist its /tmp/edgeAgent directory on the host filesystem.
    Data might be lost if the module is deleted or updated.
    Please see https://aka.ms/iotedge-storage-host for best practices.
ร— production readiness: Edge Hub's storage directory is persisted on the host filesystem - Error
    Could not check current state of edgeHub container

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 - OK
โˆš container on the IoT Edge module network can connect to IoT Hub HTTPS / WebSockets port - OK
โˆš container on the IoT Edge module network can connect to IoT Hub MQTT port - OK

23 check(s) succeeded.
1 check(s) raised warnings. Re-run with --verbose for more details.
1 check(s) raised errors. Re-run with --verbose for more details.

Device Information

  • Host OS: Raspbian stretch
  • Architecture: arm64
  • Container OS: Linux containers

Runtime Versions

  • iotedged: 1.0.10-1
  • Edge Agent: 1.0.10
  • Edge Hub: never deployed
  • Docker/Moby : moby-engine (3.0.7)

Logs

sudo iotedge list

NAME             STATUS           DESCRIPTION                CONFIG
edgeAgent        failed           Failed (1) 43 seconds ago  mcr.microsoft.com/azureiotedge-agent:1.0


iotedged logs

-- Logs begin at Thu 2020-10-22 11:01:35 BST. --
Oct 22 11:07:29 dg-p061701-200917-009 iotedged[766]: 2020-10-22T10:07:29Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hs                              m-c/src/certificate_info.c:parse_cer<3>2020-10-22T10:07:29Z [ERR!] - Internal server error: Could not get trust bundle
Oct 22 11:07:29 dg-p061701-200917-009 iotedged[766]:         caused by: An error occurred getting the certificate
Oct 22 11:07:29 dg-p061701-200917-009 iotedged[766]:         caused by: HSM failure
Oct 22 11:07:29 dg-p061701-200917-009 iotedged[766]:         caused by: HSM API returned an invalid null response
Oct 22 11:07:29 dg-p061701-200917-009 iotedged[766]: 2020-10-22T10:07:29Z [INFO] - [work] - - - [2020-10-22 10:07:29.63                              7351901 UTC] "GET /trust-bundle?api-version=2019-01-30 HTTP/1.1" 500 Internal Server Error 178 "-" "-" auth_id(-)
Oct 22 11:07:32 dg-p061701-200917-009 iotedged[766]: 2020-10-22T10:07:32Z [ERR!] - Internal server error: Could not get                               trust bundle
Oct 22 11:07:32 dg-p061701-200917-009 iotedged[766]:         caused by: An error occurred getting the certificate
Oct 22 11:07:32 dg-p061701-200917-009 iotedged[766]:         caused by: HSM failure
Oct 22 11:07:32 dg-p061701-200917-009 iotedged[766]:         caused by: HSM API returned an invalid null response
Oct 22 11:07:32 dg-p061701-200917-009 iotedged[766]: 2020-10-22T10:07:32Z [INFO] - [work] - - - [2020-10-22 10:07:32.67                              9744492 UTC] "GET /trust-bundle?api-version=2019-01-30 HTTP/1.1" 500 Internal Server Error 178 "-" "-" auth_id(-)

-- Logs begin at Thu 2020-10-22 11:01:35 BST. --
Oct 22 11:11:12 dg-p061701-200917-009 iotedged[7464]: 2020-10-22T10:11:12Z [INFO] - Configuring the Device private key using "/etc/iotedge/certs/Device_CA.key.pem".
Oct 22 11:11:12 dg-p061701-200917-009 iotedged[7464]: 2020-10-22T10:11:12Z [INFO] - Configuring the trusted CA certificates using "/etc/iotedge/certs/Root_CA.pem".
Oct 22 11:11:12 dg-p061701-200917-009 iotedged[7464]: 2020-10-22T10:11:12Z [INFO] - Finished configuring provisioning environment variables and certificates.
Oct 22 11:11:12 dg-p061701-200917-009 iotedged[7464]: 2020-10-22T10:11:12Z [INFO] - Initializing hsm...
Oct 22 11:11:12 dg-p061701-200917-009 iotedged[7464]: 2020-10-22T10:11:12Z [INFO] - Finished initializing hsm.
Oct 22 11:11:12 dg-p061701-200917-009 iotedged[7464]: 2020-10-22T10:11:12Z [INFO] - Initializing hsm X509 interface...
Oct 22 11:11:12 dg-p061701-200917-009 iotedged[7464]: 2020-10-22T10:11:12Z [INFO] - Finished initializing hsm X509 interface...
Oct 22 11:11:12 dg-p061701-200917-009 iotedged[7464]: 2020-10-22T10:11:12Z [INFO] - Provisioning edge device...
Oct 22 11:11:12 dg-p061701-200917-009 iotedged[7464]: 2020-10-22T10:11:12Z [INFO] - Starting provisioning edge device via X509 provisioning...
Oct 22 11:11:12 dg-p061701-200917-009 iotedged[7464]: 2020-10-22T10:11:12Z [INFO] - Starting DPS registration with scope_id "0ne0014273D", registration_id "DG-P061701-200917-009"
Oct 22 11:11:23 dg-p061701-200917-009 iotedged[7464]: 2020-10-22T10:11:23Z [INFO] - DPS registration assigned device "DG-P061701-200917-009" in hub "vd-prd-iothub.azure-devices.net"
Oct 22 11:11:23 dg-p061701-200917-009 iotedged[7464]: 2020-10-22T10:11:23Z [INFO] - Successful DPS provisioning.
Oct 22 11:11:23 dg-p061701-200917-009 iotedged[7464]: 2020-10-22T10:11:23Z [INFO] - Finished provisioning edge device.
Oct 22 11:11:23 dg-p061701-200917-009 iotedged[7464]: 2020-10-22T10:11:23Z [INFO] - Initializing the module runtime...
Oct 22 11:11:23 dg-p061701-200917-009 iotedged[7464]: 2020-10-22T10:11:23Z [INFO] - Initializing module runtime...
Oct 22 11:11:23 dg-p061701-200917-009 iotedged[7464]: 2020-10-22T10:11:23Z [INFO] - Using runtime network id azure-iot-edge
Oct 22 11:11:23 dg-p061701-200917-009 iotedged[7464]: 2020-10-22T10:11:23Z [INFO] - Successfully initialized module runtime
Oct 22 11:11:23 dg-p061701-200917-009 iotedged[7464]: 2020-10-22T10:11:23Z [INFO] - Finished initializing the module runtime.
Oct 22 11:11:23 dg-p061701-200917-009 iotedged[7464]: 2020-10-22T10:11:23Z [INFO] - Stopping all modules...
Oct 22 11:11:23 dg-p061701-200917-009 iotedged[7464]: 2020-10-22T10:11:23Z [INFO] - Stopping module edgeAgent...
Oct 22 11:11:23 dg-p061701-200917-009 iotedged[7464]: 2020-10-22T10:11:23Z [WARN] - Could not stop module edgeAgent
Oct 22 11:11:23 dg-p061701-200917-009 iotedged[7464]: 2020-10-22T10:11:23Z [WARN] -         caused by: Target of operation already in this state
Oct 22 11:11:23 dg-p061701-200917-009 iotedged[7464]: 2020-10-22T10:11:23Z [INFO] - Finished stopping modules.
Oct 22 11:11:23 dg-p061701-200917-009 iotedged[7464]: 2020-10-22T10:11:23Z [INFO] - Reprovisioning status InitialAssignment will trigger reconfiguration of modules.
Oct 22 11:11:23 dg-p061701-200917-009 iotedged[7464]: 2020-10-22T10:11:23Z [INFO] - Removing module edgeAgent...
Oct 22 11:11:23 dg-p061701-200917-009 iotedged[7464]: 2020-10-22T10:11:23Z [INFO] - Successfully removed module edgeAgent
Oct 22 11:11:23 dg-p061701-200917-009 iotedged[7464]: 2020-10-22T10:11:23Z [INFO] - Detecting if configuration file has changed...
Oct 22 11:11:23 dg-p061701-200917-009 iotedged[7464]: 2020-10-22T10:11:23Z [INFO] - No change to configuration file detected.
Oct 22 11:11:23 dg-p061701-200917-009 iotedged[7464]: 2020-10-22T10:11:23Z [INFO] - Edge issuer CA expiration date: 2025-10-21T09:50:47Z
Oct 22 11:11:23 dg-p061701-200917-009 iotedged[7464]: 2020-10-22T10:11:23Z [INFO] - Obtaining workload CA succeeded.
Oct 22 11:11:23 dg-p061701-200917-009 iotedged[7464]: 2020-10-22T10:11:23Z [INFO] - Starting management API...
Oct 22 11:11:23 dg-p061701-200917-009 iotedged[7464]: 2020-10-22T10:11:23Z [INFO] - Starting workload API...
Oct 22 11:11:23 dg-p061701-200917-009 iotedged[7464]: 2020-10-22T10:11:23Z [INFO] - Starting watchdog with 60 second frequency...
Oct 22 11:11:23 dg-p061701-200917-009 iotedged[7464]: 2020-10-22T10:11:23Z [INFO] - Listening on fd://iotedge.mgmt.socket/ with 1 thread for management API.
Oct 22 11:11:23 dg-p061701-200917-009 iotedged[7464]: 2020-10-22T10:11:23Z [INFO] - Listening on fd://iotedge.socket/ with 1 thread for workload API.
Oct 22 11:11:23 dg-p061701-200917-009 iotedged[7464]: 2020-10-22T10:11:23Z [INFO] - Checking edge runtime status
Oct 22 11:11:23 dg-p061701-200917-009 iotedged[7464]: 2020-10-22T10:11:23Z [INFO] - Creating and starting edge runtime module edgeAgent
Oct 22 11:11:23 dg-p061701-200917-009 iotedged[7464]: 2020-10-22T10:11:23Z [INFO] - Updating identity for module $edgeAgent
Oct 22 11:11:23 dg-p061701-200917-009 iotedged[7464]: 2020-10-22T10:11:23Z [INFO] - Pulling image mcr.microsoft.com/azureiotedge-agent:1.0...
Oct 22 11:11:24 dg-p061701-200917-009 iotedged[7464]: 2020-10-22T10:11:24Z [INFO] - Successfully pulled image mcr.microsoft.com/azureiotedge-agent:1.0
Oct 22 11:11:24 dg-p061701-200917-009 iotedged[7464]: 2020-10-22T10:11:24Z [INFO] - Creating module edgeAgent...
Oct 22 11:11:24 dg-p061701-200917-009 iotedged[7464]: 2020-10-22T10:11:24Z [INFO] - Successfully created module edgeAgent
Oct 22 11:11:24 dg-p061701-200917-009 iotedged[7464]: 2020-10-22T10:11:24Z [INFO] - Starting module edgeAgent...
Oct 22 11:11:26 dg-p061701-200917-009 iotedged[7464]: 2020-10-22T10:11:26Z [INFO] - Successfully started module edgeAgent
Oct 22 11:11:28 dg-p061701-200917-009 iotedged[7464]: 2020-10-22T10:11:28Z [ERR!] - Internal server error: Could not get trust bundle
Oct 22 11:11:28 dg-p061701-200917-009 iotedged[7464]:         caused by: An error occurred getting the certificate
Oct 22 11:11:28 dg-p061701-200917-009 iotedged[7464]:         caused by: HSM failure
Oct 22 11:11:28 dg-p061701-200917-009 iotedged[7464]:         caused by: HSM API returned an invalid null response
Oct 22 11:11:28 dg-p061701-200917-009 iotedged[7464]: 2020-10-22T10:11:28Z [INFO] - [work] - - - [2020-10-22 10:11:28.393531343 UTC] "GET /trust-bundle?api-version=2019-01-30 HTTP/1.1" 500 Internal Server Error 178 "-" "-" auth_id(-)
Oct 22 11:11:28 dg-p061701-200917-009 iotedged[7464]: 2020-10-22T10:11:28Z [ERR!] - Internal server error: Could not get trust bundle
Oct 22 11:11:28 dg-p061701-200917-009 iotedged[7464]:         caused by: An error occurred getting the certificate
Oct 22 11:11:28 dg-p061701-200917-009 iotedged[7464]:         caused by: HSM failure
Oct 22 11:11:28 dg-p061701-200917-009 iotedged[7464]:         caused by: HSM API returned an invalid null response
Oct 22 11:11:28 dg-p061701-200917-009 iotedged[7464]: 2020-10-22T10:11:28Z [INFO] - [work] - - - [2020-10-22 10:11:28.590992263 UTC] "GET /trust-bundle?api-version=2019-01-30 HTTP/1.1" 500 Internal Server Error 178 "-" "-" auth_id(-)
Oct 22 11:11:31 dg-p061701-200917-009 iotedged[7464]: 2020-10-22T10:11:31Z [ERR!] - Internal server error: Could not get trust bundle
Oct 22 11:11:31 dg-p061701-200917-009 iotedged[7464]:         caused by: An error occurred getting the certificate
Oct 22 11:11:31 dg-p061701-200917-009 iotedged[7464]:         caused by: HSM failure
Oct 22 11:11:31 dg-p061701-200917-009 iotedged[7464]:         caused by: HSM API returned an invalid null response
Oct 22 11:11:31 dg-p061701-200917-009 iotedged[7464]: 2020-10-22T10:11:31Z [INFO] - [work] - - - [2020-10-22 10:11:31.674695998 UTC] "GET /trust-bundle?api-version=2019-01-30 HTTP/1.1" 500 Internal Server Error 178 "-" "-" auth_id(-)
Oct 22 11:11:34 dg-p061701-200917-009 iotedged[7464]: 2020-10-22T10:11:34Z [ERR!] - Internal server error: Could not get trust bundle
Oct 22 11:11:34 dg-p061701-200917-009 iotedged[7464]:         caused by: An error occurred getting the certificate
Oct 22 11:11:34 dg-p061701-200917-009 iotedged[7464]:         caused by: HSM failure
Oct 22 11:11:34 dg-p061701-200917-009 iotedged[7464]:         caused by: HSM API returned an invalid null response
Oct 22 11:11:34 dg-p061701-200917-009 iotedged[7464]: 2020-10-22T10:11:34Z [INFO] - [work] - - - [2020-10-22 10:11:34.704802018 UTC] "GET /trust-bundle?api-version=2019-01-30 HTTP/1.1" 500 Internal Server Error 178 "-" "-" auth_id(-)

Additional Information

In the end we found some more details on the error

iotedged logs

customer-reported iotedge no-issue-activity

Most helpful comment

I have found some time to test this. Indeed when using the test certificates and including my own root certificate, it is indeed all working fine but when using my own device device certificate it fails.

I again also run with my own certificates and received some more details on the error. Again very strange because on version 9 the same certificates are working an on 10 they are not.

Detials

Dec 16 15:34:34 dg-0000000-191104-001 iotedged[16366]: 2020-12-16T15:34:34Z [DBUG] - [edgelet_http] accepted new connection (unknown)
Dec 16 15:34:34 dg-0000000-191104-001 iotedged[16366]: 2020-12-16T15:34:34Z [DBUG] - [edgelet_http_mgmt::server::module::list] List modules
Dec 16 15:34:34 dg-0000000-191104-001 iotedged[16366]: 2020-12-16T15:34:34Z [DBUG] - [edgelet_docker::runtime] Listing modules...
Dec 16 15:34:34 dg-0000000-191104-001 iotedged[16366]: 2020-12-16T15:34:34Z [DBUG] - [edgelet_docker::runtime] Successfully listed modules
Dec 16 15:34:34 dg-0000000-191104-001 iotedged[16366]: 2020-12-16T15:34:34Z [INFO] - [mgmt] - - - [2020-12-16 15:34:34.731057953 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 607 "-" "iotedge/0.1.0" auth_id(-)
Dec 16 15:34:47 dg-0000000-191104-001 iotedged[16366]: 2020-12-16T15:34:47Z [INFO] - Checking edge runtime status
Dec 16 15:34:47 dg-0000000-191104-001 iotedged[16366]: 2020-12-16T15:34:47Z [DBUG] - [edgelet_docker::runtime] Listing modules...
Dec 16 15:34:47 dg-0000000-191104-001 iotedged[16366]: 2020-12-16T15:34:47Z [DBUG] - [edgelet_docker::runtime] Successfully listed modules
Dec 16 15:34:47 dg-0000000-191104-001 iotedged[16366]: 2020-12-16T15:34:47Z [INFO] - Edge runtime status is failed, starting module now...
Dec 16 15:34:47 dg-0000000-191104-001 iotedged[16366]: 2020-12-16T15:34:47Z [INFO] - Starting module edgeAgent...
Dec 16 15:34:48 dg-0000000-191104-001 iotedged[16366]: 2020-12-16T15:34:48Z [INFO] - Successfully started module edgeAgent
Dec 16 15:34:50 dg-0000000-191104-001 iotedged[16366]: 2020-12-16T15:34:50Z [DBUG] - [edgelet_http] accepted new connection (unknown)
Dec 16 15:34:51 dg-0000000-191104-001 iotedged[16366]: 2020-12-16T15:34:51Z [ERR!] - Internal server error: Could not get trust bundle
Dec 16 15:34:51 dg-0000000-191104-001 iotedged[16366]:         caused by: An error occurred getting the certificate
Dec 16 15:34:51 dg-0000000-191104-001 iotedged[16366]:         caused by: HSM failure
Dec 16 15:34:51 dg-0000000-191104-001 iotedged[16366]:         caused by: HSM API returned an invalid null response
Dec 16 15:34:51 dg-0000000-191104-001 iotedged[16366]: 2020-12-16T15:34:51Z [INFO] - [work] - - - [2020-12-16 15:34:51.059240846 UTC] "GET /trust-bundle?api-version=2019-01-30 HTTP/1.1" 500 Internal Server Error 178 "-" "-" auth_id(-)
Dec 16 15:34:51 dg-0000000-191104-001 iotedged[16366]: 2020-12-16T15:34:51Z [DBUG] - [edgelet_http] accepted new connection (unknown)
Dec 16 15:34:51 dg-0000000-191104-001 iotedged[16366]: 2020-12-16T15:34:51Z [ERR!] - Internal server error: Could not get trust bundle
Dec 16 15:34:51 dg-0000000-191104-001 iotedged[16366]:         caused by: An error occurred getting the certificate
Dec 16 15:34:51 dg-0000000-191104-001 iotedged[16366]:         caused by: HSM failure
Dec 16 15:34:51 dg-0000000-191104-001 iotedged[16366]:         caused by: HSM API returned an invalid null response
Dec 16 15:34:51 dg-0000000-191104-001 iotedged[16366]: 2020-12-16T15:34:51Z [INFO] - [work] - - - [2020-12-16 15:34:51.288420210 UTC] "GET /trust-bundle?api-version=2019-01-30 HTTP/1.1" 500 Internal Server Error 178 "-" "-" auth_id(-)
Dec 16 15:34:54 dg-0000000-191104-001 iotedged[16366]: 2020-12-16T15:34:54Z [DBUG] - [edgelet_http] accepted new connection (unknown)
Dec 16 15:34:54 dg-0000000-191104-001 iotedged[16366]: 2020-12-16T15:34:54Z [ERR!] - Internal server error: Could not get trust bundle
Dec 16 15:34:54 dg-0000000-191104-001 iotedged[16366]:         caused by: An error occurred getting the certificate
Dec 16 15:34:54 dg-0000000-191104-001 iotedged[16366]:         caused by: HSM failure
Dec 16 15:34:54 dg-0000000-191104-001 iotedged[16366]:         caused by: HSM API returned an invalid null response
Dec 16 15:34:54 dg-0000000-191104-001 iotedged[16366]: 2020-12-16T15:34:54Z [INFO] - [work] - - - [2020-12-16 15:34:54.367514591 UTC] "GET /trust-bundle?api-version=2019-01-30 HTTP/1.1" 500 Internal Server Error 178 "-" "-" auth_id(-)
Dec 16 15:34:57 dg-0000000-191104-001 iotedged[16366]: 2020-12-16T15:34:57Z [DBUG] - [edgelet_http] accepted new connection (unknown)
Dec 16 15:34:57 dg-0000000-191104-001 iotedged[16366]: eate:500) Failure parsing certificate
Dec 16 15:34:57 dg-0000000-191104-001 iotedged[16366]: 2020-12-16T15:33:51Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/certificate_info.c:parse_validity_timestamps:305) Could not parse 'not after' timestamp from certificate
Dec 16 15:34:57 dg-0000000-191104-001 iotedged[16366]: 2020-12-16T15:33:51Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/certificate_info.c:parse_certificate_details:381) Error obtaining validity timestamps from certificate
Dec 16 15:34:57 dg-0000000-191104-001 iotedged[16366]: 2020-12-16T15:33:51Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/certificate_info.c:parse_certificate:418) Failure obtaining first certificate
Dec 16 15:34:57 dg-0000000-191104-001 iotedged[16366]: 2020-12-16T15:33:51Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/certificate_info.c:certificate_info_create:500) Failure parsing certificate
Dec 16 15:34:57 dg-0000000-191104-001 iotedged[16366]: 2020-12-16T15:33:54Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/certificate_info.c:parse_validity_timestamps:305) Could not parse 'not after' timestamp from certificate
Dec 16 15:34:57 dg-0000000-191104-001 iotedged[16366]: 2020-12-16T15:33:54Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/certificate_info.c:parse_certificate_details:381) Error obtaining validity timestamps from certificate
Dec 16 15:34:57 dg-0000000-191104-001 iotedged[16366]: 2020-12-16T15:33:54Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/certificate_info.c:parse_certificate:418) Failure obtaining first certificate
Dec 16 15:34:57 dg-0000000-191104-001 iotedged[16366]: 2020-12-16T15:33:54Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/certificate_info.c:certificate_info_create:500) Failure parsing certificate
Dec 16 15:34:57 dg-0000000-191104-001 iotedged[16366]: 2020-12-16T15:33:57Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/certificate_info.c:parse_validity_timestamps:305) Could not parse 'not after' timestamp from certificate
Dec 16 15:34:57 dg-0000000-191104-001 iotedged[16366]: 2020-12-16T15:33:57Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/certificate_info.c:parse_certificate_details:381) Error obtaining validity timestamps from certificate
Dec 16 15:34:57 dg-0000000-191104-001 iotedged[16366]: 2020-12-16T15:33:57Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/certificate_info.c:parse_certificate:418) Failure obtaining first certificate
Dec 16 15:34:57 dg-0000000-191104-001 iotedged[16366]: 2020-12-16T15:33:57Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/certificate_info.c:certificate_info_create:500) Failure parsing certificate
Dec 16 15:34:57 dg-0000000-191104-001 iotedged[16366]: 2020-12-16T15:34:51Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/certificate_info.c:parse_validity_timestamps:305) Could not parse 'not after' timestamp from certificate
Dec 16 15:34:57 dg-0000000-191104-001 iotedged[16366]: 2020-12-16T15:34:51Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/certificate_info.c:parse_certificate_details:381) Error obtaining validity timestamps from certificate
Dec 16 15:34:57 dg-0000000-191104-001 iotedged[16366]: 2020-12-16T15:34:51Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/certificate_info.c:parse_certificate:418) Failure obtaining first certificate
Dec 16 15:34:57 dg-0000000-191104-001 iotedged[16366]: 2020-12-16T15:34:51Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/certificate_info.c:certificate_info_create:500) Failure parsing certificate
Dec 16 15:34:57 dg-0000000-191104-001 iotedged[16366]: 2020-12-16T15:34:51Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/certificate_info.c:parse_validity_timestamps:305) Could not parse 'not after' timestamp from certificate
Dec 16 15:34:57 dg-0000000-191104-001 iotedged[16366]: 2020-12-16T15:34:51Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/certificate_info.c:parse_certificate_details:381) Error obtaining validity timestamps from certificate
Dec 16 15:34:57 dg-0000000-191104-001 iotedged[16366]: 2020-12-16T15:34:51Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/certificate_info.c:parse_certificate:418) Failure obtaining first certificate
Dec 16 15:34:57 dg-0000000-191104-001 iotedged[16366]: 2020-12-16T15:34:51Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/certificate_info.c:certificate_info_create:500) Failure parsing certificate
Dec 16 15:34:57 dg-0000000-191104-001 iotedged[16366]: 2020-12-16T15:34:54Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/certificate_info.c:parse_validity_timestamps:305) Could not parse 'not after' timestamp from certificate
Dec 16 15:34:57 dg-0000000-191104-001 iotedged[16366]: 2020-12-16T15:34:54Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/certificate_info.c:parse_certificate_details:381) Error obtaining validity timestamps from certificate
Dec 16 15:34:57 dg-0000000-191104-001 iotedged[16366]: 2020-12-16T15:34:54Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/certificate_info.c:parse_certificate:418) Failure obtaining first certificate
Dec 16 15:34:57 dg-0000000-191104-001 iotedged[16366]: 2020-12-16T15:34:54Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/certificate_info.c:certificate_info_create:500) Failure parsing certificate
Dec 16 15:34:57 dg-0000000-191104-001 iotedged[16366]: 2020-12-16<3>2020-12-16T15:34:57Z [ERR!] - Internal server error: Could not get trust bundle
Dec 16 15:34:57 dg-0000000-191104-001 iotedged[16366]:         caused by: An error occurred getting the certificate
Dec 16 15:34:57 dg-0000000-191104-001 iotedged[16366]:         caused by: HSM failure
Dec 16 15:34:57 dg-0000000-191104-001 iotedged[16366]:         caused by: HSM API returned an invalid null response
Dec 16 15:34:57 dg-0000000-191104-001 iotedged[16366]: 2020-12-16T15:34:57Z [INFO] - [work] - - - [2020-12-16 15:34:57.396989446 UTC] "GET /trust-bundle?api-version=2019-01-30 HTTP/1.1" 500 Internal Server Error 178 "-" "-" auth_id(-)

All 47 comments

The error message says that it cannot get the trust bundle. Can you confirm you have trusted_ca_certs set correctly in your config.yaml?

Yes, because I have downgraded to iotedge-1.0.9.5 without changing the config.yaml file and than everything was working fine. These certificates are already installed on 50+ devices on the previous version of iotedge all configured with same installation script.

I don't currently understand how this downgrade scenario to 1.0.9.5 works given that the error here indicates a problem reading the trust bundle. If I recall correctly, there are some options when upgrading to either keep your config yaml, or switch to the new one. What did you select here?

Also, I think it would be helpful if you could post your config.yaml here with sensitive information redacted please.

We selected to keep the config.yaml file, have check with the new version and doesn't seem to have changed. So just to be clear, we installed the device with the latest version of IoT Edge as we have always done and since 1.0.10 things don't start properly even if we deliver all the same settings as before (config, certificates, etc.). Without making any changes to settings and just downgrading to 1.0.9.5, keeping the original config file, and everything worked again as it should.


Config.yaml

###############################################################################
#                      IoT Edge Daemon configuration
###############################################################################
#
# This file configures the IoT Edge daemon. The daemon must be restarted to
# pick up any configuration changes.
#
# Note - this file is yaml. Learn more here: http://yaml.org/refcard.html
#
###############################################################################

###############################################################################
# Provisioning mode and settings
###############################################################################
#
# Configures the identity provisioning mode of the daemon.
#
# Supported modes:
#     manual   - using an iothub connection string
#     dps      - using dps for provisioning
#     external - the device has been provisioned externally.
#                Uses an external provisioning endpoint to get device specific information.
#
# DPS Settings
#     scope_id        - Required. Value of a specific DPS instance's ID scope
#     registration_id - Required for TPM and symmetric key provisioning flows.
#                       Optional for X.509 provisioning. Registration ID of a
#                       specific device in DPS.
#                       For more information regarding DPS registration ids
#                       please see https://docs.microsoft.com/en-us/azure/iot-dps/concepts-device#registration-id
#     symmetric_key   - Optional. This entry should only be specified when
#                       provisioning devices configured for symmetric key
#                       attestation. Device specific symmetric key.
#     identity_cert   - Optional. The Edge device identity X.509 certificate
#                       entry should only be specified when provisioning
#                       an Edge device configured for X.509 attestation.
#                       The value should be specified as a URI.
#                       Ex. when specifying a PEM encoded certificate file, the URI
#                       should be specified as file:///path/identity_certificate.pem
#     identity_pk     - Optional. The Edge device identity private key
#                       entry should only be specified when provisioning
#                       an Edge device configured for X.509 attestation.
#                       The value should be specified as a URI.
#                       Ex. when specifying a PEM encoded private key file, the URI
#                       should be specified as file:///path/identity_key.pem
#
# External Settings
#     endpoint - Required. Value of the endpoint used to retrieve device specific
#                information such as its IoT hub connection information.
###############################################################################

# Manual provisioning configuration
# provisioning:
#   source: "manual"
#   device_connection_string: "<ADD DEVICE CONNECTION STRING HERE>"

# DPS TPM provisioning configuration
# provisioning:
#   source: "dps"
#   global_endpoint: "https://global.azure-devices-provisioning.net"
#   scope_id: "<SCOPE_ID>"
#   attestation:
#     method: "tpm"
#     registration_id: "<REGISTRATION_ID>"

# DPS symmetric key provisioning configuration
# provisioning:
#   source: "dps"
#   global_endpoint: "https://global.azure-devices-provisioning.net"
#   scope_id: "<SCOPE_ID>"
#   attestation:
#     method: "symmetric_key"
#     registration_id: "<REGISTRATION_ID>"
#     symmetric_key: "<SYMMETRIC_KEY>"

# DPS X.509 provisioning configuration
provisioning:
  source: "dps"
  global_endpoint: "https://global.azure-devices-provisioning.net"
  scope_id: "<<ID>>"
  attestation:
    method: "x509"
    registration_id: "<<ID>>"
    identity_cert: "file:///<<HIDE>>/Device_Identity.pem"
    identity_pk: "file:///<<HIDE>>/Device_Identity.key.pem"

# External provisioning configuration
# provisioning:
#   source: "external"
#   endpoint: "http://localhost:9999"

###############################################################################
# Certificate settings
###############################################################################
#
# Configures the certificates required to operate the IoT Edge
# runtime as a gateway which enables external leaf devices to securely
# communicate with the Edge Hub. If not specified, the required certificates
# are auto generated for quick start scenarios which are not intended for
# production environments.
#
# Settings:
#     device_ca_cert   - URI of the device ca certificate and its chain.
#                        Optionally can be specified as a file path.
#     device_ca_pk     - URI of the device ca private key file.
#                        Optionally can be specified as a file path.
#     trusted_ca_certs - URI containing all the trusted CA
#                        certificates required for Edge module communication
#                        Optionally can be specified as a file path.
#
# Note:
# The values of all of these fields must be specified as a
# "file" scheme URI such as "file:///path/cert_key.pem"
###############################################################################

certificates:
  device_ca_cert: "file:///<<HIDE>>/Device_CA.pem"
  device_ca_pk: "file:///<<HIDE>>/Device_CA.key.pem"
  trusted_ca_certs: "file:///<<HIDE>>/Root_CA.pem"

###############################################################################
# Edge Agent module spec
###############################################################################
#
# Configures the initial Edge Agent module.
#
# The daemon uses this definition to bootstrap the system. The Edge Agent can
# then update itself based on the Edge Agent module definition present in the
# deployment in IoT Hub.
#
# Settings:
#     name     - name of the edge agent module. Expected to be "edgeAgent".
#     type     - type of module. Always "docker".
#     env      - Any environment variable that needs to be set for edge agent module.
#     config   - type specific configuration for edge agent module.
#       image  - (docker) Modules require a docker image tag.
#       auth   - (docker) Modules may need authoriation to connect to container registry.
#
# Adding environment variables:
# replace "env: {}" with
#  env:
#    key: "value"
#
# Adding container registry authorization:
# replace "auth: {}" with
#    auth:
#      username: "username"
#      password: "password"
#      serveraddress: "serveraddress"
#
###############################################################################

agent:
  name: "edgeAgent"
  type: "docker"
  env: {}
  config:
    image: "mcr.microsoft.com/azureiotedge-agent:1.0"
    auth: {}

###############################################################################
# Edge device hostname
###############################################################################
#
# Configures the environment variable 'IOTEDGE_GATEWAYHOSTNAME' injected into
# modules. Regardless of case the hostname is specified below, a lower case
# value is used to configure the Edge Hub server hostname as well as the
# environment variable specified above.
#
# It is important to note that when connecting downstream devices to the
# Edge Hub that the lower case value of this hostname be used in the
# 'GatewayHostName' field of the device's connection string URI.
###############################################################################

hostname: "<<Serialnumber>>"

###############################################################################
# Watchdog settings
###############################################################################
#
# The IoT edge daemon has a watchdog that periodically checks the health of the
# Edge Agent module and restarts it if it's down.
#
# max_retries - Configures the number of retry attempts that the IoT edge daemon
#               should make for failed operations before failing with a fatal error.
#
#               If this configuration is not specified, the daemon keeps retrying
#               on errors and doesn't fail fatally.
#
#               On a fatal failure, the daemon returns an exit code which
#               signifies the kind of error encountered. Currently, the following
#               error codes are returned by the daemon -
#
#               150 - Invalid Device ID specified.
#               151 - Invalid IoT hub configuration.
#               152 - Invalid SAS token used to call IoT hub.
#                     This could signal an invalid SAS key.
#               1 - All other errors.
###############################################################################

#watchdog:
#  max_retries: 2

###############################################################################
# Connect settings
###############################################################################
#
#
#Configures URIs used by clients of the management and workload APIs
#     management_uri - used by the Edge Agent and 'iotedge' CLI to start,
#                      stop, and manage modules
#     workload_uri   - used by modules to retrieve tokens and certificates
#
# The following uri schemes are supported:
#     http - connect over TCP
#     unix - connect over Unix domain socket
#
###############################################################################

connect:
  management_uri: "unix:///var/run/iotedge/mgmt.sock"
  workload_uri: "unix:///var/run/iotedge/workload.sock"

###############################################################################
# Listen settings
###############################################################################
#
# Configures the listen addresses for the daemon.
#     management_uri - used by the Edge Agent and 'iotedge' CLI to start,
#                      stop, and manage modules
#     workload_uri   - used by modules to retrieve tokens and certificates
#
# The following uri schemes are supported:
#     http - listen over TCP
#     unix - listen over Unix domain socket
#     fd   - listen using systemd socket activation
#
# These values can be different from the connect URIs. For instance, when
# using the fd:// scheme for systemd:
#     listen address is fd://iotedge.workload,
#     connect address is unix:///var/run/iotedge/workload.sock
#
###############################################################################

listen:
  management_uri: "fd://iotedge.mgmt.socket"
  workload_uri: "fd://iotedge.socket"

###############################################################################
# Home Directory
###############################################################################
#
# Configures the home directory for the daemon.
#
###############################################################################

homedir: "/var/lib/iotedge"

###############################################################################
# Moby Container Runtime settings
###############################################################################
#
# uri - configures the uri for the container runtime.
# network - configures the network on which the containers will be created.
#
# Additional container network configuration such as enabling IPv6 networking
# and providing the IPAM settings can be achieved by specifying the relevant
# configuration in the network settings.
#
# network:
#   name: "azure-iot-edge"
#   ipv6: true
#   ipam:
#     config:
#       -
#           gateway: '172.18.0.1'
#           subnet: '172.18.0.0/16'
#           ip_range: '172.18.0.0/16'
#       -
#           gateway: '2021:ffff:e0:3b1:1::1'
#           subnet: '2021:ffff:e0:3b1:1::/80'
#           ip_range: '2021:ffff:e0:3b1:1::/80'
###############################################################################

moby_runtime:
  uri: "unix:///var/run/docker.sock"
  # network: "azure-iot-edge"
  #
  # network:
  #   name: "azure-iot-edge"
  #   ipv6: true
  #   ipam:
  #     config:
  #       -
  #           gateway: '172.18.0.1'
  #           subnet: '172.18.0.0/16'
  #           ip_range: '172.18.0.0/16'
  #       -
  #           gateway: '2021:ffff:e0:3b1:1::1'
  #           subnet: '2021:ffff:e0:3b1:1::/80'
  #           ip_range: '2021:ffff:e0:3b1:1::/80'

You said you tried test certificates on 1.0.10, right? Just want to double check you tried it.

I am not sure what is going on here yet, but I was questioning the four dot syntax in your paths. I was going to suggest changing to absolute paths to eliminate noise, but I am guessing that since dps works with these same paths they aren't the issue.

I''ll check with others on the team for more insight. If you weren't sure that the downgrade scenario worked, I would think that this would be a path error with the trust bundle.

Yes we first tried it on 1.0.10 and then we had the issue with EdgeAgent throwing the error. Moving back to 1.0.9.5 solved it.

Well the dots in the paths are just hiding where the certificate is for the post here. Normally the absolute path is in the file for every certificate.

So we did make a change in 1.0.10 to some cert logic:
https://github.com/Azure/iotedge/commit/f0ff86565e81525d936582d773a83098100b3a34

This is related to what the screenshot of errors is showing. The function this change added is used for all certs, so presumably the problematic cert is in your trust bundle. Can you send your trust bundle file here? It is public information so it should be fine, but if you want to redact the subject names then go ahead.

@Sdelausnay Any update?

@Sdelausnay Also If there is a tool or script you are using to generate your production certs, that context could be helpful.

The certificates are acquired through a Windows Server CA which was setup specially for the IoT solution. This was done by an other party, where I only provided them the requirements for the certificates meaning Key length, CA requirements, etc. , and they build a template where we could request a certificate through NDES.

We have had the issue that our Root certificate was set to 2050 and this didn't work so we set it back to 2049 which solved that issue. We also had the issue with the intermediate certificate being longer then 2038 which we also set back to 2035 and both these things solve it for the previous version of IoT edge.


Trust bundle certificate

-----BEGIN CERTIFICATE-----
MIIFjzCCA3egAwIBAgIQIeM5TZ9XzJpItQkjOmFbKjANBgkqhkiG9w0BAQsFADAq
MSgwJgYDVQQDEx9EdWNvIFJvb3QgQ2VydGlmaWNhdGUgQXV0aG9yaXR5MB4XDTIw
MDcxMDA3MzQzM1oXDTQ5MDcxMDA3NDQzMlowKjEoMCYGA1UEAxMfRHVjbyBSb290
IENlcnRpZmljYXRlIEF1dGhvcml0eTCCAiIwDQYJKoZIhvcNAQEBBQADggIPADCC
AgoCggIBAMm8t8sbYEI5uhtrPxFXvJKOqh+w8UmgAlBWW59VIeRK59sCpYTmYcMZ
CfXOlJjTcodcJRsDUMD5sOg9yTCska6bWtJviGbjsSSX+gPeBDKycr992zcuvZDO
Q3PE1PCo5SwaEDxp0cTGUwdMb1S3BCAdXwo8kgWKUjnGcdGwUhnGUIAJdEw+A1u4
ZO7fl8TU+YnzsFpwXRRqcEnohnWdJ7X/dzYoPnqmHKbqGe6byXAA9p83KJBKxkFO
TL7M2RtGDiIleGJPYoBuQKnV5XzqPLFy1MmSSMa53GINlVwlbeQ4JVPYmVzIn3gL
2+OSAYeBk1kTQZu16JbQsR9tENcvVAUj8OBtBM52Zkl5j8fRmCEwQtNonGiVv3Zt
twS3n8cJjC4qM73Vz2S3j52fFB22sftYxbjI6h1ou5C96Y6QONaCHWB0mk+Us5iJ
KjRtWMJYK5xrpsBdcjwzrWvBMZJV3jKyGw8VYbsYLUCvwE9WwCLFSTu3bTgj4RPz
NCpqUkbweAjVi75XlBWWkjB7MG4shVboc3rH+3pT/7UwcrNscBCGxQDjmmZVOPEp
zDycDhnwD3HXdYjYdRWDR4aRFC9DjPTkY1AI+bfj3LWs6xpgbLEsLnkuJQfoWF0C
opqyGgra7Dk1Jcnw33pCcbb9WysSUvb6ddRclVrGO3H+ZRq7XpvRAgMBAAGjgbAw
ga0wCwYDVR0PBAQDAgGGMA8GA1UdEwEB/wQFMAMBAf8wHQYDVR0OBBYEFIEoRsum
/c55DoWx3VonY74nOvNpMBAGCSsGAQQBgjcVAQQDAgEAMFwGA1UdIARVMFMwUQYg
KoZIhvcUAb5Ak3qBxRy7U4MYgY03gtlIhbqlHILa0lcwLTArBggrBgEFBQcCARYf
aHR0cDovL3BraS5kdWNvLmV1L3BraS9jcHMuaHRtbDANBgkqhkiG9w0BAQsFAAOC
AgEAq13vIzStmQAhPDe7GwNcphbY3isbtPVRVKHjxsU3FzBRbot9ieOOi90PE0Pf
SSS1iS8MAPtJzmuOWNF/JhUxJFpt+Jrcja/IIhuY+Wc7KGbT9P/uwTOCzjydQjEa
xKcd2A8GFKJ7WQJ8/dhBcIU7x3bb0JamuI39wQXE1mPmk0OP9FrZVf+K4AbJDmSN
WADu9hwZT+jaH0QBUHvmQZ1YX60vNq5tkUKxzRmQ+BxT+mmOkesk71q2W5zJglAq
UtAfBo/R2bXgbazwihYE51unkTUWTY49WEKNdT2Bg4FCOL2GcJIYEOEi7uryeyon
vwRY+QfOJGe2QR8ln6SDZgtrkD4390Srn+T373jwHX5D+xNTmA+MdvuN6cj4ZH27
nzThKbhJu1jpvDju/5qbsv2XUQ5e+VcK7xd7Vp3ckBZqOJ0WoBS5fFJwGdEOlWue
ygXgejHPCcTTb/HqiTG8SVc3fDnoaTuY8sz7rbNXMQtLcMT7w72AkNUyvt7/BlmQ
JXMVW5nuicTmvIiTKhe780OYKjcbSr9G9AcKJmN5o7rxgpuUBTxejOv5CrrM1vgM
dWcLnZoQ9wvS5tau9V5WpkYoEmm6mH5/YO4cGKxCiynYDZbraibZ++ljnXpEK2KH
Y8Imi7Cdv0Fd7LrhRGdVWTdkXkNMicaO7tIKFhRuUBd3tO4=
-----END CERTIFICATE-----

I tried this trusted cert on 1.0.10 and 1.0.9 and it didn't cause any issues. The expiration for this cert is 2049, but you mention you set it back to 2035. Are you sure this is the correct certificate? Based on the errors you are seeing in 1.0.10 I am not sure why this also does not complain for me.

This is the root certificate which was set to 2049. It was the intermediate certificate and device CA certificate which where set back below 2035. So yes this is the correct Root certificate.

So this maybe means something is wrong with the full chain device CA certificate?

Given the log about "Could not get trust bundle" I wouldn't expect this to be the case but I suppose it is possible. I have tested both 1.0.10 and 1.0.9 with trusted cert expiring in 2049 and device ca expiring 2038, so don't think the issue is caused solely by a difference in expiration.

As a sanity check we could try your scenario where you use the test-generated certificates but also include the production root certificate in the bundle file. Based on my test I would expect this not to fail for you. If it fails though we will know there was an issue with my reproduction attempt.

I will try to setup a test like this, to also include our production certificate when using the test-generated certificates and come back to you.

@Sdelausnay Any update?

I'm seeing this failure immediately upon having upgraded from iotedge 1.0.9.4 to iotedge 1.0.10.2.

me@device:~ $ sudo iotedge check --iothub-hostname <redacted>
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 - OK
โˆš latest security daemon - OK
โˆš 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 - OK
โ€ผ production readiness: Edge Agent's storage directory is persisted on the host filesystem - Warning
    The edgeAgent module is not configured to persist its /tmp/edgeAgent directory on the host filesystem.
    Data might be lost if the module is deleted or updated.
    Please see https://aka.ms/iotedge-storage-host for best practices.
ร— production readiness: Edge Hub's storage directory is persisted on the host filesystem - Error
    Could not check current state of edgeHub container

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 - OK
โˆš container on the IoT Edge module network can connect to IoT Hub HTTPS / WebSockets port - OK
โˆš container on the IoT Edge module network can connect to IoT Hub MQTT port - OK

23 check(s) succeeded.
1 check(s) raised warnings. Re-run with --verbose for more details.

Running with --verbose provides no more or different information.

Also, running under 1.0.9.4 the system was dealing with storage properly (no warnings or errors).

If there's something I can provide to help debug this, lemme know fast. I'll have to revert on this device quite soon.

In case it helps, I did see this when running sudo apt upgrade -y on the system to get 1.0.10.2:

Unpacking iotedge (1.0.10.2-1) over (1.0.9.4-1) ...
dpkg: warning: unable to delete old directory '/var/lib/iotedge': Directory not empty

@kpm-at-hfi Are there any differences between your issue and the issue opened here? If not I would suggest the same debugging attempt above:

As a sanity check we could try your scenario where you use the test-generated certificates but also include the production root certificate in the bundle file. Based on my test I would expect this not to fail for you. If it fails though we will know there was an issue with my reproduction attempt.

Now that we know this issue reproduces, I think going the support route will help us resolve the problem sooner. That way we will be able to see the support bundle containing sensitive information:
https://portal.azure.com/#create/Microsoft.Support

Also looping in @arsing as he might have some different ideas.

@kpm-at-hfi Are you also running on Raspbian stretch?

I'm sorry I didn't see the earlier comment!

$ cat /etc/os-release
PRETTY_NAME="Raspbian GNU/Linux 10 (buster)"

Unfortunately it will be a while before I can try the sanity check described above... sorry! I'll post here if I can get to it.

@kpm-at-hfi Can you please open a support ticket when you come back to this? I'm failing to reproduce this even with the presumably problematic trusted cert and I think having all the context from the support bundle will help us fix this issue faster.

Certainly. I'll have to start fresh to recreate it since i did wipe that card and go back to the "safety" of 1.0.9.

Can you tell me how to get the support bundle so I am free to attempt this whevener I have some downtime?

Here is some documentation on the support bundle:
https://docs.microsoft.com/en-us/azure/iot-edge/troubleshoot?view=iotedge-2018-06#gather-debug-information-with-support-bundle-command

I have found some time to test this. Indeed when using the test certificates and including my own root certificate, it is indeed all working fine but when using my own device device certificate it fails.

I again also run with my own certificates and received some more details on the error. Again very strange because on version 9 the same certificates are working an on 10 they are not.

Detials

Dec 16 15:34:34 dg-0000000-191104-001 iotedged[16366]: 2020-12-16T15:34:34Z [DBUG] - [edgelet_http] accepted new connection (unknown)
Dec 16 15:34:34 dg-0000000-191104-001 iotedged[16366]: 2020-12-16T15:34:34Z [DBUG] - [edgelet_http_mgmt::server::module::list] List modules
Dec 16 15:34:34 dg-0000000-191104-001 iotedged[16366]: 2020-12-16T15:34:34Z [DBUG] - [edgelet_docker::runtime] Listing modules...
Dec 16 15:34:34 dg-0000000-191104-001 iotedged[16366]: 2020-12-16T15:34:34Z [DBUG] - [edgelet_docker::runtime] Successfully listed modules
Dec 16 15:34:34 dg-0000000-191104-001 iotedged[16366]: 2020-12-16T15:34:34Z [INFO] - [mgmt] - - - [2020-12-16 15:34:34.731057953 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 607 "-" "iotedge/0.1.0" auth_id(-)
Dec 16 15:34:47 dg-0000000-191104-001 iotedged[16366]: 2020-12-16T15:34:47Z [INFO] - Checking edge runtime status
Dec 16 15:34:47 dg-0000000-191104-001 iotedged[16366]: 2020-12-16T15:34:47Z [DBUG] - [edgelet_docker::runtime] Listing modules...
Dec 16 15:34:47 dg-0000000-191104-001 iotedged[16366]: 2020-12-16T15:34:47Z [DBUG] - [edgelet_docker::runtime] Successfully listed modules
Dec 16 15:34:47 dg-0000000-191104-001 iotedged[16366]: 2020-12-16T15:34:47Z [INFO] - Edge runtime status is failed, starting module now...
Dec 16 15:34:47 dg-0000000-191104-001 iotedged[16366]: 2020-12-16T15:34:47Z [INFO] - Starting module edgeAgent...
Dec 16 15:34:48 dg-0000000-191104-001 iotedged[16366]: 2020-12-16T15:34:48Z [INFO] - Successfully started module edgeAgent
Dec 16 15:34:50 dg-0000000-191104-001 iotedged[16366]: 2020-12-16T15:34:50Z [DBUG] - [edgelet_http] accepted new connection (unknown)
Dec 16 15:34:51 dg-0000000-191104-001 iotedged[16366]: 2020-12-16T15:34:51Z [ERR!] - Internal server error: Could not get trust bundle
Dec 16 15:34:51 dg-0000000-191104-001 iotedged[16366]:         caused by: An error occurred getting the certificate
Dec 16 15:34:51 dg-0000000-191104-001 iotedged[16366]:         caused by: HSM failure
Dec 16 15:34:51 dg-0000000-191104-001 iotedged[16366]:         caused by: HSM API returned an invalid null response
Dec 16 15:34:51 dg-0000000-191104-001 iotedged[16366]: 2020-12-16T15:34:51Z [INFO] - [work] - - - [2020-12-16 15:34:51.059240846 UTC] "GET /trust-bundle?api-version=2019-01-30 HTTP/1.1" 500 Internal Server Error 178 "-" "-" auth_id(-)
Dec 16 15:34:51 dg-0000000-191104-001 iotedged[16366]: 2020-12-16T15:34:51Z [DBUG] - [edgelet_http] accepted new connection (unknown)
Dec 16 15:34:51 dg-0000000-191104-001 iotedged[16366]: 2020-12-16T15:34:51Z [ERR!] - Internal server error: Could not get trust bundle
Dec 16 15:34:51 dg-0000000-191104-001 iotedged[16366]:         caused by: An error occurred getting the certificate
Dec 16 15:34:51 dg-0000000-191104-001 iotedged[16366]:         caused by: HSM failure
Dec 16 15:34:51 dg-0000000-191104-001 iotedged[16366]:         caused by: HSM API returned an invalid null response
Dec 16 15:34:51 dg-0000000-191104-001 iotedged[16366]: 2020-12-16T15:34:51Z [INFO] - [work] - - - [2020-12-16 15:34:51.288420210 UTC] "GET /trust-bundle?api-version=2019-01-30 HTTP/1.1" 500 Internal Server Error 178 "-" "-" auth_id(-)
Dec 16 15:34:54 dg-0000000-191104-001 iotedged[16366]: 2020-12-16T15:34:54Z [DBUG] - [edgelet_http] accepted new connection (unknown)
Dec 16 15:34:54 dg-0000000-191104-001 iotedged[16366]: 2020-12-16T15:34:54Z [ERR!] - Internal server error: Could not get trust bundle
Dec 16 15:34:54 dg-0000000-191104-001 iotedged[16366]:         caused by: An error occurred getting the certificate
Dec 16 15:34:54 dg-0000000-191104-001 iotedged[16366]:         caused by: HSM failure
Dec 16 15:34:54 dg-0000000-191104-001 iotedged[16366]:         caused by: HSM API returned an invalid null response
Dec 16 15:34:54 dg-0000000-191104-001 iotedged[16366]: 2020-12-16T15:34:54Z [INFO] - [work] - - - [2020-12-16 15:34:54.367514591 UTC] "GET /trust-bundle?api-version=2019-01-30 HTTP/1.1" 500 Internal Server Error 178 "-" "-" auth_id(-)
Dec 16 15:34:57 dg-0000000-191104-001 iotedged[16366]: 2020-12-16T15:34:57Z [DBUG] - [edgelet_http] accepted new connection (unknown)
Dec 16 15:34:57 dg-0000000-191104-001 iotedged[16366]: eate:500) Failure parsing certificate
Dec 16 15:34:57 dg-0000000-191104-001 iotedged[16366]: 2020-12-16T15:33:51Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/certificate_info.c:parse_validity_timestamps:305) Could not parse 'not after' timestamp from certificate
Dec 16 15:34:57 dg-0000000-191104-001 iotedged[16366]: 2020-12-16T15:33:51Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/certificate_info.c:parse_certificate_details:381) Error obtaining validity timestamps from certificate
Dec 16 15:34:57 dg-0000000-191104-001 iotedged[16366]: 2020-12-16T15:33:51Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/certificate_info.c:parse_certificate:418) Failure obtaining first certificate
Dec 16 15:34:57 dg-0000000-191104-001 iotedged[16366]: 2020-12-16T15:33:51Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/certificate_info.c:certificate_info_create:500) Failure parsing certificate
Dec 16 15:34:57 dg-0000000-191104-001 iotedged[16366]: 2020-12-16T15:33:54Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/certificate_info.c:parse_validity_timestamps:305) Could not parse 'not after' timestamp from certificate
Dec 16 15:34:57 dg-0000000-191104-001 iotedged[16366]: 2020-12-16T15:33:54Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/certificate_info.c:parse_certificate_details:381) Error obtaining validity timestamps from certificate
Dec 16 15:34:57 dg-0000000-191104-001 iotedged[16366]: 2020-12-16T15:33:54Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/certificate_info.c:parse_certificate:418) Failure obtaining first certificate
Dec 16 15:34:57 dg-0000000-191104-001 iotedged[16366]: 2020-12-16T15:33:54Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/certificate_info.c:certificate_info_create:500) Failure parsing certificate
Dec 16 15:34:57 dg-0000000-191104-001 iotedged[16366]: 2020-12-16T15:33:57Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/certificate_info.c:parse_validity_timestamps:305) Could not parse 'not after' timestamp from certificate
Dec 16 15:34:57 dg-0000000-191104-001 iotedged[16366]: 2020-12-16T15:33:57Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/certificate_info.c:parse_certificate_details:381) Error obtaining validity timestamps from certificate
Dec 16 15:34:57 dg-0000000-191104-001 iotedged[16366]: 2020-12-16T15:33:57Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/certificate_info.c:parse_certificate:418) Failure obtaining first certificate
Dec 16 15:34:57 dg-0000000-191104-001 iotedged[16366]: 2020-12-16T15:33:57Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/certificate_info.c:certificate_info_create:500) Failure parsing certificate
Dec 16 15:34:57 dg-0000000-191104-001 iotedged[16366]: 2020-12-16T15:34:51Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/certificate_info.c:parse_validity_timestamps:305) Could not parse 'not after' timestamp from certificate
Dec 16 15:34:57 dg-0000000-191104-001 iotedged[16366]: 2020-12-16T15:34:51Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/certificate_info.c:parse_certificate_details:381) Error obtaining validity timestamps from certificate
Dec 16 15:34:57 dg-0000000-191104-001 iotedged[16366]: 2020-12-16T15:34:51Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/certificate_info.c:parse_certificate:418) Failure obtaining first certificate
Dec 16 15:34:57 dg-0000000-191104-001 iotedged[16366]: 2020-12-16T15:34:51Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/certificate_info.c:certificate_info_create:500) Failure parsing certificate
Dec 16 15:34:57 dg-0000000-191104-001 iotedged[16366]: 2020-12-16T15:34:51Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/certificate_info.c:parse_validity_timestamps:305) Could not parse 'not after' timestamp from certificate
Dec 16 15:34:57 dg-0000000-191104-001 iotedged[16366]: 2020-12-16T15:34:51Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/certificate_info.c:parse_certificate_details:381) Error obtaining validity timestamps from certificate
Dec 16 15:34:57 dg-0000000-191104-001 iotedged[16366]: 2020-12-16T15:34:51Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/certificate_info.c:parse_certificate:418) Failure obtaining first certificate
Dec 16 15:34:57 dg-0000000-191104-001 iotedged[16366]: 2020-12-16T15:34:51Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/certificate_info.c:certificate_info_create:500) Failure parsing certificate
Dec 16 15:34:57 dg-0000000-191104-001 iotedged[16366]: 2020-12-16T15:34:54Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/certificate_info.c:parse_validity_timestamps:305) Could not parse 'not after' timestamp from certificate
Dec 16 15:34:57 dg-0000000-191104-001 iotedged[16366]: 2020-12-16T15:34:54Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/certificate_info.c:parse_certificate_details:381) Error obtaining validity timestamps from certificate
Dec 16 15:34:57 dg-0000000-191104-001 iotedged[16366]: 2020-12-16T15:34:54Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/certificate_info.c:parse_certificate:418) Failure obtaining first certificate
Dec 16 15:34:57 dg-0000000-191104-001 iotedged[16366]: 2020-12-16T15:34:54Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/certificate_info.c:certificate_info_create:500) Failure parsing certificate
Dec 16 15:34:57 dg-0000000-191104-001 iotedged[16366]: 2020-12-16<3>2020-12-16T15:34:57Z [ERR!] - Internal server error: Could not get trust bundle
Dec 16 15:34:57 dg-0000000-191104-001 iotedged[16366]:         caused by: An error occurred getting the certificate
Dec 16 15:34:57 dg-0000000-191104-001 iotedged[16366]:         caused by: HSM failure
Dec 16 15:34:57 dg-0000000-191104-001 iotedged[16366]:         caused by: HSM API returned an invalid null response
Dec 16 15:34:57 dg-0000000-191104-001 iotedged[16366]: 2020-12-16T15:34:57Z [INFO] - [work] - - - [2020-12-16 15:34:57.396989446 UTC] "GET /trust-bundle?api-version=2019-01-30 HTTP/1.1" 500 Internal Server Error 178 "-" "-" auth_id(-)

Thanks for the information. If you feel comfortable you could share the device_ca_cert (which is public information). I can then take a closer look at what is causing these errors.

Also, I think a support ticket is still the safest option. I have notified our customer support team and we will elevate it to the appropriate channels when it comes in.

@arsing Any idea why the device ca is relevant to this error?

@Sdelausnay Just to confirm, when you say:

but when using my own device device certificate it fails

You mean the device ca cert right? I just want to be double sure we can rule out your dps certs as a cause.

Yes indeed the device CA cert. In my lasted test I completely left out the DPS setup and just used the connection string.

I will check to maybe open a support ticket to share further information.

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

Any status on this? I just tried again to upgrade iotedge/stretch 1.0.10.4-1 armhf [upgradable from: 1.0.9.4-1] and I'm seeing failures:

Jan 21 18:53:10 my-device iotedged[807]: 2021-01-21T18:53:10Z [INFO] - [work] - - - [2021-01-21 18:53:10.821217615 UTC] "GET /trust-bundle?api-version=2019-01-30 HTTP/
Jan 21 18:53:13 my-device iotedged[807]: 2021-01-21T18:53:13Z [ERR!] - Internal server error: Could not get trust bundle
Jan 21 18:53:13 my-device iotedged[807]:         caused by: An error occurred getting the certificate
Jan 21 18:53:13 my-device iotedged[807]:         caused by: HSM failure
Jan 21 18:53:13 my-device iotedged[807]:         caused by: HSM API returned an invalid null response
me@my-device:~ $ sudo iotedge check --iothub-hostname <redacted>
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 - OK
โˆš latest security daemon - OK
โˆš 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 - OK
โ€ผ production readiness: Edge Agent's storage directory is persisted on the host filesystem - Warning
    The edgeAgent module is not configured to persist its /tmp/edgeAgent directory on the host filesystem.
    Data might be lost if the module is deleted or updated.
    Please see https://aka.ms/iotedge-storage-host for best practices.
ร— production readiness: Edge Hub's storage directory is persisted on the host filesystem - Error
    Could not check current state of edgeHub container

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 - OK
โˆš container on the IoT Edge module network can connect to IoT Hub HTTPS / WebSockets port - OK
โˆš container on the IoT Edge module network can connect to IoT Hub MQTT port - OK

23 check(s) succeeded.
1 check(s) raised warnings. Re-run with --verbose for more details.
1 check(s) raised errors. Re-run with --verbose for more details.

Also, as noted above, this is all working perfectly under iotedge 1.0.9.4, including the storage flagged as incorrect just above.

I'm using DPS and self-signed certs with an end date that should be fine (all working perfectly under 1.0.9.4):

me@my-device:~/certs $ openssl x509 -enddate -noout -in iot-edge-device-ca-full-chain.cert.pem
notAfter=Dec 30 18:35:03 2037 GMT

(Reposted after removing what I think is a non-related issue.)

Yep, the support ticket came in this week and we were able to reproduce it. There is an open bug being looked at now and the fix will optimistically make it into our 1.1.0 release in the coming weeks.

Thanks @and-rewsmith... I appreciate the update. Is the open ticket linkable here (so I can follow along)?

@kpm-at-hfi Unfortunately the support ticket contains confidential information from the reporting customer, so we aren't allowed to share details.

Thx for the info @and-rewsmith.L Keep me posted if you require any other information of if the fix will be implemented.

@and-rewsmith can you describe the relationship between the 1.1.0 release that you mention above, and the 1.2.0 relase that I see in pre-release on the Releases page? I'm not seeing _any_ releases for 1.1.0.

Also, how this one going? :)

The 1.1.0 release is going to be our lts release which will be similar to 1.0.10 with some more fixes. It hasn't been released yet which is why it doesn't show up, but we recently cut the branch:
https://github.com/Azure/iotedge/tree/release/1.1

We are in a a tough spot for this one. Because using trusted certs with expiration past 2038 worked on 1.0.9 and for me a couple times locally I was thinking that time_t was 64 bit, which meant this scenario should also work on 1.0.10. After reproducing and debugging with @gordonwang0 yesterday, I realize time_t on raspbian buster is 32 bit which means post 2038 expirations should not work (and similarly with any arm32 OS which uses a 32 bit libc). The reason it did work in 1.0.9 was a bug. Now we have some options on the table and are discussing how to proceed. Some of these are rather difficult:

  • Regenerate their certificates so that everything expires before 2038.
  • Recompile iotedged/libiothsm with a libc that uses 64-bit time_t on their system.
  • We could change the use of time_t to int64_t. I would not recommend doing this, as we should depend on libc for time_t.

Interesting... so if I was able to regenerate certs to expire before 2038, then I'd be able to work safely in 1.0.9 _and_ 1.0.10, _and_ beyond to 1.1.0 and 1.2.0?

@kpm-at-hfi Yes that is correct

And because I'm not afraid to ask the stupid question just to be sure...

If at some point Raspberry OS moves to 64-bit time_t, I'd still be fine with certs that expire before 2038, right?

@kpm-at-hfi yep

@and-rewsmith, just wanted to say thank you for the information here. Learning this this week rather than a week or two later makes a _huge_ difference on the project I'm working on.

Just leaving a note here for others who might have to deal with this... be sure that the _entire_ cert chain expires before 2038. I was a little confused as I saw that my iot-edge-device-ca-full-chain.cert.pem was _already_ set to expire before 2038, but walking up the chain, others were later.

Closing note from me: Just wanted to affirm that ensuring the whole cert chain expires before 2038 does indeed work.

For anyone reading this, if you encounter this issue it is because:

  • you are on a system with 32 bit time_t
  • your trusted cert expires 2038 or after

For now, the solution is to regenerate the cert chain to expire before 2038. If you have devices in the field that are using a trusted cert expiring 2038 or after, you can try recompiling iotedged to use a libc with 64 bit time_t. We are currently discussing if we will patch this in 1.0.10 and support 2038+ expiry in future versions for systems with 32 bit time_t. I will update this thread with our decision.

Should be "your trusted cert expires post 2037"

We have decided to fix this in our 1.1 and 1.2 release.

More specifically, release 1.1 will be patched soon after initial release to contain the fix. For our 1.2 GA release (to contain refactored iotedged/hsm) this issue is not a problem due to the refactor.

Note that the 1.2 rc releases do not yet contain the refactored iotedged/hsm.

Was this page helpful?
0 / 5 - 0 ratings