From c4bfbd0f4423a933cb24ea091746545a559aeb3a Mon Sep 17 00:00:00 2001 From: Stefan Ceriu Date: Thu, 9 Jan 2025 18:08:44 +0200 Subject: [PATCH] feat(ffi): move tracing setup from the final client to the ffi layer (#4492) Having the final clients define the tracing filters / log levels proved to be tricky to keep in check resulting missing logs (e.g. recently introduced modules like the event cache) or unexpected behaviors (e.g. missing panics because we don't set a global filter). As such we decided to move the tracing setup and default definitions over to the rust side and let rust developers have full control over them. We will now take a general log level and optional extra targets and apply them on top of the rust side defined defaults. Targets that log more than the requested by default will remain unchanged while the others will increase their log levels to match. Certain targets like `hyper` will be ignored in this step as they're too verbose others like `matrix_sdk` because they're too generic. --- bindings/matrix-sdk-ffi/src/platform.rs | 198 +++++++++++++++++++----- bindings/matrix-sdk-ffi/src/tracing.rs | 10 ++ 2 files changed, 170 insertions(+), 38 deletions(-) diff --git a/bindings/matrix-sdk-ffi/src/platform.rs b/bindings/matrix-sdk-ffi/src/platform.rs index 009d3c501fb..95cccccdfa5 100644 --- a/bindings/matrix-sdk-ffi/src/platform.rs +++ b/bindings/matrix-sdk-ffi/src/platform.rs @@ -14,25 +14,11 @@ use tracing_subscriber::{ EnvFilter, Layer, }; -/// Add panic=error to a filter line, if it's missing from it. -/// -/// Doesn't do anything if the directive is already present. -fn add_panic_to_filter(filter: &mut String) { - if filter.split(',').all(|pair| pair.split('=').next().is_none_or(|lhs| lhs != "panic")) { - if !filter.is_empty() { - filter.push(','); - } - filter.push_str("panic=error"); - } -} +use crate::tracing::LogLevel; -pub fn log_panics(filter: &mut String) { +pub fn log_panics() { std::env::set_var("RUST_BACKTRACE", "1"); - // Make sure that panics will be properly logged. On 2025-01-08, `log_panics` - // uses the `panic` target, at the error log level. - add_panic_to_filter(filter); - log_panics::init(); } @@ -245,12 +231,75 @@ pub struct TracingFileConfiguration { max_files: Option, } +#[derive(PartialEq, PartialOrd)] +enum LogTarget { + Hyper, + MatrixSdkFfi, + MatrixSdk, + MatrixSdkClient, + MatrixSdkCrypto, + MatrixSdkCryptoAccount, + MatrixSdkOidc, + MatrixSdkHttpClient, + MatrixSdkSlidingSync, + MatrixSdkBaseSlidingSync, + MatrixSdkUiTimeline, + MatrixSdkEventCache, + MatrixSdkBaseEventCache, + MatrixSdkEventCacheStore, +} + +impl LogTarget { + fn as_str(&self) -> &'static str { + match self { + LogTarget::Hyper => "hyper", + LogTarget::MatrixSdkFfi => "matrix_sdk_ffi", + LogTarget::MatrixSdk => "matrix_sdk", + LogTarget::MatrixSdkClient => "matrix_sdk::client", + LogTarget::MatrixSdkCrypto => "matrix_sdk_crypto", + LogTarget::MatrixSdkCryptoAccount => "matrix_sdk_crypto::olm::account", + LogTarget::MatrixSdkOidc => "matrix_sdk::oidc", + LogTarget::MatrixSdkHttpClient => "matrix_sdk::http_client", + LogTarget::MatrixSdkSlidingSync => "matrix_sdk::sliding_sync", + LogTarget::MatrixSdkBaseSlidingSync => "matrix_sdk_base::sliding_sync", + LogTarget::MatrixSdkUiTimeline => "matrix_sdk_ui::timeline", + LogTarget::MatrixSdkEventCache => "matrix_sdk::event_cache", + LogTarget::MatrixSdkBaseEventCache => "matrix_sdk_base::event_cache", + LogTarget::MatrixSdkEventCacheStore => "matrix_sdk_sqlite::event_cache_store", + } + } +} + +const DEFAULT_TARGET_LOG_LEVELS: &[(LogTarget, LogLevel)] = &[ + (LogTarget::Hyper, LogLevel::Warn), + (LogTarget::MatrixSdkFfi, LogLevel::Info), + (LogTarget::MatrixSdk, LogLevel::Info), + (LogTarget::MatrixSdkClient, LogLevel::Trace), + (LogTarget::MatrixSdkCrypto, LogLevel::Debug), + (LogTarget::MatrixSdkCryptoAccount, LogLevel::Trace), + (LogTarget::MatrixSdkOidc, LogLevel::Trace), + (LogTarget::MatrixSdkHttpClient, LogLevel::Debug), + (LogTarget::MatrixSdkSlidingSync, LogLevel::Info), + (LogTarget::MatrixSdkBaseSlidingSync, LogLevel::Info), + (LogTarget::MatrixSdkUiTimeline, LogLevel::Info), + (LogTarget::MatrixSdkEventCache, LogLevel::Info), + (LogTarget::MatrixSdkBaseEventCache, LogLevel::Info), + (LogTarget::MatrixSdkEventCacheStore, LogLevel::Info), +]; + +const IMMUTABLE_TARGET_LOG_LEVELS: &[LogTarget] = &[ + LogTarget::Hyper, // Too verbose + LogTarget::MatrixSdk, // Too generic +]; + #[derive(uniffi::Record)] pub struct TracingConfiguration { - /// A filter line following the [RUST_LOG format]. - /// - /// [RUST_LOG format]: https://rust-lang-nursery.github.io/rust-cookbook/development_tools/debugging/config_log.html - filter: String, + /// The desired log level + log_level: LogLevel, + + /// Additional targets that the FFI client would like to use e.g. + /// the target names for created [`crate::tracing::Span`] + extra_targets: Option>, /// Whether to log to stdout, or in the logcat on Android. write_to_stdout_or_system: bool, @@ -259,38 +308,111 @@ pub struct TracingConfiguration { write_to_files: Option, } +fn build_tracing_filter(config: &TracingConfiguration) -> String { + // We are intentionally not setting a global log level because we don't want to + // risk third party crates logging sensitive information. + // As such we need to make sure that panics will be properly logged. + // On 2025-01-08, `log_panics` uses the `panic` target, at the error log level. + let mut filters = vec!["panic=error".to_owned()]; + + DEFAULT_TARGET_LOG_LEVELS.iter().for_each(|(target, level)| { + // Use the default if the log level shouldn't be changed for this target or + // if it's already logging more than requested + let level = if IMMUTABLE_TARGET_LOG_LEVELS.contains(target) || level > &config.log_level { + level.as_str() + } else { + config.log_level.as_str() + }; + + filters.push(format!("{}={}", target.as_str(), level)); + }); + + // Finally append the extra targets requested by the client + if let Some(extra_targets) = &config.extra_targets { + for target in extra_targets { + filters.push(format!("{}={}", target, config.log_level.as_str())); + } + } + + filters.join(",") +} + #[matrix_sdk_ffi_macros::export] -pub fn setup_tracing(mut config: TracingConfiguration) { - log_panics(&mut config.filter); +pub fn setup_tracing(config: TracingConfiguration) { + log_panics(); tracing_subscriber::registry() - .with(EnvFilter::new(&config.filter)) + .with(EnvFilter::new(build_tracing_filter(&config))) .with(text_layers(config)) .init(); } #[cfg(test)] mod tests { - use super::add_panic_to_filter; + use super::build_tracing_filter; #[test] - fn test_add_panic_when_not_provided_empty() { - let mut filter = String::from(""); - add_panic_to_filter(&mut filter); - assert_eq!(filter, "panic=error"); - } + fn test_default_tracing_filter() { + let config = super::TracingConfiguration { + log_level: super::LogLevel::Error, + extra_targets: Some(vec!["super_duper_app".to_owned()]), + write_to_stdout_or_system: true, + write_to_files: None, + }; - #[test] - fn test_add_panic_when_not_provided_non_empty() { - let mut filter = String::from("a=b,c=d"); - add_panic_to_filter(&mut filter); - assert_eq!(filter, "a=b,c=d,panic=error"); + let filter = build_tracing_filter(&config); + + assert_eq!( + filter, + "panic=error,\ + hyper=warn,\ + matrix_sdk_ffi=info,\ + matrix_sdk=info,\ + matrix_sdk::client=trace,\ + matrix_sdk_crypto=debug,\ + matrix_sdk_crypto::olm::account=trace,\ + matrix_sdk::oidc=trace,\ + matrix_sdk::http_client=debug,\ + matrix_sdk::sliding_sync=info,\ + matrix_sdk_base::sliding_sync=info,\ + matrix_sdk_ui::timeline=info,\ + matrix_sdk::event_cache=info,\ + matrix_sdk_base::event_cache=info,\ + matrix_sdk_sqlite::event_cache_store=info,\ + super_duper_app=error" + ); } #[test] - fn test_do_nothing_when_provided() { - let mut filter = String::from("a=b,panic=info,c=d"); - add_panic_to_filter(&mut filter); - assert_eq!(filter, "a=b,panic=info,c=d"); + fn test_trace_tracing_filter() { + let config = super::TracingConfiguration { + log_level: super::LogLevel::Trace, + extra_targets: Some(vec!["super_duper_app".to_owned(), "some_other_span".to_owned()]), + write_to_stdout_or_system: true, + write_to_files: None, + }; + + let filter = build_tracing_filter(&config); + + assert_eq!( + filter, + "panic=error,\ + hyper=warn,\ + matrix_sdk_ffi=trace,\ + matrix_sdk=info,\ + matrix_sdk::client=trace,\ + matrix_sdk_crypto=trace,\ + matrix_sdk_crypto::olm::account=trace,\ + matrix_sdk::oidc=trace,\ + matrix_sdk::http_client=trace,\ + matrix_sdk::sliding_sync=trace,\ + matrix_sdk_base::sliding_sync=trace,\ + matrix_sdk_ui::timeline=trace,\ + matrix_sdk::event_cache=trace,\ + matrix_sdk_base::event_cache=trace,\ + matrix_sdk_sqlite::event_cache_store=trace,\ + super_duper_app=trace,\ + some_other_span=trace" + ); } } diff --git a/bindings/matrix-sdk-ffi/src/tracing.rs b/bindings/matrix-sdk-ffi/src/tracing.rs index cc50f14a1e3..ae7e7ba3b04 100644 --- a/bindings/matrix-sdk-ffi/src/tracing.rs +++ b/bindings/matrix-sdk-ffi/src/tracing.rs @@ -185,6 +185,16 @@ impl LogLevel { LogLevel::Trace => tracing::Level::TRACE, } } + + pub(crate) fn as_str(&self) -> &'static str { + match self { + LogLevel::Error => "error", + LogLevel::Warn => "warn", + LogLevel::Info => "info", + LogLevel::Debug => "debug", + LogLevel::Trace => "trace", + } + } } #[derive(PartialEq, Eq, PartialOrd, Ord)]