feat(logging): add a setting to panic when add_fields! overwrites a key

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

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,13 +43,17 @@ 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 {
         Self {
             inner: logger,
             nesting_level: 0,
             frozen: false,
+            panic_on_field_overwrite: false,
         }
     }
 
@@ -136,7 +147,7 @@ impl LogScope {
     }
 }
 
-pub fn add_log_fields<T>(fields: OwnedKV<T>)
+pub fn add_log_fields<T>(fields: OwnedKV<T>, allow_overwrite: bool)
 where
     T: SendSyncRefUnwindSafeKV + 'static,
 {
@@ -147,13 +158,50 @@ 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
     };
 
     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<String> {
+    #[derive(Default)]
+    struct KeyCollector(Vec<String>);
+
+    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<String> = 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();

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,
         );
     };
 }

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())),

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,
 

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::<String>().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;