From e3a99d41ebaa9770617a2a3323a67e13c2feec8b Mon Sep 17 00:00:00 2001 From: Fletcher Nichol Date: Tue, 6 Feb 2024 18:33:22 -0700 Subject: [PATCH] chore: revisit telemetry tracing levels to make debugging easier This change updates the tracing from 5 prescribed levels to 7. This means that before there were a max of 4 `-v` levels and now there are 6. Additionally, the `TelemetryConfig` has 2 new values that influence the tracing levels in addition to `app_modules`: - `interesting_modules`: a `Vec` of Rust crate/module names that are not strictly the server's library code but rather "crates of interest" the application. For example, we care about `si-data-nats` when looking at the Veritech server as it's driven primarily via NATS. The default is an empty collection of modules. - `never_modules`: a `Vec` of Rust crate/module names that will never be logged/transmitted/considered when setting levels. In other words, these modules are always set to `NAME=off` at any verbosity level. After operating our services several Rust crates demonstrated themselves to be extremely chatty at `DEBUG` and `TRACE` levels and the value we derive from this logging is low to nothing. By default a couple of initial crates are supplied here, namely `h2` and `hyper`. So now there are 4 groups of modules to consider: 1. app modules 2. interesting modules 3. never modules 4. all other modules The updated tracing level increases work as follows: 1. `INFO` for all modules (the default for all services) 2. `DEBUG` for app modules and `INFO` for all others 3. `DEBUG` for app and interesting modules, and `INFO` for all others 4. `TRACE` for app modules, `DEBUG` for interesting modules, and `INFO` for all others 5. `TRACE` for app modules, `TRACE` for interesting modules, and `INFO` for all others 6. `TRACE` for app and interesting modules, and `DEBUG` for all others 7. `TRACE` for all modules Signed-off-by: Fletcher Nichol --- bin/council/src/args.rs | 2 +- bin/council/src/main.rs | 1 + bin/cyclone/src/args.rs | 2 +- bin/cyclone/src/main.rs | 1 + bin/module-index/src/args.rs | 2 +- bin/module-index/src/main.rs | 1 + bin/pinga/src/args.rs | 2 +- bin/pinga/src/main.rs | 1 + bin/sdf/src/args.rs | 2 +- bin/sdf/src/main.rs | 1 + bin/veritech/src/args.rs | 2 +- bin/veritech/src/main.rs | 1 + lib/telemetry-application-rs/src/lib.rs | 174 +++++++++++++++--------- lib/telemetry-rs/src/lib.rs | 51 +++++-- 14 files changed, 161 insertions(+), 82 deletions(-) diff --git a/bin/council/src/args.rs b/bin/council/src/args.rs index 33674cc50a..d08b42e858 100644 --- a/bin/council/src/args.rs +++ b/bin/council/src/args.rs @@ -15,7 +15,7 @@ pub(crate) fn parse() -> Args { pub(crate) struct Args { /// Sets the verbosity mode. /// - /// Multiple -v options increase verbosity. The maximum is 4. + /// Multiple -v options increase verbosity. The maximum is 6. #[arg(short = 'v', long = "verbose", action = ArgAction::Count)] pub(crate) verbose: u8, diff --git a/bin/council/src/main.rs b/bin/council/src/main.rs index f43d972706..1c25fe5d2f 100644 --- a/bin/council/src/main.rs +++ b/bin/council/src/main.rs @@ -39,6 +39,7 @@ async fn async_main() -> Result<()> { .service_namespace("si") .log_env_var_prefix("SI") .app_modules(vec!["council", "council_server"]) + .interesting_modules(vec!["si_data_nats"]) .build()?; telemetry_application::init(config, &task_tracker, shutdown_token.clone())? diff --git a/bin/cyclone/src/args.rs b/bin/cyclone/src/args.rs index 31cd6e0ff2..3fc62a65f3 100644 --- a/bin/cyclone/src/args.rs +++ b/bin/cyclone/src/args.rs @@ -20,7 +20,7 @@ pub(crate) fn parse() -> Args { pub(crate) struct Args { /// Sets the verbosity mode. /// - /// Multiple -v options increase verbosity. The maximum is 4. + /// Multiple -v options increase verbosity. The maximum is 6. #[arg(short = 'v', long = "verbose", action = ArgAction::Count)] pub(crate) verbose: u8, diff --git a/bin/cyclone/src/main.rs b/bin/cyclone/src/main.rs index 3e8fe54f9a..bd71a4ba33 100644 --- a/bin/cyclone/src/main.rs +++ b/bin/cyclone/src/main.rs @@ -33,6 +33,7 @@ async fn main() -> Result<()> { .service_namespace("si") .log_env_var_prefix("SI") .app_modules(vec!["cyclone", "cyclone_server"]) + .interesting_modules(vec!["cyclone_core"]) .custom_default_tracing_level(CUSTOM_DEFAULT_TRACING_LEVEL) .build()?; diff --git a/bin/module-index/src/args.rs b/bin/module-index/src/args.rs index 9b6025c242..ff3aecb7d2 100644 --- a/bin/module-index/src/args.rs +++ b/bin/module-index/src/args.rs @@ -17,7 +17,7 @@ pub(crate) fn parse() -> Args { pub(crate) struct Args { /// Sets the verbosity mode. /// - /// Multiple -v options increase verbosity. The maximum is 4. + /// Multiple -v options increase verbosity. The maximum is 6. #[arg(short = 'v', long = "verbose", action = ArgAction::Count)] pub(crate) verbose: u8, diff --git a/bin/module-index/src/main.rs b/bin/module-index/src/main.rs index 3e8b8cefdd..c3f857d98c 100644 --- a/bin/module-index/src/main.rs +++ b/bin/module-index/src/main.rs @@ -39,6 +39,7 @@ async fn async_main() -> Result<()> { .service_namespace("si") .log_env_var_prefix("SI") .app_modules(vec!["module_index", "module_index_server"]) + .interesting_modules(vec!["si_data_pg"]) .build()?; telemetry_application::init(config, &task_tracker, shutdown_token.clone())? diff --git a/bin/pinga/src/args.rs b/bin/pinga/src/args.rs index 6a84d759e0..db522bfa93 100644 --- a/bin/pinga/src/args.rs +++ b/bin/pinga/src/args.rs @@ -17,7 +17,7 @@ pub(crate) fn parse() -> Args { pub(crate) struct Args { /// Sets the verbosity mode. /// - /// Multiple -v options increase verbosity. The maximum is 4. + /// Multiple -v options increase verbosity. The maximum is 6. #[arg(short = 'v', long = "verbose", action = ArgAction::Count)] pub(crate) verbose: u8, diff --git a/bin/pinga/src/main.rs b/bin/pinga/src/main.rs index dfabe2de4e..7a26506e36 100644 --- a/bin/pinga/src/main.rs +++ b/bin/pinga/src/main.rs @@ -39,6 +39,7 @@ async fn async_main() -> Result<()> { .service_namespace("si") .log_env_var_prefix("SI") .app_modules(vec!["pinga", "pinga_server"]) + .interesting_modules(vec!["si_data_nats", "si_data_pg"]) .build()?; telemetry_application::init(config, &task_tracker, shutdown_token.clone())? diff --git a/bin/sdf/src/args.rs b/bin/sdf/src/args.rs index e8c6112074..bb19940f57 100644 --- a/bin/sdf/src/args.rs +++ b/bin/sdf/src/args.rs @@ -19,7 +19,7 @@ pub(crate) fn parse() -> Args { pub(crate) struct Args { /// Sets the verbosity mode. /// - /// Multiple -v options increase verbosity. The maximum is 4. + /// Multiple -v options increase verbosity. The maximum is 6. #[arg(short = 'v', long = "verbose", action = ArgAction::Count)] pub(crate) verbose: u8, diff --git a/bin/sdf/src/main.rs b/bin/sdf/src/main.rs index adba0ff5aa..be7cfdc7b0 100644 --- a/bin/sdf/src/main.rs +++ b/bin/sdf/src/main.rs @@ -50,6 +50,7 @@ async fn async_main() -> Result<()> { .service_namespace("si") .log_env_var_prefix("SI") .app_modules(vec!["sdf", "sdf_server"]) + .interesting_modules(vec!["si_data_nats", "si_data_pg"]) .build()?; telemetry_application::init(config, &task_tracker, shutdown_token.clone())? diff --git a/bin/veritech/src/args.rs b/bin/veritech/src/args.rs index b5ea74dea4..12f9709ba9 100644 --- a/bin/veritech/src/args.rs +++ b/bin/veritech/src/args.rs @@ -13,7 +13,7 @@ pub(crate) fn parse() -> Args { pub(crate) struct Args { /// Sets the verbosity mode. /// - /// Multiple -v options increase verbosity. The maximum is 4. + /// Multiple -v options increase verbosity. The maximum is 6. #[arg(short = 'v', long = "verbose", action = ArgAction::Count)] pub(crate) verbose: u8, diff --git a/bin/veritech/src/main.rs b/bin/veritech/src/main.rs index 87d9e746f5..266434a8ea 100644 --- a/bin/veritech/src/main.rs +++ b/bin/veritech/src/main.rs @@ -25,6 +25,7 @@ async fn main() -> Result<()> { .service_namespace("si") .log_env_var_prefix("SI") .app_modules(vec!["veritech", "veritech_server"]) + .interesting_modules(vec!["si_data_nats"]) .build()?; telemetry_application::init(config, &task_tracker, shutdown_token.clone())? diff --git a/lib/telemetry-application-rs/src/lib.rs b/lib/telemetry-application-rs/src/lib.rs index 341b606e4b..8c7f7d9dc4 100644 --- a/lib/telemetry-application-rs/src/lib.rs +++ b/lib/telemetry-application-rs/src/lib.rs @@ -57,6 +57,10 @@ pub mod prelude { pub use telemetry::{ApplicationTelemetryClient, TelemetryClient}; } +// Rust crates that will not output span or event telemetry, no matter what the default level is +// set to. In other words, each of these crates/modules will have `MODULE=off` as their value. +const DEFAULT_NEVER_MODULES: &[&str] = &["h2", "hyper"]; + #[remain::sorted] #[derive(Debug, Error)] pub enum Error { @@ -88,9 +92,18 @@ pub struct TelemetryConfig { #[builder(setter(into))] service_namespace: &'static str, - #[builder(default)] + #[builder(setter(each(name = "app_module"), into), default)] app_modules: Vec<&'static str>, + #[builder(setter(each(name = "interesting_module"), into), default)] + interesting_modules: Vec<&'static str>, + + #[builder( + setter(each(name = "never_module"), into), + default = "self.default_never_modules()" + )] + never_modules: Vec<&'static str>, + #[builder(setter(into, strip_option), default = "None")] custom_default_tracing_level: Option, @@ -143,6 +156,10 @@ impl TelemetryConfig { } impl TelemetryConfigBuilder { + fn default_never_modules(&self) -> Vec<&'static str> { + DEFAULT_NEVER_MODULES.to_vec() + } + fn default_log_env_var_prefix( &self, ) -> std::result::Result, TelemetryConfigBuilderError> { @@ -227,7 +244,11 @@ pub fn init( let (subscriber, handles) = tracing_subscriber(&config, &tracing_level, span_events_fmt)?; subscriber.try_init()?; - debug!(?config, "telemetry configuration"); + info!( + ?config, + directives = TracingDirectives::from(&tracing_level).as_str(), + "telemetry configuration" + ); let (client, guard) = create_client(config, tracing_level, handles, tracker, shutdown_token)?; @@ -257,7 +278,12 @@ fn default_tracing_level(config: &TelemetryConfig) -> TracingLevel { if let Some(ref directives) = config.custom_default_tracing_level { TracingLevel::custom(directives) } else { - TracingLevel::new(Verbosity::default(), Some(config.app_modules.as_ref())) + TracingLevel::new( + Verbosity::default(), + Some(config.app_modules.as_ref()), + Some(config.interesting_modules.as_ref()), + Some(config.never_modules.as_ref()), + ) } } @@ -397,6 +423,8 @@ fn create_client( let client = ApplicationTelemetryClient::new( config.app_modules, + config.interesting_modules, + config.never_modules, tracing_level, update_telemetry_tx.clone(), ); @@ -582,8 +610,8 @@ impl TelemetryUpdateTask { info!( task = Self::NAME, - "updated tracing levels to: {:?}", - directives.as_str() + directives = directives.as_str(), + "updated tracing levels", ); Ok(()) @@ -631,7 +659,14 @@ impl From for TracingDirectives { TracingLevel::Verbosity { verbosity, app_modules, - } => Self::new(verbosity, &app_modules), + interesting_modules, + never_modules, + } => Self::new( + verbosity, + &app_modules, + &interesting_modules, + &never_modules, + ), TracingLevel::Custom(custom) => custom.into(), } } @@ -643,70 +678,83 @@ impl From<&TracingLevel> for TracingDirectives { TracingLevel::Verbosity { verbosity, app_modules, - } => Self::new(*verbosity, app_modules), + interesting_modules, + never_modules, + } => Self::new(*verbosity, app_modules, interesting_modules, never_modules), TracingLevel::Custom(custom) => custom.clone().into(), } } } impl TracingDirectives { - fn new(verbosity: Verbosity, app_modules: &Option>>) -> Self { + fn new( + verbosity: Verbosity, + app_modules: &Option>>, + interesting_modules: &Option>>, + never_modules: &Option>>, + ) -> Self { + let app_str = |level: &str| { + app_modules.as_ref().map(|arr| { + arr.iter() + .map(|m| format!("{m}={level}")) + .collect::>() + .join(",") + }) + }; + let interesting_str = |level: &str| { + interesting_modules.as_ref().map(|arr| { + arr.iter() + .map(|m| format!("{m}={level}")) + .collect::>() + .join(",") + }) + }; + let never_str = never_modules.as_ref().map(|arr| { + arr.iter() + .map(|m| format!("{m}=off")) + .collect::>() + .join(",") + }); + + let directives_for = |app_level: &'static str, + interesting_level: &'static str, + default_level: &'static str| { + match ( + app_str(app_level), + interesting_str(interesting_level), + never_str, + ) { + (None, None, None) => Cow::Borrowed(default_level), + (None, None, Some(never)) => Cow::Owned(format!("{never},{default_level}")), + (None, Some(interesting), None) => { + Cow::Owned(format!("{interesting},{default_level}")) + } + (None, Some(interesting), Some(never)) => { + Cow::Owned(format!("{interesting},{never},{default_level}")) + } + (Some(app), None, None) => Cow::Owned(format!("{app},{default_level}")), + (Some(app), None, Some(never)) => { + Cow::Owned(format!("{app},{never},{default_level}")) + } + (Some(app), Some(interesting), None) => { + Cow::Owned(format!("{app},{interesting},{default_level}")) + } + (Some(app), Some(interesting), Some(never)) => { + Cow::Owned(format!("{app},{interesting},{never},{default_level}")) + } + } + }; + let directives = match verbosity { - Verbosity::InfoAll => match &app_modules { - Some(mods) => Cow::Owned(format!( - "{},{}", - "info", - mods.iter() - .map(|m| format!("{m}=info")) - .collect::>() - .join(",") - )), - None => Cow::Borrowed("info"), - }, - Verbosity::DebugAppAndInfoAll => match &app_modules { - Some(mods) => Cow::Owned(format!( - "{},{}", - "info", - mods.iter() - .map(|m| format!("{m}=debug")) - .collect::>() - .join(",") - )), - None => Cow::Borrowed("debug"), - }, - Verbosity::TraceAppAndInfoAll => match &app_modules { - Some(mods) => Cow::Owned(format!( - "{},{}", - "info", - mods.iter() - .map(|m| format!("{m}=trace")) - .collect::>() - .join(",") - )), - None => Cow::Borrowed("trace"), - }, - Verbosity::TraceAppAndDebugAll => match &app_modules { - Some(mods) => Cow::Owned(format!( - "{},{}", - "debug", - mods.iter() - .map(|m| format!("{m}=trace")) - .collect::>() - .join(",") - )), - None => Cow::Borrowed("trace"), - }, - Verbosity::TraceAll => match &app_modules { - Some(mods) => Cow::Owned(format!( - "{},{}", - "trace", - mods.iter() - .map(|m| format!("{m}=trace")) - .collect::>() - .join(",") - )), - None => Cow::Borrowed("trace"), - }, + Verbosity::InfoAll => directives_for("info", "info", "info"), + Verbosity::DebugAppInfoInterestingInfoAll => directives_for("debug", "info", "info"), + Verbosity::DebugAppDebugInterestingInfoAll => directives_for("debug", "debug", "info"), + Verbosity::TraceAppDebugInterestingInfoAll => directives_for("trace", "debug", "info"), + Verbosity::TraceAppTraceInterestingInfoAll => directives_for("trace", "trace", "info"), + Verbosity::TraceAppTraceInterestingDebugAll => { + directives_for("trace", "trace", "debug") + } + Verbosity::TraceAll => directives_for("trace", "trace", "trace"), }; Self(directives) diff --git a/lib/telemetry-rs/src/lib.rs b/lib/telemetry-rs/src/lib.rs index 23e526d230..937a98d861 100644 --- a/lib/telemetry-rs/src/lib.rs +++ b/lib/telemetry-rs/src/lib.rs @@ -178,6 +178,8 @@ pub trait TelemetryLevel: Send + Sync { #[derive(Clone, Debug)] pub struct ApplicationTelemetryClient { app_modules: Arc>, + interesting_modules: Arc>, + never_modules: Arc>, tracing_level: Arc>, update_telemetry_tx: mpsc::UnboundedSender, } @@ -185,11 +187,15 @@ pub struct ApplicationTelemetryClient { impl ApplicationTelemetryClient { pub fn new( app_modules: Vec<&'static str>, + interesting_modules: Vec<&'static str>, + never_modules: Vec<&'static str>, tracing_level: TracingLevel, update_telemetry_tx: mpsc::UnboundedSender, ) -> Self { Self { app_modules: Arc::new(app_modules), + interesting_modules: Arc::new(interesting_modules), + never_modules: Arc::new(never_modules), tracing_level: Arc::new(Mutex::new(tracing_level)), update_telemetry_tx, } @@ -209,7 +215,12 @@ impl TelemetryClient for ApplicationTelemetryClient { *verbosity = updated; } TracingLevel::Custom(_) => { - *tracing_level = TracingLevel::new(updated, Some(self.app_modules.as_slice())); + *tracing_level = TracingLevel::new( + updated, + Some(self.app_modules.as_slice()), + Some(self.interesting_modules.as_slice()), + Some(self.never_modules.as_slice()), + ); } } @@ -327,14 +338,23 @@ pub enum TracingLevel { Verbosity { verbosity: Verbosity, app_modules: Option>>, + interesting_modules: Option>>, + never_modules: Option>>, }, } impl TracingLevel { - pub fn new(verbosity: Verbosity, app_modules: Option) -> Self { + pub fn new( + verbosity: Verbosity, + app_modules: Option, + interesting_modules: Option, + never_modules: Option, + ) -> Self { Self::Verbosity { verbosity, app_modules: app_modules.map(IntoAppModules::into_app_modules), + interesting_modules: interesting_modules.map(IntoAppModules::into_app_modules), + never_modules: never_modules.map(IntoAppModules::into_app_modules), } } @@ -350,15 +370,16 @@ impl TracingLevel { } } -#[remain::sorted] #[derive(Copy, Clone, Debug, Eq, Hash, PartialEq, PartialOrd)] #[allow(clippy::enum_variant_names)] pub enum Verbosity { - DebugAppAndInfoAll, InfoAll, + DebugAppInfoInterestingInfoAll, + DebugAppDebugInterestingInfoAll, + TraceAppDebugInterestingInfoAll, + TraceAppTraceInterestingInfoAll, + TraceAppTraceInterestingDebugAll, TraceAll, - TraceAppAndDebugAll, - TraceAppAndInfoAll, } impl Verbosity { @@ -392,9 +413,11 @@ impl From for Verbosity { fn from(value: u8) -> Self { match value { 0 => Self::InfoAll, - 1 => Self::DebugAppAndInfoAll, - 2 => Self::TraceAppAndInfoAll, - 3 => Self::TraceAppAndDebugAll, + 1 => Self::DebugAppInfoInterestingInfoAll, + 2 => Self::DebugAppDebugInterestingInfoAll, + 3 => Self::TraceAppDebugInterestingInfoAll, + 4 => Self::TraceAppTraceInterestingInfoAll, + 5 => Self::TraceAppTraceInterestingDebugAll, _ => Self::TraceAll, } } @@ -404,10 +427,12 @@ impl From for u8 { fn from(value: Verbosity) -> Self { match value { Verbosity::InfoAll => 0, - Verbosity::DebugAppAndInfoAll => 1, - Verbosity::TraceAppAndInfoAll => 2, - Verbosity::TraceAppAndDebugAll => 3, - Verbosity::TraceAll => 4, + Verbosity::DebugAppInfoInterestingInfoAll => 1, + Verbosity::DebugAppDebugInterestingInfoAll => 2, + Verbosity::TraceAppDebugInterestingInfoAll => 3, + Verbosity::TraceAppTraceInterestingInfoAll => 4, + Verbosity::TraceAppTraceInterestingDebugAll => 5, + Verbosity::TraceAll => 6, } } }