commit a38e3420baa8832ceaecb4a0696df7df9d2dc938
author David Drysdale <drysdale@google.com> Wed Mar 12 14:11:02 2025 +0000
committer David Drysdale <drysdale@google.com> Wed Mar 12 14:53:49 2025 +0000
tree 03a430fdfade3e140e9128790a036e15d3bfc388
parent b8954f4c022e48ade815d22f9d67479b02ac3780

Include security level in per-operation watchdogs

Make it easier to diagnose hung `IKeyMintOperation` entrypoints
by including the security level in the watchdog output.

Test: keystore2_client_tests + logcat with lowered timeout
Change-Id: Ieb5fd06b3b4f2b7211b7ea6e3add660c1200590f
Flag: EXEMPT bug fix to logging
Bug: 401719888

keystore2/src/operation.rs

diff --git a/keystore2/src/operation.rs b/keystore2/src/operation.rs
index c11c1f4..2d00b6d 100644
--- a/keystore2/src/operation.rs
+++ b/keystore2/src/operation.rs
@@ -237,6 +237,11 @@
         }
     }
 
+    fn watch(&self, id: &'static str) -> Option<wd::WatchPoint> {
+        let sec_level = self.logging_info.sec_level;
+        wd::watch_millis_with(id, wd::DEFAULT_TIMEOUT_MS, sec_level)
+    }
+
     fn get_pruning_info(&self) -> Option<PruningInfo> {
         // An operation may be finalized.
         if let Ok(guard) = self.outcome.try_lock() {
@@ -287,7 +292,7 @@
         }
         *locked_outcome = Outcome::Pruned;
 
-        let _wp = wd::watch("Operation::prune: calling IKeyMintOperation::abort()");
+        let _wp = self.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 +367,7 @@
             .context(ks_err!("Trying to get auth tokens."))?;
 
         self.update_outcome(&mut outcome, {
-            let _wp = wd::watch("Operation::update_aad: calling IKeyMintOperation::updateAad");
+            let _wp = self.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 +391,7 @@
 
         let output = self
             .update_outcome(&mut outcome, {
-                let _wp = wd::watch("Operation::update: calling IKeyMintOperation::update");
+                let _wp = self.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 +421,7 @@
 
         let output = self
             .update_outcome(&mut outcome, {
-                let _wp = wd::watch("Operation::finish: calling IKeyMintOperation::finish");
+                let _wp = self.watch("Operation::finish: calling IKeyMintOperation::finish");
                 map_km_error(self.km_op.finish(
                     input,
                     signature,
@@ -447,7 +452,7 @@
         *locked_outcome = outcome;
 
         {
-            let _wp = wd::watch("Operation::abort: calling IKeyMintOperation::abort");
+            let _wp = self.watch("Operation::abort: calling IKeyMintOperation::abort");
             map_km_error(self.km_op.abort()).context(ks_err!("KeyMint::abort failed."))
         }
     }