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)?;
for span in self.0.scope() {
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)?;
serializer.serialize_entry("timestamp", ×tamp)?;
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
{
ctx.ctx.current_span().id().and_then(|id| ctx.ctx.span(id))
} 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_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 crate::fmt::{test::MockWriter, time::FormatTime};
use lazy_static::lazy_static;
use tracing::{self, subscriber::with_default};
use std::{fmt, sync::Mutex};
struct MockTime;
impl FormatTime for MockTime {
fn format_time(&self, w: &mut dyn fmt::Write) -> fmt::Result {
write!(w, "fake time")
}
}
#[test]
fn json() {
lazy_static! {
static ref BUF: Mutex<Vec<u8>> = Mutex::new(vec![]);
}
let make_writer = || MockWriter::new(&BUF);
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";
test_json(make_writer, expected, &BUF, false, true, true, || {
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![]);
}
let make_writer = || MockWriter::new(&BUF);
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";
test_json(make_writer, expected, &BUF, true, true, true, || {
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![]);
}
let make_writer = || MockWriter::new(&BUF);
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";
test_json(make_writer, expected, &BUF, false, false, true, || {
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![]);
}
let make_writer = || MockWriter::new(&BUF);
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";
test_json(make_writer, expected, &BUF, false, true, false, || {
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![]);
}
let make_writer = || MockWriter::new(&BUF);
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";
test_json(make_writer, expected, &BUF, false, true, true, || {
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![]);
}
let make_writer = || MockWriter::new(&BUF);
let expected =
"{\"timestamp\":\"fake time\",\"level\":\"INFO\",\"target\":\"tracing_subscriber::fmt::format::json::test\",\"fields\":{\"message\":\"some json test\"}}\n";
test_json(make_writer, expected, &BUF, false, true, true, || {
tracing::info!("some json test");
});
}
#[test]
fn record_works() {
lazy_static! {
static ref BUF: Mutex<Vec<u8>> = Mutex::new(vec![]);
}
let make_writer = || MockWriter::new(&BUF);
let subscriber = crate::fmt().json().with_writer(make_writer).finish();
let parse_buf = || -> serde_json::Value {
let buf = String::from_utf8(BUF.try_lock().unwrap().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
),
}
};
with_default(subscriber, || {
tracing::info!("an event outside the root span");
assert_eq!(
parse_buf()["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_buf()["fields"]["message"],
"an event inside the root span"
);
});
}
#[cfg(feature = "json")]
fn test_json<T, U>(
make_writer: T,
expected: &str,
buf: &Mutex<Vec<u8>>,
flatten_event: bool,
display_current_span: bool,
display_span_list: bool,
producer: impl FnOnce() -> U,
) where
T: crate::fmt::MakeWriter + Send + Sync + 'static,
{
let subscriber = crate::fmt::Subscriber::builder()
.json()
.flatten_event(flatten_event)
.with_current_span(display_current_span)
.with_span_list(display_span_list)
.with_writer(make_writer)
.with_timer(MockTime)
.finish();
with_default(subscriber, producer);
let actual = String::from_utf8(buf.try_lock().unwrap().to_vec()).unwrap();
assert_eq!(
serde_json::from_str::<std::collections::HashMap<&str, serde_json::Value>>(expected)
.unwrap(),
serde_json::from_str(actual.as_str()).unwrap()
);
}
}