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 13 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
4 changes: 2 additions & 2 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
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
5 changes: 4 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
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
190 changes: 190 additions & 0 deletions spdlog/src/formatter/json_formatter.rs
Original file line number Diff line number Diff line change
@@ -0,0 +1,190 @@
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)
.expect("invalid timestamp")
.as_secs()
.to_string(),
)?;
Copy link
Owner

@SpriteOvO SpriteOvO Jul 28, 2024

Choose a reason for hiding this comment

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

Suggested change
record.serialize_field(
"timestamp",
&self
.0
.time()
.duration_since(SystemTime::UNIX_EPOCH)
.expect("invalid timestamp")
.as_secs()
.to_string(),
)?;
record.serialize_field(
"timestamp",
self
.0
.time()
.duration_since(SystemTime::UNIX_EPOCH)
.ok()
.and_then(|dur| u64::try_from(dur.as_millis()).ok())
.expect("invalid timestamp"),
)?;

I've discussed with @NotEvenANeko about this in private messages.

Initially I simply thought that UNIX timestamp would be OK, but then realized that it is in seconds, which is obviously not precise enough for logging. After some investigation, I think a millisecond timestamp might be more appropriate, based on the following clues:

  • I prefer not to format it to a human-readable string (e.g. ISO 8601 / RFC 3339) because JSON will eventually be parsed by a machine. And the performance of date-time formatting is quite bad for both serialization and deserialization.

  • in JavaScript, Date::now and the constructor of Date returns and accepts a number of milliseconds since January 1, 1970 00:00:00 UTC, with leap seconds ignored.

  • most programming languages have time libraries that support parsing millisecond timestamps directly or indirectly.

  • nanoseconds are more precise, but it uses more significant integer digits, and perhaps this precision is unnecessary.

Since this integer will eventually be expressed in JSON, and Duration::as_millis returns a u128, we need to convert it to u64 to express it in JSON. Although the maximum safe type for JSON integers in JavaScript is i53, I tested it with Rust chrono crate, and the maximum millisecond timestamp it supports parsing doesn't even exceed i53::MAX, and that maximum timestamp has reached the year 262142. So in my opinion, representing it as a string is not necessary for the foreseeable future.

extern crate chrono; // 0.4.38

use chrono::prelude::*;

fn main() {
    const JS_MAX_SAFE_INTEGER: i64 = 9007199254740991;
    let max_utc = DateTime::<Utc>::MAX_UTC;
    let max_timestamp = max_utc.timestamp_millis();
    println!("Max UTC supported by chrono   : {}", max_utc);
    println!("Max timestamp in millisecond  : {}", max_timestamp);
    println!("Max safe integer in JavaScript: {}", JS_MAX_SAFE_INTEGER);
    println!("Max u64                       : {}", u64::MAX);
    assert!(max_timestamp <= JS_MAX_SAFE_INTEGER);
}
Max UTC supported by chrono   : +262142-12-31 23:59:59.999999999 UTC
Max timestamp in millisecond  : 8210266876799999
Max safe integer in JavaScript: 9007199254740991
Max u64                       : 18446744073709551615

Using u64::try_from rather than as u64 here so we can catch the overflow error instead of implicit truncation.

record.serialize_field("tid", &self.0.tid())?;
record.serialize_field("payload", self.0.payload())?;

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
Copy link
Owner

Choose a reason for hiding this comment

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

Suggested change
/// JSON logs formatter
#[rustfmt::skip]
/// JSON logs formatter

The doc formatting seems to be broken by Rustfmt, try adding a #[rustfmt::skip] on it.

///
/// Output format:
///
/// ```json
/// {"level":"info","timestamp":"2024-01-01
/// 12:00:00","tid":123456,"payload":"test"}
///
/// // with source location
/// {"level":"info","timestamp":"2024-01-01
/// 12:00:00","tid":123456,"payload":"test","source_location":{"module_path":"
/// module","file":"file.rs","line":42}}
/// ```
#[derive(Clone)]
pub struct JsonFormatter(PhantomData<()>);

impl JsonFormatter {
/// Create 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();

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":"{}","tid":{},"payload":"{}"}}{}"#,
local_time.timestamp(),
record.tid(),
"payload",
__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":"{}","tid":{},"payload":"{}","source":{{"module_path":"module","file":"file.rs","line":1,"column":2}}}}{}"#,
local_time.timestamp(),
record.tid(),
"payload",
__EOL
)
);
}
}
4 changes: 4 additions & 0 deletions spdlog/src/formatter/mod.rs
Original file line number Diff line number Diff line change
Expand Up @@ -54,6 +54,8 @@ mod full_formatter;
all(doc, not(doctest))
))]
mod journald_formatter;
#[cfg(feature = "serde_json")]
mod json_formatter;
mod local_time_cacher;
mod pattern_formatter;

Expand All @@ -66,6 +68,8 @@ pub use full_formatter::*;
all(doc, not(doctest))
))]
pub(crate) use journald_formatter::*;
#[cfg(feature = "serde_json")]
pub use json_formatter::*;
pub(crate) use local_time_cacher::*;
pub use pattern_formatter::*;

Expand Down
1 change: 1 addition & 0 deletions spdlog/src/level.rs
Original file line number Diff line number Diff line change
Expand Up @@ -52,6 +52,7 @@ const LOG_LEVEL_SHORT_NAMES: [&str; Level::count()] = ["C", "E", "W", "I", "D",
/// [`log!`]: crate::log!
#[repr(u16)]
#[derive(Copy, Clone, Eq, PartialEq, Hash, Debug)]
#[cfg_attr(feature = "serde", derive(serde::Serialize))]
pub enum Level {
/// Designates critical errors.
Critical = 0,
Expand Down
2 changes: 1 addition & 1 deletion spdlog/src/lib.rs
Original file line number Diff line number Diff line change
Expand Up @@ -216,7 +216,7 @@
//! - README.md
//! -->
//!
//! 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
Expand Down
2 changes: 2 additions & 0 deletions spdlog/src/record.rs
Original file line number Diff line number Diff line change
Expand Up @@ -21,13 +21,15 @@ use crate::{Level, SourceLocation};
// FIXME: `Record` still owns some data and not just a reference, I'm not sure this is necessary and
// possible to correct.
#[derive(Clone, Debug)]
#[cfg_attr(feature = "serde", derive(serde::Serialize))]
pub struct Record<'a> {
logger_name: Option<Cow<'a, str>>,
payload: Cow<'a, str>,
inner: Cow<'a, RecordInner>,
}

#[derive(Clone, Debug)]
#[cfg_attr(feature = "serde", derive(serde::Serialize))]
struct RecordInner {
level: Level,
source_location: Option<SourceLocation>,
Expand Down
1 change: 0 additions & 1 deletion spdlog/src/sink/rotating_file_sink.rs
Original file line number Diff line number Diff line change
Expand Up @@ -648,7 +648,6 @@ impl TimePoint {

#[must_use]
fn delta_chrono(&self) -> chrono::Duration {
#[allow(deprecated)] // For keeping the current MSRV 1.56.0
match self {
Self::Daily { .. } => chrono::Duration::days(1),
Self::Hourly { .. } => chrono::Duration::hours(1),
Expand Down
1 change: 1 addition & 0 deletions spdlog/src/source_location.rs
Original file line number Diff line number Diff line change
Expand Up @@ -7,6 +7,7 @@ use std::path;
///
/// [`source_location_current`]: crate::source_location_current
#[derive(Clone, Hash, Debug)]
#[cfg_attr(feature = "serde", derive(serde::Serialize))]
pub struct SourceLocation {
module_path: &'static str,
file: &'static str,
Expand Down
Loading