Tracing usage

Posted 2022-11-27 金庆

Tracing usage

(Jin Qing’s Column, Jan., 2022)

Tracing is Rust log crate: https://github.com/tokio-rs/tracing

This example code outputs log to stdout and a log file, using a log filter config file,
which can be automatically reloaded on change.

https://gitee.com/jinq0123/tracing-example

Dependencies

Add these dependencies to Cargo.toml:

[dependencies]
anyhow = "1.0.52"
hotwatch = "0.4.6"
tracing = "0.1.29"
tracing-appender = "0.2.0"
tracing-subscriber =  version = "0.3.5", features = [ "env-filter", "json" ] 

main.rs

mod log;

use anyhow::Result;
use std::thread, time::Duration;
use tracing::info;

fn main() -> Result<()> 
    let _guard = log::init("./log", "example.log", "config/log_filter.txt")?;

    for i in 0..999 
        info!(i, "Hello, world!");
        thread::sleep(Duration::from_secs(1));
    

    Ok(())

log.rs

//! Init log.
//!

use anyhow::anyhow, Context as _, Result;
use hotwatch::Event, Hotwatch;
use std::fs;
use std::path::Path;
use tracing::debug, warn, Subscriber;
use tracing_appender::non_blocking::WorkerGuard, rolling;
use tracing_subscriber::fmt, layer::SubscriberExt, reload::Handle, EnvFilter;

/// Inits log.
/// Returns a WorkerGuard to ensure buffered logs are flushed,
///  and a Hotwatch to watch the log filter file.
pub fn init(
    directory: impl AsRef<Path>,
    file_name_prefix: impl AsRef<Path>,
    log_filter_file: impl AsRef<Path>,
) -> Result<(WorkerGuard, Hotwatch)> 
    let file_appender = rolling::daily(directory, file_name_prefix);
    let (non_blocking, worker_guard) = tracing_appender::non_blocking(file_appender);
    let file_layer = fmt::Layer::default()
        .with_writer(non_blocking)
        .json()
        .flatten_event(true)
        .with_ansi(false);

    let builder = tracing_subscriber::fmt()
        .pretty()
        .with_env_filter(EnvFilter::from_default_env())
        .with_filter_reloading();
    let handle = builder.reload_handle();
    let subscriber = builder.finish();
    let subscriber = subscriber.with(file_layer);
    tracing::subscriber::set_global_default(subscriber).context("set global default subscriber")?;

    reload_filter(handle.clone(), log_filter_file.as_ref());

    let log_filter_path_buf = log_filter_file.as_ref().to_path_buf();
    let mut hotwatch = Hotwatch::new().context("hotwatch failed to initialize!")?;
    hotwatch
        .watch(log_filter_file.as_ref(), move |event: Event| 
            debug!("log filter file event: :?", event);
            if let Event::Write(_) = event 
                reload_filter(handle.clone(), log_filter_path_buf.clone());
            
        )
        .with_context(|| format!("failed to watch file: :?", log_filter_file.as_ref()))?;

    Ok((worker_guard, hotwatch))


fn reload_filter<S: Subscriber + 'static>(
    handle: Handle<EnvFilter, S>,
    log_filter_file: impl AsRef<Path>,
) 
    let res = try_reload_filter(handle, log_filter_file);
    match res 
        Ok(_) => debug!("reload log filter OK"),
        Err(e) => warn!("reload log filter error: :?", e),
    


fn try_reload_filter<S: Subscriber + 'static>(
    handle: Handle<EnvFilter, S>,
    log_filter_file: impl AsRef<Path>,
) -> Result<()> 
    let contents = fs::read_to_string(log_filter_file.as_ref()).with_context(|| 
        format!(
            "something went wrong reading the file: :?",
            log_filter_file.as_ref()
        )
    )?;
    let contents = contents.trim();
    debug!("reload log filter: :?", contents);
    let new_filter = contents
        .parse::<EnvFilter>()
        .map_err(|e| anyhow!(e))
        .context("failed to parse env filter")?;
    handle.reload(new_filter).context("handle reload error")

log_filter.txt

log_filter.txt is the configure file for log.
The change of this file will trigger the reload.

The log filter file must exist, otherwise it will be error:

Error: failed to watch file: "config/log_filter.txt"

Caused by:
    系统找不到指定的路径。 (os error 3)

The content of log_filter.txt is a single line of filter string.
A filter string consists of one or more comma-separated directives.
The directive syntax is similar to RUST_LOG env val of env_logger’s.

target[spanfield=value]=level

See: https://docs.rs/tracing-subscriber/latest/tracing_subscriber/struct.EnvFilter.html

Example

• tracing_example enables logs that:
  • target is modules of tracing_example*
• info will enable logs that:
  • level is info
• tracing_ex=info enables logs that:
  • target is modules of tracing_ex*
  • level is info or above
• info,tracing_ex=debug enables logs that:
  • level is info or above
  • or target is tracing_ex* and level is debug
• [foo]=trace enables logs that:
  • within the span foo
  • level is trace or above
• [span_bname=\\"bob\\"] enables logs that:
  • have any target,
  • are inside a span named span_b,
  • which has a field named name with value bob,
  • at any level.

Note: span filter directive will keep effective until it exits the span.