Merge changes I803a0a7a,I7c2a7a3a into main
* changes:
Standardize watchdog messages
Reduce over-severe logging
diff --git a/keystore2/src/audit_log.rs b/keystore2/src/audit_log.rs
index 8d9735e..4952b3b 100644
--- a/keystore2/src/audit_log.rs
+++ b/keystore2/src/audit_log.rs
@@ -34,8 +34,8 @@
match domain {
Domain::APP => uid,
Domain::SELINUX => (nspace | FLAG_NAMESPACE) as i32,
- _ => {
- log::info!("Not logging audit event for key with unexpected domain");
+ d => {
+ log::info!("Not logging audit event for key with domain {d:?}");
0
}
}
diff --git a/keystore2/src/database.rs b/keystore2/src/database.rs
index 754dd9c..9ce6506 100644
--- a/keystore2/src/database.rs
+++ b/keystore2/src/database.rs
@@ -1200,7 +1200,7 @@
// Find up to `max_blobs` more superseded key blobs, load their metadata and return it.
let result: Vec<(i64, Vec<u8>)> = {
- let _wp = wd::watch("handle_next_superseded_blob find_next");
+ let _wp = wd::watch("KeystoreDB::handle_next_superseded_blob find_next");
let mut stmt = tx
.prepare(
"SELECT id, blob FROM persistent.blobentry
@@ -1231,7 +1231,7 @@
.context("Trying to extract superseded blobs.")?
};
- let _wp = wd::watch("handle_next_superseded_blob load_metadata");
+ let _wp = wd::watch("KeystoreDB::handle_next_superseded_blob load_metadata");
let result = result
.into_iter()
.map(|(blob_id, blob)| {
@@ -1249,7 +1249,7 @@
// We did not find any superseded key blob, so let's remove other superseded blob in
// one transaction.
- let _wp = wd::watch("handle_next_superseded_blob delete");
+ let _wp = wd::watch("KeystoreDB::handle_next_superseded_blob delete");
tx.execute(
"DELETE FROM persistent.blobentry
WHERE NOT subcomponent_type = ?
diff --git a/keystore2/src/database/versioning.rs b/keystore2/src/database/versioning.rs
index 2c816f4..bc68f15 100644
--- a/keystore2/src/database/versioning.rs
+++ b/keystore2/src/database/versioning.rs
@@ -15,7 +15,7 @@
use anyhow::{anyhow, Context, Result};
use rusqlite::{params, OptionalExtension, Transaction};
-pub fn create_or_get_version(tx: &Transaction, current_version: u32) -> Result<u32> {
+fn create_or_get_version(tx: &Transaction, current_version: u32) -> Result<u32> {
tx.execute(
"CREATE TABLE IF NOT EXISTS persistent.version (
id INTEGER PRIMARY KEY,
@@ -61,7 +61,7 @@
Ok(version)
}
-pub fn update_version(tx: &Transaction, new_version: u32) -> Result<()> {
+fn update_version(tx: &Transaction, new_version: u32) -> Result<()> {
let updated = tx
.execute("UPDATE persistent.version SET version = ? WHERE id = 0;", params![new_version])
.context("In update_version: Failed to update row.")?;
diff --git a/keystore2/src/globals.rs b/keystore2/src/globals.rs
index c7b495d..4b34e9e 100644
--- a/keystore2/src/globals.rs
+++ b/keystore2/src/globals.rs
@@ -165,7 +165,7 @@
(
Box::new(|uuid, blob| {
let km_dev = get_keymint_dev_by_uuid(uuid).map(|(dev, _)| dev)?;
- let _wp = wd::watch("In invalidate key closure: calling deleteKey");
+ let _wp = wd::watch("invalidate key closure: calling IKeyMintDevice::deleteKey");
map_km_error(km_dev.deleteKey(blob))
.context(ks_err!("Trying to invalidate key blob."))
}),
@@ -306,7 +306,7 @@
}
};
- let wp = wd::watch("In connect_keymint: calling getHardwareInfo()");
+ let wp = wd::watch("connect_keymint: calling IKeyMintDevice::getHardwareInfo()");
let mut hw_info =
map_km_error(keymint.getHardwareInfo()).context(ks_err!("Failed to get hardware info."))?;
drop(wp);
diff --git a/keystore2/src/legacy_importer.rs b/keystore2/src/legacy_importer.rs
index 045f848..24f3263 100644
--- a/keystore2/src/legacy_importer.rs
+++ b/keystore2/src/legacy_importer.rs
@@ -923,7 +923,7 @@
blob,
&[],
|blob| {
- let _wd = wd::watch("Calling GetKeyCharacteristics.");
+ let _wd = wd::watch("get_key_characteristics_without_app_data: calling IKeyMintDevice::getKeyCharacteristics");
map_km_error(km_dev.getKeyCharacteristics(blob, &[], &[]))
},
|_| Ok(()),
diff --git a/keystore2/src/maintenance.rs b/keystore2/src/maintenance.rs
index 43d99d1..61277f1 100644
--- a/keystore2/src/maintenance.rs
+++ b/keystore2/src/maintenance.rs
@@ -28,7 +28,7 @@
check_keystore_permission, uid_to_android_user, watchdog as wd,
};
use android_hardware_security_keymint::aidl::android::hardware::security::keymint::{
- IKeyMintDevice::IKeyMintDevice, SecurityLevel::SecurityLevel,
+ ErrorCode::ErrorCode, IKeyMintDevice::IKeyMintDevice, SecurityLevel::SecurityLevel,
};
use android_security_maintenance::aidl::android::security::maintenance::IKeystoreMaintenance::{
BnKeystoreMaintenance, IKeystoreMaintenance,
@@ -143,7 +143,7 @@
let (km_dev, _, _) =
get_keymint_device(&sec_level).context(ks_err!("getting keymint device"))?;
- let _wp = wd::watch_millis_with("In call_with_watchdog", 500, (sec_level, name));
+ let _wp = wd::watch_millis_with("Maintenance::call_with_watchdog", 500, (sec_level, name));
map_km_error(op(km_dev)).with_context(|| ks_err!("calling {}", name))?;
Ok(())
}
@@ -164,12 +164,21 @@
name,
&sec_level_string
),
- Err(ref e) => log::error!(
- "Call to {} failed for security level {}: {}.",
- name,
- &sec_level_string,
- e
- ),
+ Err(ref e) => {
+ if *sec_level == SecurityLevel::STRONGBOX
+ && e.downcast_ref::<Error>()
+ == Some(&Error::Km(ErrorCode::HARDWARE_TYPE_UNAVAILABLE))
+ {
+ log::info!("Call to {} failed for StrongBox as it is not available", name,)
+ } else {
+ log::error!(
+ "Call to {} failed for security level {}: {}.",
+ name,
+ &sec_level_string,
+ e
+ )
+ }
+ }
}
curr_result
})
@@ -313,7 +322,7 @@
}
fn deleteAllKeys(&self) -> BinderResult<()> {
- log::warn!("deleteAllKeys()");
+ log::warn!("deleteAllKeys() invoked, indicating initial setup or post-factory reset");
let _wp = wd::watch("IKeystoreMaintenance::deleteAllKeys");
Self::delete_all_keys().map_err(into_logged_binder)
}
diff --git a/keystore2/src/operation.rs b/keystore2/src/operation.rs
index 7d988e1..27f8ef6 100644
--- a/keystore2/src/operation.rs
+++ b/keystore2/src/operation.rs
@@ -286,7 +286,7 @@
}
*locked_outcome = Outcome::Pruned;
- let _wp = wd::watch("In Operation::prune: calling abort()");
+ let _wp = wd::watch("Operation::prune: calling IKeyMintOperation::abort()");
// We abort the operation. If there was an error we log it but ignore it.
if let Err(e) = map_km_error(self.km_op.abort()) {
@@ -362,7 +362,7 @@
.context(ks_err!("Trying to get auth tokens."))?;
self.update_outcome(&mut outcome, {
- let _wp = wd::watch("Operation::update_aad: calling updateAad");
+ let _wp = wd::watch("Operation::update_aad: calling IKeyMintOperation::updateAad");
map_km_error(self.km_op.updateAad(aad_input, hat.as_ref(), tst.as_ref()))
})
.context(ks_err!("Update failed."))?;
@@ -386,7 +386,7 @@
let output = self
.update_outcome(&mut outcome, {
- let _wp = wd::watch("Operation::update: calling update");
+ let _wp = wd::watch("Operation::update: calling IKeyMintOperation::update");
map_km_error(self.km_op.update(input, hat.as_ref(), tst.as_ref()))
})
.context(ks_err!("Update failed."))?;
@@ -416,7 +416,7 @@
let output = self
.update_outcome(&mut outcome, {
- let _wp = wd::watch("Operation::finish: calling finish");
+ let _wp = wd::watch("Operation::finish: calling IKeyMintOperation::finish");
map_km_error(self.km_op.finish(
input,
signature,
@@ -447,7 +447,7 @@
*locked_outcome = outcome;
{
- let _wp = wd::watch("Operation::abort: calling abort");
+ let _wp = wd::watch("Operation::abort: calling IKeyMintOperation::abort");
map_km_error(self.km_op.abort()).context(ks_err!("KeyMint::abort failed."))
}
}
diff --git a/keystore2/src/raw_device.rs b/keystore2/src/raw_device.rs
index a8a88d2..bf1149c 100644
--- a/keystore2/src/raw_device.rs
+++ b/keystore2/src/raw_device.rs
@@ -212,8 +212,8 @@
|key_blob| {
map_km_error({
let _wp = wd::watch(concat!(
- "In KeyMintDevice::lookup_or_generate_key: ",
- "calling getKeyCharacteristics."
+ "KeyMintDevice::lookup_or_generate_key: ",
+ "calling IKeyMintDevice::getKeyCharacteristics."
));
self.km_dev.getKeyCharacteristics(key_blob, &[], &[])
})
@@ -305,7 +305,9 @@
let (begin_result, _) = self
.upgrade_keyblob_if_required_with(db, key_id_guard, key_blob, |blob| {
map_km_error({
- let _wp = wd::watch("In use_key_in_one_step: calling: begin");
+ let _wp = wd::watch(
+ "KeyMintDevice::use_key_in_one_step: calling IKeyMintDevice::begin",
+ );
self.km_dev.begin(purpose, blob, operation_parameters, auth_token)
})
})
@@ -313,7 +315,8 @@
let operation: Strong<dyn IKeyMintOperation> =
begin_result.operation.ok_or_else(Error::sys).context(ks_err!("Operation missing"))?;
map_km_error({
- let _wp = wd::watch("In use_key_in_one_step: calling: finish");
+ let _wp =
+ wd::watch("KeyMintDevice::use_key_in_one_step: calling IKeyMintDevice::finish");
operation.finish(Some(input), None, None, None, None)
})
.context(ks_err!("Failed to finish operation."))
diff --git a/keystore2/src/security_level.rs b/keystore2/src/security_level.rs
index 8412397..bd20afb 100644
--- a/keystore2/src/security_level.rs
+++ b/keystore2/src/security_level.rs
@@ -329,8 +329,9 @@
operation_parameters,
|blob| loop {
match map_km_error({
- let _wp =
- self.watch("In KeystoreSecurityLevel::create_operation: calling begin");
+ let _wp = self.watch(
+ "KeystoreSecurityLevel::create_operation: calling IKeyMintDevice::begin",
+ );
self.keymint.begin(
purpose,
blob,
@@ -444,7 +445,7 @@
// If there is an attestation challenge we need to get an application id.
if params.iter().any(|kp| kp.tag == Tag::ATTESTATION_CHALLENGE) {
let _wp =
- self.watch("In KeystoreSecurityLevel::add_required_parameters calling: get_aaid");
+ self.watch(" KeystoreSecurityLevel::add_required_parameters: calling get_aaid");
match keystore2_aaid::get_aaid(uid) {
Ok(aaid_ok) => {
result.push(KeyParameter {
@@ -581,8 +582,8 @@
map_km_error({
let _wp = self.watch_millis(
concat!(
- "In KeystoreSecurityLevel::generate_key (UserGenerated): ",
- "calling generate_key."
+ "KeystoreSecurityLevel::generate_key (UserGenerated): ",
+ "calling IKeyMintDevice::generate_key"
),
5000, // Generate can take a little longer.
);
@@ -601,8 +602,8 @@
map_km_error({
let _wp = self.watch_millis(
concat!(
- "In KeystoreSecurityLevel::generate_key (RkpdProvisioned): ",
- "calling generate_key.",
+ "KeystoreSecurityLevel::generate_key (RkpdProvisioned): ",
+ "calling IKeyMintDevice::generate_key",
),
5000, // Generate can take a little longer.
);
@@ -628,8 +629,8 @@
None => map_km_error({
let _wp = self.watch_millis(
concat!(
- "In KeystoreSecurityLevel::generate_key (No attestation): ",
- "calling generate_key.",
+ "KeystoreSecurityLevel::generate_key (No attestation key): ",
+ "calling IKeyMintDevice::generate_key",
),
5000, // Generate can take a little longer.
);
@@ -696,7 +697,8 @@
let km_dev = &self.keymint;
let creation_result = map_km_error({
- let _wp = self.watch("In KeystoreSecurityLevel::import_key: calling importKey.");
+ let _wp =
+ self.watch("KeystoreSecurityLevel::import_key: calling IKeyMintDevice::importKey.");
km_dev.importKey(¶ms, format, key_data, None /* attestKey */)
})
.context(ks_err!("Trying to call importKey"))?;
@@ -810,7 +812,7 @@
&[],
|wrapping_blob| {
let _wp = self.watch(
- "In KeystoreSecurityLevel::import_wrapped_key: calling importWrappedKey.",
+ "KeystoreSecurityLevel::import_wrapped_key: calling IKeyMintDevice::importWrappedKey.",
);
let creation_result = map_km_error(self.keymint.importWrappedKey(
wrapped_data,
@@ -951,8 +953,8 @@
let km_dev = &self.keymint;
let res = {
let _wp = self.watch(concat!(
- "In IKeystoreSecurityLevel::convert_storage_key_to_ephemeral: ",
- "calling convertStorageKeyToEphemeral (1)"
+ "IKeystoreSecurityLevel::convert_storage_key_to_ephemeral: ",
+ "calling IKeyMintDevice::convertStorageKeyToEphemeral (1)"
));
map_km_error(km_dev.convertStorageKeyToEphemeral(key_blob))
};
@@ -962,19 +964,18 @@
}
Err(error::Error::Km(ErrorCode::KEY_REQUIRES_UPGRADE)) => {
let upgraded_blob = {
- let _wp = self.watch("In convert_storage_key_to_ephemeral: calling upgradeKey");
+ let _wp = self.watch("IKeystoreSecurityLevel::convert_storage_key_to_ephemeral: calling IKeyMintDevice::upgradeKey");
map_km_error(km_dev.upgradeKey(key_blob, &[]))
}
.context(ks_err!("Failed to upgrade key blob."))?;
let ephemeral_key = {
- let _wp = self.watch(
- "In convert_storage_key_to_ephemeral: calling convertStorageKeyToEphemeral (2)",
- );
+ let _wp = self.watch(concat!(
+ "IKeystoreSecurityLevel::convert_storage_key_to_ephemeral: ",
+ "calling IKeyMintDevice::convertStorageKeyToEphemeral (2)"
+ ));
map_km_error(km_dev.convertStorageKeyToEphemeral(&upgraded_blob))
}
- .context(ks_err!(
- "Failed to retrieve ephemeral key (after upgrade)."
- ))?;
+ .context(ks_err!("Failed to retrieve ephemeral key (after upgrade)."))?;
Ok(EphemeralStorageKeyResponse {
ephemeralKey: ephemeral_key,
upgradedBlob: Some(upgraded_blob),
@@ -1001,7 +1002,8 @@
let km_dev = &self.keymint;
{
- let _wp = self.watch("In KeystoreSecuritylevel::delete_key: calling deleteKey");
+ let _wp =
+ self.watch("KeystoreSecuritylevel::delete_key: calling IKeyMintDevice::deleteKey");
map_km_error(km_dev.deleteKey(key_blob)).context(ks_err!("keymint device deleteKey"))
}
}
diff --git a/keystore2/src/super_key.rs b/keystore2/src/super_key.rs
index fa1de98..42fd764 100644
--- a/keystore2/src/super_key.rs
+++ b/keystore2/src/super_key.rs
@@ -917,7 +917,7 @@
KeyType::Client, /* TODO Should be Super b/189470584 */
|dev| {
let _wp =
- wd::watch("In lock_unlocked_device_required_keys: calling importKey.");
+ wd::watch("SKM::lock_unlocked_device_required_keys: calling IKeyMintDevice::importKey.");
dev.importKey(key_params.as_slice(), KeyFormat::RAW, &encrypting_key, None)
},
)?;
diff --git a/keystore2/src/utils.rs b/keystore2/src/utils.rs
index 22c0522..0a545f7 100644
--- a/keystore2/src/utils.rs
+++ b/keystore2/src/utils.rs
@@ -146,8 +146,7 @@
binder::get_interface("permission")?;
let binder_result = {
- let _wp =
- watchdog::watch("In check_device_attestation_permissions: calling checkPermission.");
+ let _wp = watchdog::watch("check_android_permission: calling checkPermission");
permission_controller.checkPermission(
permission,
ThreadState::get_calling_pid(),
@@ -264,7 +263,9 @@
log::debug!("import parameters={import_params:?}");
let creation_result = {
- let _wp = watchdog::watch("In utils::import_keyblob_and_perform_op: calling importKey.");
+ let _wp = watchdog::watch(
+ "utils::import_keyblob_and_perform_op: calling IKeyMintDevice::importKey",
+ );
map_km_error(km_dev.importKey(&import_params, format, &key_material, None))
}
.context(ks_err!("Upgrade failed."))?;
@@ -304,7 +305,9 @@
NewBlobHandler: FnOnce(&[u8]) -> Result<()>,
{
let upgraded_blob = {
- let _wp = watchdog::watch("In utils::upgrade_keyblob_and_perform_op: calling upgradeKey.");
+ let _wp = watchdog::watch(
+ "utils::upgrade_keyblob_and_perform_op: calling IKeyMintDevice::upgradeKey.",
+ );
map_km_error(km_dev.upgradeKey(key_blob, upgrade_params))
}
.context(ks_err!("Upgrade failed."))?;