From 0e6df92c3b2d0b4ec6731874982c7eebc86994aa Mon Sep 17 00:00:00 2001 From: Lloyd Wallis Date: Mon, 29 Jul 2024 17:08:27 +0100 Subject: [PATCH] Add ability for logging to record tracing span log entries In large environments with separate logging and tracing pipelines, identifying pertinent log information for a trace can involve searching in an entirely different store, which may be subject to its own sampling and rate limiting. For these situations, the log lines generate specifically whilst the traced action is executed are particularly high value in providing additional context. This change adds trace emission options for the logging module, which allow enabling emitting logs from traces at a separately specified verbosity level, which can be changed the same was as we can with set_verbosity. To fully specify log fields, add_span_log_fields is updated to additionally be able to accept an iterable, similar to `add_span_tags`. --- foundations/src/telemetry/log/init.rs | 30 +++++++ foundations/src/telemetry/log/mod.rs | 29 +++++++ foundations/src/telemetry/log/testing.rs | 4 +- .../src/telemetry/log/tracing_drain.rs | 80 +++++++++++++++++++ foundations/src/telemetry/settings/logging.rs | 17 ++++ foundations/src/telemetry/tracing/mod.rs | 15 +++- foundations/tests/logging.rs | 69 +++++++++++++++- 7 files changed, 237 insertions(+), 7 deletions(-) create mode 100644 foundations/src/telemetry/log/tracing_drain.rs 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())] + }] + ); +}