From 5a25fd7161d58e5f7544e23730609391a5e240b7 Mon Sep 17 00:00:00 2001 From: Sebastian Moser Date: Thu, 22 Aug 2024 11:17:01 +0200 Subject: [PATCH] logging works a bit more the way i want, but it's such a pfusch --- Cargo.lock | 1 + Cargo.toml | 1 + src/core/instance/mod.rs | 2 +- src/core/instance/updater.rs | 2 - src/core/item.rs | 13 +- src/core/memstore.rs | 5 +- src/platform/os/cli/show.rs | 4 +- src/platform/os/fsstore.rs | 6 - src/platform/os/logging.rs | 274 +++++++++++++++++++++++++++++++-- src/platform/os/mod.rs | 1 - src/platform/os/unix_socket.rs | 7 +- 11 files changed, 276 insertions(+), 40 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 1478222..8de0a3d 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -1277,6 +1277,7 @@ dependencies = [ "tokio-io", "toml", "tracing", + "tracing-core", "tracing-subscriber", "uuid", "wasm-bindgen", diff --git a/Cargo.toml b/Cargo.toml index 93ef505..10583fd 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -58,6 +58,7 @@ dyn-clone = "1.0.17" tokio-core = "0.1.18" tokio-io = "0.1.13" ciborium-io = "0.2.2" +tracing-core = "0.1.32" #tokio-stream = { version = "0.1.9", optional = true } #derive_more = "0.99.17" diff --git a/src/core/instance/mod.rs b/src/core/instance/mod.rs index 9aa377c..205ff2a 100644 --- a/src/core/instance/mod.rs +++ b/src/core/instance/mod.rs @@ -160,7 +160,7 @@ impl Instance { } pub fn migrate_to_store(&self, new_store: Box) -> MizeResult<()> { - println!("MIGRATING"); + info!("MIGRATING"); let mut old_store = self.store.lock()?; let id = self.id_from_string("0".to_owned())?; diff --git a/src/core/instance/updater.rs b/src/core/instance/updater.rs index 2c2035a..2958d01 100644 --- a/src/core/instance/updater.rs +++ b/src/core/instance/updater.rs @@ -57,8 +57,6 @@ pub fn handle_operation(operation: &mut Operation, instance: &Instance) -> MizeR //check subs and handle them let mut subs_inner = instance.subs.lock()?; - println!("goooooooooooooooooot some subs: {:?}", subs_inner); - println!("some subs id: {:?}", id); if let Some(vec) = subs_inner.get_mut(&id) { let update = Update { instance: Arc::new(instance.to_owned()), diff --git a/src/core/item.rs b/src/core/item.rs index 7609386..576c601 100644 --- a/src/core/item.rs +++ b/src/core/item.rs @@ -1,6 +1,7 @@ use tracing::{debug, error, info, instrument, trace, warn, Instrument}; use serde::Serialize; use core::fmt; +use std::fmt::Debug; use std::{i128, string}; use std::{collections::HashMap, path::PathBuf, io::Cursor, fmt::Display}; use std::fs::File; @@ -105,16 +106,17 @@ impl Item<'_> { } } - pub fn merge>(&mut self, mut value: V) -> MizeResult<()> { + #[instrument(name = "fn.ItemData::merge")] + pub fn merge + Debug >(&mut self, mut value: V) -> MizeResult<()> { let mut data = self.as_data_full()?; - println!("item::merge data: {:?}", data); - println!("item::merge id: {:?}", self.id()); + trace!("item::merge data: {:?}", data); + trace!("item::merge id: {:?}", self.id()); let new_data = value.into(); data.merge(new_data); - println!("item::merge new_data: {:?}", data); + trace!("item::merge new_data: {:?}", data); if self.instance.we_are_namespace()? { let store_inner = self.instance.store.lock()?; @@ -212,7 +214,6 @@ pub fn item_data_get_path(data: &CborValue, path: Vec) -> MizeResult<&Cb //println!("path_el: {}", path_el); if let CborValue::Text(key_str) = key { if key_str == &path_el { - println!("setting sub_data to: {:?}", val); sub_data = val; } } @@ -332,7 +333,7 @@ pub fn item_data_merge(merge_into: &mut CborValue, other: &CborValue){ } } -#[instrument] +#[instrument(name = "fn.get_raw_from_cbor")] pub fn get_raw_from_cbor<'a>(value: &'a CborValue, path: Vec<&String>) -> MizeResult<&'a [u8]> { trace!("[ {} ] value: {:?}", "ARG".yellow(), value); trace!("[ {} ] path: {:?}", "ARG".yellow(), path); diff --git a/src/core/memstore.rs b/src/core/memstore.rs index a475776..c50c098 100644 --- a/src/core/memstore.rs +++ b/src/core/memstore.rs @@ -44,14 +44,14 @@ impl Store for MemStore { Ok(Vec::new()) } fn new_id(&self) -> MizeResult { - println!("are we hereeeeeee memstore new_get"); let mut inner = self.inner.lock()?; let id_string = format!("{}", inner.next_id); inner.next_id += 1; return Ok(id_string); } - #[instrument(name="MemStore::get_value_raw" skip(self))] + + #[instrument(name="fn.MemStore::get_value_raw" skip(self))] fn get_value_raw(&self, id: MizeId) -> MizeResult> { trace!("[ {} ] id: {:?}", "ARG".yellow(), id); let inner = self.inner.lock()?; @@ -90,7 +90,6 @@ impl Store for MemStore { } fn next_id(&self, prev_id_str: &str) -> MizeResult> { - println!("next_id: prev_id_str: {}", prev_id_str); let inner = self.inner.lock()?; let mut id = str_to_u64(prev_id_str)?; diff --git a/src/platform/os/cli/show.rs b/src/platform/os/cli/show.rs index a037c84..0a9e161 100644 --- a/src/platform/os/cli/show.rs +++ b/src/platform/os/cli/show.rs @@ -18,11 +18,11 @@ pub fn show(sub_matches: &ArgMatches) -> MizeResult<()> { let sub = Subscription::from_sender(tx); instance.sub(id, sub)?; - println!("ItemData: {}", item.as_data_full()?); + println!("item: {}", item.as_data_full()?); for update in rx { println!("####### GOT UPDATE #######"); - println!("ItemData: {}", update.new_item()?.as_data_full()?); + println!("item: {}", update.new_item()?.as_data_full()?); } Ok(()) diff --git a/src/platform/os/fsstore.rs b/src/platform/os/fsstore.rs index 64aaec7..b7463aa 100644 --- a/src/platform/os/fsstore.rs +++ b/src/platform/os/fsstore.rs @@ -50,9 +50,7 @@ impl FileStore { } pub fn store_is_opened(store_path: String) -> MizeResult { - println!("valid_pid_file: {}", valid_pid_file(Path::new(&store_path))?.is_some()); let res = valid_pid_file(Path::new(&store_path))?.is_some(); - println!("after fn"); Ok(res) } } @@ -65,7 +63,6 @@ impl Store for FileStore { .parse() .mize_result_msg(format!("could not parse next_id at '{}' to u64", self.path.display()))?; - println!("nextid fsstore: {}", next_id); let id_string = format!("{}", next_id); next_id += 1; @@ -76,9 +73,7 @@ impl Store for FileStore { } fn set(&self, id: MizeId, data: ItemData) -> MizeResult<()> { - println!("setting: {:?}", id); let path = self.path.join("store").join(id.namespace_str()).join(id.store_part()); - println!("path: {:?}", &path); fs::create_dir_all(self.path.join("store").join(id.namespace_str()))?; let file = OpenOptions::new().write(true).create(true).open(path)?; @@ -113,7 +108,6 @@ impl Store for FileStore { fn get_value_data_full(&self, id: MizeId) -> MizeResult { let file_path = self.path.join("store").join(id.namespace_str()).join(id.store_part()); - println!("file_path: {:?}", file_path.display()); if !file_path.exists() { } diff --git a/src/platform/os/logging.rs b/src/platform/os/logging.rs index 849b3c7..3290050 100644 --- a/src/platform/os/logging.rs +++ b/src/platform/os/logging.rs @@ -1,16 +1,17 @@ +use std::collections::HashMap; use std::path::PathBuf; use clap::{ArgAction, ArgMatches}; use clap::{Arg, crate_version, Command}; use mize::error::{MizeError, MizeResult}; +use mize::id::MizeId; use mize::item::ItemData; -use tokio::sync::{Mutex, mpsc}; +use tokio::sync::mpsc; +use std::sync::Mutex; use std::sync::Arc; -use std::io::Write; use colored::Colorize; use std::env; -use tracing_subscriber::fmt::Subscriber; -use tracing::Level; +use tracing::{span_enabled, Instrument, Level}; use tracing::level_filters::LevelFilter; use tracing_subscriber::filter::EnvFilter; use tracing_subscriber::fmt::FormatEvent; @@ -26,6 +27,12 @@ use tracing::{trace, debug, info, warn, error}; use crate::DEFAULT_LOG_LEVEL; +use std::sync::atomic::AtomicUsize; + +use tracing::{field::Visit, Id, Subscriber}; +use tracing_core::Field; +use std::fmt::Write; + pub fn init_logger(cli_matches: &ArgMatches) { // to save log messages, before the logger is setup @@ -34,7 +41,7 @@ pub fn init_logger(cli_matches: &ArgMatches) { log_messages.push((Level::INFO, "Starting Mize".to_owned())); // builder with DEFAULT_LOG_LEVEL - let mut builder = tracing_subscriber::fmt::Subscriber::builder(); + //let mut builder = tracing_subscriber::fmt::Subscriber::builder(); // set loglevel let mut log_level = DEFAULT_LOG_LEVEL; @@ -117,19 +124,21 @@ pub fn init_logger(cli_matches: &ArgMatches) { log_messages.push((Level::INFO, format!("loglevel is now {}", log_level))); // filter loging - let mut my_env_filter = tracing_subscriber::filter::EnvFilter::new("") - .add_directive("[get_raw_from_cbor]=debug".parse().expect("error parsing log directive")) + //let mut my_env_filter = tracing_subscriber::filter::EnvFilter::new("") + //.add_directive("[get_raw_from_cbor]=debug".parse().expect("error parsing log directive")) //.add_directive("[MemStore::get_value_raw]=trace".parse().expect("error parsing log directive")) - .add_directive("trace".parse().unwrap()) - .add_directive("[get_raw_from_cbor]=debug".parse().expect("error parsing log directive")) - ; + //.add_directive("trace".parse().unwrap()) + //.add_directive("[get_raw_from_cbor]=debug".parse().expect("error parsing log directive")) + //; - builder - .with_env_filter(my_env_filter) - .without_time() - .event_format(MyFormatter) + MinimalTracer::register(); + + //builder + //.with_env_filter(my_env_filter) + //.without_time() + //.event_format(MyFormatter) //.with_max_level(log_level) - .init(); + //.init(); // write out all log messages from log_messages @@ -255,3 +264,238 @@ where writeln!(writer) } } + +// thanks: https://stackoverflow.com/a/75546824 +pub struct StringVisitor<'a> { + string: &'a mut String, +} +impl<'a> StringVisitor<'a> { + pub(crate) fn new(string: &'a mut String) -> Self { + StringVisitor { string } + } +} + +impl<'a> Visit for StringVisitor<'a> { + fn record_debug(&mut self, field: &Field, value: &dyn fmt::Debug) { + if field.name() == "message" { + write!(self.string, "{value:?} ").unwrap(); + } else { + write!(self.string, "{} = {:?}; ", field.name(), value).unwrap(); + } + } +} + +struct LogFilter { + target: Option, + level: Option, +} + +pub struct MinimalTracer { + enabled: bool, + filters: Vec, + level: Arc>, + spans: Arc>>, + span_levels: Arc>>, + span_names: Arc>>, + span_names_to_enable: Arc>>, + level_no_span: Level, +} + +fn string_to_level(string: &str) -> Option { + match string.to_lowercase().as_str() { + "info" => Some(Level::INFO), + "debug" => Some(Level::DEBUG), + "warn" | "warning" => Some(Level::WARN), + "trace" => Some(Level::TRACE), + "error" => Some(Level::ERROR), + _ => None, + } +} + +impl MinimalTracer { + pub fn register() -> Result<(), tracing::subscriber::SetGlobalDefaultError> { + let mut enabled = true; + let mut span_names_to_enable = Vec::new(); + let mut my_level = Level::INFO; + + let mut filters: Vec = Vec::with_capacity(10); + if let Ok(env_value) = env::var("RUST_LOG") { + for filter in env_value.split(',') { + let mut target = Some(filter); + let mut level = None; + if let Some(equals_index) = target.unwrap().find('=') { + let (first, second) = filter.split_at(equals_index); + target = Some(first); + level = string_to_level(&second[1..]) + } else { + my_level = string_to_level(target.unwrap()).unwrap(); + } + let target_level = string_to_level(target.unwrap()); + + //if let Some(target_level) = target_level { + //level = Some(target_level); + //target = None; + //} + + // in case target is a span name, add id to span_names_to_enable + // for now every target is also a span_name..... + // i would think everything, that contains a "." would be a span, and not a module + // targeet + if let Some(name) = target { + span_names_to_enable.push(name.to_owned()); + } + + filters.push(LogFilter { + target: target.map(|v| v.to_string()), + level, + }); + } + } else { + enabled = false; + } + + tracing::subscriber::set_global_default(MinimalTracer { + enabled, filters, + spans: Arc::new(Mutex::new(Vec::new())), + level: Arc::new(Mutex::new(my_level)), + span_names: Arc::new(Mutex::new(HashMap::new())), + span_names_to_enable: Arc::new(Mutex::new(span_names_to_enable)), + span_levels: Arc::new(Mutex::new(HashMap::new())), + level_no_span: my_level, + }) + } +} + +static AUTO_ID: AtomicUsize = AtomicUsize::new(1); + +impl Subscriber for MinimalTracer { + fn enabled(&self, metadata: &tracing::Metadata<'_>) -> bool { + return true; + + if metadata.is_span() { + return true; + let mut span_names_to_enable = self.span_names_to_enable.lock().unwrap(); + if span_names_to_enable.contains(&metadata.name().to_owned()) { + return true; + } + } + + if self.enabled { + if self.filters.is_empty() { + return true; + } + + let mut matches: bool; + for filter in &self.filters { + matches = true; + if let Some(level) = filter.level { + if metadata.level() != &level { + matches = false; + } + } + if let Some(target) = &filter.target { + if !metadata.target().starts_with(target) { + matches = false; + } + } + if matches { + return true; + } + } + return false; + } + false + } + + fn new_span(&self, _span: &tracing_core::span::Attributes<'_>) -> tracing_core::span::Id { + let mut span_names = self.span_names.lock().unwrap(); + let mut span_levels = self.span_levels.lock().unwrap(); + let mut span_names_to_enable = self.span_names_to_enable.lock().unwrap(); + + let id = Id::from_u64(AUTO_ID.fetch_add(1, std::sync::atomic::Ordering::Relaxed) as u64); + let span_name = _span.metadata().name().to_string(); + + span_names.insert(id.clone(), span_name.clone()); + if span_names_to_enable.contains(&span_name) { + span_levels.insert(id.clone(), Level::TRACE); + } else { + span_levels.insert(id.clone(), Level::ERROR); + } + + id + } + + fn record(&self, _span: &tracing_core::span::Id, _values: &tracing_core::span::Record<'_>) { + } + + fn record_follows_from( + &self, + _span: &tracing_core::span::Id, + _follows: &tracing_core::span::Id, + ) { + } + + fn event(&self, event: &tracing::Event<'_>) { + let metadata = event.metadata(); + + let level = metadata.level(); + let my_level = self.level.lock().unwrap(); + + //println!("uuuuuuuuuuuu event name: {}", metadata.name()); + //println!("uuuuuuuuuuuu my_level: {}", my_level); + //println!("uuuuuuuuuuuu event level: {}", level); + + if *level > *my_level { + //println!("uuuuuuuuuuuu comparison"); + //println!("BLOCKED EVENT") + return; + } + + let target = metadata.target(); + + let mut text = String::new(); + + let mut visitor = StringVisitor::new(&mut text); + event.record(&mut visitor); + + let level_str = match metadata.level() { + &Level::TRACE => format!("[ {} ]", "TRACE".yellow()), + &Level::DEBUG => format!("[ {} ]", "DEBUG".green()), + &Level::INFO => format!("[ {} ]", "INFO".blue()), + &Level::WARN => format!("[ {} ]", "WARN".truecolor(245, 164, 66)), + &Level::ERROR => format!("[ {} ]", "ERROR".red()), + }; + + //println!("{} {:?}", "META:".red(), metadata.in_current_span()); + let mut spans = self.spans.lock().unwrap(); + let mut span_names = self.span_names.lock().unwrap(); + let span_text = spans.iter() + .map(|id| span_names.get(id).unwrap().to_owned()) + .collect::>() + .join("::"); + println!("{level_str} {span_text} {text}"); + } + + fn enter(&self, _span: &tracing_core::span::Id) { + //println!("eeeeeeeeeeeeeeeee enter"); + let mut spans = self.spans.lock().unwrap(); + let mut level = self.level.lock().unwrap(); + let mut span_levels = self.span_levels.lock().unwrap(); + let mut span_names = self.span_names.lock().unwrap(); + + let name = span_names.get(_span).unwrap().to_owned(); + *level = span_levels.get(_span).unwrap().to_owned(); + spans.push(_span.clone()); + //println!("my_level is now: {}", level); + } + + fn exit(&self, _span: &tracing_core::span::Id) { + //println!("eeeeeeeeeeeeeeeee exit"); + + let mut level = self.level.lock().unwrap(); + *level = self.level_no_span; + + let mut spans = self.spans.lock().unwrap(); + spans.pop(); + } +} diff --git a/src/platform/os/mod.rs b/src/platform/os/mod.rs index d31c162..309a8f9 100644 --- a/src/platform/os/mod.rs +++ b/src/platform/os/mod.rs @@ -63,7 +63,6 @@ pub fn os_instance_init(instance: &mut Instance) -> MizeResult<()> { ////// if a config.store_path is set, upgrade to the filestore there let mut test = instance.get("0")?.as_data_full()?; - println!("os::Mod test: {}", test); let mut store_path = instance.get("0/config/store_path")?.value_string()?; if store_path == "" { diff --git a/src/platform/os/unix_socket.rs b/src/platform/os/unix_socket.rs index 85871c4..b7ebd5d 100644 --- a/src/platform/os/unix_socket.rs +++ b/src/platform/os/unix_socket.rs @@ -5,7 +5,7 @@ use tokio::net::unix::{OwnedReadHalf, OwnedWriteHalf}; use tokio::io::{Interest, AsyncReadExt, AsyncWriteExt}; use crossbeam::channel::{Receiver, Sender, unbounded}; use ciborium::Value as CborValue; -use tracing::{info, warn}; +use tracing::{info, warn, debug}; use crate::instance::connection::{ConnListener, Connection}; use crate::instance::{self, Instance}; @@ -122,7 +122,7 @@ async fn unix_listen(listener: UnixListener, mut instance: Instance) -> MizeResu fn unix_outgoing(mut unix_write: OwnedWriteHalf, send_rx: Receiver, mut instance: Instance, conn_id: u64) -> MizeResult<()> { for msg in send_rx { - println!("unix outgoing got msg: {}", msg); + debug!("unix outgoing got msg: {}", msg); let adapter = MyCiboriumWriter { inner: &mut unix_write, instance: &mut instance }; let value = msg.value(); ciborium::into_writer(&value, adapter)? @@ -139,8 +139,7 @@ fn unix_incomming(mut unix_read: OwnedReadHalf, mut instance: Instance, conn_id: break; } let msg = MizeMessage::new(value, conn_id); - println!("unix incoming got msg: {}", msg); - println!("op channel len: {}", instance.op_tx.len()); + debug!("unix incoming got msg: {}", msg); instance.got_msg(msg); } Ok(())