From dcfc9d028769f3448515534511858d767d004716 Mon Sep 17 00:00:00 2001 From: Stefan Ceriu Date: Thu, 9 Jan 2025 13:19:42 +0200 Subject: [PATCH] feat(ffi): move tracing setup from the final client to the ffi layer 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 the final client's target name and apply them on top of the rust side defined default. 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. --- bindings/matrix-sdk-ffi/src/platform.rs | 179 +++++++++++++++++++----- bindings/matrix-sdk-ffi/src/tracing.rs | 10 ++ 2 files changed, 151 insertions(+), 38 deletions(-) diff --git a/bindings/matrix-sdk-ffi/src/platform.rs b/bindings/matrix-sdk-ffi/src/platform.rs index 009d3c501fb..e9b953510cc 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,65 @@ pub struct TracingFileConfiguration { max_files: Option, } +#[derive(PartialEq, PartialOrd)] +enum LogTarget { + Hyper, + MatrixSDKFFI, + MatrixSDKClient, + MatrixSDKCrypto, + MatrixSDKCryptoAccount, + MatrixSDKOIDC, + MatrixSDKHTTPClient, + MatrixSDKSlidingSync, + MatrixSDKBaseSlidingSync, + MatrixSDKUITimeline, + MatrixSDKEventCache, + MatrixSDKEventCacheStore, +} + +impl LogTarget { + fn as_str(&self) -> &'static str { + match self { + LogTarget::Hyper => "hyper", + LogTarget::MatrixSDKFFI => "matrix_sdk_ffi", + 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::MatrixSDKEventCacheStore => "matrix_sdk_sqlite::event_cache_store", + } + } +} + +const DEFAULT_TARGET_LOG_LEVELS: &'static [(LogTarget, LogLevel)] = &[ + (LogTarget::Hyper, LogLevel::Warn), + (LogTarget::MatrixSDKFFI, 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::MatrixSDKEventCacheStore, LogLevel::Info), +]; + +const IMMUTABLE_TARGET_LOG_LEVELS: &'static [LogTarget] = &[LogTarget::Hyper]; + #[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 LogLevel, corresponding to https://docs.rs/log/latest/log/enum.Level.html + log_level: LogLevel, + + /// The target name under which the FFI client will log messages using `tracing::log_event` + app_target: String, /// Whether to log to stdout, or in the logcat on Android. write_to_stdout_or_system: bool, @@ -259,38 +298,102 @@ 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 + // 3rd 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_string()]; + + // We're also need to include the target name that the FII client uses + filters.push(format!("{}={}", config.app_target, config.log_level.as_str())); + + 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)); + }); + + 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, + app_target: "super_duper_app".to_string(), + 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,\ + super_duper_app=error,\ + hyper=warn,\ + matrix_sdk_ffi=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_sqlite::event_cache_store=info" + ); } #[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, + app_target: "super_duper_app".to_string(), + write_to_stdout_or_system: true, + write_to_files: None, + }; + + let filter = build_tracing_filter(&config); + + assert_eq!( + filter, + "panic=error,\ + super_duper_app=trace,\ + hyper=warn,\ + matrix_sdk_ffi=trace,\ + 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_sqlite::event_cache_store=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)]