Standardize watchdog messages
Try to stick to a common layout for watchdog messages:
- Skip leading "In " prefix.
- Identify "<type>::<method>".
- Ensure that all watchpoints around KeyMint invocations mention either
"IKeyMintDevice" or "IKeyMintOperation" (to make it clearer when
Keystore is blocked on the underlying KeyMint implementation).
Bug: 265778655
Test: watch logcat, add deliberate sleeps
Change-Id: I803a0a7a60b445848afea00b5f48cf7fd1f17fe5
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/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 8cbd9c7..61277f1 100644
--- a/keystore2/src/maintenance.rs
+++ b/keystore2/src/maintenance.rs
@@ -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(())
}
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."))?;