Prevent infinite loop when using reserved fields

closes: LukeMathWalker#33

src/formatting_layer.rs

@@ -213,6 +213,7 @@ impl<W: for<'a> MakeWriter<'a> + 'static> BunyanFormattingLayer<W> {
                 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
                 );
@@ -226,6 +227,7 @@ impl<W: for<'a> MakeWriter<'a> + 'static> BunyanFormattingLayer<W> {
                     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
                     );
@@ -313,9 +315,14 @@ 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, unless the event is a "root" event.
+        let current_span = if event.is_root() {
+            None
+        } else {
+            // 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()
+        };
 
         let mut event_visitor = JsonStorage::default();
         event.record(&mut event_visitor);
@@ -365,6 +372,7 @@ where
                             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());
+}