diff --git a/examples/examples/appender-multifile.rs b/examples/examples/appender-multifile.rs new file mode 100644 index 0000000000..f96bd8f58e --- /dev/null +++ b/examples/examples/appender-multifile.rs @@ -0,0 +1,32 @@ +//! This example demonstrates the use of multiple files with +//! `tracing-appender`'s `RollingFileAppender` +//! +use tracing_appender::rolling; +use tracing_subscriber::fmt::writer::MakeWriterExt; + +#[path = "fmt/yak_shave.rs"] +mod yak_shave; + +fn main() { + // Log all `tracing` events to files prefixed with `debug`. Since these + // files will be written to very frequently, roll the log file every minute. + let debug_file = rolling::minutely("./logs", "debug"); + // Log warnings and errors to a separate file. Since we expect these events + // to occur less frequently, roll that file on a daily basis instead. + let warn_file = rolling::daily("./logs", "warnings").with_max_level(tracing::Level::WARN); + let all_files = debug_file.and(warn_file); + + tracing_subscriber::fmt() + .with_writer(all_files) + .with_ansi(false) + .with_max_level(tracing::Level::TRACE) + .init(); + + yak_shave::shave_all(6); + tracing::info!("sleeping for a minute..."); + + std::thread::sleep(std::time::Duration::from_secs(60)); + + tracing::info!("okay, time to shave some more yaks!"); + yak_shave::shave_all(10); +} diff --git a/tracing-appender/Cargo.toml b/tracing-appender/Cargo.toml index d502fa96fa..d155e4d6ae 100644 --- a/tracing-appender/Cargo.toml +++ b/tracing-appender/Cargo.toml @@ -23,6 +23,7 @@ rust-version = "1.51.0" [dependencies] crossbeam-channel = "0.5.0" time = { version = "0.3", default-features = false, features = ["formatting"] } +parking_lot = { optional = true, version = "0.11.2" } [dependencies.tracing-subscriber] path = "../tracing-subscriber" diff --git a/tracing-appender/src/inner.rs b/tracing-appender/src/inner.rs deleted file mode 100644 index 9c9a74c45f..0000000000 --- a/tracing-appender/src/inner.rs +++ /dev/null @@ -1,105 +0,0 @@ -use std::io::{BufWriter, Write}; -use std::{fs, io}; - -use crate::rolling::Rotation; -use std::fmt::Debug; -use std::fs::{File, OpenOptions}; -use std::path::Path; -use time::OffsetDateTime; - -#[derive(Debug)] -pub(crate) struct InnerAppender { - log_directory: String, - log_filename_prefix: String, - writer: BufWriter, - next_date: Option, - rotation: Rotation, -} - -impl io::Write for InnerAppender { - fn write(&mut self, buf: &[u8]) -> io::Result { - let now = OffsetDateTime::now_utc(); - self.write_timestamped(buf, now) - } - - fn flush(&mut self) -> io::Result<()> { - self.writer.flush() - } -} - -impl InnerAppender { - pub(crate) fn new( - log_directory: &Path, - log_filename_prefix: &Path, - rotation: Rotation, - now: OffsetDateTime, - ) -> io::Result { - let log_directory = log_directory.to_str().unwrap(); - let log_filename_prefix = log_filename_prefix.to_str().unwrap(); - - let filename = rotation.join_date(log_filename_prefix, &now); - let next_date = rotation.next_date(&now); - - Ok(InnerAppender { - log_directory: log_directory.to_string(), - log_filename_prefix: log_filename_prefix.to_string(), - writer: create_writer(log_directory, &filename)?, - next_date, - rotation, - }) - } - - fn write_timestamped(&mut self, buf: &[u8], date: OffsetDateTime) -> io::Result { - // Even if refresh_writer fails, we still have the original writer. Ignore errors - // and proceed with the write. - let buf_len = buf.len(); - self.refresh_writer(date); - self.writer.write_all(buf).map(|_| buf_len) - } - - fn refresh_writer(&mut self, now: OffsetDateTime) { - if self.should_rollover(now) { - let filename = self.rotation.join_date(&self.log_filename_prefix, &now); - - self.next_date = self.rotation.next_date(&now); - - match create_writer(&self.log_directory, &filename) { - Ok(writer) => { - if let Err(err) = self.writer.flush() { - eprintln!("Couldn't flush previous writer: {}", err); - } - self.writer = writer - } - Err(err) => eprintln!("Couldn't create writer for logs: {}", err), - } - } - } - - fn should_rollover(&self, date: OffsetDateTime) -> bool { - // the `None` case means that the `InnerAppender` *never* rorates log files. - match self.next_date { - None => false, - Some(next_date) => date >= next_date, - } - } -} - -fn create_writer(directory: &str, filename: &str) -> io::Result> { - let file_path = Path::new(directory).join(filename); - Ok(BufWriter::new(open_file_create_parent_dirs(&file_path)?)) -} - -fn open_file_create_parent_dirs(path: &Path) -> io::Result { - let mut open_options = OpenOptions::new(); - open_options.append(true).create(true); - - let new_file = open_options.open(path); - if new_file.is_err() { - if let Some(parent) = path.parent() { - fs::create_dir_all(parent)?; - return open_options.open(path); - } - } - - new_file -} diff --git a/tracing-appender/src/lib.rs b/tracing-appender/src/lib.rs index db7c1157af..ce5e21f935 100644 --- a/tracing-appender/src/lib.rs +++ b/tracing-appender/src/lib.rs @@ -154,14 +154,14 @@ use crate::non_blocking::{NonBlocking, WorkerGuard}; use std::io::Write; -mod inner; - pub mod non_blocking; pub mod rolling; mod worker; +pub(crate) mod sync; + /// Convenience function for creating a non-blocking, off-thread writer. /// /// See the [`non_blocking` module's docs][non_blocking]'s for more details. diff --git a/tracing-appender/src/rolling.rs b/tracing-appender/src/rolling.rs index 1a9bdac85b..2393cabce1 100644 --- a/tracing-appender/src/rolling.rs +++ b/tracing-appender/src/rolling.rs @@ -30,32 +30,85 @@ //! let file_appender = RollingFileAppender::new(Rotation::HOURLY, "/some/directory", "prefix.log"); //! # } //! ``` -use crate::inner::InnerAppender; -use std::io; -use std::path::Path; +use crate::sync::{RwLock, RwLockReadGuard}; +use std::{ + fmt::Debug, + fs::{self, File, OpenOptions}, + io::{self, Write}, + path::Path, + sync::atomic::{AtomicUsize, Ordering}, +}; use time::{format_description, Duration, OffsetDateTime, Time}; /// A file appender with the ability to rotate log files at a fixed schedule. /// -/// `RollingFileAppender` implements [`std:io::Write` trait][write] and will block on write operations. -/// It may be used with [`NonBlocking`][non-blocking] to perform writes without -/// blocking the current thread. +/// `RollingFileAppender` implements the [`std:io::Write` trait][write] and will +/// block on write operations. It may be used with [`NonBlocking`] to perform +/// writes without blocking the current thread. /// -/// [write]: https://doc.rust-lang.org/nightly/std/io/trait.Write.html -/// [non-blocking]: ../non_blocking/struct.NonBlocking.html +/// Additionally, `RollingFileAppender` also implements the [`MakeWriter` +/// trait][make_writer] from `tracing-appender`, so it may also be used +/// directly, without [`NonBlocking`]. +/// +/// [write]: std::io::Write +/// [`NonBlocking`]: super::non_blocking::NonBlocking /// /// # Examples /// +/// Rolling a log file once every hour: +/// /// ```rust /// # fn docs() { -/// let file_appender = tracing_appender::rolling::hourly("/some/directory", "prefix.log"); +/// let file_appender = tracing_appender::rolling::hourly("/some/directory", "prefix"); /// # } /// ``` +/// +/// Combining a `RollingFileAppender` with another [`MakeWriter`] implementation: +/// +/// ```rust +/// # fn docs() { +/// use tracing_subscriber::fmt::writer::MakeWriterExt; +/// +/// // Log all events to a rolling log file. +/// let logfile = tracing_appender::rolling::hourly("/logs", "myapp-logs"); + +/// // Log `INFO` and above to stdout. +/// let stdout = std::io::stdout.with_max_level(tracing::Level::INFO); +/// +/// tracing_subscriber::fmt() +/// // Combine the stdout and log file `MakeWriter`s into one +/// // `MakeWriter` that writes to both +/// .with_writer(stdout.and(logfile)) +/// .init(); +/// # } +/// ``` +/// +/// [make_writer] tracing_subscriber::fmt::writer::MakeWriter #[derive(Debug)] pub struct RollingFileAppender { - inner: InnerAppender, + state: Inner, + writer: RwLock, +} + +/// A [writer] that writes to a rolling log file. +/// +/// This is returned by the [`MakeWriter`] implementation for [`RollingFileAppender`]. +/// +/// [writer]: std::io::Write +/// [`MakeWriter`]: tracing_subscriber::fmt::writer::MakeWriter +#[derive(Debug)] +pub struct RollingWriter<'a>(RwLockReadGuard<'a, File>); + +#[derive(Debug)] +struct Inner { + log_directory: String, + log_filename_prefix: String, + rotation: Rotation, + next_date: AtomicUsize, } +// === impl RollingFileAppender === + impl RollingFileAppender { /// Creates a new `RollingFileAppender`. /// @@ -89,25 +142,62 @@ impl RollingFileAppender { directory: impl AsRef, file_name_prefix: impl AsRef, ) -> RollingFileAppender { - RollingFileAppender { - inner: InnerAppender::new( - directory.as_ref(), - file_name_prefix.as_ref(), + let now = OffsetDateTime::now_utc(); + let log_directory = directory.as_ref().to_str().unwrap(); + let log_filename_prefix = file_name_prefix.as_ref().to_str().unwrap(); + + let filename = rotation.join_date(log_filename_prefix, &now); + let next_date = rotation.next_date(&now); + let writer = RwLock::new( + create_writer(log_directory, &filename).expect("failed to create appender"), + ); + Self { + state: Inner { + log_directory: log_directory.to_string(), + log_filename_prefix: log_filename_prefix.to_string(), + next_date: AtomicUsize::new( + next_date + .map(|date| date.unix_timestamp() as usize) + .unwrap_or(0), + ), rotation, - OffsetDateTime::now_utc(), - ) - .expect("Failed to create appender"), + }, + writer, } } } impl io::Write for RollingFileAppender { fn write(&mut self, buf: &[u8]) -> io::Result { - self.inner.write(buf) + let now = OffsetDateTime::now_utc(); + let writer = self.writer.get_mut(); + if self.state.should_rollover(now) { + let _did_cas = self.state.advance_date(now); + debug_assert!(_did_cas, "if we have &mut access to the appender, no other thread can have advanced the timestamp..."); + self.state.refresh_writer(now, writer); + } + writer.write(buf) } fn flush(&mut self) -> io::Result<()> { - self.inner.flush() + self.writer.get_mut().flush() + } +} + +impl<'a> tracing_subscriber::fmt::writer::MakeWriter<'a> for RollingFileAppender { + type Writer = RollingWriter<'a>; + fn make_writer(&'a self) -> Self::Writer { + let now = OffsetDateTime::now_utc(); + + // Should we try to roll over the log file? + if self.state.should_rollover(now) { + // Did we get the right to lock the file? If not, another thread + // did it and we can just make a writer. + if self.state.advance_date(now) { + self.state.refresh_writer(now, &mut *self.writer.write()); + } + } + RollingWriter(self.writer.read()) } } @@ -372,6 +462,79 @@ impl Rotation { } } +// === impl RollingWriter === + +impl io::Write for RollingWriter<'_> { + fn write(&mut self, buf: &[u8]) -> io::Result { + (&*self.0).write(buf) + } + + fn flush(&mut self) -> io::Result<()> { + (&*self.0).flush() + } +} + +// === impl Inner === + +impl Inner { + fn refresh_writer(&self, now: OffsetDateTime, file: &mut File) { + debug_assert!(self.should_rollover(now)); + + let filename = self.rotation.join_date(&self.log_filename_prefix, &now); + + match create_writer(&self.log_directory, &filename) { + Ok(new_file) => { + if let Err(err) = file.flush() { + eprintln!("Couldn't flush previous writer: {}", err); + } + *file = new_file; + } + Err(err) => eprintln!("Couldn't create writer for logs: {}", err), + } + } + + fn should_rollover(&self, date: OffsetDateTime) -> bool { + // the `None` case means that the `InnerAppender` *never* rotates log files. + let next_date = self.next_date.load(Ordering::Acquire); + if next_date == 0 { + return false; + } + date.unix_timestamp() as usize >= next_date + } + + fn advance_date(&self, now: OffsetDateTime) -> bool { + let next_date = self + .rotation + .next_date(&now) + .map(|date| date.unix_timestamp() as usize) + .unwrap_or(0); + self.next_date + .compare_exchange( + now.unix_timestamp() as usize, + next_date, + Ordering::AcqRel, + Ordering::Acquire, + ) + .is_ok() + } +} + +fn create_writer(directory: &str, filename: &str) -> io::Result { + let path = Path::new(directory).join(filename); + let mut open_options = OpenOptions::new(); + open_options.append(true).create(true); + + let new_file = open_options.open(path.as_path()); + if new_file.is_err() { + if let Some(parent) = path.parent() { + fs::create_dir_all(parent)?; + return open_options.open(path); + } + } + + new_file +} + #[cfg(test)] mod test { use super::*; diff --git a/tracing-appender/src/sync.rs b/tracing-appender/src/sync.rs new file mode 100644 index 0000000000..2ee77e5cb2 --- /dev/null +++ b/tracing-appender/src/sync.rs @@ -0,0 +1,69 @@ +//! Abstracts over sync primitive implementations. +//! +//! Optionally, we allow the Rust standard library's `RwLock` to be replaced +//! with the `parking_lot` crate's implementation. This may provide improved +//! performance in some cases. However, the `parking_lot` dependency is an +//! opt-in feature flag. Because `parking_lot::RwLock` has a slightly different +//! API than `std::sync::RwLock` (it does not support poisoning on panics), we +//! wrap the `std::sync` version to ignore poisoning. + +#[allow(unused_imports)] // may be used later; +#[cfg(feature = "parking_lot")] +pub(crate) use parking_lot::{RwLock, RwLockReadGuard, RwLockWriteGuard}; + +#[cfg(not(feature = "parking_lot"))] +pub(crate) use self::std_impl::*; + +#[cfg(not(feature = "parking_lot"))] +mod std_impl { + use std::sync::{self, PoisonError, TryLockError}; + pub(crate) use std::sync::{RwLockReadGuard, RwLockWriteGuard}; + + #[derive(Debug)] + pub(crate) struct RwLock { + inner: sync::RwLock, + } + + impl RwLock { + pub(crate) fn new(val: T) -> Self { + Self { + inner: sync::RwLock::new(val), + } + } + + #[inline] + pub(crate) fn get_mut(&mut self) -> &mut T { + self.inner.get_mut().unwrap_or_else(PoisonError::into_inner) + } + + #[inline] + pub(crate) fn read(&self) -> RwLockReadGuard<'_, T> { + self.inner.read().unwrap_or_else(PoisonError::into_inner) + } + + #[inline] + #[allow(dead_code)] // may be used later; + pub(crate) fn try_read(&self) -> Option> { + match self.inner.try_read() { + Ok(guard) => Some(guard), + Err(TryLockError::Poisoned(e)) => Some(e.into_inner()), + Err(TryLockError::WouldBlock) => None, + } + } + + #[inline] + pub(crate) fn write(&self) -> RwLockWriteGuard<'_, T> { + self.inner.write().unwrap_or_else(PoisonError::into_inner) + } + + #[inline] + #[allow(dead_code)] // may be used later; + pub(crate) fn try_write(&self) -> Option> { + match self.inner.try_write() { + Ok(guard) => Some(guard), + Err(TryLockError::Poisoned(e)) => Some(e.into_inner()), + Err(TryLockError::WouldBlock) => None, + } + } + } +} diff --git a/tracing-attributes/src/attr.rs b/tracing-attributes/src/attr.rs index 617f4bd772..2e2ef1502d 100644 --- a/tracing-attributes/src/attr.rs +++ b/tracing-attributes/src/attr.rs @@ -14,7 +14,8 @@ pub(crate) struct InstrumentArgs { pub(crate) skips: HashSet, pub(crate) skip_all: bool, pub(crate) fields: Option, - pub(crate) err_mode: Option, + pub(crate) err_mode: Option, + pub(crate) ret_mode: Option, /// Errors describing any unrecognized parse inputs that we skipped. parse_warnings: Vec, } @@ -152,8 +153,12 @@ impl Parse for InstrumentArgs { args.fields = Some(input.parse()?); } else if lookahead.peek(kw::err) { let _ = input.parse::(); - let mode = ErrorMode::parse(input)?; + let mode = FormatMode::parse(input)?; args.err_mode = Some(mode); + } else if lookahead.peek(kw::ret) { + let _ = input.parse::()?; + let mode = FormatMode::parse(input)?; + args.ret_mode = Some(mode); } else if lookahead.peek(Token![,]) { let _ = input.parse::()?; } else { @@ -212,29 +217,30 @@ impl Parse for Skips { } #[derive(Clone, Debug, Hash, PartialEq, Eq)] -pub(crate) enum ErrorMode { +pub(crate) enum FormatMode { + Default, Display, Debug, } -impl Default for ErrorMode { +impl Default for FormatMode { fn default() -> Self { - ErrorMode::Display + FormatMode::Default } } -impl Parse for ErrorMode { +impl Parse for FormatMode { fn parse(input: ParseStream<'_>) -> syn::Result { if !input.peek(syn::token::Paren) { - return Ok(ErrorMode::default()); + return Ok(FormatMode::default()); } let content; let _ = syn::parenthesized!(content in input); let maybe_mode: Option = content.parse()?; - maybe_mode.map_or(Ok(ErrorMode::default()), |ident| { + maybe_mode.map_or(Ok(FormatMode::default()), |ident| { match ident.to_string().as_str() { - "Debug" => Ok(ErrorMode::Debug), - "Display" => Ok(ErrorMode::Display), + "Debug" => Ok(FormatMode::Debug), + "Display" => Ok(FormatMode::Display), _ => Err(syn::Error::new( ident.span(), "unknown error mode, must be Debug or Display", @@ -370,4 +376,5 @@ mod kw { syn::custom_keyword!(target); syn::custom_keyword!(name); syn::custom_keyword!(err); + syn::custom_keyword!(ret); } diff --git a/tracing-attributes/src/expand.rs b/tracing-attributes/src/expand.rs index 9f5ccd14de..e9b4f898c6 100644 --- a/tracing-attributes/src/expand.rs +++ b/tracing-attributes/src/expand.rs @@ -9,7 +9,7 @@ use syn::{ }; use crate::{ - attr::{ErrorMode, Field, Fields, InstrumentArgs}, + attr::{Field, Fields, FormatMode, InstrumentArgs}, MaybeItemFnRef, }; @@ -191,8 +191,18 @@ fn gen_block( })(); let err_event = match args.err_mode { - Some(ErrorMode::Display) => Some(quote!(tracing::error!(error = %e))), - Some(ErrorMode::Debug) => Some(quote!(tracing::error!(error = ?e))), + Some(FormatMode::Default) | Some(FormatMode::Display) => { + Some(quote!(tracing::error!(error = %e))) + } + Some(FormatMode::Debug) => Some(quote!(tracing::error!(error = ?e))), + _ => None, + }; + + let ret_event = match args.ret_mode { + Some(FormatMode::Display) => Some(quote!(tracing::event!(#level, return = %x))), + Some(FormatMode::Default) | Some(FormatMode::Debug) => { + Some(quote!(tracing::event!(#level, return = ?x))) + } _ => None, }; @@ -201,9 +211,26 @@ fn gen_block( // which is `instrument`ed using `tracing-futures`. Otherwise, this will // enter the span and then perform the rest of the body. // If `err` is in args, instrument any resulting `Err`s. + // If `ret` is in args, instrument any resulting `Ok`s when the function + // returns `Result`s, otherwise instrument any resulting values. if async_context { - let mk_fut = match err_event { - Some(err_event) => quote_spanned!(block.span()=> + let mk_fut = match (err_event, ret_event) { + (Some(err_event), Some(ret_event)) => quote_spanned!(block.span()=> + async move { + match async move { #block }.await { + #[allow(clippy::unit_arg)] + Ok(x) => { + #ret_event; + Ok(x) + }, + Err(e) => { + #err_event; + Err(e) + } + } + } + ), + (Some(err_event), None) => quote_spanned!(block.span()=> async move { match async move { #block }.await { #[allow(clippy::unit_arg)] @@ -215,7 +242,14 @@ fn gen_block( } } ), - None => quote_spanned!(block.span()=> + (None, Some(ret_event)) => quote_spanned!(block.span()=> + async move { + let x = async move { #block }.await; + #ret_event; + x + } + ), + (None, None) => quote_spanned!(block.span()=> async move { #block } ), }; @@ -254,8 +288,23 @@ fn gen_block( } ); - if let Some(err_event) = err_event { - return quote_spanned!(block.span()=> + match (err_event, ret_event) { + (Some(err_event), Some(ret_event)) => quote_spanned! {block.span()=> + #span + #[allow(clippy::redundant_closure_call)] + match (move || #block)() { + #[allow(clippy::unit_arg)] + Ok(x) => { + #ret_event; + Ok(x) + }, + Err(e) => { + #err_event; + Err(e) + } + } + }, + (Some(err_event), None) => quote_spanned!(block.span()=> #span #[allow(clippy::redundant_closure_call)] match (move || #block)() { @@ -266,22 +315,28 @@ fn gen_block( Err(e) } } - ); - } - - quote_spanned!(block.span() => - // Because `quote` produces a stream of tokens _without_ whitespace, the - // `if` and the block will appear directly next to each other. This - // generates a clippy lint about suspicious `if/else` formatting. - // Therefore, suppress the lint inside the generated code... - #[allow(clippy::suspicious_else_formatting)] - { + ), + (None, Some(ret_event)) => quote_spanned!(block.span()=> #span - // ...but turn the lint back on inside the function body. - #[warn(clippy::suspicious_else_formatting)] - #block - } - ) + #[allow(clippy::redundant_closure_call)] + let x = (move || #block)(); + #ret_event; + x + ), + (None, None) => quote_spanned!(block.span() => + // Because `quote` produces a stream of tokens _without_ whitespace, the + // `if` and the block will appear directly next to each other. This + // generates a clippy lint about suspicious `if/else` formatting. + // Therefore, suppress the lint inside the generated code... + #[allow(clippy::suspicious_else_formatting)] + { + #span + // ...but turn the lint back on inside the function body. + #[warn(clippy::suspicious_else_formatting)] + #block + } + ), + } } /// Indicates whether a field should be recorded as `Value` or `Debug`. diff --git a/tracing-attributes/src/lib.rs b/tracing-attributes/src/lib.rs index b07461c22e..a321962ca6 100644 --- a/tracing-attributes/src/lib.rs +++ b/tracing-attributes/src/lib.rs @@ -368,6 +368,35 @@ mod expand; /// } /// ``` /// +/// Adding the `ret` argument to `#[instrument]` will emit an event with the function's +/// return value when the function returns: +/// +/// ``` +/// # use tracing_attributes::instrument; +/// #[instrument(ret)] +/// fn my_function() -> i32 { +/// 42 +/// } +/// ``` +/// The return value event will have the same level as the span generated by `#[instrument]`. +/// By default, this will be `TRACE`, but if the level is overridden, the event will be at the same +/// level. +/// +/// **Note**: if the function returns a `Result`, `ret` will record returned values if and +/// only if the function returns [`Result::Ok`]. +/// +/// By default, returned values will be recorded using their [`std::fmt::Debug`] implementations. +/// If a returned value implements [`std::fmt::Display`], it can be recorded using its `Display` +/// implementation instead, by writing `ret(Display)`: +/// +/// ``` +/// # use tracing_attributes::instrument; +/// #[instrument(ret(Display))] +/// fn my_function() -> i32 { +/// 42 +/// } +/// ``` +/// /// If the function returns a `Result` and `E` implements `std::fmt::Display`, you can add /// `err` or `err(Display)` to emit error events when the function returns `Err`: /// @@ -391,6 +420,17 @@ mod expand; /// } /// ``` /// +/// The `ret` and `err` arguments can be combined in order to record an event if a +/// function returns [`Result::Ok`] or [`Result::Err`]: +/// +/// ``` +/// # use tracing_attributes::instrument; +/// #[instrument(err, ret)] +/// fn my_function(arg: usize) -> Result<(), std::io::Error> { +/// Ok(()) +/// } +/// ``` +/// /// `async fn`s may also be instrumented: /// /// ``` diff --git a/tracing-attributes/tests/ret.rs b/tracing-attributes/tests/ret.rs new file mode 100644 index 0000000000..af23182a61 --- /dev/null +++ b/tracing-attributes/tests/ret.rs @@ -0,0 +1,226 @@ +#[path = "../../tracing-futures/tests/support.rs"] +// we don't use some of the test support functions, but `tracing-futures` does. +#[allow(dead_code)] +mod support; +use support::*; + +use std::convert::TryFrom; +use std::num::TryFromIntError; + +use tracing::{subscriber::with_default, Level}; +use tracing_attributes::instrument; + +#[instrument(ret)] +fn ret() -> i32 { + 42 +} + +#[test] +fn test() { + let span = span::mock().named("ret"); + let (subscriber, handle) = subscriber::mock() + .new_span(span.clone()) + .enter(span.clone()) + .event( + event::mock() + .with_fields(field::mock("return").with_value(&tracing::field::debug(42))) + .at_level(Level::INFO), + ) + .exit(span.clone()) + .drop_span(span) + .done() + .run_with_handle(); + + with_default(subscriber, ret); + handle.assert_finished(); +} + +#[instrument(level = "warn", ret)] +fn ret_warn() -> i32 { + 42 +} + +#[test] +fn test_warn() { + let span = span::mock().named("ret_warn"); + let (subscriber, handle) = subscriber::mock() + .new_span(span.clone()) + .enter(span.clone()) + .event( + event::mock() + .with_fields(field::mock("return").with_value(&tracing::field::debug(42))) + .at_level(Level::WARN), + ) + .exit(span.clone()) + .drop_span(span) + .done() + .run_with_handle(); + + with_default(subscriber, ret_warn); + handle.assert_finished(); +} + +#[instrument(ret)] +fn ret_mut(a: &mut i32) -> i32 { + *a *= 2; + tracing::info!(?a); + *a +} + +#[test] +fn test_mut() { + let span = span::mock().named("ret_mut"); + let (subscriber, handle) = subscriber::mock() + .new_span(span.clone()) + .enter(span.clone()) + .event( + event::mock() + .with_fields(field::mock("a").with_value(&tracing::field::display(2))) + .at_level(Level::INFO), + ) + .event( + event::mock() + .with_fields(field::mock("return").with_value(&tracing::field::debug(2))) + .at_level(Level::INFO), + ) + .exit(span.clone()) + .drop_span(span) + .done() + .run_with_handle(); + + with_default(subscriber, || ret_mut(&mut 1)); + handle.assert_finished(); +} + +#[instrument(ret)] +async fn ret_async() -> i32 { + 42 +} + +#[test] +fn test_async() { + let span = span::mock().named("ret_async"); + let (subscriber, handle) = subscriber::mock() + .new_span(span.clone()) + .enter(span.clone()) + .event( + event::mock() + .with_fields(field::mock("return").with_value(&tracing::field::debug(42))) + .at_level(Level::INFO), + ) + .exit(span.clone()) + .drop_span(span) + .done() + .run_with_handle(); + + with_default(subscriber, || block_on_future(async { ret_async().await })); + handle.assert_finished(); +} + +#[instrument(ret)] +fn ret_impl_type() -> impl Copy { + 42 +} + +#[test] +fn test_impl_type() { + let span = span::mock().named("ret_impl_type"); + let (subscriber, handle) = subscriber::mock() + .new_span(span.clone()) + .enter(span.clone()) + .event( + event::mock() + .with_fields(field::mock("return").with_value(&tracing::field::debug(42))) + .at_level(Level::INFO), + ) + .exit(span.clone()) + .drop_span(span) + .done() + .run_with_handle(); + + with_default(subscriber, ret_impl_type); + handle.assert_finished(); +} + +#[instrument(ret(Display))] +fn ret_display() -> i32 { + 42 +} + +#[test] +fn test_dbg() { + let span = span::mock().named("ret_display"); + let (subscriber, handle) = subscriber::mock() + .new_span(span.clone()) + .enter(span.clone()) + .event( + event::mock() + .with_fields(field::mock("return").with_value(&tracing::field::display(42))) + .at_level(Level::INFO), + ) + .exit(span.clone()) + .drop_span(span) + .done() + .run_with_handle(); + + with_default(subscriber, ret_display); + handle.assert_finished(); +} + +#[instrument(err, ret)] +fn ret_and_err() -> Result { + u8::try_from(1234) +} + +#[test] +fn test_ret_and_err() { + let span = span::mock().named("ret_and_err"); + let (subscriber, handle) = subscriber::mock() + .new_span(span.clone()) + .enter(span.clone()) + .event( + event::mock() + .with_fields( + field::mock("error") + .with_value(&tracing::field::display(u8::try_from(1234).unwrap_err())) + .only(), + ) + .at_level(Level::ERROR), + ) + .exit(span.clone()) + .drop_span(span) + .done() + .run_with_handle(); + + with_default(subscriber, || ret_and_err().ok()); + handle.assert_finished(); +} + +#[instrument(err, ret)] +fn ret_and_ok() -> Result { + u8::try_from(123) +} + +#[test] +fn test_ret_and_ok() { + let span = span::mock().named("ret_and_ok"); + let (subscriber, handle) = subscriber::mock() + .new_span(span.clone()) + .enter(span.clone()) + .event( + event::mock() + .with_fields( + field::mock("return") + .with_value(&tracing::field::debug(u8::try_from(123).unwrap())) + .only(), + ) + .at_level(Level::INFO), + ) + .exit(span.clone()) + .drop_span(span) + .done() + .run_with_handle(); + + with_default(subscriber, || ret_and_ok().ok()); + handle.assert_finished(); +} diff --git a/tracing-core/src/callsite.rs b/tracing-core/src/callsite.rs index e840c58595..d0acae41de 100644 --- a/tracing-core/src/callsite.rs +++ b/tracing-core/src/callsite.rs @@ -12,7 +12,7 @@ use crate::{ subscriber::Interest, }; -lazy_static! { +crate::lazy_static! { static ref REGISTRY: Mutex = Mutex::new(Registry { callsites: Vec::new(), dispatchers: Vec::new(), diff --git a/tracing-core/src/lib.rs b/tracing-core/src/lib.rs index 9bf8f363ae..5c5a31d3d1 100644 --- a/tracing-core/src/lib.rs +++ b/tracing-core/src/lib.rs @@ -124,9 +124,7 @@ extern crate alloc; /// /// For example: /// ```rust -/// # #[macro_use] -/// # extern crate tracing_core; -/// use tracing_core::callsite; +/// use tracing_core::{callsite, identify_callsite}; /// # use tracing_core::{Metadata, subscriber::Interest}; /// # fn main() { /// pub struct MyCallsite { @@ -160,9 +158,8 @@ macro_rules! identify_callsite { /// /// /// For example: /// ```rust -/// # #[macro_use] -/// # extern crate tracing_core; /// # use tracing_core::{callsite::Callsite, subscriber::Interest}; +/// use tracing_core::metadata; /// use tracing_core::metadata::{Kind, Level, Metadata}; /// # fn main() { /// # pub struct MyCallsite { } @@ -228,14 +225,11 @@ macro_rules! metadata { }; } -// std uses lazy_static from crates.io +// when `std` is enabled, use the `lazy_static` crate from crates.io #[cfg(feature = "std")] -#[macro_use] -extern crate lazy_static; +pub(crate) use lazy_static::lazy_static; -// no_std uses vendored version of lazy_static 1.4.0 (4216696) with spin -// This can conflict when included in a project already using std lazy_static -// Remove this module when cargo enables specifying dependencies for no_std +// Facade module: `no_std` uses spinlocks, `std` uses the mutexes in the standard library #[cfg(not(feature = "std"))] #[macro_use] mod lazy_static; diff --git a/tracing-core/src/subscriber.rs b/tracing-core/src/subscriber.rs index 212e876062..11695e5382 100644 --- a/tracing-core/src/subscriber.rs +++ b/tracing-core/src/subscriber.rs @@ -246,8 +246,7 @@ pub trait Subscriber: 'static { /// but values for them won't be recorded at this time. /// /// ```rust,ignore - /// #[macro_use] - /// extern crate tracing; + /// # use tracing::span; /// /// let mut span = span!("my_span", foo = 3, bar, baz); /// diff --git a/tracing-journald/Cargo.toml b/tracing-journald/Cargo.toml index e7a663eac0..ef895bd8c5 100644 --- a/tracing-journald/Cargo.toml +++ b/tracing-journald/Cargo.toml @@ -16,5 +16,11 @@ keywords = ["tracing", "journald"] rust-version = "1.42.0" [dependencies] +libc = "0.2.107" tracing-core = { path = "../tracing-core", version = "0.1.10" } tracing-subscriber = { path = "../tracing-subscriber", version = "0.3" } + +[dev-dependencies] +serde_json = "1.0.68" +serde = { version = "1.0.130", features = ["derive"] } +tracing = { path = "../tracing", version = "0.1" } \ No newline at end of file diff --git a/tracing-journald/src/lib.rs b/tracing-journald/src/lib.rs index 356cbd3af8..2e00b1ea7e 100644 --- a/tracing-journald/src/lib.rs +++ b/tracing-journald/src/lib.rs @@ -49,6 +49,11 @@ use tracing_core::{ }; use tracing_subscriber::{layer::Context, registry::LookupSpan}; +#[cfg(target_os = "linux")] +mod memfd; +#[cfg(target_os = "linux")] +mod socket; + /// Sends events and their fields to journald /// /// [journald conventions] for structured field names differ from typical tracing idioms, and journald @@ -81,6 +86,9 @@ pub struct Layer { field_prefix: Option, } +#[cfg(unix)] +const JOURNALD_PATH: &str = "/run/systemd/journal/socket"; + impl Layer { /// Construct a journald layer /// @@ -90,11 +98,14 @@ impl Layer { #[cfg(unix)] { let socket = UnixDatagram::unbound()?; - socket.connect("/run/systemd/journal/socket")?; - Ok(Self { + let layer = Self { socket, field_prefix: Some("F".into()), - }) + }; + // Check that we can talk to journald, by sending empty payload which journald discards. + // However if the socket didn't exist or if none listened we'd get an error here. + layer.send_payload(&[])?; + Ok(layer) } #[cfg(not(unix))] Err(io::Error::new( @@ -109,6 +120,50 @@ impl Layer { self.field_prefix = x; self } + + #[cfg(not(unix))] + fn send_payload(&self, _opayload: &[u8]) -> io::Result<()> { + Err(io::Error::new( + io::ErrorKind::Unsupported, + "journald not supported on non-Unix", + )) + } + + #[cfg(unix)] + fn send_payload(&self, payload: &[u8]) -> io::Result { + self.socket + .send_to(payload, JOURNALD_PATH) + .or_else(|error| { + if Some(libc::EMSGSIZE) == error.raw_os_error() { + self.send_large_payload(payload) + } else { + Err(error) + } + }) + } + + #[cfg(all(unix, not(target_os = "linux")))] + fn send_large_payload(&self, _payload: &[u8]) -> io::Result { + Err(io::Error::new( + io::ErrorKind::Unsupported, + "Large payloads not supported on non-Linux OS", + )) + } + + /// Send large payloads to journald via a memfd. + #[cfg(target_os = "linux")] + fn send_large_payload(&self, payload: &[u8]) -> io::Result { + // If the payload's too large for a single datagram, send it through a memfd, see + // https://systemd.io/JOURNAL_NATIVE_PROTOCOL/ + use std::os::unix::prelude::AsRawFd; + // Write the whole payload to a memfd + let mut mem = memfd::create_sealable()?; + mem.write_all(payload)?; + // Fully seal the memfd to signal journald that its backing data won't resize anymore + // and so is safe to mmap. + memfd::seal_fully(mem.as_raw_fd())?; + socket::send_one_fd_to(&self.socket, mem.as_raw_fd(), JOURNALD_PATH) + } } /// Construct a journald layer @@ -174,9 +229,8 @@ where self.field_prefix.as_ref().map(|x| &x[..]), )); - // What could we possibly do on error? - #[cfg(unix)] - let _ = self.socket.send(&buf); + // At this point we can't handle the error anymore so just ignore it. + let _ = self.send_payload(&buf); } } @@ -188,14 +242,29 @@ struct SpanVisitor<'a> { prefix: Option<&'a str>, } -impl Visit for SpanVisitor<'_> { - fn record_debug(&mut self, field: &Field, value: &dyn fmt::Debug) { +impl SpanVisitor<'_> { + fn put_span_prefix(&mut self) { write!(self.buf, "S{}", self.depth).unwrap(); if let Some(prefix) = self.prefix { self.buf.extend_from_slice(prefix.as_bytes()); } self.buf.push(b'_'); - put_debug(self.buf, field.name(), value); + } +} + +impl Visit for SpanVisitor<'_> { + fn record_str(&mut self, field: &Field, value: &str) { + self.put_span_prefix(); + put_field_length_encoded(self.buf, field.name(), |buf| { + buf.extend_from_slice(value.as_bytes()) + }); + } + + fn record_debug(&mut self, field: &Field, value: &dyn fmt::Debug) { + self.put_span_prefix(); + put_field_length_encoded(self.buf, field.name(), |buf| { + write!(buf, "{:?}", value).unwrap() + }); } } @@ -210,23 +279,37 @@ impl<'a> EventVisitor<'a> { fn new(buf: &'a mut Vec, prefix: Option<&'a str>) -> Self { Self { buf, prefix } } -} -impl Visit for EventVisitor<'_> { - fn record_debug(&mut self, field: &Field, value: &dyn fmt::Debug) { + fn put_prefix(&mut self, field: &Field) { if let Some(prefix) = self.prefix { if field.name() != "message" { + // message maps to the standard MESSAGE field so don't prefix it self.buf.extend_from_slice(prefix.as_bytes()); self.buf.push(b'_'); } } - put_debug(self.buf, field.name(), value); + } +} + +impl Visit for EventVisitor<'_> { + fn record_str(&mut self, field: &Field, value: &str) { + self.put_prefix(field); + put_field_length_encoded(self.buf, field.name(), |buf| { + buf.extend_from_slice(value.as_bytes()) + }); + } + + fn record_debug(&mut self, field: &Field, value: &dyn fmt::Debug) { + self.put_prefix(field); + put_field_length_encoded(self.buf, field.name(), |buf| { + write!(buf, "{:?}", value).unwrap() + }); } } fn put_metadata(buf: &mut Vec, meta: &Metadata, span: Option) { if span.is_none() { - put_field( + put_field_wellformed( buf, "PRIORITY", match *meta.level() { @@ -241,12 +324,12 @@ fn put_metadata(buf: &mut Vec, meta: &Metadata, span: Option) { if let Some(n) = span { write!(buf, "S{}_", n).unwrap(); } - put_field(buf, "TARGET", meta.target().as_bytes()); + put_field_wellformed(buf, "TARGET", meta.target().as_bytes()); if let Some(file) = meta.file() { if let Some(n) = span { write!(buf, "S{}_", n).unwrap(); } - put_field(buf, "CODE_FILE", file.as_bytes()); + put_field_wellformed(buf, "CODE_FILE", file.as_bytes()); } if let Some(line) = meta.line() { if let Some(n) = span { @@ -257,12 +340,21 @@ fn put_metadata(buf: &mut Vec, meta: &Metadata, span: Option) { } } -fn put_debug(buf: &mut Vec, name: &str, value: &dyn fmt::Debug) { +/// Append a sanitized and length-encoded field into `buf`. +/// +/// Unlike `put_field_wellformed` this function handles arbitrary field names and values. +/// +/// `name` denotes the field name. It gets sanitized before being appended to `buf`. +/// +/// `write_value` is invoked with `buf` as argument to append the value data to `buf`. It must +/// not delete from `buf`, but may append arbitrary data. This function then determines the length +/// of the data written and adds it in the appropriate place in `buf`. +fn put_field_length_encoded(buf: &mut Vec, name: &str, write_value: impl FnOnce(&mut Vec)) { sanitize_name(name, buf); buf.push(b'\n'); buf.extend_from_slice(&[0; 8]); // Length tag, to be populated let start = buf.len(); - write!(buf, "{:?}", value).unwrap(); + write_value(buf); let end = buf.len(); buf[start - 8..start].copy_from_slice(&((end - start) as u64).to_le_bytes()); buf.push(b'\n'); @@ -279,14 +371,23 @@ fn sanitize_name(name: &str, buf: &mut Vec) { ); } -/// Append arbitrary data with a well-formed name -fn put_field(buf: &mut Vec, name: &str, value: &[u8]) { +/// Append arbitrary data with a well-formed name and value. +/// +/// `value` must not contain an internal newline, because this function writes +/// `value` in the new-line separated format. +/// +/// For a "newline-safe" variant, see `put_field_length_encoded`. +fn put_field_wellformed(buf: &mut Vec, name: &str, value: &[u8]) { buf.extend_from_slice(name.as_bytes()); buf.push(b'\n'); put_value(buf, value); } -/// Write the value portion of a key-value pair +/// Write the value portion of a key-value pair, in newline separated format. +/// +/// `value` must not contain an internal newline. +/// +/// For a "newline-safe" variant, see `put_field_length_encoded`. fn put_value(buf: &mut Vec, value: &[u8]) { buf.extend_from_slice(&(value.len() as u64).to_le_bytes()); buf.extend_from_slice(value); diff --git a/tracing-journald/src/memfd.rs b/tracing-journald/src/memfd.rs new file mode 100644 index 0000000000..5292db2928 --- /dev/null +++ b/tracing-journald/src/memfd.rs @@ -0,0 +1,31 @@ +//! memfd helpers. + +use libc::*; +use std::fs::File; +use std::io::Error; +use std::io::Result; +use std::os::raw::c_uint; +use std::os::unix::prelude::{FromRawFd, RawFd}; + +fn create(flags: c_uint) -> Result { + let fd = unsafe { memfd_create("tracing-journald\0".as_ptr() as *const c_char, flags) }; + if fd < 0 { + Err(Error::last_os_error()) + } else { + Ok(unsafe { File::from_raw_fd(fd as RawFd) }) + } +} + +pub fn create_sealable() -> Result { + create(MFD_ALLOW_SEALING | MFD_CLOEXEC) +} + +pub fn seal_fully(fd: RawFd) -> Result<()> { + let all_seals = F_SEAL_SHRINK | F_SEAL_GROW | F_SEAL_WRITE | F_SEAL_SEAL; + let result = unsafe { fcntl(fd, F_ADD_SEALS, all_seals) }; + if result < 0 { + Err(Error::last_os_error()) + } else { + Ok(()) + } +} diff --git a/tracing-journald/src/socket.rs b/tracing-journald/src/socket.rs new file mode 100644 index 0000000000..bba53d8658 --- /dev/null +++ b/tracing-journald/src/socket.rs @@ -0,0 +1,88 @@ +//! socket helpers. + +use std::io::{Error, Result}; +use std::mem::{size_of, zeroed}; +use std::os::unix::ffi::OsStrExt; +use std::os::unix::net::UnixDatagram; +use std::os::unix::prelude::{AsRawFd, RawFd}; +use std::path::Path; +use std::ptr; + +use libc::*; + +const CMSG_BUFSIZE: usize = 64; + +#[repr(C)] +union AlignedBuffer { + buffer: T, + align: cmsghdr, +} + +fn assert_cmsg_bufsize() { + let space_one_fd = unsafe { CMSG_SPACE(size_of::() as u32) }; + assert!( + space_one_fd <= CMSG_BUFSIZE as u32, + "cmsghdr buffer too small (< {}) to hold a single fd", + space_one_fd + ); +} + +#[cfg(test)] +#[test] +fn cmsg_buffer_size_for_one_fd() { + assert_cmsg_bufsize() +} + +pub fn send_one_fd_to>(socket: &UnixDatagram, fd: RawFd, path: P) -> Result { + assert_cmsg_bufsize(); + + let mut addr: sockaddr_un = unsafe { zeroed() }; + let path_bytes = path.as_ref().as_os_str().as_bytes(); + // path_bytes may have at most sun_path + 1 bytes, to account for the trailing NUL byte. + if addr.sun_path.len() <= path_bytes.len() { + return Err(Error::from_raw_os_error(ENAMETOOLONG)); + } + + addr.sun_family = AF_UNIX as _; + unsafe { + std::ptr::copy_nonoverlapping( + path_bytes.as_ptr(), + addr.sun_path.as_mut_ptr() as *mut u8, + path_bytes.len(), + ) + }; + + let mut msg: msghdr = unsafe { zeroed() }; + // Set the target address. + msg.msg_name = &mut addr as *mut _ as *mut c_void; + msg.msg_namelen = size_of::() as socklen_t; + + // We send no data body with this message. + msg.msg_iov = ptr::null_mut(); + msg.msg_iovlen = 0; + + // Create and fill the control message buffer with our file descriptor + let mut cmsg_buffer = AlignedBuffer { + buffer: ([0u8; CMSG_BUFSIZE]), + }; + msg.msg_control = unsafe { cmsg_buffer.buffer.as_mut_ptr() as _ }; + msg.msg_controllen = unsafe { CMSG_SPACE(size_of::() as _) as _ }; + + let mut cmsg: &mut cmsghdr = + unsafe { CMSG_FIRSTHDR(&msg).as_mut() }.expect("Control message buffer exhausted"); + + cmsg.cmsg_level = SOL_SOCKET; + cmsg.cmsg_type = SCM_RIGHTS; + cmsg.cmsg_len = unsafe { CMSG_LEN(size_of::() as _) as _ }; + + unsafe { ptr::write(CMSG_DATA(cmsg) as *mut RawFd, fd) }; + + let result = unsafe { sendmsg(socket.as_raw_fd(), &msg, libc::MSG_NOSIGNAL) }; + + if result < 0 { + Err(Error::last_os_error()) + } else { + // sendmsg returns the number of bytes written + Ok(result as usize) + } +} diff --git a/tracing-journald/tests/journal.rs b/tracing-journald/tests/journal.rs new file mode 100644 index 0000000000..25c1412e5d --- /dev/null +++ b/tracing-journald/tests/journal.rs @@ -0,0 +1,184 @@ +#![cfg(target_os = "linux")] + +use std::collections::HashMap; +use std::process::Command; +use std::time::Duration; + +use serde::Deserialize; +use tracing::{debug, error, info, warn}; +use tracing_journald::Layer; +use tracing_subscriber::layer::SubscriberExt; +use tracing_subscriber::Registry; + +fn journalctl_version() -> std::io::Result { + let output = Command::new("journalctl").arg("--version").output()?; + Ok(String::from_utf8_lossy(&output.stdout).to_string()) +} + +fn with_journald(f: impl FnOnce()) { + match journalctl_version() { + Ok(_) => { + let sub = Registry::default().with(Layer::new().unwrap().with_field_prefix(None)); + tracing::subscriber::with_default(sub, f); + } + Err(error) => eprintln!( + "SKIPPING TEST: journalctl --version failed with error: {}", + error + ), + } +} + +#[derive(Debug, PartialEq, Deserialize)] +#[serde(untagged)] +enum Field { + Text(String), + Binary(Vec), +} + +// Convenience impls to compare fields against strings and bytes with assert_eq! +impl PartialEq<&str> for Field { + fn eq(&self, other: &&str) -> bool { + match self { + Field::Text(s) => s == other, + Field::Binary(_) => false, + } + } +} + +impl PartialEq<[u8]> for Field { + fn eq(&self, other: &[u8]) -> bool { + match self { + Field::Text(s) => s.as_bytes() == other, + Field::Binary(data) => data == other, + } + } +} + +/// Retry `f` 30 times 100ms apart, i.e. a total of three seconds. +/// +/// When `f` returns an error wait 100ms and try it again, up to ten times. +/// If the last attempt failed return the error returned by that attempt. +/// +/// If `f` returns Ok immediately return the result. +fn retry(f: impl Fn() -> Result) -> Result { + let attempts = 30; + let interval = Duration::from_millis(100); + for attempt in (0..attempts).rev() { + match f() { + Ok(result) => return Ok(result), + Err(e) if attempt == 0 => return Err(e), + Err(_) => std::thread::sleep(interval), + } + } + unreachable!() +} + +/// Read from journal with `journalctl`. +/// +/// `test_name` is a string to match in the `TEST_NAME` field +/// of the `journalctl` call, to make sure to only select journal entries +/// originating from and relevant to the current test. +/// +/// Additionally filter by the `_PID` field with the PID of this +/// test process, to make sure this method only reads journal entries +/// created by this test process. +fn read_from_journal(test_name: &str) -> Vec> { + let stdout = String::from_utf8( + Command::new("journalctl") + // We pass --all to circumvent journalctl's default limit of 4096 bytes for field values + .args(&["--user", "--output=json", "--all"]) + // Filter by the PID of the current test process + .arg(format!("_PID={}", std::process::id())) + .arg(format!("TEST_NAME={}", test_name)) + .output() + .unwrap() + .stdout, + ) + .unwrap(); + + stdout + .lines() + .map(|l| serde_json::from_str(l).unwrap()) + .collect() +} + +/// Read exactly one line from journal for the given test name. +/// +/// Try to read lines for `testname` from journal, and `retry()` if the wasn't +/// _exactly_ one matching line. +fn retry_read_one_line_from_journal(testname: &str) -> HashMap { + retry(|| { + let mut messages = read_from_journal(testname); + if messages.len() == 1 { + Ok(messages.pop().unwrap()) + } else { + Err(format!( + "one messages expected, got {} messages", + messages.len() + )) + } + }) + .unwrap() +} + +#[test] +fn simple_message() { + with_journald(|| { + info!(test.name = "simple_message", "Hello World"); + + let message = retry_read_one_line_from_journal("simple_message"); + assert_eq!(message["MESSAGE"], "Hello World"); + assert_eq!(message["PRIORITY"], "5"); + }); +} + +#[test] +fn multiline_message() { + with_journald(|| { + warn!(test.name = "multiline_message", "Hello\nMultiline\nWorld"); + + let message = retry_read_one_line_from_journal("multiline_message"); + assert_eq!(message["MESSAGE"], "Hello\nMultiline\nWorld"); + assert_eq!(message["PRIORITY"], "4"); + }); +} + +#[test] +fn multiline_message_trailing_newline() { + with_journald(|| { + error!( + test.name = "multiline_message_trailing_newline", + "A trailing newline\n" + ); + + let message = retry_read_one_line_from_journal("multiline_message_trailing_newline"); + assert_eq!(message["MESSAGE"], "A trailing newline\n"); + assert_eq!(message["PRIORITY"], "3"); + }); +} + +#[test] +fn internal_null_byte() { + with_journald(|| { + debug!(test.name = "internal_null_byte", "An internal\x00byte"); + + let message = retry_read_one_line_from_journal("internal_null_byte"); + assert_eq!(message["MESSAGE"], b"An internal\x00byte"[..]); + assert_eq!(message["PRIORITY"], "6"); + }); +} + +#[test] +fn large_message() { + let large_string = "b".repeat(512_000); + with_journald(|| { + debug!(test.name = "large_message", "Message: {}", large_string); + + let message = retry_read_one_line_from_journal("large_message"); + assert_eq!( + message["MESSAGE"], + format!("Message: {}", large_string).as_str() + ); + assert_eq!(message["PRIORITY"], "6"); + }); +} diff --git a/tracing-serde/README.md b/tracing-serde/README.md index 5282199e29..09cda49a80 100644 --- a/tracing-serde/README.md +++ b/tracing-serde/README.md @@ -53,10 +53,6 @@ tracing-serde = "0.1" Next, add this to your crate: ```rust -#[macro_use] -extern crate tracing; -extern crate tracing_serde; - use tracing_serde::AsSerde; ``` diff --git a/tracing/README.md b/tracing/README.md index af7f6aa2a6..4a8a85d2dd 100644 --- a/tracing/README.md +++ b/tracing/README.md @@ -390,6 +390,10 @@ maintained by the `tokio` project. These include: - [`diesel-tracing`] provides integration with [`diesel`] database connections. - [`tracing-tracy`] provides a way to collect [Tracy] profiles in instrumented applications. +- [`tracing-elastic-apm`] provides a layer for reporting traces to [Elastic APM]. +- [`tracing-etw`] provides a layer for emitting Windows [ETW] events. +- [`tracing-fluent-assertions`] provides a fluent assertions-style testing + framework for validating the behavior of `tracing` spans. If you're the maintainer of a `tracing` ecosystem crate not listed above, please let us know! We'd love to add your project to the list! @@ -410,6 +414,11 @@ please let us know! We'd love to add your project to the list! [`diesel-tracing`]: https://crates.io/crates/diesel-tracing [`tracing-tracy`]: https://crates.io/crates/tracing-tracy [Tracy]: https://github.com/wolfpld/tracy +[`tracing-elastic-apm`]: https://crates.io/crates/tracing-elastic-apm +[Elastic APM]: https://www.elastic.co/apm +[`tracing-etw`]: https://github.com/microsoft/tracing-etw +[ETW]: https://docs.microsoft.com/en-us/windows/win32/etw/about-event-tracing +[`tracing-fluent-assertions`]: https://crates.io/crates/tracing-fluent-assertions **Note:** that some of the ecosystem crates are currently unreleased and undergoing active development. They may be less stable than `tracing` and diff --git a/tracing/benches/subscriber.rs b/tracing/benches/subscriber.rs index 0595d64222..c6418010f4 100644 --- a/tracing/benches/subscriber.rs +++ b/tracing/benches/subscriber.rs @@ -1,6 +1,3 @@ -extern crate criterion; -extern crate tracing; - use criterion::{black_box, criterion_group, criterion_main, Criterion}; use tracing::Level; diff --git a/tracing/src/level_filters.rs b/tracing/src/level_filters.rs index cfacee2efe..6052a1a65e 100644 --- a/tracing/src/level_filters.rs +++ b/tracing/src/level_filters.rs @@ -65,7 +65,7 @@ pub use tracing_core::{metadata::ParseLevelFilterError, LevelFilter}; /// [module-level documentation]: ../index.html#compile-time-filters pub const STATIC_MAX_LEVEL: LevelFilter = MAX_LEVEL; -cfg_if! { +cfg_if::cfg_if! { if #[cfg(all(not(debug_assertions), feature = "release_max_level_off"))] { const MAX_LEVEL: LevelFilter = LevelFilter::OFF; } else if #[cfg(all(not(debug_assertions), feature = "release_max_level_error"))] { diff --git a/tracing/src/lib.rs b/tracing/src/lib.rs index 5f96fc3576..e8d0ed5ef9 100644 --- a/tracing/src/lib.rs +++ b/tracing/src/lib.rs @@ -739,6 +739,8 @@ //! applications. //! - [`tracing-elastic-apm`] provides a layer for reporting traces to [Elastic APM]. //! - [`tracing-etw`] provides a layer for emitting Windows [ETW] events. +//! - [`tracing-fluent-assertions`] provides a fluent assertions-style testing +//! framework for validating the behavior of `tracing` spans. //! //! If you're the maintainer of a `tracing` ecosystem crate not listed above, //! please let us know! We'd love to add your project to the list! @@ -765,10 +767,7 @@ //! [`diesel-tracing`]: https://crates.io/crates/diesel-tracing //! [`tracing-tracy`]: https://crates.io/crates/tracing-tracy //! [Tracy]: https://github.com/wolfpld/tracy -//! [`tracing-elastic-apm`]: https://crates.io/crates/tracing-elastic-apm -//! [Elastic APM]: https://www.elastic.co/apm -//! [`tracing-etw`]: https://github.com/microsoft/tracing-etw -//! [ETW]: https://docs.microsoft.com/en-us/windows/win32/etw/about-event-tracing +//! [`tracing-fluent-assertions`]: https://crates.io/crates/tracing-fluent-assertions //! //!
 //!     Note: Some of these ecosystem crates are currently
@@ -882,9 +881,6 @@
 #[cfg(not(feature = "std"))]
 extern crate alloc;
 
-#[macro_use]
-extern crate cfg_if;
-
 #[cfg(feature = "log")]
 #[doc(hidden)]
 pub use log;
diff --git a/tracing/src/macros.rs b/tracing/src/macros.rs
index 2cffa3830f..af91eeca93 100644
--- a/tracing/src/macros.rs
+++ b/tracing/src/macros.rs
@@ -575,9 +575,7 @@ macro_rules! error_span {
 // ///
 // /// For example, the following does not compile:
 // /// ```rust,compile_fail
-// /// # #[macro_use]
-// /// # extern crate tracing;
-// /// # use tracing::Level;
+// /// # use tracing::{Level, event};
 // /// # fn main() {
 // /// event!(Level::INFO, foo = 5, bad_field, bar = "hello")
 // /// #}
diff --git a/tracing/src/span.rs b/tracing/src/span.rs
index 32c78959e6..e9e232703f 100644
--- a/tracing/src/span.rs
+++ b/tracing/src/span.rs
@@ -136,8 +136,7 @@
 //! as long as the longest-executing span in its subtree.
 //!
 //! ```
-//! # #[macro_use] extern crate tracing;
-//! # use tracing::Level;
+//! # use tracing::{Level, span};
 //! // this span is considered the "root" of a new trace tree:
 //! span!(Level::INFO, "root").in_scope(|| {
 //!     // since we are now inside "root", this span is considered a child
@@ -157,8 +156,7 @@
 //! the `span!` macro. For example:
 //!
 //! ```rust
-//! # #[macro_use] extern crate tracing;
-//! # use tracing::Level;
+//! # use tracing::{Level, span};
 //! // Create, but do not enter, a span called "foo".
 //! let foo = span!(Level::INFO, "foo");
 //!
@@ -200,8 +198,6 @@
 //! _closed_. Consider, for example, a future which has an associated
 //! span and enters that span every time it is polled:
 //! ```rust
-//! # extern crate tracing;
-//! # extern crate futures;
 //! # use futures::{Future, Poll, Async};
 //! struct MyFuture {
 //!    // data
@@ -241,8 +237,7 @@
 //! that handle "closes" the span, since the capacity to enter it no longer
 //! exists. For example:
 //! ```
-//! # #[macro_use] extern crate tracing;
-//! # use tracing::Level;
+//! # use tracing::{Level, span};
 //! {
 //!     span!(Level::TRACE, "my_span").in_scope(|| {
 //!         // perform some work in the context of `my_span`...
@@ -275,8 +270,7 @@
 //! construct one span and perform the entire loop inside of that span, like:
 //!
 //! ```rust
-//! # #[macro_use] extern crate tracing;
-//! # use tracing::Level;
+//! # use tracing::{Level, span};
 //! # let n = 1;
 //! let span = span!(Level::TRACE, "my_loop");
 //! let _enter = span.enter();
@@ -287,8 +281,7 @@
 //! ```
 //! Or, should we create a new span for each iteration of the loop, as in:
 //! ```rust
-//! # #[macro_use] extern crate tracing;
-//! # use tracing::Level;
+//! # use tracing::{Level, span};
 //! # let n = 1u64;
 //! for i in 0..n {
 //!     let span = span!(Level::TRACE, "my_loop", iteration = i);
@@ -722,8 +715,7 @@ impl Span {
     /// # Examples
     ///
     /// ```
-    /// #[macro_use] extern crate tracing;
-    /// # use tracing::Level;
+    /// # use tracing::{span, Level};
     /// let span = span!(Level::INFO, "my_span");
     /// let guard = span.enter();
     ///
@@ -738,7 +730,7 @@ impl Span {
     /// Guards need not be explicitly dropped:
     ///
     /// ```
-    /// #[macro_use] extern crate tracing;
+    /// # use tracing::trace_span;
     /// fn my_function() -> String {
     ///     // enter a span for the duration of this function.
     ///     let span = trace_span!("my_function");
@@ -760,7 +752,7 @@ impl Span {
     /// entered:
     ///
     /// ```
-    /// #[macro_use] extern crate tracing;
+    /// # use tracing::{info, info_span};
     /// let span = info_span!("my_great_span");
     ///
     /// {
@@ -1070,8 +1062,7 @@ impl Span {
     /// # Examples
     ///
     /// ```
-    /// # #[macro_use] extern crate tracing;
-    /// # use tracing::Level;
+    /// # use tracing::{trace, span, Level};
     /// let my_span = span!(Level::TRACE, "my_span");
     ///
     /// my_span.in_scope(|| {
diff --git a/tracing/test-log-support/src/lib.rs b/tracing/test-log-support/src/lib.rs
index 7e76428892..e63257445f 100644
--- a/tracing/test-log-support/src/lib.rs
+++ b/tracing/test-log-support/src/lib.rs
@@ -1,4 +1,3 @@
-extern crate log;
 use log::{LevelFilter, Log, Metadata, Record};
 use std::sync::{Arc, Mutex};
 
diff --git a/tracing/test-log-support/tests/log_no_trace.rs b/tracing/test-log-support/tests/log_no_trace.rs
index 2e71896e08..206e9b577c 100644
--- a/tracing/test-log-support/tests/log_no_trace.rs
+++ b/tracing/test-log-support/tests/log_no_trace.rs
@@ -1,9 +1,5 @@
-#[macro_use]
-extern crate tracing;
-extern crate test_log_support;
-
 use test_log_support::Test;
-use tracing::Level;
+use tracing::{error, info, span, trace, warn, Level};
 
 #[cfg_attr(target_arch = "wasm32", wasm_bindgen_test::wasm_bindgen_test)]
 #[test]
diff --git a/tracing/test-log-support/tests/log_with_trace.rs b/tracing/test-log-support/tests/log_with_trace.rs
index d2d5b2cf81..c32cb79e93 100644
--- a/tracing/test-log-support/tests/log_with_trace.rs
+++ b/tracing/test-log-support/tests/log_with_trace.rs
@@ -1,9 +1,5 @@
-#[macro_use]
-extern crate tracing;
-extern crate test_log_support;
-
 use test_log_support::Test;
-use tracing::Level;
+use tracing::{error, info, span, trace, warn, Level};
 
 pub struct NopSubscriber;
 
diff --git a/tracing/test-log-support/tests/span_activity_filtered_separately.rs b/tracing/test-log-support/tests/span_activity_filtered_separately.rs
index 3f28822c40..32bc00d96a 100644
--- a/tracing/test-log-support/tests/span_activity_filtered_separately.rs
+++ b/tracing/test-log-support/tests/span_activity_filtered_separately.rs
@@ -1,9 +1,5 @@
-#[macro_use]
-extern crate tracing;
-extern crate test_log_support;
-
 use test_log_support::Test;
-use tracing::Level;
+use tracing::{error, info, span, trace, warn, Level};
 
 #[cfg_attr(target_arch = "wasm32", wasm_bindgen_test::wasm_bindgen_test)]
 #[test]
diff --git a/tracing/test-log-support/tests/span_lifecycle_can_be_enabled.rs b/tracing/test-log-support/tests/span_lifecycle_can_be_enabled.rs
index ee099c0966..8ff515f9fe 100644
--- a/tracing/test-log-support/tests/span_lifecycle_can_be_enabled.rs
+++ b/tracing/test-log-support/tests/span_lifecycle_can_be_enabled.rs
@@ -1,9 +1,5 @@
-#[macro_use]
-extern crate tracing;
-extern crate test_log_support;
-
 use test_log_support::Test;
-use tracing::Level;
+use tracing::{error, info, span, trace, warn, Level};
 
 #[cfg_attr(target_arch = "wasm32", wasm_bindgen_test::wasm_bindgen_test)]
 #[test]
diff --git a/tracing/test-log-support/tests/span_lifecycle_defaults_off.rs b/tracing/test-log-support/tests/span_lifecycle_defaults_off.rs
index a966569cbb..ab1cb24ffa 100644
--- a/tracing/test-log-support/tests/span_lifecycle_defaults_off.rs
+++ b/tracing/test-log-support/tests/span_lifecycle_defaults_off.rs
@@ -1,9 +1,5 @@
-#[macro_use]
-extern crate tracing;
-extern crate test_log_support;
-
 use test_log_support::Test;
-use tracing::Level;
+use tracing::{error, info, span, trace, warn, Level};
 
 #[cfg_attr(target_arch = "wasm32", wasm_bindgen_test::wasm_bindgen_test)]
 #[test]
diff --git a/tracing/test-log-support/tests/span_lifecycle_is_trace.rs b/tracing/test-log-support/tests/span_lifecycle_is_trace.rs
index 62ac7194a6..b94560cfa4 100644
--- a/tracing/test-log-support/tests/span_lifecycle_is_trace.rs
+++ b/tracing/test-log-support/tests/span_lifecycle_is_trace.rs
@@ -1,9 +1,5 @@
-#[macro_use]
-extern crate tracing;
-extern crate test_log_support;
-
 use test_log_support::Test;
-use tracing::Level;
+use tracing::{error, info, span, trace, warn, Level};
 
 #[cfg_attr(target_arch = "wasm32", wasm_bindgen_test::wasm_bindgen_test)]
 #[test]
diff --git a/tracing/test_static_max_level_features/tests/test.rs b/tracing/test_static_max_level_features/tests/test.rs
index 419dd28ef0..d8be44c97e 100644
--- a/tracing/test_static_max_level_features/tests/test.rs
+++ b/tracing/test_static_max_level_features/tests/test.rs
@@ -1,9 +1,6 @@
-#[macro_use]
-extern crate tracing;
-
 use std::sync::{Arc, Mutex};
 use tracing::span::{Attributes, Record};
-use tracing::{span, Event, Id, Level, Metadata, Subscriber};
+use tracing::{debug, error, info, span, trace, warn, Event, Id, Level, Metadata, Subscriber};
 
 struct State {
     last_level: Mutex>,
diff --git a/tracing/tests/event.rs b/tracing/tests/event.rs
index 4b30032dbe..93f9c07f28 100644
--- a/tracing/tests/event.rs
+++ b/tracing/tests/event.rs
@@ -5,17 +5,16 @@
 // The alternative would be for each of these tests to be defined in a separate
 // file, which is :(
 #![cfg(feature = "std")]
-
-#[macro_use]
-extern crate tracing;
 mod support;
 
 use self::support::*;
 
 use tracing::{
+    debug, error,
     field::{debug, display},
+    info,
     subscriber::with_default,
-    Level,
+    trace, warn, Level,
 };
 
 macro_rules! event_without_message {
@@ -150,7 +149,7 @@ fn one_with_everything() {
         .run_with_handle();
 
     with_default(subscriber, || {
-        event!(
+        tracing::event!(
             target: "whatever",
             Level::ERROR,
             { foo = 666, bar = false, like_a_butterfly = 42.0 },
@@ -176,7 +175,7 @@ fn moved_field() {
         .run_with_handle();
     with_default(subscriber, || {
         let from = "my event";
-        event!(Level::INFO, foo = display(format!("hello from {}", from)))
+        tracing::event!(Level::INFO, foo = display(format!("hello from {}", from)))
     });
 
     handle.assert_finished();
@@ -197,7 +196,7 @@ fn dotted_field_name() {
         .done()
         .run_with_handle();
     with_default(subscriber, || {
-        event!(Level::INFO, foo.bar = true, foo.baz = false);
+        tracing::event!(Level::INFO, foo.bar = true, foo.baz = false);
     });
 
     handle.assert_finished();
@@ -219,7 +218,7 @@ fn borrowed_field() {
     with_default(subscriber, || {
         let from = "my event";
         let mut message = format!("hello from {}", from);
-        event!(Level::INFO, foo = display(&message));
+        tracing::event!(Level::INFO, foo = display(&message));
         message.push_str(", which happened!");
     });
 
@@ -281,7 +280,7 @@ fn display_shorthand() {
         .done()
         .run_with_handle();
     with_default(subscriber, || {
-        event!(Level::TRACE, my_field = %"hello world");
+        tracing::event!(Level::TRACE, my_field = %"hello world");
     });
 
     handle.assert_finished();
@@ -301,7 +300,7 @@ fn debug_shorthand() {
         .done()
         .run_with_handle();
     with_default(subscriber, || {
-        event!(Level::TRACE, my_field = ?"hello world");
+        tracing::event!(Level::TRACE, my_field = ?"hello world");
     });
 
     handle.assert_finished();
@@ -322,7 +321,7 @@ fn both_shorthands() {
         .done()
         .run_with_handle();
     with_default(subscriber, || {
-        event!(Level::TRACE, display_field = %"hello world", debug_field = ?"hello world");
+        tracing::event!(Level::TRACE, display_field = %"hello world", debug_field = ?"hello world");
     });
 
     handle.assert_finished();
@@ -338,8 +337,8 @@ fn explicit_child() {
         .run_with_handle();
 
     with_default(subscriber, || {
-        let foo = span!(Level::TRACE, "foo");
-        event!(parent: foo.id(), Level::TRACE, "bar");
+        let foo = tracing::span!(Level::TRACE, "foo");
+        tracing::event!(parent: foo.id(), Level::TRACE, "bar");
     });
 
     handle.assert_finished();
@@ -359,7 +358,7 @@ fn explicit_child_at_levels() {
         .run_with_handle();
 
     with_default(subscriber, || {
-        let foo = span!(Level::TRACE, "foo");
+        let foo = tracing::span!(Level::TRACE, "foo");
         trace!(parent: foo.id(), "a");
         debug!(parent: foo.id(), "b");
         info!(parent: foo.id(), "c");
diff --git a/tracing/tests/filter_caching_is_lexically_scoped.rs b/tracing/tests/filter_caching_is_lexically_scoped.rs
index 9b997a0c6b..27096cb3c9 100644
--- a/tracing/tests/filter_caching_is_lexically_scoped.rs
+++ b/tracing/tests/filter_caching_is_lexically_scoped.rs
@@ -7,12 +7,10 @@
 #[cfg(not(feature = "std"))]
 extern crate std;
 
-#[macro_use]
-extern crate tracing;
 mod support;
 
 use self::support::*;
-use tracing::Level;
+use tracing::{span, Level};
 
 use std::sync::{
     atomic::{AtomicUsize, Ordering},
diff --git a/tracing/tests/filters_are_not_reevaluated_for_the_same_span.rs b/tracing/tests/filters_are_not_reevaluated_for_the_same_span.rs
index 53e11ef448..9d2ef6e0b7 100644
--- a/tracing/tests/filters_are_not_reevaluated_for_the_same_span.rs
+++ b/tracing/tests/filters_are_not_reevaluated_for_the_same_span.rs
@@ -5,13 +5,10 @@
 // threads with shared global state lets them interfere with each other
 #[cfg(not(feature = "std"))]
 extern crate std;
-
-#[macro_use]
-extern crate tracing;
 mod support;
 
 use self::support::*;
-use tracing::Level;
+use tracing::{span, Level};
 
 use std::sync::{
     atomic::{AtomicUsize, Ordering},
diff --git a/tracing/tests/filters_are_reevaluated_for_different_call_sites.rs b/tracing/tests/filters_are_reevaluated_for_different_call_sites.rs
index 5675e4e678..432848c87a 100644
--- a/tracing/tests/filters_are_reevaluated_for_different_call_sites.rs
+++ b/tracing/tests/filters_are_reevaluated_for_different_call_sites.rs
@@ -6,12 +6,10 @@
 #[cfg(not(feature = "std"))]
 extern crate std;
 
-#[macro_use]
-extern crate tracing;
+use tracing::{span, Level};
 mod support;
 
 use self::support::*;
-use tracing::Level;
 
 use std::sync::{
     atomic::{AtomicUsize, Ordering},
diff --git a/tracing/tests/macros.rs b/tracing/tests/macros.rs
index 445d17aa43..420319d373 100644
--- a/tracing/tests/macros.rs
+++ b/tracing/tests/macros.rs
@@ -1,8 +1,9 @@
 #![deny(warnings)]
-use tracing::Level;
+use tracing::{
+    callsite, debug, debug_span, error, error_span, event, info, info_span, span, trace,
+    trace_span, warn, warn_span, Level,
+};
 
-#[macro_use]
-extern crate tracing;
 // Tests that macros work across various invocation syntax.
 //
 // These are quite repetitive, and _could_ be generated by a macro. However,
diff --git a/tracing/tests/span.rs b/tracing/tests/span.rs
index c784a96069..4f6a642bdb 100644
--- a/tracing/tests/span.rs
+++ b/tracing/tests/span.rs
@@ -3,8 +3,6 @@
 // with the standard lib disabled.
 #![cfg(feature = "std")]
 
-#[macro_use]
-extern crate tracing;
 mod support;
 
 use self::support::*;
@@ -23,7 +21,7 @@ fn handles_to_the_same_span_are_equal() {
     // won't enter any spans in this test, so the subscriber won't actually
     // expect to see any spans.
     with_default(subscriber::mock().run(), || {
-        let foo1 = span!(Level::TRACE, "foo");
+        let foo1 = tracing::span!(Level::TRACE, "foo");
         let foo2 = foo1.clone();
         // Two handles that point to the same span are equal.
         assert_eq!(foo1, foo2);
@@ -36,8 +34,8 @@ fn handles_to_different_spans_are_not_equal() {
     with_default(subscriber::mock().run(), || {
         // Even though these spans have the same name and fields, they will have
         // differing metadata, since they were created on different lines.
-        let foo1 = span!(Level::TRACE, "foo", bar = 1u64, baz = false);
-        let foo2 = span!(Level::TRACE, "foo", bar = 1u64, baz = false);
+        let foo1 = tracing::span!(Level::TRACE, "foo", bar = 1u64, baz = false);
+        let foo2 = tracing::span!(Level::TRACE, "foo", bar = 1u64, baz = false);
 
         assert_ne!(foo1, foo2);
     });
@@ -49,7 +47,7 @@ fn handles_to_different_spans_with_the_same_metadata_are_not_equal() {
     // Every time time this function is called, it will return a _new
     // instance_ of a span with the same metadata, name, and fields.
     fn make_span() -> Span {
-        span!(Level::TRACE, "foo", bar = 1u64, baz = false)
+        tracing::span!(Level::TRACE, "foo", bar = 1u64, baz = false)
     }
 
     with_default(subscriber::mock().run(), || {
@@ -75,7 +73,7 @@ fn spans_always_go_to_the_subscriber_that_tagged_them() {
     let subscriber2 = subscriber::mock().run();
 
     let foo = with_default(subscriber1, || {
-        let foo = span!(Level::TRACE, "foo");
+        let foo = tracing::span!(Level::TRACE, "foo");
         foo.in_scope(|| {});
         foo
     });
@@ -100,7 +98,7 @@ fn spans_always_go_to_the_subscriber_that_tagged_them_even_across_threads() {
         .done()
         .run();
     let foo = with_default(subscriber1, || {
-        let foo = span!(Level::TRACE, "foo");
+        let foo = tracing::span!(Level::TRACE, "foo");
         foo.in_scope(|| {});
         foo
     });
@@ -126,7 +124,7 @@ fn dropping_a_span_calls_drop_span() {
         .done()
         .run_with_handle();
     with_default(subscriber, || {
-        let span = span!(Level::TRACE, "foo");
+        let span = tracing::span!(Level::TRACE, "foo");
         span.in_scope(|| {});
         drop(span);
     });
@@ -145,8 +143,8 @@ fn span_closes_after_event() {
         .done()
         .run_with_handle();
     with_default(subscriber, || {
-        span!(Level::TRACE, "foo").in_scope(|| {
-            event!(Level::DEBUG, {}, "my event!");
+        tracing::span!(Level::TRACE, "foo").in_scope(|| {
+            tracing::event!(Level::DEBUG, {}, "my tracing::event!");
         });
     });
 
@@ -167,10 +165,10 @@ fn new_span_after_event() {
         .done()
         .run_with_handle();
     with_default(subscriber, || {
-        span!(Level::TRACE, "foo").in_scope(|| {
-            event!(Level::DEBUG, {}, "my event!");
+        tracing::span!(Level::TRACE, "foo").in_scope(|| {
+            tracing::event!(Level::DEBUG, {}, "my tracing::event!");
         });
-        span!(Level::TRACE, "bar").in_scope(|| {});
+        tracing::span!(Level::TRACE, "bar").in_scope(|| {});
     });
 
     handle.assert_finished();
@@ -187,8 +185,8 @@ fn event_outside_of_span() {
         .done()
         .run_with_handle();
     with_default(subscriber, || {
-        debug!("my event!");
-        span!(Level::TRACE, "foo").in_scope(|| {});
+        tracing::debug!("my tracing::event!");
+        tracing::span!(Level::TRACE, "foo").in_scope(|| {});
     });
 
     handle.assert_finished();
@@ -201,7 +199,7 @@ fn cloning_a_span_calls_clone_span() {
         .clone_span(span::mock().named("foo"))
         .run_with_handle();
     with_default(subscriber, || {
-        let span = span!(Level::TRACE, "foo");
+        let span = tracing::span!(Level::TRACE, "foo");
         // Allow the "redundant" `.clone` since it is used to call into the `.clone_span` hook.
         #[allow(clippy::redundant_clone)]
         let _span2 = span.clone();
@@ -219,7 +217,7 @@ fn drop_span_when_exiting_dispatchers_context() {
         .drop_span(span::mock().named("foo"))
         .run_with_handle();
     with_default(subscriber, || {
-        let span = span!(Level::TRACE, "foo");
+        let span = tracing::span!(Level::TRACE, "foo");
         let _span2 = span.clone();
         drop(span);
     });
@@ -242,7 +240,7 @@ fn clone_and_drop_span_always_go_to_the_subscriber_that_tagged_the_span() {
     let subscriber2 = subscriber::mock().done().run();
 
     let foo = with_default(subscriber1, || {
-        let foo = span!(Level::TRACE, "foo");
+        let foo = tracing::span!(Level::TRACE, "foo");
         foo.in_scope(|| {});
         foo
     });
@@ -268,7 +266,7 @@ fn span_closes_when_exited() {
         .done()
         .run_with_handle();
     with_default(subscriber, || {
-        let foo = span!(Level::TRACE, "foo");
+        let foo = tracing::span!(Level::TRACE, "foo");
 
         foo.in_scope(|| {});
 
@@ -289,9 +287,9 @@ fn enter() {
         .done()
         .run_with_handle();
     with_default(subscriber, || {
-        let foo = span!(Level::TRACE, "foo");
+        let foo = tracing::span!(Level::TRACE, "foo");
         let _enter = foo.enter();
-        debug!("dropping guard...");
+        tracing::debug!("dropping guard...");
     });
 
     handle.assert_finished();
@@ -308,8 +306,8 @@ fn entered() {
         .done()
         .run_with_handle();
     with_default(subscriber, || {
-        let _span = span!(Level::TRACE, "foo").entered();
-        debug!("dropping guard...");
+        let _span = tracing::span!(Level::TRACE, "foo").entered();
+        tracing::debug!("dropping guard...");
     });
 
     handle.assert_finished();
@@ -326,9 +324,9 @@ fn entered_api() {
         .done()
         .run_with_handle();
     with_default(subscriber, || {
-        let span = span!(Level::TRACE, "foo").entered();
+        let span = tracing::span!(Level::TRACE, "foo").entered();
         let _derefs_to_span = span.id();
-        debug!("exiting span...");
+        tracing::debug!("exiting span...");
         let _: Span = span.exit();
     });
 
@@ -353,7 +351,7 @@ fn moved_field() {
         .run_with_handle();
     with_default(subscriber, || {
         let from = "my span";
-        let span = span!(
+        let span = tracing::span!(
             Level::TRACE,
             "foo",
             bar = display(format!("hello from {}", from))
@@ -376,7 +374,7 @@ fn dotted_field_name() {
         .done()
         .run_with_handle();
     with_default(subscriber, || {
-        span!(Level::TRACE, "foo", fields.bar = true);
+        tracing::span!(Level::TRACE, "foo", fields.bar = true);
     });
 
     handle.assert_finished();
@@ -402,7 +400,7 @@ fn borrowed_field() {
     with_default(subscriber, || {
         let from = "my span";
         let mut message = format!("hello from {}", from);
-        let span = span!(Level::TRACE, "foo", bar = display(&message));
+        let span = tracing::span!(Level::TRACE, "foo", bar = display(&message));
         span.in_scope(|| {
             message.insert_str(10, " inside");
         });
@@ -449,8 +447,8 @@ fn move_field_out_of_struct() {
             x: 3.234,
             y: -1.223,
         };
-        let foo = span!(Level::TRACE, "foo", x = debug(pos.x), y = debug(pos.y));
-        let bar = span!(Level::TRACE, "bar", position = debug(pos));
+        let foo = tracing::span!(Level::TRACE, "foo", x = debug(pos.x), y = debug(pos.y));
+        let bar = tracing::span!(Level::TRACE, "bar", position = debug(pos));
         foo.in_scope(|| {});
         bar.in_scope(|| {});
     });
@@ -473,7 +471,7 @@ fn float_values() {
         .run_with_handle();
 
     with_default(subscriber, || {
-        let foo = span!(Level::TRACE, "foo", x = 3.234, y = -1.223);
+        let foo = tracing::span!(Level::TRACE, "foo", x = 3.234, y = -1.223);
         foo.in_scope(|| {});
     });
 
@@ -504,7 +502,7 @@ fn add_field_after_new_span() {
         .run_with_handle();
 
     with_default(subscriber, || {
-        let span = span!(Level::TRACE, "foo", bar = 5, baz = false);
+        let span = tracing::span!(Level::TRACE, "foo", bar = 5, baz = false);
         span.record("baz", &true);
         span.in_scope(|| {})
     });
@@ -532,7 +530,7 @@ fn add_fields_only_after_new_span() {
         .run_with_handle();
 
     with_default(subscriber, || {
-        let span = span!(Level::TRACE, "foo", bar = _, baz = _);
+        let span = tracing::span!(Level::TRACE, "foo", bar = _, baz = _);
         span.record("bar", &5);
         span.record("baz", &true);
         span.in_scope(|| {})
@@ -565,7 +563,7 @@ fn record_new_value_for_field() {
         .run_with_handle();
 
     with_default(subscriber, || {
-        let span = span!(Level::TRACE, "foo", bar = 5, baz = false);
+        let span = tracing::span!(Level::TRACE, "foo", bar = 5, baz = false);
         span.record("baz", &true);
         span.in_scope(|| {})
     });
@@ -600,7 +598,7 @@ fn record_new_values_for_fields() {
         .run_with_handle();
 
     with_default(subscriber, || {
-        let span = span!(Level::TRACE, "foo", bar = 4, baz = false);
+        let span = tracing::span!(Level::TRACE, "foo", bar = 4, baz = false);
         span.record("bar", &5);
         span.record("baz", &true);
         span.in_scope(|| {})
@@ -623,7 +621,7 @@ fn new_span_with_target_and_log_level() {
         .run_with_handle();
 
     with_default(subscriber, || {
-        span!(target: "app_span", Level::DEBUG, "foo");
+        tracing::span!(target: "app_span", Level::DEBUG, "foo");
     });
 
     handle.assert_finished();
@@ -638,7 +636,7 @@ fn explicit_root_span_is_root() {
         .run_with_handle();
 
     with_default(subscriber, || {
-        span!(parent: None, Level::TRACE, "foo");
+        tracing::span!(parent: None, Level::TRACE, "foo");
     });
 
     handle.assert_finished();
@@ -656,8 +654,8 @@ fn explicit_root_span_is_root_regardless_of_ctx() {
         .run_with_handle();
 
     with_default(subscriber, || {
-        span!(Level::TRACE, "foo").in_scope(|| {
-            span!(parent: None, Level::TRACE, "bar");
+        tracing::span!(Level::TRACE, "foo").in_scope(|| {
+            tracing::span!(parent: None, Level::TRACE, "bar");
         })
     });
 
@@ -674,8 +672,8 @@ fn explicit_child() {
         .run_with_handle();
 
     with_default(subscriber, || {
-        let foo = span!(Level::TRACE, "foo");
-        span!(parent: foo.id(), Level::TRACE, "bar");
+        let foo = tracing::span!(Level::TRACE, "foo");
+        tracing::span!(parent: foo.id(), Level::TRACE, "bar");
     });
 
     handle.assert_finished();
@@ -695,12 +693,12 @@ fn explicit_child_at_levels() {
         .run_with_handle();
 
     with_default(subscriber, || {
-        let foo = span!(Level::TRACE, "foo");
-        trace_span!(parent: foo.id(), "a");
-        debug_span!(parent: foo.id(), "b");
-        info_span!(parent: foo.id(), "c");
-        warn_span!(parent: foo.id(), "d");
-        error_span!(parent: foo.id(), "e");
+        let foo = tracing::span!(Level::TRACE, "foo");
+        tracing::trace_span!(parent: foo.id(), "a");
+        tracing::debug_span!(parent: foo.id(), "b");
+        tracing::info_span!(parent: foo.id(), "c");
+        tracing::warn_span!(parent: foo.id(), "d");
+        tracing::error_span!(parent: foo.id(), "e");
     });
 
     handle.assert_finished();
@@ -719,8 +717,9 @@ fn explicit_child_regardless_of_ctx() {
         .run_with_handle();
 
     with_default(subscriber, || {
-        let foo = span!(Level::TRACE, "foo");
-        span!(Level::TRACE, "bar").in_scope(|| span!(parent: foo.id(), Level::TRACE, "baz"))
+        let foo = tracing::span!(Level::TRACE, "foo");
+        tracing::span!(Level::TRACE, "bar")
+            .in_scope(|| tracing::span!(parent: foo.id(), Level::TRACE, "baz"))
     });
 
     handle.assert_finished();
@@ -735,7 +734,7 @@ fn contextual_root() {
         .run_with_handle();
 
     with_default(subscriber, || {
-        span!(Level::TRACE, "foo");
+        tracing::span!(Level::TRACE, "foo");
     });
 
     handle.assert_finished();
@@ -757,8 +756,8 @@ fn contextual_child() {
         .run_with_handle();
 
     with_default(subscriber, || {
-        span!(Level::TRACE, "foo").in_scope(|| {
-            span!(Level::TRACE, "bar");
+        tracing::span!(Level::TRACE, "foo").in_scope(|| {
+            tracing::span!(Level::TRACE, "bar");
         })
     });
 
@@ -779,7 +778,7 @@ fn display_shorthand() {
         .done()
         .run_with_handle();
     with_default(subscriber, || {
-        span!(Level::TRACE, "my_span", my_field = %"hello world");
+        tracing::span!(Level::TRACE, "my_span", my_field = %"hello world");
     });
 
     handle.assert_finished();
@@ -799,7 +798,7 @@ fn debug_shorthand() {
         .done()
         .run_with_handle();
     with_default(subscriber, || {
-        span!(Level::TRACE, "my_span", my_field = ?"hello world");
+        tracing::span!(Level::TRACE, "my_span", my_field = ?"hello world");
     });
 
     handle.assert_finished();
@@ -820,7 +819,7 @@ fn both_shorthands() {
         .done()
         .run_with_handle();
     with_default(subscriber, || {
-        span!(Level::TRACE, "my_span", display_field = %"hello world", debug_field = ?"hello world");
+        tracing::span!(Level::TRACE, "my_span", display_field = %"hello world", debug_field = ?"hello world");
     });
 
     handle.assert_finished();
diff --git a/tracing/tests/subscriber.rs b/tracing/tests/subscriber.rs
index 26e88c1a4c..6da764bea0 100644
--- a/tracing/tests/subscriber.rs
+++ b/tracing/tests/subscriber.rs
@@ -5,9 +5,6 @@
 // The alternative would be for each of these tests to be defined in a separate
 // file, which is :(
 #![cfg(feature = "std")]
-
-#[macro_use]
-extern crate tracing;
 use tracing::{
     field::display,
     span::{Attributes, Id, Record},
@@ -34,7 +31,7 @@ fn event_macros_dont_infinite_loop() {
 
         fn enabled(&self, meta: &Metadata<'_>) -> bool {
             assert!(meta.fields().iter().any(|f| f.name() == "foo"));
-            event!(Level::TRACE, bar = false);
+            tracing::event!(Level::TRACE, bar = false);
             true
         }
 
@@ -48,7 +45,7 @@ fn event_macros_dont_infinite_loop() {
 
         fn event(&self, event: &Event<'_>) {
             assert!(event.metadata().fields().iter().any(|f| f.name() == "foo"));
-            event!(Level::TRACE, baz = false);
+            tracing::event!(Level::TRACE, baz = false);
         }
 
         fn enter(&self, _: &Id) {}
@@ -57,7 +54,7 @@ fn event_macros_dont_infinite_loop() {
     }
 
     with_default(TestSubscriber, || {
-        event!(Level::TRACE, foo = false);
+        tracing::event!(Level::TRACE, foo = false);
     })
 }
 
@@ -81,7 +78,7 @@ fn boxed_subscriber() {
 
     with_default(subscriber, || {
         let from = "my span";
-        let span = span!(
+        let span = tracing::span!(
             Level::TRACE,
             "foo",
             bar = format_args!("hello from {}", from)
@@ -119,7 +116,7 @@ fn arced_subscriber() {
     // Test using a clone of the `Arc`ed subscriber
     with_default(subscriber.clone(), || {
         let from = "my span";
-        let span = span!(
+        let span = tracing::span!(
             Level::TRACE,
             "foo",
             bar = format_args!("hello from {}", from)