Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

feat(spdlog): impl JsonFormatter #69

Merged
merged 20 commits into from
Aug 5, 2024
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension


Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
6 changes: 3 additions & 3 deletions .github/workflows/ci.yml
Original file line number Diff line number Diff line change
Expand Up @@ -19,7 +19,7 @@ env:
# - src/lib.rs
# - Cargo.toml
# - README.md
rust_minver: 1.56.0
rust_minver: 1.60.0

defaults:
run:
Expand Down Expand Up @@ -49,7 +49,7 @@ jobs:
fail-fast: false
matrix:
os: ['ubuntu-latest', 'windows-latest', 'macos-latest']
fn_features: ['', 'log native libsystemd multi-thread runtime-pattern']
fn_features: ['', 'log native libsystemd multi-thread runtime-pattern serde_json']
cfg_feature: ['', 'flexible-string', 'source-location']
runs-on: ${{ matrix.os }}
steps:
Expand Down Expand Up @@ -212,7 +212,7 @@ jobs:
- name: Restore cargo caches
uses: Swatinem/rust-cache@v2
- name: Run benchmark
run: cargo +nightly bench --features "multi-thread,runtime-pattern" --bench spdlog_rs --bench spdlog_rs_pattern | tee bench-results.txt
run: cargo +nightly bench --features "multi-thread,runtime-pattern,serde_json" --bench spdlog_rs --bench spdlog_rs_pattern | tee bench-results.txt
- name: Discard irrelevant changes
run: git checkout -- spdlog/Cargo.toml
- name: Process results
Expand Down
2 changes: 1 addition & 1 deletion README.md
Original file line number Diff line number Diff line change
Expand Up @@ -46,7 +46,7 @@ When updating this, also update:
- Cargo.toml
-->

The current minimum supported Rust version is 1.56.
The current minimum supported Rust version is 1.60.

`spdlog-rs` is built against the latest Rust stable release, it is not guaranteed to build on Rust versions earlier than the minimum supported version.

Expand Down
2 changes: 1 addition & 1 deletion spdlog-internal/Cargo.toml
Original file line number Diff line number Diff line change
Expand Up @@ -2,7 +2,7 @@
name = "spdlog-internal"
version = "0.1.0"
edition = "2021"
rust-version = "1.56"
rust-version = "1.60"

[dependencies]
nom = "7.1.3"
Expand Down
2 changes: 1 addition & 1 deletion spdlog-macros/Cargo.toml
Original file line number Diff line number Diff line change
Expand Up @@ -2,7 +2,7 @@
name = "spdlog-macros"
version = "0.1.0"
edition = "2021"
rust-version = "1.56"
rust-version = "1.60"
description = "Macros implementation of crate \"spdlog-rs\""
repository = "https://github.com/SpriteOvO/spdlog-rs"
license = "MIT OR Apache-2.0"
Expand Down
6 changes: 5 additions & 1 deletion spdlog/Cargo.toml
Original file line number Diff line number Diff line change
Expand Up @@ -2,7 +2,7 @@
name = "spdlog-rs"
version = "0.3.13"
edition = "2021"
rust-version = "1.56"
rust-version = "1.60"
description = "A fast and combinable Rust logging crate, inspired by the C++ logging library spdlog"
repository = "https://github.com/SpriteOvO/spdlog-rs"
license = "MIT OR Apache-2.0"
Expand Down Expand Up @@ -37,6 +37,7 @@ native = []
libsystemd = ["libsystemd-sys"]
multi-thread = ["crossbeam"]
runtime-pattern = ["spdlog-internal"]
serde_json = ["serde", "dep:serde_json"]

[dependencies]
arc-swap = "1.5.1"
Expand All @@ -50,6 +51,8 @@ if_chain = "1.0.2"
is-terminal = "0.4"
log = { version = "0.4.8", optional = true }
once_cell = "1.16.0"
serde = { version = "1.0.163", optional = true, features = ["derive"] }
serde_json = { version = "1.0.120", optional = true }
spdlog-internal = { version = "=0.1.0", path = "../spdlog-internal", optional = true }
spdlog-macros = { version = "0.1.0", path = "../spdlog-macros" }
spin = "0.9.8"
Expand Down Expand Up @@ -106,6 +109,7 @@ harness = false
[[bench]]
name = "spdlog_rs_pattern"
path = "benches/spdlog-rs/pattern.rs"
required-features = ["runtime-pattern", "serde_json"]
[[bench]]
name = "fast_log"
path = "benches/fast_log/main.rs"
Expand Down
8 changes: 8 additions & 0 deletions spdlog/benches/spdlog-rs/pattern.rs
Original file line number Diff line number Diff line change
Expand Up @@ -5,6 +5,8 @@ extern crate test;
use std::{cell::RefCell, sync::Arc};

use paste::paste;
#[cfg(feature = "serde_json")]
use spdlog::formatter::JsonFormatter;
use spdlog::{
formatter::{pattern, Formatter, FullFormatter, Pattern, PatternFormatter},
prelude::*,
Expand Down Expand Up @@ -104,6 +106,12 @@ fn bench_1_full_formatter(bencher: &mut Bencher) {
bench_formatter(bencher, FullFormatter::new())
}

#[cfg(feature = "serde_json")]
#[bench]
fn bench_1_json_formatter(bencher: &mut Bencher) {
bench_formatter(bencher, JsonFormatter::new())
}

#[bench]
fn bench_2_full_pattern_ct(bencher: &mut Bencher) {
bench_full_pattern(
Expand Down
7 changes: 7 additions & 0 deletions spdlog/src/error.rs
Original file line number Diff line number Diff line change
Expand Up @@ -98,6 +98,13 @@ pub enum Error {
#[error("failed to build pattern at runtime: {0}")]
BuildPattern(BuildPatternError),

/// Returned by [`Formatter`]s when an error occurs in serializing a log.
///
/// [`Formatter`]: crate::formatter::Formatter
#[cfg(feature = "serde")]
#[error("failed to serialize log: {0}")]
SerializeRecord(io::Error),

/// Returned when multiple errors occurred.
#[error("{0:?}")]
Multiple(Vec<Error>),
Expand Down
258 changes: 258 additions & 0 deletions spdlog/src/formatter/json_formatter.rs
Original file line number Diff line number Diff line change
@@ -0,0 +1,258 @@
use std::{
fmt::{self, Write},
marker::PhantomData,
time::SystemTime,
};

use cfg_if::cfg_if;
use serde::{ser::SerializeStruct, Serialize};

use crate::{
formatter::{FmtExtraInfo, Formatter},
Error, Record, StringBuf, __EOL,
};

struct JsonRecord<'a>(&'a Record<'a>);

impl<'a> Serialize for JsonRecord<'a> {
fn serialize<S>(&self, serializer: S) -> Result<S::Ok, S::Error>
where
S: serde::Serializer,
{
let src_loc = self.0.source_location();

let mut record =
serializer.serialize_struct("JsonRecord", if src_loc.is_none() { 4 } else { 5 })?;

record.serialize_field("level", &self.0.level())?;
record.serialize_field(
"timestamp",
&self
.0
.time()
.duration_since(SystemTime::UNIX_EPOCH)
.ok()
// https://github.com/SpriteOvO/spdlog-rs/pull/69#discussion_r1694063293
.and_then(|dur| u64::try_from(dur.as_millis()).ok())
.expect("invalid timestamp"),
)?;
record.serialize_field("payload", self.0.payload())?;
if let Some(logger_name) = self.0.logger_name() {
record.serialize_field("logger", logger_name)?;
}
record.serialize_field("tid", &self.0.tid())?;
if let Some(src_loc) = src_loc {
record.serialize_field("source", src_loc)?;
}

record.end()
}
}

impl<'a> From<&'a Record<'a>> for JsonRecord<'a> {
fn from(value: &'a Record<'a>) -> Self {
JsonRecord(value)
}
}

enum JsonFormatterError {
Fmt(fmt::Error),
Serialization(serde_json::Error),
}

impl From<fmt::Error> for JsonFormatterError {
fn from(value: fmt::Error) -> Self {
JsonFormatterError::Fmt(value)
}
}

impl From<serde_json::Error> for JsonFormatterError {
fn from(value: serde_json::Error) -> Self {
JsonFormatterError::Serialization(value)
}
}

impl From<JsonFormatterError> for crate::Error {
fn from(value: JsonFormatterError) -> Self {
match value {
JsonFormatterError::Fmt(e) => Error::FormatRecord(e),
JsonFormatterError::Serialization(e) => Error::SerializeRecord(e.into()),
}
}
}

#[rustfmt::skip]
/// JSON logs formatter.
///
/// Each log will be serialized into a single line of JSON object with the following schema.
///
/// ## Schema
///
/// | Field | Type | Description |
/// |-------------|--------------|--------------------------------------------------------------------------------------------------------------------------------|
/// | `level` | String | The level of the log. Same as the return of [`Level::as_str`]. |
/// | `timestamp` | Integer(u64) | The timestamp when the log was generated, in milliseconds since January 1, 1970 00:00:00 UTC. |
/// | `payload` | String | The contents of the log. |
/// | `logger` | String/Null | The name of the logger. Null if the logger has no name. |
/// | `tid` | Integer(u64) | The thread ID when the log was generated. |
/// | `source` | Object/Null | The source location of the log. See [`SourceLocation`] for its schema. Null if crate feature `source-location` is not enabled. |
///
/// <div class="warning">
///
/// - If the type of a field is Null, the field will not be present or be `null`.
///
/// - The order of the fields is not guaranteed.
///
/// </div>
///
/// ---
///
/// ## Examples
///
/// - Default:
///
/// ```json
/// {"level":"Info","timestamp":1722817424798,"payload":"hello, world!","tid":3472525}
/// {"level":"Error","timestamp":1722817424798,"payload":"something went wrong","tid":3472525}
/// ```
///
/// - If the logger has a name:
///
/// ```json
/// {"level":"Info","timestamp":1722817541459,"payload":"hello, world!","logger":"app-component","tid":3478045}
/// {"level":"Error","timestamp":1722817541459,"payload":"something went wrong","logger":"app-component","tid":3478045}
/// ```
///
/// - If crate feature `source-location` is enabled:
///
/// ```json
/// {"level":"Info","timestamp":1722817572709,"payload":"hello, world!","tid":3479856,"source":{"module_path":"my_app::say_hi","file":"src/say_hi.rs","line":4,"column":5}}
/// {"level":"Error","timestamp":1722817572709,"payload":"something went wrong","tid":3479856,"source":{"module_path":"my_app::say_hi","file":"src/say_hi.rs","line":5,"column":5}}
/// ```
///
/// [`Level::as_str`]: crate::Level::as_str
/// [`SourceLocation`]: crate::SourceLocation
#[derive(Clone)]
pub struct JsonFormatter(PhantomData<()>);

impl JsonFormatter {
/// Constructs a `JsonFormatter`.
#[must_use]
pub fn new() -> JsonFormatter {
SpriteOvO marked this conversation as resolved.
Show resolved Hide resolved
JsonFormatter(PhantomData)
}

fn format_impl(
&self,
record: &Record,
dest: &mut StringBuf,
) -> Result<FmtExtraInfo, JsonFormatterError> {
cfg_if! {
if #[cfg(not(feature = "flexible-string"))] {
dest.reserve(crate::string_buf::RESERVE_SIZE);
}
}

let json_record: JsonRecord = record.into();

// TODO: https://github.com/serde-rs/json/issues/863
//
// The performance can be significantly optimized here if the issue can be
// solved.
dest.write_str(&serde_json::to_string(&json_record)?)?;
Copy link
Owner

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Leaving this comment as a note.

test bench_1_full_formatter       ... bench:          90.39 ns/iter (+/- 9.58)
test bench_1_json_formatter       ... bench:         121.27 ns/iter (+/- 9.10)

I benchmarked JsonFormatter and I was expecting it to be faster than that (close to FullFormatter). After a quick check, the String returned by serde::to_string will do unnecessary allocation and should be optimized out.

Unfortunately, due to the serde_json API limitation (serde-rs/json#863), this is currently not possible (at least not without using unsafe).


dest.write_str(__EOL)?;

Ok(FmtExtraInfo { style_range: None })
}
}

impl Formatter for JsonFormatter {
fn format(&self, record: &Record, dest: &mut StringBuf) -> crate::Result<FmtExtraInfo> {
self.format_impl(record, dest).map_err(Into::into)
}
}

impl Default for JsonFormatter {
fn default() -> Self {
JsonFormatter::new()
}
}

#[cfg(test)]
mod tests {
use chrono::prelude::*;

use super::*;
use crate::{Level, SourceLocation, __EOL};

#[test]
fn should_format_json() {
let mut dest = StringBuf::new();
let formatter = JsonFormatter::new();
let record = Record::builder(Level::Info, "payload").build();
let extra_info = formatter.format(&record, &mut dest).unwrap();

let local_time: DateTime<Local> = record.time().into();

assert_eq!(extra_info.style_range, None);
assert_eq!(
dest.to_string(),
format!(
r#"{{"level":"info","timestamp":{},"payload":"{}","tid":{}}}{}"#,
local_time.timestamp_millis(),
"payload",
record.tid(),
__EOL
)
);
}

#[test]
fn should_format_json_with_logger_name() {
let mut dest = StringBuf::new();
let formatter = JsonFormatter::new();
let record = Record::builder(Level::Info, "payload")
.logger_name("my-component")
.build();
let extra_info = formatter.format(&record, &mut dest).unwrap();

let local_time: DateTime<Local> = record.time().into();

assert_eq!(extra_info.style_range, None);
assert_eq!(
dest.to_string(),
format!(
r#"{{"level":"info","timestamp":{},"payload":"{}","logger":"my-component","tid":{}}}{}"#,
local_time.timestamp_millis(),
"payload",
record.tid(),
__EOL
)
);
}

#[test]
fn should_format_json_with_src_loc() {
let mut dest = StringBuf::new();
let formatter = JsonFormatter::new();
let record = Record::builder(Level::Info, "payload")
.source_location(Some(SourceLocation::__new("module", "file.rs", 1, 2)))
.build();
let extra_info = formatter.format(&record, &mut dest).unwrap();

let local_time: DateTime<Local> = record.time().into();

assert_eq!(extra_info.style_range, None);
assert_eq!(
dest.to_string(),
format!(
r#"{{"level":"info","timestamp":{},"payload":"{}","tid":{},"source":{{"module_path":"module","file":"file.rs","line":1,"column":2}}}}{}"#,
local_time.timestamp_millis(),
"payload",
record.tid(),
__EOL
)
);
}
}
Loading