WIP

crates/taskrun/Cargo.toml

@@ -10,10 +10,11 @@ path = "src/taskrun.rs"
 [dependencies]
 tokio = { version = "1.32.0", features = ["full", "tracing", "time"] }
 futures-util = "0.3.28"
-tracing = "0.1.37"
+tracing = "0.1.40"
+tracing-log = "0.2.0"
 tracing-subscriber = { version = "0.3.17", features = ["fmt", "time"] }
 #tracing-loki = { version = "0.2.1", default-features = false, features = ["compat-0-2-1"] }
-console-subscriber = { version = "0.1.10" }
+console-subscriber = { version = "0.2.0" }
 time = { version = "0.3", features = ["formatting"] }
 backtrace = "0.3.56"
 lazy_static = "1.4.0"

crates/taskrun/src/formatter.rs

@@ -0,0 +1,123 @@
+use std::fmt;
+use time::format_description::well_known::Rfc3339;
+use time::OffsetDateTime;
+use tracing::Event;
+use tracing::Subscriber;
+use tracing_log::NormalizeEvent;
+use tracing_subscriber::fmt::format::Writer;
+use tracing_subscriber::fmt::FmtContext;
+use tracing_subscriber::fmt::FormatEvent;
+use tracing_subscriber::fmt::FormatFields;
+use tracing_subscriber::fmt::FormattedFields;
+use tracing_subscriber::registry::LookupSpan;
+
+fn _dummyyyy() {
+    let _ = tracing_subscriber::fmt::format::Full;
+}
+
+pub struct FormatTxt;
+
+impl<S, N> FormatEvent<S, N> for FormatTxt
+where
+    S: Subscriber + for<'a> LookupSpan<'a>,
+    N: for<'a> FormatFields<'a> + 'static,
+{
+    fn format_event(&self, ctx: &FmtContext<'_, S, N>, mut writer: Writer<'_>, event: &Event<'_>) -> fmt::Result {
+        let normalized_meta = event.normalized_metadata();
+        let meta = normalized_meta.as_ref().unwrap_or_else(|| event.metadata());
+        // Without tracing-log:
+        // let meta = event.metadata();
+        // write!(w, "{}", datetime::DateTime::from(std::time::SystemTime::now()));
+        // write!(writer, "{} ", FmtLevel::new(meta.level()))?;
+        // Using crate `time` doing `DateTime<somehow-utc>.format_into(..)`
+
+        // tracing_subscriber::fmt::time::datetime is private:
+        // tracing_subscriber::fmt::time::datetime::DateTime::from(std::time::SystemTime::now());
+
+        if false {
+            // TODO restrict to milliseconds.
+            // TODO there must be a better way than via cursor?
+            let tsnow = OffsetDateTime::now_utc();
+            let buf = [0u8; 64];
+            let mut cr = std::io::Cursor::new(buf);
+            let n = tsnow.format_into(&mut cr, &Rfc3339).unwrap();
+            let buf = cr.into_inner();
+            writer.write_str(std::str::from_utf8(&buf[..n]).unwrap())?;
+            // writer.write_char(' ')?;
+        }
+
+        if true {
+            const DATETIME_FMT_3MS: &str = "%Y-%m-%dT%H:%M:%S.%3fZ";
+            let ts = chrono::Utc::now();
+            let tsfmt = ts.format(DATETIME_FMT_3MS);
+            writer.write_str(&tsfmt.to_string())?;
+            // writer.write_char(' ')?;
+        }
+
+        write!(writer, " {:>5} ", meta.level().as_str())?;
+
+        writer.write_str("[THR ")?;
+        let current_thread = std::thread::current();
+        match current_thread.name() {
+            Some(name) => {
+                let n = name.len();
+                let max = 14;
+                if n > max {
+                    writer.write_str(&name[0..2])?;
+                    writer.write_char('.')?;
+                    writer.write_str(&name[name.len() + 3 - max..])?;
+                } else {
+                    writer.write_str(name)?;
+                }
+            }
+            None => {
+                // write!(writer, "{:0>2?} ", current_thread.id())?;
+                write!(writer, "{:?} ", current_thread.id())?;
+            }
+        }
+        writer.write_char(' ')?;
+
+        writer.write_str("[TGT ")?;
+        writer.write_str(meta.target())?;
+        writer.write_char(' ')?;
+
+        writer.write_str("[SCP ")?;
+        if let Some(sc) = ctx.event_scope() {
+            for (i, span) in sc.from_root().enumerate() {
+                if i != 0 {
+                    writer.write_char(',')?;
+                }
+                let meta = span.metadata();
+                writer.write_str(meta.name())?;
+                let ext = span.extensions();
+                if let Some(fields) = ext.get::<FormattedFields<N>>() {
+                    if fields.is_empty() {
+                    } else {
+                        writer.write_char('{')?;
+                        writer.write_str(fields)?;
+                        // write!(writer, "{{{}}}", fields)?;
+                        writer.write_char('}')?;
+                    }
+                }
+            }
+        }
+        writer.write_char(' ')?;
+
+        if false {
+            writer.write_str("[FIL ")?;
+            if let Some(x) = meta.file() {
+                writer.write_str(x)?;
+                if let Some(x) = meta.line() {
+                    write!(writer, ":{x}")?;
+                }
+            }
+            writer.write_char(' ')?;
+        }
+
+        writer.write_str("[MSG ")?;
+        ctx.format_fields(writer.by_ref(), event)?;
+
+        writer.write_char('\n')?;
+        Ok(())
+    }
+}

crates/taskrun/src/taskrun.rs

@@ -1,3 +1,5 @@
+pub mod formatter;
+
 pub use tokio;
 
 use crate::log::*;
@@ -23,7 +25,7 @@ pub fn get_runtime() -> Arc<Runtime> {
     get_runtime_opts(24, 128)
 }
 
-// #[allow(unused)]
+#[allow(unused)]
 fn on_thread_start() {
     let old = panic::take_hook();
     panic::set_hook(Box::new(move |info| {
@@ -86,7 +88,7 @@ where
     E: fmt::Display,
 {
     let runtime = get_runtime();
-    match tracing_init() {
+    match tracing_init(TracingMode::Development) {
         Ok(_) => {}
         Err(()) => {
             eprintln!("ERROR tracing: can not init");
@@ -102,7 +104,7 @@ where
     }
 }
 
-fn tracing_init_inner() -> Result<(), Error> {
+fn tracing_init_inner(mode: TracingMode) -> Result<(), Error> {
     use tracing_subscriber::layer::SubscriberExt;
     use tracing_subscriber::util::SubscriberInitExt;
     use tracing_subscriber::Layer;
@@ -110,7 +112,12 @@ fn tracing_init_inner() -> Result<(), Error> {
     let timer = tracing_subscriber::fmt::time::UtcTime::new(
         time::format_description::parse(fmtstr).map_err(|e| format!("{e}"))?,
     );
-    if true {
+    if let TracingMode::Console = mode {
+        // Only async console
+        console_subscriber::init();
+    } else {
+        // #[cfg(DISABLED)]
+        // Logging setup
         let filter = tracing_subscriber::EnvFilter::builder()
             .with_default_directive(tracing::metadata::LevelFilter::INFO.into())
             .from_env()
@@ -121,6 +128,7 @@ fn tracing_init_inner() -> Result<(), Error> {
             .with_target(true)
             .with_ansi(false)
             .with_thread_names(true)
+            .event_format(formatter::FormatTxt)
             .with_filter(filter);
 
         let reg = tracing_subscriber::registry();
@@ -191,11 +199,21 @@ fn tracing_init_inner() -> Result<(), Error> {
     Ok(())
 }
 
-pub fn tracing_init() -> Result<(), ()> {
+pub enum TracingMode {
+    Production,
+    Development,
+    Console,
+}
+
+pub fn tracing_init_testing() -> Result<(), ()> {
+    tracing_init(TracingMode::Development)
+}
+
+pub fn tracing_init(mode: TracingMode) -> Result<(), ()> {
     match INIT_TRACING_ONCE.lock() {
         Ok(mut initg) => {
             if *initg == 0 {
-                match tracing_init_inner() {
+                match tracing_init_inner(mode) {
                     Ok(_) => {
                         *initg = 1;
                     }