EnvFilter

pub struct EnvFilter {
    statics: directive::Statics,
    dynamics: directive::Dynamics,
    has_dynamics: bool,
    by_id: RwLock<HashMap<span::Id, directive::SpanMatcher>>,
    by_cs: RwLock<HashMap<callsite::Identifier, directive::CallsiteMatcher>>,
    scope: ThreadLocal<RefCell<Vec<LevelFilter>>>,
    regex: bool,
}

    pub(crate) fn enabled(&self, meta: &Metadata<'_>) -> bool {
        let level = meta.level();
        match self.directives_for(meta).next() {
            Some(d) => d.level >= *level,
            None => false,
        }
    }

        if let Some(ref target) = self.target {
            if !meta.target().starts_with(&target[..]) {
                return false;
            }
        }

tracing = "=0.1.44"
tracing-subscriber = { version = "=0.3.23", features = ["env-filter"] }

use tracing_subscriber::EnvFilter;

fn main() {
  tracing_subscriber::fmt()
    .with_env_filter(EnvFilter::new("warn,my_app=debug,my_app::db=error"))
    .with_ansi(false)
    .without_time()
    .init();
  tracing::debug!(target: "my_app", "1");
  tracing::debug!(target: "my_app::http", "2");
  tracing::debug!(target: "my_app_extra", "3");
  tracing::warn!(target: "my_app::db", "4");
  tracing::error!(target: "my_app::db", "5");
  tracing::debug!(target: "other", "6");
  tracing::warn!(target: "other", "7");
}

DEBUG my_app: 1
DEBUG my_app::http: 2
DEBUG my_app_extra: 3
ERROR my_app::db: 5
 WARN other: 7

use tracing_subscriber::EnvFilter;

fn main() {
  tracing_subscriber::fmt()
    .with_env_filter(EnvFilter::from_default_env())
    .with_ansi(false)
    .without_time()
    .init();
  println!("module_path!() = {}", module_path!());
  tracing::error!("error event");
  tracing::debug!("debug event");
}

$ RUST_LOG=my-app=debug ./my-app
module_path!() = my_app
$ RUST_LOG=my_app=debug ./my-app
module_path!() = my_app
ERROR my_app: error event
DEBUG my_app: debug event

target[span{field=value}]=level

        let mut state = Start;
        for (i, c) in from.trim().char_indices() {
            state = match (state, c) {
                (Start, '[') => Span { span_start: i + 1 },
                (Start, c) if !['-', ':', '_'].contains(&c) && !c.is_alphanumeric() => {
                    return Err(ParseError::new())
                }
                (Start, _) => LevelOrTarget { start: i },
                (LevelOrTarget { start }, '=') => {
                    cur.target = Some(from[start..i].to_owned());
                    Level { level_start: i + 1 }
                }
                (LevelOrTarget { start }, '[') => {
                    cur.target = Some(from[start..i].to_owned());
                    Span { span_start: i + 1 }
                }
                // ...
                (Span { span_start }, ']') => {
                    cur.in_span = Some(from[span_start..i].to_owned());
                    Target
                }
                (Span { span_start }, '{') => {
                    // ...
                    Field { field_start: i + 1 }
                }
                // ...
                (Field { field_start }, '}') => {
                    cur.fields.push(match &from[field_start..i] {
                        "" => return Err(ParseError::new()),
                        field => field::Match::parse(field, regex)?,
                    });
                    Fields
                }
                // ...
                _ => return Err(ParseError::new()),
            };
        }

use tracing_subscriber::EnvFilter;

fn main() {
  let cases = [
    "info",
    "my_app=debug",
    "my-app=debug",
    "tokio::net",
    "warn,tokio::net=info",
    "[req]=debug",
    "my_app[req]=trace",
    "[{user}]=debug",
    "[req{id=42}]=debug",
    "[req{user=bob}]",
    "my_app[req{a=1,b=2}]=debug",
    "info, my_app=debug",
    "info, my_app",
    "my_app=verbose",
    "my_app=info=debug",
    "=info",
    "my_app[{}]=info",
    "[req{user=(}]=debug",
    "my_app[req",
  ];
  for s in cases {
    match EnvFilter::try_new(s) {
      Ok(f) => println!("{s:<28} Ok   {f}"),
      Err(e) => println!("{s:<28} Err  {e}"),
    }
  }
  // 不经过按逗号切分，直接解析一条 Directive
  let d: tracing_subscriber::filter::Directive = "my_app[req{a=1,b=2}]=debug".parse().unwrap();
  println!("Directive::from_str + add_directive: {}", EnvFilter::default().add_directive(d));
}

info                         Ok   info
my_app=debug                 Ok   my_app=debug
my-app=debug                 Ok   my-app=debug
tokio::net                   Ok   tokio::net=trace
warn,tokio::net=info         Ok   tokio::net=info,warn
[req]=debug                  Ok   [req]=debug
my_app[req]=trace            Ok   my_app[req]=trace
[{user}]=debug               Ok   [{user}]=debug,[{user}]=debug
[req{id=42}]=debug           Ok   [req{id=42}]=debug
[req{user=bob}]              Ok   [req{user=bob}]=trace
my_app[req{a=1,b=2}]=debug   Err  invalid filter directive
info, my_app=debug           Err  error parsing level filter: expected one of "off", "error", "warn", "info", "debug", "trace", or a number 0-5
info, my_app                 Ok    my_app=trace,info
my_app=verbose               Err  error parsing level filter: expected one of "off", "error", "warn", "info", "debug", "trace", or a number 0-5
my_app=info=debug            Err  error parsing level filter: expected one of "off", "error", "warn", "info", "debug", "trace", or a number 0-5
=info                        Err  invalid filter directive
my_app[{}]=info              Err  invalid filter directive
[req{user=(}]=debug          Err  invalid field filter: error building NFA
Directive::from_str + add_directive: my_app[req{a=1,b=2}]=debug

        let (dynamics, statics) = Directive::make_tables(directives);
        let has_dynamics = !dynamics.is_empty();

        let mut filter = EnvFilter {
            // ...
        };

        if !has_dynamics && filter.statics.is_empty() {
            if let Some(ref default) = self.default_directive {
                filter = filter.add_directive(default.clone());
            }
        }

        filter

use std::io::Write;

use tracing_subscriber::EnvFilter;
use tracing_subscriber::filter::LevelFilter;

fn set(v: Option<&str>) {
  // edition 2024 里改环境变量是 unsafe；这里是单线程
  unsafe {
    match v {
      Some(v) => std::env::set_var("RUST_LOG", v),
      None => std::env::remove_var("RUST_LOG"),
    }
  }
}

fn line(s: String) {
  // stdout 和 stderr 交错打印，先刷 stdout 让顺序可读
  println!("{s}");
  std::io::stdout().flush().unwrap();
}

fn main() {
  for v in [None, Some(""), Some("my_app=debug"), Some("my_app=debug,oops=loud"), Some("oops=loud")] {
    set(v);
    line(format!("== RUST_LOG={v:?}"));
    line(format!("  from_default_env()        -> {}", EnvFilter::from_default_env()));
    match EnvFilter::try_from_default_env() {
      Ok(f) => line(format!("  try_from_default_env()    -> Ok({f})")),
      Err(e) => line(format!("  try_from_default_env()    -> Err({e})")),
    }
    let f = EnvFilter::builder()
      .with_default_directive(LevelFilter::INFO.into())
      .from_env_lossy();
    line(format!("  builder(default INFO).from_env_lossy() -> {f}"));
    match EnvFilter::builder()
      .with_default_directive(LevelFilter::INFO.into())
      .from_env()
    {
      Ok(f) => line(format!("  builder(default INFO).from_env()       -> Ok({f})")),
      Err(e) => line(format!("  builder(default INFO).from_env()       -> Err({e})")),
    }
  }
}

== RUST_LOG=None
  from_default_env()        -> error
  try_from_default_env()    -> Err(environment variable not found)
  builder(default INFO).from_env_lossy() -> info
  builder(default INFO).from_env()       -> Ok(info)
== RUST_LOG=Some("")
  from_default_env()        -> error
  try_from_default_env()    -> Ok()
  builder(default INFO).from_env_lossy() -> info
  builder(default INFO).from_env()       -> Ok(info)
== RUST_LOG=Some("my_app=debug")
  from_default_env()        -> my_app=debug
  try_from_default_env()    -> Ok(my_app=debug)
  builder(default INFO).from_env_lossy() -> my_app=debug
  builder(default INFO).from_env()       -> Ok(my_app=debug)
== RUST_LOG=Some("my_app=debug,oops=loud")
ignoring `oops=loud`: error parsing level filter: expected one of "off", "error", "warn", "info", "debug", "trace", or a number 0-5
  from_default_env()        -> my_app=debug
  try_from_default_env()    -> Err(error parsing level filter: expected one of "off", "error", "warn", "info", "debug", "trace", or a number 0-5)
ignoring `oops=loud`: error parsing level filter: expected one of "off", "error", "warn", "info", "debug", "trace", or a number 0-5
  builder(default INFO).from_env_lossy() -> my_app=debug
  builder(default INFO).from_env()       -> Err(error parsing level filter: expected one of "off", "error", "warn", "info", "debug", "trace", or a number 0-5)
== RUST_LOG=Some("oops=loud")
ignoring `oops=loud`: error parsing level filter: expected one of "off", "error", "warn", "info", "debug", "trace", or a number 0-5
  from_default_env()        -> error
  try_from_default_env()    -> Err(error parsing level filter: expected one of "off", "error", "warn", "info", "debug", "trace", or a number 0-5)
ignoring `oops=loud`: error parsing level filter: expected one of "off", "error", "warn", "info", "debug", "trace", or a number 0-5
  builder(default INFO).from_env_lossy() -> info
  builder(default INFO).from_env()       -> Err(error parsing level filter: expected one of "off", "error", "warn", "info", "debug", "trace", or a number 0-5)

    fn is_static(&self) -> bool {
        !self.has_name() && !self.fields.iter().any(field::Match::has_value)
    }

    pub(super) fn is_dynamic(&self) -> bool {
        self.has_name() || self.has_fields()
    }

    fn base_interest(&self) -> Interest {
        if self.has_dynamics {
            Interest::sometimes()
        } else {
            Interest::never()
        }
    }

    fn register_callsite(&self, metadata: &'static Metadata<'static>) -> Interest {
        if self.has_dynamics && metadata.is_span() {
            // If this metadata describes a span, first, check if there is a
            // dynamic filter that should be constructed for it. If so, it
            // should always be enabled, since it influences filtering.
            if let Some(matcher) = self.dynamics.matcher(metadata) {
                let mut by_cs = try_lock!(self.by_cs.write(), else return self.base_interest());
                by_cs.insert(metadata.callsite(), matcher);
                return Interest::always();
            }
        }

        // Otherwise, check if any of our static filters enable this metadata.
        if self.statics.enabled(metadata) {
            Interest::always()
        } else {
            self.base_interest()
        }
    }

    pub fn enabled<S>(&self, metadata: &Metadata<'_>, _: Context<'_, S>) -> bool {
        let level = metadata.level();

        // is it possible for a dynamic filter directive to enable this event?
        // if not, we can avoid the thread local access + iterating over the
        // spans in the current scope.
        if self.has_dynamics && self.dynamics.max_level >= *level {
            if metadata.is_span() {
                // If the metadata is a span, see if we care about its callsite.
                let enabled_by_cs = self
                    .by_cs
                    .read()
                    .ok()
                    .map(|by_cs| by_cs.contains_key(&metadata.callsite()))
                    .unwrap_or(false);
                if enabled_by_cs {
                    return true;
                }
            }

            let enabled_by_scope = {
                let scope = self.scope.get_or_default().borrow();
                for filter in &*scope {
                    if filter >= level {
                        return true;
                    }
                }
                false
            };
            if enabled_by_scope {
                return true;
            }
        }

        // is it possible for a static filter directive to enable this event?
        if self.statics.max_level >= *level {
            // Otherwise, fall back to checking if the callsite is
            // statically enabled.
            return self.statics.enabled(metadata);
        }

        false
    }

use std::collections::BTreeMap;
use std::sync::Mutex;

use tracing::span::{Attributes, Id, Record};
use tracing::subscriber::Interest;
use tracing::{Event, Metadata, Subscriber};
use tracing_subscriber::filter::LevelFilter;
use tracing_subscriber::layer::{Context, Layer};
use tracing_subscriber::prelude::*;
use tracing_subscriber::{EnvFilter, Registry};

// 每个调用点（按行号）记三样：注册时的 Interest、enabled 次数、真正送达的次数
#[derive(Default)]
struct Row {
  interest: String,
  enabled: usize,
  delivered: usize,
}

static ROWS: Mutex<BTreeMap<u32, Row>> = Mutex::new(BTreeMap::new());

fn row(meta: &Metadata<'_>, f: impl FnOnce(&mut Row)) {
  f(ROWS.lock().unwrap().entry(meta.line().unwrap()).or_default());
}

// 包住 EnvFilter，把调用原样转过去，顺便记数
struct Counted(EnvFilter);

impl<S: Subscriber> Layer<S> for Counted {
  fn register_callsite(&self, meta: &'static Metadata<'static>) -> Interest {
    let i = Layer::<S>::register_callsite(&self.0, meta);
    row(meta, |r| r.interest = format!("{i:?}"));
    i
  }
  fn enabled(&self, meta: &Metadata<'_>, cx: Context<'_, S>) -> bool {
    row(meta, |r| r.enabled += 1);
    Layer::enabled(&self.0, meta, cx)
  }
  fn max_level_hint(&self) -> Option<LevelFilter> {
    Layer::<S>::max_level_hint(&self.0)
  }
  fn on_new_span(&self, a: &Attributes<'_>, id: &Id, cx: Context<'_, S>) {
    Layer::on_new_span(&self.0, a, id, cx)
  }
  fn on_record(&self, id: &Id, v: &Record<'_>, cx: Context<'_, S>) {
    Layer::on_record(&self.0, id, v, cx)
  }
  fn on_enter(&self, id: &Id, cx: Context<'_, S>) {
    Layer::on_enter(&self.0, id, cx)
  }
  fn on_exit(&self, id: &Id, cx: Context<'_, S>) {
    Layer::on_exit(&self.0, id, cx)
  }
  fn on_close(&self, id: Id, cx: Context<'_, S>) {
    Layer::on_close(&self.0, id, cx)
  }
}

// 最内层的记录者：数送达的事件和 span
struct Sink;

impl<S: Subscriber> Layer<S> for Sink {
  fn on_event(&self, e: &Event<'_>, _: Context<'_, S>) {
    row(e.metadata(), |r| r.delivered += 1);
  }
  fn on_new_span(&self, a: &Attributes<'_>, _: &Id, _: Context<'_, S>) {
    row(a.metadata(), |r| r.delivered += 1);
  }
}

fn work() {
  tracing::info!("info outside");
  tracing::debug!("debug outside");
  let span = tracing::info_span!("req", user = "bob");
  let _g = span.enter();
  tracing::debug!("debug inside");
}

fn main() {
  let names = [(72, "info! 外"), (73, "debug! 外"), (74, "info_span!(req)"), (76, "debug! 内")];
  for spec in [
    "info",
    "info,my_app::db=debug",
    "info,[req]=debug",
    "info,[req{user=bob}]=debug",
  ] {
    ROWS.lock().unwrap().clear();
    let sub = Registry::default().with(Sink).with(Counted(EnvFilter::new(spec)));
    tracing::subscriber::with_default(sub, || {
      for _ in 0..1000 {
        work();
      }
      println!("== {spec}   LevelFilter::current() = {}", LevelFilter::current());
    });
    let rows = ROWS.lock().unwrap();
    for (line, name) in names {
      match rows.get(&line) {
        Some(r) => println!(
          "  {name:<16} interest={:<20} enabled={:<5} delivered={}",
          r.interest, r.enabled, r.delivered
        ),
        None => println!("  {name:<16} （没有注册）"),
      }
    }
  }
}

== info   LevelFilter::current() = info
  info! 外          interest=Interest(Always)     enabled=0     delivered=1000
  debug! 外         （没有注册）
  info_span!(req)  interest=Interest(Always)     enabled=0     delivered=1000
  debug! 内         （没有注册）
== info,my_app::db=debug   LevelFilter::current() = debug
  info! 外          interest=Interest(Always)     enabled=0     delivered=1000
  debug! 外         interest=Interest(Never)      enabled=0     delivered=0
  info_span!(req)  interest=Interest(Always)     enabled=0     delivered=1000
  debug! 内         interest=Interest(Never)      enabled=0     delivered=0
== info,[req]=debug   LevelFilter::current() = debug
  info! 外          interest=Interest(Always)     enabled=0     delivered=1000
  debug! 外         interest=Interest(Sometimes)  enabled=1000  delivered=0
  info_span!(req)  interest=Interest(Always)     enabled=0     delivered=1000
  debug! 内         interest=Interest(Sometimes)  enabled=1000  delivered=1000
== info,[req{user=bob}]=debug   LevelFilter::current() = trace
  info! 外          interest=Interest(Always)     enabled=0     delivered=1000
  debug! 外         interest=Interest(Sometimes)  enabled=1000  delivered=0
  info_span!(req)  interest=Interest(Always)     enabled=0     delivered=1000
  debug! 内         interest=Interest(Sometimes)  enabled=1000  delivered=1000

    fn parse_regex(s: &str) -> Result<Self, matchers::BuildError> {
        s.parse::<bool>()
            .map(ValueMatch::Bool)
            .or_else(|_| s.parse::<u64>().map(ValueMatch::U64))
            .or_else(|_| s.parse::<i64>().map(ValueMatch::I64))
            .or_else(|_| s.parse::<f64>().map(value_match_f64))
            .or_else(|_| {
                s.parse::<MatchPattern>()
                    .map(|p| ValueMatch::Pat(Box::new(p)))
            })
    }

use std::sync::atomic::{AtomicUsize, Ordering::Relaxed};

use tracing::{Event, Subscriber};
use tracing_subscriber::layer::{Context, Layer};
use tracing_subscriber::prelude::*;
use tracing_subscriber::{EnvFilter, Registry};

static HITS: AtomicUsize = AtomicUsize::new(0);

struct Sink;
impl<S: Subscriber> Layer<S> for Sink {
  fn on_event(&self, _: &Event<'_>, _: Context<'_, S>) {
    HITS.fetch_add(1, Relaxed);
  }
}

#[derive(Debug)]
#[allow(dead_code)]
struct User {
  name: &'static str,
}

fn work() {
  let span = tracing::info_span!(
    "req",
    user = "bob",
    id = 42u64,
    delta = -3i64,
    ok = true,
    ratio = 0.5,
    who = ?User { name: "bob" },
  );
  let _g = span.enter();
  tracing::debug!("inside");
}

fn event_only() {
  tracing::debug!(user = "bob", "no span");
}

fn check(spec: &str, regex: bool, f: fn()) {
  HITS.store(0, Relaxed);
  let filter = EnvFilter::builder().with_regex(regex).parse(spec).unwrap();
  tracing::subscriber::with_default(Registry::default().with(Sink).with(filter), f);
  let hit = if HITS.load(Relaxed) > 0 { "命中" } else { "不中" };
  println!("regex={regex:<5} {spec:<36} {hit}");
}

fn main() {
  for (spec, regex) in [
    ("[req{user=bob}]=debug", true),
    ("[req{user=bo}]=debug", true),
    ("[req{user=ob}]=debug", true),
    ("[req{user=.*bo.*}]=debug", true),
    ("[req{user=^b.b$}]=debug", true),
    ("[req{user=\"bob\"}]=debug", true),
    ("[req{user=bob}]=debug", false),
    ("[req{user=\"bob\"}]=debug", false),
    ("[req{user=bobby}]=debug", false),
    ("[req{user=\"bob\"xyz}]=debug", false),
    ("[req{id=42}]=debug", true),
    ("[req{id=4}]=debug", true),
    ("[req{delta=-3}]=debug", true),
    ("[req{ok=true}]=debug", true),
    ("[req{ratio=0.5}]=debug", true),
    ("[req{who=bob}]=debug", true),
    ("[req{who=.*bob.*}]=debug", true),
    ("[req{who=User}]=debug", false),
  ] {
    check(spec, regex, work);
  }
  println!("-- 没有 span，字段在事件上");
  check("[{user=bob}]=debug", true, event_only);
  check("[{user}]=debug", true, event_only);
}

regex=true  [req{user=bob}]=debug                命中
regex=true  [req{user=bo}]=debug                 不中
regex=true  [req{user=ob}]=debug                 命中
regex=true  [req{user=.*bo.*}]=debug             命中
regex=true  [req{user=^b.b$}]=debug              命中
regex=true  [req{user="bob"}]=debug              不中
regex=false [req{user=bob}]=debug                不中
regex=false [req{user="bob"}]=debug              命中
regex=false [req{user=bobby}]=debug              不中
regex=false [req{user="bob"xyz}]=debug           命中
regex=true  [req{id=42}]=debug                   命中
regex=true  [req{id=4}]=debug                    不中
regex=true  [req{delta=-3}]=debug                命中
regex=true  [req{ok=true}]=debug                 命中
regex=true  [req{ratio=0.5}]=debug               命中
regex=true  [req{who=bob}]=debug                 不中
regex=true  [req{who=.*bob.*}]=debug             命中
regex=false [req{who=User}]=debug                不中
-- 没有 span，字段在事件上
regex=true  [{user=bob}]=debug                   不中
regex=true  [{user}]=debug                       命中

    pub fn max_level_hint(&self) -> Option<LevelFilter> {
        if self.dynamics.has_value_filters() {
            // If we perform any filtering on span field *values*, we will
            // enable *all* spans, because their field values are not known
            // until recording.
            return Some(LevelFilter::TRACE);
        }
        std::cmp::max(
            self.statics.max_level.into(),
            self.dynamics.max_level.into(),
        )
    }

use std::hint::black_box;
use std::time::Instant;

use tracing_subscriber::prelude::*;
use tracing_subscriber::{EnvFilter, Registry};

const N: u32 = 10_000_000;

fn per_op(f: impl Fn()) -> f64 {
  for _ in 0..N / 10 {
    f(); // 预热，也让调用点先注册好
  }
  let t = Instant::now();
  for _ in 0..N {
    f();
  }
  t.elapsed().as_nanos() as f64 / N as f64
}

fn bench(spec: &str) {
  // 只有 Registry 和 EnvFilter，没有输出层：量的是过滤本身
  let sub = Registry::default().with(EnvFilter::new(spec));
  tracing::subscriber::with_default(sub, || {
    let outside = per_op(|| tracing::debug!(n = black_box(1), "debug"));
    let span = tracing::info_span!("req");
    let enter_exit = per_op(|| {
      let _g = span.enter();
    });
    let _g = span.enter();
    let inside = per_op(|| tracing::debug!(n = black_box(1), "debug"));
    println!(
      "{spec:<20} debug!外 {outside:>6.2} ns   enter+exit {enter_exit:>6.2} ns   debug!内 {inside:>6.2} ns"
    );
  });
}

fn parse_cost(spec: &str) {
  let t = Instant::now();
  let f = EnvFilter::try_new(spec).unwrap();
  let first = t.elapsed();
  black_box(f);
  let n = 1000;
  let t = Instant::now();
  for _ in 0..n {
    black_box(EnvFilter::try_new(spec).unwrap());
  }
  let avg = t.elapsed() / n;
  println!("try_new({spec:?}): 第一次 {first:?}，之后平均 {avg:?}");
}

fn main() {
  bench("info");
  bench("info,[req]=debug");
  parse_cost("debug");
  parse_cost("info,[req{user=bob}]=debug");
}

info                 debug!外   0.34 ns   enter+exit  30.98 ns   debug!内   0.33 ns
info,[req]=debug     debug!外   7.24 ns   enter+exit  33.01 ns   debug!内  13.01 ns
try_new("debug"): 第一次 3.708µs，之后平均 270ns
try_new("info,[req{user=bob}]=debug"): 第一次 1.651291ms，之后平均 8.738µs

info                 debug!外   0.29 ns   enter+exit  30.57 ns   debug!内   0.33 ns
info,[req]=debug     debug!外   7.20 ns   enter+exit  32.54 ns   debug!内  13.08 ns
try_new("debug"): 第一次 3.917µs，之后平均 257ns
try_new("info,[req{user=bob}]=debug"): 第一次 58.416µs，之后平均 8.981µs

info                 debug!外   0.32 ns   enter+exit  30.56 ns   debug!内   0.30 ns
info,[req]=debug     debug!外   7.29 ns   enter+exit  33.10 ns   debug!内  13.27 ns
try_new("debug"): 第一次 3.625µs，之后平均 263ns
try_new("info,[req{user=bob}]=debug"): 第一次 64.792µs，之后平均 9.036µs

$ ./env_quiz
 INFO env_quiz: info event
ERROR env_quiz: error event
$ RUST_LOG= ./env_quiz