Prevent infinite loop when using reserved fields

src/formatting_layer.rs

@@ -209,20 +209,30 @@ impl<W: for<'a> MakeWriter<'a> + 'static> BunyanFormattingLayer<W> {
 
         // Add all default fields
         for (key, value) in self.default_fields.iter() {
-            // Make sure this key isn't reserved. If it is reserved,
-            // silently ignore
+            // Make sure this key isn't reserved.
             if !BUNYAN_REQUIRED_FIELDS.contains(&key.as_str()) {
                 self.serialize_field(&mut map_serializer, key, value)?;
+            } else {
+                tracing::debug!(
+                    parent: None,
+                    "{} is a reserved field in the bunyan log format. Skipping it.",
+                    key
+                );
             }
         }
 
         let extensions = span.extensions();
         if let Some(visitor) = extensions.get::<JsonStorage>() {
             for (key, value) in visitor.values() {
-                // Make sure this key isn't reserved. If it is reserved,
-                // silently ignore
+                // Make sure this key isn't reserved.
                 if !BUNYAN_REQUIRED_FIELDS.contains(key) {
                     self.serialize_field(&mut map_serializer, key, value)?;
+                } else {
+                    tracing::debug!(
+                        parent: None,
+                        "{} is a reserved field in the bunyan log format. Skipping it.",
+                        key
+                    );
                 }
             }
         }
@@ -307,9 +317,18 @@ where
     W: for<'a> MakeWriter<'a> + 'static,
 {
     fn on_event(&self, event: &Event<'_>, ctx: Context<'_, S>) {
-        // Events do not necessarily happen in the context of a span, hence lookup_current
-        // returns an `Option<SpanRef<_>>` instead of a `SpanRef<_>`.
-        let current_span = ctx.lookup_current();
+        // Lookup the current span.
+        let current_span = if event.is_contextual() {
+            // If the event is _contextual_, ask the context for what it thinks the current span
+            // is.
+            // Events do not necessarily happen in the context of a span, hence lookup_current
+            // returns an `Option<SpanRef<_>>` instead of a `SpanRef<_>`.
+            ctx.lookup_current()
+        } else {
+            // Otherwise, the event is either a _root_ event, or the parent span was explicitly
+            // set.
+            event.parent().and_then(|id| ctx.span(id))
+        };
 
         let mut event_visitor = JsonStorage::default();
         event.record(&mut event_visitor);
@@ -359,6 +378,12 @@ where
                         // silently ignore
                         if !BUNYAN_REQUIRED_FIELDS.contains(key) {
                             self.serialize_field(&mut map_serializer, key, value)?;
+                        } else {
+                            tracing::debug!(
+                                parent: None,
+                                "{} is a reserved field in the bunyan log format. Skipping it.",
+                                key
+                            );
                         }
                     }
                 }

tests/common/mod.rs

@@ -0,0 +1,54 @@
+use std::collections::HashMap;
+use std::sync::{Arc, Mutex};
+
+use mock_writer::MockWriter;
+use serde_json::{json, Value};
+use tracing_bunyan_formatter::{BunyanFormattingLayer, JsonStorageLayer};
+use tracing_subscriber::layer::SubscriberExt;
+
+mod mock_writer;
+
+// Run a closure and collect the output emitted by the tracing instrumentation using an in-memory buffer.
+//
+// If `global` is `true` the subscriber is globally installed for all threads. If `false`, it is
+// only set for the current thread, for the duration of `action`.
+pub fn run_with_subscriber_and_get_raw_output<F: Fn()>(action: F, global: bool) -> String {
+    let buffer = Arc::new(Mutex::new(vec![]));
+    let buffer_clone = buffer.clone();
+
+    let mut default_fields = HashMap::new();
+    default_fields.insert("custom_field".to_string(), json!("custom_value"));
+    let skipped_fields = vec!["skipped"];
+    let formatting_layer = BunyanFormattingLayer::with_default_fields(
+        "test".into(),
+        move || MockWriter::new(buffer_clone.clone()),
+        default_fields,
+    )
+    .skip_fields(skipped_fields.into_iter())
+    .unwrap();
+    let subscriber = tracing_subscriber::Registry::default()
+        .with(JsonStorageLayer)
+        .with(formatting_layer);
+
+    if global {
+        tracing::subscriber::set_global_default(subscriber)
+            .expect("Failed to install global subscriber");
+        action();
+    } else {
+        tracing::subscriber::with_default(subscriber, action);
+    }
+
+    // Return the formatted output as a string to make assertions against
+    let buffer_guard = buffer.lock().unwrap();
+    let output = buffer_guard.to_vec();
+    String::from_utf8(output).unwrap()
+}
+
+pub fn parse_output(output: String) -> Vec<Value> {
+    output
+        .lines()
+        .filter(|&l| !l.trim().is_empty())
+        .inspect(|l| println!("{}", l))
+        .map(|line| serde_json::from_str::<Value>(line).unwrap())
+        .collect()
+}

tests/e2e.rs

@@ -1,51 +1,21 @@
-use crate::mock_writer::MockWriter;
 use claims::assert_some_eq;
-use serde_json::{json, Value};
-use std::collections::HashMap;
-use std::sync::{Arc, Mutex};
+use common::{parse_output, run_with_subscriber_and_get_raw_output};
+use serde_json::Value;
 use time::format_description::well_known::Rfc3339;
 use tracing::{info, span, Level};
-use tracing_bunyan_formatter::{BunyanFormattingLayer, JsonStorageLayer};
-use tracing_subscriber::layer::SubscriberExt;
-use tracing_subscriber::Registry;
-
-mod mock_writer;
-
-// Run a closure and collect the output emitted by the tracing instrumentation using an in-memory buffer.
-fn run_and_get_raw_output<F: Fn()>(action: F) -> String {
-    let buffer = Arc::new(Mutex::new(vec![]));
-    let buffer_clone = buffer.clone();
-
-    let mut default_fields = HashMap::new();
-    default_fields.insert("custom_field".to_string(), json!("custom_value"));
-    let skipped_fields = vec!["skipped"];
-    let formatting_layer = BunyanFormattingLayer::with_default_fields(
-        "test".into(),
-        move || MockWriter::new(buffer_clone.clone()),
-        default_fields,
-    )
-    .skip_fields(skipped_fields.into_iter())
-    .unwrap();
-    let subscriber = Registry::default()
-        .with(JsonStorageLayer)
-        .with(formatting_layer);
-    tracing::subscriber::with_default(subscriber, action);
-
-    // Return the formatted output as a string to make assertions against
-    let buffer_guard = buffer.lock().unwrap();
-    let output = buffer_guard.to_vec();
-    String::from_utf8(output).unwrap()
+use tracing_bunyan_formatter::BunyanFormattingLayer;
+
+mod common;
+
+pub fn run_and_get_raw_output<F: Fn()>(action: F) -> String {
+    run_with_subscriber_and_get_raw_output(action, false)
 }
 
 // Run a closure and collect the output emitted by the tracing instrumentation using
 // an in-memory buffer as structured new-line-delimited JSON.
-fn run_and_get_output<F: Fn()>(action: F) -> Vec<Value> {
-    run_and_get_raw_output(action)
-        .lines()
-        .filter(|&l| !l.trim().is_empty())
-        .inspect(|l| println!("{}", l))
-        .map(|line| serde_json::from_str::<Value>(line).unwrap())
-        .collect()
+pub fn run_and_get_output<F: Fn()>(action: F) -> Vec<Value> {
+    let output = run_and_get_raw_output(action);
+    parse_output(output)
 }
 
 // Instrumented code to be run to test the behaviour of the tracing instrumentation.

tests/infinite_loop.rs

@@ -0,0 +1,29 @@
+use common::parse_output;
+use tracing::{info, info_span};
+
+mod common;
+
+/// Make sure the `tracing::debug!()` calls in `BunyanFormattingLayer` don't cause an infinite loop
+/// (and a stack overflow).
+#[test]
+pub fn no_infinite_loop() {
+    // Note: the infinite loop bug could only happen if `BunyanFormattingLayer`
+    // is set as the global subscriber. (`tracing` guards against a thread-local
+    // subscriber being aquired twice, returning `NONE` the second time, so any
+    // `tracing::debug!()` statement withing `BunyanFormattingLayer` are dropped
+    // in that case)
+    let output = common::run_with_subscriber_and_get_raw_output(
+        || {
+            info_span!("my span", name = "foo").in_scope(|| {
+                info!("Calling foo");
+            });
+        },
+        true,
+    );
+
+    // If we get here, that means the code above didn't crash with a stack overflow.
+    let logs = parse_output(output);
+    // We expect 6 log lines: 3 for the span start, log event, span end, but each one is preceded by
+    // the debug log from `BunyanFormattingLayer` regarding using a reserved field.
+    assert_eq!(6, logs.len());
+}