From 7f7bd98863f604e77b48e86c973493f01adf8de5 Mon Sep 17 00:00:00 2001 From: Antoine Busch Date: Sun, 16 Jul 2023 17:49:55 +1000 Subject: [PATCH 1/2] Prevent infinite loop when using reserved fields closes: #33 --- src/formatting_layer.rs | 35 ++++++++++++++++---- tests/{ => common}/mock_writer.rs | 0 tests/common/mod.rs | 54 +++++++++++++++++++++++++++++++ tests/e2e.rs | 52 +++++++---------------------- tests/infinite_loop.rs | 29 +++++++++++++++++ 5 files changed, 122 insertions(+), 48 deletions(-) rename tests/{ => common}/mock_writer.rs (100%) create mode 100644 tests/common/mod.rs create mode 100644 tests/infinite_loop.rs diff --git a/src/formatting_layer.rs b/src/formatting_layer.rs index f9e0f21..cb6ff9e 100644 --- a/src/formatting_layer.rs +++ b/src/formatting_layer.rs @@ -209,20 +209,30 @@ impl MakeWriter<'a> + 'static> BunyanFormattingLayer { // 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::() { 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,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>` 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>` instead of a `SpanRef<_>`. + ctx.lookup_current() + }; let mut event_visitor = JsonStorage::default(); event.record(&mut event_visitor); @@ -359,6 +374,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 + ); } } } diff --git a/tests/mock_writer.rs b/tests/common/mock_writer.rs similarity index 100% rename from tests/mock_writer.rs rename to tests/common/mock_writer.rs diff --git a/tests/common/mod.rs b/tests/common/mod.rs new file mode 100644 index 0000000..89cf1e7 --- /dev/null +++ b/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(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 { + output + .lines() + .filter(|&l| !l.trim().is_empty()) + .inspect(|l| println!("{}", l)) + .map(|line| serde_json::from_str::(line).unwrap()) + .collect() +} diff --git a/tests/e2e.rs b/tests/e2e.rs index 29fd626..88e2967 100644 --- a/tests/e2e.rs +++ b/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(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(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(action: F) -> Vec { - run_and_get_raw_output(action) - .lines() - .filter(|&l| !l.trim().is_empty()) - .inspect(|l| println!("{}", l)) - .map(|line| serde_json::from_str::(line).unwrap()) - .collect() +pub fn run_and_get_output(action: F) -> Vec { + let output = run_and_get_raw_output(action); + parse_output(output) } // Instrumented code to be run to test the behaviour of the tracing instrumentation. diff --git a/tests/infinite_loop.rs b/tests/infinite_loop.rs new file mode 100644 index 0000000..a6b7421 --- /dev/null +++ b/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()); +} From 615ef4f39aed995690803aa51b072023ccb47774 Mon Sep 17 00:00:00 2001 From: Antoine Busch Date: Sun, 16 Jul 2023 21:50:48 +1000 Subject: [PATCH 2/2] Fix resolving of the current span. --- src/formatting_layer.rs | 12 ++++++++---- 1 file changed, 8 insertions(+), 4 deletions(-) diff --git a/src/formatting_layer.rs b/src/formatting_layer.rs index cb6ff9e..f6ab150 100644 --- a/src/formatting_layer.rs +++ b/src/formatting_layer.rs @@ -317,13 +317,17 @@ where W: for<'a> MakeWriter<'a> + 'static, { fn on_event(&self, event: &Event<'_>, ctx: Context<'_, S>) { - // Lookup the current span, unless the event is a "root" event. - let current_span = if event.is_root() { - None - } else { + // 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>` 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();