diff --git a/Cargo.lock b/Cargo.lock index 3551093146..ffed99485b 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -1713,6 +1713,7 @@ dependencies = [ [[package]] name = "fastn-observer" version = "0.1.0" +source = "git+https://github.com/fastn-stack/fastn-observer?rev=47b29ea#47b29eacf78f2ec96a4932631282db9f262ce5a4" dependencies = [ "ansi_term", "smallvec", diff --git a/Cargo.toml b/Cargo.toml index 9cb0ec96fd..6a0494a7c6 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -8,7 +8,6 @@ members = [ "fastn-issues", "fastn-js", "fastn-grammar", - "fastn-observer", # "fastn-wasm", # "fastn-runtime", ] @@ -84,7 +83,6 @@ fastn-core = { path = "fastn-core" } fastn-issues = { path = "fastn-issues" } fastn-package = { path = "fastn-package" } fastn-runtime = { path = "fastn-runtime" } -fastn-observer = { path = "fastn-observer" } fastn-wasm = { path = "fastn-wasm" } fastn-grammar = { path = "fastn-grammar" } fluent = "0.16" @@ -139,6 +137,10 @@ zip = "0.6" prettify-js = "0.1.0" indexmap = { version = "2", features = ["serde"] } +[workspace.dependencies.fastn-observer] +git = "https://github.com/fastn-stack/fastn-observer" +rev = "47b29ea" + [workspace.dependencies.rusqlite] version = "0.29.0" features = [ diff --git a/fastn-observer/Cargo.toml b/fastn-observer/Cargo.toml deleted file mode 100644 index 392c9fa3c9..0000000000 --- a/fastn-observer/Cargo.toml +++ /dev/null @@ -1,11 +0,0 @@ -[package] -name = "fastn-observer" -version = "0.1.0" -edition = "2021" - -[dependencies] -tracing.workspace = true -tracing-subscriber.workspace = true -tokio.workspace = true -smallvec.workspace = true -ansi_term.workspace = true \ No newline at end of file diff --git a/fastn-observer/src/duration_display.rs b/fastn-observer/src/duration_display.rs deleted file mode 100644 index b5335507bd..0000000000 --- a/fastn-observer/src/duration_display.rs +++ /dev/null @@ -1,21 +0,0 @@ -// borrowed from https://github.com/QnnOkabayashi/tracing-forest/ (license: MIT) - -pub struct DurationDisplay(pub(crate) f64); - -// Taken from chrono -impl std::fmt::Display for DurationDisplay { - fn fmt(&self, f: &mut std::fmt::Formatter) -> std::fmt::Result { - let mut t = self.0; - for unit in ["ns", "µs", "ms", "s"] { - if t < 10.0 { - return write!(f, "{:.2}{}", t, unit); - } else if t < 100.0 { - return write!(f, "{:.1}{}", t, unit); - } else if t < 1000.0 { - return write!(f, "{:.0}{}", t, unit); - } - t /= 1000.0; - } - write!(f, "{:.0}s", t * 1000.0) - } -} diff --git a/fastn-observer/src/field.rs b/fastn-observer/src/field.rs deleted file mode 100644 index d6764aa937..0000000000 --- a/fastn-observer/src/field.rs +++ /dev/null @@ -1,26 +0,0 @@ -// borrowed from https://github.com/QnnOkabayashi/tracing-forest/ (license: MIT) - -pub type FieldSet = smallvec::SmallVec<[Field; 3]>; - -/// A key-value pair recorded from trace data. -#[derive(Clone, Debug, Hash, PartialEq, Eq)] -pub struct Field { - key: &'static str, - value: String, -} - -impl Field { - pub(crate) fn new(key: &'static str, value: String) -> Self { - Field { key, value } - } - - /// Returns the field's key. - pub fn key(&self) -> &'static str { - self.key - } - - /// Returns the field's value. - pub fn value(&self) -> &str { - &self.value - } -} diff --git a/fastn-observer/src/formatter.rs b/fastn-observer/src/formatter.rs deleted file mode 100644 index d0b5ed9052..0000000000 --- a/fastn-observer/src/formatter.rs +++ /dev/null @@ -1,207 +0,0 @@ -// borrowed from https://github.com/QnnOkabayashi/tracing-forest/ (license: MIT) - -pub fn write_immediate( - _event: &fastn_observer::Event, - _current: Option<&tracing_subscriber::registry::SpanRef>, -) -> std::io::Result<()> -where - S: for<'a> tracing_subscriber::registry::LookupSpan<'a>, -{ - // dbg!(event); - Ok(()) -} - -type IndentVec = smallvec::SmallVec<[Indent; 32]>; - -use ansi_term::Color; - -/// Format logs for pretty printing. -/// -/// # Examples -/// -/// An arbitrarily complex example: -/// ```log -/// INFO try_from_entry_ro [ 324µs | 8.47% / 100.00% ] -/// INFO ┝━ server::internal_search [ 296µs | 19.02% / 91.53% ] -/// INFO │ ┝━ ｉ [filter.info]: Some filter info... -/// INFO │ ┝━ server::search [ 226µs | 10.11% / 70.01% ] -/// INFO │ │ ┝━ be::search [ 181µs | 6.94% / 55.85% ] -/// INFO │ │ │ ┕━ be::search -> filter2idl [ 158µs | 19.65% / 48.91% ] -/// INFO │ │ │ ┝━ be::idl_arc_sqlite::get_idl [ 20.4µs | 6.30% ] -/// INFO │ │ │ │ ┕━ ｉ [filter.info]: Some filter info... -/// INFO │ │ │ ┕━ be::idl_arc_sqlite::get_idl [ 74.3µs | 22.96% ] -/// ERROR │ │ │ ┝━ 🚨 [admin.error]: On no, an admin error occurred :( -/// DEBUG │ │ │ ┝━ 🐛 [debug]: An untagged debug log -/// INFO │ │ │ ┕━ ｉ [admin.info]: there's been a big mistake | alive: false | status: "very sad" -/// INFO │ │ ┕━ be::idl_arc_sqlite::get_identry [ 13.1µs | 4.04% ] -/// ERROR │ │ ┝━ 🔐 [security.critical]: A security critical log -/// INFO │ │ ┕━ 🔓 [security.access]: A security access log -/// INFO │ ┕━ server::search [ 8.08µs | 2.50% ] -/// WARN │ ┕━ 🚧 [filter.warn]: Some filter warning -/// TRACE ┕━ 📍 [trace]: Finished! -/// ``` -#[derive(Debug)] -pub struct Pretty; - -impl Pretty { - pub fn fmt(&self, tree: &fastn_observer::Tree) -> Result { - let mut writer = String::with_capacity(256); - - Pretty::format_tree(tree, None, &mut IndentVec::new(), &mut writer)?; - - Ok(writer) - } -} - -impl Pretty { - fn format_tree( - tree: &fastn_observer::Tree, - duration_root: Option, - indent: &mut IndentVec, - writer: &mut String, - ) -> std::fmt::Result { - match tree { - fastn_observer::Tree::Event(event) => { - Pretty::format_shared(&event.shared, writer)?; - Pretty::format_indent(indent, writer)?; - Pretty::format_event(event, writer) - } - fastn_observer::Tree::Span(span) => { - Pretty::format_shared(&span.shared, writer)?; - Pretty::format_indent(indent, writer)?; - Pretty::format_span(span, duration_root, indent, writer) - } - } - } - - fn format_shared(shared: &fastn_observer::Shared, writer: &mut String) -> std::fmt::Result { - use std::fmt::Write; - - write!(writer, "{:<8} ", ColorLevel(shared.level)) - } - - fn format_indent(indent: &[Indent], writer: &mut String) -> std::fmt::Result { - use std::fmt::Write; - - for indent in indent { - writer.write_str(indent.repr())?; - } - Ok(()) - } - - fn format_event(event: &fastn_observer::Event, writer: &mut String) -> std::fmt::Result { - use std::fmt::Write; - - // write!(writer, "{} [{}]: ", tag.icon(), tag)?; - - if let Some(ref message) = event.message { - writer.write_str(message)?; - } - - for field in event.shared.fields.iter() { - write!( - writer, - " | {} {}: {}", - fastn_observer::DurationDisplay(event.shared.on.as_nanos() as f64), - field.key(), - field.value() - )?; - } - - writeln!(writer) - } - - fn format_span( - span: &fastn_observer::Span, - duration_root: Option, - indent: &mut IndentVec, - writer: &mut String, - ) -> std::fmt::Result { - use std::fmt::Write; - - let total_duration = span.duration.as_nanos() as f64; - let root_duration = duration_root.unwrap_or(total_duration); - - write!( - writer, - "{} {} [ {} ] ", - fastn_observer::DurationDisplay(span.shared.on.as_nanos() as f64), - span.name, - fastn_observer::DurationDisplay(total_duration) - )?; - - for (n, field) in span.shared.fields.iter().enumerate() { - write!( - writer, - "{} {}: {}", - if n == 0 { "" } else { " |" }, - field.key(), - field.value() - )?; - } - writeln!(writer)?; - - if let Some((last, remaining)) = span.nodes.split_last() { - match indent.last_mut() { - Some(edge @ Indent::Turn) => *edge = Indent::Null, - Some(edge @ Indent::Fork) => *edge = Indent::Line, - _ => {} - } - - indent.push(Indent::Fork); - - for tree in remaining { - if let Some(edge) = indent.last_mut() { - *edge = Indent::Fork; - } - Pretty::format_tree(tree, Some(root_duration), indent, writer)?; - } - - if let Some(edge) = indent.last_mut() { - *edge = Indent::Turn; - } - Pretty::format_tree(last, Some(root_duration), indent, writer)?; - - indent.pop(); - } - - Ok(()) - } -} - -enum Indent { - Null, - Line, - Fork, - Turn, -} - -impl Indent { - fn repr(&self) -> &'static str { - match self { - Self::Null => " ", - Self::Line => "│ ", - Self::Fork => "┝━ ", - Self::Turn => "┕━ ", - } - } -} - -// From tracing-tree -struct ColorLevel(tracing::Level); - -impl std::fmt::Display for ColorLevel { - fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { - let color = match self.0 { - tracing::Level::TRACE => Color::Purple, - tracing::Level::DEBUG => Color::Blue, - tracing::Level::INFO => Color::Green, - tracing::Level::WARN => Color::RGB(252, 234, 160), // orange - tracing::Level::ERROR => Color::Red, - }; - let style = color.bold(); - write!(f, "{}", style.prefix())?; - f.pad(self.0.as_str())?; - write!(f, "{}", style.suffix()) - } -} diff --git a/fastn-observer/src/layer.rs b/fastn-observer/src/layer.rs deleted file mode 100644 index a2a80ba001..0000000000 --- a/fastn-observer/src/layer.rs +++ /dev/null @@ -1,130 +0,0 @@ -// borrowed from https://github.com/QnnOkabayashi/tracing-forest/ (license: MIT) - -pub const SPAN_NOT_IN_CONTEXT: &str = "Span not in context, this is a bug"; -pub const OPENED_SPAN_NOT_IN_EXTENSIONS: &str = - "Span extension doesn't contain `OpenedSpan`, this is a bug"; -pub const WRITING_URGENT_ERROR: &str = "writing_urgent failed, this is a bug"; - -#[derive(Default)] -pub struct Layer {} - -impl tracing_subscriber::Layer for Layer -where - S: tracing::Subscriber + for<'a> tracing_subscriber::registry::LookupSpan<'a> + std::fmt::Debug, -{ - fn on_new_span( - &self, - attrs: &tracing::span::Attributes, - id: &tracing::Id, - ctx: tracing_subscriber::layer::Context, - ) { - let span = ctx.span(id).expect(SPAN_NOT_IN_CONTEXT); - let opened = fastn_observer::OpenedSpan::new( - attrs, - span.parent().and_then(|v| { - v.extensions() - .get::() - .map(|v| v.start) - }), - ); - - let mut extensions = span.extensions_mut(); - extensions.insert(opened); - } - - fn on_event(&self, event: &tracing::Event, ctx: tracing_subscriber::layer::Context) { - struct Visitor { - message: Option, - fields: fastn_observer::FieldSet, - immediate: bool, - } - - impl tracing::field::Visit for Visitor { - fn record_bool(&mut self, field: &tracing::field::Field, value: bool) { - match field.name() { - "immediate" => self.immediate |= value, - _ => self.record_debug(field, &value), - } - } - - fn record_debug(&mut self, field: &tracing::field::Field, value: &dyn std::fmt::Debug) { - let value = format!("{:?}", value); - match field.name() { - "message" if self.message.is_none() => self.message = Some(value), - key => self.fields.push(fastn_observer::Field::new(key, value)), - } - } - } - - let mut visitor = Visitor { - message: None, - fields: fastn_observer::FieldSet::default(), - immediate: false, - }; - - event.record(&mut visitor); - let current_span = ctx.event_span(event); - - let shared = fastn_observer::Shared { - level: *event.metadata().level(), - fields: visitor.fields, - on: current_span - .as_ref() - .and_then(|v| { - v.extensions() - .get::() - .map(|v| v.start) - }) - .unwrap_or_else(std::time::Instant::now) - .elapsed(), - }; - - let tree_event = fastn_observer::Event { - shared, - message: visitor.message, - }; - - if visitor.immediate { - fastn_observer::write_immediate(&tree_event, current_span.as_ref()) - .expect(WRITING_URGENT_ERROR); - } - - match current_span.as_ref() { - Some(parent) => parent - .extensions_mut() - .get_mut::() - .expect(OPENED_SPAN_NOT_IN_EXTENSIONS) - .record_event(tree_event), - None => fastn_observer::write_immediate(&tree_event, current_span.as_ref()) - .expect(WRITING_URGENT_ERROR), - } - } - - fn on_close(&self, id: tracing::Id, ctx: tracing_subscriber::layer::Context) { - let span_ref = ctx.span(&id).expect(SPAN_NOT_IN_CONTEXT); - - let span = span_ref - .extensions_mut() - .remove::() - .expect(OPENED_SPAN_NOT_IN_EXTENSIONS) - .close(); - - match span_ref.parent() { - Some(parent) => parent - .extensions_mut() - .get_mut::() - .expect(OPENED_SPAN_NOT_IN_EXTENSIONS) - .record_span(span), - None => { - if fastn_observer::is_traced() { - println!( - "{}", - fastn_observer::formatter::Pretty {} - .fmt(&fastn_observer::Tree::Span(span)) - .unwrap() - ); - } - } - } - } -} diff --git a/fastn-observer/src/lib.rs b/fastn-observer/src/lib.rs deleted file mode 100644 index 310f7009e4..0000000000 --- a/fastn-observer/src/lib.rs +++ /dev/null @@ -1,33 +0,0 @@ -extern crate self as fastn_observer; - -mod duration_display; -mod field; -mod formatter; -mod layer; -mod opened_span; -mod tree; - -pub(crate) use duration_display::DurationDisplay; -pub use field::{Field, FieldSet}; -pub use formatter::write_immediate; -pub use layer::Layer; -pub use opened_span::OpenedSpan; -pub use tree::{Event, Shared, Span, Tree}; - -pub fn observe() { - use tracing_subscriber::layer::SubscriberExt; - - // let level = std::env::var("TRACING") - // .unwrap_or_else(|_| "info".to_string()) - // .parse::() - // .unwrap_or(tracing_forest::util::LevelFilter::INFO); - - let s = tracing_subscriber::registry() - //.with(level) - .with(Layer::default()); - tracing::subscriber::set_global_default(s).unwrap(); -} - -pub fn is_traced() -> bool { - std::env::var("TRACING").is_ok() || std::env::args().any(|e| e == "--trace") -} diff --git a/fastn-observer/src/main.rs b/fastn-observer/src/main.rs deleted file mode 100644 index 17d2769c9d..0000000000 --- a/fastn-observer/src/main.rs +++ /dev/null @@ -1,31 +0,0 @@ -fn main() { - fastn_observer::observe(); - - tokio::runtime::Builder::new_multi_thread() - .enable_all() - .build() - .unwrap() - .block_on(outer_main(2, 3)) -} - -#[tracing::instrument] -async fn outer_main(time1: u64, time2: u64) { - tracing::info!(time1, time2); - test(time1, time2).await; - tracing::info!("we are done"); -} - -#[tracing::instrument] -async fn foo(time: u64) { - tracing::info!(time); - tokio::time::sleep(std::time::Duration::from_secs(time)).await; - tracing::info!(tag = "we are done"); -} - -#[tracing::instrument] -async fn test(time1: u64, time2: u64) { - tracing::info!(hello = 10); - tokio::time::sleep(std::time::Duration::from_secs(time1)).await; - foo(time2).await; - tracing::info!(awesome = "we are done"); -} diff --git a/fastn-observer/src/opened_span.rs b/fastn-observer/src/opened_span.rs deleted file mode 100644 index 9f091882d0..0000000000 --- a/fastn-observer/src/opened_span.rs +++ /dev/null @@ -1,47 +0,0 @@ -// borrowed from https://github.com/QnnOkabayashi/tracing-forest/ (license: MIT) - -pub struct OpenedSpan { - span: fastn_observer::Span, - pub start: std::time::Instant, -} - -impl OpenedSpan { - pub fn new( - attrs: &tracing::span::Attributes, - parent_start: Option, - ) -> Self { - let start = std::time::Instant::now(); - let mut fields = fastn_observer::FieldSet::default(); - - attrs.record( - &mut |field: &tracing::field::Field, value: &dyn std::fmt::Debug| { - let value = format!("{:?}", value); - fields.push(fastn_observer::Field::new(field.name(), value)); - }, - ); - - let shared = fastn_observer::Shared { - level: *attrs.metadata().level(), - fields, - on: parent_start.unwrap_or(start).elapsed(), - }; - - OpenedSpan { - span: fastn_observer::Span::new(shared, attrs.metadata().name()), - start, - } - } - - pub fn close(mut self) -> fastn_observer::Span { - self.span.duration = self.start.elapsed(); - self.span - } - - pub fn record_event(&mut self, event: fastn_observer::Event) { - self.span.nodes.push(fastn_observer::Tree::Event(event)); - } - - pub fn record_span(&mut self, span: fastn_observer::Span) { - self.span.nodes.push(fastn_observer::Tree::Span(span)); - } -} diff --git a/fastn-observer/src/tree.rs b/fastn-observer/src/tree.rs deleted file mode 100644 index 19b2bec5eb..0000000000 --- a/fastn-observer/src/tree.rs +++ /dev/null @@ -1,40 +0,0 @@ -// borrowed from https://github.com/QnnOkabayashi/tracing-forest/ (license: MIT) - -#[derive(Debug)] -pub enum Tree { - Event(Event), - Span(Span), -} - -#[derive(Debug)] -pub struct Event { - pub(crate) shared: Shared, - pub(crate) message: Option, -} - -#[derive(Debug)] -pub struct Span { - pub(crate) shared: Shared, - pub(crate) name: &'static str, - pub(crate) duration: std::time::Duration, - pub(crate) nodes: Vec, -} - -#[derive(Debug)] -pub struct Shared { - pub(crate) level: tracing::Level, - pub(crate) fields: fastn_observer::FieldSet, - /// when did this event occur, with respect to immediate parent start - pub(crate) on: std::time::Duration, -} - -impl Span { - pub(crate) fn new(shared: Shared, name: &'static str) -> Self { - Span { - shared, - name, - duration: std::time::Duration::ZERO, - nodes: Vec::new(), - } - } -}