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/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")
+        }
     }
 }