keystore2: add more logging
Also remove benign logging when there are multiple strong
biometrics.
Test: adb logcat on CF while adding/removing user/pwd
Change-Id: I777404d566990a4a604554133c0d87abba2200bc
diff --git a/keystore2/src/maintenance.rs b/keystore2/src/maintenance.rs
index 8c9ed63..59f5d70 100644
--- a/keystore2/src/maintenance.rs
+++ b/keystore2/src/maintenance.rs
@@ -279,21 +279,29 @@
impl IKeystoreMaintenance for Maintenance {
fn onUserPasswordChanged(&self, user_id: i32, password: Option<&[u8]>) -> BinderResult<()> {
+ log::info!(
+ "onUserPasswordChanged(user={}, password.is_some()={})",
+ user_id,
+ password.is_some()
+ );
let _wp = wd::watch_millis("IKeystoreMaintenance::onUserPasswordChanged", 500);
map_or_log_err(Self::on_user_password_changed(user_id, password.map(|pw| pw.into())), Ok)
}
fn onUserAdded(&self, user_id: i32) -> BinderResult<()> {
+ log::info!("onUserAdded(user={user_id})");
let _wp = wd::watch_millis("IKeystoreMaintenance::onUserAdded", 500);
map_or_log_err(self.add_or_remove_user(user_id), Ok)
}
fn onUserRemoved(&self, user_id: i32) -> BinderResult<()> {
+ log::info!("onUserRemoved(user={user_id})");
let _wp = wd::watch_millis("IKeystoreMaintenance::onUserRemoved", 500);
map_or_log_err(self.add_or_remove_user(user_id), Ok)
}
fn clearNamespace(&self, domain: Domain, nspace: i64) -> BinderResult<()> {
+ log::info!("clearNamespace({domain:?}, nspace={nspace})");
let _wp = wd::watch_millis("IKeystoreMaintenance::clearNamespace", 500);
map_or_log_err(self.clear_namespace(domain, nspace), Ok)
}
@@ -304,11 +312,13 @@
}
fn earlyBootEnded(&self) -> BinderResult<()> {
+ log::info!("earlyBootEnded()");
let _wp = wd::watch_millis("IKeystoreMaintenance::earlyBootEnded", 500);
map_or_log_err(Self::early_boot_ended(), Ok)
}
fn onDeviceOffBody(&self) -> BinderResult<()> {
+ log::info!("onDeviceOffBody()");
let _wp = wd::watch_millis("IKeystoreMaintenance::onDeviceOffBody", 500);
map_or_log_err(Self::on_device_off_body(), Ok)
}
@@ -318,11 +328,13 @@
source: &KeyDescriptor,
destination: &KeyDescriptor,
) -> BinderResult<()> {
+ log::info!("migrateKeyNamespace(src={source:?}, dest={destination:?})");
let _wp = wd::watch_millis("IKeystoreMaintenance::migrateKeyNamespace", 500);
map_or_log_err(Self::migrate_key_namespace(source, destination), Ok)
}
fn deleteAllKeys(&self) -> BinderResult<()> {
+ log::warn!("deleteAllKeys()");
let _wp = wd::watch_millis("IKeystoreMaintenance::deleteAllKeys", 500);
map_or_log_err(Self::delete_all_keys(), Ok)
}
diff --git a/keystore2/src/super_key.rs b/keystore2/src/super_key.rs
index 7fc3ed4..5ee4f17 100644
--- a/keystore2/src/super_key.rs
+++ b/keystore2/src/super_key.rs
@@ -644,17 +644,17 @@
// super key is not unlocked or the LSKF is not setup, an error is returned.
match self
.get_user_state(db, legacy_importer, user_id)
- .context(ks_err!("Failed to get user state."))?
+ .context(ks_err!("Failed to get user state for user {user_id}"))?
{
- UserState::LskfUnlocked(super_key) => {
- Self::encrypt_with_aes_super_key(key_blob, &super_key)
- .context(ks_err!("Failed to encrypt with LskfBound key."))
- }
+ UserState::LskfUnlocked(super_key) => Self::encrypt_with_aes_super_key(
+ key_blob, &super_key,
+ )
+ .context(ks_err!("Failed to encrypt with LskfBound key for user {user_id}")),
UserState::LskfLocked => {
Err(Error::Rc(ResponseCode::LOCKED)).context(ks_err!("Device is locked."))
}
UserState::Uninitialized => Err(Error::Rc(ResponseCode::UNINITIALIZED))
- .context(ks_err!("LSKF is not setup for the user.")),
+ .context(ks_err!("LSKF is not setup for user {user_id}")),
}
}
SuperEncryptionType::ScreenLockBound => {
@@ -912,9 +912,11 @@
.context(ks_err!("load_key_entry failed"))?;
let km_dev: KeyMintDevice = KeyMintDevice::get(SecurityLevel::TRUSTED_ENVIRONMENT)
.context(ks_err!("KeyMintDevice::get failed"))?;
+ let mut errs = vec![];
for sid in &biometric.sids {
+ let sid = *sid;
if let Some((auth_token_entry, _)) = db.find_auth_token_entry(|entry| {
- entry.auth_token().userId == *sid || entry.auth_token().authenticatorId == *sid
+ entry.auth_token().userId == sid || entry.auth_token().authenticatorId == sid
}) {
let res: Result<(Arc<SuperKey>, Arc<SuperKey>)> = (|| {
let slb = biometric.screen_lock_bound.decrypt(
@@ -941,15 +943,22 @@
entry.screen_lock_bound_private = Some(slbp.clone());
self.data.add_key_to_key_index(&slb)?;
self.data.add_key_to_key_index(&slbp)?;
- log::info!("Successfully unlocked with biometric");
+ log::info!("Successfully unlocked user {user_id} with biometric {sid}",);
return Ok(());
}
Err(e) => {
- log::warn!("attempt failed: {:?}", e)
+ // Don't log an error yet, as some other biometric SID might work.
+ errs.push((sid, e));
}
}
}
}
+ if !errs.is_empty() {
+ log::warn!("biometric unlock failed for all SIDs, with errors:");
+ for (sid, err) in errs {
+ log::warn!(" biometric {sid}: {err}");
+ }
+ }
}
Ok(())
}
@@ -988,6 +997,7 @@
legacy_importer: &LegacyImporter,
user_id: UserId,
) -> Result<()> {
+ log::info!("remove_user(user={user_id})");
// Mark keys created on behalf of the user as unreferenced.
legacy_importer
.bulk_delete_user(user_id, false)
@@ -1008,6 +1018,7 @@
legacy_importer: &LegacyImporter,
user_id: UserId,
) -> Result<()> {
+ log::info!("reset_user(user={user_id})");
match self.get_user_state(db, legacy_importer, user_id)? {
UserState::Uninitialized => {
Err(Error::sys()).context(ks_err!("Tried to reset an uninitialized user!"))
@@ -1039,6 +1050,7 @@
user_id: UserId,
password: &Password,
) -> Result<()> {
+ log::info!("init_user(user={user_id})");
match self.get_user_state(db, legacy_importer, user_id)? {
UserState::LskfUnlocked(_) | UserState::LskfLocked => {
Err(Error::sys()).context(ks_err!("Tried to re-init an initialized user!"))
@@ -1091,6 +1103,7 @@
user_id: UserId,
password: &Password,
) -> Result<()> {
+ log::info!("unlock_user(user={user_id})");
match self.get_user_state(db, legacy_importer, user_id)? {
UserState::LskfUnlocked(_) => self.unlock_screen_lock_bound_key(db, user_id, password),
UserState::Uninitialized => {