chore(rust): logs adjustments

implementations/rust/ockam/ockam_api/src/logs/logging_options.rs

@@ -109,7 +109,7 @@ impl OckamLogFormat {
     }
 
     fn format_timestamp(&self, writer: &mut Writer<'_>) -> std::fmt::Result {
-        let now = chrono::Utc::now().format("%Y-%m-%d %H:%M:%S%.3f");
+        let now = chrono::Utc::now().format("%Y-%m-%dT%H:%M:%S%.6fZ");
         if writer.has_ansi_escapes() {
             let style = Style::new().dimmed();
             write!(writer, "{}", style.prefix())?;

implementations/rust/ockam/ockam_api/src/logs/setup.rs

@@ -3,7 +3,6 @@ use opentelemetry::trace::TracerProvider;
 use opentelemetry::{global, KeyValue};
 use opentelemetry_appender_tracing::layer::OpenTelemetryTracingBridge;
 use opentelemetry_otlp::WithExportConfig;
-use opentelemetry_sdk as sdk;
 use opentelemetry_sdk::export::logs::LogExporter;
 use opentelemetry_sdk::export::trace::SpanExporter;
 use opentelemetry_sdk::logs::{BatchLogProcessor, LoggerProvider};

implementations/rust/ockam/ockam_api/src/nodes/service/relay.rs

@@ -204,7 +204,6 @@ impl NodeManager {
 
         info!(
             %alias, %address, ?authorized, ?relay_address,
-            forwarding_route = ?relay_info.forwarding_route(),
             remote_address = ?relay_info.remote_address(),
             "relay created"
         );

implementations/rust/ockam/ockam_api/tests/logging_tracing.rs

@@ -5,11 +5,6 @@ use ockam_api::logs::{
 
 use opentelemetry::global;
 use opentelemetry::trace::Tracer;
-
-use opentelemetry_sdk as sdk;
-use sdk::testing::logs::*;
-use sdk::testing::trace::*;
-
 use opentelemetry_sdk::testing::logs::InMemoryLogsExporter;
 use opentelemetry_sdk::testing::trace::InMemorySpanExporter;
 use std::fs;

implementations/rust/ockam/ockam_command/src/node/create/foreground.rs

@@ -54,7 +54,7 @@ impl CreateCommand {
         // Set node_name so that node can isolate its data in the storage from other nodes
         self.get_or_create_identity(&opts, &self.identity).await?;
         let _notification_handler = if self.foreground_args.child_process {
-            // If enabled, the user's terminal will receive notifications
+            // If enabled, the user's terminal would receive notifications
             // from the node after the command exited.
             None
         } else {

implementations/rust/ockam/ockam_command/src/node/show.rs

@@ -171,7 +171,7 @@ pub async fn is_node_up(
         .ask_with_timeout::<(), NodeStatus>(ctx, api::query_status(), Duration::from_secs(1))
         .await
     {
-        if status.status.is_running() {
+        if status.process_status.is_running() {
             return Ok(true);
         }
     }

implementations/rust/ockam/ockam_command/src/relay/create.rs

@@ -91,8 +91,6 @@ impl Command for CreateCommand {
         let alias = cmd.relay_name();
         let return_timing = cmd.return_timing();
 
-        // let _notification_handler = NotificationHandler::start(&opts.state, opts.terminal.clone());
-
         let node = BackgroundNodeClient::create(ctx, &opts.state, &cmd.to).await?;
         let relay_info = {
             if at.starts_with(Project::CODE) && cmd.authorized.is_some() {

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

@@ -13,6 +13,8 @@ use ockam_vault::{
     X25519PublicKey, X25519SecretKeyHandle, X25519_PUBLIC_KEY_LENGTH,
 };
 use sha2::{Digest, Sha256};
+#[cfg(feature = "debugger")]
+use tracing::debug;
 use Status::*;
 
 /// The number of bytes in a SHA256 digest
@@ -50,6 +52,9 @@ impl Handshake {
 
     /// Encode the first message, sent from the initiator to the responder
     pub(super) async fn encode_message1(&mut self, payload: &[u8]) -> Result<Vec<u8>> {
+        #[cfg(feature = "debugger")]
+        debug!("Encoding message 1");
+
         let mut state = self.state.clone();
         // output e.pubKey
         let e_pub_key = self.get_public_key(state.e()?).await?;
@@ -70,6 +75,9 @@ impl Handshake {
 
     /// Decode the first message to get the ephemeral public key sent by the initiator
     pub(super) async fn decode_message1(&mut self, message1: &[u8]) -> Result<Vec<u8>> {
+        #[cfg(feature = "debugger")]
+        debug!("Decoding message 2");
+
         if message1.len() > NOISE_MAX_MESSAGE_SIZE {
             return Err(XXError::ExceededMaxMessageLen)?;
         }
@@ -93,6 +101,9 @@ impl Handshake {
     /// That message contains: the responder ephemeral public key + a Diffie-Hellman key +
     ///   an encrypted payload containing the responder identity / signature / credentials
     pub(super) async fn encode_message2(&mut self, payload: &[u8]) -> Result<Vec<u8>> {
+        #[cfg(feature = "debugger")]
+        debug!("Encoding message 2");
+
         let mut state = self.state.clone();
         // output e.pubKey
         let e_pub_key = self.get_public_key(state.e()?).await?;
@@ -126,6 +137,9 @@ impl Handshake {
 
     /// Decode the second message sent by the responder
     pub(super) async fn decode_message2(&mut self, message2: &[u8]) -> Result<Vec<u8>> {
+        #[cfg(feature = "debugger")]
+        debug!("Decoding message 2");
+
         if message2.len() > NOISE_MAX_MESSAGE_SIZE {
             return Err(XXError::ExceededMaxMessageLen)?;
         }
@@ -166,6 +180,9 @@ impl Handshake {
     /// That message contains: the initiator static public key (encrypted) + a Diffie-Hellman key +
     ///   an encrypted payload containing the initiator identity / signature / credentials
     pub(super) async fn encode_message3(&mut self, payload: &[u8]) -> Result<Vec<u8>> {
+        #[cfg(feature = "debugger")]
+        debug!("Encoding message 3");
+
         let mut state = self.state.clone();
         // encrypt s.pubKey
         let s_pub_key = self.get_public_key(state.s()?).await?;
@@ -190,6 +207,9 @@ impl Handshake {
 
     /// Decode the third message sent by the initiator
     pub(super) async fn decode_message3(&mut self, message3: &[u8]) -> Result<Vec<u8>> {
+        #[cfg(feature = "debugger")]
+        debug!("Decoding message 3");
+
         if message3.len() > NOISE_MAX_MESSAGE_SIZE {
             return Err(XXError::ExceededMaxMessageLen)?;
         }
@@ -219,6 +239,9 @@ impl Handshake {
     /// Set the final state of the state machine by creating the encryption / decryption keys
     /// and return the other party identity
     pub(super) async fn set_final_state(&mut self, role: Role) -> Result<()> {
+        #[cfg(feature = "debugger")]
+        debug!("Setting final state");
+
         // k1, k2 = HKDF(ck, zerolen, 2)
         let mut state = self.state.clone();
         let (k1, k2) = self.compute_final_keys(&mut state).await?;
@@ -239,6 +262,9 @@ impl Handshake {
 
     /// Return the final results of the handshake if we reached the final state
     pub(super) fn get_handshake_keys(&self) -> Option<HandshakeKeys> {
+        #[cfg(feature = "debugger")]
+        debug!("Getting handshake keys");
+
         match &self.state.status {
             Ready(keys) => Some(keys.clone()),
             _ => None,

implementations/rust/ockam/ockam_node/src/api.rs

@@ -132,7 +132,8 @@ impl Client {
             method = ?req.header().method(),
             path   = %req.header().path(),
             body   = %req.header().has_body(),
-        };
+            "sending request"
+        }
         let options = if let Some(t) = timeout {
             MessageSendReceiveOptions::new().with_timeout(t)
         } else {
@@ -147,6 +148,15 @@ impl Client {
         let local_info = resp.local_message().local_info().to_vec();
         let body = resp.into_body()?;
 
+        trace! {
+            target:  "ockam_api",
+            id     = %req.header().id(),
+            method = ?req.header().method(),
+            path   = %req.header().path(),
+            body   = %req.header().has_body(),
+            "received response"
+        }
+
         Ok((body, local_info))
     }
 }

implementations/rust/ockam/ockam_node/src/context/receive_message.rs

@@ -61,7 +61,7 @@ impl Context {
     pub(crate) async fn receiver_next(&mut self) -> Result<Option<RelayMessage>> {
         loop {
             let relay_msg = if let Some(msg) = self.receiver.recv().await.map(|msg| {
-                trace!("{}: received new message!", self.address());
+                trace!(address=%self.address(), "received new message!");
 
                 // First we update the mailbox fill metrics
                 self.mailbox_count.fetch_sub(1, Ordering::Acquire);