Keystore 2.0: Add more watch points.

This patch adds watch points on all calls into keymint, on get_aaid, and
calls to the permission controller.

Test: N/A
Change-Id: If5b85fd1ad5c33e08ba9fd25f5cb0c76be747d3e
diff --git a/keystore2/src/error.rs b/keystore2/src/error.rs
index d1b2ffb..f969cb6 100644
--- a/keystore2/src/error.rs
+++ b/keystore2/src/error.rs
@@ -30,16 +30,13 @@
 //! Keystore functions should use `anyhow::Result` to return error conditions, and
 //! context should be added every time an error is forwarded.
 
-use std::cmp::PartialEq;
-
 pub use android_hardware_security_keymint::aidl::android::hardware::security::keymint::ErrorCode::ErrorCode;
 pub use android_system_keystore2::aidl::android::system::keystore2::ResponseCode::ResponseCode;
-
-use keystore2_selinux as selinux;
-
 use android_system_keystore2::binder::{
     ExceptionCode, Result as BinderResult, Status as BinderStatus, StatusCode,
 };
+use keystore2_selinux as selinux;
+use std::cmp::PartialEq;
 
 /// This is the main Keystore error type. It wraps the Keystore `ResponseCode` generated
 /// from AIDL in the `Rc` variant and Keymint `ErrorCode` in the Km variant.
diff --git a/keystore2/src/globals.rs b/keystore2/src/globals.rs
index 9f38799..b640326b 100644
--- a/keystore2/src/globals.rs
+++ b/keystore2/src/globals.rs
@@ -20,6 +20,7 @@
 use crate::legacy_blob::LegacyBlobLoader;
 use crate::legacy_migrator::LegacyMigrator;
 use crate::super_key::SuperKeyManager;
+use crate::utils::watchdog as wd;
 use crate::utils::Asp;
 use crate::{async_task::AsyncTask, database::MonotonicRawTime};
 use crate::{
@@ -58,6 +59,7 @@
             Box::new(|uuid, blob| {
                 let km_dev: Strong<dyn IKeyMintDevice> =
                     get_keymint_dev_by_uuid(uuid).map(|(dev, _)| dev)?.get_interface()?;
+                let _wp = wd::watch_millis("In create_thread_local_db: calling deleteKey", 500);
                 map_km_error(km_dev.deleteKey(&*blob))
                     .context("In invalidate key closure: Trying to invalidate key blob.")
             }),
@@ -227,8 +229,10 @@
             .context("In connect_keymint: Trying to get Legacy wrapper.")
     }?;
 
+    let wp = wd::watch_millis("In connect_keymint: calling getHardwareInfo()", 500);
     let hw_info = map_km_error(keymint.getHardwareInfo())
         .context("In connect_keymint: Failed to get hardware info.")?;
+    drop(wp);
 
     Ok((Asp::new(keymint.as_binder()), hw_info))
 }
diff --git a/keystore2/src/maintenance.rs b/keystore2/src/maintenance.rs
index 9e7576e..13a5b43 100644
--- a/keystore2/src/maintenance.rs
+++ b/keystore2/src/maintenance.rs
@@ -22,7 +22,7 @@
 use crate::globals::{DB, LEGACY_MIGRATOR, SUPER_KEY};
 use crate::permission::{KeyPerm, KeystorePerm};
 use crate::super_key::UserState;
-use crate::utils::{check_key_permission, check_keystore_permission};
+use crate::utils::{check_key_permission, check_keystore_permission, watchdog as wd};
 use android_hardware_security_keymint::aidl::android::hardware::security::keymint::IKeyMintDevice::IKeyMintDevice;
 use android_hardware_security_keymint::aidl::android::hardware::security::keymint::SecurityLevel::SecurityLevel;
 use android_security_maintenance::aidl::android::security::maintenance::{
@@ -133,11 +133,17 @@
         }
     }
 
-    fn early_boot_ended_help(sec_level: &SecurityLevel) -> Result<()> {
-        let (dev, _, _) =
-            get_keymint_device(sec_level).context("In early_boot_ended: getting keymint device")?;
+    fn early_boot_ended_help(sec_level: SecurityLevel) -> Result<()> {
+        let (dev, _, _) = get_keymint_device(&sec_level)
+            .context("In early_boot_ended: getting keymint device")?;
         let km_dev: Strong<dyn IKeyMintDevice> =
             dev.get_interface().context("In early_boot_ended: getting keymint device interface")?;
+
+        let _wp = wd::watch_millis_with(
+            "In early_boot_ended_help: calling earlyBootEnded()",
+            500,
+            move || format!("Seclevel: {:?}", sec_level),
+        );
         map_km_error(km_dev.earlyBootEnded())
             .context("In keymint device: calling earlyBootEnded")?;
         Ok(())
@@ -157,7 +163,7 @@
             (SecurityLevel::STRONGBOX, "STRONGBOX"),
         ];
         sec_levels.iter().fold(Ok(()), |result, (sec_level, sec_level_string)| {
-            let curr_result = Maintenance::early_boot_ended_help(sec_level);
+            let curr_result = Maintenance::early_boot_ended_help(*sec_level);
             if curr_result.is_err() {
                 log::error!(
                     "Call to earlyBootEnded failed for security level {}.",
diff --git a/keystore2/src/operation.rs b/keystore2/src/operation.rs
index 0b5c77a..3ef3c1c 100644
--- a/keystore2/src/operation.rs
+++ b/keystore2/src/operation.rs
@@ -128,7 +128,7 @@
 use crate::enforcements::AuthInfo;
 use crate::error::{map_err_with, map_km_error, map_or_log_err, Error, ErrorCode, ResponseCode};
 use crate::metrics::log_key_operation_event_stats;
-use crate::utils::Asp;
+use crate::utils::{watchdog as wd, Asp};
 use android_hardware_security_keymint::aidl::android::hardware::security::keymint::{
     IKeyMintOperation::IKeyMintOperation, KeyParameter::KeyParameter, KeyPurpose::KeyPurpose,
     SecurityLevel::SecurityLevel,
@@ -291,6 +291,8 @@
                 }
             };
 
+        let _wp = wd::watch_millis("In Operation::prune: calling abort()", 500);
+
         // We abort the operation. If there was an error we log it but ignore it.
         if let Err(e) = map_km_error(km_op.abort()) {
             log::error!("In prune: KeyMint::abort failed with {:?}.", e);
@@ -370,10 +372,10 @@
             .before_update()
             .context("In update_aad: Trying to get auth tokens.")?;
 
-        self.update_outcome(
-            &mut *outcome,
-            map_km_error(km_op.updateAad(aad_input, hat.as_ref(), tst.as_ref())),
-        )
+        self.update_outcome(&mut *outcome, {
+            let _wp = wd::watch_millis("Operation::update_aad: calling updateAad", 500);
+            map_km_error(km_op.updateAad(aad_input, hat.as_ref(), tst.as_ref()))
+        })
         .context("In update_aad: KeyMint::update failed.")?;
 
         Ok(())
@@ -397,10 +399,10 @@
             .context("In update: Trying to get auth tokens.")?;
 
         let output = self
-            .update_outcome(
-                &mut *outcome,
-                map_km_error(km_op.update(input, hat.as_ref(), tst.as_ref())),
-            )
+            .update_outcome(&mut *outcome, {
+                let _wp = wd::watch_millis("Operation::update: calling update", 500);
+                map_km_error(km_op.update(input, hat.as_ref(), tst.as_ref()))
+            })
             .context("In update: KeyMint::update failed.")?;
 
         if output.is_empty() {
@@ -430,16 +432,16 @@
             .context("In finish: Trying to get auth tokens.")?;
 
         let output = self
-            .update_outcome(
-                &mut *outcome,
+            .update_outcome(&mut *outcome, {
+                let _wp = wd::watch_millis("Operation::finish: calling finish", 500);
                 map_km_error(km_op.finish(
                     input,
                     signature,
                     hat.as_ref(),
                     tst.as_ref(),
                     confirmation_token.as_deref(),
-                )),
-            )
+                ))
+            })
             .context("In finish: KeyMint::finish failed.")?;
 
         self.auth_info.lock().unwrap().after_finish().context("In finish.")?;
@@ -463,7 +465,10 @@
         let km_op: binder::public_api::Strong<dyn IKeyMintOperation> =
             self.km_op.get_interface().context("In abort: Failed to get KeyMintOperation.")?;
 
-        map_km_error(km_op.abort()).context("In abort: KeyMint::abort failed.")
+        {
+            let _wp = wd::watch_millis("Operation::abort: calling abort", 500);
+            map_km_error(km_op.abort()).context("In abort: KeyMint::abort failed.")
+        }
     }
 }
 
diff --git a/keystore2/src/raw_device.rs b/keystore2/src/raw_device.rs
index 06432fe..9e6ef41 100644
--- a/keystore2/src/raw_device.rs
+++ b/keystore2/src/raw_device.rs
@@ -22,7 +22,7 @@
     error::{map_km_error, Error},
     globals::get_keymint_device,
     super_key::KeyBlob,
-    utils::{key_characteristics_to_internal, Asp, AID_KEYSTORE},
+    utils::{key_characteristics_to_internal, watchdog as wd, Asp, AID_KEYSTORE},
 };
 use android_hardware_security_keymint::aidl::android::hardware::security::keymint::{
     BeginResult::BeginResult, ErrorCode::ErrorCode, HardwareAuthToken::HardwareAuthToken,
@@ -151,7 +151,7 @@
             self.create_and_store_key(db, &key_desc, |km_dev| km_dev.generateKey(&params, None))
                 .context("In lookup_or_generate_key: generate_and_store_key failed")?;
             Self::lookup_from_desc(db, key_desc)
-                .context("In lookup_or_generate_key: secpnd lookup failed")
+                .context("In lookup_or_generate_key: second lookup failed")
         }
     }
 
@@ -170,8 +170,14 @@
     {
         match f(key_blob) {
             Err(Error::Km(ErrorCode::KEY_REQUIRES_UPGRADE)) => {
-                let upgraded_blob = map_km_error(km_dev.upgradeKey(key_blob, &[]))
-                    .context("In upgrade_keyblob_if_required_with: Upgrade failed")?;
+                let upgraded_blob = map_km_error({
+                    let _wp = wd::watch_millis(
+                        "In KeyMintDevice::upgrade_keyblob_if_required_with: calling upgradeKey.",
+                        500,
+                    );
+                    km_dev.upgradeKey(key_blob, &[])
+                })
+                .context("In upgrade_keyblob_if_required_with: Upgrade failed")?;
 
                 let mut new_blob_metadata = BlobMetaData::new();
                 new_blob_metadata.add(BlobMetaEntry::KmUuid(self.km_uuid));
@@ -223,14 +229,20 @@
 
         let begin_result: BeginResult = self
             .upgrade_keyblob_if_required_with(db, &km_dev, key_id_guard, &key_blob, |blob| {
-                map_km_error(km_dev.begin(purpose, blob, operation_parameters, auth_token))
+                map_km_error({
+                    let _wp = wd::watch_millis("In use_key_in_one_step: calling: begin", 500);
+                    km_dev.begin(purpose, blob, operation_parameters, auth_token)
+                })
             })
             .context("In use_key_in_one_step: Failed to begin operation.")?;
         let operation: Strong<dyn IKeyMintOperation> = begin_result
             .operation
             .ok_or_else(Error::sys)
             .context("In use_key_in_one_step: Operation missing")?;
-        map_km_error(operation.finish(Some(input), None, None, None, None))
-            .context("In use_key_in_one_step: Failed to finish operation.")
+        map_km_error({
+            let _wp = wd::watch_millis("In use_key_in_one_step: calling: finish", 500);
+            operation.finish(Some(input), None, None, None, None)
+        })
+        .context("In use_key_in_one_step: Failed to finish operation.")
     }
 }
diff --git a/keystore2/src/security_level.rs b/keystore2/src/security_level.rs
index 53880a1..84d1963 100644
--- a/keystore2/src/security_level.rs
+++ b/keystore2/src/security_level.rs
@@ -14,6 +14,30 @@
 
 //! This crate implements the IKeystoreSecurityLevel interface.
 
+use crate::attestation_key_utils::{get_attest_key_info, AttestationKeyInfo};
+use crate::audit_log::{log_key_deleted, log_key_generated, log_key_imported};
+use crate::database::{CertificateInfo, KeyIdGuard};
+use crate::error::{self, map_km_error, map_or_log_err, Error, ErrorCode};
+use crate::globals::{DB, ENFORCEMENTS, LEGACY_MIGRATOR, SUPER_KEY};
+use crate::key_parameter::KeyParameter as KsKeyParam;
+use crate::key_parameter::KeyParameterValue as KsKeyParamValue;
+use crate::metrics::log_key_creation_event_stats;
+use crate::remote_provisioning::RemProvState;
+use crate::super_key::{KeyBlob, SuperKeyManager};
+use crate::utils::{
+    check_device_attestation_permissions, check_key_permission, is_device_id_attestation_tag,
+    key_characteristics_to_internal, uid_to_android_user, watchdog as wd, Asp,
+};
+use crate::{
+    database::{
+        BlobMetaData, BlobMetaEntry, DateTime, KeyEntry, KeyEntryLoadBits, KeyMetaData,
+        KeyMetaEntry, KeyType, SubComponentType, Uuid,
+    },
+    operation::KeystoreOperation,
+    operation::LoggingInfo,
+    operation::OperationDb,
+    permission::KeyPerm,
+};
 use crate::{globals::get_keymint_device, id_rotation::IdRotationState};
 use android_hardware_security_keymint::aidl::android::hardware::security::keymint::{
     Algorithm::Algorithm, AttestationKey::AttestationKey,
@@ -30,34 +54,6 @@
     IKeystoreSecurityLevel::IKeystoreSecurityLevel, KeyDescriptor::KeyDescriptor,
     KeyMetadata::KeyMetadata, KeyParameters::KeyParameters,
 };
-
-use crate::attestation_key_utils::{get_attest_key_info, AttestationKeyInfo};
-use crate::audit_log::{log_key_deleted, log_key_generated, log_key_imported};
-use crate::database::{CertificateInfo, KeyIdGuard};
-use crate::globals::{DB, ENFORCEMENTS, LEGACY_MIGRATOR, SUPER_KEY};
-use crate::key_parameter::KeyParameter as KsKeyParam;
-use crate::key_parameter::KeyParameterValue as KsKeyParamValue;
-use crate::metrics::log_key_creation_event_stats;
-use crate::remote_provisioning::RemProvState;
-use crate::super_key::{KeyBlob, SuperKeyManager};
-use crate::utils::{
-    check_device_attestation_permissions, check_key_permission, is_device_id_attestation_tag,
-    uid_to_android_user, Asp,
-};
-use crate::{
-    database::{
-        BlobMetaData, BlobMetaEntry, DateTime, KeyEntry, KeyEntryLoadBits, KeyMetaData,
-        KeyMetaEntry, KeyType, SubComponentType, Uuid,
-    },
-    operation::KeystoreOperation,
-    operation::LoggingInfo,
-    operation::OperationDb,
-    permission::KeyPerm,
-};
-use crate::{
-    error::{self, map_km_error, map_or_log_err, Error, ErrorCode},
-    utils::key_characteristics_to_internal,
-};
 use anyhow::{anyhow, Context, Result};
 
 /// Implementation of the IKeystoreSecurityLevel Interface.
@@ -104,6 +100,11 @@
         Ok((result, km_uuid))
     }
 
+    fn watch_millis(&self, id: &'static str, millis: u64) -> Option<wd::WatchPoint> {
+        let sec_level = self.security_level;
+        wd::watch_millis_with(id, millis, move || format!("SecurityLevel {:?}", sec_level))
+    }
+
     fn store_new_key(
         &self,
         key: KeyDescriptor,
@@ -313,12 +314,13 @@
                 &blob_metadata,
                 &operation_parameters,
                 |blob| loop {
-                    match map_km_error(km_dev.begin(
-                        purpose,
-                        blob,
-                        &operation_parameters,
-                        immediate_hat.as_ref(),
-                    )) {
+                    match map_km_error({
+                        let _wp = self.watch_millis(
+                            "In KeystoreSecurityLevel::create_operation: calling begin",
+                            500,
+                        );
+                        km_dev.begin(purpose, blob, &operation_parameters, immediate_hat.as_ref())
+                    }) {
                         Err(Error::Km(ErrorCode::TOO_MANY_OPERATIONS)) => {
                             self.operation_db.prune(caller_uid, forced)?;
                             continue;
@@ -334,12 +336,19 @@
         let op_params: Vec<KeyParameter> = operation_parameters.to_vec();
 
         let operation = match begin_result.operation {
-            Some(km_op) => {
-                self.operation_db.create_operation(km_op, caller_uid, auth_info, forced,
-                    LoggingInfo::new(self.security_level, purpose, op_params,
-                         upgraded_blob.is_some()))
-            },
-            None => return Err(Error::sys()).context("In create_operation: Begin operation returned successfully, but did not return a valid operation."),
+            Some(km_op) => self.operation_db.create_operation(
+                km_op,
+                caller_uid,
+                auth_info,
+                forced,
+                LoggingInfo::new(self.security_level, purpose, op_params, upgraded_blob.is_some()),
+            ),
+            None => {
+                return Err(Error::sys()).context(concat!(
+                    "In create_operation: Begin operation returned successfully, ",
+                    "but did not return a valid operation."
+                ))
+            }
         };
 
         let op_binder: binder::public_api::Strong<dyn IKeystoreOperation> =
@@ -371,9 +380,19 @@
         let mut result = params.to_vec();
         // If there is an attestation challenge we need to get an application id.
         if params.iter().any(|kp| kp.tag == Tag::ATTESTATION_CHALLENGE) {
-            let aaid = keystore2_aaid::get_aaid(uid).map_err(|e| {
-                anyhow!(format!("In add_certificate_parameters: get_aaid returned status {}.", e))
-            })?;
+            let aaid = {
+                let _wp = self.watch_millis(
+                    "In KeystoreSecurityLevel::add_certificate_parameters calling: get_aaid",
+                    500,
+                );
+                keystore2_aaid::get_aaid(uid).map_err(|e| {
+                    anyhow!(format!(
+                        "In add_certificate_parameters: get_aaid returned status {}.",
+                        e
+                    ))
+                })
+            }?;
+
             result.push(KeyParameter {
                 tag: Tag::ATTESTATION_APPLICATION_ID,
                 value: KeyParameterValue::Blob(aaid),
@@ -495,21 +514,48 @@
                             attestKeyParams: vec![],
                             issuerSubjectName: issuer_subject.clone(),
                         });
-                        map_km_error(km_dev.generateKey(&params, attest_key.as_ref()))
+                        map_km_error({
+                            let _wp = self.watch_millis(
+                                concat!(
+                                    "In KeystoreSecurityLevel::generate_key (UserGenerated): ",
+                                    "calling generate_key."
+                                ),
+                                5000, // Generate can take a little longer.
+                            );
+                            km_dev.generateKey(&params, attest_key.as_ref())
+                        })
                     },
                 )
                 .context("In generate_key: Using user generated attestation key.")
                 .map(|(result, _)| result),
             Some(AttestationKeyInfo::RemoteProvisioned { attestation_key, attestation_certs }) => {
-                map_km_error(km_dev.generateKey(&params, Some(&attestation_key)))
-                    .context("While generating Key with remote provisioned attestation key.")
-                    .map(|mut creation_result| {
-                        creation_result.certificateChain.push(attestation_certs);
-                        creation_result
-                    })
+                map_km_error({
+                    let _wp = self.watch_millis(
+                        concat!(
+                            "In KeystoreSecurityLevel::generate_key (RemoteProvisioned): ",
+                            "calling generate_key.",
+                        ),
+                        5000, // Generate can take a little longer.
+                    );
+                    km_dev.generateKey(&params, Some(&attestation_key))
+                })
+                .context("While generating Key with remote provisioned attestation key.")
+                .map(|mut creation_result| {
+                    creation_result.certificateChain.push(attestation_certs);
+                    creation_result
+                })
             }
-            None => map_km_error(km_dev.generateKey(&params, None))
-                .context("While generating Key without explicit attestation key."),
+            None => map_km_error({
+                let _wp = self.watch_millis(
+                    concat!(
+                        "In KeystoreSecurityLevel::generate_key (No attestation): ",
+                        "calling generate_key.",
+                    ),
+                    5000, // Generate can take a little longer.
+                );
+                km_dev.generateKey(&params, None)
+            })
+            .context("While generating Key without explicit attestation key."),
         }
         .context("In generate_key.")?;
 
@@ -566,9 +612,12 @@
 
         let km_dev: Strong<dyn IKeyMintDevice> =
             self.keymint.get_interface().context("In import_key: Trying to get the KM device")?;
-        let creation_result =
-            map_km_error(km_dev.importKey(&params, format, key_data, None /* attestKey */))
-                .context("In import_key: Trying to call importKey")?;
+        let creation_result = map_km_error({
+            let _wp =
+                self.watch_millis("In KeystoreSecurityLevel::import_key: calling importKey.", 500);
+            km_dev.importKey(&params, format, key_data, None /* attestKey */)
+        })
+        .context("In import_key: Trying to call importKey")?;
 
         let user_id = uid_to_android_user(caller_uid);
         self.store_new_key(key, creation_result, user_id, Some(flags)).context("In import_key.")
@@ -681,6 +730,10 @@
                 &wrapping_blob_metadata,
                 &[],
                 |wrapping_blob| {
+                    let _wp = self.watch_millis(
+                        "In KeystoreSecurityLevel::import_wrapped_key: calling importWrappedKey.",
+                        500,
+                    );
                     let creation_result = map_km_error(km_dev.importWrappedKey(
                         wrapped_data,
                         wrapping_blob,
@@ -739,8 +792,17 @@
     {
         match f(key_blob) {
             Err(Error::Km(ErrorCode::KEY_REQUIRES_UPGRADE)) => {
-                let upgraded_blob = map_km_error(km_dev.upgradeKey(key_blob, params))
-                    .context("In upgrade_keyblob_if_required_with: Upgrade failed.")?;
+                let upgraded_blob = {
+                    let _wp = self.watch_millis(
+                        concat!(
+                            "In KeystoreSecurityLevel::upgrade_keyblob_if_required_with: ",
+                            "calling upgradeKey."
+                        ),
+                        500,
+                    );
+                    map_km_error(km_dev.upgradeKey(key_blob, params))
+                }
+                .context("In upgrade_keyblob_if_required_with: Upgrade failed.")?;
 
                 if let Some(kid) = key_id_guard {
                     Self::store_upgraded_keyblob(
@@ -810,14 +872,35 @@
             "In IKeystoreSecurityLevel convert_storage_key_to_ephemeral: ",
             "Getting keymint device interface"
         ))?;
-        match map_km_error(km_dev.convertStorageKeyToEphemeral(key_blob)) {
+        match {
+            let _wp = self.watch_millis(
+                concat!(
+                    "In IKeystoreSecurityLevel::convert_storage_key_to_ephemeral: ",
+                    "calling convertStorageKeyToEphemeral (1)"
+                ),
+                500,
+            );
+            map_km_error(km_dev.convertStorageKeyToEphemeral(key_blob))
+        } {
             Ok(result) => {
                 Ok(EphemeralStorageKeyResponse { ephemeralKey: result, upgradedBlob: None })
             }
             Err(error::Error::Km(ErrorCode::KEY_REQUIRES_UPGRADE)) => {
-                let upgraded_blob = map_km_error(km_dev.upgradeKey(key_blob, &[]))
-                    .context("In convert_storage_key_to_ephemeral: Failed to upgrade key blob.")?;
-                let ephemeral_key = map_km_error(km_dev.convertStorageKeyToEphemeral(key_blob))
+                let upgraded_blob = {
+                    let _wp = self.watch_millis(
+                        "In convert_storage_key_to_ephemeral: calling upgradeKey",
+                        500,
+                    );
+                    map_km_error(km_dev.upgradeKey(key_blob, &[]))
+                }
+                .context("In convert_storage_key_to_ephemeral: Failed to upgrade key blob.")?;
+                let ephemeral_key = {
+                    let _wp = self.watch_millis(
+                        "In convert_storage_key_to_ephemeral: calling convertStorageKeyToEphemeral (2)",
+                        500,
+                    );
+                    map_km_error(km_dev.convertStorageKeyToEphemeral(key_blob))
+                }
                     .context(concat!(
                         "In convert_storage_key_to_ephemeral: ",
                         "Failed to retrieve ephemeral key (after upgrade)."
@@ -851,7 +934,11 @@
             .keymint
             .get_interface()
             .context("In IKeystoreSecurityLevel delete_key: Getting keymint device interface")?;
-        map_km_error(km_dev.deleteKey(&key_blob)).context("In keymint device deleteKey")
+        {
+            let _wp =
+                self.watch_millis("In KeystoreSecuritylevel::delete_key: calling deleteKey", 500);
+            map_km_error(km_dev.deleteKey(&key_blob)).context("In keymint device deleteKey")
+        }
     }
 }
 
diff --git a/keystore2/src/super_key.rs b/keystore2/src/super_key.rs
index 50a5f31..848707c 100644
--- a/keystore2/src/super_key.rs
+++ b/keystore2/src/super_key.rs
@@ -29,6 +29,7 @@
     legacy_migrator::LegacyMigrator,
     raw_device::KeyMintDevice,
     try_insert::TryInsert,
+    utils::watchdog as wd,
 };
 use android_hardware_security_keymint::aidl::android::hardware::security::keymint::{
     Algorithm::Algorithm, BlockMode::BlockMode, HardwareAuthToken::HardwareAuthToken,
@@ -949,6 +950,10 @@
                     let key_params: Vec<KmKeyParameter> =
                         key_params.into_iter().map(|x| x.into()).collect();
                     km_dev.create_and_store_key(db, &key_desc, |dev| {
+                        let _wp = wd::watch_millis(
+                            "In lock_screen_lock_bound_key: calling importKey.",
+                            500,
+                        );
                         dev.importKey(key_params.as_slice(), KeyFormat::RAW, &encrypting_key, None)
                     })?;
                     entry.biometric_unlock = Some(BiometricUnlock {
diff --git a/keystore2/src/utils.rs b/keystore2/src/utils.rs
index 982d8f5..9852aad 100644
--- a/keystore2/src/utils.rs
+++ b/keystore2/src/utils.rs
@@ -107,11 +107,17 @@
     let permission_controller: binder::Strong<dyn IPermissionController::IPermissionController> =
         binder::get_interface("permission")?;
 
-    let binder_result = permission_controller.checkPermission(
-        "android.permission.READ_PRIVILEGED_PHONE_STATE",
-        ThreadState::get_calling_pid(),
-        ThreadState::get_calling_uid() as i32,
-    );
+    let binder_result = {
+        let _wp = watchdog::watch_millis(
+            "In check_device_attestation_permissions: calling checkPermission.",
+            500,
+        );
+        permission_controller.checkPermission(
+            "android.permission.READ_PRIVILEGED_PHONE_STATE",
+            ThreadState::get_calling_pid(),
+            ThreadState::get_calling_uid() as i32,
+        )
+    };
     let has_permissions = map_binder_status(binder_result)
         .context("In check_device_attestation_permissions: checkPermission failed")?;
     match has_permissions {
diff --git a/keystore2/src/watchdog.rs b/keystore2/src/watchdog.rs
index 0171901..0ed522f 100644
--- a/keystore2/src/watchdog.rs
+++ b/keystore2/src/watchdog.rs
@@ -268,6 +268,7 @@
                     break;
                 }
             }
+            log::info!("Watchdog thread idle -> terminating. Have a great day.");
         }));
         state.state = State::Running;
     }