itsscb/tracing
1
0
Fork 0
mirror of https://github.com/tokio-rs/tracing.git synced 2025-10-02 15:24:47 +00:00
Code Issues Packages Projects Releases Wiki Activity

fmt: Timestamped log messages (#96)

Browse Source 
Currently there is no good way to get timestamped log entries with the
`tracing-fmt` subscriber. Even with `full`, timestamps are not included.
This is surprising to those coming from other logging crates. It is also
inconvenient to work around, as you would either need to add a custom
field to _all_ spans and events across all your crates, or write your
own subscriber which sort of reduces the usefulness of `fmt`.

This patch introduces a trait for event formatters (`FormatEvent`) so
that it is easier to write more complex formatters (previously they were
just `Fn(...) -> fmt::Result` which would require boxing a closure to
produce). It then implements this new trait for `default::Format`, which
is the new default formatter. It implements "compact"/full formatting
exactly like before, except that is also generic over a timer. The timer
must implement `default::FormatTime`, which has a single method that
writes the current time out to a `fmt::Write`. This method is
implemented for a two new unit structs `SystemTime` and `Uptime`.
`SystemTime` is pretty-printed using `chrono` with the new default
feature `chrono`, and `Debug` of `std::net::SystemTime` is used if the
feature is turned off. `Uptime` prints the fractional number of seconds
since an epoch. Users can also provide `()` as the time formatter to not
produce timestamps in logged entries (accessible through
`default::Format::without_time`).

This patch also switches the default output to the verbose format, with
`compact` offered to return to the compact output format.

Closes #94.
This commit is contained in:
Jon Gjengset 2019-06-26 19:33:56 -04:00 committed by Eliza Weisman
parent 1af521e7e6
commit 7bc97b1abe
No known key found for this signature in database
GPG Key ID: F9C1A595C3814436
12 changed files with 314 additions and 64 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

2
tracing-env-logger/examples/hyper-echo.rs
View File

@ -119,7 +119,7 @@ fn echo(req: Request<Body>) -> Instrumented<BoxFut> {
}
fn main() {
let subscriber = tracing_fmt::FmtSubscriber::builder().full().finish();
let subscriber = tracing_fmt::FmtSubscriber::builder().finish();
tracing_env_logger::try_init().expect("init log adapter");
tracing::subscriber::with_default(subscriber, || {

3
tracing-fmt/Cargo.toml
View File

@ -4,7 +4,7 @@ version = "0.1.0"
authors = ["Eliza Weisman <eliza@buoyant.io>"]
[features]
default = ["ansi"]
default = ["ansi", "chrono"]
ansi = ["ansi_term"]
[dependencies]
@ -14,6 +14,7 @@ lazy_static = "1"
owning_ref = "0.4.0"
parking_lot = { version = "0.7"}
lock_api = "0.1"
chrono = { version = "0.4", optional = true }
[dependencies.tracing-core]
# TODO: replace this with a path dependency on the local `tracing-core`.

2
tracing-fmt/examples/yak_shave.rs
View File

@ -21,7 +21,7 @@ fn shave(yak: usize) -> bool {
}
fn main() {
let subscriber = tracing_fmt::FmtSubscriber::builder().full().finish();
let subscriber = tracing_fmt::FmtSubscriber::builder().finish();
tracing::subscriber::with_default(subscriber, || {
let number_of_yaks = 3;

150
tracing-fmt/src/default.rs
View File

@ -1,53 +1,135 @@
use span;
use time::{self, FormatTime, SystemTime};
use FormatEvent;
use std::fmt::{self, Write};
use std::marker::PhantomData;
use tracing_core::{
field::{self, Field},
Event, Level,
};
use std::fmt::{self, Write};
#[cfg(feature = "ansi")]
use ansi_term::{Colour, Style};
pub fn fmt_event<N>(ctx: &span::Context<N>, f: &mut dyn Write, event: &Event) -> fmt::Result
where
N: for<'a> ::NewVisitor<'a>,
{
let meta = event.metadata();
write!(
f,
"{} {}{}: ",
FmtLevel(meta.level()),
FmtCtx(&ctx),
meta.target()
)?;
{
let mut recorder = ctx.new_visitor(f, true);
event.record(&mut recorder);
}
ctx.with_current(|(_, span)| write!(f, " {}", span.fields()))
.unwrap_or(Ok(()))?;
writeln!(f)
/// Marker for `Format` that indicates that the compact log format should be used.
///
/// The compact format only includes the fields from the most recently entered span.
#[derive(Default, Debug, Copy, Clone, Eq, PartialEq)]
pub struct Compact;
/// Marker for `Format` that indicates that the verbose log format should be used.
///
/// The full format includes fields from all entered spans.
#[derive(Default, Debug, Copy, Clone, Eq, PartialEq)]
pub struct Full;
/// A pre-configured event formatter.
///
/// You will usually want to use this as the `FormatEvent` for a `FmtSubscriber`.
///
/// The default logging format, [`Full`] includes all fields in each event and its containing
/// spans. The [`Compact`] logging format includes only the fields from the most-recently-entered
/// span.
#[derive(Debug, Clone)]
pub struct Format<F = Full, T = SystemTime> {
format: PhantomData<F>,
timer: T,
}
pub fn fmt_verbose<N>(ctx: &span::Context<N>, f: &mut dyn Write, event: &Event) -> fmt::Result
impl<T: Default> Default for Format<Full, T> {
fn default() -> Self {
Format {
format: PhantomData,
timer: T::default(),
}
}
}
impl<F, T> Format<F, T> {
/// Use a less verbose output format.
///
/// See [`Compact`].
pub fn compact(self) -> Format<Compact, T> {
Format {
format: PhantomData,
timer: self.timer,
}
}
/// Use the given `timer` for log message timestamps.
pub fn with_timer<T2>(self, timer: T2) -> Format<F, T2> {
Format {
format: self.format,
timer,
}
}
/// Do not emit timestamps with log messages.
pub fn without_time(self) -> Format<F, ()> {
Format {
format: self.format,
timer: (),
}
}
}
impl<N, T> FormatEvent<N> for Format<Full, T>
where
N: for<'a> ::NewVisitor<'a>,
T: FormatTime,
{
let meta = event.metadata();
write!(
f,
"{} {}{}: ",
FmtLevel(meta.level()),
FullCtx(&ctx),
meta.target()
)?;
{
let mut recorder = ctx.new_visitor(f, true);
event.record(&mut recorder);
fn format_event(
&self,
ctx: &span::Context<N>,
writer: &mut dyn fmt::Write,
event: &Event,
) -> fmt::Result {
let meta = event.metadata();
time::write(&self.timer, writer)?;
write!(
writer,
"{} {}{}: ",
FmtLevel(meta.level()),
FullCtx(&ctx),
meta.target()
)?;
{
let mut recorder = ctx.new_visitor(writer, true);
event.record(&mut recorder);
}
writeln!(writer)
}
}
impl<N, T> FormatEvent<N> for Format<Compact, T>
where
N: for<'a> ::NewVisitor<'a>,
T: FormatTime,
{
fn format_event(
&self,
ctx: &span::Context<N>,
writer: &mut fmt::Write,
event: &Event,
) -> fmt::Result {
let meta = event.metadata();
time::write(&self.timer, writer)?;
write!(
writer,
"{} {}{}: ",
FmtLevel(meta.level()),
FmtCtx(&ctx),
meta.target()
)?;
{
let mut recorder = ctx.new_visitor(writer, true);
event.record(&mut recorder);
}
ctx.with_current(|(_, span)| write!(writer, " {}", span.fields()))
.unwrap_or(Ok(()))?;
writeln!(writer)
}
writeln!(f)
}
pub struct NewRecorder;

6
tracing-fmt/src/filter/reload.rs
View File

@ -164,6 +164,7 @@ mod test {
}
let subscriber = FmtSubscriber::builder()
.compact()
.with_filter(filter1 as fn(&Metadata, &span::Context<_>) -> bool)
.with_filter_reloading();
let handle = subscriber.reload_handle();
@ -192,10 +193,7 @@ mod test {
#[test]
fn reload_from_env() {
use filter::EnvFilter;
let subscriber = FmtSubscriber::builder()
.with_filter_reloading()
.full()
.finish();
let subscriber = FmtSubscriber::builder().with_filter_reloading().finish();
let reload_handle = subscriber.reload_handle();
reload_handle.reload(EnvFilter::from_default_env());
}

89
tracing-fmt/src/lib.rs
View File

@ -5,6 +5,8 @@ extern crate tracing;
#[cfg(feature = "ansi")]
extern crate ansi_term;
#[cfg(feature = "chrono")]
extern crate chrono;
extern crate lock_api;
extern crate owning_ref;
extern crate parking_lot;
@ -20,14 +22,43 @@ use std::{any::TypeId, cell::RefCell, fmt, io};
pub mod default;
pub mod filter;
mod span;
pub mod time;
pub use filter::Filter;
pub use span::Context;
/// A type that can format a tracing `Event` for a `fmt::Write`.
///
/// `FormatEvent` is primarily used in the context of [`FmtSubscriber`]. Each time an event is
/// dispatched to [`FmtSubscriber`], the subscriber forwards it to its associated `FormatEvent` to
/// emit a log message.
///
/// This trait is already implemented for function pointers with the same signature as `format`.
pub trait FormatEvent<N> {
/// Write a log message for `Event` in `Context` to the given `Write`.
fn format_event(
&self,
ctx: &span::Context<N>,
writer: &mut fmt::Write,
event: &Event,
) -> fmt::Result;
}
impl<N> FormatEvent<N> for fn(&span::Context<N>, &mut fmt::Write, &Event) -> fmt::Result {
fn format_event(
&self,
ctx: &span::Context<N>,
writer: &mut fmt::Write,
event: &Event,
) -> fmt::Result {
(*self)(ctx, writer, event)
}
}
#[derive(Debug)]
pub struct FmtSubscriber<
N = default::NewRecorder,
E = fn(&span::Context<N>, &mut dyn fmt::Write, &Event) -> fmt::Result,
E = default::Format<default::Full>,
F = filter::EnvFilter,
> {
new_visitor: N,
@ -40,7 +71,7 @@ pub struct FmtSubscriber<
#[derive(Debug, Default)]
pub struct Builder<
N = default::NewRecorder,
E = fn(&span::Context<N>, &mut dyn fmt::Write, &Event) -> fmt::Result,
E = default::Format<default::Full>,
F = filter::EnvFilter,
> {
new_visitor: N,
@ -94,7 +125,7 @@ where
impl<N, E, F> tracing_core::Subscriber for FmtSubscriber<N, E, F>
where
N: for<'a> NewVisitor<'a> + 'static,
E: Fn(&span::Context<N>, &mut dyn fmt::Write, &Event) -> fmt::Result + 'static,
E: FormatEvent<N> + 'static,
F: Filter<N> + 'static,
{
fn register_callsite(&self, metadata: &Metadata) -> Interest {
@ -141,7 +172,7 @@ where
};
let ctx = span::Context::new(&self.spans, &self.new_visitor);
if (self.fmt_event)(&ctx, buf, event).is_ok() {
if self.fmt_event.format_event(&ctx, buf, event).is_ok() {
// TODO: make the io object configurable
let _ = io::Write::write_all(&mut io::stdout(), buf.as_bytes());
}
@ -207,7 +238,7 @@ impl Default for Builder {
Builder {
filter: filter::EnvFilter::from_default_env(),
new_visitor: default::NewRecorder,
fmt_event: default::fmt_event,
fmt_event: default::Format::default(),
settings: Settings::default(),
}
}
@ -216,7 +247,7 @@ impl Default for Builder {
impl<N, E, F> Builder<N, E, F>
where
N: for<'a> NewVisitor<'a> + 'static,
E: Fn(&span::Context<N>, &mut dyn fmt::Write, &Event) -> fmt::Result + 'static,
E: FormatEvent<N> + 'static,
F: Filter<N> + 'static,
{
pub fn finish(self) -> FmtSubscriber<N, E, F> {
@ -230,6 +261,32 @@ where
}
}
impl<N, L, T, F> Builder<N, default::Format<L, T>, F>
where
N: for<'a> NewVisitor<'a> + 'static,
F: Filter<N> + 'static,
{
/// Use the given `timer` for log message timestamps.
pub fn with_timer<T2>(self, timer: T2) -> Builder<N, default::Format<L, T2>, F> {
Builder {
new_visitor: self.new_visitor,
fmt_event: self.fmt_event.with_timer(timer),
filter: self.filter,
settings: self.settings,
}
}
/// Use the given `timer` for log message timestamps.
pub fn without_time(self) -> Builder<N, default::Format<L, ()>, F> {
Builder {
new_visitor: self.new_visitor,
fmt_event: self.fmt_event.without_time(),
filter: self.filter,
settings: self.settings,
}
}
}
impl<N, E, F> Builder<N, E, F>
where
F: Filter<N> + 'static,
@ -286,16 +343,15 @@ impl<N, E, F> Builder<N, E, F> {
}
}
/// Sets the subscriber being built to use the default full span formatter.
// TODO: this should probably just become the default.
pub fn full(
self,
) -> Builder<N, fn(&span::Context<N>, &mut dyn fmt::Write, &Event) -> fmt::Result, F>
/// Sets the subscriber being built to use a less verbose formatter.
///
/// See [`default::Compact`].
pub fn compact(self) -> Builder<N, default::Format<default::Compact>, F>
where
N: for<'a> NewVisitor<'a> + 'static,
{
Builder {
fmt_event: default::fmt_verbose,
fmt_event: default::Format::default().compact(),
filter: self.filter,
new_visitor: self.new_visitor,
settings: self.settings,
@ -306,7 +362,7 @@ impl<N, E, F> Builder<N, E, F> {
/// events that occur.
pub fn on_event<E2>(self, fmt_event: E2) -> Builder<N, E2, F>
where
E2: Fn(&span::Context<N>, &mut dyn fmt::Write, &Event) -> fmt::Result + 'static,
E2: FormatEvent<N> + 'static,
{
Builder {
new_visitor: self.new_visitor,
@ -329,8 +385,7 @@ impl<N, E, F> Builder<N, E, F> {
#[cfg(test)]
mod test {
use super::*;
use std::fmt;
use tracing_core::Dispatch;
use tracing_core::dispatcher::Dispatch;
#[test]
fn subscriber_downcasts() {
@ -341,12 +396,10 @@ mod test {
#[test]
fn subscriber_downcasts_to_parts() {
type FmtEvent =
fn(&span::Context<default::NewRecorder>, &mut dyn fmt::Write, &Event) -> fmt::Result;
let subscriber = FmtSubscriber::new();
let dispatch = Dispatch::new(subscriber);
assert!(dispatch.downcast_ref::<default::NewRecorder>().is_some());
assert!(dispatch.downcast_ref::<filter::EnvFilter>().is_some());
assert!(dispatch.downcast_ref::<FmtEvent>().is_some())
assert!(dispatch.downcast_ref::<default::Format>().is_some())
}
}

117
tracing-fmt/src/time.rs Normal file
View File

@ -0,0 +1,117 @@
#[cfg(feature = "chrono")]
use chrono;
#[cfg(feature = "ansi")]
use ansi_term::Style;
use std::fmt;
use std::time::Instant;
/// A type that can measure and format the current time.
///
/// This trait is used by `Format` to include a timestamp with each `Event` when it is logged.
///
/// Notable default implementations of this trait are `SystemTime` and `()`. The former prints the
/// current time as reported by `std::time::SystemTime`, and the latter does not print the current
/// time at all. `FormatTime` is also automatically implemented for any function pointer with the
/// appropriate signature.
pub trait FormatTime {
/// Measure and write out the current time.
///
/// When `format_time` is called, implementors should get the current time using their desired
/// mechanism, and write it out to the given `fmt::Write`. Implementors must insert a trailing
/// space themselves if they wish to separate the time from subsequent log message text.
fn format_time(&self, w: &mut fmt::Write) -> fmt::Result;
}
impl<'a, F> FormatTime for &'a F
where
F: FormatTime,
{
fn format_time(&self, w: &mut fmt::Write) -> fmt::Result {
(*self).format_time(w)
}
}
impl FormatTime for () {
fn format_time(&self, _: &mut fmt::Write) -> fmt::Result {
Ok(())
}
}
impl FormatTime for fn(&mut fmt::Write) -> fmt::Result {
fn format_time(&self, w: &mut fmt::Write) -> fmt::Result {
(*self)(w)
}
}
/// Retrieve and print the current wall-clock time.
///
/// If the `chrono` feature is enabled, the current time is printed in a human-readable format like
/// "Jun 25 14:27:12.955". Otherwise the `Debug` implementation of `std::time::SystemTime` is used.
#[derive(Debug, Clone, Copy, Eq, PartialEq, Default)]
pub struct SystemTime;
/// Retrieve and print the relative elapsed wall-clock time since an epoch.
///
/// The `Default` implementation for `Uptime` makes the epoch the current time.
#[derive(Debug, Clone, Copy, Eq, PartialEq)]
pub struct Uptime {
epoch: Instant,
}
impl Default for Uptime {
fn default() -> Self {
Uptime {
epoch: Instant::now(),
}
}
}
impl From<Instant> for Uptime {
fn from(epoch: Instant) -> Self {
Uptime { epoch }
}
}
#[cfg(feature = "chrono")]
impl FormatTime for SystemTime {
fn format_time(&self, w: &mut fmt::Write) -> fmt::Result {
write!(w, "{} ", chrono::Local::now().format("%b %d %H:%M:%S%.3f"))
}
}
#[cfg(not(feature = "chrono"))]
impl FormatTime for SystemTime {
fn format_time(&self, w: &mut fmt::Write) -> fmt::Result {
write!(w, "{:?} ", std::time::SystemTime::now())
}
}
impl FormatTime for Uptime {
fn format_time(&self, w: &mut fmt::Write) -> fmt::Result {
let e = self.epoch.elapsed();
write!(w, "{:4}.{:09}s ", e.as_secs(), e.subsec_nanos())
}
}
#[inline(always)]
#[cfg(feature = "ansi")]
pub(crate) fn write<T>(timer: T, writer: &mut fmt::Write) -> fmt::Result
where
T: FormatTime,
{
let style = Style::new().dimmed();
write!(writer, "{}", style.prefix())?;
timer.format_time(writer)?;
write!(writer, "{}", style.suffix())?;
Ok(())
}
#[inline(always)]
#[cfg(not(feature = "ansi"))]
pub(crate) fn write<T>(timer: T, writer: &mut fmt::Write) -> fmt::Result
where
T: FormatTime,
{
timer.format_time(writer)
}

2
tracing-futures/examples/proxy_server.rs
View File

@ -113,7 +113,7 @@ fn main() -> Result<(), Box<dyn std::error::Error>> {
Ok(())
});
let subscriber = tracing_fmt::FmtSubscriber::builder().full().finish();
let subscriber = tracing_fmt::FmtSubscriber::builder().finish();
tracing::subscriber::with_default(subscriber, || {
let done = done.instrument(span!(
Level::TRACE,

2
tracing-futures/examples/spawny-thing.rs
View File

@ -37,7 +37,7 @@ fn subtask(number: usize) -> impl Future<Item = usize, Error = ()> {
}
fn main() {
let subscriber = tracing_fmt::FmtSubscriber::builder().full().finish();
let subscriber = tracing_fmt::FmtSubscriber::builder().finish();
tracing::subscriber::with_default(subscriber, || {
tokio::run(parent_task(10));
});

2
tracing-proc-macros/examples/args.rs
View File

@ -30,7 +30,7 @@ fn fibonacci_seq(to: u64) -> Vec<u64> {
fn main() {
env_logger::Builder::new().parse("trace").init();
let subscriber = tracing_fmt::FmtSubscriber::builder().full().finish();
let subscriber = tracing_fmt::FmtSubscriber::builder().finish();
tracing::subscriber::with_default(subscriber, || {
let n: u64 = 5;

2
tracing-proc-macros/examples/basic.rs
View File

@ -9,7 +9,7 @@ use tracing::{field, Level};
fn main() {
env_logger::Builder::new().parse("trace").init();
let subscriber = tracing_fmt::FmtSubscriber::builder().full().finish();
let subscriber = tracing_fmt::FmtSubscriber::builder().finish();
tracing::subscriber::with_default(subscriber, || {
let num: u64 = 1;

1
tracing-tower-http/examples/tower-h2-server.rs
View File

@ -112,7 +112,6 @@ fn main() {
.with_filter(tracing_fmt::filter::EnvFilter::from(
"tower_h2_server=trace",
))
.full()
.finish();
tracing::subscriber::with_default(subscriber, || {