Add debugging info for transactions
Pass around information about which code is performing an exclusive
database transaction, and run an additional watchdog inside the
transaction closure.
Bug: 319563050
Test: CtsKeystoreTestCases
Change-Id: Ib54f1f4c0c37f9d7392d21d9ccb880d066029945
diff --git a/keystore2/src/database.rs b/keystore2/src/database.rs
index 8f14cb0..50cd3ba 100644
--- a/keystore2/src/database.rs
+++ b/keystore2/src/database.rs
@@ -82,7 +82,7 @@
types::FromSqlResult,
types::ToSqlOutput,
types::{FromSqlError, Value, ValueRef},
- Connection, OptionalExtension, ToSql, Transaction, TransactionBehavior,
+ Connection, OptionalExtension, ToSql, Transaction,
};
use std::{
@@ -92,9 +92,37 @@
time::{Duration, SystemTime},
};
+use TransactionBehavior::Immediate;
+
#[cfg(test)]
use tests::random;
+/// Wrapper for `rusqlite::TransactionBehavior` which includes information about the transaction
+/// being performed.
+#[derive(Clone, Copy)]
+enum TransactionBehavior {
+ Deferred,
+ Immediate(&'static str),
+}
+
+impl From<TransactionBehavior> for rusqlite::TransactionBehavior {
+ fn from(val: TransactionBehavior) -> Self {
+ match val {
+ TransactionBehavior::Deferred => rusqlite::TransactionBehavior::Deferred,
+ TransactionBehavior::Immediate(_) => rusqlite::TransactionBehavior::Immediate,
+ }
+ }
+}
+
+impl TransactionBehavior {
+ fn name(&self) -> Option<&'static str> {
+ match self {
+ TransactionBehavior::Deferred => None,
+ TransactionBehavior::Immediate(v) => Some(v),
+ }
+ }
+}
+
/// 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.
@@ -863,7 +891,7 @@
let conn = Self::make_connection(&persistent_path)?;
let mut db = Self { conn, gc, perboot: perboot::PERBOOT_DB.clone() };
- db.with_transaction(TransactionBehavior::Immediate, |tx| {
+ db.with_transaction(Immediate("TX_new"), |tx| {
versioning::upgrade_database(tx, Self::CURRENT_DB_VERSION, Self::UPGRADERS)
.context(ks_err!("KeystoreDB::new: trying to upgrade database."))?;
Self::init_tables(tx).context("Trying to initialize tables.").no_gc()
@@ -1156,7 +1184,7 @@
max_blobs: usize,
) -> Result<Vec<(i64, Vec<u8>, BlobMetaData)>> {
let _wp = wd::watch("KeystoreDB::handle_next_superseded_blob");
- self.with_transaction(TransactionBehavior::Immediate, |tx| {
+ self.with_transaction(Immediate("TX_handle_next_superseded_blob"), |tx| {
// Delete the given blobs.
for blob_id in blob_ids_to_delete {
tx.execute(
@@ -1245,7 +1273,7 @@
pub fn cleanup_leftovers(&mut self) -> Result<usize> {
let _wp = wd::watch("KeystoreDB::cleanup_leftovers");
- self.with_transaction(TransactionBehavior::Immediate, |tx| {
+ self.with_transaction(Immediate("TX_cleanup_leftovers"), |tx| {
tx.execute(
"UPDATE persistent.keyentry SET state = ? WHERE state = ?;",
params![KeyLifeCycle::Unreferenced, KeyLifeCycle::Existing],
@@ -1266,7 +1294,7 @@
) -> Result<bool> {
let _wp = wd::watch("KeystoreDB::key_exists");
- self.with_transaction(TransactionBehavior::Immediate, |tx| {
+ self.with_transaction(Immediate("TX_key_exists"), |tx| {
let key_descriptor =
KeyDescriptor { domain, nspace, alias: Some(alias.to_string()), blob: None };
let result = Self::load_key_entry_id(tx, &key_descriptor, key_type);
@@ -1293,7 +1321,7 @@
) -> Result<KeyEntry> {
let _wp = wd::watch("KeystoreDB::store_super_key");
- self.with_transaction(TransactionBehavior::Immediate, |tx| {
+ self.with_transaction(Immediate("TX_store_super_key"), |tx| {
let key_id = Self::insert_with_retry(|id| {
tx.execute(
"INSERT into persistent.keyentry
@@ -1338,7 +1366,7 @@
) -> Result<Option<(KeyIdGuard, KeyEntry)>> {
let _wp = wd::watch("KeystoreDB::load_super_key");
- self.with_transaction(TransactionBehavior::Immediate, |tx| {
+ self.with_transaction(Immediate("TX_load_super_key"), |tx| {
let key_descriptor = KeyDescriptor {
domain: Domain::APP,
nspace: user_id as i64,
@@ -1381,12 +1409,16 @@
F: Fn(&Transaction) -> Result<(bool, T)>,
{
let start = std::time::Instant::now();
+ let name = behavior.name();
loop {
let result = self
.conn
- .transaction_with_behavior(behavior)
+ .transaction_with_behavior(behavior.into())
.context(ks_err!())
- .and_then(|tx| f(&tx).map(|result| (result, tx)))
+ .and_then(|tx| {
+ let _wp = name.map(wd::watch);
+ f(&tx).map(|result| (result, tx))
+ })
.and_then(|(result, tx)| {
tx.commit().context(ks_err!("Failed to commit transaction."))?;
Ok(result)
@@ -1472,7 +1504,7 @@
) -> Result<()> {
let _wp = wd::watch("KeystoreDB::set_blob");
- self.with_transaction(TransactionBehavior::Immediate, |tx| {
+ self.with_transaction(Immediate("TX_set_blob"), |tx| {
Self::set_blob_internal(tx, key_id.0, sc_type, blob, blob_metadata).need_gc()
})
.context(ks_err!())
@@ -1485,7 +1517,7 @@
pub fn set_deleted_blob(&mut self, blob: &[u8], blob_metadata: &BlobMetaData) -> Result<()> {
let _wp = wd::watch("KeystoreDB::set_deleted_blob");
- self.with_transaction(TransactionBehavior::Immediate, |tx| {
+ self.with_transaction(Immediate("TX_set_deleted_blob"), |tx| {
Self::set_blob_internal(
tx,
Self::UNASSIGNED_KEY_ID,
@@ -1544,7 +1576,7 @@
/// and associates them with the given `key_id`.
#[cfg(test)]
fn insert_keyparameter(&mut self, key_id: &KeyIdGuard, params: &[KeyParameter]) -> Result<()> {
- self.with_transaction(TransactionBehavior::Immediate, |tx| {
+ self.with_transaction(Immediate("TX_insert_keyparameter"), |tx| {
Self::insert_keyparameter_internal(tx, key_id, params).no_gc()
})
.context(ks_err!())
@@ -1577,7 +1609,7 @@
/// Insert a set of key entry specific metadata into the database.
#[cfg(test)]
fn insert_key_metadata(&mut self, key_id: &KeyIdGuard, metadata: &KeyMetaData) -> Result<()> {
- self.with_transaction(TransactionBehavior::Immediate, |tx| {
+ self.with_transaction(Immediate("TX_insert_key_metadata"), |tx| {
metadata.store_in_db(key_id.0, tx).no_gc()
})
.context(ks_err!())
@@ -1665,7 +1697,7 @@
.ok_or(KsError::Rc(ResponseCode::INVALID_ARGUMENT))
.context(ks_err!("Alias must be specified."))?;
- self.with_transaction(TransactionBehavior::Immediate, |tx| {
+ self.with_transaction(Immediate("TX_migrate_key_namespace"), |tx| {
// Query the destination location. If there is a key, the migration request fails.
if tx
.query_row(
@@ -1728,7 +1760,7 @@
.context(ks_err!("Need alias and domain must be APP or SELINUX."));
}
};
- self.with_transaction(TransactionBehavior::Immediate, |tx| {
+ self.with_transaction(Immediate("TX_store_new_key"), |tx| {
let key_id = Self::create_key_entry_internal(tx, &domain, namespace, key_type, km_uuid)
.context("Trying to create new key entry.")?;
let BlobInfo { blob, metadata: blob_metadata, superseded_blob } = *blob_info;
@@ -1807,7 +1839,7 @@
.context(ks_err!("Need alias and domain must be APP or SELINUX."));
}
};
- self.with_transaction(TransactionBehavior::Immediate, |tx| {
+ self.with_transaction(Immediate("TX_store_new_certificate"), |tx| {
let key_id = Self::create_key_entry_internal(tx, &domain, namespace, key_type, km_uuid)
.context("Trying to create new key entry.")?;
@@ -2077,7 +2109,7 @@
pub fn check_and_update_key_usage_count(&mut self, key_id: i64) -> Result<()> {
let _wp = wd::watch("KeystoreDB::check_and_update_key_usage_count");
- self.with_transaction(TransactionBehavior::Immediate, |tx| {
+ self.with_transaction(Immediate("TX_check_and_update_key_usage_count"), |tx| {
let limit: Option<i32> = tx
.query_row(
"SELECT data FROM persistent.keyparameter WHERE keyentryid = ? AND tag = ?;",
@@ -2255,7 +2287,7 @@
) -> Result<()> {
let _wp = wd::watch("KeystoreDB::unbind_key");
- self.with_transaction(TransactionBehavior::Immediate, |tx| {
+ self.with_transaction(Immediate("TX_unbind_key"), |tx| {
let (key_id, access_key_descriptor, access_vector) =
Self::load_access_tuple(tx, key, key_type, caller_uid)
.context("Trying to get access tuple.")?;
@@ -2289,7 +2321,7 @@
if !(domain == Domain::APP || domain == Domain::SELINUX) {
return Err(KsError::Rc(ResponseCode::INVALID_ARGUMENT)).context(ks_err!());
}
- self.with_transaction(TransactionBehavior::Immediate, |tx| {
+ self.with_transaction(Immediate("TX_unbind_keys_for_namespace"), |tx| {
tx.execute(
"DELETE FROM persistent.keymetadata
WHERE keyentryid IN (
@@ -2380,7 +2412,7 @@
) -> Result<()> {
let _wp = wd::watch("KeystoreDB::unbind_keys_for_user");
- self.with_transaction(TransactionBehavior::Immediate, |tx| {
+ self.with_transaction(Immediate("TX_unbind_keys_for_user"), |tx| {
let mut stmt = tx
.prepare(&format!(
"SELECT id from persistent.keyentry
@@ -2457,7 +2489,7 @@
pub fn unbind_auth_bound_keys_for_user(&mut self, user_id: u32) -> Result<()> {
let _wp = wd::watch("KeystoreDB::unbind_auth_bound_keys_for_user");
- self.with_transaction(TransactionBehavior::Immediate, |tx| {
+ self.with_transaction(Immediate("TX_unbind_auth_bound_keys_for_user"), |tx| {
let mut stmt = tx
.prepare(&format!(
"SELECT id from persistent.keyentry
@@ -2640,7 +2672,7 @@
) -> Result<KeyDescriptor> {
let _wp = wd::watch("KeystoreDB::grant");
- self.with_transaction(TransactionBehavior::Immediate, |tx| {
+ self.with_transaction(Immediate("TX_grant"), |tx| {
// Load the key_id and complete the access control tuple.
// We ignore the access vector here because grants cannot be granted.
// The access vector returned here expresses the permissions the
@@ -2706,7 +2738,7 @@
) -> Result<()> {
let _wp = wd::watch("KeystoreDB::ungrant");
- self.with_transaction(TransactionBehavior::Immediate, |tx| {
+ self.with_transaction(Immediate("TX_ungrant"), |tx| {
// Load the key_id and complete the access control tuple.
// We ignore the access vector here because grants cannot be granted.
let (key_id, access_key_descriptor, _) =
@@ -2803,7 +2835,7 @@
) -> Result<Vec<i64>> {
let _wp = wd::watch("KeystoreDB::get_app_uids_affected_by_sid");
- let key_ids_and_app_uids = self.with_transaction(TransactionBehavior::Immediate, |tx| {
+ let ids = self.with_transaction(Immediate("TX_get_app_uids_affected_by_sid"), |tx| {
let mut stmt = tx
.prepare(&format!(
"SELECT id, namespace from persistent.keyentry
@@ -2832,13 +2864,13 @@
Ok(key_ids_and_app_uids).no_gc()
})?;
let mut app_uids_affected_by_sid: HashSet<i64> = Default::default();
- for (key_id, app_uid) in key_ids_and_app_uids {
+ for (key_id, app_uid) in ids {
// Read the key parameters for each key in its own transaction. It is OK to ignore
// an error to get the properties of a particular key since it might have been deleted
// under our feet after the previous transaction concluded. If the key was deleted
// then it is no longer applicable if it was auth-bound or not.
if let Ok(is_key_bound_to_sid) =
- self.with_transaction(TransactionBehavior::Immediate, |tx| {
+ self.with_transaction(Immediate("TX_get_app_uids_affects_by_sid 2"), |tx| {
let params = Self::load_key_parameters(key_id, tx)
.context("Failed to load key parameters.")?;
// Check if the key is bound to this secure user ID.
@@ -2881,7 +2913,6 @@
use android_hardware_security_secureclock::aidl::android::hardware::security::secureclock::{
Timestamp::Timestamp,
};
- use rusqlite::TransactionBehavior;
use std::cell::RefCell;
use std::collections::BTreeMap;
use std::fmt::Write;
@@ -2897,7 +2928,7 @@
let conn = KeystoreDB::make_connection("file::memory:")?;
let mut db = KeystoreDB { conn, gc: None, perboot: Arc::new(perboot::PerbootDB::new()) };
- db.with_transaction(TransactionBehavior::Immediate, |tx| {
+ db.with_transaction(Immediate("TX_new_test_db"), |tx| {
KeystoreDB::init_tables(tx).context("Failed to initialize tables.").no_gc()
})?;
Ok(db)
@@ -2910,7 +2941,7 @@
domain: Domain,
namespace: i64,
) -> Result<bool> {
- db.with_transaction(TransactionBehavior::Immediate, |tx| {
+ db.with_transaction(Immediate("TX_rebind_alias"), |tx| {
KeystoreDB::rebind_alias(tx, newid, alias, &domain, &namespace, KeyType::Client).no_gc()
})
.context(ks_err!())
@@ -3037,7 +3068,7 @@
key_type: KeyType,
km_uuid: &Uuid,
) -> Result<KeyIdGuard> {
- db.with_transaction(TransactionBehavior::Immediate, |tx| {
+ db.with_transaction(Immediate("TX_create_key_entry"), |tx| {
KeystoreDB::create_key_entry_internal(tx, domain, namespace, key_type, km_uuid).no_gc()
})
}
@@ -3352,7 +3383,7 @@
drop(stmt);
assert_eq!(
- db.with_transaction(TransactionBehavior::Immediate, |tx| {
+ db.with_transaction(Immediate("TX_test"), |tx| {
BlobMetaData::load_from_db(id, tx).no_gc()
})
.expect("Should find blob metadata."),
@@ -4027,10 +4058,8 @@
.unwrap();
assert_eq!(key_entry, make_bootlevel_test_key_entry_test_vector(key_id_deleted, true));
- db.with_transaction(TransactionBehavior::Immediate, |tx| {
- KeystoreDB::from_0_to_1(tx).no_gc()
- })
- .unwrap();
+ db.with_transaction(Immediate("TX_test"), |tx| KeystoreDB::from_0_to_1(tx).no_gc())
+ .unwrap();
let (_, key_entry) = db
.load_key_entry(
@@ -4183,12 +4212,12 @@
let _tx1 = db1
.conn
- .transaction_with_behavior(TransactionBehavior::Immediate)
+ .transaction_with_behavior(rusqlite::TransactionBehavior::Immediate)
.expect("Failed to create first transaction.");
let error = db2
.conn
- .transaction_with_behavior(TransactionBehavior::Immediate)
+ .transaction_with_behavior(rusqlite::TransactionBehavior::Immediate)
.context("Transaction begin failed.")
.expect_err("This should fail.");
let root_cause = error.root_cause();
@@ -5527,10 +5556,8 @@
// 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(
- TransactionBehavior::Immediate,
- Duration::from_secs(3),
- |_tx| {
+ 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
@@ -5539,8 +5566,7 @@
let _guard = KEY_ID_LOCK.get(key_id);
Ok(()).no_gc()
- },
- );
+ });
});
// Second thread gets the `KeyIdGuard`, then waits before trying to perform an immediate
@@ -5559,11 +5585,10 @@
// this thread also tries to do one.
b_receiver.recv().unwrap();
- let result = db.with_transaction_timeout(
- TransactionBehavior::Immediate,
- Duration::from_secs(3),
- |_tx| Ok(()).no_gc(),
- );
+ 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());