port over hierarchical layer/tree

Author: davidbarsky

Cargo.toml

@@ -7,7 +7,9 @@ edition = "2018"
 # See more keys and their definitions at https://doc.rust-lang.org/cargo/reference/manifest.html
 
 [dependencies]
-tracing = "0.1.11"
-tracing-subscriber = { git = "https://github.com/tokio-rs/tracing" }
+tracing = "0.1.12"
+tracing-subscriber = "0.2.0-alpha.5"
 quanta = "0.3.1"
 termcolor = "1.0.5"
+ansi_term = "0.12.1"
+chrono = "0.4.10"

examples/basic.rs

@@ -1,12 +1,44 @@
-use tracing::{info, instrument, span, Level};
-use tracing_subscriber::layer::SubscriberExt;
-use tracing_subscriber::{registry::Registry, Layer};
-use tracing_tree::TreeLayer;
+use tracing::{debug, info, instrument, span, warn, Level};
+use tracing_subscriber::{layer::SubscriberExt, registry::Registry};
+use tracing_tree::HierarchicalLayer;
 
 fn main() {
-    let subscriber = Registry::default().with(TreeLayer::default());
-    tracing::subscriber::set_global_default(subscriber).expect("Unable to set a global default");
-    call_a("david");
+    let subscriber = Registry::default().with(HierarchicalLayer::new(2));
+    tracing::subscriber::set_global_default(subscriber).unwrap();
+
+    let app_span = span!(Level::TRACE, "hierarchical-example", version = %0.1);
+    let _e = app_span.enter();
+
+    let server_span = span!(Level::TRACE, "server", host = "localhost", port = 8080);
+    let _e2 = server_span.enter();
+    info!("starting");
+    std::thread::sleep(std::time::Duration::from_millis(300));
+    info!("listening");
+    let peer1 = span!(Level::TRACE, "conn", peer_addr = "82.9.9.9", port = 42381);
+    peer1.in_scope(|| {
+        debug!("connected");
+        std::thread::sleep(std::time::Duration::from_millis(300));
+        debug!(length = 2, "message received");
+    });
+    let peer2 = span!(Level::TRACE, "conn", peer_addr = "8.8.8.8", port = 18230);
+    peer2.in_scope(|| {
+        std::thread::sleep(std::time::Duration::from_millis(300));
+        debug!("connected");
+    });
+    peer1.in_scope(|| {
+        warn!(algo = "xor", "weak encryption requested");
+        std::thread::sleep(std::time::Duration::from_millis(300));
+        debug!(length = 8, "response sent");
+        debug!("disconnected");
+    });
+    peer2.in_scope(|| {
+        debug!(length = 5, "message received");
+        std::thread::sleep(std::time::Duration::from_millis(300));
+        debug!(length = 8, "response sent");
+        debug!("disconnected");
+    });
+    warn!("internal error");
+    info!("exit");
 }
 
 #[instrument]

src/lib.rs

@@ -1,53 +1,247 @@
-use quanta::Clock;
-use std::fmt::Debug;
+use ansi_term::{Color, Style};
+use chrono::{DateTime, Local};
+use std::{fmt, io, io::Write as _};
 use tracing::{
-    span::{Attributes, Id, Record},
-    Event, Level, Metadata, Subscriber,
+    field::{Field, Visit},
+    span::{Attributes, Id},
+    Event, Level, Subscriber,
 };
 use tracing_subscriber::{
     layer::{Context, Layer},
     registry::LookupSpan,
 };
 
-#[derive(Debug, Default)]
-pub struct TreeLayer {
-    clock: Clock,
+#[derive(Debug)]
+pub struct HierarchicalLayer {
+    stdout: io::Stdout,
+    indent_amount: usize,
 }
 
-#[derive(Debug)]
 struct Data {
-    start: u64,
-    level: Level,
+    start: DateTime<Local>,
+    kvs: Vec<(&'static str, String)>,
+}
+
+struct FmtEvent<'a> {
+    stdout: io::StdoutLock<'a>,
+    comma: bool,
+}
+
+impl Data {
+    fn new(attrs: &tracing::span::Attributes<'_>) -> Self {
+        let mut span = Self {
+            start: Local::now(),
+            kvs: Vec::new(),
+        };
+        attrs.record(&mut span);
+        span
+    }
+}
+
+impl Visit for Data {
+    fn record_debug(&mut self, field: &Field, value: &dyn fmt::Debug) {
+        self.kvs.push((field.name(), format!("{:?}", value)))
+    }
+}
+
+impl<'a> Visit for FmtEvent<'a> {
+    fn record_debug(&mut self, field: &Field, value: &dyn fmt::Debug) {
+        write!(
+            &mut self.stdout,
+            "{comma} ",
+            comma = if self.comma { "," } else { "" },
+        )
+        .unwrap();
+        let name = field.name();
+        if name == "message" {
+            write!(&mut self.stdout, "{:?}", value).unwrap();
+            self.comma = true;
+        } else {
+            write!(&mut self.stdout, "{}={:?}", name, value).unwrap();
+            self.comma = true;
+        }
+    }
+}
+
+struct ColorLevel<'a>(&'a Level);
+
+impl<'a> fmt::Display for ColorLevel<'a> {
+    fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
+        match *self.0 {
+            Level::TRACE => Color::Purple.bold().paint("TRACE"),
+            Level::DEBUG => Color::Blue.bold().paint("DEBUG"),
+            Level::INFO => Color::Green.bold().paint(" INFO"),
+            Level::WARN => Color::RGB(252, 234, 160).bold().paint(" WARN"), // orange
+            Level::ERROR => Color::Red.bold().paint("ERROR"),
+        }
+        .fmt(f)
+    }
 }
 
-impl<S> Layer<S> for TreeLayer
+impl HierarchicalLayer {
+    pub fn new(indent_amount: usize) -> Self {
+        Self {
+            indent_amount,
+            stdout: io::stdout(),
+        }
+    }
+
+    fn print_kvs<'a, I, K, V>(
+        &self,
+        writer: &mut impl io::Write,
+        kvs: I,
+        leading: &str,
+    ) -> io::Result<()>
+    where
+        I: IntoIterator<Item = (K, V)>,
+        K: AsRef<str> + 'a,
+        V: fmt::Display + 'a,
+    {
+        let mut kvs = kvs.into_iter();
+        if let Some((k, v)) = kvs.next() {
+            write!(
+                writer,
+                "{}{}={}",
+                leading,
+                // Style::new().fg(Color::Purple).bold().paint(k.as_ref()),
+                k.as_ref(),
+                v
+            )?;
+        }
+        for (k, v) in kvs {
+            write!(
+                writer,
+                ", {}={}",
+                // Style::new().fg(Color::Purple).bold().paint(k.as_ref()),
+                k.as_ref(),
+                v
+            )?;
+        }
+        Ok(())
+    }
+
+    fn print_indent(&self, writer: &mut impl io::Write, indent: usize) -> io::Result<()> {
+        for _ in 0..(indent * self.indent_amount) {
+            write!(writer, " ")?;
+        }
+        Ok(())
+    }
+}
+
+impl<S> Layer<S> for HierarchicalLayer
 where
-    S: Subscriber + for<'span> LookupSpan<'span> + Debug,
+    S: Subscriber + for<'span> LookupSpan<'span> + fmt::Debug,
 {
     fn new_span(&self, attrs: &Attributes, id: &Id, ctx: Context<S>) {
-        let start = self.clock.now();
-        let level = attrs.metadata().level();
-        dbg!(attrs);
-        let data = Data {
-            start,
-            level: level.clone(),
-        };
+        let data = Data::new(attrs);
         let span = ctx.span(id).expect("in new_span but span does not exist");
         span.extensions_mut().insert(data);
     }
 
-    fn on_event(&self, event: &Event<'_>, _ctx: Context<S>) {
-        dbg!(event);
+    fn on_enter(&self, id: &tracing::Id, ctx: Context<S>) {
+        let mut stdout = self.stdout.lock();
+        let span = ctx.span(&id).expect("in on_enter but span does not exist");
+        let ext = span.extensions();
+        let data = ext.get::<Data>().expect("span does not have data");
+
+        let indent = ctx.scope().collect::<Vec<_>>().len() - 1;
+        self.print_indent(&mut stdout, indent)
+            .expect("Unable to write to stdout");
+
+        write!(
+            &mut stdout,
+            "{name}",
+            name = Style::new()
+                .fg(Color::Green)
+                .bold()
+                .paint(span.metadata().name())
+        )
+        .unwrap();
+        write!(
+            &mut stdout,
+            "{}",
+            Style::new().fg(Color::Green).paint("{") // Style::new().fg(Color::Green).dimmed().paint("{")
+        )
+        .unwrap();
+        self.print_kvs(&mut stdout, data.kvs.iter().map(|(k, v)| (k, v)), "")
+            .unwrap();
+        write!(
+            &mut stdout,
+            "{}",
+            Style::new().fg(Color::Green).bold().paint("}") // Style::new().dimmed().paint("}")
+        )
+        .unwrap();
+        writeln!(&mut stdout).unwrap();
+    }
+
+    fn on_event(&self, event: &Event<'_>, ctx: Context<S>) {
+        let mut stdout = self.stdout.lock();
+        // printing the indentation
+        if let Some(_) = ctx.current_span().id() {
+            // size hint isn't implemented on Scope.
+            let indent = ctx.scope().collect::<Vec<_>>().len();
+            self.print_indent(&mut stdout, indent)
+                .expect("Unable to write to stdout");
+        }
+
+        // check if this event occurred in the context of a span.
+        // if it has, get the start time of this span.
+        let start = match ctx.current_span().id() {
+            Some(id) => match ctx.span(id) {
+                // if the event is in a span, get the span's starting point.
+                Some(ctx) => {
+                    let ext = ctx.extensions();
+                    let data = ext
+                        .get::<Data>()
+                        .expect("Data cannot be found in extensions");
+                    Some(data.start)
+                }
+                None => None,
+            },
+            None => None,
+        };
+        let now = Local::now();
+        if let Some(start) = start {
+            let elapsed = now - start;
+            write!(
+                &mut stdout,
+                "{timestamp}{unit} {level}",
+                timestamp = Style::new()
+                    .dimmed()
+                    .paint(elapsed.num_milliseconds().to_string()),
+                unit = Style::new().dimmed().paint("ms"),
+                level = ColorLevel(event.metadata().level())
+            )
+            .expect("Unable to write to stdout");
+        }
+        let mut visitor = FmtEvent {
+            stdout,
+            comma: false,
+        };
+        event.record(&mut visitor);
+        writeln!(&mut visitor.stdout).unwrap();
     }
 
-    fn on_close(&self, id: Id, ctx: Context<S>) {
-        let end = self.clock.now();
-        let span = ctx.span(&id).expect("in on_close but span does not exist");
-        let mut ext = span.extensions_mut();
-        let data = ext
-            .get_mut::<Data>()
-            .expect("span does not have metric data");
+    fn on_close(&self, _: Id, _: Context<S>) {
+        // let end = Local::now();
+        // let span = ctx.span(&id).expect("in on_close but span does not exist");
+        // let ext = span.extensions();
+        // let data = ext.get::<Data>().expect("span does not have metric data");
+
+        // let indent = ctx.scope().collect::<Vec<_>>().len();
+        // let mut stdout = self.stdout.lock();
+        // self.print_indent(&mut stdout, indent)
+        //     .expect("Unable to write to stdout");
 
-        let elapsed = self.clock.delta(data.start, end);
+        // let elapsed = end - data.start;
+        // writeln!(
+        //     &mut stdout,
+        //     "Elapsed: {timestamp}{unit}",
+        //     timestamp = Style::new()
+        //         .dimmed()
+        //         .paint(elapsed.num_milliseconds().to_string()),
+        //     unit = Style::new().dimmed().paint("ms"),
+        // )
+        // .expect("Unable to write to stdout");
     }
 }