re_log/

lib.rs

//! Text logging (nothing to do with rerun logging) for use in rerun libraries.
//!
//! Provides helpers for adding multiple loggers,
//! and for setting up logging on native and on web.
//!
//! * `trace`: spammy things
//! * `debug`: things that might be useful when debugging
//! * `info`: things that we want to show to users
//! * `warn`: problems that we can recover from
//! * `error`: problems that lead to loss of functionality or data
//!
//! The `warn_once` etc macros are for when you want to suppress repeated
//! logging of the exact same message.
//!
//! In the viewer these logs, if >= info, become notifications. See
//! `re_ui::notifications` for more information.

#[cfg(feature = "setup")]
mod channel_logger;
mod debug_assert;
#[cfg(feature = "setup")]
mod event_visitor;
mod log_once;
mod result_extensions;
#[cfg(feature = "setup")]
mod setup;

#[cfg(feature = "setup")]
pub use channel_logger::{LogMsg, Receiver, Sender, add_log_msg_receiver};
#[cfg(feature = "setup")]
pub use event_visitor::FieldValue;
pub use log_once::LogOnceSet;
pub use result_extensions::ResultExt;
#[cfg(all(feature = "setup", not(target_arch = "wasm32")))]
pub use setup::PanicOnWarnScope;
#[cfg(feature = "setup")]
pub use setup::{setup_logging, setup_logging_with_filter};
pub use tracing::Level;
#[cfg(feature = "setup")]
pub use tracing_subscriber::filter::LevelFilter;
// The tracing macros support more syntax features than the log, that's why we use them:
pub use tracing::{debug, error, event, info, trace, warn};

/// Log a warning in debug builds, or a debug message in release builds.
///
/// This is useful for logging messages that should be visible during development
/// (to help catch issues), but shouldn't spam the logs in release builds.
///
/// In debug builds, the message is prefixed with "DEBUG: " and logged at WARN level.
/// In release builds, the message is logged at DEBUG level without any prefix.
///
/// This macro never triggers panic-on-warn (`RERUN_PANIC_ON_WARN` or `PanicOnWarnScope`):
/// that is meant to catch user-facing warnings, and this macro is never a warning
/// in release builds.
#[cfg(debug_assertions)]
#[macro_export]
macro_rules! debug_warn {
    ($($arg:tt)+) => {
        $crate::_with_panic_on_warn_suppressed(|| $crate::warn!("DEBUG: {}", format_args!($($arg)+)))
    };
}

/// Log a warning in debug builds, or a debug message in release builds.
///
/// This is useful for logging messages that should be visible during development
/// (to help catch issues), but shouldn't spam the logs in release builds.
///
/// In debug builds, the message is prefixed with "DEBUG: " and logged at WARN level.
/// In release builds, the message is logged at DEBUG level without any prefix.
#[cfg(not(debug_assertions))]
#[macro_export]
macro_rules! debug_warn {
    ($($arg:tt)+) => {
        $crate::debug!($($arg)+)
    };
}

/// Like [`debug_warn!`], but only logs once per call site.
///
/// This is useful for logging messages that should be visible during development
/// (to help catch issues), but shouldn't spam the logs in release builds.
///
/// In debug builds, the message is prefixed with "DEBUG: " and logged at WARN level.
/// In release builds, the message is logged at DEBUG level without any prefix.
///
/// This macro never triggers panic-on-warn (`RERUN_PANIC_ON_WARN` or `PanicOnWarnScope`):
/// that is meant to catch user-facing warnings, and this macro is never a warning
/// in release builds.
#[cfg(debug_assertions)]
#[macro_export]
macro_rules! debug_warn_once {
    ($($arg:tt)+) => {
        $crate::_with_panic_on_warn_suppressed(|| $crate::warn_once!("DEBUG: {}", format_args!($($arg)+)))
    };
}

/// Like [`debug_warn!`], but only logs once per call site.
///
/// This is useful for logging messages that should be visible during development
/// (to help catch issues), but shouldn't spam the logs in release builds.
///
/// In debug builds, the message is prefixed with "DEBUG: " and logged at WARN level.
/// In release builds, the message is logged at DEBUG level without any prefix.
#[cfg(not(debug_assertions))]
#[macro_export]
macro_rules! debug_warn_once {
    ($($arg:tt)+) => {
        $crate::debug_once!($($arg)+)
    };
}

/// Re-exports of other crates.
pub mod external {
    pub use log;
}

/// Never log anything less serious than a `ERROR` from these crates.
#[cfg(any(feature = "setup", not(target_arch = "wasm32")))]
const CRATES_AT_ERROR_LEVEL: &[&str] = &[
    // silence rustls in release mode: https://github.com/rerun-io/rerun/issues/3104
    #[cfg(not(debug_assertions))]
    "rustls",
];

/// Never log anything less serious than a `WARN` from these crates.
#[cfg(any(feature = "setup", not(target_arch = "wasm32")))]
const CRATES_AT_WARN_LEVEL: &[&str] = &[
    // wgpu crates spam a lot on info level, which is really annoying
    // TODO(emilk): remove once https://github.com/gfx-rs/wgpu/issues/3206 is fixed
    "naga",
    "tracing",
    "wgpu_core",
    "wgpu_hal",
    "zbus",
];

/// Never log anything less serious than a `INFO` from these crates.
///
/// These creates are quite spammy on debug, drowning out what we care about:
#[cfg(any(feature = "setup", not(target_arch = "wasm32")))]
const CRATES_AT_INFO_LEVEL: &[&str] = &[
    "datafusion_optimizer",
    "datafusion",
    "h2",
    "hyper",
    "opentelemetry", // Spams about NoopMeterProvider
    "prost_build",
    "reqwest", // Spams "starting new connection: …"
    "sqlparser",
    "tonic_web",
    "tower",
    "ureq",
    // only let rustls log in debug mode: https://github.com/rerun-io/rerun/issues/3104
    #[cfg(debug_assertions)]
    "rustls",
    // walkers generates noise around tile download, see https://github.com/podusowski/walkers/issues/199
    "walkers",
    // winit 0.30.5 spams about `set_cursor_visible` calls. It's gone on winit master, so hopefully gone in next winit release.
    "winit",
];

/// Determines the default log filter.
///
/// Native: Get `RUST_LOG` environment variable or `info`, if not set.
/// Also sets some other log levels on crates that are too loud.
///
/// Web: `debug` since web console allows arbitrary filtering.
#[cfg(not(target_arch = "wasm32"))]
pub fn default_log_filter() -> String {
    let base_log_filter = if cfg!(debug_assertions) {
        // We want the DEBUG level to be useful yet not too spammy.
        // This is a good way to enforce that.
        "debug"
    } else {
        // Important to keep the default at (at least) "info",
        // as we print crucial information at INFO,
        // e.g. the ip:port when hosting a server with `rerun-cli`.
        "info"
    };
    log_filter_from_env_or_default(base_log_filter)
}

/// Determines the default log filter.
///
/// Native: Get `RUST_LOG` environment variable or `info`, if not set.
/// Also sets some other log levels on crates that are too loud.
///
/// Web: `debug` since web console allows arbitrary filtering.
#[cfg(target_arch = "wasm32")]
pub fn default_log_filter() -> String {
    "debug".to_owned()
}

/// Determines the log filter from the `RUST_LOG` environment variable or an explicit default.
///
/// Always adds builtin filters as well.
#[cfg(not(target_arch = "wasm32"))]
pub fn log_filter_from_env_or_default(default_base_log_filter: &str) -> String {
    let rust_log = std::env::var("RUST_LOG").unwrap_or_else(|_| default_base_log_filter.to_owned());
    add_builtin_log_filter(&rust_log)
}

/// Adds builtin log level filters for crates that are too verbose.
#[cfg(not(target_arch = "wasm32"))]
fn add_builtin_log_filter(base_log_filter: &str) -> String {
    use std::fmt::Write as _;

    let mut rust_log = base_log_filter.to_lowercase();

    if base_log_filter != "off" {
        // If base level is `off`, don't opt-in to anything.

        for crate_name in crate::CRATES_AT_ERROR_LEVEL {
            if !rust_log.contains(&format!("{crate_name}=")) {
                write!(rust_log, ",{crate_name}=error").ok();
            }
        }

        if base_log_filter != "error" {
            // If base level is `error`, don't opt-in to `warn` or `info`.

            for crate_name in crate::CRATES_AT_WARN_LEVEL {
                if !rust_log.contains(&format!("{crate_name}=")) {
                    write!(rust_log, ",{crate_name}=warn").ok();
                }
            }

            if base_log_filter != "warn" {
                // If base level is not `error`/`warn`, don't opt-in to `info`.

                for crate_name in crate::CRATES_AT_INFO_LEVEL {
                    if !rust_log.contains(&format!("{crate_name}=")) {
                        write!(rust_log, ",{crate_name}=info").ok();
                    }
                }
            }
        }
    }

    //TODO(#8077): should be removed as soon as the upstream issue is resolved
    rust_log += ",walkers::download=off";

    rust_log
}

/// Should we log this message given the filter?
#[cfg(feature = "setup")]
fn is_log_enabled(
    filter: tracing_subscriber::filter::LevelFilter,
    target: &str,
    level: &tracing::Level,
) -> bool {
    if CRATES_AT_ERROR_LEVEL
        .iter()
        .any(|crate_name| target.starts_with(crate_name))
    {
        *level <= tracing_subscriber::filter::LevelFilter::ERROR
    } else if CRATES_AT_WARN_LEVEL
        .iter()
        .any(|crate_name| target.starts_with(crate_name))
    {
        *level <= tracing_subscriber::filter::LevelFilter::WARN
    } else if CRATES_AT_INFO_LEVEL
        .iter()
        .any(|crate_name| target.starts_with(crate_name))
    {
        *level <= tracing_subscriber::filter::LevelFilter::INFO
    } else {
        *level <= filter
    }
}

/// Check if an environment variable is set to a truthy value.
///
/// Returns `true` if the environment variable is set to "1/true/yes/on" (case-insensitive).
/// Returns `false` if the environment variable is set to "0/false/no/off" (case-insensitive).
/// Otherwise returns `None`.
///
/// # Example
///
/// ```ignore
/// if env_var_flag("TELEMETRY_ENABLED") == Some(true) {
///     // enable telemetry
/// }
/// ```
pub fn env_var_flag(var_name: &str) -> Option<bool> {
    match std::env::var(var_name)
        .ok()?
        .trim()
        .to_ascii_lowercase()
        .as_str()
    {
        "" => None,
        "0" | "false" | "no" | "off" => Some(false),
        "1" | "true" | "yes" | "on" => Some(true),
        value => {
            crate::warn_once!(
                "Ignoring unrecognized value {value:?} for environment variable {var_name:?} \
                    (expected one of: 1/true/yes/on, 0/false/no/off); falling back to the default."
            );
            None
        }
    }
}

/// Check if an environment variable is set to a truthy value.
///
/// Returns `true` if the environment variable is set to "1/true/yes/on" (case-insensitive).
/// Otherwise returns `false`.
///
/// # Example
///
/// ```ignore
/// if env_var_is_truthy("TELEMETRY_ENABLED") {
///     // enable telemetry
/// }
/// ```
pub fn env_var_is_truthy(var_name: &str) -> bool {
    env_var_flag(var_name).unwrap_or(false)
}

/// Is `RERUN_VERY_STRICT` set to a truthy value?
///
/// In very strict mode, Rerun may panic anywhere, at any time, for any reason whenever it
/// detects something it does not like — e.g. out-of-order chunks, unsorted timelines,
/// or other invariant violations. Very strict mode is meant for development, testing and
/// CI, never for production: enable it to catch silent corruption early.
///
/// The result is cached on the first call, so subsequent calls are very cheap and
/// changing the environment variable at runtime has no effect.
pub fn is_rerun_very_strict() -> bool {
    static VERY_STRICT: std::sync::OnceLock<bool> = std::sync::OnceLock::new();
    *VERY_STRICT.get_or_init(|| env_var_is_truthy("RERUN_VERY_STRICT"))
}

/// Is `RERUN_PANIC_ON_WARN` set to a truthy value?
///
/// When enabled, any user-facing warning or error log message causes a panic
/// (see `setup_logging`). This is meant for tests and CI, to catch warnings early.
///
/// The result is cached on the first call, so subsequent calls are very cheap and
/// changing the environment variable at runtime has no effect.
pub fn is_panic_on_warn() -> bool {
    static PANIC_ON_WARN: std::sync::OnceLock<bool> = std::sync::OnceLock::new();
    *PANIC_ON_WARN.get_or_init(|| env_var_is_truthy("RERUN_PANIC_ON_WARN"))
}

thread_local! {
    static SUPPRESS_PANIC_ON_WARN: std::cell::Cell<bool> = const { std::cell::Cell::new(false) };
}

/// Runs `f` with panic-on-warn suppressed on the current thread.
///
/// Used by [`debug_warn!`] & co, which are warnings only in debug builds
/// and thus shouldn't trip `RERUN_PANIC_ON_WARN` or `PanicOnWarnScope`.
///
/// This relies on `tracing` dispatching events synchronously on the emitting thread.
#[doc(hidden)] // implementation detail of the `debug_warn!` family
pub fn _with_panic_on_warn_suppressed<R>(f: impl FnOnce() -> R) -> R {
    // RAII-restore, so a panic during `f` (e.g. while formatting) doesn't leak the flag.
    struct Guard(bool);

    impl Drop for Guard {
        fn drop(&mut self) {
            SUPPRESS_PANIC_ON_WARN.with(|suppress| suppress.set(self.0));
        }
    }

    let _guard = Guard(SUPPRESS_PANIC_ON_WARN.with(|suppress| suppress.replace(true)));
    f()
}

/// Is panic-on-warn currently suppressed on this thread (see [`_with_panic_on_warn_suppressed`])?
#[cfg(all(feature = "setup", not(target_arch = "wasm32")))] // only used by the `PanicOnWarn` layer
pub(crate) fn is_panic_on_warn_suppressed() -> bool {
    SUPPRESS_PANIC_ON_WARN.with(|suppress| suppress.get())
}

/// Shorten a path to a Rust source file.
///
/// Example input:
/// * `/Users/emilk/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-1.24.1/src/runtime/runtime.rs`
/// * `crates/rerun/src/main.rs`
/// * `/rustc/d5a82bbd26e1ad8b7401f6a718a9c57c96905483/library/core/src/ops/function.rs`
///
/// Example output:
/// * `tokio-1.24.1/src/runtime/runtime.rs`
/// * `rerun/src/main.rs`
/// * `core/src/ops/function.rs`
#[allow(clippy::allow_attributes, dead_code)] // only used on web and in tests
fn shorten_file_path(file_path: &str) -> &str {
    if let Some(i) = file_path.rfind("/src/") {
        if let Some(prev_slash) = file_path[..i].rfind('/') {
            &file_path[prev_slash + 1..]
        } else {
            file_path
        }
    } else {
        file_path
    }
}

#[test]
fn test_shorten_file_path() {
    for (before, after) in [
        (
            "/Users/emilk/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-1.24.1/src/runtime/runtime.rs",
            "tokio-1.24.1/src/runtime/runtime.rs",
        ),
        ("crates/rerun/src/main.rs", "rerun/src/main.rs"),
        (
            "/rustc/d5a82bbd26e1ad8b7401f6a718a9c57c96905483/library/core/src/ops/function.rs",
            "core/src/ops/function.rs",
        ),
        ("/weird/path/file.rs", "/weird/path/file.rs"),
    ] {
        assert_eq!(shorten_file_path(before), after);
    }
}