From 698f8c2f01ea549d77d7dc3338a12e04c11057b9 Mon Sep 17 00:00:00 2001 From: Daniel Baumann Date: Wed, 17 Apr 2024 14:02:58 +0200 Subject: Adding upstream version 1.64.0+dfsg1. Signed-off-by: Daniel Baumann --- vendor/tracing-log/src/env_logger.rs | 49 +++ vendor/tracing-log/src/interest_cache.rs | 542 ++++++++++++++++++++++++++ vendor/tracing-log/src/lib.rs | 628 +++++++++++++++++++++++++++++++ vendor/tracing-log/src/log_tracer.rs | 307 +++++++++++++++ vendor/tracing-log/src/trace_logger.rs | 458 ++++++++++++++++++++++ 5 files changed, 1984 insertions(+) create mode 100644 vendor/tracing-log/src/env_logger.rs create mode 100644 vendor/tracing-log/src/interest_cache.rs create mode 100644 vendor/tracing-log/src/lib.rs create mode 100644 vendor/tracing-log/src/log_tracer.rs create mode 100644 vendor/tracing-log/src/trace_logger.rs (limited to 'vendor/tracing-log/src') diff --git a/vendor/tracing-log/src/env_logger.rs b/vendor/tracing-log/src/env_logger.rs new file mode 100644 index 000000000..74922d1dc --- /dev/null +++ b/vendor/tracing-log/src/env_logger.rs @@ -0,0 +1,49 @@ +//! Utilities for configuring the `env_logger` crate to emit `tracing` events. + +/// Extension trait to configure an `env_logger::Builder` to emit traces. +pub trait BuilderExt: crate::sealed::Sealed { + /// Configure the built `env_logger::Logger` to emit `tracing` events for + /// all consumed `log` records, rather than printing them to standard out. + /// + /// Note that this replaces any previously configured formatting. + fn emit_traces(&mut self) -> &mut Self; +} + +impl crate::sealed::Sealed for env_logger::Builder {} + +impl BuilderExt for env_logger::Builder { + fn emit_traces(&mut self) -> &mut Self { + self.format(|_, record| super::format_trace(record)) + } +} + +/// Attempts to initialize the global logger with an env logger configured to +/// emit `tracing` events. +/// +/// This should be called early in the execution of a Rust program. Any log +/// events that occur before initialization will be ignored. +/// +/// # Errors +/// +/// This function will fail if it is called more than once, or if another +/// library has already initialized a global logger. +pub fn try_init() -> Result<(), log::SetLoggerError> { + env_logger::Builder::from_default_env() + .emit_traces() + .try_init() +} + +/// Initializes the global logger with an env logger configured to +/// emit `tracing` events. +/// +/// This should be called early in the execution of a Rust program. Any log +/// events that occur before initialization will be ignored. +/// +/// # Panics +/// +/// This function will panic if it is called more than once, or if another +/// library has already initialized a global logger. +pub fn init() { + try_init() + .expect("tracing_log::env_logger::init should not be called after logger initialized"); +} diff --git a/vendor/tracing-log/src/interest_cache.rs b/vendor/tracing-log/src/interest_cache.rs new file mode 100644 index 000000000..fb3da875e --- /dev/null +++ b/vendor/tracing-log/src/interest_cache.rs @@ -0,0 +1,542 @@ +use ahash::AHasher; +use log::{Level, Metadata}; +use lru::LruCache; +use std::cell::RefCell; +use std::hash::Hasher; +use std::sync::atomic::{AtomicUsize, Ordering}; +use std::sync::Mutex; + +/// The interest cache configuration. +#[derive(Debug)] +pub struct InterestCacheConfig { + min_verbosity: Level, + lru_cache_size: usize, +} + +impl Default for InterestCacheConfig { + fn default() -> Self { + InterestCacheConfig { + min_verbosity: Level::Debug, + lru_cache_size: 1024, + } + } +} + +impl InterestCacheConfig { + fn disabled() -> Self { + Self { + lru_cache_size: 0, + ..Self::default() + } + } +} + +impl InterestCacheConfig { + /// Sets the minimum logging verbosity for which the cache will apply. + /// + /// The interest for logs with a lower verbosity than specified here + /// will not be cached. + /// + /// It should be set to the lowest verbosity level for which the majority + /// of the logs in your application are usually *disabled*. + /// + /// In normal circumstances with typical logger usage patterns + /// you shouldn't ever have to change this. + /// + /// By default this is set to `Debug`. + pub fn with_min_verbosity(mut self, level: Level) -> Self { + self.min_verbosity = level; + self + } + + /// Sets the number of entries in the LRU cache used to cache interests + /// for `log` records. + /// + /// The bigger the cache, the more unlikely it will be for the interest + /// in a given callsite to be recalculated, at the expense of extra + /// memory usage per every thread which tries to log events. + /// + /// Every unique [level] + [target] pair consumes a single slot + /// in the cache. Entries will be added to the cache until its size + /// reaches the value configured here, and from then on it will evict + /// the least recently seen level + target pair when adding a new entry. + /// + /// The ideal value to set here widely depends on how much exactly + /// you're logging, and how diverse the targets are to which you are logging. + /// + /// If your application spends a significant amount of time filtering logs + /// which are *not* getting printed out then increasing this value will most + /// likely help. + /// + /// Setting this to zero will disable the cache. + /// + /// By default this is set to 1024. + /// + /// [level]: log::Metadata::level + /// [target]: log::Metadata::target + pub fn with_lru_cache_size(mut self, size: usize) -> Self { + self.lru_cache_size = size; + self + } +} + +#[derive(Copy, Clone, PartialEq, Eq, Hash)] +struct Key { + target_address: usize, + level_and_length: usize, +} + +struct State { + min_verbosity: Level, + epoch: usize, + cache: LruCache, +} + +impl State { + fn new(epoch: usize, config: &InterestCacheConfig) -> Self { + State { + epoch, + min_verbosity: config.min_verbosity, + cache: LruCache::new(config.lru_cache_size), + } + } +} + +// When the logger's filters are reconfigured the interest cache in core is cleared, +// and we also want to get notified when that happens so that we can clear our cache too. +// +// So what we do here is to register a dummy callsite with the core, just so that we can be +// notified when that happens. It doesn't really matter how exactly our dummy callsite looks +// like and whether subscribers will actually be interested in it, since nothing will actually +// be logged from it. + +static INTEREST_CACHE_EPOCH: AtomicUsize = AtomicUsize::new(0); + +fn interest_cache_epoch() -> usize { + INTEREST_CACHE_EPOCH.load(Ordering::Relaxed) +} + +struct SentinelCallsite; + +impl tracing_core::Callsite for SentinelCallsite { + fn set_interest(&self, _: tracing_core::subscriber::Interest) { + INTEREST_CACHE_EPOCH.fetch_add(1, Ordering::SeqCst); + } + + fn metadata(&self) -> &tracing_core::Metadata<'_> { + &SENTINEL_METADATA + } +} + +static SENTINEL_CALLSITE: SentinelCallsite = SentinelCallsite; +static SENTINEL_METADATA: tracing_core::Metadata<'static> = tracing_core::Metadata::new( + "log interest cache", + "log", + tracing_core::Level::ERROR, + None, + None, + None, + tracing_core::field::FieldSet::new(&[], tracing_core::identify_callsite!(&SENTINEL_CALLSITE)), + tracing_core::metadata::Kind::EVENT, +); + +lazy_static::lazy_static! { + static ref CONFIG: Mutex = { + tracing_core::callsite::register(&SENTINEL_CALLSITE); + Mutex::new(InterestCacheConfig::disabled()) + }; +} + +thread_local! { + static STATE: RefCell = { + let config = CONFIG.lock().unwrap(); + RefCell::new(State::new(interest_cache_epoch(), &config)) + }; +} + +pub(crate) fn configure(new_config: Option) { + *CONFIG.lock().unwrap() = new_config.unwrap_or_else(InterestCacheConfig::disabled); + INTEREST_CACHE_EPOCH.fetch_add(1, Ordering::SeqCst); +} + +pub(crate) fn try_cache(metadata: &Metadata<'_>, callback: impl FnOnce() -> bool) -> bool { + STATE.with(|state| { + let mut state = state.borrow_mut(); + + // If the interest cache in core was rebuilt we need to reset the cache here too. + let epoch = interest_cache_epoch(); + if epoch != state.epoch { + *state = State::new(epoch, &CONFIG.lock().unwrap()); + } + + let level = metadata.level(); + if state.cache.cap() == 0 || level < state.min_verbosity { + return callback(); + } + + let target = metadata.target(); + + let mut hasher = AHasher::default(); + hasher.write(target.as_bytes()); + + const HASH_MASK: u64 = !1; + const INTEREST_MASK: u64 = 1; + + // We mask out the least significant bit of the hash since we'll use + // that space to save the interest. + // + // Since we use a good hashing function the loss of only a single bit + // won't really affect us negatively. + let target_hash = hasher.finish() & HASH_MASK; + + // Since log targets are usually static strings we just use the address of the pointer + // as the key for our cache. + // + // We want each level to be cached separately so we also use the level as key, and since + // some linkers at certain optimization levels deduplicate strings if their prefix matches + // (e.g. "ham" and "hamster" might actually have the same address in memory) we also use the length. + let key = Key { + target_address: target.as_ptr() as usize, + // For extra efficiency we pack both the level and the length into a single field. + // The `level` can be between 1 and 5, so it can take at most 3 bits of space. + level_and_length: level as usize | target.len().wrapping_shl(3), + }; + + if let Some(&cached) = state.cache.get(&key) { + // And here we make sure that the target actually matches. + // + // This is just a hash of the target string, so theoretically we're not guaranteed + // that it won't collide, however in practice it shouldn't matter as it is quite + // unlikely that the target string's address and its length and the level and + // the hash will *all* be equal at the same time. + // + // We could of course actually store the whole target string in our cache, + // but we really want to avoid doing that as the necessary memory allocations + // would completely tank our performance, especially in cases where the cache's + // size is too small so it needs to regularly replace entries. + if cached & HASH_MASK == target_hash { + return (cached & INTEREST_MASK) != 0; + } + + // Realistically we should never land here, unless someone is using a non-static + // target string with the same length and level, or is very lucky and found a hash + // collision for the cache's key. + } + + let interest = callback(); + state.cache.put(key, target_hash | interest as u64); + + interest + }) +} + +#[cfg(test)] +mod tests { + use super::*; + + fn lock_for_test() -> impl Drop { + // We need to make sure only one test runs at a time. + + lazy_static::lazy_static! { + static ref LOCK: Mutex<()> = Mutex::new(()); + } + + match LOCK.lock() { + Ok(guard) => guard, + Err(poison) => poison.into_inner(), + } + } + + #[test] + fn test_when_disabled_the_callback_is_always_called() { + let _lock = lock_for_test(); + + *CONFIG.lock().unwrap() = InterestCacheConfig::disabled(); + + std::thread::spawn(|| { + let metadata = log::MetadataBuilder::new() + .level(Level::Trace) + .target("dummy") + .build(); + let mut count = 0; + try_cache(&metadata, || { + count += 1; + true + }); + assert_eq!(count, 1); + try_cache(&metadata, || { + count += 1; + true + }); + assert_eq!(count, 2); + }) + .join() + .unwrap(); + } + + #[test] + fn test_when_enabled_the_callback_is_called_only_once_for_a_high_enough_verbosity() { + let _lock = lock_for_test(); + + *CONFIG.lock().unwrap() = InterestCacheConfig::default().with_min_verbosity(Level::Debug); + + std::thread::spawn(|| { + let metadata = log::MetadataBuilder::new() + .level(Level::Debug) + .target("dummy") + .build(); + let mut count = 0; + try_cache(&metadata, || { + count += 1; + true + }); + assert_eq!(count, 1); + try_cache(&metadata, || { + count += 1; + true + }); + assert_eq!(count, 1); + }) + .join() + .unwrap(); + } + + #[test] + fn test_when_core_interest_cache_is_rebuilt_this_cache_is_also_flushed() { + let _lock = lock_for_test(); + + *CONFIG.lock().unwrap() = InterestCacheConfig::default().with_min_verbosity(Level::Debug); + + std::thread::spawn(|| { + let metadata = log::MetadataBuilder::new() + .level(Level::Debug) + .target("dummy") + .build(); + { + let mut count = 0; + try_cache(&metadata, || { + count += 1; + true + }); + try_cache(&metadata, || { + count += 1; + true + }); + assert_eq!(count, 1); + } + tracing_core::callsite::rebuild_interest_cache(); + { + let mut count = 0; + try_cache(&metadata, || { + count += 1; + true + }); + try_cache(&metadata, || { + count += 1; + true + }); + assert_eq!(count, 1); + } + }) + .join() + .unwrap(); + } + + #[test] + fn test_when_enabled_the_callback_is_always_called_for_a_low_enough_verbosity() { + let _lock = lock_for_test(); + + *CONFIG.lock().unwrap() = InterestCacheConfig::default().with_min_verbosity(Level::Debug); + + std::thread::spawn(|| { + let metadata = log::MetadataBuilder::new() + .level(Level::Info) + .target("dummy") + .build(); + let mut count = 0; + try_cache(&metadata, || { + count += 1; + true + }); + assert_eq!(count, 1); + try_cache(&metadata, || { + count += 1; + true + }); + assert_eq!(count, 2); + }) + .join() + .unwrap(); + } + + #[test] + fn test_different_log_levels_are_cached_separately() { + let _lock = lock_for_test(); + + *CONFIG.lock().unwrap() = InterestCacheConfig::default().with_min_verbosity(Level::Debug); + + std::thread::spawn(|| { + let metadata_debug = log::MetadataBuilder::new() + .level(Level::Debug) + .target("dummy") + .build(); + let metadata_trace = log::MetadataBuilder::new() + .level(Level::Trace) + .target("dummy") + .build(); + let mut count_debug = 0; + let mut count_trace = 0; + try_cache(&metadata_debug, || { + count_debug += 1; + true + }); + try_cache(&metadata_trace, || { + count_trace += 1; + true + }); + try_cache(&metadata_debug, || { + count_debug += 1; + true + }); + try_cache(&metadata_trace, || { + count_trace += 1; + true + }); + assert_eq!(count_debug, 1); + assert_eq!(count_trace, 1); + }) + .join() + .unwrap(); + } + + #[test] + fn test_different_log_targets_are_cached_separately() { + let _lock = lock_for_test(); + + *CONFIG.lock().unwrap() = InterestCacheConfig::default().with_min_verbosity(Level::Debug); + + std::thread::spawn(|| { + let metadata_1 = log::MetadataBuilder::new() + .level(Level::Trace) + .target("dummy_1") + .build(); + let metadata_2 = log::MetadataBuilder::new() + .level(Level::Trace) + .target("dummy_2") + .build(); + let mut count_1 = 0; + let mut count_2 = 0; + try_cache(&metadata_1, || { + count_1 += 1; + true + }); + try_cache(&metadata_2, || { + count_2 += 1; + true + }); + try_cache(&metadata_1, || { + count_1 += 1; + true + }); + try_cache(&metadata_2, || { + count_2 += 1; + true + }); + assert_eq!(count_1, 1); + assert_eq!(count_2, 1); + }) + .join() + .unwrap(); + } + + #[test] + fn test_when_cache_runs_out_of_space_the_callback_is_called_again() { + let _lock = lock_for_test(); + + *CONFIG.lock().unwrap() = InterestCacheConfig::default() + .with_min_verbosity(Level::Debug) + .with_lru_cache_size(1); + + std::thread::spawn(|| { + let metadata_1 = log::MetadataBuilder::new() + .level(Level::Trace) + .target("dummy_1") + .build(); + let metadata_2 = log::MetadataBuilder::new() + .level(Level::Trace) + .target("dummy_2") + .build(); + let mut count = 0; + try_cache(&metadata_1, || { + count += 1; + true + }); + try_cache(&metadata_1, || { + count += 1; + true + }); + assert_eq!(count, 1); + try_cache(&metadata_2, || true); + try_cache(&metadata_1, || { + count += 1; + true + }); + assert_eq!(count, 2); + }) + .join() + .unwrap(); + } + + #[test] + fn test_cache_returns_previously_computed_value() { + let _lock = lock_for_test(); + + *CONFIG.lock().unwrap() = InterestCacheConfig::default().with_min_verbosity(Level::Debug); + + std::thread::spawn(|| { + let metadata_1 = log::MetadataBuilder::new() + .level(Level::Trace) + .target("dummy_1") + .build(); + let metadata_2 = log::MetadataBuilder::new() + .level(Level::Trace) + .target("dummy_2") + .build(); + try_cache(&metadata_1, || true); + assert_eq!(try_cache(&metadata_1, || { unreachable!() }), true); + try_cache(&metadata_2, || false); + assert_eq!(try_cache(&metadata_2, || { unreachable!() }), false); + }) + .join() + .unwrap(); + } + + #[test] + fn test_cache_handles_non_static_target_string() { + let _lock = lock_for_test(); + + *CONFIG.lock().unwrap() = InterestCacheConfig::default().with_min_verbosity(Level::Debug); + + std::thread::spawn(|| { + let mut target = *b"dummy_1"; + let metadata_1 = log::MetadataBuilder::new() + .level(Level::Trace) + .target(std::str::from_utf8(&target).unwrap()) + .build(); + + try_cache(&metadata_1, || true); + assert_eq!(try_cache(&metadata_1, || { unreachable!() }), true); + + *target.last_mut().unwrap() = b'2'; + let metadata_2 = log::MetadataBuilder::new() + .level(Level::Trace) + .target(std::str::from_utf8(&target).unwrap()) + .build(); + + try_cache(&metadata_2, || false); + assert_eq!(try_cache(&metadata_2, || { unreachable!() }), false); + }) + .join() + .unwrap(); + } +} diff --git a/vendor/tracing-log/src/lib.rs b/vendor/tracing-log/src/lib.rs new file mode 100644 index 000000000..09e9114a4 --- /dev/null +++ b/vendor/tracing-log/src/lib.rs @@ -0,0 +1,628 @@ +//! Adapters for connecting unstructured log records from the `log` crate into +//! the `tracing` ecosystem. +//! +//! # Overview +//! +//! [`tracing`] is a framework for instrumenting Rust programs with context-aware, +//! structured, event-based diagnostic information. This crate provides +//! compatibility layers for using `tracing` alongside the logging facade provided +//! by the [`log`] crate. +//! +//! This crate provides: +//! +//! - [`AsTrace`] and [`AsLog`] traits for converting between `tracing` and `log` types. +//! - [`LogTracer`], a [`log::Log`] implementation that consumes [`log::Record`]s +//! and outputs them as [`tracing::Event`]. +//! - An [`env_logger`] module, with helpers for using the [`env_logger` crate] +//! with `tracing` (optional, enabled by the `env-logger` feature). +//! +//! *Compiler support: [requires `rustc` 1.49+][msrv]* +//! +//! [msrv]: #supported-rust-versions +//! +//! # Usage +//! +//! ## Convert log records to tracing `Event`s +//! +//! To convert [`log::Record`]s as [`tracing::Event`]s, set `LogTracer` as the default +//! logger by calling its [`init`] or [`init_with_filter`] methods. +//! +//! ```rust +//! # use std::error::Error; +//! use tracing_log::LogTracer; +//! use log; +//! +//! # fn main() -> Result<(), Box> { +//! LogTracer::init()?; +//! +//! // will be available for Subscribers as a tracing Event +//! log::trace!("an example trace log"); +//! # Ok(()) +//! # } +//! ``` +//! +//! This conversion does not convert unstructured data in log records (such as +//! values passed as format arguments to the `log!` macro) to structured +//! `tracing` fields. However, it *does* attach these new events to to the +//! span that was currently executing when the record was logged. This is the +//! primary use-case for this library: making it possible to locate the log +//! records emitted by dependencies which use `log` within the context of a +//! trace. +//! +//! ## Convert tracing `Event`s to logs +//! +//! Enabling the ["log" and "log-always" feature flags][flags] on the `tracing` +//! crate will cause all `tracing` spans and events to emit `log::Record`s as +//! they occur. +//! +//! ## Caution: Mixing both conversions +//! +//! Note that logger implementations that convert log records to trace events +//! should not be used with `Subscriber`s that convert trace events _back_ into +//! log records (such as the `TraceLogger`), as doing so will result in the +//! event recursing between the subscriber and the logger forever (or, in real +//! life, probably overflowing the call stack). +//! +//! If the logging of trace events generated from log records produced by the +//! `log` crate is desired, either the `log` crate should not be used to +//! implement this logging, or an additional layer of filtering will be +//! required to avoid infinitely converting between `Event` and `log::Record`. +//! +//! # Feature Flags +//! * `trace-logger`: enables an experimental `log` subscriber, deprecated since +//! version 0.1.1. +//! * `log-tracer`: enables the `LogTracer` type (on by default) +//! * `env_logger`: enables the `env_logger` module, with helpers for working +//! with the [`env_logger` crate]. +//! * `interest-cache`: makes it possible to configure an interest cache for +//! logs emitted through the `log` crate (see [`Builder::with_interest_cache`]); requires `std` +//! +//! ## Supported Rust Versions +//! +//! Tracing is built against the latest stable release. The minimum supported +//! version is 1.49. The current Tracing version is not guaranteed to build on +//! Rust versions earlier than the minimum supported version. +//! +//! Tracing follows the same compiler support policies as the rest of the Tokio +//! project. The current stable Rust compiler and the three most recent minor +//! versions before it will always be supported. For example, if the current +//! stable compiler version is 1.45, the minimum supported version will not be +//! increased past 1.42, three minor versions prior. Increasing the minimum +//! supported compiler version is not considered a semver breaking change as +//! long as doing so complies with this policy. +//! +//! [`init`]: LogTracer::init +//! [`init_with_filter`]: LogTracer::init_with_filter +//! [`tracing`]: https://crates.io/crates/tracing +//! [`env_logger` crate]: https://crates.io/crates/env-logger +//! [`tracing::Subscriber`]: https://docs.rs/tracing/latest/tracing/trait.Subscriber.html +//! [`Subscriber`]: https://docs.rs/tracing/latest/tracing/trait.Subscriber.html +//! [`tracing::Event`]: https://docs.rs/tracing/latest/tracing/struct.Event.html +//! [flags]: https://docs.rs/tracing/latest/tracing/#crate-feature-flags +//! [`Builder::with_interest_cache`]: log_tracer::Builder::with_interest_cache +#![doc(html_root_url = "https://docs.rs/tracing-log/0.1.3")] +#![doc( + html_logo_url = "https://raw.githubusercontent.com/tokio-rs/tracing/master/assets/logo-type.png", + issue_tracker_base_url = "https://github.com/tokio-rs/tracing/issues/" +)] +#![cfg_attr(docsrs, feature(doc_cfg), deny(rustdoc::broken_intra_doc_links))] +#![warn( + missing_debug_implementations, + missing_docs, + rust_2018_idioms, + unreachable_pub, + bad_style, + const_err, + dead_code, + improper_ctypes, + non_shorthand_field_patterns, + no_mangle_generic_items, + overflowing_literals, + path_statements, + patterns_in_fns_without_body, + private_in_public, + unconditional_recursion, + unused, + unused_allocation, + unused_comparisons, + unused_parens, + while_true +)] +use lazy_static::lazy_static; + +use std::{fmt, io}; + +use tracing_core::{ + callsite::{self, Callsite}, + dispatcher, + field::{self, Field, Visit}, + identify_callsite, + metadata::{Kind, Level}, + subscriber, Event, Metadata, +}; + +#[cfg(feature = "log-tracer")] +#[cfg_attr(docsrs, doc(cfg(feature = "log-tracer")))] +pub mod log_tracer; + +#[cfg(feature = "trace-logger")] +#[cfg_attr(docsrs, doc(cfg(feature = "trace-logger")))] +pub mod trace_logger; + +#[cfg(feature = "log-tracer")] +#[cfg_attr(docsrs, doc(cfg(feature = "log-tracer")))] +#[doc(inline)] +pub use self::log_tracer::LogTracer; + +#[cfg(feature = "trace-logger")] +#[cfg_attr(docsrs, doc(cfg(feature = "trace-logger")))] +#[deprecated( + since = "0.1.1", + note = "use the `tracing` crate's \"log\" feature flag instead" +)] +#[allow(deprecated)] +#[doc(inline)] +pub use self::trace_logger::TraceLogger; + +#[cfg(feature = "env_logger")] +#[cfg_attr(docsrs, doc(cfg(feature = "env_logger")))] +pub mod env_logger; + +pub use log; + +#[cfg(all(feature = "interest-cache", feature = "log-tracer", feature = "std"))] +mod interest_cache; + +#[cfg(all(feature = "interest-cache", feature = "log-tracer", feature = "std"))] +#[cfg_attr( + docsrs, + doc(cfg(all(feature = "interest-cache", feature = "log-tracer", feature = "std"))) +)] +pub use crate::interest_cache::InterestCacheConfig; + +/// Format a log record as a trace event in the current span. +pub fn format_trace(record: &log::Record<'_>) -> io::Result<()> { + dispatch_record(record); + Ok(()) +} + +// XXX(eliza): this is factored out so that we don't have to deal with the pub +// function `format_trace`'s `Result` return type...maybe we should get rid of +// that in 0.2... +pub(crate) fn dispatch_record(record: &log::Record<'_>) { + dispatcher::get_default(|dispatch| { + let filter_meta = record.as_trace(); + if !dispatch.enabled(&filter_meta) { + return; + } + + let (_, keys, meta) = loglevel_to_cs(record.level()); + + let log_module = record.module_path(); + let log_file = record.file(); + let log_line = record.line(); + + let module = log_module.as_ref().map(|s| s as &dyn field::Value); + let file = log_file.as_ref().map(|s| s as &dyn field::Value); + let line = log_line.as_ref().map(|s| s as &dyn field::Value); + + dispatch.event(&Event::new( + meta, + &meta.fields().value_set(&[ + (&keys.message, Some(record.args() as &dyn field::Value)), + (&keys.target, Some(&record.target())), + (&keys.module, module), + (&keys.file, file), + (&keys.line, line), + ]), + )); + }); +} + +/// Trait implemented for `tracing` types that can be converted to a `log` +/// equivalent. +pub trait AsLog: crate::sealed::Sealed { + /// The `log` type that this type can be converted into. + type Log; + /// Returns the `log` equivalent of `self`. + fn as_log(&self) -> Self::Log; +} + +/// Trait implemented for `log` types that can be converted to a `tracing` +/// equivalent. +pub trait AsTrace: crate::sealed::Sealed { + /// The `tracing` type that this type can be converted into. + type Trace; + /// Returns the `tracing` equivalent of `self`. + fn as_trace(&self) -> Self::Trace; +} + +impl<'a> crate::sealed::Sealed for Metadata<'a> {} + +impl<'a> AsLog for Metadata<'a> { + type Log = log::Metadata<'a>; + fn as_log(&self) -> Self::Log { + log::Metadata::builder() + .level(self.level().as_log()) + .target(self.target()) + .build() + } +} +impl<'a> crate::sealed::Sealed for log::Metadata<'a> {} + +impl<'a> AsTrace for log::Metadata<'a> { + type Trace = Metadata<'a>; + fn as_trace(&self) -> Self::Trace { + let cs_id = identify_callsite!(loglevel_to_cs(self.level()).0); + Metadata::new( + "log record", + self.target(), + self.level().as_trace(), + None, + None, + None, + field::FieldSet::new(FIELD_NAMES, cs_id), + Kind::EVENT, + ) + } +} + +struct Fields { + message: field::Field, + target: field::Field, + module: field::Field, + file: field::Field, + line: field::Field, +} + +static FIELD_NAMES: &[&str] = &[ + "message", + "log.target", + "log.module_path", + "log.file", + "log.line", +]; + +impl Fields { + fn new(cs: &'static dyn Callsite) -> Self { + let fieldset = cs.metadata().fields(); + let message = fieldset.field("message").unwrap(); + let target = fieldset.field("log.target").unwrap(); + let module = fieldset.field("log.module_path").unwrap(); + let file = fieldset.field("log.file").unwrap(); + let line = fieldset.field("log.line").unwrap(); + Fields { + message, + target, + module, + file, + line, + } + } +} + +macro_rules! log_cs { + ($level:expr, $cs:ident, $meta:ident, $ty:ident) => { + struct $ty; + static $cs: $ty = $ty; + static $meta: Metadata<'static> = Metadata::new( + "log event", + "log", + $level, + None, + None, + None, + field::FieldSet::new(FIELD_NAMES, identify_callsite!(&$cs)), + Kind::EVENT, + ); + + impl callsite::Callsite for $ty { + fn set_interest(&self, _: subscriber::Interest) {} + fn metadata(&self) -> &'static Metadata<'static> { + &$meta + } + } + }; +} + +log_cs!( + tracing_core::Level::TRACE, + TRACE_CS, + TRACE_META, + TraceCallsite +); +log_cs!( + tracing_core::Level::DEBUG, + DEBUG_CS, + DEBUG_META, + DebugCallsite +); +log_cs!(tracing_core::Level::INFO, INFO_CS, INFO_META, InfoCallsite); +log_cs!(tracing_core::Level::WARN, WARN_CS, WARN_META, WarnCallsite); +log_cs!( + tracing_core::Level::ERROR, + ERROR_CS, + ERROR_META, + ErrorCallsite +); + +lazy_static! { + static ref TRACE_FIELDS: Fields = Fields::new(&TRACE_CS); + static ref DEBUG_FIELDS: Fields = Fields::new(&DEBUG_CS); + static ref INFO_FIELDS: Fields = Fields::new(&INFO_CS); + static ref WARN_FIELDS: Fields = Fields::new(&WARN_CS); + static ref ERROR_FIELDS: Fields = Fields::new(&ERROR_CS); +} + +fn level_to_cs(level: Level) -> (&'static dyn Callsite, &'static Fields) { + match level { + Level::TRACE => (&TRACE_CS, &*TRACE_FIELDS), + Level::DEBUG => (&DEBUG_CS, &*DEBUG_FIELDS), + Level::INFO => (&INFO_CS, &*INFO_FIELDS), + Level::WARN => (&WARN_CS, &*WARN_FIELDS), + Level::ERROR => (&ERROR_CS, &*ERROR_FIELDS), + } +} + +fn loglevel_to_cs( + level: log::Level, +) -> ( + &'static dyn Callsite, + &'static Fields, + &'static Metadata<'static>, +) { + match level { + log::Level::Trace => (&TRACE_CS, &*TRACE_FIELDS, &TRACE_META), + log::Level::Debug => (&DEBUG_CS, &*DEBUG_FIELDS, &DEBUG_META), + log::Level::Info => (&INFO_CS, &*INFO_FIELDS, &INFO_META), + log::Level::Warn => (&WARN_CS, &*WARN_FIELDS, &WARN_META), + log::Level::Error => (&ERROR_CS, &*ERROR_FIELDS, &ERROR_META), + } +} + +impl<'a> crate::sealed::Sealed for log::Record<'a> {} + +impl<'a> AsTrace for log::Record<'a> { + type Trace = Metadata<'a>; + fn as_trace(&self) -> Self::Trace { + let cs_id = identify_callsite!(loglevel_to_cs(self.level()).0); + Metadata::new( + "log record", + self.target(), + self.level().as_trace(), + self.file(), + self.line(), + self.module_path(), + field::FieldSet::new(FIELD_NAMES, cs_id), + Kind::EVENT, + ) + } +} + +impl crate::sealed::Sealed for tracing_core::Level {} + +impl AsLog for tracing_core::Level { + type Log = log::Level; + fn as_log(&self) -> log::Level { + match *self { + tracing_core::Level::ERROR => log::Level::Error, + tracing_core::Level::WARN => log::Level::Warn, + tracing_core::Level::INFO => log::Level::Info, + tracing_core::Level::DEBUG => log::Level::Debug, + tracing_core::Level::TRACE => log::Level::Trace, + } + } +} + +impl crate::sealed::Sealed for log::Level {} + +impl AsTrace for log::Level { + type Trace = tracing_core::Level; + #[inline] + fn as_trace(&self) -> tracing_core::Level { + match self { + log::Level::Error => tracing_core::Level::ERROR, + log::Level::Warn => tracing_core::Level::WARN, + log::Level::Info => tracing_core::Level::INFO, + log::Level::Debug => tracing_core::Level::DEBUG, + log::Level::Trace => tracing_core::Level::TRACE, + } + } +} + +impl crate::sealed::Sealed for log::LevelFilter {} + +impl AsTrace for log::LevelFilter { + type Trace = tracing_core::LevelFilter; + #[inline] + fn as_trace(&self) -> tracing_core::LevelFilter { + match self { + log::LevelFilter::Off => tracing_core::LevelFilter::OFF, + log::LevelFilter::Error => tracing_core::LevelFilter::ERROR, + log::LevelFilter::Warn => tracing_core::LevelFilter::WARN, + log::LevelFilter::Info => tracing_core::LevelFilter::INFO, + log::LevelFilter::Debug => tracing_core::LevelFilter::DEBUG, + log::LevelFilter::Trace => tracing_core::LevelFilter::TRACE, + } + } +} + +impl crate::sealed::Sealed for tracing_core::LevelFilter {} + +impl AsLog for tracing_core::LevelFilter { + type Log = log::LevelFilter; + #[inline] + fn as_log(&self) -> Self::Log { + match *self { + tracing_core::LevelFilter::OFF => log::LevelFilter::Off, + tracing_core::LevelFilter::ERROR => log::LevelFilter::Error, + tracing_core::LevelFilter::WARN => log::LevelFilter::Warn, + tracing_core::LevelFilter::INFO => log::LevelFilter::Info, + tracing_core::LevelFilter::DEBUG => log::LevelFilter::Debug, + tracing_core::LevelFilter::TRACE => log::LevelFilter::Trace, + } + } +} +/// Extends log `Event`s to provide complete `Metadata`. +/// +/// In `tracing-log`, an `Event` produced by a log (through [`AsTrace`]) has an hard coded +/// "log" target and no `file`, `line`, or `module_path` attributes. This happens because `Event` +/// requires its `Metadata` to be `'static`, while [`log::Record`]s provide them with a generic +/// lifetime. +/// +/// However, these values are stored in the `Event`'s fields and +/// the [`normalized_metadata`] method allows to build a new `Metadata` +/// that only lives as long as its source `Event`, but provides complete +/// data. +/// +/// It can typically be used by `Subscriber`s when processing an `Event`, +/// to allow accessing its complete metadata in a consistent way, +/// regardless of the source of its source. +/// +/// [`normalized_metadata`]: NormalizeEvent#normalized_metadata +pub trait NormalizeEvent<'a>: crate::sealed::Sealed { + /// If this `Event` comes from a `log`, this method provides a new + /// normalized `Metadata` which has all available attributes + /// from the original log, including `file`, `line`, `module_path` + /// and `target`. + /// Returns `None` is the `Event` is not issued from a `log`. + fn normalized_metadata(&'a self) -> Option>; + /// Returns whether this `Event` represents a log (from the `log` crate) + fn is_log(&self) -> bool; +} + +impl<'a> crate::sealed::Sealed for Event<'a> {} + +impl<'a> NormalizeEvent<'a> for Event<'a> { + fn normalized_metadata(&'a self) -> Option> { + let original = self.metadata(); + if self.is_log() { + let mut fields = LogVisitor::new_for(self, level_to_cs(*original.level()).1); + self.record(&mut fields); + + Some(Metadata::new( + "log event", + fields.target.unwrap_or("log"), + *original.level(), + fields.file, + fields.line.map(|l| l as u32), + fields.module_path, + field::FieldSet::new(&["message"], original.callsite()), + Kind::EVENT, + )) + } else { + None + } + } + + fn is_log(&self) -> bool { + self.metadata().callsite() == identify_callsite!(level_to_cs(*self.metadata().level()).0) + } +} + +struct LogVisitor<'a> { + target: Option<&'a str>, + module_path: Option<&'a str>, + file: Option<&'a str>, + line: Option, + fields: &'static Fields, +} + +impl<'a> LogVisitor<'a> { + // We don't actually _use_ the provided event argument; it is simply to + // ensure that the `LogVisitor` does not outlive the event whose fields it + // is visiting, so that the reference casts in `record_str` are safe. + fn new_for(_event: &'a Event<'a>, fields: &'static Fields) -> Self { + Self { + target: None, + module_path: None, + file: None, + line: None, + fields, + } + } +} + +impl<'a> Visit for LogVisitor<'a> { + fn record_debug(&mut self, _field: &Field, _value: &dyn fmt::Debug) {} + + fn record_u64(&mut self, field: &Field, value: u64) { + if field == &self.fields.line { + self.line = Some(value); + } + } + + fn record_str(&mut self, field: &Field, value: &str) { + unsafe { + // The `Visit` API erases the string slice's lifetime. However, we + // know it is part of the `Event` struct with a lifetime of `'a`. If + // (and only if!) this `LogVisitor` was constructed with the same + // lifetime parameter `'a` as the event in question, it's safe to + // cast these string slices to the `'a` lifetime. + if field == &self.fields.file { + self.file = Some(&*(value as *const _)); + } else if field == &self.fields.target { + self.target = Some(&*(value as *const _)); + } else if field == &self.fields.module { + self.module_path = Some(&*(value as *const _)); + } + } + } +} + +mod sealed { + pub trait Sealed {} +} + +#[cfg(test)] +mod test { + use super::*; + + fn test_callsite(level: log::Level) { + let record = log::Record::builder() + .args(format_args!("Error!")) + .level(level) + .target("myApp") + .file(Some("server.rs")) + .line(Some(144)) + .module_path(Some("server")) + .build(); + + let meta = record.as_trace(); + let (cs, _keys, _) = loglevel_to_cs(record.level()); + let cs_meta = cs.metadata(); + assert_eq!( + meta.callsite(), + cs_meta.callsite(), + "actual: {:#?}\nexpected: {:#?}", + meta, + cs_meta + ); + assert_eq!(meta.level(), &level.as_trace()); + } + + #[test] + fn error_callsite_is_correct() { + test_callsite(log::Level::Error); + } + + #[test] + fn warn_callsite_is_correct() { + test_callsite(log::Level::Warn); + } + + #[test] + fn info_callsite_is_correct() { + test_callsite(log::Level::Info); + } + + #[test] + fn debug_callsite_is_correct() { + test_callsite(log::Level::Debug); + } + + #[test] + fn trace_callsite_is_correct() { + test_callsite(log::Level::Trace); + } +} diff --git a/vendor/tracing-log/src/log_tracer.rs b/vendor/tracing-log/src/log_tracer.rs new file mode 100644 index 000000000..6b24dab10 --- /dev/null +++ b/vendor/tracing-log/src/log_tracer.rs @@ -0,0 +1,307 @@ +//! An adapter for converting [`log`] records into `tracing` `Event`s. +//! +//! This module provides the [`LogTracer`] type which implements `log`'s [logger +//! interface] by recording log records as `tracing` `Event`s. This is intended for +//! use in conjunction with a `tracing` `Subscriber` to consume events from +//! dependencies that emit [`log`] records within a trace context. +//! +//! # Usage +//! +//! To create and initialize a `LogTracer` with the default configurations, use: +//! +//! * [`init`] if you want to convert all logs, regardless of log level, +//! allowing the tracing `Subscriber` to perform any filtering +//! * [`init_with_filter`] to convert all logs up to a specified log level +//! +//! In addition, a [builder] is available for cases where more advanced +//! configuration is required. In particular, the builder can be used to [ignore +//! log records][ignore] emitted by particular crates. This is useful in cases +//! such as when a crate emits both `tracing` diagnostics _and_ log records by +//! default. +//! +//! [logger interface]: log::Log +//! [`init`]: LogTracer.html#method.init +//! [`init_with_filter`]: LogTracer.html#method.init_with_filter +//! [builder]: LogTracer::builder() +//! [ignore]: Builder::ignore_crate() +use crate::AsTrace; +pub use log::SetLoggerError; +use tracing_core::dispatcher; + +/// A simple "logger" that converts all log records into `tracing` `Event`s. +#[derive(Debug)] +pub struct LogTracer { + ignore_crates: Box<[String]>, +} + +/// Configures a new `LogTracer`. +#[derive(Debug)] +pub struct Builder { + ignore_crates: Vec, + filter: log::LevelFilter, + #[cfg(all(feature = "interest-cache", feature = "std"))] + interest_cache_config: Option, +} + +// ===== impl LogTracer ===== + +impl LogTracer { + /// Returns a builder that allows customizing a `LogTracer` and setting it + /// the default logger. + /// + /// For example: + /// ```rust + /// # use std::error::Error; + /// use tracing_log::LogTracer; + /// use log; + /// + /// # fn main() -> Result<(), Box> { + /// LogTracer::builder() + /// .ignore_crate("foo") // suppose the `foo` crate is using `tracing`'s log feature + /// .with_max_level(log::LevelFilter::Info) + /// .init()?; + /// + /// // will be available for Subscribers as a tracing Event + /// log::info!("an example info log"); + /// # Ok(()) + /// # } + /// ``` + pub fn builder() -> Builder { + Builder::default() + } + + /// Creates a new `LogTracer` that can then be used as a logger for the `log` crate. + /// + /// It is generally simpler to use the [`init`] or [`init_with_filter`] methods + /// which will create the `LogTracer` and set it as the global logger. + /// + /// Logger setup without the initialization methods can be done with: + /// + /// ```rust + /// # use std::error::Error; + /// use tracing_log::LogTracer; + /// use log; + /// + /// # fn main() -> Result<(), Box> { + /// let logger = LogTracer::new(); + /// log::set_boxed_logger(Box::new(logger))?; + /// log::set_max_level(log::LevelFilter::Trace); + /// + /// // will be available for Subscribers as a tracing Event + /// log::trace!("an example trace log"); + /// # Ok(()) + /// # } + /// ``` + /// + /// [`init`]: LogTracer::init() + /// [`init_with_filter`]: .#method.init_with_filter + pub fn new() -> Self { + Self { + ignore_crates: Vec::new().into_boxed_slice(), + } + } + + /// Sets up `LogTracer` as global logger for the `log` crate, + /// with the given level as max level filter. + /// + /// Setting a global logger can only be done once. + /// + /// The [`builder`] function can be used to customize the `LogTracer` before + /// initializing it. + /// + /// [`builder`]: LogTracer::builder() + #[cfg(feature = "std")] + #[cfg_attr(docsrs, doc(cfg(feature = "std")))] + pub fn init_with_filter(level: log::LevelFilter) -> Result<(), SetLoggerError> { + Self::builder().with_max_level(level).init() + } + + /// Sets a `LogTracer` as the global logger for the `log` crate. + /// + /// Setting a global logger can only be done once. + /// + /// ```rust + /// # use std::error::Error; + /// use tracing_log::LogTracer; + /// use log; + /// + /// # fn main() -> Result<(), Box> { + /// LogTracer::init()?; + /// + /// // will be available for Subscribers as a tracing Event + /// log::trace!("an example trace log"); + /// # Ok(()) + /// # } + /// ``` + /// + /// This will forward all logs to `tracing` and lets the current `Subscriber` + /// determine if they are enabled. + /// + /// The [`builder`] function can be used to customize the `LogTracer` before + /// initializing it. + /// + /// If you know in advance you want to filter some log levels, + /// use [`builder`] or [`init_with_filter`] instead. + /// + /// [`init_with_filter`]: LogTracer::init_with_filter() + /// [`builder`]: LogTracer::builder() + #[cfg(feature = "std")] + #[cfg_attr(docsrs, doc(cfg(feature = "std")))] + pub fn init() -> Result<(), SetLoggerError> { + Self::builder().init() + } +} + +impl Default for LogTracer { + fn default() -> Self { + Self::new() + } +} + +#[cfg(all(feature = "interest-cache", feature = "std"))] +use crate::interest_cache::try_cache as try_cache_interest; + +#[cfg(not(all(feature = "interest-cache", feature = "std")))] +fn try_cache_interest(_: &log::Metadata<'_>, callback: impl FnOnce() -> bool) -> bool { + callback() +} + +impl log::Log for LogTracer { + fn enabled(&self, metadata: &log::Metadata<'_>) -> bool { + // First, check the log record against the current max level enabled by + // the current `tracing` subscriber. + if metadata.level().as_trace() > tracing_core::LevelFilter::current() { + // If the log record's level is above that, disable it. + return false; + } + + // Okay, it wasn't disabled by the max level — do we have any specific + // modules to ignore? + if !self.ignore_crates.is_empty() { + // If we are ignoring certain module paths, ensure that the metadata + // does not start with one of those paths. + let target = metadata.target(); + for ignored in &self.ignore_crates[..] { + if target.starts_with(ignored) { + return false; + } + } + } + + try_cache_interest(metadata, || { + // Finally, check if the current `tracing` dispatcher cares about this. + dispatcher::get_default(|dispatch| dispatch.enabled(&metadata.as_trace())) + }) + } + + fn log(&self, record: &log::Record<'_>) { + if self.enabled(record.metadata()) { + crate::dispatch_record(record); + } + } + + fn flush(&self) {} +} + +// ===== impl Builder ===== + +impl Builder { + /// Returns a new `Builder` to construct a [`LogTracer`]. + /// + pub fn new() -> Self { + Self::default() + } + + /// Sets a global maximum level for `log` records. + /// + /// Log records whose level is more verbose than the provided level will be + /// disabled. + /// + /// By default, all `log` records will be enabled. + pub fn with_max_level(self, filter: impl Into) -> Self { + let filter = filter.into(); + Self { filter, ..self } + } + + /// Configures the `LogTracer` to ignore all log records whose target + /// starts with the given string. + /// + /// This should be used when a crate enables the `tracing/log` feature to + /// emit log records for tracing events. Otherwise, those events will be + /// recorded twice. + pub fn ignore_crate(mut self, name: impl Into) -> Self { + self.ignore_crates.push(name.into()); + self + } + + /// Configures the `LogTracer` to ignore all log records whose target + /// starts with any of the given the given strings. + /// + /// This should be used when a crate enables the `tracing/log` feature to + /// emit log records for tracing events. Otherwise, those events will be + /// recorded twice. + pub fn ignore_all(self, crates: impl IntoIterator) -> Self + where + I: Into, + { + crates.into_iter().fold(self, Self::ignore_crate) + } + + /// Configures the `LogTracer` to either disable or enable the interest cache. + /// + /// When enabled, a per-thread LRU cache will be used to cache whenever the logger + /// is interested in a given [level] + [target] pair for records generated through + /// the `log` crate. + /// + /// When no `trace!` logs are enabled the logger is able to cheaply filter + /// them out just by comparing their log level to the globally specified + /// maximum, and immediately reject them. When *any* other `trace!` log is + /// enabled (even one which doesn't actually exist!) the logger has to run + /// its full filtering machinery on each and every `trace!` log, which can + /// potentially be very expensive. + /// + /// Enabling this cache is useful in such situations to improve performance. + /// + /// You most likely do not want to enabled this if you have registered any dynamic + /// filters on your logger and you want them to be run every time. + /// + /// This is disabled by default. + /// + /// [level]: log::Metadata::level + /// [target]: log::Metadata::target + #[cfg(all(feature = "interest-cache", feature = "std"))] + #[cfg_attr(docsrs, doc(cfg(all(feature = "interest-cache", feature = "std"))))] + pub fn with_interest_cache(mut self, config: crate::InterestCacheConfig) -> Self { + self.interest_cache_config = Some(config); + self + } + + /// Constructs a new `LogTracer` with the provided configuration and sets it + /// as the default logger. + /// + /// Setting a global logger can only be done once. + #[cfg(feature = "std")] + #[cfg_attr(docsrs, doc(cfg(feature = "std")))] + #[allow(unused_mut)] + pub fn init(mut self) -> Result<(), SetLoggerError> { + #[cfg(all(feature = "interest-cache", feature = "std"))] + crate::interest_cache::configure(self.interest_cache_config.take()); + + let ignore_crates = self.ignore_crates.into_boxed_slice(); + let logger = Box::new(LogTracer { ignore_crates }); + log::set_boxed_logger(logger)?; + log::set_max_level(self.filter); + Ok(()) + } +} + +impl Default for Builder { + fn default() -> Self { + Self { + ignore_crates: Vec::new(), + filter: log::LevelFilter::max(), + #[cfg(all(feature = "interest-cache", feature = "std"))] + interest_cache_config: None, + } + } +} diff --git a/vendor/tracing-log/src/trace_logger.rs b/vendor/tracing-log/src/trace_logger.rs new file mode 100644 index 000000000..88a52f752 --- /dev/null +++ b/vendor/tracing-log/src/trace_logger.rs @@ -0,0 +1,458 @@ +//! A `tracing` [`Subscriber`] that uses the [`log`] crate as a backend for +//! formatting `tracing` spans and events. +//! +//! When a [`TraceLogger`] is set as the current subscriber, it will record +//! traces by emitting [`log::Record`]s that can be collected by a logger. +//! +//! **Note**: This API has been deprecated since version 0.1.1. In order to emit +//! `tracing` events as `log` records, the ["log" and "log-always" feature +//! flags][flags] on the `tracing` crate should be used instead. +//! +//! [`log`]: log +//! [`Subscriber`]: https://docs.rs/tracing/0.1.7/tracing/subscriber/trait.Subscriber.html +//! [`log::Record`]:log::Record +//! [flags]: https://docs.rs/tracing/latest/tracing/#crate-feature-flags +#![deprecated( + since = "0.1.1", + note = "use the `tracing` crate's \"log\" feature flag instead" +)] +use crate::AsLog; +use std::{ + cell::RefCell, + collections::HashMap, + fmt::{self, Write}, + sync::{ + atomic::{AtomicUsize, Ordering}, + Mutex, + }, +}; +use tracing_core::{ + field, + span::{self, Id}, + Event, Metadata, Subscriber, +}; + +/// A `tracing` [`Subscriber`] implementation that logs all recorded +/// trace events. +/// +/// **Note**: This API has been deprecated since version 0.1.1. In order to emit +/// `tracing` events as `log` records, the ["log" and "log-always" feature +/// flags][flags] on the `tracing` crate should be used instead. +/// +/// [`Subscriber`]: https://docs.rs/tracing/0.1.7/tracing/subscriber/trait.Subscriber.html +/// [flags]: https://docs.rs/tracing/latest/tracing/#crate-feature-flags +pub struct TraceLogger { + settings: Builder, + spans: Mutex>, + next_id: AtomicUsize, +} + +thread_local! { + static CURRENT: RefCell> = RefCell::new(Vec::new()); +} +/// Configures and constructs a [`TraceLogger`]. +/// +#[derive(Debug)] +pub struct Builder { + log_span_closes: bool, + log_enters: bool, + log_exits: bool, + log_ids: bool, + parent_fields: bool, + log_parent: bool, +} + +// ===== impl TraceLogger ===== + +impl TraceLogger { + /// Returns a new `TraceLogger` with the default configuration. + pub fn new() -> Self { + Self::builder().finish() + } + + /// Returns a `Builder` for configuring a `TraceLogger`. + pub fn builder() -> Builder { + Default::default() + } + + fn from_builder(settings: Builder) -> Self { + Self { + settings, + ..Default::default() + } + } + + fn next_id(&self) -> Id { + Id::from_u64(self.next_id.fetch_add(1, Ordering::SeqCst) as u64) + } +} + +// ===== impl Builder ===== + +impl Builder { + /// Configures whether or not the [`TraceLogger`] being constructed will log + /// when a span closes. + /// + pub fn with_span_closes(self, log_span_closes: bool) -> Self { + Self { + log_span_closes, + ..self + } + } + + /// Configures whether or not the [`TraceLogger`] being constructed will + /// include the fields of parent spans when formatting events. + /// + pub fn with_parent_fields(self, parent_fields: bool) -> Self { + Self { + parent_fields, + ..self + } + } + + /// Configures whether or not the [`TraceLogger`] being constructed will log + /// when a span is entered. + /// + /// If this is set to false, fields from the current span will still be + /// recorded as context, but the actual entry will not create a log record. + /// + pub fn with_span_entry(self, log_enters: bool) -> Self { + Self { log_enters, ..self } + } + + /// Configures whether or not the [`TraceLogger`] being constructed will log + /// when a span is exited. + /// + pub fn with_span_exits(self, log_exits: bool) -> Self { + Self { log_exits, ..self } + } + + /// Configures whether or not the [`TraceLogger`] being constructed will + /// include span IDs when formatting log output. + /// + pub fn with_ids(self, log_ids: bool) -> Self { + Self { log_ids, ..self } + } + + /// Configures whether or not the [`TraceLogger`] being constructed will + /// include the names of parent spans as context when formatting events. + /// + pub fn with_parent_names(self, log_parent: bool) -> Self { + Self { log_parent, ..self } + } + + /// Complete the builder, returning a configured [`TraceLogger`]. + /// + pub fn finish(self) -> TraceLogger { + TraceLogger::from_builder(self) + } +} + +impl Default for Builder { + fn default() -> Self { + Builder { + log_span_closes: false, + parent_fields: true, + log_exits: false, + log_ids: false, + log_parent: true, + log_enters: false, + } + } +} + +impl Default for TraceLogger { + fn default() -> Self { + TraceLogger { + settings: Default::default(), + spans: Default::default(), + next_id: AtomicUsize::new(1), + } + } +} + +#[derive(Debug)] +struct SpanLineBuilder { + parent: Option, + ref_count: usize, + fields: String, + file: Option, + line: Option, + module_path: Option, + target: String, + level: log::Level, + name: &'static str, +} + +impl SpanLineBuilder { + fn new(parent: Option, meta: &Metadata<'_>, fields: String) -> Self { + Self { + parent, + ref_count: 1, + fields, + file: meta.file().map(String::from), + line: meta.line(), + module_path: meta.module_path().map(String::from), + target: String::from(meta.target()), + level: meta.level().as_log(), + name: meta.name(), + } + } + + fn log_meta(&self) -> log::Metadata<'_> { + log::MetadataBuilder::new() + .level(self.level) + .target(self.target.as_ref()) + .build() + } + + fn finish(self) { + let log_meta = self.log_meta(); + let logger = log::logger(); + if logger.enabled(&log_meta) { + logger.log( + &log::Record::builder() + .metadata(log_meta) + .target(self.target.as_ref()) + .module_path(self.module_path.as_ref().map(String::as_ref)) + .file(self.file.as_ref().map(String::as_ref)) + .line(self.line) + .args(format_args!("close {}; {}", self.name, self.fields)) + .build(), + ); + } + } +} + +impl field::Visit for SpanLineBuilder { + fn record_debug(&mut self, field: &field::Field, value: &dyn fmt::Debug) { + write!(self.fields, " {}={:?};", field.name(), value) + .expect("write to string should never fail") + } +} + +impl Subscriber for TraceLogger { + fn enabled(&self, metadata: &Metadata<'_>) -> bool { + log::logger().enabled(&metadata.as_log()) + } + + fn new_span(&self, attrs: &span::Attributes<'_>) -> Id { + let id = self.next_id(); + let mut spans = self.spans.lock().unwrap(); + let mut fields = String::new(); + let parent = self.current_id(); + if self.settings.parent_fields { + let mut next_parent = parent.as_ref(); + while let Some(parent) = next_parent.and_then(|p| spans.get(p)) { + write!(&mut fields, "{}", parent.fields).expect("write to string cannot fail"); + next_parent = parent.parent.as_ref(); + } + } + let mut span = SpanLineBuilder::new(parent, attrs.metadata(), fields); + attrs.record(&mut span); + spans.insert(id.clone(), span); + id + } + + fn record(&self, span: &Id, values: &span::Record<'_>) { + let mut spans = self.spans.lock().unwrap(); + if let Some(span) = spans.get_mut(span) { + values.record(span); + } + } + + fn record_follows_from(&self, span: &Id, follows: &Id) { + // TODO: this should eventually track the relationship? + log::logger().log( + &log::Record::builder() + .level(log::Level::Trace) + .args(format_args!("span {:?} follows_from={:?};", span, follows)) + .build(), + ); + } + + fn enter(&self, id: &Id) { + let _ = CURRENT.try_with(|current| { + let mut current = current.borrow_mut(); + if current.contains(id) { + // Ignore duplicate enters. + return; + } + current.push(id.clone()); + }); + let spans = self.spans.lock().unwrap(); + if self.settings.log_enters { + if let Some(span) = spans.get(id) { + let log_meta = span.log_meta(); + let logger = log::logger(); + if logger.enabled(&log_meta) { + let current_id = self.current_id(); + let current_fields = current_id + .as_ref() + .and_then(|id| spans.get(id)) + .map(|span| span.fields.as_ref()) + .unwrap_or(""); + if self.settings.log_ids { + logger.log( + &log::Record::builder() + .metadata(log_meta) + .target(span.target.as_ref()) + .module_path(span.module_path.as_ref().map(String::as_ref)) + .file(span.file.as_ref().map(String::as_ref)) + .line(span.line) + .args(format_args!( + "enter {}; in={:?}; {}", + span.name, current_id, current_fields + )) + .build(), + ); + } else { + logger.log( + &log::Record::builder() + .metadata(log_meta) + .target(span.target.as_ref()) + .module_path(span.module_path.as_ref().map(String::as_ref)) + .file(span.file.as_ref().map(String::as_ref)) + .line(span.line) + .args(format_args!("enter {}; {}", span.name, current_fields)) + .build(), + ); + } + } + } + } + } + + fn exit(&self, id: &Id) { + let _ = CURRENT.try_with(|current| { + let mut current = current.borrow_mut(); + if current.last() == Some(id) { + current.pop() + } else { + None + } + }); + if self.settings.log_exits { + let spans = self.spans.lock().unwrap(); + if let Some(span) = spans.get(id) { + let log_meta = span.log_meta(); + let logger = log::logger(); + if logger.enabled(&log_meta) { + logger.log( + &log::Record::builder() + .metadata(log_meta) + .target(span.target.as_ref()) + .module_path(span.module_path.as_ref().map(String::as_ref)) + .file(span.file.as_ref().map(String::as_ref)) + .line(span.line) + .args(format_args!("exit {}", span.name)) + .build(), + ); + } + } + } + } + + fn event(&self, event: &Event<'_>) { + let meta = event.metadata(); + let log_meta = meta.as_log(); + let logger = log::logger(); + if logger.enabled(&log_meta) { + let spans = self.spans.lock().unwrap(); + let current = self.current_id().and_then(|id| spans.get(&id)); + let (current_fields, parent) = current + .map(|span| { + let fields = span.fields.as_ref(); + let parent = if self.settings.log_parent { + Some(span.name) + } else { + None + }; + (fields, parent) + }) + .unwrap_or(("", None)); + logger.log( + &log::Record::builder() + .metadata(log_meta) + .target(meta.target()) + .module_path(meta.module_path().as_ref().cloned()) + .file(meta.file().as_ref().cloned()) + .line(meta.line()) + .args(format_args!( + "{}{}{}{}", + parent.unwrap_or(""), + if parent.is_some() { ": " } else { "" }, + LogEvent(event), + current_fields, + )) + .build(), + ); + } + } + + fn clone_span(&self, id: &Id) -> Id { + let mut spans = self.spans.lock().unwrap(); + if let Some(span) = spans.get_mut(id) { + span.ref_count += 1; + } + id.clone() + } + + fn try_close(&self, id: Id) -> bool { + let mut spans = self.spans.lock().unwrap(); + if spans.contains_key(&id) { + if spans.get(&id).unwrap().ref_count == 1 { + let span = spans.remove(&id).unwrap(); + if self.settings.log_span_closes { + span.finish(); + } + return true; + } else { + spans.get_mut(&id).unwrap().ref_count -= 1; + } + } + false + } +} + +impl TraceLogger { + #[inline] + fn current_id(&self) -> Option { + CURRENT + .try_with(|current| current.borrow().last().map(|span| self.clone_span(span))) + .ok()? + } +} + +struct LogEvent<'a>(&'a Event<'a>); + +impl<'a> fmt::Display for LogEvent<'a> { + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { + let mut has_logged = false; + let mut format_fields = |field: &field::Field, value: &dyn fmt::Debug| { + let name = field.name(); + let leading = if has_logged { " " } else { "" }; + // TODO: handle fmt error? + let _ = if name == "message" { + write!(f, "{}{:?};", leading, value) + } else { + write!(f, "{}{}={:?};", leading, name, value) + }; + has_logged = true; + }; + + self.0.record(&mut format_fields); + Ok(()) + } +} + +impl fmt::Debug for TraceLogger { + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { + f.debug_struct("TraceLogger") + .field("settings", &self.settings) + .field("spans", &self.spans) + .field("current", &self.current_id()) + .field("next_id", &self.next_id) + .finish() + } +} -- cgit v1.2.3