From ca110b6f2427e7e0ba3a4010be04dadf6b0a2940 Mon Sep 17 00:00:00 2001 From: Cole Mackenzie Date: Fri, 20 Oct 2023 14:38:26 -0700 Subject: [PATCH] Use a visitor pattern instead of `FormattedFields` (#12) This changes a lot of the insides of the crate, but the API is mostly the same. While the visitor pattern is a bit more verbose, it's also more flexible and allows for more customization in the future. --- .github/workflows/rust.yml | 15 +- .rustfmt.toml | 3 + Cargo.toml | 2 +- Makefile | 4 +- README.md | 29 ++- examples/README.md | 8 +- examples/customize.rs | 28 +-- examples/default.rs | 15 ++ examples/defaults.rs | 16 -- src/formatter.rs | 460 ------------------------------------- src/layer.rs | 193 ++++++++++++++++ src/lib.rs | 108 +++++---- src/storage.rs | 62 +++++ src/visitor.rs | 124 ---------- 14 files changed, 386 insertions(+), 681 deletions(-) create mode 100644 .rustfmt.toml create mode 100644 examples/default.rs delete mode 100644 examples/defaults.rs delete mode 100644 src/formatter.rs create mode 100644 src/layer.rs create mode 100644 src/storage.rs delete mode 100644 src/visitor.rs diff --git a/.github/workflows/rust.yml b/.github/workflows/rust.yml index 31000a2..464d816 100644 --- a/.github/workflows/rust.yml +++ b/.github/workflows/rust.yml @@ -2,21 +2,20 @@ name: Rust on: push: - branches: [ "main" ] + branches: ["main"] pull_request: - branches: [ "main" ] + branches: ["main"] env: CARGO_TERM_COLOR: always jobs: build: - runs-on: ubuntu-latest steps: - - uses: actions/checkout@v3 - - name: Build - run: cargo build --verbose - - name: Run tests - run: cargo test --verbose + - uses: actions/checkout@v3 + - name: Build + run: cargo build --verbose + - name: Run tests + run: cargo test --verbose diff --git a/.rustfmt.toml b/.rustfmt.toml new file mode 100644 index 0000000..ab2f7e6 --- /dev/null +++ b/.rustfmt.toml @@ -0,0 +1,3 @@ +# rustup install nightly +group_imports = "StdExternalCrate" +format_code_in_doc_comments = true diff --git a/Cargo.toml b/Cargo.toml index c186693..b137646 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -1,6 +1,6 @@ [package] name = "tracing-ndjson" -version = "0.1.3" +version = "0.2.0" edition = "2021" license = "MIT" authors = ["Cole Mackenzie"] diff --git a/Makefile b/Makefile index d3b4382..fced7c2 100644 --- a/Makefile +++ b/Makefile @@ -1,5 +1,5 @@ fmt: - @cargo fmt + @cargo +nightly fmt || cargo fmt build: @cargo build @@ -8,7 +8,7 @@ clean: @cargo clean test: - @cargo test + @cargo test -- --nocapture lint: fmt @cargo clippy --all-targets -- -D warnings diff --git a/README.md b/README.md index 41bee4a..3e75a26 100644 --- a/README.md +++ b/README.md @@ -4,14 +4,25 @@ [![Rust](https://github.com/cmackenzie1/tracing-ndjson/actions/workflows/rust.yml/badge.svg)](https://github.com/cmackenzie1/tracing-ndjson/actions/workflows/rust.yml) [![docs.rs](https://img.shields.io/docsrs/tracing-ndjson)](https://docs.rs/tracing-ndjson/latest/tracing_ndjson) - A simple library for tracing in new-line delimited JSON format. This library is meant to be used with [tracing](https://github.com/tokio-rs/tracing) as an alternative to the `tracing_subscriber::fmt::json` formatter. +The goal of this crate is to provide a flattend JSON event, comprising of fields from the span attributes and event fields, with customizeable field names and timestamp formats. + ## Features - Configurable field names for `target`, `message`, `level`, and `timestamp`. -- Configurable timestamp formats such as RFC3339, UNIX timestamp, or any custom chrono format. -- Captures all span attributes and event fields in the root of the JSON object. +- Configurable timestamp formats + - RFC3339 (`2023-10-08T03:30:52Z`), + - RFC339Nanos (`2023-10-08T03:30:52.123456789Z`) + - Unix timestamp (`1672535452`) + - UnixMills (`1672535452123`) +- Captures all span attributes and event fields in the root of the JSON object. Collisions will result in overwriting the existing field. + +## Limitations + +- When flattening span attributes and event fields, the library will overwrite any existing fields with the same name, including the built-in fields such as `target`, `message`, `level`, `timestamp`, `file`, and `line`. +- Non-determistic ordering of fields in the JSON object. ([JSON objects are unordered](https://www.json.org/json-en.html)) +- Currently only logs to stdout. (PRs welcome!) ## Usage @@ -20,24 +31,24 @@ Add this to your `Cargo.toml`: ```toml [dependencies] tracing = "0.1" -tracing-ndjson = "0.1" +tracing-ndjson = "0.2" ``` ```rust use tracing_subscriber::prelude::*; fn main() { - tracing_subscriber::registry() - .with(tracing_ndjson::builder().layer()) - .init(); + let subscriber = tracing_subscriber::registry().with(tracing_ndjson::layer()); + + tracing::subscriber::set_global_default(subscriber).unwrap(); tracing::info!(life = 42, "Hello, world!"); - // {"level":"info","timestamp":"2023-10-10T20:35:26Z","target":"defaults","message":"Hello, world!","life":42} + // {"level":"info","target":"default","life":42,"timestamp":"2023-10-20T21:17:49Z","message":"Hello, world!"} let span = tracing::info_span!("hello", "request.uri" = "https://example.com"); span.in_scope(|| { tracing::info!("Hello, world!"); - // {"level":"info","timestamp":"2023-10-10T20:35:26Z","target":"defaults","message":"Hello, world!","request.uri":"https://example.com"} + // {"message":"Hello, world!","request.uri":"https://example.com","level":"info","target":"default","timestamp":"2023-10-20T21:17:49Z"} }); } ``` diff --git a/examples/README.md b/examples/README.md index c4cb0a5..88a7103 100644 --- a/examples/README.md +++ b/examples/README.md @@ -3,17 +3,11 @@ ## Defaults ```bash -cargo run --example defaults - -{"level":"info","timestamp":"2023-10-08T03:35:11Z","target":"defaults","message":"Hello, world!","life":42} -{"level":"info","timestamp":"2023-10-08T03:35:11Z","target":"defaults","message":"Hello, world!","request.uri":"https://example.com"} +cargo run --example default ``` ## Customized ```bash cargo run --example customize - -{"severity":"info","ts":1696736208,"target":"customize","message":"Hello, world!","life":42} -{"severity":"info","ts":1696736208,"target":"customize","message":"Hello, world!","request.uri":"https://example.com"} ``` diff --git a/examples/customize.rs b/examples/customize.rs index 95945d5..26fe50c 100644 --- a/examples/customize.rs +++ b/examples/customize.rs @@ -1,23 +1,25 @@ use tracing_subscriber::prelude::*; - fn main() { - tracing_subscriber::registry() - .with( - tracing_ndjson::builder() - .with_level_name("severity") - .with_message_name("msg") - .with_timestamp_name("ts") - .with_timestamp_format(tracing_ndjson::TimestampFormat::Unix) - .layer(), - ) - .init(); + let subscriber = tracing_subscriber::registry().with( + tracing_ndjson::builder() + .with_level_name("severity") + .with_level_value_casing(tracing_ndjson::Casing::Uppercase) + .with_timestamp_name("ts") + .with_timestamp_format(tracing_ndjson::TimestampFormat::UnixMillis) + .with_message_name("msg") + .with_line_numbers(true) + .with_file_names(true) + .layer(), + ); + + tracing::subscriber::set_global_default(subscriber).unwrap(); tracing::info!(life = 42, "Hello, world!"); - // {"level":"info","timestamp":"2023-10-08T03:30:52Z","target":"default","message":"Hello, world!"} + // {"life":42,"msg":"Hello, world!","target":"customize","ts":1697836630814,"file":"examples/customize.rs","line":17,"severity":"INFO"} let span = tracing::info_span!("hello", "request.uri" = "https://example.com"); span.in_scope(|| { tracing::info!("Hello, world!"); - // {"level":"info","timestamp":"2023-10-08T03:34:33Z","target":"defaults","message":"Hello, world!","request.uri":"https://example.com"} + // {"severity":"INFO","target":"customize","file":"examples/customize.rs","msg":"Hello, world!","ts":1697836630814,"line":22,"request.uri":"https://example.com"} }); } diff --git a/examples/default.rs b/examples/default.rs new file mode 100644 index 0000000..6ed25ea --- /dev/null +++ b/examples/default.rs @@ -0,0 +1,15 @@ +use tracing_subscriber::prelude::*; +fn main() { + let subscriber = tracing_subscriber::registry().with(tracing_ndjson::layer()); + + tracing::subscriber::set_global_default(subscriber).unwrap(); + + tracing::info!(life = 42, "Hello, world!"); + // {"level":"info","target":"default","life":42,"timestamp":"2023-10-20T21:17:49Z","message":"Hello, world!"} + + let span = tracing::info_span!("hello", "request.uri" = "https://example.com"); + span.in_scope(|| { + tracing::info!("Hello, world!"); + // {"message":"Hello, world!","request.uri":"https://example.com","level":"info","target":"default","timestamp":"2023-10-20T21:17:49Z"} + }); +} diff --git a/examples/defaults.rs b/examples/defaults.rs deleted file mode 100644 index e51c8f8..0000000 --- a/examples/defaults.rs +++ /dev/null @@ -1,16 +0,0 @@ -use tracing_subscriber::prelude::*; - -fn main() { - tracing_subscriber::registry() - .with(tracing_ndjson::builder().layer()) - .init(); - - tracing::info!(life = 42, "Hello, world!"); - // {"level":"info","timestamp":"2023-10-08T03:30:52Z","target":"default","message":"Hello, world!"} - - let span = tracing::info_span!("hello", "request.uri" = "https://example.com"); - span.in_scope(|| { - tracing::info!("Hello, world!"); - // {"level":"info","timestamp":"2023-10-08T03:34:33Z","target":"defaults","message":"Hello, world!","request.uri":"https://example.com"} - }); -} diff --git a/src/formatter.rs b/src/formatter.rs deleted file mode 100644 index 11a8207..0000000 --- a/src/formatter.rs +++ /dev/null @@ -1,460 +0,0 @@ -use std::fmt; - -use serde::{ser::SerializeMap, Serializer}; - -use tracing_core::{Event, Subscriber}; -use tracing_subscriber::{ - fmt::{format, FmtContext, FormatEvent, FormatFields, FormattedFields}, - registry::LookupSpan, -}; - -use crate::{visitor, Error}; - -const DEFAULT_TIMESTAMP_FORMAT: crate::TimestampFormat = crate::TimestampFormat::Rfc3339; -const DEFAULT_LEVEL_NAME: &str = "level"; -const DEFAULT_LEVEL_VALUE_CASING: crate::Casing = crate::Casing::Lowercase; -const DEFAULT_MESSAGE_NAME: &str = "message"; -const DEFAULT_TARGET_NAME: &str = "target"; -const DEFAULT_TIMESTAMP_NAME: &str = "timestamp"; -const DEFAULT_FLATTEN_FIELDS: bool = true; - -/// A JSON formatter for tracing events. -/// This is used to format the event field in the JSON output. -pub struct JsonEventFormatter { - level_name: &'static str, - level_value_casing: crate::Casing, - message_name: &'static str, - target_name: &'static str, - timestamp_name: &'static str, - timestamp_format: crate::TimestampFormat, - flatten_fields: bool, -} - -impl Default for JsonEventFormatter { - fn default() -> Self { - Self { - level_name: DEFAULT_LEVEL_NAME, - level_value_casing: DEFAULT_LEVEL_VALUE_CASING, - message_name: DEFAULT_MESSAGE_NAME, - target_name: DEFAULT_TARGET_NAME, - timestamp_name: DEFAULT_TIMESTAMP_NAME, - timestamp_format: DEFAULT_TIMESTAMP_FORMAT, - flatten_fields: DEFAULT_FLATTEN_FIELDS, - } - } -} - -impl JsonEventFormatter { - pub fn new() -> Self { - Self::default() - } - - pub fn with_level_name(mut self, level_name: &'static str) -> Self { - self.level_name = level_name; - self - } - - pub fn with_level_value_casing(mut self, level_value_casing: crate::Casing) -> Self { - self.level_value_casing = level_value_casing; - self - } - - pub fn with_message_name(mut self, message_name: &'static str) -> Self { - self.message_name = message_name; - self - } - - pub fn with_target_name(mut self, target_name: &'static str) -> Self { - self.target_name = target_name; - self - } - - pub fn with_timestamp_name(mut self, timestamp_name: &'static str) -> Self { - self.timestamp_name = timestamp_name; - self - } - - pub fn with_timestamp_format(mut self, timestamp_format: crate::TimestampFormat) -> Self { - self.timestamp_format = timestamp_format; - self - } - - pub fn with_flatten_fields(mut self, flatten_fields: bool) -> Self { - self.flatten_fields = flatten_fields; - self - } -} - -impl FormatEvent for JsonEventFormatter -where - S: Subscriber + for<'a> LookupSpan<'a>, - N: for<'a> FormatFields<'a> + 'static, -{ - fn format_event( - &self, - ctx: &FmtContext<'_, S, N>, - mut writer: format::Writer<'_>, - event: &Event<'_>, - ) -> fmt::Result { - let now = chrono::Utc::now(); - - let mut binding = serde_json::Serializer::new(Vec::new()); - let mut serializer = binding.serialize_map(None).map_err(Error::Serde)?; - - let level_str = match self.level_value_casing { - crate::Casing::Lowercase => event.metadata().level().to_string().to_lowercase(), - crate::Casing::Uppercase => event.metadata().level().to_string().to_uppercase(), - }; - - serializer - .serialize_entry(self.level_name, &level_str) - .map_err(Error::Serde)?; - - if matches!( - self.timestamp_format, - crate::TimestampFormat::Unix | crate::TimestampFormat::UnixMillis - ) { - serializer - .serialize_entry( - self.timestamp_name, - &self.timestamp_format.format_number(&now), - ) - .map_err(Error::Serde)?; - } else { - serializer - .serialize_entry( - self.timestamp_name, - &self.timestamp_format.format_string(&now), - ) - .map_err(Error::Serde)?; - } - - serializer - .serialize_entry(self.target_name, event.metadata().target()) - .map_err(Error::Serde)?; - - let msg_name = if self.message_name != DEFAULT_MESSAGE_NAME { - Some(self.message_name) - } else { - None - }; - - if self.flatten_fields { - // record fields in the top-level map - let mut visitor = visitor::Visitor::new(&mut serializer, msg_name); - event.record(&mut visitor); - visitor.finish().map_err(Error::Serde)?; - } else { - // record fields in a nested map under the key "fields" - let mut binding = serde_json::Serializer::pretty(Vec::new()); - let mut field_serializer = binding.serialize_map(None).map_err(Error::Serde)?; - let mut visitor = visitor::Visitor::new(&mut field_serializer, msg_name); - event.record(&mut visitor); - visitor.finish().map_err(Error::Serde)?; - field_serializer.end().map_err(Error::Serde)?; - - // Add the new map to the top-level map - let obj: Option = serde_json::from_str( - std::str::from_utf8(&binding.into_inner()).map_err(Error::Utf8)?, - ) - .ok(); - if matches!(obj, Some(serde_json::Value::Object(_))) { - let obj = obj.expect("matched object"); - serializer - .serialize_entry("fields", &obj) - .map_err(Error::Serde)?; - } - } - - // Write all fields from spans - if let Some(leaf_span) = ctx.lookup_current() { - for span in leaf_span.scope().from_root() { - let ext = span.extensions(); - let formatted_fields = ext - .get::>() - .expect("Unable to find FormattedFields in extensions; this is a bug"); - - // formatted_fields actually contains multiple ndjson objects, one for every time a spans fields are formatted. - // re-parse these into JSON for serialization into the final map. Any fields redefined in a subsequent span - // will overwrite the previous value. - // TODO(cmackenzie1): There has to be a better way to do this. - for data in formatted_fields.split('\n') { - if !data.is_empty() { - let obj: Option = serde_json::from_str(data).ok(); - if matches!(obj, Some(serde_json::Value::Object(_))) { - let obj = obj.expect("matched object"); - for (key, value) in obj.as_object().unwrap() { - serializer - .serialize_entry(key, value) - .map_err(Error::Serde)?; - } - } - } - } - } - } - - serializer.end().map_err(Error::Serde)?; - - writeln!( - writer, - "{}", - std::str::from_utf8(&binding.into_inner()).map_err(Error::Utf8)? - )?; - - Ok(()) - } -} - -pub struct FieldsFormatter {} - -impl FieldsFormatter { - pub fn new() -> Self { - Self {} - } -} - -impl Default for FieldsFormatter { - fn default() -> Self { - Self::new() - } -} - -impl<'writer> FormatFields<'writer> for FieldsFormatter { - fn format_fields(&self, mut writer: format::Writer<'writer>, fields: R) -> fmt::Result - where - R: tracing_subscriber::field::RecordFields, - { - let mut binding = serde_json::Serializer::new(Vec::new()); - let mut serializer = binding.serialize_map(None).map_err(Error::Serde)?; - let mut visitor = visitor::Visitor::new(&mut serializer, None); - - fields.record(&mut visitor); - - serializer.end().map_err(Error::Serde)?; - writeln!( - writer, - "{}", - std::str::from_utf8(&binding.into_inner()).map_err(Error::Utf8)? - )?; - - Ok(()) - } -} - -#[cfg(test)] -mod tests { - - use std::{ - io, - sync::{Arc, Mutex}, - }; - - use super::*; - use chrono::Utc; - use tracing::{info, info_span}; - use tracing_subscriber::fmt::MakeWriter; - - #[derive(Clone, Debug)] - struct MockWriter { - buf: Arc>>, - } - - #[derive(Clone, Debug)] - struct MockMakeWriter { - buf: Arc>>, - } - - impl MockMakeWriter { - fn new() -> Self { - Self { - buf: Arc::new(Mutex::new(Vec::new())), - } - } - fn get_content(&self) -> String { - let buf = self.buf.lock().unwrap(); - std::str::from_utf8(&buf[..]).unwrap().to_owned() - } - } - - impl MockWriter { - fn new(buf: Arc>>) -> Self { - Self { buf } - } - } - - impl io::Write for MockWriter { - fn write(&mut self, buf: &[u8]) -> io::Result { - self.buf.lock().unwrap().write(buf) - } - - fn flush(&mut self) -> io::Result<()> { - self.buf.lock().unwrap().flush() - } - } - - impl<'a> MakeWriter<'a> for MockMakeWriter { - type Writer = MockWriter; - - fn make_writer(&'a self) -> Self::Writer { - MockWriter::new(self.buf.clone()) - } - } - - fn subscriber( - make_writer: MockMakeWriter, - json_event_formatter: Option, - fields_formatter: Option, - ) -> tracing_subscriber::FmtSubscriber< - FieldsFormatter, - JsonEventFormatter, - tracing_core::LevelFilter, - MockMakeWriter, - > { - let json_event_formatter = json_event_formatter.unwrap_or(JsonEventFormatter::default()); - let field_formatter = fields_formatter.unwrap_or(FieldsFormatter::default()); - - tracing_subscriber::fmt::Subscriber::builder() - .event_format(json_event_formatter) - .fmt_fields(field_formatter) - .with_writer(make_writer) - .finish() - } - - fn get_json_object(content: &str) -> serde_json::Value { - let obj: Option = serde_json::from_str(content).ok(); - assert!(matches!(&obj, Some(serde_json::Value::Object(_)))); - obj.expect("matched object") - } - - #[test] - fn test_json_event_formatter() { - use tracing::subscriber; - - let mock_writer = MockMakeWriter::new(); - let subscriber = subscriber(mock_writer.clone(), None, None); - - subscriber::with_default(subscriber, || { - info!(life = 42, "Hello, world!"); - }); - - let obj = get_json_object(&mock_writer.get_content()); - - assert_eq!( - obj.get("level").unwrap(), - &serde_json::Value::String("info".to_owned()) - ); - assert_eq!( - obj.get("message").unwrap(), - &serde_json::Value::String("Hello, world!".to_owned()) - ); - assert_eq!( - obj.get("target").unwrap(), - &serde_json::Value::String("tracing_ndjson::formatter::tests".to_owned()) - ); - assert_eq!( - obj.get("life").unwrap(), - &serde_json::Value::Number(serde_json::Number::from(42)) - ); - - let timestamp = obj - .get("timestamp") - .unwrap() - .as_str() - .unwrap() - .parse::>() - .unwrap(); - assert!(timestamp > Utc::now() - chrono::Duration::seconds(1)); - } - - #[test] - fn test_json_event_formatter_span() { - use tracing::subscriber; - - let mock_writer = MockMakeWriter::new(); - let subscriber = subscriber(mock_writer.clone(), None, None); - - subscriber::with_default(subscriber, || { - let span = info_span!("hello", "request.uri" = "https://example.com"); - span.in_scope(|| { - info!("Hello, world!"); - }); - }); - - let obj = get_json_object(&mock_writer.get_content()); - - assert_eq!( - obj.get("level").unwrap(), - &serde_json::Value::String("info".to_owned()) - ); - assert_eq!( - obj.get("message").unwrap(), - &serde_json::Value::String("Hello, world!".to_owned()) - ); - assert_eq!( - obj.get("target").unwrap(), - &serde_json::Value::String("tracing_ndjson::formatter::tests".to_owned()) - ); - assert_eq!( - obj.get("request.uri").unwrap(), - &serde_json::Value::String("https://example.com".to_owned()) - ); - - let timestamp = obj - .get("timestamp") - .unwrap() - .as_str() - .unwrap() - .parse::>() - .unwrap(); - assert!(timestamp > Utc::now() - chrono::Duration::seconds(1)); - } - - #[test] - fn test_all_options() { - use tracing::subscriber; - - let mock_writer = MockMakeWriter::new(); - let subscriber = subscriber( - mock_writer.clone(), - Some( - JsonEventFormatter::default() - .with_level_name("severity") - .with_target_name("logger") - .with_message_name("msg") - .with_timestamp_name("ts") - .with_timestamp_format(crate::TimestampFormat::Unix) - .with_level_value_casing(crate::Casing::Uppercase), - ), - None, - ); - - subscriber::with_default(subscriber, || { - let span = info_span!("hello", "request.uri" = "https://example.com"); - span.in_scope(|| { - info!("Hello, world!"); - }); - }); - - let obj = get_json_object(&mock_writer.get_content()); - - assert_eq!( - obj.get("severity").unwrap(), - &serde_json::Value::String("INFO".to_owned()) - ); - assert_eq!( - obj.get("msg").unwrap(), - &serde_json::Value::String("Hello, world!".to_owned()) - ); - assert_eq!( - obj.get("logger").unwrap(), - &serde_json::Value::String("tracing_ndjson::formatter::tests".to_owned()) - ); - assert_eq!( - obj.get("request.uri").unwrap(), - &serde_json::Value::String("https://example.com".to_owned()) - ); - let timestamp = obj.get("ts").unwrap().as_i64().unwrap(); - assert!(timestamp > Utc::now().timestamp() - 1); - } -} diff --git a/src/layer.rs b/src/layer.rs new file mode 100644 index 0000000..f789358 --- /dev/null +++ b/src/layer.rs @@ -0,0 +1,193 @@ +use std::collections::HashMap; + +use serde_json::json; +use tracing_core::Subscriber; +use tracing_subscriber::{registry::LookupSpan, Layer}; + +use crate::{storage::JsonStorage, TimestampFormat}; + +pub struct JsonFormattingLayer { + pub(crate) level_name: &'static str, + pub(crate) level_value_casing: crate::Casing, + pub(crate) message_name: &'static str, + pub(crate) target_name: &'static str, + pub(crate) timestamp_name: &'static str, + pub(crate) timestamp_format: crate::TimestampFormat, + pub(crate) line_numbers: bool, + pub(crate) file_names: bool, + pub(crate) flatten_fields: bool, + pub(crate) flatten_spans: bool, +} + +impl Default for JsonFormattingLayer { + fn default() -> Self { + Self { + level_name: "level", + level_value_casing: crate::Casing::default(), + message_name: "message", + target_name: "target", + timestamp_name: "timestamp", + timestamp_format: crate::TimestampFormat::default(), + line_numbers: false, + file_names: false, + flatten_fields: true, + flatten_spans: true, + } + } +} + +impl Layer for JsonFormattingLayer +where + S: Subscriber + for<'a> LookupSpan<'a>, +{ + fn on_new_span( + &self, + attrs: &tracing_core::span::Attributes<'_>, + id: &tracing_core::span::Id, + ctx: tracing_subscriber::layer::Context<'_, S>, + ) { + let span = ctx.span(id).expect("Span not found, this is a bug"); + + // Create a new visitor to store fields + let mut visitor = JsonStorage::default(); + + // Register all fields. + // Fields on the new span should override fields on the parent span if there is a conflict. + attrs.record(&mut visitor); + + // Associate the visitor with the Span for future usage via the Span's extensions + let mut extensions = span.extensions_mut(); + extensions.insert(visitor); + } + + fn on_record( + &self, + span: &tracing_core::span::Id, + values: &tracing_core::span::Record<'_>, + ctx: tracing_subscriber::layer::Context<'_, S>, + ) { + let span = ctx.span(span).expect("Span not found, this is a bug"); + + // Before you can associate a record to an existing Span, well, that Span has to be created! + // We can thus rely on the invariant that we always associate a JsonVisitor with a Span + // on creation (`new_span` method), hence it's safe to unwrap the Option. + let mut extensions = span.extensions_mut(); + let visitor = extensions + .get_mut::() + .expect("Visitor not found on 'record', this is a bug"); + // Register all new fields + values.record(visitor); + } + + fn on_event( + &self, + event: &tracing_core::Event<'_>, + _ctx: tracing_subscriber::layer::Context<'_, S>, + ) { + // Record the event fields + let mut visitor = crate::storage::JsonStorage::default(); + event.record(&mut visitor); + + let mut root: HashMap<&str, serde_json::Value> = HashMap::new(); + + // level + root.insert( + self.level_name, + match self.level_value_casing { + crate::Casing::Lowercase => { + json!(event.metadata().level().to_string().to_lowercase()) + } + crate::Casing::Uppercase => { + json!(event.metadata().level().to_string().to_uppercase()) + } + }, + ); + + // target + root.insert(self.target_name, json!(event.metadata().target())); + + // timestamp + let timestamp = match &self.timestamp_format { + TimestampFormat::Unix | TimestampFormat::UnixMillis => { + json!(self.timestamp_format.format_number(&chrono::Utc::now())) + } + TimestampFormat::Rfc3339 | TimestampFormat::Rfc3339Nanos => { + json!(self.timestamp_format.format_string(&chrono::Utc::now())) + } + TimestampFormat::Custom(_) => { + json!(self.timestamp_format.format_string(&chrono::Utc::now())) + } + }; + root.insert(self.timestamp_name, timestamp); + + if self.file_names && event.metadata().file().is_some() { + root.insert("file", json!(event.metadata().file().expect("is some"))); + } + + if self.line_numbers && event.metadata().line().is_some() { + root.insert("line", json!(event.metadata().line().expect("is some"))); + } + + // Serialize the event fields + if self.flatten_fields { + visitor.values().iter().for_each(|(k, v)| { + if *k == "message" { + root.insert(self.message_name, v.clone()); + } else { + root.insert(k, v.clone()); + } + }); + } else { + let mut fields = HashMap::new(); + visitor.values().iter().for_each(|(k, v)| { + if *k == "message" { + fields.insert(self.message_name, v.clone()); + } else { + fields.insert(k, v.clone()); + } + }); + root.insert("fields", json!(fields)); + } + + // Span fields (if any) + let mut spans = vec![]; + if let Some(leaf_span) = _ctx.lookup_current() { + for span in leaf_span.scope().from_root() { + let mut fields = HashMap::new(); + let ext = span.extensions(); + let visitor = ext.get::(); + if let Some(visitor) = visitor { + visitor.values().iter().for_each(|(k, v)| { + if *k == "message" { + fields.insert(self.message_name, v.clone()); + } else { + fields.insert(k, v.clone()); + } + }); + } + if !fields.is_empty() { + spans.push(fields); + } + } + } + + if !spans.is_empty() { + if self.flatten_spans { + spans.iter().for_each(|fields| { + fields.iter().for_each(|(k, v)| { + if *k == "message" { + root.insert(self.message_name, v.clone()); + } else { + root.insert(k, v.clone()); + } + }); + }); + } else { + root.insert("spans", json!(spans)); + } + } + + let output = serde_json::to_string(&root).unwrap(); + println!("{}", output); + } +} diff --git a/src/lib.rs b/src/lib.rs index e1e7f4a..e855e75 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -4,11 +4,23 @@ //! //! A simple library for tracing in new-line delimited JSON format. This library is meant to be used with [tracing](https://github.com/tokio-rs/tracing) as an alternative to the `tracing_subscriber::fmt::json` formatter. //! +//! The goal of this crate is to provide a flattend JSON event, comprising of fields from the span attributes and event fields, with customizeable field names and timestamp formats. +//! //! ## Features //! //! - Configurable field names for `target`, `message`, `level`, and `timestamp`. -//! - Configurable timestamp formats such as RFC3339, UNIX timestamp, or any custom chrono format. -//! - Captures all span attributes and event fields in the root of the JSON object. +//! - Configurable timestamp formats +//! - RFC3339 (`2023-10-08T03:30:52Z`), +//! - RFC339Nanos (`2023-10-08T03:30:52.123456789Z`) +//! - Unix timestamp (`1672535452`) +//! - UnixMills (`1672535452123`) +//! - Captures all span attributes and event fields in the root of the JSON object. Collisions will result in overwriting the existing field. +//! +//! ## Limitations +//! +//! - When flattening span attributes and event fields, the library will overwrite any existing fields with the same name, including the built-in fields such as `target`, `message`, `level`, `timestamp`, `file`, and `line`. +//! - Non-determistic ordering of fields in the JSON object. ([JSON objects are unordered](https://www.json.org/json-en.html)) +//! - Currently only logs to stdout. (PRs welcome!) //! //! ## Usage //! @@ -17,21 +29,23 @@ //! ```toml //! [dependencies] //! tracing = "0.1" -//! tracing-ndjson = "0.1" +//! tracing-ndjson = "0.2" //! ``` //! //! ```rust //! use tracing_subscriber::prelude::*; //! -//! tracing_subscriber::registry() -//! .with(tracing_ndjson::builder().layer()) -//! .init(); +//! let subscriber = tracing_subscriber::registry().with(tracing_ndjson::layer()); +//! +//! tracing::subscriber::set_global_default(subscriber).unwrap(); +//! //! tracing::info!(life = 42, "Hello, world!"); -//! // {"level":"info","timestamp":"2023-10-08T03:30:52Z","target":"default","message":"Hello, world!"} +//! // {"level":"info","target":"default","life":42,"timestamp":"2023-10-20T21:17:49Z","message":"Hello, world!"} +//! //! let span = tracing::info_span!("hello", "request.uri" = "https://example.com"); //! span.in_scope(|| { //! tracing::info!("Hello, world!"); -//! // {"level":"info","timestamp":"2023-10-08T03:34:33Z","target":"defaults","message":"Hello, world!","request.uri":"https://example.com"} +//! // {"message":"Hello, world!","request.uri":"https://example.com","level":"info","target":"default","timestamp":"2023-10-20T21:17:49Z"} //! }); //! ``` //! @@ -41,24 +55,26 @@ //! //! ## License //! -//! Licensed under MIT license [LICENSE](./LICENSE) -mod formatter; -mod visitor; +//! Licensed under [MIT license](./LICENSE) +mod layer; +mod storage; + +pub use layer::*; use tracing_core::Subscriber; -use tracing_subscriber::fmt::{Layer, SubscriberBuilder}; use tracing_subscriber::registry::LookupSpan; /// A timestamp format for the JSON formatter. /// This is used to format the timestamp field in the JSON output. /// The default is RFC3339. -#[derive(Debug)] +#[derive(Debug, Default)] pub enum TimestampFormat { /// Seconds since UNIX_EPOCH Unix, /// Milliseconds since UNIX_EPOCH UnixMillis, /// RFC3339 + #[default] Rfc3339, /// RFC3339 with nanoseconds Rfc3339Nanos, @@ -90,7 +106,9 @@ impl TimestampFormat { } } +#[derive(Debug, Default)] pub enum Casing { + #[default] Lowercase, Uppercase, } @@ -120,7 +138,10 @@ impl From for std::fmt::Error { /// * target_name: "target" /// * timestamp_name: "timestamp" /// * timestamp_format: TimestampFormat::Rfc3339 +/// * line_numbers: false +/// * file_names: false /// * flatten_fields: true +/// * flatten_spans: true /// /// # Examples /// @@ -131,7 +152,7 @@ impl From for std::fmt::Error { /// .with( /// tracing_ndjson::Builder::default() /// .with_level_name("severity") -/// .with_level_value_casing(tracing_ndjson::Casing::Uppercase) +/// .with_level_value_casing(tracing_ndjson::Casing::Uppercase) /// .with_message_name("msg") /// .with_timestamp_name("ts") /// .with_timestamp_format(tracing_ndjson::TimestampFormat::Unix) @@ -140,15 +161,13 @@ impl From for std::fmt::Error { /// /// tracing::info!(life = 42, "Hello, world!"); pub struct Builder { - events: formatter::JsonEventFormatter, - fields: formatter::FieldsFormatter, + layer: crate::JsonFormattingLayer, } impl Builder { pub fn new() -> Self { Self { - events: formatter::JsonEventFormatter::new(), - fields: formatter::FieldsFormatter::new(), + layer: crate::JsonFormattingLayer::default(), } } } @@ -169,68 +188,75 @@ impl Builder { /// Set the field name for the level field. /// The default is "level". pub fn with_level_name(mut self, level_name: &'static str) -> Self { - self.events = self.events.with_level_name(level_name); + self.layer.level_name = level_name; self } /// Set the casing for the level field value. /// The default is Casing::Lowercase. pub fn with_level_value_casing(mut self, casing: Casing) -> Self { - self.events = self.events.with_level_value_casing(casing); + self.layer.level_value_casing = casing; self } /// Set the field name for the message field. /// The default is "message". pub fn with_message_name(mut self, message_name: &'static str) -> Self { - self.events = self.events.with_message_name(message_name); + self.layer.message_name = message_name; self } /// Set the field name for the target field. /// The default is "target". pub fn with_target_name(mut self, target_name: &'static str) -> Self { - self.events = self.events.with_target_name(target_name); + self.layer.target_name = target_name; self } /// Set the field name for the timestamp field. /// The default is "timestamp". pub fn with_timestamp_name(mut self, timestamp_name: &'static str) -> Self { - self.events = self.events.with_timestamp_name(timestamp_name); + self.layer.timestamp_name = timestamp_name; self } /// Set the timestamp format for the timestamp field. /// The default is TimestampFormat::Rfc3339. pub fn with_timestamp_format(mut self, timestamp_format: TimestampFormat) -> Self { - self.events = self.events.with_timestamp_format(timestamp_format); + self.layer.timestamp_format = timestamp_format; self } /// Set whether to flatten fields. /// The default is true. If false, fields will be nested under a "fields" object. pub fn with_flatten_fields(mut self, flatten_fields: bool) -> Self { - self.events = self.events.with_flatten_fields(flatten_fields); + self.layer.flatten_fields = flatten_fields; + self + } + + /// Set whether to flatten spans. + pub fn with_flatten_spans(mut self, flatten_spans: bool) -> Self { + self.layer.flatten_spans = flatten_spans; + self + } + + /// Set whether to include line numbers. + pub fn with_line_numbers(mut self, line_numbers: bool) -> Self { + self.layer.line_numbers = line_numbers; + self + } + + /// Set whether to include file names. + pub fn with_file_names(mut self, file_names: bool) -> Self { + self.layer.file_names = file_names; self } - /// Return a `Layer` that subscribes to all spans and events using the defined formatter. - pub fn layer(self) -> Layer + pub fn layer(self) -> impl tracing_subscriber::Layer where S: Subscriber + for<'a> LookupSpan<'a>, { - tracing_subscriber::fmt::layer() - .fmt_fields(self.fields) - .event_format(self.events) - } - - pub fn subscriber_builder( - self, - ) -> SubscriberBuilder { - tracing_subscriber::fmt::Subscriber::builder() - .event_format(self.events) - .fmt_fields(self.fields) + self.layer } } @@ -240,17 +266,17 @@ pub fn layer() -> impl tracing_subscriber::Layer where S: Subscriber + for<'a> LookupSpan<'a>, { - crate::builder().layer() + crate::builder().layer } #[cfg(test)] mod tests { - use super::*; - use tracing::{debug, error, info, info_span, instrument, trace, warn}; use tracing_subscriber::prelude::*; + use super::*; + #[instrument] fn some_function(a: u32, b: u32) { let span = info_span!("some_span", a = a, b = b); diff --git a/src/storage.rs b/src/storage.rs new file mode 100644 index 0000000..de541f9 --- /dev/null +++ b/src/storage.rs @@ -0,0 +1,62 @@ +use std::collections::BTreeMap; +use std::fmt; + +use tracing_core::{field::Visit, Field}; + +#[derive(Debug, Default)] +pub(crate) struct JsonStorage<'a> { + pub(crate) values: BTreeMap<&'a str, serde_json::Value>, +} + +impl<'a> JsonStorage<'a> { + pub(crate) fn values(&self) -> &BTreeMap<&'a str, serde_json::Value> { + &self.values + } +} + +impl Visit for JsonStorage<'_> { + /// Visit a signed 64-bit integer value. + fn record_i64(&mut self, field: &Field, value: i64) { + self.values + .insert(field.name(), serde_json::Value::from(value)); + } + + /// Visit an unsigned 64-bit integer value. + fn record_u64(&mut self, field: &Field, value: u64) { + self.values + .insert(field.name(), serde_json::Value::from(value)); + } + + /// Visit a 64-bit floating point value. + fn record_f64(&mut self, field: &Field, value: f64) { + self.values + .insert(field.name(), serde_json::Value::from(value)); + } + + /// Visit a boolean value. + fn record_bool(&mut self, field: &Field, value: bool) { + self.values + .insert(field.name(), serde_json::Value::from(value)); + } + + /// Visit a string 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() { + // Skip fields that are actually log metadata that have already been handled + 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))); + } + }; + } +} diff --git a/src/visitor.rs b/src/visitor.rs deleted file mode 100644 index 803c1f1..0000000 --- a/src/visitor.rs +++ /dev/null @@ -1,124 +0,0 @@ -use tracing_core::field::Visit; - -pub struct Visitor<'a, W> -where - W: serde::ser::SerializeMap, -{ - serializer: &'a mut W, - state: Result<(), W::Error>, - overwrite_message_name: Option<&'static str>, -} - -impl<'a, W> Visitor<'a, W> -where - W: serde::ser::SerializeMap, -{ - pub fn new(serializer: &'a mut W, overwrite_message_name: Option<&'static str>) -> Self { - Self { - serializer, - state: Ok(()), - overwrite_message_name, - } - } - - pub fn finish(self) -> Result<(), W::Error> { - self.state - } - - /// Serialize a key-value pair, replacing the message field if overwrite_message_name is set. - pub fn serialize_entry(&mut self, key: &str, value: V) -> Result<(), W::Error> - where - V: serde::Serialize, - { - if self.overwrite_message_name.is_some() && key == "message" { - self.serializer - .serialize_entry(self.overwrite_message_name.expect("message"), &value) - } else { - self.serializer.serialize_entry(key, &value) - } - } -} - -impl<'a, W> Visit for Visitor<'a, W> -where - W: serde::ser::SerializeMap, -{ - fn record_f64(&mut self, field: &tracing_core::Field, value: f64) { - if self.state.is_ok() { - self.state = self.serialize_entry(field.name(), value) - } - } - - fn record_i64(&mut self, field: &tracing_core::Field, value: i64) { - if self.state.is_ok() { - self.state = self.serialize_entry(field.name(), value) - } - } - - fn record_u64(&mut self, field: &tracing_core::Field, value: u64) { - if self.state.is_ok() { - self.state = self.serialize_entry(field.name(), value) - } - } - - fn record_i128(&mut self, field: &tracing_core::Field, value: i128) { - if self.state.is_ok() { - self.state = self.serialize_entry(field.name(), value) - } - } - - fn record_u128(&mut self, field: &tracing_core::Field, value: u128) { - if self.state.is_ok() { - self.state = self.serialize_entry(field.name(), value) - } - } - - fn record_bool(&mut self, field: &tracing_core::Field, value: bool) { - if self.state.is_ok() { - self.state = self.serialize_entry(field.name(), value) - } - } - - fn record_str(&mut self, field: &tracing_core::Field, value: &str) { - if self.state.is_ok() { - self.state = self.serialize_entry(field.name(), value) - } - } - - fn record_error( - &mut self, - field: &tracing_core::Field, - value: &(dyn std::error::Error + 'static), - ) { - if self.state.is_ok() { - self.state = self.serialize_entry(field.name(), &value.to_string()) - } - } - - fn record_debug(&mut self, field: &tracing_core::Field, value: &dyn std::fmt::Debug) { - if self.state.is_ok() { - self.state = self.serialize_entry(field.name(), &format!("{:?}", value)) - } - } -} - -#[cfg(test)] -mod tests { - use serde::{ser::SerializeMap, Serializer}; - - #[test] - fn test_overwrite_message_name() { - use super::Visitor; - - let mut binding = serde_json::Serializer::new(Vec::new()); - let mut serializer = binding.serialize_map(None).unwrap(); - let mut visitor = Visitor::new(&mut serializer, Some("msg")); - - let _ = visitor.serialize_entry("message", "hello"); - visitor.finish().unwrap(); - serializer.end().unwrap(); - - let result = String::from_utf8(binding.into_inner()).unwrap(); - assert_eq!(result, r#"{"msg":"hello"}"#); - } -}