diff --git a/foundations/src/telemetry/log/init.rs b/foundations/src/telemetry/log/init.rs index a0b239a..49942c8 100644 --- a/foundations/src/telemetry/log/init.rs +++ b/foundations/src/telemetry/log/init.rs @@ -2,6 +2,10 @@ use super::field_dedup::FieldDedupFilterFactory; use super::field_filtering::FieldFilteringDrain; use super::field_redact::FieldRedactFilterFactory; use super::internal::{LoggerWithKvNestingTracking, SharedLog}; +#[cfg(feature = "tracing")] +use super::tracing_drain::{TracingDrain, TracingFilteringDrain}; +#[cfg(feature = "tracing")] +use slog::Duplicate; #[cfg(feature = "metrics")] use crate::telemetry::log::log_volume::LogVolumeMetricsDrain; @@ -128,6 +132,26 @@ fn get_root_drain( base_drain } +#[cfg(feature = "tracing")] +fn add_tracing_drain( + drain: D, + settings: &LoggingSettings, +) -> Fuse>>> +where + D: Drain + 'static, +{ + let tracing_drain = TracingDrain::new(); + let tracing_drain = FieldFilteringDrain::new(tracing_drain, FieldDedupFilterFactory); + let tracing_drain = FieldFilteringDrain::new( + tracing_drain, + FieldRedactFilterFactory::new(settings.redact_keys.clone()), + ); + let tracing_drain = tracing_drain.filter_level(*settings.trace_emission.verbosity); + let tracing_drain = TracingFilteringDrain::new(tracing_drain); + + Duplicate::new(drain, tracing_drain).fuse() +} + pub(crate) fn apply_filters_to_drain( drain: D, settings: &LoggingSettings, @@ -155,6 +179,12 @@ where K: SendSyncRefUnwindSafeKV + 'static, { let drain = apply_filters_to_drain(drain, settings); + + #[cfg(feature = "tracing")] + if settings.trace_emission.enabled { + return Logger::root(add_tracing_drain(drain, settings), kv); + } + Logger::root(drain, kv) } diff --git a/foundations/src/telemetry/log/mod.rs b/foundations/src/telemetry/log/mod.rs index a3a2997..bb05c81 100644 --- a/foundations/src/telemetry/log/mod.rs +++ b/foundations/src/telemetry/log/mod.rs @@ -4,6 +4,8 @@ mod field_dedup; mod field_filtering; mod field_redact; mod rate_limit; +#[cfg(feature = "tracing")] +mod tracing_drain; pub(crate) mod init; @@ -61,6 +63,33 @@ pub fn verbosity() -> LogVerbosity { harness.settings.verbosity } +/// Sets the level of log messages to emit to tracing span logs, overriding the settings used +/// in [`init`]. +/// +/// Does not enable or disable emission to trace spans, and so will have no impact if +/// [`trace_emission.enabled`] was set to false in [`init`]. +/// +/// This is subject to the same nesting limitations of `set_verbosity`. +/// +/// [`init`]: crate::telemetry::init +/// [`trace_emission.enabled`]: crate::telemetry::settings::TraceEmissionSettings +#[cfg(feature = "tracing")] +pub fn set_trace_emission_verbosity(level: Level) -> Result<()> { + let harness = LogHarness::get(); + + let mut settings = harness.settings.clone(); + settings.trace_emission.verbosity = LogVerbosity(level); + + let current_log = current_log(); + let mut current_log_lock = current_log.write(); + + let kv = OwnedKV(current_log_lock.list().clone()); + current_log_lock.inner = build_log_with_drain(&settings, kv, Arc::clone(&harness.root_drain)); + current_log_lock.inc_nesting_level(); + + Ok(()) +} + /// Returns current log as a raw [slog] crate's `Logger` used by Foundations internally. /// /// Can be used to propagate the logging context to libraries that don't use Foundations' diff --git a/foundations/src/telemetry/log/testing.rs b/foundations/src/telemetry/log/testing.rs index 94b5359..5104f81 100644 --- a/foundations/src/telemetry/log/testing.rs +++ b/foundations/src/telemetry/log/testing.rs @@ -1,4 +1,4 @@ -use crate::telemetry::log::init::{apply_filters_to_drain, LogHarness}; +use crate::telemetry::log::init::{build_log_with_drain, LogHarness}; use crate::telemetry::log::internal::LoggerWithKvNestingTracking; use crate::telemetry::settings::LoggingSettings; use parking_lot::RwLock as ParkingRwLock; @@ -69,7 +69,7 @@ pub(crate) fn create_test_log( records: Arc::clone(&log_records), }; - let drain = Arc::new(apply_filters_to_drain(drain, settings)); + let drain = Arc::new(build_log_with_drain(settings, slog::o!(), drain)); let log = LoggerWithKvNestingTracking::new(Logger::root(Arc::clone(&drain), slog::o!())); let _ = LogHarness::override_for_testing(LogHarness { diff --git a/foundations/src/telemetry/log/tracing_drain.rs b/foundations/src/telemetry/log/tracing_drain.rs new file mode 100644 index 0000000..4214c24 --- /dev/null +++ b/foundations/src/telemetry/log/tracing_drain.rs @@ -0,0 +1,80 @@ +use slog::{Drain, Never, OwnedKVList, Record, Serializer, KV}; + +use crate::telemetry::tracing; + +pub(crate) struct TracingFilteringDrain> { + inner: D, +} + +impl> TracingFilteringDrain { + pub(crate) fn new(inner: D) -> Self { + Self { inner } + } +} + +impl> Drain for TracingFilteringDrain { + type Ok = (); + type Err = D::Err; + + fn log(&self, record: &Record, values: &OwnedKVList) -> Result { + if tracing::rustracing_span().is_some() { + self.inner.log(record, values).map(|_| ()) + } else { + Ok(()) + } + } +} + +pub(crate) struct TracingDrain {} + +impl TracingDrain { + pub(crate) fn new() -> Self { + Self {} + } +} + +impl Drain for TracingDrain { + type Ok = (); + type Err = Never; + + fn log(&self, record: &Record, values: &OwnedKVList) -> Result { + let mut serializer = TracingValueSerializer::new(); + serializer.add_field("name".to_string(), record.module().to_string()); + serializer.add_field( + "level".to_string(), + record.level().as_short_str().to_string(), + ); + serializer.add_field("msg".to_string(), record.msg().to_string()); + values.serialize(record, &mut serializer).unwrap(); + serializer.store(); + Ok(()) + } +} + +struct TracingValueSerializer { + fields: Vec<(String, String)>, +} + +impl TracingValueSerializer { + pub(crate) fn new() -> Self { + // We know we're expecting at least name/level/msg next + let fields = Vec::<(String, String)>::with_capacity(3); + Self { fields } + } + + pub(crate) fn add_field(&mut self, key: String, val: String) { + self.fields.push((key, val)); + } + + pub(crate) fn store(self) { + tracing::add_span_log_fields!(self.fields); + } +} + +impl Serializer for TracingValueSerializer { + fn emit_arguments(&mut self, key: slog::Key, val: &std::fmt::Arguments<'_>) -> slog::Result { + let value = val.to_string(); + self.fields.push((key.to_string(), value)); + Ok(()) + } +} diff --git a/foundations/src/telemetry/settings/logging.rs b/foundations/src/telemetry/settings/logging.rs index 9282aa7..9386b38 100644 --- a/foundations/src/telemetry/settings/logging.rs +++ b/foundations/src/telemetry/settings/logging.rs @@ -39,6 +39,10 @@ pub struct LoggingSettings { /// Configure log volume metrics. pub log_volume_metrics: LogVolumeMetricSettings, + + /// Settings to allow additionally emitting logs to trace spans + #[cfg(feature = "tracing")] + pub trace_emission: TraceEmissionSettings, } /// Log output destination. @@ -95,6 +99,19 @@ pub struct LogVolumeMetricSettings { pub enabled: bool, } +/// Trace logging settings +/// +/// If enabled, logs can be emitted as span log entries if the current context +/// is traced. Unlike the main output, these will not be rate limited. +#[cfg_attr(feature = "settings", settings(crate_path = "crate"))] +#[cfg_attr(not(feature = "settings"), derive(Clone, Debug, Default))] +pub struct TraceEmissionSettings { + /// Whether to enable logging to trace spans + pub enabled: bool, + /// The verbosity of logs to emit to trace spans + pub verbosity: LogVerbosity, +} + #[cfg(feature = "settings")] mod with_settings_feature { use super::*; diff --git a/foundations/src/telemetry/tracing/mod.rs b/foundations/src/telemetry/tracing/mod.rs index b68d3c2..5fc3835 100644 --- a/foundations/src/telemetry/tracing/mod.rs +++ b/foundations/src/telemetry/tracing/mod.rs @@ -479,8 +479,9 @@ macro_rules! __add_span_tags { /// Adds log fields to the current span. /// -/// Log entries need to be provided as comma-separated `"field" => "value"` pairs there. Fields and -/// values can be strings or string slices. +/// Log entries can be provided eother as comma-separated `"field" => "value"` pairs, +/// or an [iterable] over `("key", value)` tuples. Fields and values can be strings or +/// string slices. /// /// # Examples /// ``` @@ -531,6 +532,7 @@ macro_rules! __add_span_tags { /// }] /// ); /// ``` +/// [iterable]: std::iter::IntoIterator #[macro_export] #[doc(hidden)] macro_rules! __add_span_log_fields { @@ -543,6 +545,15 @@ macro_rules! __add_span_log_fields { }); }); }; + ( $fields:expr ) => { + $crate::telemetry::tracing::internal::write_current_span(|span| { + span.log(|builder| { + for (name, val) in $fields.into_iter() { + builder.field((name, val)); + } + }); + }); + }; } /// Overrides the start time of the current span with the provided [`SystemTime`] value. diff --git a/foundations/tests/logging.rs b/foundations/tests/logging.rs index 6f61c82..b2d7e48 100644 --- a/foundations/tests/logging.rs +++ b/foundations/tests/logging.rs @@ -1,7 +1,12 @@ use foundations::telemetry::log::internal::LoggerWithKvNestingTracking; -use foundations::telemetry::log::{add_fields, set_verbosity, warn}; -use foundations::telemetry::settings::{LoggingSettings, RateLimitingSettings}; -use foundations::telemetry::TestTelemetryContext; +use foundations::telemetry::log::{ + add_fields, error, info, set_verbosity, trace, warn, TestLogRecord, +}; +use foundations::telemetry::settings::{ + LogVerbosity, LoggingSettings, RateLimitingSettings, TraceEmissionSettings, +}; +use foundations::telemetry::tracing::test_trace; +use foundations::telemetry::{tracing, TestTelemetryContext}; use foundations_macros::with_test_telemetry; use slog::Level; @@ -73,3 +78,61 @@ fn test_not_exceed_limit_kv_nesting(_ctx: TestTelemetryContext) { set_verbosity(Level::Info).expect("set_verbosity"); } } + +#[with_test_telemetry(test)] +fn test_trace_span_logging(mut ctx: TestTelemetryContext) { + ctx.set_logging_settings(LoggingSettings { + verbosity: LogVerbosity(Level::Error), + trace_emission: TraceEmissionSettings { + enabled: true, + verbosity: LogVerbosity(Level::Info), + }, + ..Default::default() + }); + + { + let _span = tracing::span("root"); + error!("error {}", 1; "error" => "log"); + let _span = tracing::span("child 1"); + info!("info {}", 2; "info" => "log"); + let _span = tracing::span("child 2"); + trace!("trace {}", 3; "trace" => "log"); + } + + assert_eq!( + ctx.traces(tracing::TestTraceOptions { + include_logs: true, + ..Default::default() + }), + vec![test_trace! { + "root"; { + logs: [ + ("level", "ERRO"), + ("msg", "error 1"), + ("name", "logging") + ] + } => { + "child 1"; { + logs: [ + ("level", "INFO"), + ("msg", "info 2"), + ("name", "logging") + ] + } => { + "child 2"; { + logs: [] + } + } + } + }] + ); + + assert_eq!( + *ctx.log_records(), + &[TestLogRecord { + level: Level::Error, + message: "error 1".into(), + fields: vec![("error".into(), "log".into())] + }] + ); +}