From a1eb047b808421babfadca6133f872a6e36ec4fa Mon Sep 17 00:00:00 2001 From: Chris Frantz Date: Mon, 25 Nov 2024 15:32:19 -0800 Subject: [PATCH] [provisioning] Log data from provisionging as json 1. Collect personalization data and timing statistics during personalization and log it as json when provisioning is done. Signed-off-by: Chris Frantz --- sw/host/opentitanlib/src/dif/lc_ctrl.rs | 2 +- sw/host/ot_certs/src/lib.rs | 3 +- sw/host/provisioning/cert_lib/BUILD | 1 + sw/host/provisioning/cert_lib/src/lib.rs | 11 ++- sw/host/provisioning/ft/BUILD | 2 + sw/host/provisioning/ft/src/main.rs | 54 ++++++++++--- sw/host/provisioning/ft_lib/BUILD | 6 +- sw/host/provisioning/ft_lib/src/lib.rs | 87 ++++++++++++++++++--- sw/host/provisioning/ft_lib/src/response.rs | 57 ++++++++++++++ 9 files changed, 193 insertions(+), 30 deletions(-) create mode 100644 sw/host/provisioning/ft_lib/src/response.rs diff --git a/sw/host/opentitanlib/src/dif/lc_ctrl.rs b/sw/host/opentitanlib/src/dif/lc_ctrl.rs index 8800ec3984cf5..6239d93d63f01 100644 --- a/sw/host/opentitanlib/src/dif/lc_ctrl.rs +++ b/sw/host/opentitanlib/src/dif/lc_ctrl.rs @@ -10,7 +10,7 @@ use serde::{Deserialize, Serialize}; use crate::with_unknown; with_unknown! { - pub enum DifLcCtrlState: u32 { + pub enum DifLcCtrlState: u32 [default = Self::StateInvalid] { Raw = bindgen::dif::dif_lc_ctrl_state_kDifLcCtrlStateRaw , TestUnlocked0 = bindgen::dif::dif_lc_ctrl_state_kDifLcCtrlStateTestUnlocked0 , TestLocked0 = bindgen::dif::dif_lc_ctrl_state_kDifLcCtrlStateTestLocked0 , diff --git a/sw/host/ot_certs/src/lib.rs b/sw/host/ot_certs/src/lib.rs index 6ecbff3a9e997..19f1fa6f97584 100644 --- a/sw/host/ot_certs/src/lib.rs +++ b/sw/host/ot_certs/src/lib.rs @@ -23,9 +23,10 @@ pub mod template; pub mod x509; use clap::ValueEnum; +use serde::{Deserialize, Serialize}; /// Supported OpenTitan certificate formats. -#[derive(Clone, Debug, ValueEnum)] +#[derive(Clone, Debug, ValueEnum, Serialize, Deserialize)] pub enum CertFormat { X509, Cwt, diff --git a/sw/host/provisioning/cert_lib/BUILD b/sw/host/provisioning/cert_lib/BUILD index 080517ccad4b2..34c01bfa1f355 100644 --- a/sw/host/provisioning/cert_lib/BUILD +++ b/sw/host/provisioning/cert_lib/BUILD @@ -15,6 +15,7 @@ rust_library( "//sw/host/ot_certs", "@crate_index//:anyhow", "@crate_index//:arrayvec", + "@crate_index//:base64ct", "@crate_index//:elliptic-curve", "@crate_index//:hex", "@crate_index//:log", diff --git a/sw/host/provisioning/cert_lib/src/lib.rs b/sw/host/provisioning/cert_lib/src/lib.rs index 7d1564653cf13..513179fabda48 100644 --- a/sw/host/provisioning/cert_lib/src/lib.rs +++ b/sw/host/provisioning/cert_lib/src/lib.rs @@ -8,12 +8,13 @@ use std::path::PathBuf; use std::process::Command; use anyhow::{bail, Context, Result}; +use base64ct::{Base64, Encoding}; use elliptic_curve::SecretKey; use num_bigint_dig::BigUint; use openssl::ecdsa::EcdsaSig; use p256::ecdsa::SigningKey; use p256::NistP256; -use serde::Deserialize; +use serde::{Deserialize, Serialize, Serializer}; use opentitanlib::crypto::sha256::sha256; use opentitanlib::util::tmpfilename; @@ -219,15 +220,21 @@ fn write_cert_to_temp_pem_file(der_cert_bytes: &[u8], base_filename: &str) -> Re Ok(binding_pem) } +fn serialize_certificate(cert: &Vec, serializer: S) -> Result { + let s = Base64::encode_string(cert.as_slice()); + serializer.serialize_str(&s) +} + /// Container for an endorsed certificate. /// /// This is used to pass a collection of endorsed certificates, along with metadata, /// to various functions that check the certificates validate properly with third-party /// tools. -#[derive(Clone, Debug)] +#[derive(Clone, Debug, Serialize)] pub struct EndorsedCert { pub format: CertFormat, pub name: String, + #[serde(serialize_with = "serialize_certificate")] pub bytes: Vec, pub ignore_critical: bool, } diff --git a/sw/host/provisioning/ft/BUILD b/sw/host/provisioning/ft/BUILD index dc3a12d7532ff..4c872793a099e 100644 --- a/sw/host/provisioning/ft/BUILD +++ b/sw/host/provisioning/ft/BUILD @@ -21,12 +21,14 @@ package(default_visibility = ["//visibility:public"]) "//sw/host/provisioning/ujson_lib", "//sw/host/provisioning/util_lib", "@crate_index//:anyhow", + "@crate_index//:base64ct", "@crate_index//:clap", "@crate_index//:elliptic-curve", "@crate_index//:hex", "@crate_index//:humantime", "@crate_index//:log", "@crate_index//:p256", + "@crate_index//:serde_json", "@lowrisc_serde_annotate//serde_annotate", ], ) diff --git a/sw/host/provisioning/ft/src/main.rs b/sw/host/provisioning/ft/src/main.rs index 25e3225c298ce..f983d5254ddb7 100644 --- a/sw/host/provisioning/ft/src/main.rs +++ b/sw/host/provisioning/ft/src/main.rs @@ -4,15 +4,17 @@ use std::collections::HashMap; use std::path::PathBuf; -use std::time::Duration; +use std::time::{Duration, Instant}; use anyhow::{bail, Context, Result}; +use base64ct::{Base64, Encoding}; use clap::{Args, Parser}; use elliptic_curve::pkcs8::DecodePrivateKey; use elliptic_curve::SecretKey; use p256::NistP256; use cert_lib::{CaConfig, CaKey, CaKeyType}; +use ft_lib::response::PersonalizeResponse; use ft_lib::{ check_rom_ext_boot_up, run_ft_personalize, run_sram_ft_individualize, test_exit, test_unlock, }; @@ -76,6 +78,10 @@ pub struct ManufFtProvisioningDataInput { /// Token Encryption public key (RSA) DER file path. #[arg(long)] token_encrypt_key_der_file: PathBuf, + + /// Pretty-print the provisioning data output. + #[arg(long, default_value = "false")] + pretty: bool, } #[derive(Debug, Parser)] @@ -110,6 +116,8 @@ fn main() -> Result<()> { let opts = Opts::parse(); opts.init.init_logging(); + let mut response = PersonalizeResponse::default(); + // We call the below functions, instead of calling `opts.init.init_target()` since we do not // want to perform bootstrap yet. let transport = backend::create(&opts.init.backend_opts)?; @@ -131,15 +139,19 @@ fn main() -> Result<()> { let token_encrypt_key = load_rsa_public_key(&opts.provisioning_data.token_encrypt_key_der_file)?; let encrypted_rma_unlock_token = encrypt_token(&token_encrypt_key, &rma_unlock_token)?; - log::info!( - "Encrypted rma_unlock_token = {}", - hex::encode(&encrypted_rma_unlock_token) - ); + response.rma_unlock_token = Base64::encode_string(&encrypted_rma_unlock_token); + log::info!("Encrypted rma_unlock_token = {}", response.rma_unlock_token); // Parse and prepare individualization ujson data payload. - let _ft_individualize_data_in = ManufFtIndividualizeData { + let ft_individualize_data_in = ManufFtIndividualizeData { device_id: hex_string_to_u32_arrayvec::<8>(opts.provisioning_data.device_id.as_str())?, }; + response.device_id = ft_individualize_data_in + .device_id + .iter() + .map(|v| format!("{v:08X}")) + .collect::>() + .join(""); // Parse and prepare CA key. let mut ca_cfgs: HashMap = serde_annotate::from_str( @@ -188,11 +200,12 @@ fn main() -> Result<()> { }; // Only run test unlock operation if we are in a locked LC state. - match read_lc_state( + response.lc_state.initial = read_lc_state( &transport, &opts.init.jtag_params, opts.init.bootstrap.options.reset_delay, - )? { + )?; + match response.lc_state.initial { DifLcCtrlState::TestLocked0 | DifLcCtrlState::TestLocked1 | DifLcCtrlState::TestLocked2 @@ -200,12 +213,14 @@ fn main() -> Result<()> { | DifLcCtrlState::TestLocked4 | DifLcCtrlState::TestLocked5 | DifLcCtrlState::TestLocked6 => { + let t0 = Instant::now(); test_unlock( &transport, &opts.init.jtag_params, opts.init.bootstrap.options.reset_delay, &_test_unlock_token, )?; + response.stats.log_elapsed_time("test-unlock", t0); } _ => { log::info!("Skipping test unlock operation. Device is already unlocked."); @@ -214,11 +229,12 @@ fn main() -> Result<()> { // Only run the SRAM individualize program in a test unlocked state. If we have transitioned to // a mission state already, then we can skip this step. - match read_lc_state( + response.lc_state.unlocked = read_lc_state( &transport, &opts.init.jtag_params, opts.init.bootstrap.options.reset_delay, - )? { + )?; + match response.lc_state.unlocked { DifLcCtrlState::TestUnlocked0 => { bail!("FT stage cannot be run from test unlocked 0. Run CP stage first."); } @@ -229,15 +245,19 @@ fn main() -> Result<()> { | DifLcCtrlState::TestUnlocked5 | DifLcCtrlState::TestUnlocked6 | DifLcCtrlState::TestUnlocked7 => { + response.lc_state.individualize = Some(response.lc_state.unlocked); + let t0 = Instant::now(); run_sram_ft_individualize( &transport, &opts.init.jtag_params, opts.init.bootstrap.options.reset_delay, &opts.sram_program, - &_ft_individualize_data_in, + &ft_individualize_data_in, opts.timeout, &spi_console_device, )?; + response.stats.log_elapsed_time("ft-individualize", t0); + let t0 = Instant::now(); test_exit( &transport, &opts.init.jtag_params, @@ -245,6 +265,9 @@ fn main() -> Result<()> { &_test_exit_token, opts.provisioning_data.target_mission_mode_lc_state, )?; + response.lc_state.mission_mode = + Some(opts.provisioning_data.target_mission_mode_lc_state); + response.stats.log_elapsed_time("test-exit", t0); } _ => { log::info!("Skipping individualize operation. Device is already in a mission mode."); @@ -265,10 +288,17 @@ fn main() -> Result<()> { opts.second_bootstrap, &spi_console_device, opts.timeout, + &mut response, )?; - check_rom_ext_boot_up(&transport, &opts.init, opts.timeout)?; + check_rom_ext_boot_up(&transport, &opts.init, opts.timeout, &mut response)?; log::info!("Provisioning Done"); + let doc = if opts.provisioning_data.pretty { + serde_json::to_string_pretty(&response)? + } else { + serde_json::to_string(&response)? + }; + println!("PROVISIONING_DATA: {doc}"); Ok(()) } diff --git a/sw/host/provisioning/ft_lib/BUILD b/sw/host/provisioning/ft_lib/BUILD index ab6c6214e4ebf..b23a58689b63f 100644 --- a/sw/host/provisioning/ft_lib/BUILD +++ b/sw/host/provisioning/ft_lib/BUILD @@ -10,7 +10,10 @@ package(default_visibility = ["//visibility:public"]) [ rust_library( name = "ft_lib_{}".format(sku), - srcs = ["src/lib.rs"], + srcs = [ + "src/lib.rs", + "src/response.rs", + ], crate_name = "ft_lib", deps = [ "//sw/host/opentitanlib", @@ -24,6 +27,7 @@ package(default_visibility = ["//visibility:public"]) "@crate_index//:arrayvec", "@crate_index//:clap", "@crate_index//:hex", + "@crate_index//:indexmap", "@crate_index//:log", "@crate_index//:serde", "@crate_index//:serde_json", diff --git a/sw/host/provisioning/ft_lib/src/lib.rs b/sw/host/provisioning/ft_lib/src/lib.rs index eb39c43491718..3f043132c6b13 100644 --- a/sw/host/provisioning/ft_lib/src/lib.rs +++ b/sw/host/provisioning/ft_lib/src/lib.rs @@ -6,7 +6,7 @@ use sha2::{Digest, Sha256}; use std::collections::HashMap; use std::collections::HashSet; use std::path::PathBuf; -use std::time::Duration; +use std::time::{Duration, Instant}; use anyhow::{bail, Result}; use arrayvec::ArrayVec; @@ -34,6 +34,9 @@ use ujson_lib::provisioning_data::{ }; use util_lib::hash_lc_token; +pub mod response; +use response::*; + pub fn test_unlock( transport: &TransportWrapper, jtag_params: &JtagParams, @@ -259,9 +262,10 @@ fn push_endorsed_cert( Ok(()) } -fn process_dev_seeds(seeds: &[u8]) -> Result<()> { +fn process_dev_seeds(seeds: &[u8]) -> Result>> { let expected_seed_num = 2usize; let seed_size = 64usize; + let mut response = Vec::new(); if seeds.len() != seed_size * expected_seed_num { bail!("Unexpected seeds perso object size {}", seeds.len()) @@ -269,10 +273,10 @@ fn process_dev_seeds(seeds: &[u8]) -> Result<()> { for i in 0..expected_seed_num { let seed = &seeds[i * seed_size..(i + 1) * seed_size]; - + response.push(seed.to_vec()); log::info!("Seed #{}: {}", i, hex::encode(seed)) } - Ok(()) + Ok(response) } fn provision_certificates( @@ -281,14 +285,22 @@ fn provision_certificates( perso_certgen_inputs: &ManufCertgenInputs, timeout: Duration, spi_console: &SpiConsoleDevice, + response: &mut PersonalizeResponse, ) -> Result<()> { // Send attestation TCB measurements for generating DICE certificates. + let t0 = Instant::now(); let _ = UartConsole::wait_for(spi_console, r"Waiting for certificate inputs ...", timeout)?; + response.stats.log_elapsed_time("perso-wait-ready", t0); + + let t0 = Instant::now(); perso_certgen_inputs.send(spi_console)?; + response.stats.log_elapsed_time("perso-certgen-inputs", t0); // Wait until the device exports the TBS certificates. + let t0 = Instant::now(); let _ = UartConsole::wait_for(spi_console, r"Exporting TBS certificates ...", timeout)?; let perso_blob = PersoBlob::recv(spi_console, timeout, true)?; + response.stats.log_elapsed_time("perso-tbs-export", t0); // Extract certificate byte vectors, endorse TBS certs, and ensure they parse with OpenSSL. // During the process, both: @@ -311,6 +323,7 @@ fn provision_certificates( // DICE certificate names. let dice_cert_names = HashSet::from(["UDS", "CDI_0", "CDI_1"]); + let t0 = Instant::now(); for _ in 0..perso_blob.num_objs { log::info!("Processing next object"); let header = get_obj_header(&perso_blob.body[start..])?; @@ -326,8 +339,10 @@ fn provision_certificates( let dev_seed_size = header.obj_size - obj_header_size; let seeds = &perso_blob.body[start..start + dev_seed_size]; cert_hasher.update(seeds); - process_dev_seeds(seeds)?; + let r = process_dev_seeds(seeds)?; start += dev_seed_size; + response.seeds.number += r.len(); + response.seeds.seed.extend(r); continue; } } @@ -348,12 +363,14 @@ fn provision_certificates( // Prepare a collection of (SKU-specific) certs whose endorsements should be verified. if !dice_cert_names.contains(cert.cert_name) { - sku_specific_certs.push(EndorsedCert { + let ec = EndorsedCert { format: CertFormat::X509, name: cert.cert_name.to_string(), bytes: cert_bytes.clone(), ignore_critical: false, - }); + }; + response.certs.insert(ec.name.clone(), ec.clone()); + sku_specific_certs.push(ec); } // Prepare the UJSON data payloads that will be sent back to the device. @@ -369,12 +386,14 @@ fn provision_certificates( if dice_cert_names.contains(cert.cert_name) && header.obj_type == ObjType::UnendorsedX509Cert { - dice_cert_chain.push(EndorsedCert { + let ec = EndorsedCert { format: CertFormat::X509, name: cert.cert_name.to_string(), bytes: cert_bytes.clone(), ignore_critical: true, - }); + }; + response.certs.insert(ec.name.clone(), ec.clone()); + dice_cert_chain.push(ec); } // Ensure all certs parse with OpenSSL (even those that where endorsed on device). @@ -387,9 +406,12 @@ fn provision_certificates( // info pages match those verified on the host. cert_hasher.update(cert_bytes); } + response.stats.log_elapsed_time("perso-process-blobs", t0); // Execute extension hook. + let t0 = Instant::now(); endorsed_cert_concat = ft_ext(endorsed_cert_concat)?; + response.stats.log_elapsed_time("perso-ft-ext", t0); // Complete hash of all certs that will be sent back to the device and written to flash. This // is used as integrity check on what will be written to flash. @@ -401,9 +423,11 @@ fn provision_certificates( next_free: endorsed_cert_concat.len(), body: endorsed_cert_concat, }; + let t0 = Instant::now(); let _ = UartConsole::wait_for(spi_console, r"Importing endorsed certificates ...", timeout)?; manuf_perso_data_back.send(spi_console)?; let _ = UartConsole::wait_for(spi_console, r"Finished importing certificates.", timeout)?; + response.stats.log_elapsed_time("perso-import-certs", t0); // Check the integrity of the certificates written to the device's flash by comparing a // SHA256 over all certificates computed on the host and device sides. @@ -425,11 +449,15 @@ fn provision_certificates( // Validate the certificate endorsements with OpenSSL. // TODO(lowRISC/opentitan:#24281): Add CWT verifier + let t0 = Instant::now(); if !dice_cert_chain.is_empty() { log::info!("Validating DICE certificate chain with OpenSSL ..."); validate_cert_chain(dice_ca_cert.to_str().unwrap(), &dice_cert_chain)?; log::info!("Success."); } + response.stats.log_elapsed_time("perso-validate-dice", t0); + + let t0 = Instant::now(); if !sku_specific_certs.is_empty() { log::info!("Validating SKU-specific certificates with OpenSSL ..."); for sku_specific_cert in sku_specific_certs.iter() { @@ -437,7 +465,7 @@ fn provision_certificates( } log::info!("Success."); } - + response.stats.log_elapsed_time("perso-validate-sku", t0); Ok(()) } @@ -452,23 +480,45 @@ pub fn run_ft_personalize( second_bootstrap: PathBuf, spi_console: &SpiConsoleDevice, timeout: Duration, + response: &mut PersonalizeResponse, ) -> Result<()> { // Bootstrap only personalization binary into ROM_EXT slot A in flash. + let t0 = Instant::now(); init.bootstrap.init(transport)?; + response.stats.log_elapsed_time("first-bootstrap", t0); // Bootstrap personalization + ROM_EXT + Owner FW binaries into flash, since // flash scrambling seeds were provisioned in the previous step. + let t0 = Instant::now(); let _ = UartConsole::wait_for(spi_console, r"Bootstrap requested.", timeout)?; + response.stats.log_elapsed_time("first-bootstrap-done", t0); + + let t0 = Instant::now(); init.bootstrap.load(transport, &second_bootstrap)?; + response.stats.log_elapsed_time("second-bootstrap", t0); // Send RMA unlock token digest to device. + let second_t0 = Instant::now(); + let t0 = second_t0; send_rma_unlock_token_hash(rma_unlock_token, timeout, spi_console)?; + response.stats.log_elapsed_time("send-rma-unlock-token", t0); // Provision all device certificates. - provision_certificates(ca_cfgs, ca_keys, perso_certgen_inputs, timeout, spi_console)?; + let t0 = Instant::now(); + provision_certificates( + ca_cfgs, + ca_keys, + perso_certgen_inputs, + timeout, + spi_console, + response, + )?; + response.stats.log_elapsed_time("perso-all-certs-done", t0); let _ = UartConsole::wait_for(spi_console, r"Personalization done.", timeout)?; - + response + .stats + .log_elapsed_time("second-bootstrap-done", second_t0); Ok(()) } @@ -476,23 +526,34 @@ pub fn check_rom_ext_boot_up( transport: &TransportWrapper, init: &InitializeTest, timeout: Duration, + response: &mut PersonalizeResponse, ) -> Result<()> { transport.reset_target(init.bootstrap.options.reset_delay, true)?; let uart_console = transport.uart("console")?; // The ROM_EXT used to print "Starting ROM_EXT 0.1", but we cleaned up the // ROM_EXT output. It now prints "ROM_EXT:0.1". // The following regex recognizes both forms: - let _ = UartConsole::wait_for(&*uart_console, r"ROM_EXT[: ].*\r\n", timeout)?; + let result = UartConsole::wait_for(&*uart_console, r"ROM_EXT[: ](.*)\r\n", timeout)?; + response.stats.log_string( + "rom_ext-version", + result + .get(1) + .as_ref() + .map(|s| s.as_str()) + .unwrap_or("unknown"), + ); // Timeout for waiting for a potential error message indicating invalid UDS certificate. // This value is tested on fpga cw340 and could be potentially fine-tuned. const UDS_CERT_INVALID_TIMEOUT: Duration = Duration::from_millis(200); + let t0 = Instant::now(); let result = UartConsole::wait_for( &*uart_console, r".*UDS certificate not valid.", UDS_CERT_INVALID_TIMEOUT, ); + response.stats.log_elapsed_time("rom_ext-done", t0); match result { Ok(_captures) => { diff --git a/sw/host/provisioning/ft_lib/src/response.rs b/sw/host/provisioning/ft_lib/src/response.rs new file mode 100644 index 0000000000000..c941958462a16 --- /dev/null +++ b/sw/host/provisioning/ft_lib/src/response.rs @@ -0,0 +1,57 @@ +// Copyright lowRISC contributors (OpenTitan project). +// Licensed under the Apache License, Version 2.0, see LICENSE for details. +// SPDX-License-Identifier: Apache-2.0 + +use std::time::Instant; + +use cert_lib::EndorsedCert; +use indexmap::IndexMap; +use opentitanlib::dif::lc_ctrl::DifLcCtrlState; +use serde::Serialize; + +#[derive(Clone, Debug, Serialize)] +#[serde(rename_all = "snake_case")] +pub enum Stat { + Microseconds(u64), + String(String), +} + +#[derive(Clone, Debug, Serialize, Default)] +pub struct Statistics(IndexMap); + +#[derive(Clone, Debug, Serialize, Default)] +pub struct DevSeedResponse { + pub number: usize, + pub seed: Vec>, +} + +#[derive(Clone, Debug, Serialize, Default)] +pub struct LcStateSequence { + pub initial: DifLcCtrlState, + pub unlocked: DifLcCtrlState, + pub individualize: Option, + pub mission_mode: Option, +} + +#[derive(Clone, Debug, Serialize, Default)] +pub struct PersonalizeResponse { + pub lc_state: LcStateSequence, + pub device_id: String, + pub rma_unlock_token: String, + pub seeds: DevSeedResponse, + pub certs: IndexMap, + pub stats: Statistics, +} + +impl Statistics { + pub fn log_elapsed_time(&mut self, name: &str, start: Instant) { + let end = Instant::now(); + let duration = end - start; + self.0 + .insert(name.into(), Stat::Microseconds(duration.as_micros() as u64)); + } + + pub fn log_string(&mut self, name: &str, val: &str) { + self.0.insert(name.into(), Stat::String(val.into())); + } +}