Merge "Simplify/clarify watchdog code" into main
diff --git a/keystore2/src/database.rs b/keystore2/src/database.rs
index 50cd3ba..a7f6a22 100644
--- a/keystore2/src/database.rs
+++ b/keystore2/src/database.rs
@@ -125,21 +125,6 @@
/// If the database returns a busy error code, retry after this interval.
const DB_BUSY_RETRY_INTERVAL: Duration = Duration::from_micros(500);
-/// If the database returns a busy error code, keep retrying for this long.
-const MAX_DB_BUSY_RETRY_PERIOD: Duration = Duration::from_secs(15);
-
-/// Check whether a database lock has timed out.
-fn check_lock_timeout(start: &std::time::Instant, timeout: Duration) -> Result<()> {
- if keystore2_flags::database_loop_timeout() {
- let elapsed = start.elapsed();
- if elapsed >= timeout {
- error!("Abandon locked DB after {elapsed:?}");
- return Err(&KsError::Rc(ResponseCode::BACKEND_BUSY))
- .context(ks_err!("Abandon locked DB after {elapsed:?}",));
- }
- }
- Ok(())
-}
impl_metadata!(
/// A set of metadata for key entries.
@@ -1397,18 +1382,6 @@
where
F: Fn(&Transaction) -> Result<(bool, T)>,
{
- self.with_transaction_timeout(behavior, MAX_DB_BUSY_RETRY_PERIOD, f)
- }
- fn with_transaction_timeout<T, F>(
- &mut self,
- behavior: TransactionBehavior,
- timeout: Duration,
- f: F,
- ) -> Result<T>
- where
- F: Fn(&Transaction) -> Result<(bool, T)>,
- {
- let start = std::time::Instant::now();
let name = behavior.name();
loop {
let result = self
@@ -1427,7 +1400,6 @@
Ok(result) => break Ok(result),
Err(e) => {
if Self::is_locked_error(&e) {
- check_lock_timeout(&start, timeout)?;
std::thread::sleep(DB_BUSY_RETRY_INTERVAL);
continue;
} else {
@@ -2156,7 +2128,6 @@
check_permission: impl Fn(&KeyDescriptor, Option<KeyPermSet>) -> Result<()>,
) -> Result<(KeyIdGuard, KeyEntry)> {
let _wp = wd::watch("KeystoreDB::load_key_entry");
- let start = std::time::Instant::now();
loop {
match self.load_key_entry_internal(
@@ -2169,7 +2140,6 @@
Ok(result) => break Ok(result),
Err(e) => {
if Self::is_locked_error(&e) {
- check_lock_timeout(&start, MAX_DB_BUSY_RETRY_PERIOD)?;
std::thread::sleep(DB_BUSY_RETRY_INTERVAL);
continue;
} else {
@@ -5523,81 +5493,4 @@
assert_eq!(third_sid_apps, vec![second_app_id]);
Ok(())
}
-
- #[test]
- fn test_key_id_guard_immediate() -> Result<()> {
- if !keystore2_flags::database_loop_timeout() {
- eprintln!("Skipping test as loop timeout flag disabled");
- return Ok(());
- }
- // Emit logging from test.
- android_logger::init_once(
- android_logger::Config::default()
- .with_tag("keystore_database_tests")
- .with_max_level(log::LevelFilter::Debug),
- );
-
- // Preparation: put a single entry into a test DB.
- let temp_dir = Arc::new(TempDir::new("key_id_guard_immediate")?);
- let temp_dir_clone_a = temp_dir.clone();
- let temp_dir_clone_b = temp_dir.clone();
- let mut db = KeystoreDB::new(temp_dir.path(), None)?;
- let key_id = make_test_key_entry(&mut db, Domain::APP, 1, TEST_ALIAS, None)?.0;
-
- let (a_sender, b_receiver) = std::sync::mpsc::channel();
- let (b_sender, a_receiver) = std::sync::mpsc::channel();
-
- // First thread starts an immediate transaction, then waits on a synchronization channel
- // before trying to get the `KeyIdGuard`.
- let handle_a = thread::spawn(move || {
- let temp_dir = temp_dir_clone_a;
- let mut db = KeystoreDB::new(temp_dir.path(), None).unwrap();
-
- // Make sure the other thread has initialized its database access before we lock it out.
- a_receiver.recv().unwrap();
-
- let _result =
- db.with_transaction_timeout(Immediate("TX_test"), Duration::from_secs(3), |_tx| {
- // Notify the other thread that we're inside the immediate transaction...
- a_sender.send(()).unwrap();
- // ...then wait to be sure that the other thread has the `KeyIdGuard` before
- // this thread also tries to get it.
- a_receiver.recv().unwrap();
-
- let _guard = KEY_ID_LOCK.get(key_id);
- Ok(()).no_gc()
- });
- });
-
- // Second thread gets the `KeyIdGuard`, then waits before trying to perform an immediate
- // transaction.
- let handle_b = thread::spawn(move || {
- let temp_dir = temp_dir_clone_b;
- let mut db = KeystoreDB::new(temp_dir.path(), None).unwrap();
- // Notify the other thread that we are initialized (so it can lock the immediate
- // transaction).
- b_sender.send(()).unwrap();
-
- let _guard = KEY_ID_LOCK.get(key_id);
- // Notify the other thread that we have the `KeyIdGuard`...
- b_sender.send(()).unwrap();
- // ...then wait to be sure that the other thread is in the immediate transaction before
- // this thread also tries to do one.
- b_receiver.recv().unwrap();
-
- let result =
- db.with_transaction_timeout(Immediate("TX_test"), Duration::from_secs(3), |_tx| {
- Ok(()).no_gc()
- });
- // Expect the attempt to get an immediate transaction to fail, and then this thread will
- // exit and release the `KeyIdGuard`, allowing the other thread to complete.
- assert!(result.is_err());
- check_result_is_error_containing_string(result, "BACKEND_BUSY");
- });
-
- let _ = handle_a.join();
- let _ = handle_b.join();
-
- Ok(())
- }
}
diff --git a/keystore2/src/legacy_importer.rs b/keystore2/src/legacy_importer.rs
index f64af0b..f9d5d1b 100644
--- a/keystore2/src/legacy_importer.rs
+++ b/keystore2/src/legacy_importer.rs
@@ -928,6 +928,6 @@
},
|_| Ok(()),
)
- .context(ks_err!())?;
+ .context(ks_err!("Key blob upgrade failed, possibly invalid keyblob for uuid {uuid:?}"))?;
Ok((key_characteristics_to_internal(characteristics), upgraded_blob))
}
diff --git a/keystore2/src/security_level.rs b/keystore2/src/security_level.rs
index 8ce802e..951acb5 100644
--- a/keystore2/src/security_level.rs
+++ b/keystore2/src/security_level.rs
@@ -34,7 +34,8 @@
use crate::utils::{
check_device_attestation_permissions, check_key_permission,
check_unique_id_attestation_permissions, is_device_id_attestation_tag,
- key_characteristics_to_internal, uid_to_android_user, watchdog as wd, UNDEFINED_NOT_AFTER,
+ key_characteristics_to_internal, log_security_safe_params, uid_to_android_user, watchdog as wd,
+ UNDEFINED_NOT_AFTER,
};
use crate::{
database::{
@@ -514,6 +515,7 @@
flags: i32,
_entropy: &[u8],
) -> Result<KeyMetadata> {
+ log::info!("security_level: generate_key(key={:?})", key);
if key.domain != Domain::BLOB && key.alias.is_none() {
return Err(error::Error::Km(ErrorCode::INVALID_ARGUMENT))
.context(ks_err!("Alias must be specified"));
@@ -583,7 +585,12 @@
})
},
)
- .context(ks_err!("Using user generated attestation key."))
+ .context(ks_err!(
+ "While generating Key {:?} with remote \
+ provisioned attestation key and params: {:?}.",
+ key.alias,
+ log_security_safe_params(¶ms)
+ ))
.map(|(result, _)| result),
Some(AttestationKeyInfo::RkpdProvisioned { attestation_key, attestation_certs }) => {
self.upgrade_rkpd_keyblob_if_required_with(&attestation_key.keyBlob, &[], |blob| {
@@ -603,7 +610,12 @@
self.keymint.generateKey(¶ms, dynamic_attest_key.as_ref())
})
})
- .context(ks_err!("While generating Key with remote provisioned attestation key."))
+ .context(ks_err!(
+ "While generating Key {:?} with remote \
+ provisioned attestation key and params: {:?}.",
+ key.alias,
+ log_security_safe_params(¶ms)
+ ))
.map(|(mut result, _)| {
result.certificateChain.push(attestation_certs);
result
@@ -619,7 +631,12 @@
);
self.keymint.generateKey(¶ms, None)
})
- .context(ks_err!("While generating Key without explicit attestation key.")),
+ .context(ks_err!(
+ "While generating Key {:?} with remote \
+ provisioned attestation key and params: {:?}.",
+ key.alias,
+ log_security_safe_params(¶ms)
+ )),
}
.context(ks_err!())?;
@@ -847,6 +864,7 @@
where
F: Fn(&[u8]) -> Result<T, Error>,
{
+ log::info!("upgrade_keyblob_if_required_with(key_id={:?})", key_id_guard);
let (v, upgraded_blob) = crate::utils::upgrade_keyblob_if_required_with(
&*self.keymint,
self.hw_info.versionNumber,
@@ -887,6 +905,10 @@
where
F: Fn(&[u8]) -> Result<T, Error>,
{
+ log::info!(
+ "upgrade_rkpd_keyblob_if_required_with(params={:?})",
+ log_security_safe_params(params)
+ );
let rpc_name = get_remotely_provisioned_component_name(&self.security_level)
.context(ks_err!("Trying to get IRPC name."))?;
crate::utils::upgrade_keyblob_if_required_with(
diff --git a/keystore2/src/utils.rs b/keystore2/src/utils.rs
index 196cac5..c80bfa5 100644
--- a/keystore2/src/utils.rs
+++ b/keystore2/src/utils.rs
@@ -551,8 +551,8 @@
items_to_return
}
-/// List all key aliases for a given domain + namespace. whose alias is greater
-/// than start_past_alias (if provided).
+/// Log the key parameters, excluding sensitive ones such as
+/// APPLICATION_DATA and APPLICATION_ID
pub fn list_key_entries(
db: &mut KeystoreDB,
domain: Domain,
@@ -591,6 +591,16 @@
Ok((legacy_keys.len() + num_keys_in_db) as i32)
}
+/// For params remove sensitive data before returning a string for logging
+pub fn log_security_safe_params(params: &[KmKeyParameter]) -> String {
+ format!(
+ "{:?}",
+ params
+ .iter()
+ .filter(|kp| (kp.tag != Tag::APPLICATION_ID && kp.tag != Tag::APPLICATION_DATA))
+ )
+}
+
/// Trait implemented by objects that can be used to decrypt cipher text using AES-GCM.
pub trait AesGcm {
/// Deciphers `data` using the initialization vector `iv` and AEAD tag `tag`