Changing code to have better error logging
This changes the error logs to show the file and line number instead of
naming a specific a function where the error originated. In some cases
the function name is kept where it made sense for readibility of the
logs.
Test: Run and tested using `atest keystore2_test` for Rust test and CTS test with `atest CtsKeystoreTestCases`
Bug: 241924261
Change-Id: I2ea970dd83e18033506555f2726c716626697cdf
diff --git a/keystore2/src/remote_provisioning.rs b/keystore2/src/remote_provisioning.rs
index 8ed2be4..0331295 100644
--- a/keystore2/src/remote_provisioning.rs
+++ b/keystore2/src/remote_provisioning.rs
@@ -48,6 +48,7 @@
use crate::database::{CertificateChain, KeyIdGuard, KeystoreDB, Uuid};
use crate::error::{self, map_or_log_err, map_rem_prov_error, Error};
use crate::globals::{get_keymint_device, get_remotely_provisioned_component, DB};
+use crate::ks_err;
use crate::metrics_store::log_rkp_error_stats;
use crate::permission::KeystorePerm;
use crate::utils::{check_keystore_permission, watchdog as wd};
@@ -174,10 +175,7 @@
issuerSubjectName: parse_subject_from_certificate(
&cert_chain.batch_cert,
)
- .context(concat!(
- "In get_remote_provisioning_key_and_certs: Failed to ",
- "parse subject."
- ))?,
+ .context(ks_err!("Failed to parse subject."))?,
},
Certificate { encodedCertificate: cert_chain.cert_chain },
))),
@@ -202,9 +200,9 @@
if let Some(dev) = self.device_by_sec_level.get(sec_level) {
Ok(dev.as_ref())
} else {
- Err(error::Error::sys()).context(concat!(
- "In get_dev_by_sec_level: Remote instance for requested security level",
- " not found."
+ Err(error::Error::sys()).context(ks_err!(
+ "Remote instance for requested security level \
+ not found.",
))
}
}
@@ -213,11 +211,11 @@
pub fn new_native_binder() -> Result<Strong<dyn IRemoteProvisioning>> {
let mut result: Self = Default::default();
let dev = get_remotely_provisioned_component(&SecurityLevel::TRUSTED_ENVIRONMENT)
- .context("In new_native_binder: Failed to get TEE Remote Provisioner instance.")?;
+ .context(ks_err!("Failed to get TEE Remote Provisioner instance."))?;
result.curve_by_sec_level.insert(
SecurityLevel::TRUSTED_ENVIRONMENT,
dev.getHardwareInfo()
- .context("In new_native_binder: Failed to get hardware info for the TEE.")?
+ .context(ks_err!("Failed to get hardware info for the TEE."))?
.supportedEekCurve,
);
result.device_by_sec_level.insert(SecurityLevel::TRUSTED_ENVIRONMENT, dev);
@@ -225,7 +223,7 @@
result.curve_by_sec_level.insert(
SecurityLevel::STRONGBOX,
dev.getHardwareInfo()
- .context("In new_native_binder: Failed to get hardware info for StrongBox.")?
+ .context(ks_err!("Failed to get hardware info for StrongBox."))?
.supportedEekCurve,
);
result.device_by_sec_level.insert(SecurityLevel::STRONGBOX, dev);
@@ -234,23 +232,24 @@
}
fn extract_payload_from_cose_mac(data: &[u8]) -> Result<Value> {
- let cose_mac0: Vec<Value> = serde_cbor::from_slice(data).context(
- "In extract_payload_from_cose_mac: COSE_Mac0 returned from IRPC cannot be parsed",
- )?;
+ let cose_mac0: Vec<Value> = serde_cbor::from_slice(data)
+ .context(ks_err!("COSE_Mac0 returned from IRPC cannot be parsed"))?;
if cose_mac0.len() != COSE_MAC0_LEN {
- return Err(error::Error::sys()).context(format!(
- "In extract_payload_from_cose_mac: COSE_Mac0 has improper length. \
+ return Err(error::Error::sys()).context(ks_err!(
+ "COSE_Mac0 has improper length. \
Expected: {}, Actual: {}",
COSE_MAC0_LEN,
cose_mac0.len(),
));
}
match &cose_mac0[COSE_MAC0_PAYLOAD] {
- Value::Bytes(key) => Ok(serde_cbor::from_slice(key)
- .context("In extract_payload_from_cose_mac: COSE_Mac0 payload is malformed.")?),
- _ => Err(error::Error::sys()).context(
- "In extract_payload_from_cose_mac: COSE_Mac0 payload is the wrong type.",
- )?,
+ Value::Bytes(key) => {
+ Ok(serde_cbor::from_slice(key)
+ .context(ks_err!("COSE_Mac0 payload is malformed."))?)
+ }
+ _ => {
+ Err(error::Error::sys()).context(ks_err!("COSE_Mac0 payload is the wrong type."))?
+ }
}
}
@@ -291,17 +290,17 @@
device_info,
protected_data,
))
- .context("In generate_csr: Failed to generate csr")?;
+ .context(ks_err!("Failed to generate csr"))?;
let mut mac_and_keys: Vec<Value> = vec![Value::from(mac)];
for maced_public_key in keys_to_sign {
mac_and_keys.push(
Self::extract_payload_from_cose_mac(&maced_public_key.macedKey)
- .context("In generate_csr: Failed to get the payload from the COSE_Mac0")?,
+ .context(ks_err!("Failed to get the payload from the COSE_Mac0"))?,
)
}
let cbor_array: Value = Value::Array(mac_and_keys);
serde_cbor::to_vec(&cbor_array)
- .context("In generate_csr: Failed to serialize the mac and keys array")
+ .context(ks_err!("Failed to serialize the mac and keys array"))
}
/// Provisions a certificate chain for a key whose CSR was included in generate_csr. The
@@ -329,28 +328,27 @@
}
fn parse_cose_mac0_for_coords(data: &[u8]) -> Result<Vec<u8>> {
- let cose_mac0: Vec<Value> = serde_cbor::from_slice(data).context(
- "In parse_cose_mac0_for_coords: COSE_Mac0 returned from IRPC cannot be parsed",
- )?;
+ let cose_mac0: Vec<Value> = serde_cbor::from_slice(data)
+ .context(ks_err!("COSE_Mac0 returned from IRPC cannot be parsed"))?;
if cose_mac0.len() != COSE_MAC0_LEN {
- return Err(error::Error::sys()).context(format!(
- "In parse_cose_mac0_for_coords: COSE_Mac0 has improper length. \
+ return Err(error::Error::sys()).context(ks_err!(
+ "COSE_Mac0 has improper length. \
Expected: {}, Actual: {}",
COSE_MAC0_LEN,
cose_mac0.len(),
));
}
let cose_key: BTreeMap<Value, Value> = match &cose_mac0[COSE_MAC0_PAYLOAD] {
- Value::Bytes(key) => serde_cbor::from_slice(key)
- .context("In parse_cose_mac0_for_coords: COSE_Key is malformed.")?,
- _ => Err(error::Error::sys())
- .context("In parse_cose_mac0_for_coords: COSE_Mac0 payload is the wrong type.")?,
+ Value::Bytes(key) => {
+ serde_cbor::from_slice(key).context(ks_err!("COSE_Key is malformed."))?
+ }
+ _ => {
+ Err(error::Error::sys()).context(ks_err!("COSE_Mac0 payload is the wrong type."))?
+ }
};
if !cose_key.contains_key(&COSE_KEY_XCOORD) || !cose_key.contains_key(&COSE_KEY_YCOORD) {
- return Err(error::Error::sys()).context(
- "In parse_cose_mac0_for_coords: \
- COSE_Key returned from IRPC is lacking required fields",
- );
+ return Err(error::Error::sys())
+ .context(ks_err!("COSE_Key returned from IRPC is lacking required fields"));
}
let mut raw_key: Vec<u8> = vec![0; 64];
match &cose_key[&COSE_KEY_XCOORD] {
@@ -358,15 +356,15 @@
raw_key[0..32].clone_from_slice(x_coord)
}
Value::Bytes(x_coord) => {
- return Err(error::Error::sys()).context(format!(
- "In parse_cose_mac0_for_coords: COSE_Key X-coordinate is not the right length. \
+ return Err(error::Error::sys()).context(ks_err!(
+ "COSE_Key X-coordinate is not the right length. \
Expected: 32; Actual: {}",
x_coord.len()
- ))
+ ));
}
_ => {
return Err(error::Error::sys())
- .context("In parse_cose_mac0_for_coords: COSE_Key X-coordinate is not a bstr")
+ .context(ks_err!("COSE_Key X-coordinate is not a bstr"));
}
}
match &cose_key[&COSE_KEY_YCOORD] {
@@ -374,15 +372,15 @@
raw_key[32..64].clone_from_slice(y_coord)
}
Value::Bytes(y_coord) => {
- return Err(error::Error::sys()).context(format!(
- "In parse_cose_mac0_for_coords: COSE_Key Y-coordinate is not the right length. \
+ return Err(error::Error::sys()).context(ks_err!(
+ "COSE_Key Y-coordinate is not the right length. \
Expected: 32; Actual: {}",
y_coord.len()
- ))
+ ));
}
_ => {
return Err(error::Error::sys())
- .context("In parse_cose_mac0_for_coords: COSE_Key Y-coordinate is not a bstr")
+ .context(ks_err!("COSE_Key Y-coordinate is not a bstr"));
}
}
Ok(raw_key)
@@ -399,18 +397,17 @@
sec_level: SecurityLevel,
) -> Result<()> {
let (_, _, uuid) = get_keymint_device(&sec_level)?;
- let dev = self.get_dev_by_sec_level(&sec_level).context(format!(
- "In generate_key_pair: Failed to get device for security level {:?}",
- sec_level
- ))?;
+ let dev = self
+ .get_dev_by_sec_level(&sec_level)
+ .context(ks_err!("Failed to get device for security level {:?}", sec_level))?;
let mut maced_key = MacedPublicKey { macedKey: Vec::new() };
let priv_key =
map_rem_prov_error(dev.generateEcdsaP256KeyPair(is_test_mode, &mut maced_key))
- .context("In generate_key_pair: Failed to generated ECDSA keypair.")?;
+ .context(ks_err!("Failed to generated ECDSA keypair."))?;
let raw_key = Self::parse_cose_mac0_for_coords(&maced_key.macedKey)
- .context("In generate_key_pair: Failed to parse raw key")?;
+ .context(ks_err!("Failed to parse raw key"))?;
db.create_attestation_key_entry(&maced_key.macedKey, &raw_key, &priv_key, &uuid)
- .context("In generate_key_pair: Failed to insert attestation key entry")
+ .context(ks_err!("Failed to insert attestation key entry"))
}
/// Checks the security level of each available IRemotelyProvisionedComponent hal and returns
@@ -472,15 +469,15 @@
|| get_rem_prov_attest_key_helper(domain, caller_uid, db, km_uuid),
|v| Ok(Some(v)),
)
- .context(concat!(
- "In get_rem_prov_attest_key: Failed to get a key after",
- "attempting to assign one."
+ .context(ks_err!(
+ "Failed to get a key after \
+ attempting to assign one.",
))?
.map_or_else(
|| {
- Err(Error::sys()).context(concat!(
- "In get_rem_prov_attest_key: Attempted to assign a ",
- "key and failed silently. Something is very wrong."
+ Err(Error::sys()).context(ks_err!(
+ "Attempted to assign a \
+ key and failed silently. Something is very wrong.",
))
},
|(guard, cert_chain)| Ok(Some((guard, cert_chain))),
@@ -499,7 +496,7 @@
) -> Result<Option<(KeyIdGuard, CertificateChain)>> {
let guard_and_chain = db
.retrieve_attestation_key_and_cert_chain(domain, caller_uid as i64, km_uuid)
- .context("In get_rem_prov_attest_key_helper: Failed to retrieve a key + cert chain")?;
+ .context(ks_err!("Failed to retrieve a key + cert chain"))?;
match guard_and_chain {
Some((guard, cert_chain)) => Ok(Some((guard, cert_chain))),
// Either this app needs to be assigned a key, or the pool is empty. An error will
@@ -507,7 +504,7 @@
// should be nudged to provision more keys so keystore can retry.
None => {
db.assign_attestation_key(domain, caller_uid as i64, km_uuid)
- .context("In get_rem_prov_attest_key_helper: Failed to assign a key")?;
+ .context(ks_err!("Failed to assign a key"))?;
Ok(None)
}
}
@@ -625,7 +622,7 @@
let guard_and_cert_chain =
get_rem_prov_attest_key(Domain::APP, caller_uid as u32, db, &km_uuid)
- .context("In get_attestation_key")?;
+ .context(ks_err!())?;
match guard_and_cert_chain {
Some((_, chain)) => Ok(RemotelyProvisionedKey {
keyBlob: chain.private_key.to_vec(),
@@ -634,7 +631,7 @@
// It should be impossible to get `None`, but handle it just in case as a
// precaution against future behavioral changes in `get_rem_prov_attest_key`.
None => Err(error::Error::Rc(ResponseCode::OUT_OF_KEYS))
- .context("In get_attestation_key: No available attestation keys"),
+ .context(ks_err!("No available attestation keys")),
}
}
@@ -644,7 +641,7 @@
let mut result: Self = Default::default();
let dev = get_remotely_provisioned_component(&SecurityLevel::TRUSTED_ENVIRONMENT)
- .context("In new_native_binder: Failed to get TEE Remote Provisioner instance.")?;
+ .context(ks_err!("Failed to get TEE Remote Provisioner instance."))?;
if let Some(id) = dev.getHardwareInfo()?.uniqueId {
result.unique_id_to_sec_level.insert(id, SecurityLevel::TRUSTED_ENVIRONMENT);
}