Add trace logging on method calls and exit

That would allow to make sure that Parsec is indeed useful :)

Signed-off-by: Hugues de Valon <hugues.devalon@arm.com>

Author: hug-dev

src/back/backend_handler.rs

@@ -8,6 +8,7 @@
 use crate::authenticators::ApplicationName;
 use crate::providers::Provide;
 use derivative::Derivative;
+use log::trace;
 use parsec_interface::operations::Convert;
 use parsec_interface::operations::{NativeOperation, NativeResult};
 use parsec_interface::requests::{
@@ -78,6 +79,7 @@ impl BackEndHandler {
     /// If any of the steps fails, a response containing an appropriate status code is
     /// returned.
     pub fn execute_request(&self, request: Request, app_name: Option<ApplicationName>) -> Response {
+        trace!("execute_request ingress");
         let opcode = request.header.opcode;
         let header = request.header;
 
@@ -94,14 +96,17 @@ impl BackEndHandler {
             NativeOperation::ListProviders(op_list_providers) => {
                 let result =
                     unwrap_or_else_return!(self.provider.list_providers(op_list_providers));
+                trace!("list_providers egress");
                 self.result_to_response(NativeResult::ListProviders(result), header)
             }
             NativeOperation::ListOpcodes(op_list_opcodes) => {
                 let result = unwrap_or_else_return!(self.provider.list_opcodes(op_list_opcodes));
+                trace!("list_opcodes egress");
                 self.result_to_response(NativeResult::ListOpcodes(result), header)
             }
             NativeOperation::Ping(op_ping) => {
                 let result = unwrap_or_else_return!(self.provider.ping(op_ping));
+                trace!("ping egress");
                 self.result_to_response(NativeResult::Ping(result), header)
             }
             NativeOperation::PsaGenerateKey(op_generate_key) => {
@@ -110,13 +115,15 @@ impl BackEndHandler {
                 let result = unwrap_or_else_return!(self
                     .provider
                     .psa_generate_key(app_name, op_generate_key));
+                trace!("psa_generate_key egress");
                 self.result_to_response(NativeResult::PsaGenerateKey(result), header)
             }
             NativeOperation::PsaImportKey(op_import_key) => {
                 let app_name =
                     unwrap_or_else_return!(app_name.ok_or(ResponseStatus::NotAuthenticated));
                 let result =
                     unwrap_or_else_return!(self.provider.psa_import_key(app_name, op_import_key));
+                trace!("psa_import_key egress");
                 self.result_to_response(NativeResult::PsaImportKey(result), header)
             }
             NativeOperation::PsaExportPublicKey(op_export_public_key) => {
@@ -125,27 +132,31 @@ impl BackEndHandler {
                 let result = unwrap_or_else_return!(self
                     .provider
                     .psa_export_public_key(app_name, op_export_public_key));
+                trace!("psa_export_public_key egress");
                 self.result_to_response(NativeResult::PsaExportPublicKey(result), header)
             }
             NativeOperation::PsaDestroyKey(op_destroy_key) => {
                 let app_name =
                     unwrap_or_else_return!(app_name.ok_or(ResponseStatus::NotAuthenticated));
                 let result =
                     unwrap_or_else_return!(self.provider.psa_destroy_key(app_name, op_destroy_key));
+                trace!("psa_destroy_key egress");
                 self.result_to_response(NativeResult::PsaDestroyKey(result), header)
             }
             NativeOperation::PsaSignHash(op_sign_hash) => {
                 let app_name =
                     unwrap_or_else_return!(app_name.ok_or(ResponseStatus::NotAuthenticated));
                 let result =
                     unwrap_or_else_return!(self.provider.psa_sign_hash(app_name, op_sign_hash));
+                trace!("psa_sign_hash egress");
                 self.result_to_response(NativeResult::PsaSignHash(result), header)
             }
             NativeOperation::PsaVerifyHash(op_verify_hash) => {
                 let app_name =
                     unwrap_or_else_return!(app_name.ok_or(ResponseStatus::NotAuthenticated));
                 let result =
                     unwrap_or_else_return!(self.provider.psa_verify_hash(app_name, op_verify_hash));
+                trace!("psa_verify_hash egress");
                 self.result_to_response(NativeResult::PsaVerifyHash(result), header)
             }
         }

src/back/dispatcher.rs

@@ -6,6 +6,7 @@
 //! said provider is available on the system, thus acting as a multiplexer.
 use super::backend_handler::BackEndHandler;
 use crate::authenticators::ApplicationName;
+use log::trace;
 use parsec_interface::requests::request::Request;
 use parsec_interface::requests::ProviderID;
 use parsec_interface::requests::{Response, ResponseStatus};
@@ -36,11 +37,16 @@ impl Dispatcher {
         request: Request,
         app_name: Option<ApplicationName>,
     ) -> Response {
+        trace!("dispatch_request ingress");
         if let Some(backend) = self.backends.get(&request.header.provider) {
             if let Err(status) = backend.is_capable(&request) {
                 Response::from_request_header(request.header, status)
             } else {
-                backend.execute_request(request, app_name)
+                {
+                    let response = backend.execute_request(request, app_name);
+                    trace!("execute_request egress");
+                    response
+                }
             }
         } else {
             Response::from_request_header(request.header, ResponseStatus::ProviderNotRegistered)

src/bin/main.rs

@@ -31,7 +31,7 @@
 // This one is hard to avoid.
 #![allow(clippy::multiple_crate_versions)]
 
-use log::info;
+use log::{info, trace};
 use parsec_service::utils::{ServiceBuilder, ServiceConfig};
 use signal_hook::{flag, SIGHUP, SIGTERM};
 use std::io::{Error, ErrorKind, Result};
@@ -129,6 +129,7 @@ fn main() -> Result<()> {
             let front_end_handler = front_end_handler.clone();
             threadpool.execute(move || {
                 front_end_handler.handle_request(stream);
+                trace!("handle_request egress");
             });
         } else {
             ::std::thread::sleep(Duration::from_millis(

src/front/front_end.rs

@@ -7,7 +7,7 @@
 use crate::authenticators::Authenticate;
 use crate::back::dispatcher::Dispatcher;
 use derivative::Derivative;
-use log::{error, info};
+use log::{error, info, trace};
 use parsec_interface::requests::AuthType;
 use parsec_interface::requests::ResponseStatus;
 use parsec_interface::requests::{Request, Response};
@@ -41,6 +41,7 @@ impl FrontEndHandler {
     /// If an error occurs during (un)marshalling, no operation will be performed and the
     /// method will return.
     pub fn handle_request<T: Read + Write>(&self, mut stream: T) {
+        trace!("handle_request ingress");
         // Read bytes from stream
         // De-Serialise bytes into a request
         let request = match Request::read_from_stream(&mut stream, self.body_len_limit) {
@@ -57,14 +58,20 @@ impl FrontEndHandler {
         };
         // Check if the request was sent without authentication
         let response = if AuthType::NoAuth == request.header.auth_type {
-            self.dispatcher.dispatch_request(request, None)
+            let response = self.dispatcher.dispatch_request(request, None);
+            trace!("dispatch_request egress");
+            response
         // Otherwise find an authenticator that is capable to authenticate the request
         } else if let Some(authenticator) = self.authenticators.get(&request.header.auth_type) {
             // Authenticate the request
             match authenticator.authenticate(&request.auth) {
                 // Send the request to the dispatcher
                 // Get a response back
-                Ok(app_name) => self.dispatcher.dispatch_request(request, Some(app_name)),
+                Ok(app_name) => {
+                    let response = self.dispatcher.dispatch_request(request, Some(app_name));
+                    trace!("dispatch_request egress");
+                    response
+                }
                 Err(status) => Response::from_request_header(request.header, status),
             }
         } else {

src/providers/core_provider/mod.rs

@@ -6,7 +6,7 @@
 //! aiding clients in discovering the capabilities offered by their underlying
 //! platform.
 use super::Provide;
-use log::error;
+use log::{error, trace};
 use parsec_interface::operations::list_providers::ProviderInfo;
 use parsec_interface::operations::{list_opcodes, list_providers, ping};
 use parsec_interface::requests::{Opcode, ProviderID, ResponseStatus, Result};
@@ -33,6 +33,7 @@ pub struct CoreProvider {
 
 impl Provide for CoreProvider {
     fn list_opcodes(&self, op: list_opcodes::Operation) -> Result<list_opcodes::Result> {
+        trace!("list_opcodes ingress");
         Ok(list_opcodes::Result {
             opcodes: self
                 .provider_opcodes
@@ -43,12 +44,14 @@ impl Provide for CoreProvider {
     }
 
     fn list_providers(&self, _op: list_providers::Operation) -> Result<list_providers::Result> {
+        trace!("list_providers ingress");
         Ok(list_providers::Result {
             providers: self.provider_info.clone(),
         })
     }
 
     fn ping(&self, _op: ping::Operation) -> Result<ping::Result> {
+        trace!("ping ingress");
         let result = ping::Result {
             wire_protocol_version_maj: self.wire_protocol_version_maj,
             wire_protocol_version_min: self.wire_protocol_version_min,

src/providers/mbed_provider/mod.rs

@@ -5,7 +5,7 @@ use crate::authenticators::ApplicationName;
 use crate::key_info_managers::{KeyTriple, ManageKeyInfo};
 use constants::PSA_SUCCESS;
 use derivative::Derivative;
-use log::error;
+use log::{error, trace};
 use parsec_interface::operations::list_providers::ProviderInfo;
 use parsec_interface::operations::{
     psa_destroy_key, psa_export_public_key, psa_generate_key, psa_import_key, psa_sign_hash,
@@ -153,6 +153,7 @@ impl MbedProvider {
 
 impl Provide for MbedProvider {
     fn describe(&self) -> Result<(ProviderInfo, HashSet<Opcode>)> {
+        trace!("describe ingress");
         Ok((ProviderInfo {
             // Assigned UUID for this provider: 1c1139dc-ad7c-47dc-ad6b-db6fdb466552
             uuid: Uuid::parse_str("1c1139dc-ad7c-47dc-ad6b-db6fdb466552").or(Err(ResponseStatus::InvalidEncoding))?,
@@ -170,6 +171,7 @@ impl Provide for MbedProvider {
         app_name: ApplicationName,
         op: psa_generate_key::Operation,
     ) -> Result<psa_generate_key::Result> {
+        trace!("psa_generate_key ingress");
         self.psa_generate_key_internal(app_name, op)
     }
 
@@ -178,6 +180,7 @@ impl Provide for MbedProvider {
         app_name: ApplicationName,
         op: psa_import_key::Operation,
     ) -> Result<psa_import_key::Result> {
+        trace!("psa_import_key ingress");
         self.psa_import_key_internal(app_name, op)
     }
 
@@ -186,6 +189,7 @@ impl Provide for MbedProvider {
         app_name: ApplicationName,
         op: psa_export_public_key::Operation,
     ) -> Result<psa_export_public_key::Result> {
+        trace!("psa_export_public_key ingress");
         self.psa_export_public_key_internal(app_name, op)
     }
 
@@ -194,6 +198,7 @@ impl Provide for MbedProvider {
         app_name: ApplicationName,
         op: psa_destroy_key::Operation,
     ) -> Result<psa_destroy_key::Result> {
+        trace!("psa_destroy_key ingress");
         self.psa_destroy_key_internal(app_name, op)
     }
 
@@ -202,6 +207,7 @@ impl Provide for MbedProvider {
         app_name: ApplicationName,
         op: psa_sign_hash::Operation,
     ) -> Result<psa_sign_hash::Result> {
+        trace!("psa_sign_hash ingress");
         self.psa_sign_hash_internal(app_name, op)
     }
 
@@ -210,6 +216,7 @@ impl Provide for MbedProvider {
         app_name: ApplicationName,
         op: psa_verify_hash::Operation,
     ) -> Result<psa_verify_hash::Result> {
+        trace!("psa_verify_hash ingress");
         self.psa_verify_hash_internal(app_name, op)
     }
 }

src/providers/mod.rs

@@ -6,6 +6,7 @@
 //! are the real implementors of the operations that Parsec claims to support. They map to
 //! functionality in the underlying hardware which allows the PSA Crypto operations to be
 //! backed by a hardware root of trust.
+use log::trace;
 use parsec_interface::requests::{Opcode, ProviderID};
 use serde::Deserialize;
 use std::collections::HashSet;
@@ -88,16 +89,19 @@ pub trait Provide {
     ///
     /// The descriptions are gathered in the Core Provider and returned for a ListProviders operation.
     fn describe(&self) -> Result<(list_providers::ProviderInfo, HashSet<Opcode>)> {
+        trace!("describe ingress");
         Err(ResponseStatus::PsaErrorNotSupported)
     }
 
     /// List the providers running in the service.
     fn list_providers(&self, _op: list_providers::Operation) -> Result<list_providers::Result> {
+        trace!("list_providers ingress");
         Err(ResponseStatus::PsaErrorNotSupported)
     }
 
     /// List the opcodes supported by the given provider.
     fn list_opcodes(&self, _op: list_opcodes::Operation) -> Result<list_opcodes::Result> {
+        trace!("list_opcodes ingress");
         Err(ResponseStatus::PsaErrorNotSupported)
     }
 
@@ -108,6 +112,7 @@ pub trait Provide {
     /// This operation will only fail if not implemented. It will never fail when being called on
     /// the `CoreProvider`.
     fn ping(&self, _op: ping::Operation) -> Result<ping::Result> {
+        trace!("ping ingress");
         Err(ResponseStatus::PsaErrorNotSupported)
     }
 
@@ -117,6 +122,7 @@ pub trait Provide {
         _app_name: ApplicationName,
         _op: psa_generate_key::Operation,
     ) -> Result<psa_generate_key::Result> {
+        trace!("psa_generate_key ingress");
         Err(ResponseStatus::PsaErrorNotSupported)
     }
 
@@ -126,6 +132,7 @@ pub trait Provide {
         _app_name: ApplicationName,
         _op: psa_import_key::Operation,
     ) -> Result<psa_import_key::Result> {
+        trace!("psa_import_key ingress");
         Err(ResponseStatus::PsaErrorNotSupported)
     }
 
@@ -135,6 +142,7 @@ pub trait Provide {
         _app_name: ApplicationName,
         _op: psa_export_public_key::Operation,
     ) -> Result<psa_export_public_key::Result> {
+        trace!("psa_export_public_key ingress");
         Err(ResponseStatus::PsaErrorNotSupported)
     }
 
@@ -144,6 +152,7 @@ pub trait Provide {
         _app_name: ApplicationName,
         _op: psa_destroy_key::Operation,
     ) -> Result<psa_destroy_key::Result> {
+        trace!("psa_destroy_key ingress");
         Err(ResponseStatus::PsaErrorNotSupported)
     }
 
@@ -154,6 +163,7 @@ pub trait Provide {
         _app_name: ApplicationName,
         _op: psa_sign_hash::Operation,
     ) -> Result<psa_sign_hash::Result> {
+        trace!("psa_sign_hash ingress");
         Err(ResponseStatus::PsaErrorNotSupported)
     }
 
@@ -163,6 +173,7 @@ pub trait Provide {
         _app_name: ApplicationName,
         _op: psa_verify_hash::Operation,
     ) -> Result<psa_verify_hash::Result> {
+        trace!("psa_verify_hash ingress");
         Err(ResponseStatus::PsaErrorNotSupported)
     }
 }