search

Azure / iotedge

The IoT Edge OSS project
MIT License
1.45k stars 458 forks source link

HSM API returned an invalid null response #537

Closed shaeussler closed 5 years ago

shaeussler commented 5 years ago

Expected Behavior

The Azure IoT Edge Security Daemon should be able to provision a configured device with a defined IoT Hub via TPM attestation.

Current Behavior

While provisioning an IoT Edge device configured to use TPM attestation, the Azure IoT Edge Security Daemon crashes due to DPS error caused by HSM hardware.

Steps to Reproduce

  1. Follow the [how-to] (https://docs.microsoft.com/en-us/azure/iot-edge/how-to-auto-provision-simulated-device-windows) guide for creating and provisioning an Edge device. Substitute the simulated TPM with a real one.
  2. Use the tpm_device_provision application to get the Registration ID and Endorsement Key.
  3. Start-Service iotedge

Context (Environment)

Device (Host) Operating System

The Dell Precision Tower 3620 PC which has a TPM 2.0 chip on board running Windows 10 Pro.

Architecture

x64

Container Operating System

Linux containers

Runtime Versions

iotedged

Version - 1.0.4 (2835ac47fbb944ba628a5cfe812ff394768842e0)

Edge Agent

Image tag 1.0.4

Edge Hub

Image tag 1.0.4

Docker

Client: Version: 18.06.1-ce API version: 1.38 Go version: go1.10.3 Git commit: e68fc7a Built: Tue Aug 21 17:21:34 2018 OS/Arch: windows/amd64 Experimental: false

Server: Engine: Version: 18.06.1-ce API version: 1.38 (minimum version 1.12) Go version: go1.10.3 Git commit: e68fc7a Built: Tue Aug 21 17:29:02 2018 OS/Arch: linux/amd64 Experimental: false

Logs

13.11.2018 15:49:30 info: iotedged::app -- Version - 1.0.4 (2835ac47fbb944ba628a5cfe812ff394768842e0) 13.11.2018 15:49:30 info: iotedged::app -- Starting Azure IoT Edge Security Daemon 13.11.2018 15:49:30 info: iotedged::app -- Using config file: C:\ProgramData\iotedge\config.yaml 13.11.2018 15:49:30 info: iotedged::windows -- Starting iotedged service. 13.11.2018 15:49:30 info: iotedged -- Initializing the module runtime... 13.11.2018 15:49:30 info: iotedged -- Using runtime network id azure-iot-edge 13.11.2018 15:49:30 info: iotedged -- Finished initializing the module runtime. 13.11.2018 15:49:30 info: iotedged -- Finished configuring certificates. 13.11.2018 15:49:30 info: iotedged -- Initializing hsm... 13.11.2018 15:49:30 info: iotedged -- Transparent gateway certificates not found, operating in quick start mode... 13.11.2018 15:49:30 info: iotedged -- Configuring C:\ProgramData\iotedge as the home directory. 13.11.2018 15:49:30 info: iotedged -- Configuring certificates... 13.11.2018 15:49:30 info: iotedged -- Detecting if configuration file has changed... 13.11.2018 15:49:30 info: iotedged -- Finished initializing hsm. 13.11.2018 15:49:30 info: iotedged -- No change to configuration file detected. 13.11.2018 15:49:30 info: iotedged -- Provisioning edge device... 13.11.2018 15:49:30 info: iotedged -- Obtaining workload CA succeeded. 13.11.2018 15:49:31 error: edgelet_utils::logging -- A hardware hsm error occurred. 13.11.2018 15:49:31 error: iotedged::windows -- Error while running service. Quitting. 13.11.2018 15:49:31 info: iotedged::windows -- Stopped iotedged service. 13.11.2018 15:49:31 error: edgelet_utils::logging -- caused by: HSM API returned an invalid null response

Additional Information

I have done the same test one another Dell Precision Tower PC which has a newer TPM 2.0 chip firmware and running Windows 10 Pro. The result was the same error.

darobs commented 5 years ago

Hello @shaeussler

There are two expected reasons you would expect to see this error.

The first is you configured the edge deployment for DPS, but did not set an environment variable, IOTEDGE_USE_TPM_DEVICE=ON.

This is normally done by the setup script, but if you're running the iotedged executable manually, or did not set up iotedged in DPS mode before, this might not be set.

If you're running this manually, setting the environment variable before running it will help.

If you are running the service, the relevant powershell commands to set this in the service are:

        New-Item "HKLM:\SYSTEM\CurrentControlSet\Services\iotedge" -Force | Out-Null
        New-ItemProperty `
            -Path "HKLM:\SYSTEM\CurrentControlSet\Services\iotedge" `
            -Name "Environment" `
            -PropertyType "MultiString" `
            -Value "IOTEDGE_USE_TPM_DEVICE=ON" `
            -Force | Out-Null

The second reason is that the call to TPM initialization actually returned NULL. I'm investigating that right now.

darobs commented 5 years ago

I was able to reproduce a problem with Windows on a real TPM device, but I think some logs are getting lost because they're being generated on stdout or stderr.

In order to confirm what I'm seeing is the same as your problem, would you do the following for me in an administrator powershell windows?

Stop-Service iotedge -NoWait
$Env:IOTEDGE_RUN_AS_CONSOLE = "ON"
$Env:IOTEDGE_USE_TPM_DEVICE = "ON"
$Env:IOTEDGE_LOG = "debug"

C:\ProgramData\iotedge\iotedged.exe -c C:\ProgramData\iotedge\config.yaml

And then provide the console output after "Provisioning edge device..."?

Based on the error I'm getting, it shouldn't have any personal information in the logs, but please remove any if visible.

Thanks, DAVE!!!

shaeussler commented 5 years ago

The console output:

<6>2018-11-14T08:46:57Z [INFO] - Provisioning edge device...
Error: Time:Wed Nov 14 09:46:58 2018 File:d:\a\1\s\edgelet\hsm-sys\azure-iot-hsm-c\deps\utpm\src\tpm_socket_comm.c Func:tpm_socket_create Line:208 Failure: connecting to tpm simulator.
Error: Time:Wed Nov 14 09:46:58 2018 File:d:\a\1\s\edgelet\hsm-sys\azure-iot-hsm-c\deps\utpm\src\tpm_comm_emulator.c Func:tpm_comm_create Line:245 Failure: connecting to tpm simulator.
Error: Time:Wed Nov 14 09:46:58 2018 File:d:\a\1\s\edgelet\hsm-sys\azure-iot-hsm-c\deps\utpm\src\tpm_codec.c Func:Initialize_TPM_Codec Line:258 creating tpm_comm object
<3>2018-11-14T08:46:58Z [ERR!] (d:\a\1\s\edgelet\hsm-sys\azure-iot-hsm-c\src\hsm_client_tpm_device.c:initialize_tpm_device:272) Failure initializeing TPM Codec
<3>2018-11-14T08:46:58Z [ERR!] (d:\a\1\s\edgelet\hsm-sys\azure-iot-hsm-c\src\hsm_client_tpm_device.c:hsm_client_tpm_create:305) Failure initializing tpm device.
<7>2018-11-14T08:46:58Z [DBUG] - [tokio_reactor] dropping I/O source: 0
<7>2018-11-14T08:46:58Z [DBUG] - [tokio_reactor] loop process - 0 events, 0.000s
<7>2018-11-14T08:46:58Z [DBUG] - [tokio_reactor::background] shutting background reactor down NOW
<7>2018-11-14T08:46:58Z [DBUG] - [tokio_reactor::background] background reactor has shutdown
<3>2018-11-14T08:46:58Z [ERR!] - A hardware hsm error occurred.
<3>2018-11-14T08:46:58Z [ERR!] -        caused by: HSM API returned an invalid null response
darobs commented 5 years ago

Thanks @shaeussler,

You're experiencing the same thing I am. If I'm reading this correctly. it looks like we distributed an HSM library which is compiled to expect a TPM simulator - the TPM code we are using makes that choice at compile time.

I've submitted this as a bug into our backlog.

Unfortunately, the only workaround is to rebuild the HSM library with use_emulator=off. This requires CMake and a C/C++ compiler for Windows.

Quick steps:

  1. clone repo
  2. cd \<repo>/edgelet/hsm-sys/azure-iot-hsm-c/build
  3. cmake -use_emulator=OFF --build . --config Release
myagley commented 5 years ago

The 1.0.5 release of the runtime will contain a fix for this issue. It's currently scheduled for some time before the end of the year.

myagley commented 5 years ago

This has been fixed in the 1.0.5 release. More information on upgrading is here: https://docs.microsoft.com/en-us/azure/iot-edge/how-to-update-iot-edge

piyushsharma2512 commented 5 years ago

I'm facing the same issue to setup edge runtime using TPM and also having edge run-time version 1.0.6.1 and windows version 1809.