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(&params)
+                ))
                 .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(&params, 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(&params)
+                ))
                 .map(|(mut result, _)| {
                     result.certificateChain.push(attestation_certs);
                     result
@@ -619,7 +631,12 @@
                 );
                 self.keymint.generateKey(&params, 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(&params)
+            )),
         }
         .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`