chore(rust): add some more logs to the secure-channel

implementations/rust/ockam/ockam_identity/src/purpose_keys/purpose_key_verification.rs

@@ -1,13 +1,14 @@
 use ockam_core::compat::sync::Arc;
 use ockam_core::Result;
 use ockam_vault::VaultForVerifyingSignatures;
+use tracing::trace;
 
 use crate::models::{Identifier, PurposeKeyAttestation, PurposeKeyAttestationData, VersionedData};
 use crate::utils::now;
 use crate::{ChangeHistoryRepository, IdentitiesVerification, IdentityError, TimestampInSeconds};
 
 /// We allow purpose keys to be created in the future related to this machine's time due to
-/// possible time dyssynchronization
+/// possible time desynchronization
 const MAX_ALLOWED_TIME_DRIFT: TimestampInSeconds = TimestampInSeconds(60);
 
 /// This struct supports all the services related to identities
@@ -45,6 +46,8 @@ impl PurposeKeyVerification {
         expected_subject: Option<&Identifier>,
         attestation: &PurposeKeyAttestation,
     ) -> Result<PurposeKeyAttestationData> {
+        trace!(?expected_subject, "verifying purpose key attestation");
+
         let versioned_data_hash = self.verifying_vault.sha256(&attestation.data).await?;
 
         let versioned_data: VersionedData = minicbor::decode(&attestation.data)?;
@@ -118,6 +121,8 @@ impl PurposeKeyVerification {
             return Err(IdentityError::PurposeKeyAttestationVerificationFailed)?;
         }
 
+        trace!(?expected_subject, "verified purpose key attestation");
+
         Ok(purpose_key_data)
     }
 }

implementations/rust/ockam/ockam_identity/src/secure_channel/encryptor_worker.rs

@@ -1,6 +1,6 @@
 use core::sync::atomic::{AtomicBool, Ordering};
 
-use tracing::{debug, error, info, warn};
+use tracing::{debug, error, info, trace, warn};
 use tracing_attributes::instrument;
 
 use ockam_core::compat::boxed::Box;
@@ -99,12 +99,23 @@ impl EncryptorWorker {
         ctx: &Context,
         msg: SecureChannelPaddedMessage<'static>,
     ) -> Result<Vec<u8>> {
+        trace!(
+            role=%self.role,
+            encryptor=%self.addresses.encryptor,
+            "encrypting message");
+
         let expected_len = minicbor::len(&msg);
         let mut destination = vec![0u8; NOISE_NONCE_LEN + expected_len + AES_GCM_TAGSIZE];
         minicbor::encode(&msg, &mut destination[NOISE_NONCE_LEN..])?;
 
         match self.encryptor.encrypt(&mut destination).await {
-            Ok(()) => Ok(destination),
+            Ok(()) => {
+                trace!(
+                    role=%self.role,
+                    encryptor=%self.addresses.encryptor,
+                    "message encrypted");
+                Ok(destination)
+            }
             // If encryption failed, that means we have some internal error,
             // and we may be in an invalid state, it's better to stop the Worker
             Err(err) => {
@@ -122,10 +133,10 @@ impl EncryptorWorker {
         ctx: &mut <Self as Worker>::Context,
         msg: Routed<<Self as Worker>::Message>,
     ) -> Result<()> {
-        debug!(
-            "SecureChannel {} received Encrypt API {}",
-            self.role, &self.addresses.encryptor
-        );
+        trace!(
+            role=%self.role,
+            encryptor=%self.addresses.encryptor,
+            "handling encrypt API message");
 
         let msg = msg.into_local_message();
         let return_route = msg.return_route;
@@ -161,6 +172,11 @@ impl EncryptorWorker {
         ctx.send_from_address(return_route, response, self.addresses.encryptor_api.clone())
             .await?;
 
+        trace!(
+            role=%self.role,
+            encryptor=%self.addresses.encryptor,
+            "sent encrypt API response");
+
         if should_stop {
             ctx.stop_worker(self.addresses.encryptor.clone()).await?;
         }
@@ -174,10 +190,10 @@ impl EncryptorWorker {
         ctx: &mut <Self as Worker>::Context,
         msg: Routed<<Self as Worker>::Message>,
     ) -> Result<()> {
-        debug!(
-            "SecureChannel {} received Encrypt {}",
-            self.role, &self.addresses.encryptor
-        );
+        trace!(
+            role=%self.role,
+            encryptor=%self.addresses.encryptor,
+            "handling encrypt message");
 
         let msg = msg.into_local_message();
         let mut onward_route = msg.onward_route;
@@ -208,14 +224,19 @@ impl EncryptorWorker {
         ctx.forward_from_address(msg, self.addresses.encryptor.clone())
             .await?;
 
+        debug!(
+            role=%self.role,
+            encryptor=%self.addresses.encryptor,
+            "forwarded message to decryptor");
+
         Ok(())
     }
 
     /// Asks credential retriever for a new credential and presents it to the other side, including
     /// the latest change_history
     #[instrument(skip_all)]
     async fn handle_refresh_credentials(&mut self, ctx: &<Self as Worker>::Context) -> Result<()> {
-        debug!(
+        trace!(
             "Started credentials refresh for {}",
             self.addresses.encryptor
         );
@@ -283,6 +304,11 @@ impl EncryptorWorker {
         )
         .await?;
 
+        trace!(
+            role=%self.role,
+            encryptor=%self.addresses.encryptor,
+            "credentials refresh sent");
+
         self.last_presented_credential = Some(credential);
 
         Ok(())

implementations/rust/ockam/ockam_identity/src/secure_channel/handshake/handshake_worker.rs

@@ -11,7 +11,7 @@ use ockam_core::{Result, Worker};
 use ockam_node::callback::CallbackSender;
 use ockam_node::{Context, WorkerBuilder};
 use ockam_vault::AeadSecretKeyHandle;
-use tracing::{debug, error, info, warn};
+use tracing::{debug, error, info, trace, warn};
 use tracing_attributes::instrument;
 
 use crate::models::Identifier;
@@ -74,7 +74,11 @@ impl Worker for HandshakeWorker {
         if let Some(state_machine) = self.state_machine.as_mut() {
             match state_machine.on_event(Initialize).await? {
                 SendMessage(message) => {
-                    debug!(remote_route=?self.remote_route, decryptor_remote=%self.addresses.decryptor_remote, "sending message");
+                    trace!(
+                        remote_route = ?self.remote_route,
+                        decryptor_remote = %self.addresses.decryptor_remote,
+                        "sending message",
+                    );
                     context
                         .send_from_address(
                             self.remote_route()?,
@@ -264,6 +268,11 @@ impl HandshakeWorker {
         context: &mut Context,
         message: Routed<Any>,
     ) -> Result<()> {
+        trace!(
+            remote_route = ?self.remote_route,
+            decryptor_remote = %self.addresses.decryptor_remote,
+            "handling handshake message",
+        );
         let message = message.into_local_message();
         let return_route = message.return_route;
         let payload = message.payload;
@@ -315,6 +324,11 @@ impl HandshakeWorker {
     /// and for decryption.
     #[instrument(skip_all, name = "DecryptorWorker::handle_message")]
     async fn handle_decrypt(&mut self, context: &mut Context, message: Routed<Any>) -> Result<()> {
+        trace!(
+            remote_route = ?self.remote_route,
+            decryptor_remote = %self.addresses.decryptor_remote,
+            "handling decrypt message",
+        );
         let decryptor_handler = self.decryptor_handler.as_mut().unwrap();
         let msg_addr = message.msg_addr();