diff --git a/Cargo.lock b/Cargo.lock index a0de50b56d..1364104562 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -6640,6 +6640,7 @@ dependencies = [ "cargo_metadata 0.19.2", "celes", "chacha", + "chrono", "clap", "colored", "criterion", @@ -6707,6 +6708,7 @@ dependencies = [ "tracing-core", "tracing-indicatif", "tracing-opentelemetry", + "tracing-serde", "tracing-subscriber", "url", "utoipa", diff --git a/Cargo.toml b/Cargo.toml index 5fea382a36..8b58190a66 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -345,6 +345,7 @@ tracing = "0.1.41" tracing-core = "0.1.33" tracing-log = "0.2" tracing-opentelemetry = "0.31.0" +tracing-serde = "0.2.0" tracing-subscriber = "0.3.19" tracing-tree = "0.2.2" tracing-indicatif = "0.3.9" diff --git a/nym-node/Cargo.toml b/nym-node/Cargo.toml index c7485eaa3d..321975b179 100644 --- a/nym-node/Cargo.toml +++ b/nym-node/Cargo.toml @@ -119,11 +119,13 @@ opentelemetry = { workspace = true } opentelemetry_sdk = { workspace = true } tracing-core = { workspace = true } tracing-opentelemetry = { workspace = true } +tracing-serde = { workspace = true } opentelemetry-otlp = { version = "0.30.0" } opentelemetry-semantic-conventions = { workspace = true, features = [ "semconv_experimental", ] } opentelemetry-stdout = { workspace = true, features = ["trace", "metrics"] } +chrono = { workspace = true } [[bench]] name = "benchmarks" diff --git a/nym-node/src/logging.rs b/nym-node/src/logging.rs index 8e3ef96326..2f1472c8a7 100644 --- a/nym-node/src/logging.rs +++ b/nym-node/src/logging.rs @@ -9,6 +9,7 @@ use tracing_subscriber::util::SubscriberInitExt; use tracing_subscriber::{fmt, Layer}; // Signoz +use crate::trace_id_format::TraceIdFormat; use opentelemetry::trace::TracerProvider; use opentelemetry::{global, KeyValue}; use opentelemetry_otlp::tonic_types::metadata::MetadataMap; @@ -55,7 +56,8 @@ pub(crate) fn build_tracing_logger() -> anyhow::Result { .with_writer(std::io::stderr) .with_span_events(FmtSpan::NEW | FmtSpan::CLOSE) .with_span_list(false) - .with_current_span(true); + .with_current_span(true) + .event_format(TraceIdFormat); let registry = tracing_subscriber::registry() .with(fmt_layer) diff --git a/nym-node/src/main.rs b/nym-node/src/main.rs index 04ff85bb91..cd2b3a03a6 100644 --- a/nym-node/src/main.rs +++ b/nym-node/src/main.rs @@ -16,6 +16,7 @@ pub(crate) mod error; mod logging; pub(crate) mod node; pub(crate) mod throughput_tester; +mod trace_id_format; pub(crate) mod wireguard; fn main() -> anyhow::Result<()> { diff --git a/nym-node/src/trace_id_format.rs b/nym-node/src/trace_id_format.rs new file mode 100644 index 0000000000..9eed818eaa --- /dev/null +++ b/nym-node/src/trace_id_format.rs @@ -0,0 +1,88 @@ +use chrono::Utc; +use opentelemetry::trace::TraceContextExt; +use opentelemetry::{SpanId, TraceId}; +use serde::ser::{SerializeMap, Serializer as _}; +use std::io; +use tracing::{Event, Subscriber}; +use tracing_opentelemetry::OpenTelemetrySpanExt; +use tracing_serde::fields::AsMap; +use tracing_serde::AsSerde; +use tracing_subscriber::fmt::format::Writer; +use tracing_subscriber::fmt::{FmtContext, FormatEvent, FormatFields}; +use tracing_subscriber::registry::LookupSpan; + +pub struct WriteAdaptor<'a> { + fmt_write: &'a mut dyn std::fmt::Write, +} + +impl<'a> WriteAdaptor<'a> { + pub fn new(fmt_write: &'a mut dyn std::fmt::Write) -> Self { + Self { fmt_write } + } +} + +impl<'a> io::Write for WriteAdaptor<'a> { + fn write(&mut self, buf: &[u8]) -> io::Result { + 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(()) + } +} + +pub struct TraceIdFormat; + +impl FormatEvent for TraceIdFormat +where + S: Subscriber + for<'lookup> LookupSpan<'lookup>, + N: for<'writer> FormatFields<'writer> + 'static, +{ + fn format_event( + &self, + _ctx: &FmtContext<'_, S, N>, + mut writer: Writer<'_>, + event: &Event<'_>, + ) -> std::fmt::Result + where + S: Subscriber + for<'a> LookupSpan<'a>, + { + let meta = event.metadata(); + + let mut visit = || { + let mut serializer = serde_json::Serializer::new(WriteAdaptor::new(&mut writer)); + let mut serializer = serializer.serialize_map(None)?; + serializer.serialize_entry("timestamp", &Utc::now().to_rfc3339())?; + serializer.serialize_entry("level", &meta.level().as_serde())?; + serializer.serialize_entry("fields", &event.field_map())?; + serializer.serialize_entry("target", meta.target())?; + + let current_span = tracing::Span::current(); + let context = current_span.context(); + let span_ref = context.span(); + let span_context = span_ref.span_context(); + + let trace_id = span_context.trace_id(); + if trace_id != TraceId::INVALID { + serializer.serialize_entry("trace_id", &trace_id.to_string())?; + + let span_id = span_context.span_id(); + if span_id != SpanId::INVALID { + serializer.serialize_entry("span_id", &span_id.to_string())?; + } + } + + serializer.end() + }; + + visit().map_err(|_| std::fmt::Error)?; + writeln!(writer) + } +}