From eeaa1b8ba32d8a005eadbde5b20d35e139b72d92 Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Thu, 7 Feb 2019 11:22:39 -0800 Subject: [PATCH 1/7] Update tokio-trace-futures to work with latest tokio-trace --- tokio-trace-futures/src/test_support/event.rs | 92 +++++++ tokio-trace-futures/src/test_support/field.rs | 224 ++++++++++++++++++ .../src/test_support/metadata.rs | 64 +++++ tokio-trace-futures/src/test_support/mod.rs | 3 + tokio-trace-futures/src/test_support/span.rs | 91 ++++++- .../src/test_support/subscriber.rs | 164 ++++++++----- 6 files changed, 568 insertions(+), 70 deletions(-) create mode 100644 tokio-trace-futures/src/test_support/event.rs create mode 100644 tokio-trace-futures/src/test_support/field.rs create mode 100644 tokio-trace-futures/src/test_support/metadata.rs diff --git a/tokio-trace-futures/src/test_support/event.rs b/tokio-trace-futures/src/test_support/event.rs new file mode 100644 index 0000000000..cd58d76492 --- /dev/null +++ b/tokio-trace-futures/src/test_support/event.rs @@ -0,0 +1,92 @@ +#![allow(missing_docs)] +use super::{field, metadata}; + +use std::fmt; + +/// A mock event. +/// +/// This is intended for use with the mock subscriber API in the +/// `subscriber` module. +#[derive(Debug, Default, Eq, PartialEq)] +pub struct MockEvent { + pub fields: Option, + metadata: metadata::Expect, +} + +pub fn mock() -> MockEvent { + MockEvent { + ..Default::default() + } +} + +impl MockEvent { + pub fn named(self, name: I) -> Self + where + I: Into, + { + Self { + metadata: metadata::Expect { + name: Some(name.into()), + ..self.metadata + }, + ..self + } + } + + pub fn with_fields(self, fields: I) -> Self + where + I: Into, + { + Self { + fields: Some(fields.into()), + ..self + } + } + + pub fn at_level(self, level: tokio_trace::Level) -> Self { + Self { + metadata: metadata::Expect { + level: Some(level), + ..self.metadata + }, + ..self + } + } + + pub fn with_target(self, target: I) -> Self + where + I: Into, + { + Self { + metadata: metadata::Expect { + target: Some(target.into()), + ..self.metadata + }, + ..self + } + } + + pub(in test_support) fn check(self, event: &tokio_trace::Event) { + let meta = event.metadata(); + let name = meta.name(); + self.metadata.check(meta, format_args!("event {}", name)); + if let Some(mut expected_fields) = self.fields { + let mut checker = expected_fields.checker(format!("{}", name)); + event.record(&mut checker); + checker.finish(); + } + } +} + +impl fmt::Display for MockEvent { + fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result { + write!(f, "an event")?; + if let Some(ref name) = self.metadata.name { + write!(f, " named {:?}", name)?; + } + if let Some(ref fields) = self.fields { + write!(f, " with {}", fields)? + } + Ok(()) + } +} diff --git a/tokio-trace-futures/src/test_support/field.rs b/tokio-trace-futures/src/test_support/field.rs new file mode 100644 index 0000000000..578452b0b9 --- /dev/null +++ b/tokio-trace-futures/src/test_support/field.rs @@ -0,0 +1,224 @@ +use tokio_trace::{ + callsite::Callsite, + field::{self, Field, Record, Value}, +}; + +use std::{collections::HashMap, fmt}; + +#[derive(Default, Debug, Eq, PartialEq)] +pub struct Expect { + fields: HashMap, + only: bool, +} + +#[derive(Debug)] +pub struct MockField { + name: String, + value: MockValue, +} + +#[derive(Debug, Eq, PartialEq)] +pub enum MockValue { + I64(i64), + U64(u64), + Bool(bool), + Str(String), + Debug(String), + Any, +} + +pub fn mock(name: K) -> MockField +where + String: From, +{ + MockField { + name: name.into(), + value: MockValue::Any, + } +} + +impl MockField { + /// Expect a field with the given name and value. + pub fn with_value(self, value: &Value) -> Self { + Self { + value: MockValue::from(value), + ..self + } + } + + pub fn and(self, other: MockField) -> Expect { + Expect { + fields: HashMap::new(), + only: false, + } + .and(self) + .and(other) + } + + pub fn only(self) -> Expect { + Expect { + fields: HashMap::new(), + only: true, + } + .and(self) + } +} + +impl Into for MockField { + fn into(self) -> Expect { + Expect { + fields: HashMap::new(), + only: false, + } + .and(self) + } +} + +impl Expect { + pub fn and(mut self, field: MockField) -> Self { + self.fields.insert(field.name, field.value); + self + } + + /// Indicates that no fields other than those specified should be expected. + pub fn only(self) -> Self { + Self { only: true, ..self } + } + + fn compare_or_panic(&mut self, name: &str, value: &Value, ctx: &str) { + let value = value.into(); + match self.fields.remove(name) { + Some(MockValue::Any) => {} + Some(expected) => assert!( + expected == value, + "\nexpected `{}` to contain:\n\t`{}{}`\nbut got:\n\t`{}{}`", + ctx, + name, + expected, + name, + value + ), + None if self.only => panic!( + "\nexpected `{}` to contain only:\n\t`{}`\nbut got:\n\t`{}{}`", + ctx, self, name, value + ), + _ => {} + } + } + + pub fn checker<'a>(&'a mut self, ctx: String) -> CheckRecorder<'a> { + CheckRecorder { expect: self, ctx } + } + + pub fn is_empty(&self) -> bool { + self.fields.is_empty() + } +} + +impl fmt::Display for MockValue { + fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result { + match self { + MockValue::I64(v) => write!(f, ": i64 = {:?}", v), + MockValue::U64(v) => write!(f, ": u64 = {:?}", v), + MockValue::Bool(v) => write!(f, ": bool = {:?}", v), + MockValue::Str(v) => write!(f, ": &str = {:?}", v), + MockValue::Debug(v) => write!(f, ": &fmt::Debug = {:?}", v), + MockValue::Any => write!(f, ": _ = _"), + } + } +} + +pub struct CheckRecorder<'a> { + expect: &'a mut Expect, + ctx: String, +} + +impl<'a> Record for CheckRecorder<'a> { + fn record_i64(&mut self, field: &Field, value: i64) { + self.expect + .compare_or_panic(field.name(), &value, &self.ctx[..]) + } + + fn record_u64(&mut self, field: &Field, value: u64) { + self.expect + .compare_or_panic(field.name(), &value, &self.ctx[..]) + } + + fn record_bool(&mut self, field: &Field, value: bool) { + self.expect + .compare_or_panic(field.name(), &value, &self.ctx[..]) + } + + fn record_str(&mut self, field: &Field, value: &str) { + self.expect + .compare_or_panic(field.name(), &value, &self.ctx[..]) + } + + fn record_debug(&mut self, field: &Field, value: &fmt::Debug) { + self.expect + .compare_or_panic(field.name(), &field::debug(value), &self.ctx) + } +} + +impl<'a> CheckRecorder<'a> { + pub fn finish(self) { + assert!( + self.expect.fields.is_empty(), + "{}missing {}", + self.expect, + self.ctx + ); + } +} + +impl<'a> From<&'a Value> for MockValue { + fn from(value: &'a Value) -> Self { + struct MockValueBuilder { + value: Option, + } + + impl Record for MockValueBuilder { + fn record_i64(&mut self, _: &Field, value: i64) { + self.value = Some(MockValue::I64(value)); + } + + fn record_u64(&mut self, _: &Field, value: u64) { + self.value = Some(MockValue::U64(value)); + } + + fn record_bool(&mut self, _: &Field, value: bool) { + self.value = Some(MockValue::Bool(value)); + } + + fn record_str(&mut self, _: &Field, value: &str) { + self.value = Some(MockValue::Str(value.to_owned())); + } + + fn record_debug(&mut self, _: &Field, value: &fmt::Debug) { + self.value = Some(MockValue::Debug(format!("{:?}", value))); + } + } + + let fake_field = callsite!(name: "fake", fields: fake_field) + .metadata() + .fields() + .field("fake_field") + .unwrap(); + let mut builder = MockValueBuilder { value: None }; + value.record(&fake_field, &mut builder); + builder + .value + .expect("finish called before a value was recorded") + } +} + +impl fmt::Display for Expect { + fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result { + write!(f, "fields ")?; + let entries = self + .fields + .iter() + .map(|(k, v)| (field::display(k), field::display(v))); + f.debug_map().entries(entries).finish() + } +} diff --git a/tokio-trace-futures/src/test_support/metadata.rs b/tokio-trace-futures/src/test_support/metadata.rs new file mode 100644 index 0000000000..a8f57f2878 --- /dev/null +++ b/tokio-trace-futures/src/test_support/metadata.rs @@ -0,0 +1,64 @@ +use std::fmt; +use tokio_trace::Metadata; + +#[derive(Debug, Eq, PartialEq, Default)] +pub struct Expect { + pub name: Option, + pub level: Option, + pub target: Option, +} + +impl Expect { + pub(in test_support) fn check(&self, actual: &Metadata, ctx: fmt::Arguments) { + if let Some(ref expected_name) = self.name { + let name = actual.name(); + assert!( + expected_name == name, + "expected {} to be named `{}`, but got one named `{}`", + ctx, + expected_name, + name + ) + } + + if let Some(ref expected_level) = self.level { + let level = actual.level(); + assert!( + expected_level == level, + "expected {} to be at level `{:?}`, but it was at level `{:?}` instead", + ctx, + expected_level, + level, + ) + } + + if let Some(ref expected_target) = self.target { + let target = actual.target(); + assert!( + expected_target == &target, + "expected {} to have target `{}`, but it had target `{}` instead", + ctx, + expected_target, + target, + ) + } + } +} + +impl fmt::Display for Expect { + fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result { + if let Some(ref name) = self.name { + write!(f, "named `{}`", name)?; + } + + if let Some(ref level) = self.level { + write!(f, " at the `{:?}` level", level)?; + } + + if let Some(ref target) = self.target { + write!(f, " with target `{}`", target)?; + } + + Ok(()) + } +} diff --git a/tokio-trace-futures/src/test_support/mod.rs b/tokio-trace-futures/src/test_support/mod.rs index 919f6af49a..b8f78cc7a2 100644 --- a/tokio-trace-futures/src/test_support/mod.rs +++ b/tokio-trace-futures/src/test_support/mod.rs @@ -1,3 +1,6 @@ #![allow(dead_code)] +pub mod event; +pub mod field; +mod metadata; pub mod span; pub mod subscriber; diff --git a/tokio-trace-futures/src/test_support/span.rs b/tokio-trace-futures/src/test_support/span.rs index f72e59f12d..b2606693ca 100644 --- a/tokio-trace-futures/src/test_support/span.rs +++ b/tokio-trace-futures/src/test_support/span.rs @@ -1,4 +1,5 @@ #![allow(missing_docs)] +use super::{field, metadata}; use std::fmt; /// A mock span. @@ -7,8 +8,13 @@ use std::fmt; /// `subscriber` module. #[derive(Debug, Default, Eq, PartialEq)] pub struct MockSpan { - pub name: Option<&'static str>, - // TODO: more + pub(in test_support) metadata: metadata::Expect, +} + +#[derive(Debug, Default, Eq, PartialEq)] +pub struct NewSpan { + pub(in test_support) span: MockSpan, + pub(in test_support) fields: field::Expect, } pub fn mock() -> MockSpan { @@ -18,19 +24,86 @@ pub fn mock() -> MockSpan { } impl MockSpan { - pub fn named(mut self, name: &'static str) -> Self { - self.name = Some(name); - self + pub fn named(self, name: I) -> Self + where + I: Into, + { + Self { + metadata: metadata::Expect { + name: Some(name.into()), + ..self.metadata + }, + ..self + } + } + + pub fn at_level(self, level: tokio_trace::Level) -> Self { + Self { + metadata: metadata::Expect { + level: Some(level), + ..self.metadata + }, + ..self + } } - // TODO: fields, etc + pub fn with_target(self, target: I) -> Self + where + I: Into, + { + Self { + metadata: metadata::Expect { + target: Some(target.into()), + ..self.metadata + }, + ..self + } + } + + pub fn name(&self) -> Option<&str> { + self.metadata.name.as_ref().map(String::as_ref) + } + + pub fn with_field(self, fields: I) -> NewSpan + where + I: Into, + { + NewSpan { + span: self, + fields: fields.into(), + } + } + + pub(in test_support) fn check_metadata(&self, actual: &tokio_trace::Metadata) { + self.metadata.check(actual, format_args!("span {}", self)) + } } impl fmt::Display for MockSpan { fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result { - match self.name { - Some(name) => write!(f, "a span named {:?}", name), - None => write!(f, "any span"), + if self.metadata.name.is_some() { + write!(f, "a span{}", self.metadata) + } else { + write!(f, "any span{}", self.metadata) + } + } +} + +impl Into for MockSpan { + fn into(self) -> NewSpan { + NewSpan { + span: self, + ..Default::default() + } + } +} + +impl fmt::Display for NewSpan { + fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result { + write!(f, "a new span{}", self.span.metadata)?; + if !self.fields.is_empty() { + write!(f, " with {}", self.fields)?; } + Ok(()) } } diff --git a/tokio-trace-futures/src/test_support/subscriber.rs b/tokio-trace-futures/src/test_support/subscriber.rs index 3b4c10b69a..662e0cc397 100644 --- a/tokio-trace-futures/src/test_support/subscriber.rs +++ b/tokio-trace-futures/src/test_support/subscriber.rs @@ -1,5 +1,9 @@ #![allow(missing_docs)] -use super::span::MockSpan; +use super::{ + event::MockEvent, + field as mock_field, + span::{MockSpan, NewSpan}, +}; use std::{ collections::{HashMap, VecDeque}, fmt, @@ -8,21 +12,17 @@ use std::{ Arc, Mutex, }, }; -use tokio_trace::{field, Id, Metadata, Subscriber}; - -#[derive(Debug, Eq, PartialEq)] -struct ExpectEvent { - // TODO: implement -} +use tokio_trace::{field, Event, Id, Metadata, Subscriber}; #[derive(Debug, Eq, PartialEq)] enum Expect { - #[allow(dead_code)] // TODO: implement! - Event(ExpectEvent), + Event(MockEvent), Enter(MockSpan), Exit(MockSpan), CloneSpan(MockSpan), DropSpan(MockSpan), + Record(MockSpan, mock_field::Expect), + NewSpan(NewSpan), Nothing, } @@ -58,9 +58,8 @@ impl bool> MockSubscriber { self } - pub fn event(mut self) -> Self { - // TODO: expect message/fields! - self.expected.push_back(Expect::Event(ExpectEvent {})); + pub fn event(mut self, event: MockEvent) -> Self { + self.expected.push_back(Expect::Event(event)); self } @@ -84,6 +83,22 @@ impl bool> MockSubscriber { self } + pub fn record(mut self, span: MockSpan, fields: I) -> Self + where + I: Into, + { + self.expected.push_back(Expect::Record(span, fields.into())); + self + } + + pub fn new_span(mut self, new_span: I) -> Self + where + I: Into, + { + self.expected.push_back(Expect::NewSpan(new_span.into())); + self + } + pub fn with_filter(self, filter: G) -> MockSubscriber where G: Fn(&Metadata) -> bool, @@ -117,15 +132,47 @@ impl bool> Subscriber for Running { (self.filter)(meta) } - fn record_debug(&self, _span: &Id, _field: &field::Field, _value: &fmt::Debug) { - // TODO: it would be nice to be able to expect field values... + fn record(&self, id: &Id, values: &field::ValueSet) { + let spans = self.spans.lock().unwrap(); + let mut expected = self.expected.lock().unwrap(); + let span = spans + .get(id) + .unwrap_or_else(|| panic!("no span for ID {:?}", id)); + println!("record: {}; id={:?}; values={:?};", span.name, id, values); + let was_expected = if let Some(Expect::Record(_, _)) = expected.front() { + true + } else { + false + }; + if was_expected { + if let Expect::Record(expected_span, mut expected_values) = + expected.pop_front().unwrap() + { + if let Some(name) = expected_span.name() { + assert_eq!(name, span.name); + } + let mut checker = expected_values.checker(format!("span {}: ", span.name)); + values.record(&mut checker); + checker.finish(); + } + } } - fn add_follows_from(&self, _span: &Id, _follows: Id) { + fn event(&self, event: &Event) { + let name = event.metadata().name(); + println!("event: {};", name); + match self.expected.lock().unwrap().pop_front() { + None => {} + Some(Expect::Event(expected)) => expected.check(event), + Some(ex) => ex.bad(format_args!("observed event {:?}", event)), + } + } + + fn record_follows_from(&self, _span: &Id, _follows: &Id) { // TODO: it should be possible to expect spans to follow from other spans } - fn new_span(&self, meta: &Metadata) -> Id { + fn new_span(&self, meta: &Metadata, values: &field::ValueSet) -> Id { let id = self.ids.fetch_add(1, Ordering::SeqCst); let id = Id::from_u64(id as u64); println!( @@ -134,6 +181,23 @@ impl bool> Subscriber for Running { meta.target(), id ); + let mut expected = self.expected.lock().unwrap(); + let was_expected = match expected.front() { + Some(Expect::NewSpan(_)) => true, + _ => false, + }; + if was_expected { + if let Expect::NewSpan(mut expected) = expected.pop_front().unwrap() { + let name = meta.name(); + expected + .span + .metadata + .check(meta, format_args!("span `{}`", name)); + let mut checker = expected.fields.checker(format!("{}", name)); + values.record(&mut checker); + checker.finish(); + } + } self.spans.lock().unwrap().insert( id.clone(), SpanState { @@ -150,32 +214,12 @@ impl bool> Subscriber for Running { println!("enter: {}; id={:?};", span.name, id); match self.expected.lock().unwrap().pop_front() { None => {} - Some(Expect::Event(_)) => panic!( - "expected an event, but entered span {:?} instead", - span.name - ), Some(Expect::Enter(ref expected_span)) => { - if let Some(name) = expected_span.name { + if let Some(name) = expected_span.name() { assert_eq!(name, span.name); } - // TODO: expect fields } - Some(Expect::Exit(ref expected_span)) => panic!( - "expected to exit {}, but entered span {:?} instead", - expected_span, span.name - ), - Some(Expect::CloneSpan(ref expected_span)) => panic!( - "expected to clone {}, but entered span {:?} instead", - expected_span, span.name - ), - Some(Expect::DropSpan(ref expected_span)) => panic!( - "expected to drop {}, but entered span {:?} instead", - expected_span, span.name - ), - Some(Expect::Nothing) => panic!( - "expected nothing else to happen, but entered span {:?}", - span.name, - ), + Some(ex) => ex.bad(format_args!("entered span {:?}", span.name)), } }; } @@ -188,31 +232,12 @@ impl bool> Subscriber for Running { println!("exit: {}; id={:?};", span.name, id); match self.expected.lock().unwrap().pop_front() { None => {} - Some(Expect::Event(_)) => { - panic!("expected an event, but exited span {:?} instead", span.name) - } - Some(Expect::Enter(ref expected_span)) => panic!( - "expected to enter {}, but exited span {:?} instead", - expected_span, span.name - ), Some(Expect::Exit(ref expected_span)) => { - if let Some(name) = expected_span.name { + if let Some(name) = expected_span.name() { assert_eq!(name, span.name); } - // TODO: expect fields } - Some(Expect::CloneSpan(ref expected_span)) => panic!( - "expected to clone {}, but exited span {:?} instead", - expected_span, span.name - ), - Some(Expect::DropSpan(ref expected_span)) => panic!( - "expected to drop {}, but exited span {:?} instead", - expected_span, span.name - ), - Some(Expect::Nothing) => panic!( - "expected nothing else to happen, but exited span {:?}", - span.name, - ), + Some(ex) => ex.bad(format_args!("exited span {:?}", span.name)), }; } @@ -228,7 +253,7 @@ impl bool> Subscriber for Running { } let mut expected = self.expected.lock().unwrap(); let was_expected = if let Some(Expect::CloneSpan(ref span)) = expected.front() { - assert_eq!(name, span.name); + assert_eq!(name, span.name()); true } else { false @@ -263,7 +288,7 @@ impl bool> Subscriber for Running { // Don't assert if this function was called while panicking, // as failing the assertion can cause a double panic. if !::std::thread::panicking() { - assert_eq!(name, span.name); + assert_eq!(name, span.name()); } true } @@ -293,3 +318,20 @@ impl MockHandle { } } } + +impl Expect { + fn bad<'a>(&self, what: fmt::Arguments<'a>) { + match self { + Expect::Event(e) => panic!("expected event {}, but {} instead", e, what,), + Expect::Enter(e) => panic!("expected to enter {} but {} instead", e, what,), + Expect::Exit(e) => panic!("expected to exit {} but {} instead", e, what,), + Expect::CloneSpan(e) => panic!("expected to clone {} but {} instead", e, what,), + Expect::DropSpan(e) => panic!("expected to drop {} but {} instead", e, what,), + Expect::Record(e, fields) => { + panic!("expected {} to record {} but {} instead", e, fields, what,) + } + Expect::NewSpan(e) => panic!("expected {} but {} instead", e, what), + Expect::Nothing => panic!("expected nothing else to happen, but {} instead", what,), + } + } +} From a1c0bbfe807643ce96c50cc1731832d3c76eb094 Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Thu, 7 Feb 2019 11:23:28 -0800 Subject: [PATCH 2/7] Update tokio-trace-subscriber to compile with latest tokio-trace It still needs some work to actually *work* correctly, but the whole subscriber crate needs to be rewritten. Now it won't break the build anymore. Signed-off-by: Eliza Weisman --- tokio-trace-subscriber/src/compose.rs | 13 ++++++++----- tokio-trace-subscriber/src/registry.rs | 4 ++-- 2 files changed, 10 insertions(+), 7 deletions(-) diff --git a/tokio-trace-subscriber/src/compose.rs b/tokio-trace-subscriber/src/compose.rs index d439094034..b2ed7cbb6a 100644 --- a/tokio-trace-subscriber/src/compose.rs +++ b/tokio-trace-subscriber/src/compose.rs @@ -1,5 +1,4 @@ -use std::fmt; -use tokio_trace::{field, subscriber::Subscriber, Id, Metadata}; +use tokio_trace::{field, subscriber::Subscriber, Id, Metadata, Event}; use {filter::NoFilter, observe::NoObserver, Filter, Observe, RegisterSpan}; #[derive(Debug, Clone)] @@ -95,18 +94,22 @@ where self.filter.enabled(metadata) && self.observer.filter().enabled(metadata) } - fn new_span(&self, meta: &Metadata) -> Id { + fn new_span(&self, meta: &Metadata, _values: &field::ValueSet) -> Id { self.registry.new_id(meta) } - fn record_debug(&self, _span: &Id, _name: &field::Field, _value: &fmt::Debug) { + fn record(&self, _span: &Id, _values: &field::ValueSet) { unimplemented!() } - fn add_follows_from(&self, span: &Id, follows: Id) { + fn record_follows_from(&self, span: &Id, follows: &Id) { self.registry.add_follows_from(span, follows) } + fn event(&self, _event: &Event) { + unimplemented!() + } + fn enter(&self, id: &Id) { self.registry.with_span(id, |span| { self.observer.enter(span); diff --git a/tokio-trace-subscriber/src/registry.rs b/tokio-trace-subscriber/src/registry.rs index 6fce5f97b5..03b106f489 100644 --- a/tokio-trace-subscriber/src/registry.rs +++ b/tokio-trace-subscriber/src/registry.rs @@ -58,7 +58,7 @@ pub trait RegisterSpan { /// registry knows about, or if a cyclical relationship would be created /// (i.e., some span _a_ which proceeds some other span _b_ may not also /// follow from _b_), it should do nothing. - fn add_follows_from(&self, span: &Id, follows: Id); + fn add_follows_from(&self, span: &Id, follows: &Id); /// Queries the registry for an iterator over the IDs of the spans that /// `span` follows from. @@ -181,7 +181,7 @@ impl RegisterSpan for IncreasingCounter { id } - fn add_follows_from(&self, _span: &Id, _follows: Id) { + fn add_follows_from(&self, _span: &Id, _follows: &Id) { // unimplemented } From c343fbd18ed647abe9ab43c120bcabd950d2264e Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Thu, 7 Feb 2019 11:36:32 -0800 Subject: [PATCH 3/7] Update tokio-trace-log to work with latest tokio-trace Signed-off-by: Eliza Weisman --- tokio-trace-log/src/lib.rs | 168 ++++++++++++++++++++++--------------- 1 file changed, 99 insertions(+), 69 deletions(-) diff --git a/tokio-trace-log/src/lib.rs b/tokio-trace-log/src/lib.rs index 50ee41567e..af42cd765b 100644 --- a/tokio-trace-log/src/lib.rs +++ b/tokio-trace-log/src/lib.rs @@ -37,18 +37,19 @@ use tokio_trace::{ callsite::{self, Callsite}, field, subscriber::{self, Subscriber}, - Id, Metadata, + Event, Id, Metadata, }; /// Format a log record as a trace event in the current span. pub fn format_trace(record: &log::Record) -> io::Result<()> { let meta = record.as_trace(); - let k = meta.fields().field(&"message").unwrap(); - let mut event = tokio_trace::Event::new(subscriber::Interest::sometimes(), &meta); - if !event.is_disabled() { - event.message(&k, record.args().clone()); - } - drop(event); + let fields = meta.fields(); + let key = fields.field(&"message") + .expect("log record fields must have a message"); + Event::observe( + &meta, + &fields.value_set(&[(&key, Some(record.args() as &field::Value))]) + ); Ok(()) } @@ -148,7 +149,7 @@ pub struct LogTracer { #[derive(Default)] pub struct TraceLogger { settings: TraceLoggerBuilder, - in_progress: Mutex>, + spans: Mutex>, current: tokio_trace_subscriber::CurrentSpanPerThread, } @@ -248,15 +249,13 @@ impl TraceLoggerBuilder { struct SpanLineBuilder { parent: Option, ref_count: usize, - log_line: String, fields: String, file: Option, line: Option, module_path: Option, target: String, level: log::Level, - name: String, - log_finish: bool, + name: &'static str, } impl SpanLineBuilder { @@ -264,42 +263,20 @@ impl SpanLineBuilder { parent: Option, meta: &Metadata, fields: String, - id: Id, - settings: &TraceLoggerBuilder, ) -> Self { - let mut log_line = String::new(); - let name = meta.name(); - let log_finish = if !name.contains("event") { - write!(&mut log_line, "close {}; ", name).expect("write to string shouldn't fail"); - settings.log_span_closes - } else { - true - }; - if settings.log_ids { - write!(&mut log_line, "id={:?}; ", id).expect("write to string shouldn't fail"); - } Self { parent, ref_count: 1, - log_line, fields, file: meta.file().map(String::from), line: meta.line(), module_path: meta.module_path().map(String::from), target: String::from(meta.target()), level: meta.level().as_log(), - name: String::from(name), - log_finish, + name: meta.name(), } } - fn record(&mut self, key: &field::Field, value: &fmt::Debug) -> fmt::Result { - if key.name() == "message" { - write!(&mut self.log_line, "{:?} ", value) - } else { - write!(&mut self.fields, "{}={:?}; ", key.name(), value) - } - } fn log_meta(&self) -> log::Metadata { log::MetadataBuilder::new() .level(self.level) @@ -307,14 +284,10 @@ impl SpanLineBuilder { .build() } - fn finish(self, current_span: &str) { - if !self.log_finish { - return; - } + fn finish(self) { let log_meta = self.log_meta(); let logger = log::logger(); if logger.enabled(&log_meta) { - let before_current = if current_span != "" { "; " } else { "" }; logger.log( &log::Record::builder() .metadata(log_meta) @@ -322,49 +295,51 @@ impl SpanLineBuilder { .module_path(self.module_path.as_ref().map(String::as_ref)) .file(self.file.as_ref().map(String::as_ref)) .line(self.line) - .args(format_args!( - "{}{}{}{}", - self.log_line, before_current, current_span, self.fields - )) + .args(format_args!("close {}; {}", self.name, self.fields)) .build(), ); } } } +impl field::Record for SpanLineBuilder { + fn record_debug(&mut self, field: &field::Field, value: &fmt::Debug) { + write!(self.fields, " {}={:?};", field.name(), value) + .expect("write to string should never fail") + } +} + impl Subscriber for TraceLogger { fn enabled(&self, metadata: &Metadata) -> bool { log::logger().enabled(&metadata.as_log()) } - fn new_span(&self, new_span: &Metadata) -> Id { + fn new_span(&self, meta: &Metadata, values: &field::ValueSet) -> Id { let id = self.next_id(); - let mut in_progress = self.in_progress.lock().unwrap(); + let mut spans = self.spans.lock().unwrap(); let mut fields = String::new(); let parent = self.current.id(); if self.settings.parent_fields { let mut next_parent = parent.as_ref(); - while let Some(ref parent) = next_parent.and_then(|p| in_progress.get(&p)) { + while let Some(ref parent) = next_parent.and_then(|p| spans.get(&p)) { write!(&mut fields, "{}", parent.fields).expect("write to string cannot fail"); next_parent = parent.parent.as_ref(); } } - let span = SpanLineBuilder::new(parent, new_span, fields, id.clone(), &self.settings); - in_progress.insert(id.clone(), span); + let mut span = SpanLineBuilder::new(parent, meta, fields); + values.record(&mut span); + spans.insert(id.clone(), span); id } - fn record_debug(&self, span: &Id, key: &field::Field, value: &fmt::Debug) { - let mut in_progress = self.in_progress.lock().unwrap(); - if let Some(span) = in_progress.get_mut(span) { - if let Err(_e) = span.record(key, value) { - eprintln!("error formatting span"); - } - return; + fn record(&self, span: &Id, values: &field::ValueSet) { + let mut spans = self.spans.lock().unwrap(); + if let Some(span) = spans.get_mut(span) { + values.record(span); } } - fn add_follows_from(&self, span: &Id, follows: Id) { + fn record_follows_from(&self, span: &Id, follows: &Id) { // TODO: this should eventually track the relationship? log::logger().log( &log::Record::builder() @@ -376,16 +351,16 @@ impl Subscriber for TraceLogger { fn enter(&self, id: &Id) { self.current.enter(id.clone()); - let in_progress = self.in_progress.lock().unwrap(); + let spans = self.spans.lock().unwrap(); if self.settings.log_enters { - if let Some(span) = in_progress.get(id) { + if let Some(span) = spans.get(id) { let log_meta = span.log_meta(); let logger = log::logger(); if logger.enabled(&log_meta) { let current_id = self.current.id(); let current_fields = current_id .as_ref() - .and_then(|id| in_progress.get(&id)) + .and_then(|id| spans.get(&id)) .map(|span| span.fields.as_ref()) .unwrap_or(""); if self.settings.log_ids { @@ -422,8 +397,8 @@ impl Subscriber for TraceLogger { fn exit(&self, id: &Id) { self.current.exit(); if self.settings.log_exits { - let in_progress = self.in_progress.lock().unwrap(); - if let Some(span) = in_progress.get(id) { + let spans = self.spans.lock().unwrap(); + if let Some(span) = spans.get(id) { let log_meta = span.log_meta(); let logger = log::logger(); if logger.enabled(&log_meta) { @@ -442,28 +417,83 @@ impl Subscriber for TraceLogger { } } + fn event(&self, event: &Event) { + let meta = event.metadata(); + let log_meta = meta.as_log(); + let logger = log::logger(); + if logger.enabled(&log_meta) { + let spans = self.spans.lock().unwrap(); + let current_fields = self.current.id() + .and_then(|id| { + spans.get(&id) + }) + .map(|span| span.fields.as_ref()) + .unwrap_or(""); + logger.log( + &log::Record::builder() + .metadata(log_meta) + .target(meta.target) + .module_path(meta.module_path.as_ref().map(|&p| p)) + .file(meta.file.as_ref().map(|&f| f)) + .line(meta.line) + .args(format_args!("{}{}", LogEvent(event), current_fields)) + .build(), + ); + + } + } + fn clone_span(&self, id: &Id) -> Id { - let mut in_progress = self.in_progress.lock().unwrap(); - if let Some(span) = in_progress.get_mut(id) { + let mut spans = self.spans.lock().unwrap(); + if let Some(span) = spans.get_mut(id) { span.ref_count += 1; } id.clone() } fn drop_span(&self, id: Id) { - let mut in_progress = self.in_progress.lock().unwrap(); - if in_progress.contains_key(&id) { - if in_progress.get(&id).unwrap().ref_count == 1 { - let span = in_progress.remove(&id).unwrap(); - span.finish(""); + + let mut spans = self.spans.lock().unwrap(); + if spans.contains_key(&id) { + if spans.get(&id).unwrap().ref_count == 1 { + let span = spans.remove(&id).unwrap(); + if self.settings.log_span_closes { + span.finish(); + } } else { - in_progress.get_mut(&id).unwrap().ref_count -= 1; + spans.get_mut(&id).unwrap().ref_count -= 1; } return; } } } +struct LogEvent<'a>(&'a Event<'a>); + +impl<'a> fmt::Display for LogEvent<'a> { + fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result { + let mut has_logged = false; + let mut format_fields = |field: &field::Field, value: &fmt::Debug| { + let name = field.name(); + let leading = if has_logged { + " " + } else { + "" + }; + // TODO: handle fmt error? + let _ = if name == "message" { + write!(f, "{}{:?};", leading, value) + } else { + write!(f, "{}{}={:?};", leading, name, value) + }; + has_logged = true; + }; + + self.0.record(&mut format_fields); + Ok(()) + } +} + // impl tokio_trace_subscriber::Observe for TraceLogger { // fn observe_event<'a>(&self, event: &'a Event<'a>) { // ::observe_event(&self, event) From 3dd3d9997389340bcbbdb941470b4842762311a2 Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Thu, 7 Feb 2019 12:04:18 -0800 Subject: [PATCH 4/7] Update tokio-trace-macros to work with latest tokio-trace --- tokio-trace-macros/src/lib.rs | 24 ++++++++---------------- 1 file changed, 8 insertions(+), 16 deletions(-) diff --git a/tokio-trace-macros/src/lib.rs b/tokio-trace-macros/src/lib.rs index f0670430d2..4cff90b565 100644 --- a/tokio-trace-macros/src/lib.rs +++ b/tokio-trace-macros/src/lib.rs @@ -1,4 +1,3 @@ -#[macro_use] extern crate tokio_trace; /// Alias of `dbg!` for avoiding conflicts with the `std::dbg!` macro. @@ -28,30 +27,23 @@ macro_rules! trace_dbg { macro_rules! dbg { (target: $target:expr, level: $level:expr, $ex:expr) => { { - #[allow(unused_imports)] use tokio_trace::{callsite, Id, Subscriber, Event, field::{debug, Value}}; use tokio_trace::callsite::Callsite; - let callsite = callsite! {@ + let callsite = callsite! { name: concat!("event:trace_dbg(", stringify!($ex), ")"), target: $target, level: $level, - fields: &[stringify!($ex)] + fields: $ex }; - let interest = callsite.interest(); let val = $ex; - if interest.is_never() { - val - } else { + if is_enabled!(callsite) { let meta = callsite.metadata(); - let mut event = Event::new(interest, meta); - if !event.is_disabled() { - let key = meta.fields().into_iter().next() - .expect("trace_dbg event must have one field"); - event.record(&key, &debug(val)); - } - drop(event); - val + let fields = meta.fields(); + let key = meta.fields().into_iter().next() + .expect("trace_dbg event must have one field"); + Event::observe(meta, &fields.value_set(&[(&key, Some(&debug(&val) as &Value))])); } + val } }; (level: $level:expr, $ex:expr) => { From ded0e20b7b4278093b4725857989c4b690b5d6c2 Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Thu, 7 Feb 2019 12:05:04 -0800 Subject: [PATCH 5/7] Update examples to work with latest tokio-trace Signed-off-by: Eliza Weisman --- .../examples/hyper-echo/sloggish.rs | 211 ++++++++++-------- 1 file changed, 124 insertions(+), 87 deletions(-) diff --git a/tokio-trace-env-logger/examples/hyper-echo/sloggish.rs b/tokio-trace-env-logger/examples/hyper-echo/sloggish.rs index 7d8247b484..4a93f93533 100644 --- a/tokio-trace-env-logger/examples/hyper-echo/sloggish.rs +++ b/tokio-trace-env-logger/examples/hyper-echo/sloggish.rs @@ -12,12 +12,15 @@ //! [`slog` README]: https://github.com/slog-rs/slog#terminal-output-example extern crate ansi_term; extern crate humantime; -extern crate tokio_trace_subscriber; - use self::ansi_term::{Color, Style}; -use super::tokio_trace::{self, Id, Level, Subscriber}; +use super::tokio_trace::{ + self, + field::{Field, Record}, + Id, Level, Subscriber, +}; use std::{ + cell::RefCell, collections::HashMap, fmt, io::{self, Write}, @@ -25,18 +28,52 @@ use std::{ atomic::{AtomicUsize, Ordering}, Mutex, }, + thread, time::SystemTime, }; +/// Tracks the currently executing span on a per-thread basis. +#[derive(Clone)] +pub struct CurrentSpanPerThread { + current: &'static thread::LocalKey>>, +} + +impl CurrentSpanPerThread { + pub fn new() -> Self { + thread_local! { + static CURRENT: RefCell> = RefCell::new(vec![]); + }; + Self { current: &CURRENT } + } + + /// Returns the [`Id`](::Id) of the span in which the current thread is + /// executing, or `None` if it is not inside of a span. + pub fn id(&self) -> Option { + self.current + .with(|current| current.borrow().last().cloned()) + } + + pub fn enter(&self, span: Id) { + self.current.with(|current| { + current.borrow_mut().push(span); + }) + } + + pub fn exit(&self) { + self.current.with(|current| { + let _ = current.borrow_mut().pop(); + }) + } +} + pub struct SloggishSubscriber { // TODO: this can probably be unified with the "stack" that's used for // printing? - current: tokio_trace_subscriber::CurrentSpanPerThread, + current: CurrentSpanPerThread, indent_amount: usize, stderr: io::Stderr, stack: Mutex>, spans: Mutex>, - events: Mutex>, ids: AtomicUsize, } @@ -45,72 +82,86 @@ struct Span { kvs: Vec<(&'static str, String)>, } -struct Event { - level: tokio_trace::Level, - target: String, - message: String, - kvs: Vec<(&'static str, String)>, +struct Event<'a> { + stderr: io::StderrLock<'a>, + comma: bool, } -struct ColorLevel(Level); +struct ColorLevel<'a>(&'a Level); -impl fmt::Display for ColorLevel { +impl<'a> fmt::Display for ColorLevel<'a> { fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result { match self.0 { - Level::TRACE => Color::Purple.paint("TRACE"), - Level::DEBUG => Color::Blue.paint("DEBUG"), - Level::INFO => Color::Green.paint("INFO"), - Level::WARN => Color::Yellow.paint("WARN "), - Level::ERROR => Color::Red.paint("ERROR"), + &Level::TRACE => Color::Purple.paint("TRACE"), + &Level::DEBUG => Color::Blue.paint("DEBUG"), + &Level::INFO => Color::Green.paint("INFO "), + &Level::WARN => Color::Yellow.paint("WARN "), + &Level::ERROR => Color::Red.paint("ERROR"), } .fmt(f) } } impl Span { - fn new(parent: Option, _meta: &tokio_trace::Metadata) -> Self { - Self { + fn new( + parent: Option, + _meta: &tokio_trace::Metadata, + values: &tokio_trace::field::ValueSet, + ) -> Self { + let mut span = Self { parent, kvs: Vec::new(), - } - } - - fn record(&mut self, key: &tokio_trace::field::Field, value: fmt::Arguments) { - let v = fmt::format(value); - self.kvs.push((key.name(), v)); + }; + values.record(&mut span); + span } } -impl Event { - fn new(meta: &tokio_trace::Metadata) -> Self { - Self { - target: meta.target.to_owned(), - level: meta.level.clone(), - message: String::new(), - kvs: Vec::new(), - } +impl Record for Span { + fn record_debug(&mut self, field: &Field, value: &fmt::Debug) { + self.kvs.push((field.name(), format!("{:?}", value))) } +} - fn record(&mut self, key: &tokio_trace::field::Field, value: fmt::Arguments) { - if key.name() == "message" { - self.message = fmt::format(value); - return; +impl<'a> Record for Event<'a> { + fn record_debug(&mut self, field: &Field, value: &fmt::Debug) { + write!( + &mut self.stderr, + "{comma} ", + comma = if self.comma { "," } else { "" }, + ) + .unwrap(); + let name = field.name(); + if name == "message" { + write!( + &mut self.stderr, + "{}", + // Have to alloc here due to `ansi_term`'s API... + Style::new().bold().paint(format!("{:?}", value)) + ) + .unwrap(); + self.comma = true; + } else { + write!( + &mut self.stderr, + "{}: {:?}", + Style::new().bold().paint(name), + value + ) + .unwrap(); + self.comma = true; } - - let v = fmt::format(value); - self.kvs.push((key.name(), v)); } } impl SloggishSubscriber { pub fn new(indent_amount: usize) -> Self { Self { - current: tokio_trace_subscriber::CurrentSpanPerThread::new(), + current: CurrentSpanPerThread::new(), indent_amount, stderr: io::stderr(), stack: Mutex::new(vec![]), spans: Mutex::new(HashMap::new()), - events: Mutex::new(HashMap::new()), ids: AtomicUsize::new(0), } } @@ -155,39 +206,26 @@ impl Subscriber for SloggishSubscriber { true } - fn new_span(&self, span: &tokio_trace::Metadata) -> tokio_trace::Id { + fn new_span( + &self, + span: &tokio_trace::Metadata, + values: &tokio_trace::field::ValueSet, + ) -> tokio_trace::Id { let next = self.ids.fetch_add(1, Ordering::SeqCst) as u64; let id = tokio_trace::Id::from_u64(next); - if span.name.contains("event") { - self.events - .lock() - .unwrap() - .insert(id.clone(), Event::new(span)); - } else { - self.spans - .lock() - .unwrap() - .insert(id.clone(), Span::new(self.current.id(), span)); - } + let span = Span::new(self.current.id(), span, values); + self.spans.lock().unwrap().insert(id.clone(), span); id } - fn record_debug( - &self, - span: &tokio_trace::Id, - name: &tokio_trace::field::Field, - value: &fmt::Debug, - ) { - if let Some(event) = self.events.lock().expect("mutex poisoned!").get_mut(span) { - return event.record(name, format_args!("{:?}", value)); - }; + fn record(&self, span: &tokio_trace::Id, values: &tokio_trace::field::ValueSet) { let mut spans = self.spans.lock().expect("mutex poisoned!"); if let Some(span) = spans.get_mut(span) { - span.record(name, format_args!("{:?}", value)) + values.record(span); } } - fn add_follows_from(&self, _span: &tokio_trace::Id, _follows: tokio_trace::Id) { + fn record_follows_from(&self, _span: &tokio_trace::Id, _follows: &tokio_trace::Id) { // unimplemented } @@ -223,34 +261,33 @@ impl Subscriber for SloggishSubscriber { } } + fn event(&self, event: &tokio_trace::Event) { + let mut stderr = self.stderr.lock(); + let indent = self.stack.lock().unwrap().len(); + self.print_indent(&mut stderr, indent).unwrap(); + write!( + &mut stderr, + "{timestamp} {level} {target}", + timestamp = humantime::format_rfc3339_seconds(SystemTime::now()), + level = ColorLevel(event.metadata().level()), + target = &event.metadata().target(), + ) + .unwrap(); + let mut recorder = Event { + stderr, + comma: false, + }; + event.record(&mut recorder); + write!(&mut recorder.stderr, "\n").unwrap(); + } + #[inline] fn exit(&self, _span: &tokio_trace::Id) { // TODO: unify stack with current span self.current.exit(); } - fn drop_span(&self, id: tokio_trace::Id) { - if let Some(event) = self.events.lock().expect("mutex poisoned").remove(&id) { - let mut stderr = self.stderr.lock(); - let indent = self.stack.lock().unwrap().len(); - self.print_indent(&mut stderr, indent).unwrap(); - write!( - &mut stderr, - "{timestamp} {level} {target} {message}", - timestamp = humantime::format_rfc3339_seconds(SystemTime::now()), - level = ColorLevel(event.level), - target = &event.target, - message = Style::new().bold().paint(event.message), - ) - .unwrap(); - self.print_kvs( - &mut stderr, - event.kvs.iter().map(|&(ref k, ref v)| (k, v)), - ", ", - ) - .unwrap(); - write!(&mut stderr, "\n").unwrap(); - } + fn drop_span(&self, _id: tokio_trace::Id) { // TODO: GC unneeded spans. } } From 5296a4cb4f581f2cdcfece8f7b86bf7342f0823c Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Thu, 7 Feb 2019 13:39:41 -0800 Subject: [PATCH 6/7] futures: Make `WithSubscriber` work with existing `Dispatch` The upstream change that made `Dispatch` no longer implement `Subscriber` broke this a bit, since a `Dispatch` can no longer be passed to `with_subscriber`. To make this also work with unwrapped subscribers, we'll probably want an impl of `From` for `Dispatch`. Signed-off-by: Eliza Weisman --- tokio-trace-futures/src/lib.rs | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/tokio-trace-futures/src/lib.rs b/tokio-trace-futures/src/lib.rs index 1584e55540..3cec49c43d 100644 --- a/tokio-trace-futures/src/lib.rs +++ b/tokio-trace-futures/src/lib.rs @@ -5,7 +5,7 @@ extern crate tokio; extern crate tokio_trace; use futures::{Async, Future, Poll, Sink, StartSend, Stream}; -use tokio_trace::{dispatcher, Dispatch, Span, Subscriber}; +use tokio_trace::{dispatcher, Dispatch, Span}; pub mod executor; @@ -21,11 +21,11 @@ pub trait Instrument: Sized { pub trait WithSubscriber: Sized { fn with_subscriber(self, subscriber: S) -> WithDispatch where - S: Subscriber + Send + Sync + 'static, + S: Into, { WithDispatch { inner: self, - dispatch: Dispatch::new(subscriber), + dispatch: subscriber.into(), } } } From 349b22c50038059c8b2e2fda5a7de498fc30ea9d Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Thu, 7 Feb 2019 14:22:02 -0800 Subject: [PATCH 7/7] Add parent span names to TraceLogger Signed-off-by: Eliza Weisman --- tokio-trace-log/src/lib.rs | 42 +++++++++++++++++++++++++++++++++----- 1 file changed, 37 insertions(+), 5 deletions(-) diff --git a/tokio-trace-log/src/lib.rs b/tokio-trace-log/src/lib.rs index af42cd765b..f0c0ed0b25 100644 --- a/tokio-trace-log/src/lib.rs +++ b/tokio-trace-log/src/lib.rs @@ -153,13 +153,13 @@ pub struct TraceLogger { current: tokio_trace_subscriber::CurrentSpanPerThread, } -#[derive(Default)] pub struct TraceLoggerBuilder { log_span_closes: bool, log_enters: bool, log_exits: bool, log_ids: bool, parent_fields: bool, + log_parent: bool, } // ===== impl LogTracer ===== @@ -241,11 +241,29 @@ impl TraceLoggerBuilder { Self { log_ids, ..self } } + pub fn with_parent_names(self, log_parent: bool) -> Self { + Self { log_parent, ..self } + } + + pub fn finish(self) -> TraceLogger { TraceLogger::from_builder(self) } } +impl Default for TraceLoggerBuilder { + fn default() -> Self { + TraceLoggerBuilder { + log_span_closes: false, + parent_fields: true, + log_exits: false, + log_ids: false, + log_parent: true, + log_enters: false, + } + } +} + struct SpanLineBuilder { parent: Option, ref_count: usize, @@ -423,12 +441,21 @@ impl Subscriber for TraceLogger { let logger = log::logger(); if logger.enabled(&log_meta) { let spans = self.spans.lock().unwrap(); - let current_fields = self.current.id() + let current = self.current.id() .and_then(|id| { spans.get(&id) + }); + let (current_fields, parent) = current + .map(|span| { + let fields = span.fields.as_ref(); + let parent = if self.settings.log_parent { + Some(span.name) + } else { + None + }; + (fields, parent) }) - .map(|span| span.fields.as_ref()) - .unwrap_or(""); + .unwrap_or(("", None)); logger.log( &log::Record::builder() .metadata(log_meta) @@ -436,7 +463,12 @@ impl Subscriber for TraceLogger { .module_path(meta.module_path.as_ref().map(|&p| p)) .file(meta.file.as_ref().map(|&f| f)) .line(meta.line) - .args(format_args!("{}{}", LogEvent(event), current_fields)) + .args(format_args!("{}{}{}{}", + parent.unwrap_or(""), + if parent.is_some() { ": " } else { "" }, + LogEvent(event), + current_fields, + )) .build(), );