use super::{Format, FormatEvent, FormatFields, FormatTime};
use crate::{
field::{RecordFields, VisitOutput},
fmt::fmt_layer::{FmtContext, FormattedFields},
registry::LookupSpan,
};
use serde::ser::{SerializeMap, Serializer as _};
use serde_json::Serializer;
use std::{
collections::BTreeMap,
fmt::{self, Write},
io,
};
use tracing_core::{
field::{self, Field},
span::Record,
Event, Subscriber,
};
use tracing_serde::AsSerde;
#[cfg(feature = "tracing-log")]
use tracing_log::NormalizeEvent;
#[derive(Debug, Copy, Clone, Eq, PartialEq)]
pub struct Json {
pub(crate) flatten_event: bool,
pub(crate) display_current_span: bool,
pub(crate) display_span_list: bool,
}
impl Json {
pub fn flatten_event(&mut self, flatten_event: bool) {
self.flatten_event = flatten_event;
}
pub fn with_current_span(&mut self, display_current_span: bool) {
self.display_current_span = display_current_span;
}
pub fn with_span_list(&mut self, display_span_list: bool) {
self.display_span_list = display_span_list;
}
}
struct SerializableContext<'a, 'b, Span, N>(
&'b crate::layer::Context<'a, Span>,
std::marker::PhantomData<N>,
)
where
Span: Subscriber + for<'lookup> crate::registry::LookupSpan<'lookup>,
N: for<'writer> FormatFields<'writer> + 'static;
impl<'a, 'b, Span, N> serde::ser::Serialize for SerializableContext<'a, 'b, Span, N>
where
Span: Subscriber + for<'lookup> crate::registry::LookupSpan<'lookup>,
N: for<'writer> FormatFields<'writer> + 'static,
{
fn serialize<Ser>(&self, serializer_o: Ser) -> Result<Ser::Ok, Ser::Error>
where
Ser: serde::ser::Serializer,
{
use serde::ser::SerializeSeq;
let mut serializer = serializer_o.serialize_seq(None)?;
if let Some(leaf_span) = self.0.lookup_current() {
for span in leaf_span.scope().from_root() {
serializer.serialize_element(&SerializableSpan(&span, self.1))?;
}
}
serializer.end()
}
}
struct SerializableSpan<'a, 'b, Span, N>(
&'b crate::registry::SpanRef<'a, Span>,
std::marker::PhantomData<N>,
)
where
Span: for<'lookup> crate::registry::LookupSpan<'lookup>,
N: for<'writer> FormatFields<'writer> + 'static;
impl<'a, 'b, Span, N> serde::ser::Serialize for SerializableSpan<'a, 'b, Span, N>
where
Span: for<'lookup> crate::registry::LookupSpan<'lookup>,
N: for<'writer> FormatFields<'writer> + 'static,
{
fn serialize<Ser>(&self, serializer: Ser) -> Result<Ser::Ok, Ser::Error>
where
Ser: serde::ser::Serializer,
{
let mut serializer = serializer.serialize_map(None)?;
let ext = self.0.extensions();
let data = ext
.get::<FormattedFields<N>>()
.expect("Unable to find FormattedFields in extensions; this is a bug");
match serde_json::from_str::<serde_json::Value>(data) {
Ok(serde_json::Value::Object(fields)) => {
for field in fields {
serializer.serialize_entry(&field.0, &field.1)?;
}
}
Ok(_) if cfg!(debug_assertions) => panic!(
"span '{}' had malformed fields! this is a bug.\n error: invalid JSON object\n fields: {:?}",
self.0.metadata().name(),
data
),
Ok(value) => {
serializer.serialize_entry("field", &value)?;
serializer.serialize_entry("field_error", "field was no a valid object")?
}
Err(e) if cfg!(debug_assertions) => panic!(
"span '{}' had malformed fields! this is a bug.\n error: {}\n fields: {:?}",
self.0.metadata().name(),
e,
data
),
Err(e) => serializer.serialize_entry("field_error", &format!("{}", e))?,
};
serializer.serialize_entry("name", self.0.metadata().name())?;
serializer.end()
}
}
impl<S, N, T> FormatEvent<S, N> for Format<Json, T>
where
S: Subscriber + for<'lookup> LookupSpan<'lookup>,
N: for<'writer> FormatFields<'writer> + 'static,
T: FormatTime,
{
fn format_event(
&self,
ctx: &FmtContext<'_, S, N>,
writer: &mut dyn fmt::Write,
event: &Event<'_>,
) -> fmt::Result
where
S: Subscriber + for<'a> LookupSpan<'a>,
{
let mut timestamp = String::new();
self.timer.format_time(&mut timestamp)?;
#[cfg(feature = "tracing-log")]
let normalized_meta = event.normalized_metadata();
#[cfg(feature = "tracing-log")]
let meta = normalized_meta.as_ref().unwrap_or_else(|| event.metadata());
#[cfg(not(feature = "tracing-log"))]
let meta = event.metadata();
let mut visit = || {
let mut serializer = Serializer::new(WriteAdaptor::new(writer));
let mut serializer = serializer.serialize_map(None)?;
if self.display_timestamp {
serializer.serialize_entry("timestamp", ×tamp)?;
}
if self.display_level {
serializer.serialize_entry("level", &meta.level().as_serde())?;
}
let format_field_marker: std::marker::PhantomData<N> = std::marker::PhantomData;
let current_span = if self.format.display_current_span || self.format.display_span_list
{
event
.parent()
.and_then(|id| ctx.span(id))
.or_else(|| ctx.lookup_current())
} else {
None
};
if self.format.flatten_event {
let mut visitor = tracing_serde::SerdeMapVisitor::new(serializer);
event.record(&mut visitor);
serializer = visitor.take_serializer()?;
} else {
use tracing_serde::fields::AsMap;
serializer.serialize_entry("fields", &event.field_map())?;
};
if self.display_target {
serializer.serialize_entry("target", meta.target())?;
}
if self.format.display_current_span {
if let Some(ref span) = current_span {
serializer
.serialize_entry("span", &SerializableSpan(span, format_field_marker))
.unwrap_or(());
}
}
if self.format.display_span_list && current_span.is_some() {
serializer.serialize_entry(
"spans",
&SerializableContext(&ctx.ctx, format_field_marker),
)?;
}
if self.display_thread_name {
let current_thread = std::thread::current();
match current_thread.name() {
Some(name) => {
serializer.serialize_entry("threadName", name)?;
}
None if !self.display_thread_id => {
serializer
.serialize_entry("threadName", &format!("{:?}", current_thread.id()))?;
}
_ => {}
}
}
if self.display_thread_id {
serializer
.serialize_entry("threadId", &format!("{:?}", std::thread::current().id()))?;
}
serializer.end()
};
visit().map_err(|_| fmt::Error)?;
writeln!(writer)
}
}
impl Default for Json {
fn default() -> Json {
Json {
flatten_event: false,
display_current_span: true,
display_span_list: true,
}
}
}
#[derive(Debug)]
pub struct JsonFields {
_private: (),
}
impl JsonFields {
pub fn new() -> Self {
Self { _private: () }
}
}
impl Default for JsonFields {
fn default() -> Self {
Self::new()
}
}
impl<'a> FormatFields<'a> for JsonFields {
fn format_fields<R: RecordFields>(
&self,
writer: &'a mut dyn fmt::Write,
fields: R,
) -> fmt::Result {
let mut v = JsonVisitor::new(writer);
fields.record(&mut v);
v.finish()
}
fn add_fields(&self, current: &'a mut String, fields: &Record<'_>) -> fmt::Result {
if !current.is_empty() {
let mut new = String::new();
let map: BTreeMap<&'_ str, serde_json::Value> =
serde_json::from_str(current).map_err(|_| fmt::Error)?;
let mut v = JsonVisitor::new(&mut new);
v.values = map;
fields.record(&mut v);
v.finish()?;
*current = new;
} else {
let mut v = JsonVisitor::new(current);
fields.record(&mut v);
v.finish()?;
}
Ok(())
}
}
pub struct JsonVisitor<'a> {
values: BTreeMap<&'a str, serde_json::Value>,
writer: &'a mut dyn Write,
}
impl<'a> fmt::Debug for JsonVisitor<'a> {
fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
f.write_fmt(format_args!("JsonVisitor {{ values: {:?} }}", self.values))
}
}
impl<'a> JsonVisitor<'a> {
pub fn new(writer: &'a mut dyn Write) -> Self {
Self {
values: BTreeMap::new(),
writer,
}
}
}
impl<'a> crate::field::VisitFmt for JsonVisitor<'a> {
fn writer(&mut self) -> &mut dyn fmt::Write {
self.writer
}
}
impl<'a> crate::field::VisitOutput<fmt::Result> for JsonVisitor<'a> {
fn finish(self) -> fmt::Result {
let inner = || {
let mut serializer = Serializer::new(WriteAdaptor::new(self.writer));
let mut ser_map = serializer.serialize_map(None)?;
for (k, v) in self.values {
ser_map.serialize_entry(k, &v)?;
}
ser_map.end()
};
if inner().is_err() {
Err(fmt::Error)
} else {
Ok(())
}
}
}
impl<'a> field::Visit for JsonVisitor<'a> {
fn record_f64(&mut self, field: &Field, value: f64) {
self.values
.insert(field.name(), serde_json::Value::from(value));
}
fn record_i64(&mut self, field: &Field, value: i64) {
self.values
.insert(field.name(), serde_json::Value::from(value));
}
fn record_u64(&mut self, field: &Field, value: u64) {
self.values
.insert(field.name(), serde_json::Value::from(value));
}
fn record_bool(&mut self, field: &Field, value: bool) {
self.values
.insert(field.name(), serde_json::Value::from(value));
}
fn record_str(&mut self, field: &Field, value: &str) {
self.values
.insert(field.name(), serde_json::Value::from(value));
}
fn record_debug(&mut self, field: &Field, value: &dyn fmt::Debug) {
match field.name() {
#[cfg(feature = "tracing-log")]
name if name.starts_with("log.") => (),
name if name.starts_with("r#") => {
self.values
.insert(&name[2..], serde_json::Value::from(format!("{:?}", value)));
}
name => {
self.values
.insert(name, serde_json::Value::from(format!("{:?}", value)));
}
};
}
}
struct WriteAdaptor<'a> {
fmt_write: &'a mut dyn fmt::Write,
}
impl<'a> WriteAdaptor<'a> {
fn new(fmt_write: &'a mut dyn fmt::Write) -> Self {
Self { fmt_write }
}
}
impl<'a> io::Write for WriteAdaptor<'a> {
fn write(&mut self, buf: &[u8]) -> io::Result<usize> {
let s =
std::str::from_utf8(buf).map_err(|e| io::Error::new(io::ErrorKind::InvalidData, e))?;
self.fmt_write
.write_str(s)
.map_err(|e| io::Error::new(io::ErrorKind::Other, e))?;
Ok(s.as_bytes().len())
}
fn flush(&mut self) -> io::Result<()> {
Ok(())
}
}
impl<'a> fmt::Debug for WriteAdaptor<'a> {
fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
f.pad("WriteAdaptor { .. }")
}
}
#[cfg(test)]
mod test {
use super::*;
use crate::fmt::{format::FmtSpan, test::MockMakeWriter, time::FormatTime, SubscriberBuilder};
use lazy_static::lazy_static;
use std::{fmt, sync::Mutex};
use tracing::{self, subscriber::with_default};
struct MockTime;
impl FormatTime for MockTime {
fn format_time(&self, w: &mut dyn fmt::Write) -> fmt::Result {
write!(w, "fake time")
}
}
fn subscriber() -> SubscriberBuilder<JsonFields, Format<Json>> {
SubscriberBuilder::default().json()
}
#[test]
fn json() {
lazy_static! {
static ref BUF: Mutex<Vec<u8>> = Mutex::new(Vec::new());
}
let expected =
"{\"timestamp\":\"fake time\",\"level\":\"INFO\",\"span\":{\"answer\":42,\"name\":\"json_span\",\"number\":3},\"spans\":[{\"answer\":42,\"name\":\"json_span\",\"number\":3}],\"target\":\"tracing_subscriber::fmt::format::json::test\",\"fields\":{\"message\":\"some json test\"}}\n";
let subscriber = subscriber()
.flatten_event(false)
.with_current_span(true)
.with_span_list(true);
test_json(expected, subscriber, &BUF, || {
let span = tracing::span!(tracing::Level::INFO, "json_span", answer = 42, number = 3);
let _guard = span.enter();
tracing::info!("some json test");
});
}
#[test]
fn json_flattened_event() {
lazy_static! {
static ref BUF: Mutex<Vec<u8>> = Mutex::new(Vec::new());
}
let expected =
"{\"timestamp\":\"fake time\",\"level\":\"INFO\",\"span\":{\"answer\":42,\"name\":\"json_span\",\"number\":3},\"spans\":[{\"answer\":42,\"name\":\"json_span\",\"number\":3}],\"target\":\"tracing_subscriber::fmt::format::json::test\",\"message\":\"some json test\"}\n";
let subscriber = subscriber()
.flatten_event(true)
.with_current_span(true)
.with_span_list(true);
test_json(expected, subscriber, &BUF, || {
let span = tracing::span!(tracing::Level::INFO, "json_span", answer = 42, number = 3);
let _guard = span.enter();
tracing::info!("some json test");
});
}
#[test]
fn json_disabled_current_span_event() {
lazy_static! {
static ref BUF: Mutex<Vec<u8>> = Mutex::new(Vec::new());
}
let expected =
"{\"timestamp\":\"fake time\",\"level\":\"INFO\",\"spans\":[{\"answer\":42,\"name\":\"json_span\",\"number\":3}],\"target\":\"tracing_subscriber::fmt::format::json::test\",\"fields\":{\"message\":\"some json test\"}}\n";
let subscriber = subscriber()
.flatten_event(false)
.with_current_span(false)
.with_span_list(true);
test_json(expected, subscriber, &BUF, || {
let span = tracing::span!(tracing::Level::INFO, "json_span", answer = 42, number = 3);
let _guard = span.enter();
tracing::info!("some json test");
});
}
#[test]
fn json_disabled_span_list_event() {
lazy_static! {
static ref BUF: Mutex<Vec<u8>> = Mutex::new(Vec::new());
}
let expected =
"{\"timestamp\":\"fake time\",\"level\":\"INFO\",\"span\":{\"answer\":42,\"name\":\"json_span\",\"number\":3},\"target\":\"tracing_subscriber::fmt::format::json::test\",\"fields\":{\"message\":\"some json test\"}}\n";
let subscriber = subscriber()
.flatten_event(false)
.with_current_span(true)
.with_span_list(false);
test_json(expected, subscriber, &BUF, || {
let span = tracing::span!(tracing::Level::INFO, "json_span", answer = 42, number = 3);
let _guard = span.enter();
tracing::info!("some json test");
});
}
#[test]
fn json_nested_span() {
lazy_static! {
static ref BUF: Mutex<Vec<u8>> = Mutex::new(Vec::new());
}
let expected =
"{\"timestamp\":\"fake time\",\"level\":\"INFO\",\"span\":{\"answer\":43,\"name\":\"nested_json_span\",\"number\":4},\"spans\":[{\"answer\":42,\"name\":\"json_span\",\"number\":3},{\"answer\":43,\"name\":\"nested_json_span\",\"number\":4}],\"target\":\"tracing_subscriber::fmt::format::json::test\",\"fields\":{\"message\":\"some json test\"}}\n";
let subscriber = subscriber()
.flatten_event(false)
.with_current_span(true)
.with_span_list(true);
test_json(expected, subscriber, &BUF, || {
let span = tracing::span!(tracing::Level::INFO, "json_span", answer = 42, number = 3);
let _guard = span.enter();
let span = tracing::span!(
tracing::Level::INFO,
"nested_json_span",
answer = 43,
number = 4
);
let _guard = span.enter();
tracing::info!("some json test");
});
}
#[test]
fn json_no_span() {
lazy_static! {
static ref BUF: Mutex<Vec<u8>> = Mutex::new(Vec::new());
}
let expected =
"{\"timestamp\":\"fake time\",\"level\":\"INFO\",\"target\":\"tracing_subscriber::fmt::format::json::test\",\"fields\":{\"message\":\"some json test\"}}\n";
let subscriber = subscriber()
.flatten_event(false)
.with_current_span(true)
.with_span_list(true);
test_json(expected, subscriber, &BUF, || {
tracing::info!("some json test");
});
}
#[test]
fn record_works() {
lazy_static! {
static ref BUF: Mutex<Vec<u8>> = Mutex::new(Vec::new());
}
let buffer = MockMakeWriter::new(&BUF);
let subscriber = crate::fmt().json().with_writer(buffer.clone()).finish();
with_default(subscriber, || {
tracing::info!("an event outside the root span");
assert_eq!(
parse_as_json(&buffer)["fields"]["message"],
"an event outside the root span"
);
let span = tracing::info_span!("the span", na = tracing::field::Empty);
span.record("na", &"value");
let _enter = span.enter();
tracing::info!("an event inside the root span");
assert_eq!(
parse_as_json(&buffer)["fields"]["message"],
"an event inside the root span"
);
});
}
#[test]
fn json_span_event_show_correct_context() {
lazy_static! {
static ref BUF: Mutex<Vec<u8>> = Mutex::new(Vec::new());
}
let buffer = MockMakeWriter::new(&BUF);
let subscriber = subscriber()
.with_writer(buffer.clone())
.flatten_event(false)
.with_current_span(true)
.with_span_list(false)
.with_span_events(FmtSpan::FULL)
.finish();
with_default(subscriber, || {
let context = "parent";
let parent_span = tracing::info_span!("parent_span", context);
let event = parse_as_json(&buffer);
assert_eq!(event["fields"]["message"], "new");
assert_eq!(event["span"]["context"], "parent");
let _parent_enter = parent_span.enter();
let event = parse_as_json(&buffer);
assert_eq!(event["fields"]["message"], "enter");
assert_eq!(event["span"]["context"], "parent");
let context = "child";
let child_span = tracing::info_span!("child_span", context);
let event = parse_as_json(&buffer);
assert_eq!(event["fields"]["message"], "new");
assert_eq!(event["span"]["context"], "child");
let _child_enter = child_span.enter();
let event = parse_as_json(&buffer);
assert_eq!(event["fields"]["message"], "enter");
assert_eq!(event["span"]["context"], "child");
drop(_child_enter);
let event = parse_as_json(&buffer);
assert_eq!(event["fields"]["message"], "exit");
assert_eq!(event["span"]["context"], "child");
drop(child_span);
let event = parse_as_json(&buffer);
assert_eq!(event["fields"]["message"], "close");
assert_eq!(event["span"]["context"], "child");
drop(_parent_enter);
let event = parse_as_json(&buffer);
assert_eq!(event["fields"]["message"], "exit");
assert_eq!(event["span"]["context"], "parent");
drop(parent_span);
let event = parse_as_json(&buffer);
assert_eq!(event["fields"]["message"], "close");
assert_eq!(event["span"]["context"], "parent");
});
}
#[test]
fn json_span_event_with_no_fields() {
lazy_static! {
static ref BUF: Mutex<Vec<u8>> = Mutex::new(Vec::new());
}
let buffer = MockMakeWriter::new(&BUF);
let subscriber = subscriber()
.with_writer(buffer.clone())
.flatten_event(false)
.with_current_span(false)
.with_span_list(false)
.with_span_events(FmtSpan::FULL)
.finish();
with_default(subscriber, || {
let span = tracing::info_span!("valid_json");
assert_eq!(parse_as_json(&buffer)["fields"]["message"], "new");
let _enter = span.enter();
assert_eq!(parse_as_json(&buffer)["fields"]["message"], "enter");
drop(_enter);
assert_eq!(parse_as_json(&buffer)["fields"]["message"], "exit");
drop(span);
assert_eq!(parse_as_json(&buffer)["fields"]["message"], "close");
});
}
fn parse_as_json(buffer: &MockMakeWriter<'_>) -> serde_json::Value {
let buf = String::from_utf8(buffer.buf().to_vec()).unwrap();
let json = buf
.lines()
.last()
.expect("expected at least one line to be written!");
match serde_json::from_str(json) {
Ok(v) => v,
Err(e) => panic!(
"assertion failed: JSON shouldn't be malformed\n error: {}\n json: {}",
e, json
),
}
}
fn test_json<T>(
expected: &str,
builder: crate::fmt::SubscriberBuilder<JsonFields, Format<Json>>,
buf: &'static Mutex<Vec<u8>>,
producer: impl FnOnce() -> T,
) {
let make_writer = MockMakeWriter::new(buf);
let subscriber = builder
.with_writer(make_writer.clone())
.with_timer(MockTime)
.finish();
with_default(subscriber, producer);
let buf = make_writer.buf();
let actual = std::str::from_utf8(&buf[..]).unwrap();
assert_eq!(
serde_json::from_str::<std::collections::HashMap<&str, serde_json::Value>>(expected)
.unwrap(),
serde_json::from_str(actual).unwrap()
);
}
}