From 752ac751d15121edffd39d8bc04133c450624d56 Mon Sep 17 00:00:00 2001 From: stsantilena <12675156+stsantilena@users.noreply.github.com> Date: Mon, 6 Feb 2023 14:42:22 -0800 Subject: [PATCH 1/5] Add additional error type with span trace --- Cargo.lock | 13 +++++++++ bin/Cargo.toml | 1 + bin/src/main.rs | 5 +++- common/fs/Cargo.toml | 1 + common/fs/src/cache/mod.rs | 6 ++--- common/notify_stream/Cargo.toml | 1 + common/notify_stream/src/lib.rs | 48 ++++++++++++++++++++++++--------- 7 files changed, 58 insertions(+), 17 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 1d41cfd5b..5779ec936 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -1059,6 +1059,7 @@ dependencies = [ "tokio-test", "tokio-util", "tracing", + "tracing-error", "tracing-subscriber", "walkdir", "winapi-util", @@ -1983,6 +1984,7 @@ dependencies = [ "tokio-stream", "tokio-test", "tracing", + "tracing-error", "tracing-subscriber", "types", "wait-timeout", @@ -2282,6 +2284,7 @@ dependencies = [ "time 0.3.9", "tokio", "tracing", + "tracing-error", "tracing-subscriber", ] @@ -3865,6 +3868,16 @@ dependencies = [ "valuable", ] +[[package]] +name = "tracing-error" +version = "0.2.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "d686ec1c0f384b1277f097b2f279a2ecc11afe8c133c1aabf036a27cb4cd206e" +dependencies = [ + "tracing", + "tracing-subscriber", +] + [[package]] name = "tracing-log" version = "0.1.3" diff --git a/bin/Cargo.toml b/bin/Cargo.toml index 02986f4a6..37aaaca59 100644 --- a/bin/Cargo.toml +++ b/bin/Cargo.toml @@ -46,6 +46,7 @@ futures = "0.3" tokio = { version = "1", features = ["rt-multi-thread", "signal", "time"] } tokio-stream = "0.1" tracing = "0.1" +tracing-error = "0.2" tracing-subscriber = { version = "0.3", features = ["env-filter"]} pin-utils = "0.1" regex = "1" diff --git a/bin/src/main.rs b/bin/src/main.rs index 62a754ef3..80ad926eb 100644 --- a/bin/src/main.rs +++ b/bin/src/main.rs @@ -2,6 +2,8 @@ use config::{self, Config}; use std::sync::Arc; use tokio::sync::Mutex; use tracing::{debug, info, trace, warn}; +use tracing_error::ErrorLayer; +use tracing_subscriber::layer::SubscriberExt; use tracing_subscriber::{filter::LevelFilter, EnvFilter, FmtSubscriber}; mod _main; @@ -37,7 +39,8 @@ fn main() -> anyhow::Result<()> { .with_writer(std::io::stderr) .finish(); - tracing::subscriber::set_global_default(subscriber).expect("failied to set subscriber"); + tracing::subscriber::set_global_default(subscriber.with(ErrorLayer::default())) + .expect("failied to set subscriber"); info!("running version: {}", env!("CARGO_PKG_VERSION")); diff --git a/common/fs/Cargo.toml b/common/fs/Cargo.toml index b0d1cabfb..9b0db0bdc 100644 --- a/common/fs/Cargo.toml +++ b/common/fs/Cargo.toml @@ -29,6 +29,7 @@ walkdir = "2" #logging lazy_static = "1" tracing = "0.1" +tracing-error = { version = "0.2", feature = ["traced-error"] } tracing-subscriber = "0.3" #async diff --git a/common/fs/src/cache/mod.rs b/common/fs/src/cache/mod.rs index 0b3fd1ba3..7f59f832e 100755 --- a/common/fs/src/cache/mod.rs +++ b/common/fs/src/cache/mod.rs @@ -6,7 +6,7 @@ use crate::lookback::Lookback; use crate::rule::{RuleDef, Rules, Status}; use metrics::Metrics; -use notify_stream::{Event as WatchEvent, RecursiveMode, Watcher}; +use notify_stream::{ContextError, Event as WatchEvent, RecursiveMode, Watcher}; use state::{FileId, Span, SpanVec}; use std::borrow::Cow; @@ -57,7 +57,7 @@ const TAIL_WARN_THRESHOLD_B: u64 = 3000000; #[derive(Debug, Error)] pub enum Error { #[error("error watching: {0:?} {1:?}")] - Watch(Option, notify_stream::Error), + Watch(Option, ContextError), #[error("error need to rescan")] Rescan, #[error("got event for untracked watch descriptor: {0:?}")] @@ -671,7 +671,7 @@ impl FileSystem { "There was an error mapping a file change: {:?} ({:?})", e, p ); - Err(Error::Watch(p.clone(), e.clone())) + Err(Error::Watch(p.clone(), ContextError::new(e.clone()))) } WatchEvent::Rescan => Err(Error::Rescan), }; diff --git a/common/notify_stream/Cargo.toml b/common/notify_stream/Cargo.toml index 50e1b4605..b3aeb1614 100644 --- a/common/notify_stream/Cargo.toml +++ b/common/notify_stream/Cargo.toml @@ -13,6 +13,7 @@ async-channel = "1.6" tokio = { package = "tokio", version = "1", features = ["rt-multi-thread"] } tracing = "0.1" tracing-subscriber = "0.3" +tracing-error = { version = "0.2", feature = ["traced-error"] } [dev-dependencies] env_logger = "0.9" diff --git a/common/notify_stream/src/lib.rs b/common/notify_stream/src/lib.rs index 0dbc1206e..5fd0ee269 100644 --- a/common/notify_stream/src/lib.rs +++ b/common/notify_stream/src/lib.rs @@ -7,6 +7,7 @@ use std::path::Path; use std::rc::Rc; use time::OffsetDateTime; use tracing::{debug, info, instrument, trace}; +use tracing_error::SpanTrace; type PathId = std::path::PathBuf; @@ -83,6 +84,22 @@ pub enum Error { MaxFilesWatch, } +#[derive(Clone, Debug)] +pub struct ContextError { + error: Error, + #[allow(dead_code)] + context: SpanTrace, +} + +impl ContextError { + pub fn new(error: Error) -> Self { + Self { + error, + context: SpanTrace::capture(), + } + } +} + #[derive(Debug)] pub enum RecursiveMode { Recursive, @@ -123,14 +140,14 @@ impl Watcher { /// Adds a new directory or file to watch #[instrument(level = "trace")] - pub fn watch(&mut self, path: &Path, mode: RecursiveMode) -> Result<(), Error> { + pub fn watch(&mut self, path: &Path, mode: RecursiveMode) -> Result<(), ContextError> { trace!("watching {:?}", path); self.watcher.watch(path, mode.into()).map_err(|e| e.into()) } #[instrument(level = "trace")] /// Removes a file or directory - pub fn unwatch(&mut self, path: &Path) -> Result<(), Error> { + pub fn unwatch(&mut self, path: &Path) -> Result<(), ContextError> { trace!("unwatching {:?}", path); self.watcher.unwatch(path).map_err(|e| e.into()) } @@ -139,11 +156,16 @@ impl Watcher { /// /// Returns Ok(true) when watch was found and removed. #[instrument(level = "trace")] - pub fn unwatch_if_exists(&mut self, path: &Path) -> Result { + pub fn unwatch_if_exists(&mut self, path: &Path) -> Result { trace!("unwatching {:?} if it exists", path); - match self.watcher.unwatch(path).map_err(|e| e.into()) { + #[allow(clippy::redundant_closure)] + match self + .watcher + .unwatch(path) + .map_err(|e| >::into(e)) + { Ok(_) => Ok(true), - Err(e) => match e { + Err(e) => match e.error { // Ignore watch not found Error::WatchNotFound => Ok(false), _ => Err(e), @@ -235,15 +257,15 @@ impl Default for Watcher { } } -impl From for Error { - fn from(e: notify::Error) -> Error { +impl From for ContextError { + fn from(e: notify::Error) -> ContextError { match e.kind { - ErrorKind::Generic(s) => Error::Generic(s), - ErrorKind::Io(err) => Error::Io(format!("{}", err)), - ErrorKind::PathNotFound => Error::PathNotFound, - ErrorKind::WatchNotFound => Error::WatchNotFound, - ErrorKind::InvalidConfig(c) => Error::InvalidConfig(c), - ErrorKind::MaxFilesWatch => Error::MaxFilesWatch, + ErrorKind::Generic(s) => ContextError::new(Error::Generic(s)), + ErrorKind::Io(err) => ContextError::new(Error::Io(format!("{}", err))), + ErrorKind::PathNotFound => ContextError::new(Error::PathNotFound), + ErrorKind::WatchNotFound => ContextError::new(Error::WatchNotFound), + ErrorKind::InvalidConfig(c) => ContextError::new(Error::InvalidConfig(c)), + ErrorKind::MaxFilesWatch => ContextError::new(Error::MaxFilesWatch), } } } From cdca6a86150e0db2276b5031b1147eda42ceaa0c Mon Sep 17 00:00:00 2001 From: stsantilena <12675156+stsantilena@users.noreply.github.com> Date: Wed, 8 Feb 2023 16:26:34 -0800 Subject: [PATCH 2/5] Update tracing subscriber layer --- bin/src/main.rs | 15 ++++++++------- common/notify_stream/src/lib.rs | 31 ++++++++++++++++++++++++++++++- 2 files changed, 38 insertions(+), 8 deletions(-) diff --git a/bin/src/main.rs b/bin/src/main.rs index 80ad926eb..93dc3862f 100644 --- a/bin/src/main.rs +++ b/bin/src/main.rs @@ -4,7 +4,8 @@ use tokio::sync::Mutex; use tracing::{debug, info, trace, warn}; use tracing_error::ErrorLayer; use tracing_subscriber::layer::SubscriberExt; -use tracing_subscriber::{filter::LevelFilter, EnvFilter, FmtSubscriber}; +use tracing_subscriber::Registry; +use tracing_subscriber::{filter::LevelFilter, EnvFilter}; mod _main; #[cfg(feature = "dep_audit")] @@ -34,13 +35,13 @@ fn main() -> anyhow::Result<()> { let log_level_env_filter = EnvFilter::builder() .with_default_directive(LevelFilter::INFO.into()) .from_env_lossy(); - let subscriber = FmtSubscriber::builder() - .with_env_filter(log_level_env_filter) - .with_writer(std::io::stderr) - .finish(); + let log_level_layer = tracing_subscriber::fmt::layer().with_writer(std::io::stderr); + let subscriber = Registry::default() + .with(log_level_env_filter) + .with(log_level_layer) + .with(ErrorLayer::default()); - tracing::subscriber::set_global_default(subscriber.with(ErrorLayer::default())) - .expect("failied to set subscriber"); + tracing::subscriber::set_global_default(subscriber).expect("failied to set subscriber"); info!("running version: {}", env!("CARGO_PKG_VERSION")); diff --git a/common/notify_stream/src/lib.rs b/common/notify_stream/src/lib.rs index 5fd0ee269..6e2cf080a 100644 --- a/common/notify_stream/src/lib.rs +++ b/common/notify_stream/src/lib.rs @@ -6,7 +6,7 @@ use notify::{Config, ErrorKind, EventKind, Watcher as NotifyWatcher}; use std::path::Path; use std::rc::Rc; use time::OffsetDateTime; -use tracing::{debug, info, instrument, trace}; +use tracing::{debug, info, instrument, trace, trace_span}; use tracing_error::SpanTrace; type PathId = std::path::PathBuf; @@ -279,6 +279,17 @@ impl From for notify::RecursiveMode { } } +#[instrument(level = "trace")] +fn test_these_span_traces(input: &str) -> Result<(), ContextError> { + let span = trace_span!("test-span"); + let _guard = span.enter(); + trace!("I am tracing"); + Err(ContextError { + error: Error::Generic(input.to_string()), + context: SpanTrace::capture(), + }) +} + #[cfg(test)] mod tests { use super::*; @@ -289,6 +300,7 @@ mod tests { use std::io::{self, Write}; use std::time::Duration; use tempfile::tempdir; + use tracing::{instrument, span, Level}; #[cfg(windows)] use std::sync::mpsc; @@ -348,6 +360,23 @@ mod tests { }; } + #[tokio::test] + #[instrument] + async fn test_context_error_type() { + let span = span!(Level::TRACE, "test-span"); + let _guard = span.enter(); + let error = test_these_span_traces("test-trace"); + trace!("test tracing: {:?}", error); + + //let bt = SpanTrace::capture(); + let context_error = error.err().unwrap(); + println!("ERROR: {:?}", context_error.context.status()); + assert_eq!( + context_error.error, + Error::Generic(String::from("test-trace")) + ); + } + #[tokio::test] #[cfg(unix)] async fn test_unwatch_if_exists() { From 2c9fa9fc60ab9ecab02799af4ed15ef42082d449 Mon Sep 17 00:00:00 2001 From: stsantilena <12675156+stsantilena@users.noreply.github.com> Date: Thu, 9 Feb 2023 16:01:09 -0800 Subject: [PATCH 3/5] Use backtrace capture --- Makefile | 2 +- bin/src/main.rs | 4 +--- common/notify_stream/src/lib.rs | 34 ++++++++------------------------- 3 files changed, 10 insertions(+), 30 deletions(-) diff --git a/Makefile b/Makefile index 8670e664b..fc14da6ca 100644 --- a/Makefile +++ b/Makefile @@ -206,7 +206,7 @@ test: unit-test test-journald ## Run unit tests .PHONY:unit-test unit-test: - $(RUST_COMMAND) "$(BUILD_ENV_DOCKER_ARGS) --env RUST_BACKTRACE=full --env RUST_LOG=$(RUST_LOG)" "cargo nextest run $(TESTS) --no-fail-fast --nocapture" + $(RUST_COMMAND) "$(BUILD_ENV_DOCKER_ARGS) --env RUST_BACKTRACE=full --env RUST_LOG=$(RUST_LOG)" "cargo nextest run test_context_error_type --no-fail-fast --nocapture" .PHONY:unit-test-coverage unit-code-coverage: ## Run code coverage report and output to HTML diff --git a/bin/src/main.rs b/bin/src/main.rs index 93dc3862f..bb07a3914 100644 --- a/bin/src/main.rs +++ b/bin/src/main.rs @@ -2,7 +2,6 @@ use config::{self, Config}; use std::sync::Arc; use tokio::sync::Mutex; use tracing::{debug, info, trace, warn}; -use tracing_error::ErrorLayer; use tracing_subscriber::layer::SubscriberExt; use tracing_subscriber::Registry; use tracing_subscriber::{filter::LevelFilter, EnvFilter}; @@ -38,8 +37,7 @@ fn main() -> anyhow::Result<()> { let log_level_layer = tracing_subscriber::fmt::layer().with_writer(std::io::stderr); let subscriber = Registry::default() .with(log_level_env_filter) - .with(log_level_layer) - .with(ErrorLayer::default()); + .with(log_level_layer); tracing::subscriber::set_global_default(subscriber).expect("failied to set subscriber"); diff --git a/common/notify_stream/src/lib.rs b/common/notify_stream/src/lib.rs index 6e2cf080a..79358afec 100644 --- a/common/notify_stream/src/lib.rs +++ b/common/notify_stream/src/lib.rs @@ -3,11 +3,11 @@ extern crate notify; use futures::{stream, Stream}; use notify::event::{CreateKind, DataChange, ModifyKind, RemoveKind, RenameMode}; use notify::{Config, ErrorKind, EventKind, Watcher as NotifyWatcher}; +use std::backtrace::Backtrace; use std::path::Path; use std::rc::Rc; use time::OffsetDateTime; -use tracing::{debug, info, instrument, trace, trace_span}; -use tracing_error::SpanTrace; +use tracing::{debug, info, instrument, trace}; type PathId = std::path::PathBuf; @@ -84,18 +84,18 @@ pub enum Error { MaxFilesWatch, } -#[derive(Clone, Debug)] +#[derive(Debug)] pub struct ContextError { error: Error, #[allow(dead_code)] - context: SpanTrace, + context: Backtrace, } impl ContextError { pub fn new(error: Error) -> Self { Self { error, - context: SpanTrace::capture(), + context: Backtrace::capture(), } } } @@ -279,28 +279,17 @@ impl From for notify::RecursiveMode { } } -#[instrument(level = "trace")] -fn test_these_span_traces(input: &str) -> Result<(), ContextError> { - let span = trace_span!("test-span"); - let _guard = span.enter(); - trace!("I am tracing"); - Err(ContextError { - error: Error::Generic(input.to_string()), - context: SpanTrace::capture(), - }) -} - #[cfg(test)] mod tests { use super::*; use futures::StreamExt; use pin_utils::pin_mut; + use std::backtrace::BacktraceStatus; use std::fs::{self, File}; use std::io::{self, Write}; use std::time::Duration; use tempfile::tempdir; - use tracing::{instrument, span, Level}; #[cfg(windows)] use std::sync::mpsc; @@ -361,16 +350,9 @@ mod tests { } #[tokio::test] - #[instrument] async fn test_context_error_type() { - let span = span!(Level::TRACE, "test-span"); - let _guard = span.enter(); - let error = test_these_span_traces("test-trace"); - trace!("test tracing: {:?}", error); - - //let bt = SpanTrace::capture(); - let context_error = error.err().unwrap(); - println!("ERROR: {:?}", context_error.context.status()); + let context_error = ContextError::new(Error::Generic("test-trace".to_string())); + assert_eq!(context_error.context.status(), BacktraceStatus::Captured); assert_eq!( context_error.error, Error::Generic(String::from("test-trace")) From 596562b9a32f09239ecb78c0e2f3e477eb9e0354 Mon Sep 17 00:00:00 2001 From: stsantilena <12675156+stsantilena@users.noreply.github.com> Date: Thu, 9 Feb 2023 16:37:34 -0800 Subject: [PATCH 4/5] Update config and makefile --- Cargo.lock | 2 -- Makefile | 2 +- bin/Cargo.toml | 1 - common/fs/Cargo.toml | 1 - 4 files changed, 1 insertion(+), 5 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 5779ec936..8571ce8d3 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -1059,7 +1059,6 @@ dependencies = [ "tokio-test", "tokio-util", "tracing", - "tracing-error", "tracing-subscriber", "walkdir", "winapi-util", @@ -1984,7 +1983,6 @@ dependencies = [ "tokio-stream", "tokio-test", "tracing", - "tracing-error", "tracing-subscriber", "types", "wait-timeout", diff --git a/Makefile b/Makefile index fc14da6ca..8670e664b 100644 --- a/Makefile +++ b/Makefile @@ -206,7 +206,7 @@ test: unit-test test-journald ## Run unit tests .PHONY:unit-test unit-test: - $(RUST_COMMAND) "$(BUILD_ENV_DOCKER_ARGS) --env RUST_BACKTRACE=full --env RUST_LOG=$(RUST_LOG)" "cargo nextest run test_context_error_type --no-fail-fast --nocapture" + $(RUST_COMMAND) "$(BUILD_ENV_DOCKER_ARGS) --env RUST_BACKTRACE=full --env RUST_LOG=$(RUST_LOG)" "cargo nextest run $(TESTS) --no-fail-fast --nocapture" .PHONY:unit-test-coverage unit-code-coverage: ## Run code coverage report and output to HTML diff --git a/bin/Cargo.toml b/bin/Cargo.toml index 37aaaca59..02986f4a6 100644 --- a/bin/Cargo.toml +++ b/bin/Cargo.toml @@ -46,7 +46,6 @@ futures = "0.3" tokio = { version = "1", features = ["rt-multi-thread", "signal", "time"] } tokio-stream = "0.1" tracing = "0.1" -tracing-error = "0.2" tracing-subscriber = { version = "0.3", features = ["env-filter"]} pin-utils = "0.1" regex = "1" diff --git a/common/fs/Cargo.toml b/common/fs/Cargo.toml index 9b0db0bdc..b0d1cabfb 100644 --- a/common/fs/Cargo.toml +++ b/common/fs/Cargo.toml @@ -29,7 +29,6 @@ walkdir = "2" #logging lazy_static = "1" tracing = "0.1" -tracing-error = { version = "0.2", feature = ["traced-error"] } tracing-subscriber = "0.3" #async From 08613b3d6d52f894e966a36cb923fff349e9db18 Mon Sep 17 00:00:00 2001 From: stsantilena <12675156+stsantilena@users.noreply.github.com> Date: Thu, 9 Feb 2023 16:46:25 -0800 Subject: [PATCH 5/5] Update config --- Cargo.lock | 11 ----------- common/notify_stream/Cargo.toml | 1 - 2 files changed, 12 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 8571ce8d3..1d41cfd5b 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -2282,7 +2282,6 @@ dependencies = [ "time 0.3.9", "tokio", "tracing", - "tracing-error", "tracing-subscriber", ] @@ -3866,16 +3865,6 @@ dependencies = [ "valuable", ] -[[package]] -name = "tracing-error" -version = "0.2.0" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "d686ec1c0f384b1277f097b2f279a2ecc11afe8c133c1aabf036a27cb4cd206e" -dependencies = [ - "tracing", - "tracing-subscriber", -] - [[package]] name = "tracing-log" version = "0.1.3" diff --git a/common/notify_stream/Cargo.toml b/common/notify_stream/Cargo.toml index b3aeb1614..50e1b4605 100644 --- a/common/notify_stream/Cargo.toml +++ b/common/notify_stream/Cargo.toml @@ -13,7 +13,6 @@ async-channel = "1.6" tokio = { package = "tokio", version = "1", features = ["rt-multi-thread"] } tracing = "0.1" tracing-subscriber = "0.3" -tracing-error = { version = "0.2", feature = ["traced-error"] } [dev-dependencies] env_logger = "0.9"