format log lines. LogItem::new.

Author: jonaro00

common/src/log.rs

@@ -1,14 +1,20 @@
+use std::fmt::Write;
+
 use chrono::{DateTime, Utc};
 #[cfg(feature = "display")]
+use crossterm::style::StyledContent;
+#[cfg(feature = "display")]
 use crossterm::style::Stylize;
 use serde::{Deserialize, Serialize};
 use strum::EnumString;
-use tracing::{field::Visit, span, warn, Metadata, Subscriber};
+use tracing::{field::Visit, span, warn, Event, Level, Metadata, Subscriber};
 use tracing_subscriber::Layer;
 #[cfg(feature = "openapi")]
 use utoipa::ToSchema;
 use uuid::Uuid;
 
+use crate::tracing::JsonVisitor;
+
 /// Used to determine settings based on which backend crate does what
 #[derive(Clone, Debug, EnumString, Eq, PartialEq, Deserialize, Serialize)]
 #[cfg_attr(feature = "display", derive(strum::Display))]
@@ -52,21 +58,85 @@ pub struct LogItem {
     pub line: String,
 }
 
+impl LogItem {
+    pub fn new(id: Uuid, internal_origin: Backend, line: String) -> Self {
+        Self {
+            id,
+            internal_origin,
+            timestamp: Utc::now(),
+            line,
+        }
+    }
+}
+
 #[cfg(feature = "display")]
 impl std::fmt::Display for LogItem {
     fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
         let datetime: chrono::DateTime<chrono::Local> = DateTime::from(self.timestamp);
 
         write!(
             f,
-            "{} [{}] {}",
+            "{} {} {}",
             datetime.to_rfc3339().dim(),
-            self.internal_origin,
+            format!("[{}]", self.internal_origin).grey(),
             self.line,
         )
     }
 }
 
+#[cfg(feature = "display")]
+pub trait ColoredLevel {
+    fn colored(&self) -> StyledContent<&str>;
+}
+
+#[cfg(feature = "display")]
+impl ColoredLevel for tracing::Level {
+    fn colored(&self) -> StyledContent<&str> {
+        match *self {
+            Level::TRACE => "TRACE".magenta(),
+            Level::DEBUG => "DEBUG".blue(),
+            Level::INFO => " INFO".green(),
+            Level::WARN => " WARN".yellow(),
+            Level::ERROR => "ERROR".red(),
+        }
+    }
+}
+
+#[cfg(feature = "display")]
+pub fn format_event(event: &Event<'_>) -> String {
+    let metadata = event.metadata();
+    let mut visitor = JsonVisitor::default();
+    event.record(&mut visitor);
+
+    let mut message = String::new();
+
+    let target = visitor
+        .target
+        .unwrap_or_else(|| metadata.target().to_string());
+
+    if !target.is_empty() {
+        let t = format!("{target}: ").dim();
+        write!(message, "{t}").unwrap();
+    }
+
+    let mut simple = None;
+    let mut extra = vec![];
+    for (key, value) in visitor.fields.iter() {
+        match key.as_str() {
+            "message" => simple = value.as_str(),
+            _ => extra.push(format!("{key}={value}")),
+        }
+    }
+    if !extra.is_empty() {
+        write!(message, "{{{}}} ", extra.join(" ")).unwrap();
+    }
+    if let Some(msg) = simple {
+        write!(message, "{msg}").unwrap();
+    }
+
+    format!("{} {}", metadata.level().colored(), message)
+}
+
 /// Records logs for the deployment progress
 pub trait LogRecorder: Clone + Send + 'static {
     fn record(&self, log: LogItem);
@@ -95,17 +165,16 @@ where
             return;
         };
 
-        // Find the outermost scope with the scope details containing the current state
+        // Find the outermost scope with the scope details containing the current deployment id
         for span in scope.from_root() {
             let extensions = span.extensions();
 
             if let Some(details) = extensions.get::<ScopeDetails>() {
-                self.recorder.record(LogItem {
-                    id: details.id,
-                    internal_origin: self.internal_service.clone(),
-                    timestamp: Utc::now(),
-                    line: "Test".into(),
-                });
+                self.recorder.record(LogItem::new(
+                    details.deployment_id,
+                    self.internal_service.clone(),
+                    format_event(event),
+                ));
                 break;
             }
         }
@@ -124,39 +193,46 @@ where
         attrs.record(&mut visitor);
         let details = visitor.details;
 
-        if details.id.is_nil() {
-            warn!("scope details does not have a valid id");
+        if details.deployment_id.is_nil() {
+            warn!("scope details does not have a valid deployment_id");
             return;
         }
 
         // Safe to unwrap since this is the `on_new_span` method
         let span = ctx.span(id).unwrap();
         let mut extensions = span.extensions_mut();
 
-        self.recorder.record(LogItem {
-            id: details.id,
-            internal_origin: self.internal_service.clone(),
-            timestamp: Utc::now(),
-            line: "Test".into(),
-        });
+        let metadata = attrs.metadata();
+
+        let message = format!(
+            "{} Entering span {}",
+            metadata.level().colored(),
+            metadata.name().blue(),
+        );
+
+        self.recorder.record(LogItem::new(
+            details.deployment_id,
+            self.internal_service.clone(),
+            message,
+        ));
 
         extensions.insert::<ScopeDetails>(details);
     }
 }
 
 #[derive(Debug, Default)]
 struct ScopeDetails {
-    id: Uuid,
+    deployment_id: Uuid,
 }
-/// To extract `id` field for scopes that have it
+/// To extract `deployment_id` field for scopes that have it
 #[derive(Default)]
 struct DeploymentIdVisitor {
     details: ScopeDetails,
 }
 
 impl DeploymentIdVisitor {
     /// Field containing the deployment identifier
-    const ID_IDENT: &'static str = "id";
+    const ID_IDENT: &'static str = "deployment_id";
 
     fn is_valid(metadata: &Metadata) -> bool {
         metadata.is_span() && metadata.fields().field(Self::ID_IDENT).is_some()
@@ -166,7 +242,7 @@ impl DeploymentIdVisitor {
 impl Visit for DeploymentIdVisitor {
     fn record_debug(&mut self, field: &tracing::field::Field, value: &dyn std::fmt::Debug) {
         if field.name() == Self::ID_IDENT {
-            self.details.id = Uuid::try_parse(&format!("{value:?}")).unwrap_or_default();
+            self.details.deployment_id = Uuid::try_parse(&format!("{value:?}")).unwrap_or_default();
         }
     }
 }
@@ -186,12 +262,11 @@ mod tests {
 
     #[test]
     fn test_timezone_formatting() {
-        let item = LogItem {
-            id: Uuid::new_v4(),
-            internal_origin: Backend::Deployer,
-            timestamp: Utc::now(),
-            line: r#"{"message": "Building"}"#.to_owned(),
-        };
+        let item = LogItem::new(
+            Uuid::new_v4(),
+            Backend::Deployer,
+            r#"{"message": "Building"}"#.to_owned(),
+        );
 
         with_tz("CEST", || {
             let cest_dt = item.timestamp.with_timezone(&chrono::Local).to_rfc3339();

deployer/src/deployment/queue.rs

@@ -190,21 +190,20 @@ impl Queued {
         info!("Building deployment");
 
         let (tx, rx): (crossbeam_channel::Sender<Message>, _) = crossbeam_channel::bounded(0);
-        let id = self.id;
+
         tokio::task::spawn_blocking(move || {
             while let Ok(message) = rx.recv() {
                 trace!(?message, "received cargo message");
                 // TODO: change these to `info!(...)` as [valuable] support increases.
                 // Currently it is not possible to turn these serde `message`s into a `valuable`, but once it is the passing down of `log_recorder` should be removed.
-                let log = LogItem {
-                    id: self.id,
-                    internal_origin: shuttle_common::log::Backend::Deployer, // will change to Builder
-                    timestamp: Utc::now(),
-                    line: match message {
+                let log = LogItem::new(
+                    self.id,
+                    shuttle_common::log::Backend::Deployer, // will change to Builder
+                    match message {
                         Message::TextLine(line) => line,
                         message => serde_json::to_string(&message).unwrap(),
                     },
-                };
+                );
                 log_recorder.record(log);
             }
         });
@@ -243,7 +242,7 @@ impl Queued {
         let is_next = built_service.is_wasm;
 
         deployment_updater
-            .set_is_next(&id, is_next)
+            .set_is_next(&self.id, is_next)
             .await
             .map_err(|e| Error::Build(Box::new(e)))?;
 

deployer/src/deployment/state_change_layer.rs

@@ -25,7 +25,7 @@ use tracing_subscriber::Layer;
 use uuid::Uuid;
 
 use shuttle_common::{
-    log::{Backend, LogRecorder},
+    log::{Backend, ColoredLevel, LogRecorder},
     LogItem,
 };
 
@@ -74,12 +74,15 @@ where
             state: visitor.state,
         });
         // To logger
-        self.log_recorder.record(LogItem {
-            id: visitor.id,
-            internal_origin: Backend::Deployer,
-            timestamp: Utc::now(),
-            line: format!(" INFO Entering {:?} state", visitor.state),
-        });
+        self.log_recorder.record(LogItem::new(
+            visitor.id,
+            Backend::Deployer,
+            format!(
+                "{} {}",
+                tracing::Level::INFO.colored(),
+                format!("Entering {} state", visitor.state), // make blue?
+            ),
+        ));
     }
 }