Add ability for logging to record tracing span log entries

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<D>(
+    drain: D,
+    settings: &LoggingSettings,
+) -> Fuse<Duplicate<D, TracingFilteringDrain<FilteredDrain<TracingDrain>>>>
+where
+    D: Drain<Ok = (), Err = Never> + '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<D>(
     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)
 }
 

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'

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 {

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<D: Drain<Err = Never>> {
+    inner: D,
+}
+
+impl<D: Drain<Err = Never>> TracingFilteringDrain<D> {
+    pub(crate) fn new(inner: D) -> Self {
+        Self { inner }
+    }
+}
+
+impl<D: Drain<Err = Never>> Drain for TracingFilteringDrain<D> {
+    type Ok = ();
+    type Err = D::Err;
+
+    fn log(&self, record: &Record, values: &OwnedKVList) -> Result<Self::Ok, Self::Err> {
+        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<Self::Ok, Self::Err> {
+        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(())
+    }
+}

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::*;

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.

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())]
+        }]
+    );
+}