Failed to use aziot_keys engine with OpenSSL

bemol38 commented 2 years ago

Hi everybody, I'm using the iot-identity-service to provision a device with Azure DPS, issuing the device certificate with an EST Server. Everything works FINE. But I'm having some issue using the aziot_keys engine with Azure IOT SDK for C, when I want connect to the IoT Hub. For that reason, I'd like to perform a simple test with OpenSSL command line tool using the aziot_keys engine This is the script I'm using:

#!/bin/bash
identity="$(sudo curl --unix-socket '/run/aziot/identityd.sock' 'http://identityd.sock/identities/identity?api-version=2020-09-01')"
hub_name="$(<<< "$identity" jq -r '.spec.hubName')"
cert_id="$(<<< "$identity" jq -r '.spec.auth.certId')"
key_handle="$(<<< "$identity" jq -r '.spec.auth.keyHandle')"
curl --unix-socket '/run/aziot/certd.sock' "http://certd.sock/certificates/${cert_id}?api-version=2020-09-01" \
    | jq -r '.pem' > cert_from_identity_service.pem
openssl s_client -connect $hub_name -cert ./cert_from_identity_service.pem -keyform engine -engine aziot_keys -key "$key_handle_from_identity_service"

This is the error I got:

engine "aziot-key-openssl-engine" set.
cannot load client certificate private key file from engine
139993012631232:error:80001001:aziot_key_openssl_engine:aziot_key_engine_load_privkey::key/aziot-key-openssl-engine/src/lib.rs:112:parameter "handle" has an invalid value
caused by: invalid handle
139993012631232:error:26096080:engine routines:ENGINE_load_private_key:failed loading private key:../crypto/engine/eng_pkey.c:77:
unable to load client certificate private key file

I would really appreciate to know if this approach to test the engine is correct, and what kind of error I'm doing.

Thank you in advance for supporting me.

arsing commented 2 years ago

What's the output of <<< "$identity" jq ? ie post the blob that the identityd request returned.

Also post logs from keyd at the time you did this.

bemol38 commented 2 years ago

Hi arsing, Output of <<< "identity" jq:

{"type":"aziot","spec":{"hubName":"hbb.azure-devices.net","gatewayHost":"hbb.azure-devices.net","deviceId":"hbb-device-01","auth":{"type":"x509","keyHandle":"sr=eyJrZXlfaWQiOnsiS2V5UGFpciI6ImRldmljZS1pZCJ9LCJub25jZSI6Ik1UYnJHMUJGOUNoUUpESTNXTnhtNzE4RDJKd1FuSTJGcGlqczBSb0x2a0lYRkNTMG9tbzN6SDRWeWduSmM3eExRWUJYeXl3SnNCdS9uKyt1Ti9rV2x3PT0ifQ==&sig=WblP6hzUrclZc45hR37QhHlEPIJj9q4VBHNKzjZib0s=","certId":"device-id"}}}

Log of aziotctl (the error is in the last 20 lines) The aziotctl service is restarted at 09:49:17. The openssl command is started at 09:49:59

avril 14 09:49:17 ******** systemd[1]: Started Azure IoT Keys Service.
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [INFO] - Starting service...
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [INFO] - Version - 1.2.6
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [INFO] - Loaded libaziot-keys with version 0x02000000
avril 14 09:49:17 ******** aziot-keyd[93978]: WARNING:fapi:src/tss2-fapi/api/Fapi_List.c:226:Fapi_List_Finish() Profile of path not provisioned: /HS/SRK
avril 14 09:49:17 ******** aziot-keyd[93978]: ERROR:fapi:src/tss2-fapi/api/Fapi_List.c:81:Fapi_List() ErrorCode (0x00060034) Entities_List
avril 14 09:49:17 ******** aziot-keyd[93978]: ERROR: Listing FAPI token objects failed.
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [INFO] - Starting server...
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [TRCE] - [mio::poll] registering event source with poller: token=Token(0), interests=READABLE | WRITABLE
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [TRCE] - [mio::poll] registering event source with poller: token=Token(1), interests=READABLE | WRITABLE
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [TRCE] - [hyper::proto::h1::conn] Conn::read_head
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [TRCE] - [tracing::span] parse_headers
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [TRCE] - [tracing::span::active] -> parse_headers
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [TRCE] - [hyper::proto::h1::role] Request.parse([Header; 100], [u8; 75])
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [TRCE] - [hyper::proto::h1::role] Request.parse Complete(75)
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [TRCE] - [hyper::proto::h1::role] headers: [Header { name: "host", value: [107, 101, 121, 100, 46, 115, 111, 99, 107] }]
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [TRCE] - [tracing::span::active] <- parse_headers
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [TRCE] - [tracing::span] -- parse_headers
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [DBUG] - [hyper::proto::h1::io] parsed 1 headers
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [DBUG] - [hyper::proto::h1::conn] incoming body is empty
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [INFO] - <-- GET /keypair/device-id?api-version=2020-09-01 {"host": "keyd.sock"}
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [TRCE] - [mio::poll] registering with poller
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [TRCE] - [mio::poll] registering with poller
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [TRCE] - [mio::poll] registering with poller
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [INFO] - --> 200 {"content-type": "application/json"}
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [TRCE] - [tracing::span] encode_headers
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [TRCE] - [tracing::span::active] -> encode_headers
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [TRCE] - [hyper::proto::h1::role] Server::encode status=200, body=Some(Known(248)), req_method=Some(GET)
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [TRCE] - [tracing::span::active] <- encode_headers
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [TRCE] - [tracing::span] -- encode_headers
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [DBUG] - [hyper::proto::h1::io] flushed 357 bytes
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [TRCE] - [hyper::proto::h1::conn] flushed({role=server}): State { reading: Init, writing: Init, keep_alive: Idle }
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [TRCE] - [mio::poll] registering event source with poller: token=Token(2), interests=READABLE | WRITABLE
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [TRCE] - [hyper::proto::h1::conn] Conn::read_head
avril 14 09:49:17 ******** aziot-identityd[93941]: 2022-04-14T07:49:17Z [TRCE] - [hyper::proto::h1::conn] Conn::read_head
avril 14 09:49:17 ******** aziot-identityd[93941]: 2022-04-14T07:49:17Z [TRCE] - [tracing::span] parse_headers
avril 14 09:49:17 ******** aziot-identityd[93941]: 2022-04-14T07:49:17Z [TRCE] - [tracing::span::active] -> parse_headers
avril 14 09:49:17 ******** aziot-identityd[93941]: 2022-04-14T07:49:17Z [TRCE] - [hyper::proto::h1::role] Response.parse([Header; 100], [u8; 357])
avril 14 09:49:17 ******** aziot-identityd[93941]: 2022-04-14T07:49:17Z [TRCE] - [hyper::proto::h1::role] Response.parse Complete(109)
avril 14 09:49:17 ******** aziot-identityd[93941]: 2022-04-14T07:49:17Z [TRCE] - [tracing::span::active] <- parse_headers
avril 14 09:49:17 ******** aziot-identityd[93941]: 2022-04-14T07:49:17Z [TRCE] - [tracing::span] -- parse_headers
avril 14 09:49:17 ******** aziot-identityd[93941]: 2022-04-14T07:49:17Z [DBUG] - [hyper::proto::h1::io] parsed 3 headers
avril 14 09:49:17 ******** aziot-identityd[93941]: 2022-04-14T07:49:17Z [DBUG] - [hyper::proto::h1::conn] incoming body is content-length (248 bytes)
avril 14 09:49:17 ******** aziot-identityd[93941]: 2022-04-14T07:49:17Z [TRCE] - [hyper::proto::h1::decode] decode; state=Length(248)
avril 14 09:49:17 ******** aziot-identityd[93941]: 2022-04-14T07:49:17Z [DBUG] - [hyper::proto::h1::conn] incoming body completed
avril 14 09:49:17 ******** aziot-identityd[93941]: 2022-04-14T07:49:17Z [TRCE] - [hyper::proto::h1::conn] maybe_notify; read_from_io blocked
avril 14 09:49:17 ******** aziot-identityd[93941]: 2022-04-14T07:49:17Z [TRCE] - [want] signal: Want
avril 14 09:49:17 ******** aziot-identityd[93941]: 2022-04-14T07:49:17Z [TRCE] - [hyper::proto::h1::conn] flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Idle }
avril 14 09:49:17 ******** aziot-identityd[93941]: 2022-04-14T07:49:17Z [TRCE] - [want] signal: Want
avril 14 09:49:17 ******** aziot-identityd[93941]: 2022-04-14T07:49:17Z [TRCE] - [hyper::proto::h1::conn] flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Idle }
avril 14 09:49:17 ******** aziot-identityd[93941]: 2022-04-14T07:49:17Z [TRCE] - [hyper::client::pool] put; add idle connection for ("http", keyd.sock)
avril 14 09:49:17 ******** aziot-identityd[93941]: 2022-04-14T07:49:17Z [DBUG] - [hyper::client::pool] pooling idle connection for ("http", keyd.sock)
avril 14 09:49:17 ******** aziot-identityd[93941]: 2022-04-14T07:49:17Z [TRCE] - [want] signal: Want
avril 14 09:49:17 ******** aziot-identityd[93941]: 2022-04-14T07:49:17Z [TRCE] - [hyper::proto::h1::conn] flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Idle }
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [TRCE] - [tracing::span] parse_headers
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [TRCE] - [tracing::span::active] -> parse_headers
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [TRCE] - [hyper::proto::h1::role] Request.parse([Header; 100], [u8; 363])
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [TRCE] - [hyper::proto::h1::role] Request.parse Complete(115)
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [TRCE] - [hyper::proto::h1::role] headers: [Header { name: "content-length", value: [50, 52, 56] }, Header { name: "content-type", value: [97, 112, 112, 108, 105, 99, 97, 116, 105, 111, 110, 47, 106, 115, 111, 110] }]
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [TRCE] - [tracing::span::active] <- parse_headers
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [TRCE] - [tracing::span] -- parse_headers
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [DBUG] - [hyper::proto::h1::io] parsed 2 headers
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [DBUG] - [hyper::proto::h1::conn] incoming body is content-length (248 bytes)
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [INFO] - <-- POST /parameters/algorithm?api-version=2020-09-01 {"content-length": "248", "content-type": "application/json"}
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [TRCE] - [hyper::proto::h1::decode] decode; state=Length(248)
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [DBUG] - [hyper::proto::h1::conn] incoming body completed
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [INFO] - --> 200 {"content-type": "application/json"}
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [TRCE] - [tracing::span] encode_headers
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [TRCE] - [tracing::span::active] -> encode_headers
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [TRCE] - [hyper::proto::h1::role] Server::encode status=200, body=Some(Known(15)), req_method=Some(POST)
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [TRCE] - [tracing::span::active] <- encode_headers
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [TRCE] - [tracing::span] -- encode_headers
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [DBUG] - [hyper::proto::h1::io] flushed 123 bytes
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [TRCE] - [hyper::proto::h1::conn] flushed({role=server}): State { reading: Init, writing: Init, keep_alive: Idle }
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [TRCE] - [hyper::proto::h1::conn] Conn::read_head
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [TRCE] - [hyper::proto::h1::conn] flushed({role=server}): State { reading: Init, writing: Init, keep_alive: Idle }
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [TRCE] - [hyper::proto::h1::conn] Conn::read_head
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [TRCE] - [hyper::proto::h1::io] parse eof
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [TRCE] - [hyper::proto::h1::conn] State::close_read()
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [DBUG] - [hyper::proto::h1::conn] read eof
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [TRCE] - [hyper::proto::h1::conn] State::close_write()
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [TRCE] - [hyper::proto::h1::conn] State::close_read()
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [TRCE] - [hyper::proto::h1::conn] State::close_write()
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [TRCE] - [hyper::proto::h1::conn] flushed({role=server}): State { reading: Closed, writing: Closed, keep_alive: Disabled }
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [TRCE] - [hyper::proto::h1::conn] shut down IO complete
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [TRCE] - [mio::poll] deregistering event source from poller
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [TRCE] - [mio::poll] registering event source with poller: token=Token(16777218), interests=READABLE | WRITABLE
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [TRCE] - [hyper::proto::h1::conn] Conn::read_head
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [TRCE] - [hyper::proto::h1::conn] flushed({role=server}): State { reading: Init, writing: Init, keep_alive: Busy }
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [TRCE] - [hyper::proto::h1::conn] Conn::read_head
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [TRCE] - [tracing::span] parse_headers
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [TRCE] - [tracing::span::active] -> parse_headers
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [TRCE] - [hyper::proto::h1::role] Request.parse([Header; 100], [u8; 365])
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [TRCE] - [hyper::proto::h1::role] Request.parse Complete(117)
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [TRCE] - [hyper::proto::h1::role] headers: [Header { name: "content-length", value: [50, 52, 56] }, Header { name: "content-type", value: [97, 112, 112, 108, 105, 99, 97, 116, 105, 111, 110, 47, 106, 115, 111, 110] }]
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [TRCE] - [tracing::span::active] <- parse_headers
avril 14 09:49:17 ******** aziot-identityd[93941]: 2022-04-14T07:49:17Z [TRCE] - [hyper::client::pool] take? ("http", certd.sock): expiration = Some(90s)
avril 14 09:49:17 ******** aziot-identityd[93941]: 2022-04-14T07:49:17Z [DBUG] - [hyper::client::pool] reuse idle connection for ("http", certd.sock)
avril 14 09:49:17 ******** aziot-identityd[93941]: 2022-04-14T07:49:17Z [TRCE] - [tracing::span] encode_headers
avril 14 09:49:17 ******** aziot-identityd[93941]: 2022-04-14T07:49:17Z [TRCE] - [tracing::span::active] -> encode_headers
avril 14 09:49:17 ******** aziot-identityd[93941]: 2022-04-14T07:49:17Z [TRCE] - [hyper::proto::h1::role] Client::encode method=GET, body=None
avril 14 09:49:17 ******** aziot-identityd[93941]: 2022-04-14T07:49:17Z [TRCE] - [tracing::span::active] <- encode_headers
avril 14 09:49:17 ******** aziot-identityd[93941]: 2022-04-14T07:49:17Z [TRCE] - [tracing::span] -- encode_headers
avril 14 09:49:17 ******** aziot-identityd[93941]: 2022-04-14T07:49:17Z [DBUG] - [hyper::proto::h1::io] flushed 81 bytes
avril 14 09:49:17 ******** aziot-identityd[93941]: 2022-04-14T07:49:17Z [TRCE] - [hyper::proto::h1::conn] flushed({role=client}): State { reading: Init, writing: KeepAlive, keep_alive: Busy }
avril 14 09:49:17 ******** aziot-identityd[93941]: 2022-04-14T07:49:17Z [TRCE] - [hyper::proto::h1::conn] Conn::read_head
avril 14 09:49:17 ******** aziot-identityd[93941]: 2022-04-14T07:49:17Z [TRCE] - [tracing::span] parse_headers
avril 14 09:49:17 ******** aziot-identityd[93941]: 2022-04-14T07:49:17Z [TRCE] - [tracing::span::active] -> parse_headers
avril 14 09:49:17 ******** aziot-identityd[93941]: 2022-04-14T07:49:17Z [TRCE] - [hyper::proto::h1::role] Response.parse([Header; 100], [u8; 5290])
avril 14 09:49:17 ******** aziot-identityd[93941]: 2022-04-14T07:49:17Z [TRCE] - [hyper::proto::h1::role] Response.parse Complete(110)
avril 14 09:49:17 ******** aziot-identityd[93941]: 2022-04-14T07:49:17Z [TRCE] - [tracing::span::active] <- parse_headers
avril 14 09:49:17 ******** aziot-identityd[93941]: 2022-04-14T07:49:17Z [TRCE] - [tracing::span] -- parse_headers
avril 14 09:49:17 ******** aziot-identityd[93941]: 2022-04-14T07:49:17Z [DBUG] - [hyper::proto::h1::io] parsed 3 headers
avril 14 09:49:17 ******** aziot-identityd[93941]: 2022-04-14T07:49:17Z [DBUG] - [hyper::proto::h1::conn] incoming body is content-length (5180 bytes)
avril 14 09:49:17 ******** aziot-identityd[93941]: 2022-04-14T07:49:17Z [TRCE] - [hyper::proto::h1::decode] decode; state=Length(5180)
avril 14 09:49:17 ******** aziot-identityd[93941]: 2022-04-14T07:49:17Z [DBUG] - [hyper::proto::h1::conn] incoming body completed
avril 14 09:49:17 ******** aziot-identityd[93941]: 2022-04-14T07:49:17Z [TRCE] - [hyper::proto::h1::conn] maybe_notify; read_from_io blocked
avril 14 09:49:17 ******** aziot-identityd[93941]: 2022-04-14T07:49:17Z [TRCE] - [want] signal: Want
avril 14 09:49:17 ******** aziot-identityd[93941]: 2022-04-14T07:49:17Z [TRCE] - [hyper::proto::h1::conn] flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Idle }
avril 14 09:49:17 ******** aziot-identityd[93941]: 2022-04-14T07:49:17Z [TRCE] - [want] signal: Want
avril 14 09:49:17 ******** aziot-certd[93958]: 2022-04-14T07:49:17Z [TRCE] - [hyper::proto::h1::conn] Conn::read_head
avril 14 09:49:17 ******** aziot-certd[93958]: 2022-04-14T07:49:17Z [TRCE] - [tracing::span] parse_headers
avril 14 09:49:17 ******** aziot-certd[93958]: 2022-04-14T07:49:17Z [TRCE] - [tracing::span::active] -> parse_headers
avril 14 09:49:17 ******** aziot-certd[93958]: 2022-04-14T07:49:17Z [TRCE] - [hyper::proto::h1::role] Request.parse([Header; 100], [u8; 81])
avril 14 09:49:17 ******** aziot-certd[93958]: 2022-04-14T07:49:17Z [TRCE] - [hyper::proto::h1::role] Request.parse Complete(81)
avril 14 09:49:17 ******** aziot-certd[93958]: 2022-04-14T07:49:17Z [TRCE] - [hyper::proto::h1::role] headers: [Header { name: "host", value: [99, 101, 114, 116, 100, 46, 115, 111, 99, 107] }]
avril 14 09:49:17 ******** aziot-certd[93958]: 2022-04-14T07:49:17Z [TRCE] - [tracing::span::active] <- parse_headers
avril 14 09:49:17 ******** aziot-certd[93958]: 2022-04-14T07:49:17Z [TRCE] - [tracing::span] -- parse_headers
avril 14 09:49:17 ******** aziot-certd[93958]: 2022-04-14T07:49:17Z [DBUG] - [hyper::proto::h1::io] parsed 1 headers
avril 14 09:49:17 ******** aziot-certd[93958]: 2022-04-14T07:49:17Z [DBUG] - [hyper::proto::h1::conn] incoming body is empty
avril 14 09:49:17 ******** aziot-certd[93958]: 2022-04-14T07:49:17Z [INFO] - <-- GET /certificates/device-id?api-version=2020-09-01 {"host": "certd.sock"}
avril 14 09:49:17 ******** aziot-certd[93958]: 2022-04-14T07:49:17Z [INFO] - --> 200 {"content-type": "application/json"}
avril 14 09:49:17 ******** aziot-certd[93958]: 2022-04-14T07:49:17Z [TRCE] - [tracing::span] encode_headers
avril 14 09:49:17 ******** aziot-certd[93958]: 2022-04-14T07:49:17Z [TRCE] - [tracing::span::active] -> encode_headers
avril 14 09:49:17 ******** aziot-certd[93958]: 2022-04-14T07:49:17Z [TRCE] - [hyper::proto::h1::role] Server::encode status=200, body=Some(Known(5180)), req_method=Some(GET)
avril 14 09:49:17 ******** aziot-certd[93958]: 2022-04-14T07:49:17Z [TRCE] - [tracing::span::active] <- encode_headers
avril 14 09:49:17 ******** aziot-certd[93958]: 2022-04-14T07:49:17Z [TRCE] - [tracing::span] -- encode_headers
avril 14 09:49:17 ******** aziot-certd[93958]: 2022-04-14T07:49:17Z [DBUG] - [hyper::proto::h1::io] flushed 5290 bytes
avril 14 09:49:17 ******** aziot-certd[93958]: 2022-04-14T07:49:17Z [TRCE] - [hyper::proto::h1::conn] flushed({role=server}): State { reading: Init, writing: Init, keep_alive: Idle }
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [TRCE] - [tracing::span] -- parse_headers
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [DBUG] - [hyper::proto::h1::io] parsed 2 headers
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [DBUG] - [hyper::proto::h1::conn] incoming body is content-length (248 bytes)
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [INFO] - <-- POST /parameters/rsa-modulus?api-version=2020-09-01 {"content-length": "248", "content-type": "application/json"}
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [TRCE] - [hyper::proto::h1::decode] decode; state=Length(248)
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [DBUG] - [hyper::proto::h1::conn] incoming body completed
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [INFO] - --> 200 {"content-type": "application/json"}
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [TRCE] - [tracing::span] encode_headers
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [TRCE] - [tracing::span::active] -> encode_headers
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [TRCE] - [hyper::proto::h1::role] Server::encode status=200, body=Some(Known(356)), req_method=Some(POST)
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [TRCE] - [tracing::span::active] <- encode_headers
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [TRCE] - [tracing::span] -- encode_headers
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [DBUG] - [hyper::proto::h1::io] flushed 465 bytes
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [TRCE] - [hyper::proto::h1::conn] flushed({role=server}): State { reading: Init, writing: Init, keep_alive: Idle }
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [TRCE] - [hyper::proto::h1::conn] Conn::read_head
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [TRCE] - [hyper::proto::h1::conn] flushed({role=server}): State { reading: Init, writing: Init, keep_alive: Idle }
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [TRCE] - [hyper::proto::h1::conn] Conn::read_head
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [TRCE] - [hyper::proto::h1::io] parse eof
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [TRCE] - [hyper::proto::h1::conn] State::close_read()
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [DBUG] - [hyper::proto::h1::conn] read eof
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [TRCE] - [hyper::proto::h1::conn] State::close_write()
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [TRCE] - [hyper::proto::h1::conn] State::close_read()
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [TRCE] - [hyper::proto::h1::conn] State::close_write()
avril 14 09:49:17 ******** aziot-identityd[93941]: 2022-04-14T07:49:17Z [TRCE] - [hyper::proto::h1::conn] flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Idle }
avril 14 09:49:17 ******** aziot-identityd[93941]: 2022-04-14T07:49:17Z [TRCE] - [want] poll_want: taker wants!
avril 14 09:49:17 ******** aziot-identityd[93941]: 2022-04-14T07:49:17Z [TRCE] - [hyper::client::pool] put; add idle connection for ("http", certd.sock)
avril 14 09:49:17 ******** aziot-identityd[93941]: 2022-04-14T07:49:17Z [DBUG] - [hyper::client::pool] pooling idle connection for ("http", certd.sock)
avril 14 09:49:17 ******** aziot-identityd[93941]: 2022-04-14T07:49:17Z [TRCE] - [want] signal: Want
avril 14 09:49:17 ******** aziot-identityd[93941]: 2022-04-14T07:49:17Z [TRCE] - [hyper::proto::h1::conn] flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Idle }
avril 14 09:49:17 ******** aziot-identityd[93941]: 2022-04-14T07:49:17Z [TRCE] - [hyper::client::pool] checkout waiting for idle connection: ("https", hbb.azure-devices.net)
avril 14 09:49:17 ******** aziot-identityd[93941]: 2022-04-14T07:49:17Z [TRCE] - [hyper::client::connect::http] Http::connect; scheme=Some("https"), host=Some("hbb.azure-devices.net"), port=None
avril 14 09:49:17 ******** aziot-identityd[93941]: 2022-04-14T07:49:17Z [DBUG] - [hyper::client::connect::dns] resolving host="hbb.azure-devices.net"
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [TRCE] - [hyper::proto::h1::conn] flushed({role=server}): State { reading: Closed, writing: Closed, keep_alive: Disabled }
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [TRCE] - [hyper::proto::h1::conn] shut down IO complete
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [TRCE] - [mio::poll] deregistering event source from poller
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [TRCE] - [mio::poll] registering event source with poller: token=Token(33554434), interests=READABLE | WRITABLE
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [TRCE] - [hyper::proto::h1::conn] Conn::read_head
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [TRCE] - [hyper::proto::h1::conn] flushed({role=server}): State { reading: Init, writing: Init, keep_alive: Busy }
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [TRCE] - [hyper::proto::h1::conn] Conn::read_head
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [TRCE] - [tracing::span] parse_headers
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [TRCE] - [tracing::span::active] -> parse_headers
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [TRCE] - [hyper::proto::h1::role] Request.parse([Header; 100], [u8; 366])
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [TRCE] - [hyper::proto::h1::role] Request.parse Complete(118)
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [TRCE] - [hyper::proto::h1::role] headers: [Header { name: "content-length", value: [50, 52, 56] }, Header { name: "content-type", value: [97, 112, 112, 108, 105, 99, 97, 116, 105, 111, 110, 47, 106, 115, 111, 110] }]
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [TRCE] - [tracing::span::active] <- parse_headers
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [TRCE] - [tracing::span] -- parse_headers
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [DBUG] - [hyper::proto::h1::io] parsed 2 headers
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [DBUG] - [hyper::proto::h1::conn] incoming body is content-length (248 bytes)
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [INFO] - <-- POST /parameters/rsa-exponent?api-version=2020-09-01 {"content-length": "248", "content-type": "application/json"}
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [TRCE] - [hyper::proto::h1::decode] decode; state=Length(248)
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [DBUG] - [hyper::proto::h1::conn] incoming body completed
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [INFO] - --> 200 {"content-type": "application/json"}
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [TRCE] - [tracing::span] encode_headers
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [TRCE] - [tracing::span::active] -> encode_headers
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [TRCE] - [hyper::proto::h1::role] Server::encode status=200, body=Some(Known(16)), req_method=Some(POST)
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [TRCE] - [tracing::span::active] <- encode_headers
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [TRCE] - [tracing::span] -- encode_headers
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [DBUG] - [hyper::proto::h1::io] flushed 124 bytes
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [TRCE] - [hyper::proto::h1::conn] flushed({role=server}): State { reading: Init, writing: Init, keep_alive: Idle }
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [TRCE] - [hyper::proto::h1::conn] Conn::read_head
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [TRCE] - [hyper::proto::h1::conn] flushed({role=server}): State { reading: Init, writing: Init, keep_alive: Idle }
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [TRCE] - [hyper::proto::h1::conn] Conn::read_head
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [TRCE] - [hyper::proto::h1::io] parse eof
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [TRCE] - [hyper::proto::h1::conn] State::close_read()
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [DBUG] - [hyper::proto::h1::conn] read eof
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [TRCE] - [hyper::proto::h1::conn] State::close_write()
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [TRCE] - [hyper::proto::h1::conn] State::close_read()
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [TRCE] - [hyper::proto::h1::conn] State::close_write()
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [TRCE] - [hyper::proto::h1::conn] flushed({role=server}): State { reading: Closed, writing: Closed, keep_alive: Disabled }
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [TRCE] - [hyper::proto::h1::conn] shut down IO complete
avril 14 09:49:17 ******** aziot-keyd[93978]: 2022-04-14T07:49:17Z [TRCE] - [mio::poll] deregistering event source from poller
avril 14 09:49:17 ******** aziot-identityd[93941]: 2022-04-14T07:49:17Z [DBUG] - [hyper::client::connect::http] connecting to 13.69.109.1:443
avril 14 09:49:17 ******** aziot-identityd[93941]: 2022-04-14T07:49:17Z [TRCE] - [mio::poll] registering event source with poller: token=Token(2), interests=READABLE | WRITABLE
avril 14 09:49:17 ******** aziot-identityd[93941]: 2022-04-14T07:49:17Z [DBUG] - [hyper::client::connect::http] connected to 13.69.109.1:443
avril 14 09:49:17 ******** aziot-identityd[93941]: 2022-04-14T07:49:17Z [TRCE] - [hyper::client::conn] client handshake Http1
avril 14 09:49:17 ******** aziot-identityd[93941]: 2022-04-14T07:49:17Z [TRCE] - [hyper::client::client] handshake complete, spawning background dispatcher task
avril 14 09:49:17 ******** aziot-identityd[93941]: 2022-04-14T07:49:17Z [TRCE] - [want] signal: Want
avril 14 09:49:17 ******** aziot-identityd[93941]: 2022-04-14T07:49:17Z [TRCE] - [want] signal found waiting giver, notifying
avril 14 09:49:17 ******** aziot-identityd[93941]: 2022-04-14T07:49:17Z [TRCE] - [hyper::proto::h1::conn] flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Busy }
avril 14 09:49:17 ******** aziot-identityd[93941]: 2022-04-14T07:49:17Z [TRCE] - [want] poll_want: taker wants!
avril 14 09:49:17 ******** aziot-identityd[93941]: 2022-04-14T07:49:17Z [TRCE] - [hyper::client::pool] checkout dropped for ("https", hbb.azure-devices.net)
avril 14 09:49:17 ******** aziot-identityd[93941]: 2022-04-14T07:49:17Z [TRCE] - [tracing::span] encode_headers
avril 14 09:49:17 ******** aziot-identityd[93941]: 2022-04-14T07:49:17Z [TRCE] - [tracing::span::active] -> encode_headers
avril 14 09:49:17 ******** aziot-identityd[93941]: 2022-04-14T07:49:17Z [TRCE] - [hyper::proto::h1::role] Client::encode method=GET, body=None
avril 14 09:49:17 ******** aziot-identityd[93941]: 2022-04-14T07:49:17Z [TRCE] - [tracing::span::active] <- encode_headers
avril 14 09:49:17 ******** aziot-identityd[93941]: 2022-04-14T07:49:17Z [TRCE] - [tracing::span] -- encode_headers
avril 14 09:49:17 ******** aziot-identityd[93941]: 2022-04-14T07:49:17Z [DBUG] - [hyper::proto::h1::io] flushed 107 bytes
avril 14 09:49:17 ******** aziot-identityd[93941]: 2022-04-14T07:49:17Z [TRCE] - [hyper::proto::h1::conn] flushed({role=client}): State { reading: Init, writing: KeepAlive, keep_alive: Busy }
avril 14 09:49:17 ******** aziot-identityd[93941]: 2022-04-14T07:49:17Z [TRCE] - [hyper::proto::h1::conn] Conn::read_head
avril 14 09:49:17 ******** aziot-identityd[93941]: 2022-04-14T07:49:17Z [TRCE] - [hyper::proto::h1::conn] flushed({role=client}): State { reading: Init, writing: KeepAlive, keep_alive: Busy }
avril 14 09:49:18 ******** aziot-identityd[93941]: 2022-04-14T07:49:18Z [TRCE] - [hyper::proto::h1::conn] Conn::read_head
avril 14 09:49:18 ******** aziot-keyd[93978]: 2022-04-14T07:49:18Z [TRCE] - [mio::poll] registering event source with poller: token=Token(50331650), interests=READABLE | WRITABLE
avril 14 09:49:18 ******** aziot-keyd[93978]: 2022-04-14T07:49:18Z [TRCE] - [hyper::proto::h1::conn] Conn::read_head
avril 14 09:49:18 ******** aziot-keyd[93978]: 2022-04-14T07:49:18Z [TRCE] - [tracing::span] parse_headers
avril 14 09:49:18 ******** aziot-keyd[93978]: 2022-04-14T07:49:18Z [TRCE] - [tracing::span::active] -> parse_headers
avril 14 09:49:18 ******** aziot-keyd[93978]: 2022-04-14T07:49:18Z [TRCE] - [hyper::proto::h1::role] Request.parse([Header; 100], [u8; 738])
avril 14 09:49:18 ******** aziot-keyd[93978]: 2022-04-14T07:49:18Z [TRCE] - [hyper::proto::h1::role] Request.parse Complete(102)
avril 14 09:49:18 ******** aziot-keyd[93978]: 2022-04-14T07:49:18Z [TRCE] - [hyper::proto::h1::role] headers: [Header { name: "content-length", value: [54, 51, 54] }, Header { name: "content-type", value: [97, 112, 112, 108, 105, 99, 97, 116, 105, 111, 110, 47, 106, 115, 111, 110] }]
avril 14 09:49:18 ******** aziot-keyd[93978]: 2022-04-14T07:49:18Z [TRCE] - [tracing::span::active] <- parse_headers
avril 14 09:49:18 ******** aziot-keyd[93978]: 2022-04-14T07:49:18Z [TRCE] - [tracing::span] -- parse_headers
avril 14 09:49:18 ******** aziot-keyd[93978]: 2022-04-14T07:49:18Z [DBUG] - [hyper::proto::h1::io] parsed 2 headers
avril 14 09:49:18 ******** aziot-keyd[93978]: 2022-04-14T07:49:18Z [DBUG] - [hyper::proto::h1::conn] incoming body is content-length (636 bytes)
avril 14 09:49:18 ******** aziot-keyd[93978]: 2022-04-14T07:49:18Z [INFO] - <-- POST /encrypt?api-version=2020-09-01 {"content-length": "636", "content-type": "application/json"}
avril 14 09:49:18 ******** aziot-keyd[93978]: 2022-04-14T07:49:18Z [TRCE] - [hyper::proto::h1::decode] decode; state=Length(636)
avril 14 09:49:18 ******** aziot-keyd[93978]: 2022-04-14T07:49:18Z [DBUG] - [hyper::proto::h1::conn] incoming body completed
avril 14 09:49:18 ******** aziot-keyd[93978]: 2022-04-14T07:49:18Z [INFO] - --> 200 {"content-type": "application/json"}
avril 14 09:49:18 ******** aziot-keyd[93978]: 2022-04-14T07:49:18Z [TRCE] - [tracing::span] encode_headers
avril 14 09:49:18 ******** aziot-keyd[93978]: 2022-04-14T07:49:18Z [TRCE] - [tracing::span::active] -> encode_headers
avril 14 09:49:18 ******** aziot-keyd[93978]: 2022-04-14T07:49:18Z [TRCE] - [hyper::proto::h1::role] Server::encode status=200, body=Some(Known(361)), req_method=Some(POST)
avril 14 09:49:18 ******** aziot-keyd[93978]: 2022-04-14T07:49:18Z [TRCE] - [tracing::span::active] <- encode_headers
avril 14 09:49:18 ******** aziot-keyd[93978]: 2022-04-14T07:49:18Z [TRCE] - [tracing::span] -- encode_headers
avril 14 09:49:18 ******** aziot-keyd[93978]: 2022-04-14T07:49:18Z [DBUG] - [hyper::proto::h1::io] flushed 470 bytes
avril 14 09:49:18 ******** aziot-keyd[93978]: 2022-04-14T07:49:18Z [TRCE] - [hyper::proto::h1::conn] flushed({role=server}): State { reading: Init, writing: Init, keep_alive: Idle }
avril 14 09:49:18 ******** aziot-keyd[93978]: 2022-04-14T07:49:18Z [TRCE] - [hyper::proto::h1::conn] Conn::read_head
avril 14 09:49:18 ******** aziot-keyd[93978]: 2022-04-14T07:49:18Z [TRCE] - [hyper::proto::h1::conn] flushed({role=server}): State { reading: Init, writing: Init, keep_alive: Idle }
avril 14 09:49:18 ******** aziot-keyd[93978]: 2022-04-14T07:49:18Z [TRCE] - [hyper::proto::h1::conn] Conn::read_head
avril 14 09:49:18 ******** aziot-keyd[93978]: 2022-04-14T07:49:18Z [TRCE] - [hyper::proto::h1::io] parse eof
avril 14 09:49:18 ******** aziot-keyd[93978]: 2022-04-14T07:49:18Z [TRCE] - [hyper::proto::h1::conn] State::close_read()
avril 14 09:49:18 ******** aziot-keyd[93978]: 2022-04-14T07:49:18Z [DBUG] - [hyper::proto::h1::conn] read eof
avril 14 09:49:18 ******** aziot-keyd[93978]: 2022-04-14T07:49:18Z [TRCE] - [hyper::proto::h1::conn] State::close_write()
avril 14 09:49:18 ******** aziot-keyd[93978]: 2022-04-14T07:49:18Z [TRCE] - [hyper::proto::h1::conn] State::close_read()
avril 14 09:49:18 ******** aziot-keyd[93978]: 2022-04-14T07:49:18Z [TRCE] - [hyper::proto::h1::conn] State::close_write()
avril 14 09:49:18 ******** aziot-keyd[93978]: 2022-04-14T07:49:18Z [TRCE] - [hyper::proto::h1::conn] flushed({role=server}): State { reading: Closed, writing: Closed, keep_alive: Disabled }
avril 14 09:49:18 ******** aziot-keyd[93978]: 2022-04-14T07:49:18Z [TRCE] - [hyper::proto::h1::conn] shut down IO complete
avril 14 09:49:18 ******** aziot-keyd[93978]: 2022-04-14T07:49:18Z [TRCE] - [mio::poll] deregistering event source from poller
avril 14 09:49:18 ******** aziot-identityd[93941]: 2022-04-14T07:49:18Z [TRCE] - [hyper::proto::h1::conn] flushed({role=client}): State { reading: Init, writing: KeepAlive, keep_alive: Busy }
avril 14 09:49:18 ******** aziot-identityd[93941]: 2022-04-14T07:49:18Z [TRCE] - [hyper::proto::h1::conn] Conn::read_head
avril 14 09:49:18 ******** aziot-identityd[93941]: 2022-04-14T07:49:18Z [TRCE] - [hyper::proto::h1::conn] flushed({role=client}): State { reading: Init, writing: KeepAlive, keep_alive: Busy }
avril 14 09:49:18 ******** aziot-identityd[93941]: 2022-04-14T07:49:18Z [TRCE] - [hyper::proto::h1::conn] Conn::read_head
avril 14 09:49:18 ******** aziot-identityd[93941]: 2022-04-14T07:49:18Z [TRCE] - [tracing::span] parse_headers
avril 14 09:49:18 ******** aziot-identityd[93941]: 2022-04-14T07:49:18Z [TRCE] - [tracing::span::active] -> parse_headers
avril 14 09:49:18 ******** aziot-identityd[93941]: 2022-04-14T07:49:18Z [TRCE] - [hyper::proto::h1::role] Response.parse([Header; 100], [u8; 107])
avril 14 09:49:18 ******** aziot-identityd[93941]: 2022-04-14T07:49:18Z [TRCE] - [hyper::proto::h1::role] Response.parse Complete(107)
avril 14 09:49:18 ******** aziot-identityd[93941]: 2022-04-14T07:49:18Z [TRCE] - [tracing::span::active] <- parse_headers
avril 14 09:49:18 ******** aziot-identityd[93941]: 2022-04-14T07:49:18Z [TRCE] - [tracing::span] -- parse_headers
avril 14 09:49:18 ******** aziot-identityd[93941]: 2022-04-14T07:49:18Z [DBUG] - [hyper::proto::h1::io] parsed 3 headers
avril 14 09:49:18 ******** aziot-identityd[93941]: 2022-04-14T07:49:18Z [DBUG] - [hyper::proto::h1::conn] incoming body is content-length (2 bytes)
avril 14 09:49:18 ******** aziot-identityd[93941]: 2022-04-14T07:49:18Z [TRCE] - [hyper::proto::h1::decode] decode; state=Length(2)
avril 14 09:49:18 ******** aziot-identityd[93941]: 2022-04-14T07:49:18Z [DBUG] - [hyper::proto::h1::conn] incoming body completed
avril 14 09:49:18 ******** aziot-identityd[93941]: 2022-04-14T07:49:18Z [TRCE] - [hyper::proto::h1::conn] maybe_notify; read_from_io blocked
avril 14 09:49:18 ******** aziot-identityd[93941]: 2022-04-14T07:49:18Z [TRCE] - [want] signal: Want
avril 14 09:49:18 ******** aziot-identityd[93941]: 2022-04-14T07:49:18Z [TRCE] - [hyper::proto::h1::conn] flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Idle }
avril 14 09:49:18 ******** aziot-identityd[93941]: 2022-04-14T07:49:18Z [TRCE] - [want] signal: Want
avril 14 09:49:18 ******** aziot-identityd[93941]: 2022-04-14T07:49:18Z [TRCE] - [hyper::proto::h1::conn] flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Idle }
avril 14 09:49:18 ******** aziot-identityd[93941]: 2022-04-14T07:49:18Z [TRCE] - [want] poll_want: taker wants!
avril 14 09:49:18 ******** aziot-identityd[93941]: 2022-04-14T07:49:18Z [DBUG] - [aziot_hub_client_async] IoTHub response status 200
avril 14 09:49:18 ******** aziot-identityd[93941]: 2022-04-14T07:49:18Z [TRCE] - [hyper::client::pool] pool dropped, dropping pooled (("https", hbb.azure-devices.net))
avril 14 09:49:18 ******** aziot-identityd[93941]: 2022-04-14T07:49:18Z [DBUG] - [aziot_hub_client_async] IoTHub response headers{"content-length": "2", "content-type": "application/json", "date": "Thu, 14 Apr 2022 07:49:18 GMT"}
avril 14 09:49:18 ******** aziot-identityd[93941]: 2022-04-14T07:49:18Z [TRCE] - [hyper::proto::h1::dispatch] client tx closed
avril 14 09:49:18 ******** aziot-identityd[93941]: 2022-04-14T07:49:18Z [TRCE] - [hyper::proto::h1::conn] State::close_read()
avril 14 09:49:18 ******** aziot-identityd[93941]: 2022-04-14T07:49:18Z [TRCE] - [hyper::proto::h1::conn] State::close_write()
avril 14 09:49:18 ******** aziot-identityd[93941]: 2022-04-14T07:49:18Z [TRCE] - [hyper::proto::h1::conn] flushed({role=client}): State { reading: Closed, writing: Closed, keep_alive: Disabled }
avril 14 09:49:18 ******** aziot-identityd[93941]: 2022-04-14T07:49:18Z [TRCE] - [hyper::proto::h1::conn] shut down IO complete
avril 14 09:49:18 ******** aziot-identityd[93941]: 2022-04-14T07:49:18Z [TRCE] - [mio::poll] deregistering event source from poller
avril 14 09:49:18 ******** aziot-identityd[93941]: 2022-04-14T07:49:18Z [TRCE] - [want] signal: Closed
avril 14 09:49:18 ******** aziot-identityd[93941]: 2022-04-14T07:49:18Z [INFO] - Identity reconciliation complete.
avril 14 09:49:18 ******** aziot-identityd[93941]: 2022-04-14T07:49:18Z [INFO] - Starting server...
avril 14 09:49:18 ******** aziot-identityd[93941]: 2022-04-14T07:49:18Z [TRCE] - [mio::poll] registering event source with poller: token=Token(16777218), interests=READABLE | WRITABLE
avril 14 09:49:18 ******** aziot-identityd[93941]: 2022-04-14T07:49:18Z [TRCE] - [mio::poll] registering with poller
avril 14 09:49:18 ******** aziot-identityd[93941]: 2022-04-14T07:49:18Z [TRCE] - [mio::poll] registering with poller
avril 14 09:49:18 ******** aziot-identityd[93941]: 2022-04-14T07:49:18Z [TRCE] - [mio::poll] registering with poller
avril 14 09:49:59 ******** aziot-identityd[93941]: 2022-04-14T07:49:59Z [TRCE] - [mio::poll] registering event source with poller: token=Token(3), interests=READABLE | WRITABLE
avril 14 09:49:59 ******** aziot-identityd[93941]: 2022-04-14T07:49:59Z [TRCE] - [hyper::proto::h1::conn] Conn::read_head
avril 14 09:49:59 ******** aziot-identityd[93941]: 2022-04-14T07:49:59Z [TRCE] - [hyper::proto::h1::conn] flushed({role=server}): State { reading: Init, writing: Init, keep_alive: Busy }
avril 14 09:49:59 ******** aziot-identityd[93941]: 2022-04-14T07:49:59Z [TRCE] - [hyper::proto::h1::conn] Conn::read_head
avril 14 09:49:59 ******** aziot-identityd[93941]: 2022-04-14T07:49:59Z [TRCE] - [tracing::span] parse_headers
avril 14 09:49:59 ******** aziot-identityd[93941]: 2022-04-14T07:49:59Z [TRCE] - [tracing::span::active] -> parse_headers
avril 14 09:49:59 ******** aziot-identityd[93941]: 2022-04-14T07:49:59Z [TRCE] - [hyper::proto::h1::role] Request.parse([Header; 100], [u8; 120])
avril 14 09:49:59 ******** aziot-identityd[93941]: 2022-04-14T07:49:59Z [TRCE] - [hyper::proto::h1::role] Request.parse Complete(120)
avril 14 09:49:59 ******** aziot-identityd[93941]: 2022-04-14T07:49:59Z [TRCE] - [hyper::proto::h1::role] headers: [Header { name: "Host", value: [105, 100, 101, 110, 116, 105, 116, 121, 100, 46, 115, 111, 99, 107] }, Header { name: "User-Agent", value: [99, 117, 114, 108, 47, 55, 46, 54, 56, 46, 48] }, Header { name: "Accept", value: [42, 47, 42] }]
avril 14 09:49:59 ******** aziot-identityd[93941]: 2022-04-14T07:49:59Z [TRCE] - [tracing::span::active] <- parse_headers
avril 14 09:49:59 ******** aziot-identityd[93941]: 2022-04-14T07:49:59Z [TRCE] - [tracing::span] -- parse_headers
avril 14 09:49:59 ******** aziot-identityd[93941]: 2022-04-14T07:49:59Z [DBUG] - [hyper::proto::h1::io] parsed 3 headers
avril 14 09:49:59 ******** aziot-identityd[93941]: 2022-04-14T07:49:59Z [DBUG] - [hyper::proto::h1::conn] incoming body is empty
avril 14 09:49:59 ******** aziot-identityd[93941]: 2022-04-14T07:49:59Z [INFO] - <-- GET /identities/identity?api-version=2020-09-01 {"host": "identityd.sock", "user-agent": "curl/7.68.0", "accept": "*/*"}
avril 14 09:49:59 ******** aziot-identityd[93941]: 2022-04-14T07:49:59Z [TRCE] - [hyper::client::pool] take? ("http", keyd.sock): expiration = Some(90s)
avril 14 09:49:59 ******** aziot-identityd[93941]: 2022-04-14T07:49:59Z [DBUG] - [hyper::client::pool] reuse idle connection for ("http", keyd.sock)
avril 14 09:49:59 ******** aziot-identityd[93941]: 2022-04-14T07:49:59Z [TRCE] - [hyper::proto::h1::conn] flushed({role=server}): State { reading: KeepAlive, writing: Init, keep_alive: Busy }
avril 14 09:49:59 ******** aziot-identityd[93941]: 2022-04-14T07:49:59Z [TRCE] - [tracing::span] encode_headers
avril 14 09:49:59 ******** aziot-identityd[93941]: 2022-04-14T07:49:59Z [TRCE] - [tracing::span::active] -> encode_headers
avril 14 09:49:59 ******** aziot-identityd[93941]: 2022-04-14T07:49:59Z [TRCE] - [hyper::proto::h1::role] Client::encode method=GET, body=None
avril 14 09:49:59 ******** aziot-identityd[93941]: 2022-04-14T07:49:59Z [TRCE] - [tracing::span::active] <- encode_headers
avril 14 09:49:59 ******** aziot-identityd[93941]: 2022-04-14T07:49:59Z [TRCE] - [tracing::span] -- encode_headers
avril 14 09:49:59 ******** aziot-identityd[93941]: 2022-04-14T07:49:59Z [DBUG] - [hyper::proto::h1::io] flushed 75 bytes
avril 14 09:49:59 ******** aziot-identityd[93941]: 2022-04-14T07:49:59Z [TRCE] - [hyper::proto::h1::conn] flushed({role=client}): State { reading: Init, writing: KeepAlive, keep_alive: Busy }
avril 14 09:49:59 ******** aziot-keyd[93978]: 2022-04-14T07:49:59Z [TRCE] - [hyper::proto::h1::conn] Conn::read_head
avril 14 09:49:59 ******** aziot-keyd[93978]: 2022-04-14T07:49:59Z [TRCE] - [tracing::span] parse_headers
avril 14 09:49:59 ******** aziot-keyd[93978]: 2022-04-14T07:49:59Z [TRCE] - [tracing::span::active] -> parse_headers
avril 14 09:49:59 ******** aziot-keyd[93978]: 2022-04-14T07:49:59Z [TRCE] - [hyper::proto::h1::role] Request.parse([Header; 100], [u8; 75])
avril 14 09:49:59 ******** aziot-keyd[93978]: 2022-04-14T07:49:59Z [TRCE] - [hyper::proto::h1::role] Request.parse Complete(75)
avril 14 09:49:59 ******** aziot-keyd[93978]: 2022-04-14T07:49:59Z [TRCE] - [hyper::proto::h1::role] headers: [Header { name: "host", value: [107, 101, 121, 100, 46, 115, 111, 99, 107] }]
avril 14 09:49:59 ******** aziot-keyd[93978]: 2022-04-14T07:49:59Z [TRCE] - [tracing::span::active] <- parse_headers
avril 14 09:49:59 ******** aziot-keyd[93978]: 2022-04-14T07:49:59Z [TRCE] - [tracing::span] -- parse_headers
avril 14 09:49:59 ******** aziot-keyd[93978]: 2022-04-14T07:49:59Z [DBUG] - [hyper::proto::h1::io] parsed 1 headers
avril 14 09:49:59 ******** aziot-keyd[93978]: 2022-04-14T07:49:59Z [DBUG] - [hyper::proto::h1::conn] incoming body is empty
avril 14 09:49:59 ******** aziot-keyd[93978]: 2022-04-14T07:49:59Z [INFO] - <-- GET /keypair/device-id?api-version=2020-09-01 {"host": "keyd.sock"}
avril 14 09:49:59 ******** aziot-keyd[93978]: 2022-04-14T07:49:59Z [INFO] - --> 200 {"content-type": "application/json"}
avril 14 09:49:59 ******** aziot-keyd[93978]: 2022-04-14T07:49:59Z [TRCE] - [tracing::span] encode_headers
avril 14 09:49:59 ******** aziot-keyd[93978]: 2022-04-14T07:49:59Z [TRCE] - [tracing::span::active] -> encode_headers
avril 14 09:49:59 ******** aziot-keyd[93978]: 2022-04-14T07:49:59Z [TRCE] - [hyper::proto::h1::role] Server::encode status=200, body=Some(Known(248)), req_method=Some(GET)
avril 14 09:49:59 ******** aziot-keyd[93978]: 2022-04-14T07:49:59Z [TRCE] - [tracing::span::active] <- encode_headers
avril 14 09:49:59 ******** aziot-keyd[93978]: 2022-04-14T07:49:59Z [TRCE] - [tracing::span] -- encode_headers
avril 14 09:49:59 ******** aziot-keyd[93978]: 2022-04-14T07:49:59Z [DBUG] - [hyper::proto::h1::io] flushed 357 bytes
avril 14 09:49:59 ******** aziot-keyd[93978]: 2022-04-14T07:49:59Z [TRCE] - [hyper::proto::h1::conn] flushed({role=server}): State { reading: Init, writing: Init, keep_alive: Idle }
avril 14 09:49:59 ******** aziot-identityd[93941]: 2022-04-14T07:49:59Z [TRCE] - [hyper::proto::h1::conn] Conn::read_head
avril 14 09:49:59 ******** aziot-identityd[93941]: 2022-04-14T07:49:59Z [TRCE] - [tracing::span] parse_headers
avril 14 09:49:59 ******** aziot-identityd[93941]: 2022-04-14T07:49:59Z [TRCE] - [tracing::span::active] -> parse_headers
avril 14 09:49:59 ******** aziot-identityd[93941]: 2022-04-14T07:49:59Z [TRCE] - [hyper::proto::h1::role] Response.parse([Header; 100], [u8; 357])
avril 14 09:49:59 ******** aziot-identityd[93941]: 2022-04-14T07:49:59Z [TRCE] - [hyper::proto::h1::role] Response.parse Complete(109)
avril 14 09:49:59 ******** aziot-identityd[93941]: 2022-04-14T07:49:59Z [TRCE] - [tracing::span::active] <- parse_headers
avril 14 09:49:59 ******** aziot-identityd[93941]: 2022-04-14T07:49:59Z [TRCE] - [tracing::span] -- parse_headers
avril 14 09:49:59 ******** aziot-identityd[93941]: 2022-04-14T07:49:59Z [DBUG] - [hyper::proto::h1::io] parsed 3 headers
avril 14 09:49:59 ******** aziot-identityd[93941]: 2022-04-14T07:49:59Z [DBUG] - [hyper::proto::h1::conn] incoming body is content-length (248 bytes)
avril 14 09:49:59 ******** aziot-identityd[93941]: 2022-04-14T07:49:59Z [TRCE] - [hyper::proto::h1::decode] decode; state=Length(248)
avril 14 09:49:59 ******** aziot-identityd[93941]: 2022-04-14T07:49:59Z [DBUG] - [hyper::proto::h1::conn] incoming body completed
avril 14 09:49:59 ******** aziot-identityd[93941]: 2022-04-14T07:49:59Z [TRCE] - [hyper::proto::h1::conn] maybe_notify; read_from_io blocked
avril 14 09:49:59 ******** aziot-identityd[93941]: 2022-04-14T07:49:59Z [TRCE] - [want] signal: Want
avril 14 09:49:59 ******** aziot-identityd[93941]: 2022-04-14T07:49:59Z [TRCE] - [hyper::proto::h1::conn] flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Idle }
avril 14 09:49:59 ******** aziot-identityd[93941]: 2022-04-14T07:49:59Z [TRCE] - [want] signal: Want
avril 14 09:49:59 ******** aziot-identityd[93941]: 2022-04-14T07:49:59Z [TRCE] - [hyper::proto::h1::conn] flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Idle }
avril 14 09:49:59 ******** aziot-identityd[93941]: 2022-04-14T07:49:59Z [TRCE] - [hyper::client::pool] put; add idle connection for ("http", keyd.sock)
avril 14 09:49:59 ******** aziot-identityd[93941]: 2022-04-14T07:49:59Z [DBUG] - [hyper::client::pool] pooling idle connection for ("http", keyd.sock)
avril 14 09:49:59 ******** aziot-identityd[93941]: 2022-04-14T07:49:59Z [INFO] - --> 200 {"content-type": "application/json"}
avril 14 09:49:59 ******** aziot-identityd[93941]: 2022-04-14T07:49:59Z [TRCE] - [tracing::span] encode_headers
avril 14 09:49:59 ******** aziot-identityd[93941]: 2022-04-14T07:49:59Z [TRCE] - [tracing::span::active] -> encode_headers
avril 14 09:49:59 ******** aziot-identityd[93941]: 2022-04-14T07:49:59Z [TRCE] - [hyper::proto::h1::role] Server::encode status=200, body=Some(Known(415)), req_method=Some(GET)
avril 14 09:49:59 ******** aziot-identityd[93941]: 2022-04-14T07:49:59Z [TRCE] - [tracing::span::active] <- encode_headers
avril 14 09:49:59 ******** aziot-identityd[93941]: 2022-04-14T07:49:59Z [TRCE] - [tracing::span] -- encode_headers
avril 14 09:49:59 ******** aziot-identityd[93941]: 2022-04-14T07:49:59Z [DBUG] - [hyper::proto::h1::io] flushed 524 bytes
avril 14 09:49:59 ******** aziot-identityd[93941]: 2022-04-14T07:49:59Z [TRCE] - [hyper::proto::h1::conn] flushed({role=server}): State { reading: Init, writing: Init, keep_alive: Idle }
avril 14 09:49:59 ******** aziot-identityd[93941]: 2022-04-14T07:49:59Z [TRCE] - [want] signal: Want
avril 14 09:49:59 ******** aziot-identityd[93941]: 2022-04-14T07:49:59Z [TRCE] - [hyper::proto::h1::conn] flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Idle }
avril 14 09:49:59 ******** aziot-identityd[93941]: 2022-04-14T07:49:59Z [TRCE] - [hyper::proto::h1::conn] Conn::read_head
avril 14 09:49:59 ******** aziot-identityd[93941]: 2022-04-14T07:49:59Z [TRCE] - [hyper::proto::h1::io] parse eof
avril 14 09:49:59 ******** aziot-identityd[93941]: 2022-04-14T07:49:59Z [TRCE] - [hyper::proto::h1::conn] State::close_read()
avril 14 09:49:59 ******** aziot-identityd[93941]: 2022-04-14T07:49:59Z [DBUG] - [hyper::proto::h1::conn] read eof
avril 14 09:49:59 ******** aziot-identityd[93941]: 2022-04-14T07:49:59Z [TRCE] - [hyper::proto::h1::conn] State::close_write()
avril 14 09:49:59 ******** aziot-identityd[93941]: 2022-04-14T07:49:59Z [TRCE] - [hyper::proto::h1::conn] State::close_read()
avril 14 09:49:59 ******** aziot-identityd[93941]: 2022-04-14T07:49:59Z [TRCE] - [hyper::proto::h1::conn] State::close_write()
avril 14 09:49:59 ******** aziot-identityd[93941]: 2022-04-14T07:49:59Z [TRCE] - [hyper::proto::h1::conn] flushed({role=server}): State { reading: Closed, writing: Closed, keep_alive: Disabled }
avril 14 09:49:59 ******** aziot-identityd[93941]: 2022-04-14T07:49:59Z [TRCE] - [hyper::proto::h1::conn] shut down IO complete
avril 14 09:49:59 ******** aziot-identityd[93941]: 2022-04-14T07:49:59Z [TRCE] - [mio::poll] deregistering event source from poller
avril 14 09:49:59 ******** aziot-certd[93958]: 2022-04-14T07:49:59Z [TRCE] - [mio::poll] registering event source with poller: token=Token(2), interests=READABLE | WRITABLE
avril 14 09:49:59 ******** aziot-certd[93958]: 2022-04-14T07:49:59Z [TRCE] - [hyper::proto::h1::conn] Conn::read_head
avril 14 09:49:59 ******** aziot-certd[93958]: 2022-04-14T07:49:59Z [TRCE] - [hyper::proto::h1::conn] flushed({role=server}): State { reading: Init, writing: Init, keep_alive: Busy }
avril 14 09:49:59 ******** aziot-certd[93958]: 2022-04-14T07:49:59Z [TRCE] - [hyper::proto::h1::conn] Conn::read_head
avril 14 09:49:59 ******** aziot-certd[93958]: 2022-04-14T07:49:59Z [TRCE] - [tracing::span] parse_headers
avril 14 09:49:59 ******** aziot-certd[93958]: 2022-04-14T07:49:59Z [TRCE] - [tracing::span::active] -> parse_headers
avril 14 09:49:59 ******** aziot-certd[93958]: 2022-04-14T07:49:59Z [TRCE] - [hyper::proto::h1::role] Request.parse([Header; 100], [u8; 119])
avril 14 09:49:59 ******** aziot-certd[93958]: 2022-04-14T07:49:59Z [TRCE] - [hyper::proto::h1::role] Request.parse Complete(119)
avril 14 09:49:59 ******** aziot-certd[93958]: 2022-04-14T07:49:59Z [TRCE] - [hyper::proto::h1::role] headers: [Header { name: "Host", value: [99, 101, 114, 116, 100, 46, 115, 111, 99, 107] }, Header { name: "User-Agent", value: [99, 117, 114, 108, 47, 55, 46, 54, 56, 46, 48] }, Header { name: "Accept", value: [42, 47, 42] }]
avril 14 09:49:59 ******** aziot-certd[93958]: 2022-04-14T07:49:59Z [TRCE] - [tracing::span::active] <- parse_headers
avril 14 09:49:59 ******** aziot-certd[93958]: 2022-04-14T07:49:59Z [TRCE] - [tracing::span] -- parse_headers
avril 14 09:49:59 ******** aziot-certd[93958]: 2022-04-14T07:49:59Z [DBUG] - [hyper::proto::h1::io] parsed 3 headers
avril 14 09:49:59 ******** aziot-certd[93958]: 2022-04-14T07:49:59Z [DBUG] - [hyper::proto::h1::conn] incoming body is empty
avril 14 09:49:59 ******** aziot-certd[93958]: 2022-04-14T07:49:59Z [INFO] - <-- GET /certificates/device-id?api-version=2020-09-01 {"host": "certd.sock", "user-agent": "curl/7.68.0", "accept": "*/*"}
avril 14 09:49:59 ******** aziot-certd[93958]: 2022-04-14T07:49:59Z [INFO] - --> 200 {"content-type": "application/json"}
avril 14 09:49:59 ******** aziot-certd[93958]: 2022-04-14T07:49:59Z [TRCE] - [tracing::span] encode_headers
avril 14 09:49:59 ******** aziot-certd[93958]: 2022-04-14T07:49:59Z [TRCE] - [tracing::span::active] -> encode_headers
avril 14 09:49:59 ******** aziot-certd[93958]: 2022-04-14T07:49:59Z [TRCE] - [hyper::proto::h1::role] Server::encode status=200, body=Some(Known(5180)), req_method=Some(GET)
avril 14 09:49:59 ******** aziot-certd[93958]: 2022-04-14T07:49:59Z [TRCE] - [tracing::span::active] <- encode_headers
avril 14 09:49:59 ******** aziot-certd[93958]: 2022-04-14T07:49:59Z [TRCE] - [tracing::span] -- encode_headers
avril 14 09:49:59 ******** aziot-certd[93958]: 2022-04-14T07:49:59Z [DBUG] - [hyper::proto::h1::io] flushed 5290 bytes
avril 14 09:49:59 ******** aziot-certd[93958]: 2022-04-14T07:49:59Z [TRCE] - [hyper::proto::h1::conn] flushed({role=server}): State { reading: Init, writing: Init, keep_alive: Idle }
avril 14 09:49:59 ******** aziot-certd[93958]: 2022-04-14T07:49:59Z [TRCE] - [hyper::proto::h1::conn] Conn::read_head
avril 14 09:49:59 ******** aziot-certd[93958]: 2022-04-14T07:49:59Z [TRCE] - [hyper::proto::h1::io] parse eof
avril 14 09:49:59 ******** aziot-certd[93958]: 2022-04-14T07:49:59Z [TRCE] - [hyper::proto::h1::conn] State::close_read()
avril 14 09:49:59 ******** aziot-certd[93958]: 2022-04-14T07:49:59Z [DBUG] - [hyper::proto::h1::conn] read eof
avril 14 09:49:59 ******** aziot-certd[93958]: 2022-04-14T07:49:59Z [TRCE] - [hyper::proto::h1::conn] State::close_write()
avril 14 09:49:59 ******** aziot-certd[93958]: 2022-04-14T07:49:59Z [TRCE] - [hyper::proto::h1::conn] State::close_read()
avril 14 09:49:59 ******** aziot-certd[93958]: 2022-04-14T07:49:59Z [TRCE] - [hyper::proto::h1::conn] State::close_write()
avril 14 09:49:59 ******** aziot-certd[93958]: 2022-04-14T07:49:59Z [TRCE] - [hyper::proto::h1::conn] flushed({role=server}): State { reading: Closed, writing: Closed, keep_alive: Disabled }
avril 14 09:49:59 ******** aziot-certd[93958]: 2022-04-14T07:49:59Z [TRCE] - [hyper::proto::h1::conn] shut down IO complete
avril 14 09:49:59 ******** aziot-certd[93958]: 2022-04-14T07:49:59Z [TRCE] - [mio::poll] deregistering event source from poller
avril 14 09:49:59 ******** aziot-keyd[93978]: 2022-04-14T07:49:59Z [TRCE] - [mio::poll] registering event source with poller: token=Token(67108866), interests=READABLE | WRITABLE
avril 14 09:49:59 ******** aziot-keyd[93978]: 2022-04-14T07:49:59Z [TRCE] - [hyper::proto::h1::conn] Conn::read_head
avril 14 09:49:59 ******** aziot-keyd[93978]: 2022-04-14T07:49:59Z [TRCE] - [tracing::span] parse_headers
avril 14 09:49:59 ******** aziot-keyd[93978]: 2022-04-14T07:49:59Z [TRCE] - [tracing::span::active] -> parse_headers
avril 14 09:49:59 ******** aziot-keyd[93978]: 2022-04-14T07:49:59Z [TRCE] - [hyper::proto::h1::role] Request.parse([Header; 100], [u8; 133])
avril 14 09:49:59 ******** aziot-keyd[93978]: 2022-04-14T07:49:59Z [TRCE] - [hyper::proto::h1::role] Request.parse Complete(114)
avril 14 09:49:59 ******** aziot-keyd[93978]: 2022-04-14T07:49:59Z [TRCE] - [hyper::proto::h1::role] headers: [Header { name: "content-length", value: [49, 57] }, Header { name: "content-type", value: [97, 112, 112, 108, 105, 99, 97, 116, 105, 111, 110, 47, 106, 115, 111, 110] }]
avril 14 09:49:59 ******** aziot-keyd[93978]: 2022-04-14T07:49:59Z [TRCE] - [tracing::span::active] <- parse_headers
avril 14 09:49:59 ******** aziot-keyd[93978]: 2022-04-14T07:49:59Z [TRCE] - [tracing::span] -- parse_headers
avril 14 09:49:59 ******** aziot-keyd[93978]: 2022-04-14T07:49:59Z [DBUG] - [hyper::proto::h1::io] parsed 2 headers
avril 14 09:49:59 ******** aziot-keyd[93978]: 2022-04-14T07:49:59Z [DBUG] - [hyper::proto::h1::conn] incoming body is content-length (19 bytes)
avril 14 09:49:59 ******** aziot-keyd[93978]: 2022-04-14T07:49:59Z [INFO] - <-- POST /parameters/algorithm?api-version=2020-09-01 {"content-length": "19", "content-type": "application/json"}
avril 14 09:49:59 ******** aziot-keyd[93978]: 2022-04-14T07:49:59Z [TRCE] - [hyper::proto::h1::decode] decode; state=Length(19)
avril 14 09:49:59 ******** aziot-keyd[93978]: 2022-04-14T07:49:59Z [DBUG] - [hyper::proto::h1::conn] incoming body completed
avril 14 09:49:59 ******** aziot-keyd[93978]: 2022-04-14T07:49:59Z [INFO] - !!! parameter "handle" has an invalid value
avril 14 09:49:59 ******** aziot-keyd[93978]: 2022-04-14T07:49:59Z [INFO] - !!! caused by: invalid handle
avril 14 09:49:59 ******** aziot-keyd[93978]: 2022-04-14T07:49:59Z [INFO] - --> 400 {"content-type": "application/json"}
avril 14 09:49:59 ******** aziot-keyd[93978]: 2022-04-14T07:49:59Z [TRCE] - [tracing::span] encode_headers
avril 14 09:49:59 ******** aziot-keyd[93978]: 2022-04-14T07:49:59Z [TRCE] - [tracing::span::active] -> encode_headers
avril 14 09:49:59 ******** aziot-keyd[93978]: 2022-04-14T07:49:59Z [TRCE] - [hyper::proto::h1::role] Server::encode status=400, body=Some(Known(82)), req_method=Some(POST)
avril 14 09:49:59 ******** aziot-keyd[93978]: 2022-04-14T07:49:59Z [TRCE] - [tracing::span::active] <- encode_headers
avril 14 09:49:59 ******** aziot-keyd[93978]: 2022-04-14T07:49:59Z [TRCE] - [tracing::span] -- encode_headers
avril 14 09:49:59 ******** aziot-keyd[93978]: 2022-04-14T07:49:59Z [DBUG] - [hyper::proto::h1::io] flushed 199 bytes
avril 14 09:49:59 ******** aziot-keyd[93978]: 2022-04-14T07:49:59Z [TRCE] - [hyper::proto::h1::conn] flushed({role=server}): State { reading: Init, writing: Init, keep_alive: Idle }
avril 14 09:49:59 ******** aziot-keyd[93978]: 2022-04-14T07:49:59Z [TRCE] - [hyper::proto::h1::conn] Conn::read_head
avril 14 09:49:59 ******** aziot-keyd[93978]: 2022-04-14T07:49:59Z [TRCE] - [hyper::proto::h1::conn] flushed({role=server}): State { reading: Init, writing: Init, keep_alive: Idle }
avril 14 09:49:59 ******** aziot-keyd[93978]: 2022-04-14T07:49:59Z [TRCE] - [hyper::proto::h1::conn] Conn::read_head
avril 14 09:49:59 ******** aziot-keyd[93978]: 2022-04-14T07:49:59Z [TRCE] - [hyper::proto::h1::io] parse eof
avril 14 09:49:59 ******** aziot-keyd[93978]: 2022-04-14T07:49:59Z [TRCE] - [hyper::proto::h1::conn] State::close_read()
avril 14 09:49:59 ******** aziot-keyd[93978]: 2022-04-14T07:49:59Z [DBUG] - [hyper::proto::h1::conn] read eof
avril 14 09:49:59 ******** aziot-keyd[93978]: 2022-04-14T07:49:59Z [TRCE] - [hyper::proto::h1::conn] State::close_write()
avril 14 09:49:59 ******** aziot-keyd[93978]: 2022-04-14T07:49:59Z [TRCE] - [hyper::proto::h1::conn] State::close_read()
avril 14 09:49:59 ******** aziot-keyd[93978]: 2022-04-14T07:49:59Z [TRCE] - [hyper::proto::h1::conn] State::close_write()
avril 14 09:49:59 ******** aziot-keyd[93978]: 2022-04-14T07:49:59Z [TRCE] - [hyper::proto::h1::conn] flushed({role=server}): State { reading: Closed, writing: Closed, keep_alive: Disabled }
avril 14 09:49:59 ******** aziot-keyd[93978]: 2022-04-14T07:49:59Z [TRCE] - [hyper::proto::h1::conn] shut down IO complete
avril 14 09:49:59 ******** aziot-keyd[93978]: 2022-04-14T07:49:59Z [TRCE] - [mio::poll] deregistering event source from poller

bemol38 commented 2 years ago

I forgot to tell, that I'm using TPM for the storage.

arsing commented 2 years ago

Okay, so the failing request is the very first one to get the key algorithm, ie whether it's an RSA or EC key. That's a very simple thing, so the problem is likely very fundamental.

So you're saying you configured keyd to use tpm2-pkcs11 ? If so, did you compile the tpm2-pkcs11 stack yourself (like in our docs) or did you install distro packages? In either case, post the versions of tpm2-pkcs11, tpm2-tools, tpm2-tss and tpm2-abrmd (if you're using it).

bemol38 commented 2 years ago

Hi arsing, Just to be sure, I cleaned up all tpm2 libraries out of /usr/local/lib and rerun the installation script from your documentation. I also cleaned up the TPM and recreated slot and token (also according to your doc). From the script:

checkouts['tpm2-abrmd']='2.4.0'
checkouts['tpm2-pkcs11']='1.5.0'
checkouts['tpm2-tools']='5.0'
checkouts['tpm2-tss']='3.0.3'

I don't know how to confirm the versions after installation for tpm2-pkcs11, tpm2-tss and tpm2-tools, except by checking the version in CHANGELOG.md after repositories are pulled (and they are correct)
For tpm2-abrmd:

tpm2-abrmd --version

** (process:20378): WARNING **: 11:20:09.848: tcti_conf before: "(null)"
tpm2-abrmd version 2.4.0

arsing commented 2 years ago

Okay. If you're using the script in our docs then yes that tells us what versions you have.

Looking at the logs closer, the request made by identityd that succeeds is:

aziot-keyd[93978]: 2022-04-14T07:49:17Z [INFO] - <-- POST /parameters/algorithm?api-version=2020-09-01 {"content-length": "248", "content-type": "application/json"}

... while the one made by your process (via the engine) is:

aziot-keyd[93978]: 2022-04-14T07:49:59Z [INFO] - <-- POST /parameters/algorithm?api-version=2020-09-01 {"content-length": "19", "content-type": "application/json"}

The request bodies are of very different length. The request body ought to be { "keyHandle": "..." }. If it were { "keyHandle": "" } then that would be around 19 characters. So it implies you are sending a malformed request without the key handle filled in.

And indeed, in your OP you have:

key_handle="$(<<< "$identity" jq -r '.spec.auth.keyHandle')"
openssl s_client [...] -key "$key_handle_from_identity_service"

The two variable names are not the same :)

bemol38 commented 2 years ago

Oh, sorry for that typo ! But it is not the source of the error. It does not work either after correcting my script. Which is quite strange. So now the content-length of the openssl POST is closer to the one of the identity service:

<-- POST /parameters/algorithm?api-version=2020-09-01 {"host": "keyd.sock", "user-agent": "curl/7.68.0", "accept": "*/*", "content-type": "application/json", "content-length": "248"}

versus request by identity service that succeeds:

<-- POST /parameters/algorithm?api-version=2020-09-01 {"content-length": "251", "content-type": "application/json"}

But still not identical.

I made a search and cleaned up every tpm2-pkcs11 storages except the one in /var/lib/aziot/keyd. Does openssl need additional info to find the storage ? Do I need an openssl.conf ?

If I use tpm2_ptool, I can display the token only if I run the command with aziotks user:

sudo -Hu aziotks tpm2_ptool listtokens --pid '1'

otherwise I need to use the path argument:

sudo tpm2_ptool listtokens --pid '1' --path "/var/lib/aziot/keyd/.tpm2_pkcs11"

arsing commented 2 years ago

Sure, so now post the logs the services again, with your corrected invocation. Because I assume it will not be:

avril 14 09:49:59 **** aziot-keyd[93978]: 2022-04-14T07:49:59Z [INFO] - !!! parameter "handle" has an invalid value

... this time.

Does openssl need additional info to find the storage ? Do I need an openssl.conf ?

No. For example we run curl with the engine in our CI with no other configuration required: https://github.com/Azure/iot-identity-service/blob/d5cb24590c0b7c41442b1149a2feb4c226bbb8f9/key/test-aziot-key-openssl-engine-shared.sh#L219-L224 This only tests with the PKCS#11 implementation of softhsm, but the specific PKCS#11 implementation doesn't change the fact that the engine itself is able to talk to keyd just fine.

If I use tpm2_ptool, I can display the token only if I run the command with aziotks user:

That is correct. tpm2-pkcs11 stores PKCS#11 metadata on the filesystem, so it needs to be ACLed to the keyd user, which is aziotks. But again it does not affect the ability of engine to talk to keyd.

bemol38 commented 2 years ago

Obviously, after cleaning up old pkcs11 stores, cleaning up my user account and root account from pkcs11-related experiments, and rebooting, the problem with the openssl s_client command is solved. This is the final script I used:

#!/bin/bash

identity="$(sudo curl --unix-socket '/run/aziot/identityd.sock' 'http://identityd.sock/identities/identity?api-version=2020-09-01')"
hub_name="$(<<< "$identity" jq -r '.spec.hubName')"
cert_id="$(<<< "$identity" jq -r '.spec.auth.certId')"
key_handle="$(<<< "$identity" jq -r '.spec.auth.keyHandle')"

rm -r cert_from_identity_service.pem
sudo curl --unix-socket '/run/aziot/certd.sock' "http://certd.sock/certificates/${cert_id}?api-version=2020-09-01" \
    | jq -r '.pem' > cert_from_identity_service.pem

echo | openssl s_client -connect $hub_name:443 -cert ./cert_from_identity_service.pem -keyform engine -engine aziot_keys -key "$key_handle"

So to conclude: I have to investigate further why it does not work for me from within the Azure IOT C SDK.

I learned a lot, so thank you very much for your time, @arsing !

Azure / iot-identity-service

Failed to use aziot_keys engine with OpenSSL #393