From 7f14c08c340b2f14bc6b949b1765d35004e75fac Mon Sep 17 00:00:00 2001 From: strawberry Date: Sun, 7 Apr 2024 00:13:47 -0400 Subject: [PATCH] admin command to change tracing log level dynamically Signed-off-by: strawberry --- src/database/mod.rs | 10 ++++-- src/main.rs | 69 +++++++++++++++++++++++------------ src/service/admin/debug.rs | 74 ++++++++++++++++++++++++++++++++++++++ src/service/globals/mod.rs | 9 ++++- src/service/mod.rs | 6 +++- 5 files changed, 142 insertions(+), 26 deletions(-) diff --git a/src/database/mod.rs b/src/database/mod.rs index 3ace1ecd..6f057ef0 100644 --- a/src/database/mod.rs +++ b/src/database/mod.rs @@ -206,7 +206,13 @@ struct CheckForUpdatesResponse { impl KeyValueDatabase { /// Load an existing database or create a new one. #[allow(clippy::too_many_lines)] - pub async fn load_or_create(config: Config) -> Result<()> { + pub async fn load_or_create( + config: Config, + tracing_reload_handler: tracing_subscriber::reload::Handle< + tracing_subscriber::EnvFilter, + tracing_subscriber::Registry, + >, + ) -> Result<()> { Self::check_db_setup(&config)?; if !Path::new(&config.database_path).exists() { @@ -369,7 +375,7 @@ impl KeyValueDatabase { let db = Box::leak(db_raw); - let services_raw = Box::new(Services::build(db, &config)?); + let services_raw = Box::new(Services::build(db, &config, tracing_reload_handler)?); // This is the first and only time we initialize the SERVICE static *SERVICES.write().unwrap() = Some(Box::leak(services_raw)); diff --git a/src/main.rs b/src/main.rs index cb042049..27c19454 100644 --- a/src/main.rs +++ b/src/main.rs @@ -38,7 +38,7 @@ use tower_http::{ ServiceBuilderExt as _, }; use tracing::{debug, error, info, warn, Level}; -use tracing_subscriber::{prelude::*, EnvFilter}; +use tracing_subscriber::{prelude::*, reload, EnvFilter, Registry}; mod routes; @@ -51,6 +51,8 @@ struct Server { runtime: tokio::runtime::Runtime, + tracing_reload_handle: reload::Handle, + #[cfg(feature = "sentry_telemetry")] _sentry_guard: Option, } @@ -267,7 +269,7 @@ async fn stop(_server: &Server) -> io::Result<()> { /// Async initializations async fn start(server: &Server) -> Result<(), Error> { let db_load_time = std::time::Instant::now(); - KeyValueDatabase::load_or_create(server.config.clone()).await?; + KeyValueDatabase::load_or_create(server.config.clone(), server.tracing_reload_handle.clone()).await?; info!("Database took {:?} to load", db_load_time.elapsed()); Ok(()) @@ -427,15 +429,24 @@ fn init(args: clap::Args) -> Result { None }; - if config.allow_jaeger { - #[cfg(feature = "perf_measurements")] - init_tracing_jaeger(&config); - } else if config.tracing_flame { - #[cfg(feature = "perf_measurements")] - init_tracing_flame(&config); - } else { - init_tracing_sub(&config); - } + let tracing_reload_handle; + + #[cfg(feature = "perf_measurements")] + { + tracing_reload_handle = if config.allow_jaeger { + init_tracing_jaeger(&config) + } else if config.tracing_flame { + #[cfg(feature = "perf_measurements")] + init_tracing_flame(&config) + } else { + init_tracing_sub(&config) + }; + }; + + #[cfg(not(feature = "perf_measurements"))] + { + tracing_reload_handle = init_tracing_sub(&config); + }; info!( server_name = ?config.server_name, @@ -459,6 +470,8 @@ fn init(args: clap::Args) -> Result { .build() .unwrap(), + tracing_reload_handle, + #[cfg(feature = "sentry_telemetry")] _sentry_guard: sentry_guard, }) @@ -481,8 +494,8 @@ fn init_sentry(config: &Config) -> sentry::ClientInitGuard { )) } -fn init_tracing_sub(config: &Config) { - let registry = tracing_subscriber::Registry::default(); +fn init_tracing_sub(config: &Config) -> reload::Handle { + let registry = Registry::default(); let fmt_layer = tracing_subscriber::fmt::Layer::new(); let filter_layer = match EnvFilter::try_new(&config.log) { Ok(s) => s, @@ -492,6 +505,8 @@ fn init_tracing_sub(config: &Config) { }, }; + let (reload_filter, reload_handle) = reload::Layer::new(filter_layer); + #[cfg(feature = "sentry_telemetry")] let sentry_layer = sentry_tracing::layer(); @@ -501,7 +516,7 @@ fn init_tracing_sub(config: &Config) { #[cfg(feature = "sentry_telemetry")] { subscriber = registry - .with(filter_layer) + .with(reload_filter) .with(fmt_layer) .with(sentry_layer); }; @@ -509,14 +524,16 @@ fn init_tracing_sub(config: &Config) { #[allow(clippy::unnecessary_operation)] // error[E0658]: attributes on expressions are experimental #[cfg(not(feature = "sentry_telemetry"))] { - subscriber = registry.with(filter_layer).with(fmt_layer); + subscriber = registry.with(reload_filter).with(fmt_layer); }; tracing::subscriber::set_global_default(subscriber).unwrap(); + + reload_handle } #[cfg(feature = "perf_measurements")] -fn init_tracing_jaeger(config: &Config) { +fn init_tracing_jaeger(config: &Config) -> reload::Handle { opentelemetry::global::set_text_map_propagator(opentelemetry_jaeger::Propagator::new()); let tracer = opentelemetry_jaeger::new_agent_pipeline() .with_auto_split_batch(true) @@ -533,22 +550,30 @@ fn init_tracing_jaeger(config: &Config) { }, }; - let subscriber = tracing_subscriber::Registry::default() - .with(filter_layer) - .with(telemetry); + let (reload_filter, reload_handle) = reload::Layer::new(filter_layer); + + let subscriber = Registry::default().with(reload_filter).with(telemetry); + tracing::subscriber::set_global_default(subscriber).unwrap(); + + reload_handle } #[cfg(feature = "perf_measurements")] -fn init_tracing_flame(_config: &Config) { - let registry = tracing_subscriber::Registry::default(); +fn init_tracing_flame(_config: &Config) -> reload::Handle { + let registry = Registry::default(); let (flame_layer, _guard) = tracing_flame::FlameLayer::with_file("./tracing.folded").unwrap(); let flame_layer = flame_layer.with_empty_samples(false); let filter_layer = EnvFilter::new("trace,h2=off"); - let subscriber = registry.with(filter_layer).with(flame_layer); + let (reload_filter, reload_handle) = reload::Layer::new(filter_layer); + + let subscriber = registry.with(reload_filter).with(flame_layer); + tracing::subscriber::set_global_default(subscriber).unwrap(); + + reload_handle } // This is needed for opening lots of file descriptors, which tends to diff --git a/src/service/admin/debug.rs b/src/service/admin/debug.rs index 2e0a3b36..e2775c93 100644 --- a/src/service/admin/debug.rs +++ b/src/service/admin/debug.rs @@ -7,6 +7,7 @@ use ruma::{ }; use tokio::sync::RwLock; use tracing::{debug, error, info, warn}; +use tracing_subscriber::EnvFilter; use crate::{api::server_server::parse_incoming_pdu, services, utils::HtmlEscape, Error, PduEvent, Result}; @@ -71,6 +72,18 @@ pub(crate) enum DebugCommand { /// - Forces device lists for all local and remote users to be updated (as /// having new keys available) ForceDeviceListUpdates, + + /// - Change tracing log level/filter on the fly + /// + /// This accepts the same format as the `log` config option. + ChangeLogLevel { + /// Log level/filter + filter: Option, + + /// Resets the log level/filter to the one in your config + #[arg(short, long)] + reset: bool, + }, } pub(crate) async fn process(command: DebugCommand, body: Vec<&str>) -> Result { @@ -354,5 +367,66 @@ pub(crate) async fn process(command: DebugCommand, body: Vec<&str>) -> Result { + if reset { + let old_filter_layer = match EnvFilter::try_new(&services().globals.config.log) { + Ok(s) => s, + Err(e) => { + return Ok(RoomMessageEventContent::text_plain(format!( + "Log level from config appears to be invalid now: {e}" + ))); + }, + }; + + match services() + .globals + .tracing_reload_handle + .modify(|filter| *filter = old_filter_layer) + { + Ok(()) => { + return Ok(RoomMessageEventContent::text_plain(format!( + "Successfully changed log level back to config value {}", + services().globals.config.log + ))); + }, + Err(e) => { + return Ok(RoomMessageEventContent::text_plain(format!( + "Failed to modify and reload the global tracing log level: {e}" + ))); + }, + } + } + + if let Some(filter) = filter { + let new_filter_layer = match EnvFilter::try_new(filter) { + Ok(s) => s, + Err(e) => { + return Ok(RoomMessageEventContent::text_plain(format!( + "Invalid log level filter specified: {e}" + ))); + }, + }; + + match services() + .globals + .tracing_reload_handle + .modify(|filter| *filter = new_filter_layer) + { + Ok(()) => { + return Ok(RoomMessageEventContent::text_plain("Successfully changed log level")); + }, + Err(e) => { + return Ok(RoomMessageEventContent::text_plain(format!( + "Failed to modify and reload the global tracing log level: {e}" + ))); + }, + } + } + + return Ok(RoomMessageEventContent::text_plain("No log level was specified.")); + }, }) } diff --git a/src/service/globals/mod.rs b/src/service/globals/mod.rs index d78f5a12..d01e22cd 100644 --- a/src/service/globals/mod.rs +++ b/src/service/globals/mod.rs @@ -26,6 +26,7 @@ use ruma::{ }; use tokio::sync::{broadcast, watch::Receiver, Mutex, RwLock, Semaphore}; use tracing::{error, info}; +use tracing_subscriber::{EnvFilter, Registry}; use crate::{services, Config, Result}; @@ -42,6 +43,7 @@ type SyncHandle = ( pub struct Service<'a> { pub db: &'static dyn Data, + pub tracing_reload_handle: tracing_subscriber::reload::Handle, pub config: Config, keypair: Arc, jwt_decoding_key: Option, @@ -94,7 +96,10 @@ impl Default for RotationHandler { } impl Service<'_> { - pub fn load(db: &'static dyn Data, config: &Config) -> Result { + pub fn load( + db: &'static dyn Data, config: &Config, + tracing_reload_handle: tracing_subscriber::reload::Handle, + ) -> Result { let keypair = db.load_keypair(); let keypair = match keypair { @@ -135,7 +140,9 @@ impl Service<'_> { argon2::Version::default(), argon2::Params::new(19456, 2, 1, None).expect("valid parameters"), ); + let mut s = Self { + tracing_reload_handle, db, config: config.clone(), keypair: Arc::new(keypair), diff --git a/src/service/mod.rs b/src/service/mod.rs index 1e29eacf..c419c4ac 100644 --- a/src/service/mod.rs +++ b/src/service/mod.rs @@ -56,6 +56,10 @@ impl Services<'_> { + 'static, >( db: &'static D, config: &Config, + tracing_reload_handle: tracing_subscriber::reload::Handle< + tracing_subscriber::EnvFilter, + tracing_subscriber::Registry, + >, ) -> Result { Ok(Self { appservice: appservice::Service::build(db)?, @@ -166,7 +170,7 @@ impl Services<'_> { }, sending: sending::Service::build(db, config), - globals: globals::Service::load(db, config)?, + globals: globals::Service::load(db, config, tracing_reload_handle)?, }) }