Implement keystore2 logging of key operation events.

This CL implements logging of key operation events via statsd.

Bug: 172013262
Test: to be tested with test drive script.

Change-Id: I2c9ff8012ff7c5bd68f76b20ad59484cc8d594da
diff --git a/keystore2/src/metrics.rs b/keystore2/src/metrics.rs
index 04ad893..9524cb2 100644
--- a/keystore2/src/metrics.rs
+++ b/keystore2/src/metrics.rs
@@ -15,6 +15,7 @@
 //! This module provides convenience functions for keystore2 logging.
 use crate::error::get_error_code;
 use crate::key_parameter::KeyParameterValue as KsKeyParamValue;
+use crate::operation::Outcome;
 use android_hardware_security_keymint::aidl::android::hardware::security::keymint::{
     Algorithm::Algorithm, BlockMode::BlockMode, Digest::Digest, EcCurve::EcCurve,
     HardwareAuthenticatorType::HardwareAuthenticatorType, KeyOrigin::KeyOrigin,
@@ -25,6 +26,10 @@
     Keystore2KeyCreationEventReported, UserAuthType as StatsdUserAuthType,
 };
 
+use statslog_rust::keystore2_key_operation_event_reported::{
+    Keystore2KeyOperationEventReported, Outcome as StatsdOutcome, Purpose as StatsdKeyPurpose,
+};
+
 fn create_default_key_creation_atom() -> Keystore2KeyCreationEventReported {
     // If a value is not present, fields represented by bitmaps and i32 fields
     // will take 0, except error_code which defaults to 1 indicating NO_ERROR and key_size,
@@ -50,18 +55,52 @@
     }
 }
 
-/// Log key events via statsd API.
+fn create_default_key_operation_atom() -> Keystore2KeyOperationEventReported {
+    Keystore2KeyOperationEventReported {
+        purpose: StatsdKeyPurpose::KeyPurposeUnspecified,
+        padding_mode_bitmap: 0,
+        digest_bitmap: 0,
+        block_mode_bitmap: 0,
+        outcome: StatsdOutcome::OutcomeUnspecified,
+        error_code: 1,
+        key_upgraded: false,
+    }
+}
+
+/// Log key creation events via statsd API.
 pub fn log_key_creation_event_stats<U>(key_params: &[KeyParameter], result: &anyhow::Result<U>) {
     let key_creation_event_stats = construct_key_creation_event_stats(key_params, result);
 
     let logging_result = key_creation_event_stats.stats_write();
 
     if let Err(e) = logging_result {
-        log::error!("In log_key_event_stats. Error in logging key event. {:?}", e);
+        log::error!(
+            "In log_key_creation_event_stats. Error in logging key creation event. {:?}",
+            e
+        );
     }
 }
 
-// Given key parameters, event_type and result, populate the information in Keystore2KeyEventAtom.
+/// Log key operation events via statsd API.
+pub fn log_key_operation_event_stats(
+    key_purpose: KeyPurpose,
+    op_params: &[KeyParameter],
+    op_outcome: &Outcome,
+    key_upgraded: bool,
+) {
+    let key_operation_event_stats =
+        construct_key_operation_event_stats(key_purpose, op_params, op_outcome, key_upgraded);
+
+    let logging_result = key_operation_event_stats.stats_write();
+
+    if let Err(e) = logging_result {
+        log::error!(
+            "In log_key_operation_event_stats. Error in logging key operation event. {:?}",
+            e
+        );
+    }
+}
+
 fn construct_key_creation_event_stats<U>(
     key_params: &[KeyParameter],
     result: &anyhow::Result<U>,
@@ -143,6 +182,59 @@
     key_creation_event_atom
 }
 
+fn construct_key_operation_event_stats(
+    key_purpose: KeyPurpose,
+    op_params: &[KeyParameter],
+    op_outcome: &Outcome,
+    key_upgraded: bool,
+) -> Keystore2KeyOperationEventReported {
+    let mut key_operation_event_atom = create_default_key_operation_atom();
+
+    key_operation_event_atom.key_upgraded = key_upgraded;
+
+    key_operation_event_atom.purpose = match key_purpose {
+        KeyPurpose::ENCRYPT => StatsdKeyPurpose::Encrypt,
+        KeyPurpose::DECRYPT => StatsdKeyPurpose::Decrypt,
+        KeyPurpose::SIGN => StatsdKeyPurpose::Sign,
+        KeyPurpose::VERIFY => StatsdKeyPurpose::Verify,
+        KeyPurpose::WRAP_KEY => StatsdKeyPurpose::WrapKey,
+        KeyPurpose::AGREE_KEY => StatsdKeyPurpose::AgreeKey,
+        KeyPurpose::ATTEST_KEY => StatsdKeyPurpose::AttestKey,
+        _ => StatsdKeyPurpose::KeyPurposeUnspecified,
+    };
+
+    key_operation_event_atom.outcome = match op_outcome {
+        Outcome::Unknown | Outcome::Dropped => StatsdOutcome::Dropped,
+        Outcome::Success => StatsdOutcome::Success,
+        Outcome::Abort => StatsdOutcome::Abort,
+        Outcome::Pruned => StatsdOutcome::Pruned,
+        Outcome::ErrorCode(e) => {
+            key_operation_event_atom.error_code = e.0;
+            StatsdOutcome::Error
+        }
+    };
+
+    for key_param in op_params.iter().map(KsKeyParamValue::from) {
+        match key_param {
+            KsKeyParamValue::PaddingMode(p) => {
+                key_operation_event_atom.padding_mode_bitmap =
+                    compute_padding_mode_bitmap(&key_operation_event_atom.padding_mode_bitmap, p);
+            }
+            KsKeyParamValue::Digest(d) => {
+                key_operation_event_atom.digest_bitmap =
+                    compute_digest_bitmap(&key_operation_event_atom.digest_bitmap, d);
+            }
+            KsKeyParamValue::BlockMode(b) => {
+                key_operation_event_atom.block_mode_bitmap =
+                    compute_block_mode_bitmap(&key_operation_event_atom.block_mode_bitmap, b);
+            }
+            _ => {}
+        }
+    }
+
+    key_operation_event_atom
+}
+
 fn compute_purpose_bitmap(purpose_bitmap: &i32, purpose: KeyPurpose) -> i32 {
     let mut bitmap = *purpose_bitmap;
     match purpose {
diff --git a/keystore2/src/operation.rs b/keystore2/src/operation.rs
index 0f5bcaf..f71577b 100644
--- a/keystore2/src/operation.rs
+++ b/keystore2/src/operation.rs
@@ -127,9 +127,10 @@
 
 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 android_hardware_security_keymint::aidl::android::hardware::security::keymint::{
-    IKeyMintOperation::IKeyMintOperation,
+    IKeyMintOperation::IKeyMintOperation, KeyParameter::KeyParameter, KeyPurpose::KeyPurpose,
 };
 use android_system_keystore2::aidl::android::system::keystore2::{
     IKeystoreOperation::BnKeystoreOperation, IKeystoreOperation::IKeystoreOperation,
@@ -147,12 +148,18 @@
 /// to one of the other variants exactly once. The distinction in outcome is mainly
 /// for the statistic.
 #[derive(Debug, Copy, Clone, Eq, PartialEq, Ord, PartialOrd)]
-enum Outcome {
+pub enum Outcome {
+    /// Operations have `Outcome::Unknown` as long as they are active.
     Unknown,
+    /// Operation is successful.
     Success,
+    /// Operation is aborted.
     Abort,
+    /// Operation is dropped.
     Dropped,
+    /// Operation is pruned.
     Pruned,
+    /// Operation is failed with the error code.
     ErrorCode(ErrorCode),
 }
 
@@ -168,6 +175,26 @@
     owner: u32, // Uid of the operation's owner.
     auth_info: Mutex<AuthInfo>,
     forced: bool,
+    logging_info: LoggingInfo,
+}
+
+/// Keeps track of the information required for logging operations.
+#[derive(Debug)]
+pub struct LoggingInfo {
+    purpose: KeyPurpose,
+    op_params: Vec<KeyParameter>,
+    key_upgraded: bool,
+}
+
+impl LoggingInfo {
+    /// Constructor
+    pub fn new(
+        purpose: KeyPurpose,
+        op_params: Vec<KeyParameter>,
+        key_upgraded: bool,
+    ) -> LoggingInfo {
+        Self { purpose, op_params, key_upgraded }
+    }
 }
 
 struct PruningInfo {
@@ -188,6 +215,7 @@
         owner: u32,
         auth_info: AuthInfo,
         forced: bool,
+        logging_info: LoggingInfo,
     ) -> Self {
         Self {
             index,
@@ -197,6 +225,7 @@
             owner,
             auth_info: Mutex::new(auth_info),
             forced,
+            logging_info,
         }
     }
 
@@ -437,7 +466,15 @@
 
 impl Drop for Operation {
     fn drop(&mut self) {
-        if let Ok(Outcome::Unknown) = self.outcome.get_mut() {
+        let guard = self.outcome.lock().expect("In drop.");
+        log_key_operation_event_stats(
+            self.logging_info.purpose,
+            &(self.logging_info.op_params),
+            &guard,
+            self.logging_info.key_upgraded,
+        );
+        if let Outcome::Unknown = *guard {
+            drop(guard);
             // If the operation was still active we call abort, setting
             // the outcome to `Outcome::Dropped`
             if let Err(e) = self.abort(Outcome::Dropped) {
@@ -471,6 +508,7 @@
         owner: u32,
         auth_info: AuthInfo,
         forced: bool,
+        logging_info: LoggingInfo,
     ) -> Arc<Operation> {
         // We use unwrap because we don't allow code that can panic while locked.
         let mut operations = self.operations.lock().expect("In create_operation.");
@@ -483,13 +521,26 @@
             s.upgrade().is_none()
         }) {
             Some(free_slot) => {
-                let new_op = Arc::new(Operation::new(index - 1, km_op, owner, auth_info, forced));
+                let new_op = Arc::new(Operation::new(
+                    index - 1,
+                    km_op,
+                    owner,
+                    auth_info,
+                    forced,
+                    logging_info,
+                ));
                 *free_slot = Arc::downgrade(&new_op);
                 new_op
             }
             None => {
-                let new_op =
-                    Arc::new(Operation::new(operations.len(), km_op, owner, auth_info, forced));
+                let new_op = Arc::new(Operation::new(
+                    operations.len(),
+                    km_op,
+                    owner,
+                    auth_info,
+                    forced,
+                    logging_info,
+                ));
                 operations.push(Arc::downgrade(&new_op));
                 new_op
             }
diff --git a/keystore2/src/security_level.rs b/keystore2/src/security_level.rs
index 1de39e6..4636906 100644
--- a/keystore2/src/security_level.rs
+++ b/keystore2/src/security_level.rs
@@ -50,6 +50,7 @@
         KeyMetaEntry, KeyType, SubComponentType, Uuid,
     },
     operation::KeystoreOperation,
+    operation::LoggingInfo,
     operation::OperationDb,
     permission::KeyPerm,
 };
@@ -322,9 +323,12 @@
 
         let operation_challenge = auth_info.finalize_create_authorization(begin_result.challenge);
 
+        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)
+                self.operation_db.create_operation(km_op, caller_uid, auth_info, forced,
+                    LoggingInfo::new(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."),
         };