diff --git a/foundations/src/telemetry/log/init.rs b/foundations/src/telemetry/log/init.rs index cf00c918..51482e0e 100644 --- a/foundations/src/telemetry/log/init.rs +++ b/foundations/src/telemetry/log/init.rs @@ -128,11 +128,12 @@ pub(crate) fn init( ); let root_log = build_log_with_drain(settings.verbosity, root_kv, Arc::clone(&root_drain)); + let mut root_log = LoggerWithKvNestingTracking::new(root_log); + root_log.panic_on_field_overwrite = settings.panic_on_field_overwrite; + let harness = LogHarness { root_drain, - root_log: Arc::new(parking_lot::RwLock::new(LoggerWithKvNestingTracking::new( - root_log, - ))), + root_log: Arc::new(parking_lot::RwLock::new(root_log)), settings: settings.clone(), log_scope_stack: Default::default(), }; diff --git a/foundations/src/telemetry/log/internal.rs b/foundations/src/telemetry/log/internal.rs index 5d7b72af..4f671be3 100644 --- a/foundations/src/telemetry/log/internal.rs +++ b/foundations/src/telemetry/log/internal.rs @@ -1,7 +1,10 @@ use super::init::LogHarness; use crate::telemetry::scope::Scope; -use slog::{Logger, OwnedKV, Record, SendSyncRefUnwindSafeKV}; -use std::fmt::Debug; +use slog::{ + KV, Key, Level, Logger, OwnedKV, OwnedKVList, Record, SendSyncRefUnwindSafeKV, Serializer, +}; +use std::collections::HashSet; +use std::fmt::{Arguments, Debug}; use std::ops::Deref; use std::sync::Arc; @@ -27,6 +30,10 @@ pub struct LoggerWithKvNestingTracking { // // Forked loggers always start unfrozen, regardless of the parent's frozen state. pub(crate) frozen: bool, + + // Whether add_fields! panics when it sets a key that the logger already has. Set from + // `LoggingSettings::panic_on_field_overwrite`, and inherited by forked loggers. + pub(crate) panic_on_field_overwrite: bool, } impl LoggerWithKvNestingTracking { @@ -36,6 +43,9 @@ impl LoggerWithKvNestingTracking { pub const FROZEN_LOGGER_ERROR: &'static str = "foundations: attempt to modify a frozen logger \ (are you modifying the root logger from a spawned task/thread that lacks a forked context?)"; + pub const FIELD_OVERWRITE_ERROR: &'static str = "foundations: add_fields! overwrote an existing \ + log field (use `add_fields!(allow_overwrite; ...)` if this is intended)"; + /// Create a new LoggerWithKvNestingTracking based on a fresh logger. The KV nesting level is /// initialized to zero and the logger starts unfrozen. pub(crate) fn new(logger: Logger) -> Self { @@ -43,6 +53,7 @@ impl LoggerWithKvNestingTracking { inner: logger, nesting_level: 0, frozen: false, + panic_on_field_overwrite: false, } } @@ -136,7 +147,7 @@ impl LogScope { } } -pub fn add_log_fields(fields: OwnedKV) +pub fn add_log_fields(fields: OwnedKV, allow_overwrite: bool) where T: SendSyncRefUnwindSafeKV + 'static, { @@ -147,6 +158,17 @@ where return; // logger is frozen, mutation rejected }; + if log_lock.panic_on_field_overwrite + && !allow_overwrite + && let Some(key) = overwritten_key(log_lock.list(), &fields.0) + { + drop(log_lock); + panic!( + "{} (key: `{key}`)", + LoggerWithKvNestingTracking::FIELD_OVERWRITE_ERROR + ); + } + let Some(mut log_lock) = LoggerWithKvNestingTracking::check_nesting_level(log_lock) else { return; // avoid changes, nesting level was beyond threshold }; @@ -154,6 +176,32 @@ where log_lock.inner = log_lock.inner.new(fields); } +/// Returns the first key in `fields` that is already in `existing`. +fn overwritten_key(existing: &OwnedKVList, fields: &dyn KV) -> Option { + #[derive(Default)] + struct KeyCollector(Vec); + + impl Serializer for KeyCollector { + fn emit_arguments(&mut self, key: Key, _val: &Arguments) -> slog::Result { + self.0.push(key.to_string()); + Ok(()) + } + } + + let keys = |kv: &dyn KV| { + let mut keys = KeyCollector::default(); + // `KV::serialize` needs a record, but only the keys are collected here. + let _ = kv.serialize( + &slog::record!(Level::Info, "", &format_args!(""), slog::b!()), + &mut keys, + ); + keys.0 + }; + + let existing: HashSet = keys(existing).into_iter().collect(); + keys(fields).into_iter().find(|key| existing.contains(key)) +} + pub fn current_log() -> SharedLog { let harness = LogHarness::get(); let log = harness.log_scope_stack.current(); diff --git a/foundations/src/telemetry/log/mod.rs b/foundations/src/telemetry/log/mod.rs index 73717082..e291eba0 100644 --- a/foundations/src/telemetry/log/mod.rs +++ b/foundations/src/telemetry/log/mod.rs @@ -130,6 +130,9 @@ pub fn is_frozen() -> bool { /// To avoid this panic, make sure to only use `add_fields!` for fields that will remain relatively /// static (under 1000 updates over the lifetime of any given logger). /// +/// If [`LoggingSettings::panic_on_field_overwrite`] is enabled, setting a key that the logger +/// already has panics. Use `add_fields!(allow_overwrite; ...)` where the overwrite is intended. +/// /// Certain added fields may not be present in the resulting logs if /// [`LoggingSettings::redact_keys`] is used. /// @@ -150,7 +153,7 @@ pub fn is_frozen() -> bool { /// log::warn!("With context fields"; "foo" => "bar"); /// /// // Update the context field value -/// log::add_fields!("ctx_field1" => 43); +/// log::add_fields!(allow_overwrite; "ctx_field1" => 43); /// /// log::warn!("One more with context fields"); /// @@ -181,12 +184,20 @@ pub fn is_frozen() -> bool { /// ``` /// /// [`LoggingSettings::redact_keys`]: crate::telemetry::settings::LoggingSettings::redact_keys +/// [`LoggingSettings::panic_on_field_overwrite`]: crate::telemetry::settings::LoggingSettings::panic_on_field_overwrite #[macro_export] #[doc(hidden)] macro_rules! __add_fields { + ( allow_overwrite ; $($args:tt)* ) => { + $crate::telemetry::log::internal::add_log_fields( + $crate::reexports_for_macros::slog::o!($($args)*), + true, + ); + }; ( $($args:tt)* ) => { $crate::telemetry::log::internal::add_log_fields( - $crate::reexports_for_macros::slog::o!($($args)*) + $crate::reexports_for_macros::slog::o!($($args)*), + false, ); }; } diff --git a/foundations/src/telemetry/log/testing.rs b/foundations/src/telemetry/log/testing.rs index d069dc07..a4eb261d 100644 --- a/foundations/src/telemetry/log/testing.rs +++ b/foundations/src/telemetry/log/testing.rs @@ -87,7 +87,8 @@ where let drain = wrap_root_drain(settings, drain); let logger = build_log_with_drain(settings.verbosity, slog::o!(), Arc::clone(&drain)); - let log = LoggerWithKvNestingTracking::new(logger); + let mut log = LoggerWithKvNestingTracking::new(logger); + log.panic_on_field_overwrite = settings.panic_on_field_overwrite; let _ = LogHarness::override_for_testing(LogHarness { root_log: Arc::new(ParkingRwLock::new(log.clone())), diff --git a/foundations/src/telemetry/settings/logging.rs b/foundations/src/telemetry/settings/logging.rs index 0e1a0ea4..09031b39 100644 --- a/foundations/src/telemetry/settings/logging.rs +++ b/foundations/src/telemetry/settings/logging.rs @@ -46,6 +46,16 @@ pub struct LoggingSettings { /// running if a log sink returns an error such as [`std::io::ErrorKind::BrokenPipe`]. pub ignore_io_errors: bool, + /// Whether to panic when [`add_fields!`] sets a key that the current logger already has. + /// + /// Adding the same key over and over without forking the logger builds a long logger + /// chain, which can overflow the stack when it is dropped. Enabling this setting catches + /// such call sites early. Intentional overwrites can opt out with + /// `add_fields!(allow_overwrite; ...)`. + /// + /// [`add_fields!`]: crate::telemetry::log::add_fields + pub panic_on_field_overwrite: bool, + /// Settings for rate limiting emission of log events pub rate_limit: RateLimitingSettings, diff --git a/foundations/tests/logging.rs b/foundations/tests/logging.rs index df388d21..201f03b7 100644 --- a/foundations/tests/logging.rs +++ b/foundations/tests/logging.rs @@ -1,8 +1,12 @@ use foundations::telemetry::TelemetryContext; use foundations::telemetry::TestTelemetryContext; use foundations::telemetry::log::internal::LoggerWithKvNestingTracking; -use foundations::telemetry::log::{add_fields, freeze, is_frozen, set_verbosity, unfreeze, warn}; -use foundations::telemetry::settings::{LogVerbosity, LoggingSettings, RateLimitingSettings}; +use foundations::telemetry::log::{ + TestLogRecord, add_fields, freeze, is_frozen, set_verbosity, unfreeze, warn, +}; +use foundations::telemetry::settings::{ + Level, LogVerbosity, LoggingSettings, RateLimitingSettings, +}; use foundations_macros::with_test_telemetry; #[with_test_telemetry(test)] @@ -141,6 +145,54 @@ fn test_frozen_logger_add_fields_panics(_ctx: TestTelemetryContext) { } } +// With panic_on_field_overwrite, add_fields! must panic when it sets a key the logger already +// has, including a key inherited by a forked logger. +#[with_test_telemetry(test)] +fn test_field_overwrite_panics(mut ctx: TestTelemetryContext) { + ctx.set_logging_settings(LoggingSettings { + panic_on_field_overwrite: true, + ..Default::default() + }); + + add_fields! { "key" => "value" } + + let forked_ctx = TelemetryContext::current().with_forked_log(); + let _scope = forked_ctx.scope(); + + add_fields! { "other_key" => "value" } + + let err = std::panic::catch_unwind(|| { + add_fields! { "key" => "new value" } + }) + .expect_err("expected a panic when add_fields! overwrites a key"); + + let msg = err.downcast_ref::().expect("String panic payload"); + assert!(msg.starts_with(LoggerWithKvNestingTracking::FIELD_OVERWRITE_ERROR)); + assert!(msg.contains("`key`")); +} + +// allow_overwrite opts a single add_fields! call out of panic_on_field_overwrite. +#[with_test_telemetry(test)] +fn test_field_overwrite_allowed(mut ctx: TestTelemetryContext) { + ctx.set_logging_settings(LoggingSettings { + panic_on_field_overwrite: true, + ..Default::default() + }); + + add_fields! { "key" => "value" } + add_fields! { allow_overwrite; "key" => "new value" } + warn!("hello"); + + assert_eq!( + *ctx.log_records(), + [TestLogRecord { + level: Level::Warning, + message: "hello".into(), + fields: vec![("key".into(), "new value".into())], + }] + ); +} + #[cfg(feature = "tracing-rs-compat")] mod tracing_rs_compat { use std::io;