arsing
commented
3 years ago keyd and further services fail, no containers of hub and agent are downloaded.
keyd is fine. The problem is in certd.
It seems important error is in
aziot-certdservice, but not sure what certificate the logs are about:
It's about the server cert of the EST server.
You correctly put the EST server's issuer in the cert_issuance.est.trusted_certs config. But we ignore the trusted certs when building a MaybeProxyConnector without a client cert.
This is a bug. It needs to add the trusted certs to a custom openssl::ssl::SslConnector just like the beginning of identity_to_tls_connector
ondrejspilkaABB
Expected Behavior
When Aziot Edge configured to provision against DPS and enrollment group using EST test server with certificates stored in TPM using PKCS11, provisioning should work and device shall be registered.
Current Behavior
keyd and further services fail, no containers of hub and agent are downloaded.
Steps to Reproduce
It seems important error is in
aziot-certdservice, but not sure what certificate the logs are about:Example EST CA certificate
Context (Environment)
Output of
iotedge checkClick here
``` Configuration checks (aziot-identity-service) --------------------------------------------- √ keyd configuration is well-formed - OK √ certd configuration is well-formed - OK √ tpmd configuration is well-formed - OK √ identityd configuration is well-formed - OK √ daemon configurations up-to-date with config.toml - OK √ identityd config toml file specifies a valid hostname - OK √ aziot-identity-service package is up-to-date - OK √ host time is close to reference time - OK √ production readiness: identity certificates expiry - OK √ preloaded certificates are valid - OK √ keyd is running - OK √ certd is running - OK √ identityd is running - OK × read all preloaded certificates from the Certificates Service - Error could not load cert with ID "aziot-edged-trust-bundle" Caused by: parameter "id" has an invalid value caused by: not found √ read all preloaded key pairs from the Keys Service - OK √ ensure all preloaded certificates match preloaded private keys with the same ID - OK Connectivity checks (aziot-identity-service) -------------------------------------------- ‼ host can connect to and perform TLS handshake with iothub AMQP port - Warning Could not retrieve iothub_hostname from provisioning file. Please specify the backing IoT Hub name using --iothub-hostname switch if you have that information. Since no hostname is provided, all hub connectivity tests will be skipped. ‼ host can connect to and perform TLS handshake with iothub HTTPS / WebSockets port - Warning Could not retrieve iothub_hostname from provisioning file. Please specify the backing IoT Hub name using --iothub-hostname switch if you have that information. Since no hostname is provided, all hub connectivity tests will be skipped. ‼ host can connect to and perform TLS handshake with iothub MQTT port - Warning Could not retrieve iothub_hostname from provisioning file. Please specify the backing IoT Hub name using --iothub-hostname switch if you have that information. Since no hostname is provided, all hub connectivity tests will be skipped. √ host can connect to and perform TLS handshake with DPS endpoint - OK Configuration checks -------------------- √ aziot-edged configuration is well-formed - OK √ configuration up-to-date with config.toml - OK √ container engine is installed and functional - OK × configuration has correct URIs for daemon mgmt endpoint - Error SocketError - SocketErrorCode (TimedOut) : Operation timed out One or more errors occurred. (Got bad response: ) √ aziot-edge package is up-to-date - OK √ container time is close to host time - OK ‼ DNS server - Warning Container engine is not configured with DNS server setting, which may impact connectivity to IoT Hub. Please see https://aka.ms/iotedge-prod-checklist-dns for best practices. You can ignore this warning if you are setting DNS server per module in the Edge deployment. √ production readiness: container engine - 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 × production readiness: Edge Hub's storage directory is persisted on the host filesystem - Error Could not check current state of edgeHub container √ Agent image is valid and can be pulled from upstream - OK Connectivity checks ------------------- 23 check(s) succeeded. 5 check(s) raised warnings. Re-run with --verbose for more details. 4 check(s) raised errors. Re-run with --verbose for more details. 6 check(s) were skipped due to errors from other checks. Re-run with --verbose for more details. ```Device Information
Runtime Versions
Server: Engine: Version: 20.10.7+azure API version: 1.41 (minimum version 1.12) Go version: go1.13.15 Git commit: b0f5bc36fea9dfb9672e1e9b1278ebab797b9ee0 Built: Tue Jun 1 22:34:42 2021 OS/Arch: linux/amd64 Experimental: false containerd: Version: 1.4.6+azure GitCommit: d71fcd7d8303cbf684402823e425e9dd2e99285d runc: Version: 1.0.0 GitCommit: 84113eef6fc27af1b01b3181f31bbaf708715301 docker-init: Version: 0.19.0 GitCommit:
Aug 03 12:30:04 dfa-wg-onsp-001 aziot-edged[28260]: 2021-08-03T12:30:04Z [INFO] - Obtaining edge device provisioning data... Aug 03 12:30:04 dfa-wg-onsp-001 aziot-edged[28260]: 2021-08-03T12:30:04Z [WARN] - The daemon could not start up successfully: Could not retrieve device information Aug 03 12:30:04 dfa-wg-onsp-001 aziot-edged[28260]: 2021-08-03T12:30:04Z [WARN] - caused by: HTTP request error Aug 03 12:30:04 dfa-wg-onsp-001 aziot-edged[28260]: 2021-08-03T12:30:04Z [WARN] - caused by: connection error: Connection reset by peer (os error 104) Aug 03 12:30:04 dfa-wg-onsp-001 aziot-edged[28260]: 2021-08-03T12:30:04Z [WARN] - Requesting device reprovision. Aug 03 12:30:04 dfa-wg-onsp-001 aziot-edged[28260]: 2021-08-03T12:30:04Z [WARN] - The reprovisioning operation failed Aug 03 12:30:09 dfa-wg-onsp-001 aziot-edged[28260]: 2021-08-03T12:30:09Z [INFO] - Obtaining edge device provisioning data... Aug 03 12:30:09 dfa-wg-onsp-001 aziot-edged[28260]: 2021-08-03T12:30:09Z [WARN] - The daemon could not start up successfully: Could not retrieve device information Aug 03 12:30:09 dfa-wg-onsp-001 aziot-edged[28260]: 2021-08-03T12:30:09Z [WARN] - caused by: HTTP request error Aug 03 12:30:09 dfa-wg-onsp-001 aziot-edged[28260]: 2021-08-03T12:30:09Z [WARN] - caused by: connection error: Connection reset by peer (os error 104) Aug 03 12:30:09 dfa-wg-onsp-001 aziot-edged[28260]: 2021-08-03T12:30:09Z [WARN] - Requesting device reprovision. Aug 03 12:30:09 dfa-wg-onsp-001 aziot-edged[28260]: 2021-08-03T12:30:09Z [WARN] - The reprovisioning operation failed
Aug 03 12:32:31 dfa-wg-onsp-001 aziot-keyd[28302]: 2021-08-03T12:32:31Z [INFO] - <-- POST /keypair?api-version=2020-09-01 {"content-type": "application/json", "host": "keyd.sock", "content-length": "56"} Aug 03 12:32:31 dfa-wg-onsp-001 aziot-keyd[28302]: 2021-08-03T12:32:31Z [INFO] - --> 200 {"content-type": "application/json"} Aug 03 12:32:31 dfa-wg-onsp-001 aziot-keyd[28302]: 2021-08-03T12:32:31Z [INFO] - <-- POST /parameters/algorithm?api-version=2020-09-01 {"content-length": "248", "content-type": "application/json"} Aug 03 12:32:31 dfa-wg-onsp-001 aziot-keyd[28302]: 2021-08-03T12:32:31Z [INFO] - --> 200 {"content-type": "application/json"} Aug 03 12:32:31 dfa-wg-onsp-001 aziot-keyd[28302]: 2021-08-03T12:32:31Z [INFO] - <-- POST /parameters/rsa-modulus?api-version=2020-09-01 {"content-length": "248", "content-type": "application/json"} Aug 03 12:32:31 dfa-wg-onsp-001 aziot-keyd[28302]: 2021-08-03T12:32:31Z [INFO] - --> 200 {"content-type": "application/json"} Aug 03 12:32:31 dfa-wg-onsp-001 aziot-keyd[28302]: 2021-08-03T12:32:31Z [INFO] - <-- POST /parameters/rsa-exponent?api-version=2020-09-01 {"content-length": "248", "content-type": "application/json"} Aug 03 12:32:31 dfa-wg-onsp-001 aziot-keyd[28302]: 2021-08-03T12:32:31Z [INFO] - --> 200 {"content-type": "application/json"} Aug 03 12:32:31 dfa-wg-onsp-001 aziot-keyd[28302]: 2021-08-03T12:32:31Z [INFO] - <-- POST /parameters/algorithm?api-version=2020-09-01 {"content-length": "248", "content-type": "application/json"} Aug 03 12:32:31 dfa-wg-onsp-001 aziot-keyd[28302]: 2021-08-03T12:32:31Z [INFO] - --> 200 {"content-type": "application/json"} Aug 03 12:32:31 dfa-wg-onsp-001 aziot-keyd[28302]: 2021-08-03T12:32:31Z [INFO] - <-- POST /parameters/rsa-modulus?api-version=2020-09-01 {"content-length": "248", "content-type": "application/json"} Aug 03 12:32:31 dfa-wg-onsp-001 aziot-keyd[28302]: 2021-08-03T12:32:31Z [INFO] - --> 200 {"content-type": "application/json"} Aug 03 12:32:31 dfa-wg-onsp-001 aziot-keyd[28302]: 2021-08-03T12:32:31Z [INFO] - <-- POST /parameters/rsa-exponent?api-version=2020-09-01 {"content-length": "248", "content-type": "application/json"} Aug 03 12:32:31 dfa-wg-onsp-001 aziot-keyd[28302]: 2021-08-03T12:32:31Z [INFO] - --> 200 {"content-type": "application/json"} Aug 03 12:32:31 dfa-wg-onsp-001 aziot-keyd[28302]: 2021-08-03T12:32:31Z [INFO] - <-- POST /encrypt?api-version=2020-09-01 {"content-length": "355", "content-type": "application/json"} Aug 03 12:32:31 dfa-wg-onsp-001 aziot-keyd[28302]: WARNING:esys:src/tss2-esys/api/Esys_RSA_Decrypt.c:305:Esys_RSA_Decrypt_Finish() Received TPM Error Aug 03 12:32:31 dfa-wg-onsp-001 aziot-keyd[28302]: ERROR:esys:src/tss2-esys/api/Esys_RSA_Decrypt.c:102:Esys_RSA_Decrypt() Esys Finish ErrorCode (0x00000918) Aug 03 12:32:31 dfa-wg-onsp-001 aziot-keyd[28302]: ERROR: Esys_RSA_Decrypt: tpm:warn(2.0): the 1st authorization session handle references a session that is not loaded Aug 03 12:32:31 dfa-wg-onsp-001 aziot-keyd[28302]: 2021-08-03T12:32:31Z [ERR!] - could not encrypt: C_Sign failed with CKR_GENERAL_ERROR Aug 03 12:32:31 dfa-wg-onsp-001 aziot-keyd[28302]: 2021-08-03T12:32:31Z [ERR!] - !!! internal error Aug 03 12:32:31 dfa-wg-onsp-001 aziot-keyd[28302]: 2021-08-03T12:32:31Z [ERR!] - !!! caused by: could not encrypt Aug 03 12:32:31 dfa-wg-onsp-001 aziot-keyd[28302]: 2021-08-03T12:32:31Z [ERR!] - !!! caused by: could not encrypt: AZIOT_KEYS_RC_ERR_EXTERNAL Aug 03 12:32:31 dfa-wg-onsp-001 aziot-keyd[28302]: 2021-08-03T12:32:31Z [INFO] - --> 500 {"content-type": "application/json"}
Aug 03 12:32:57 dfa-wg-onsp-001 systemd[1]: aziot-identityd.service: Main process exited, code=exited, status=1/FAILURE Aug 03 12:32:57 dfa-wg-onsp-001 systemd[1]: aziot-identityd.service: Failed with result 'exit-code'. Aug 03 12:33:03 dfa-wg-onsp-001 systemd[1]: aziot-identityd.service: Service hold-off time over, scheduling restart. Aug 03 12:33:03 dfa-wg-onsp-001 systemd[1]: aziot-identityd.service: Scheduled restart job, restart counter is at 173. Aug 03 12:33:03 dfa-wg-onsp-001 systemd[1]: Stopped Azure IoT Identity Service. Aug 03 12:33:03 dfa-wg-onsp-001 systemd[1]: Started Azure IoT Identity Service. Aug 03 12:33:03 dfa-wg-onsp-001 aziot-identityd[1550]: 2021-08-03T12:33:03Z [INFO] - Starting service... Aug 03 12:33:03 dfa-wg-onsp-001 aziot-identityd[1550]: 2021-08-03T12:33:03Z [INFO] - Version - 1.2.2 Aug 03 12:33:03 dfa-wg-onsp-001 aziot-identityd[1550]: 2021-08-03T12:33:03Z [INFO] - Provisioning starting. Reason: Startup Aug 03 12:33:03 dfa-wg-onsp-001 aziot-identityd[1550]: 2021-08-03T12:33:03Z [ERR!] - Failed to provision with IoT Hub, and no valid device backup was found: internal error Aug 03 12:33:03 dfa-wg-onsp-001 aziot-identityd[1550]: 2021-08-03T12:33:03Z [ERR!] - service encountered an error Aug 03 12:33:03 dfa-wg-onsp-001 aziot-identityd[1550]: 2021-08-03T12:33:03Z [ERR!] - caused by: internal error Aug 03 12:33:03 dfa-wg-onsp-001 aziot-identityd[1550]: 2021-08-03T12:33:03Z [ERR!] - caused by: could not create certificate Aug 03 12:33:03 dfa-wg-onsp-001 aziot-identityd[1550]: 2021-08-03T12:33:03Z [ERR!] - caused by: error:80005001:aziot_key_openssl_engine:aziot_key_rsa_priv_enc::key/aziot-key-openssl-engine/src/lib.rs:112:internal error, error:0D0DC006:asn1 encoding routines:ASN1_item_sign_ctx:EVP lib:../crypto/asn1/a_sign.c:212: Aug 03 12:33:03 dfa-wg-onsp-001 aziot-identityd[1550]: 2021-08-03T12:33:03Z [ERR!] - 0:
Aug 03 12:33:03 dfa-wg-onsp-001 aziot-identityd[1550]: 1:
Aug 03 12:33:03 dfa-wg-onsp-001 systemd[1]: aziot-identityd.service: Main process exited, code=exited, status=1/FAILURE
Aug 03 12:33:03 dfa-wg-onsp-001 systemd[1]: aziot-identityd.service: Failed with result 'exit-code'.
edge@dfa-wg-onsp-001:~$ sudo -u aziotks pkcs11-tool --module "$PKCS11_LIB_PATH" -IOT WARNING:fapi:src/tss2-fapi/ifapi_io.c:282:ifapi_io_check_create_dir() Directory /home/edge//.local/share/tpm2-tss/user/keystore does not exist, creating ERROR:fapi:src/tss2-fapi/ifapi_helpers.c:986:create_dirs() mkdir not possible: -1 /home/edge/.local/share/tpm2-tss/ ERROR:fapi:src/tss2-fapi/ifapi_helpers.c:1013:ifapi_create_dirs() ErrorCode (0x0006000b) Create directories for /home/edge//.local/share/tpm2-tss/user/keystore ERROR:fapi:src/tss2-fapi/ifapi_io.c:285:ifapi_io_check_create_dir() ErrorCode (0x0006000b) Directory /home/edge//.local/share/tpm2-tss/user/keystore can't be created. ERROR:fapi:src/tss2-fapi/ifapi_keystore.c:464:ifapi_keystore_initialize() ErrorCode (0x0006000b) User directory /home/edge//.local/share/tpm2-tss/user/keystore can't be created. ERROR:fapi:src/tss2-fapi/api/Fapi_Initialize.c:206:Fapi_Initialize_Finish() ErrorCode (0x0006000b) Keystore could not be initialized. Cryptoki version 2.40 Manufacturer tpm2-software.github.io Library TPM2.0 Cryptoki (ver 0.0) Available slots: Slot 0 (0x1): dfapairs Intel token label : dfapairs token manufacturer : Intel token model : Intel token flags : login required, rng, token initialized, PIN initialized hardware version : 1.16 firmware version : 45.9 serial num : 0000000000000000 pin min/max : 0/128 Slot 1 (0x2): Intel token state: uninitialized Using slot 0 with a present token (0x1) Public Key Object; RSA 2048 bits label: device-id Usage: encrypt, verify
Aug 03 13:20:43 dfa-wg-onsp-001 aziot-certd[9262]: 2021-08-03T13:20:43Z [INFO] - --> 500 {"content-type": "application/json"} Aug 03 13:20:49 dfa-wg-onsp-001 aziot-certd[9262]: 2021-08-03T13:20:49Z [INFO] - <-- GET /certificates/device-id?api-version=2020-09-01 {"host": "certd.sock"} Aug 03 13:20:49 dfa-wg-onsp-001 aziot-certd[9262]: 2021-08-03T13:20:49Z [INFO] - !!! parameter "id" has an invalid value Aug 03 13:20:49 dfa-wg-onsp-001 aziot-certd[9262]: 2021-08-03T13:20:49Z [INFO] - !!! caused by: not found Aug 03 13:20:49 dfa-wg-onsp-001 aziot-certd[9262]: 2021-08-03T13:20:49Z [INFO] - --> 400 {"content-type": "application/json"} Aug 03 13:20:49 dfa-wg-onsp-001 aziot-certd[9262]: 2021-08-03T13:20:49Z [INFO] - <-- POST /certificates?api-version=2020-09-01 {"content-type": "application/json", "host": "certd.sock", "content-length": "959"} Aug 03 13:20:49 dfa-wg-onsp-001 aziot-certd[9262]: 2021-08-03T13:20:49Z [ERR!] - !!! internal error Aug 03 13:20:49 dfa-wg-onsp-001 aziot-certd[9262]: 2021-08-03T13:20:49Z [ERR!] - !!! caused by: could not create cert Aug 03 13:20:49 dfa-wg-onsp-001 aziot-certd[9262]: 2021-08-03T13:20:49Z [ERR!] - !!! caused by: internal error Aug 03 13:20:49 dfa-wg-onsp-001 aziot-certd[9262]: 2021-08-03T13:20:49Z [ERR!] - !!! caused by: could not create cert Aug 03 13:20:49 dfa-wg-onsp-001 aziot-certd[9262]: 2021-08-03T13:20:49Z [ERR!] - !!! caused by: error trying to connect: error:1416F086:SSL routines:tls_process_server_certificate:certificate verify failed:../ssl/statem/statem_clnt.c:1924:: self signed certificate in certificate chain Aug 03 13:20:49 dfa-wg-onsp-001 aziot-certd[9262]: 2021-08-03T13:20:49Z [ERR!] - !!! caused by: error:1416F086:SSL routines:tls_process_server_certificate:certificate verify failed:../ssl/statem/statem_clnt.c:1924:: self signed certificate in certificate chain Aug 03 13:20:49 dfa-wg-onsp-001 aziot-certd[9262]: 2021-08-03T13:20:49Z [ERR!] - !!! caused by: error:1416F086:SSL routines:tls_process_server_certificate:certificate verify failed:../ssl/statem/statem_clnt.c:1924: Aug 03 13:20:49 dfa-wg-onsp-001 aziot-certd[9262]: 2021-08-03T13:20:49Z [INFO] - --> 500 {"content-type": "application/json"}