From c39c89f71bb9c4c6380cd0c39d3726ec6b4f820d Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Tue, 7 Jan 2020 11:15:44 -0800 Subject: [PATCH 1/6] subscriber: test that child spans close parents Signed-off-by: Eliza Weisman --- tracing-subscriber/src/registry/sharded.rs | 93 +++++++++++++++++++++- 1 file changed, 90 insertions(+), 3 deletions(-) diff --git a/tracing-subscriber/src/registry/sharded.rs b/tracing-subscriber/src/registry/sharded.rs index b050805a40..f2302305e0 100644 --- a/tracing-subscriber/src/registry/sharded.rs +++ b/tracing-subscriber/src/registry/sharded.rs @@ -352,9 +352,12 @@ impl<'a> SpanData<'a> for Data<'a> { mod tests { use super::{Registry, CURRENT_SPANS}; use crate::{layer::Context, registry::LookupSpan, Layer}; - use std::sync::{ - atomic::{AtomicBool, Ordering}, - Arc, + use std::{ + collections::VecDeque, + sync::{ + atomic::{AtomicBool, Ordering}, + Arc, Mutex, + }, }; use tracing::{self, subscriber::with_default}; use tracing_core::{ @@ -396,6 +399,11 @@ mod tests { }); } + struct CloseInOrder { + inner: Mutex>, + okay: Arc, + } + struct ClosingLayer { span1_removed: Arc, span2_removed: Arc, @@ -439,6 +447,43 @@ mod tests { } } + impl Layer for CloseInOrder + where + S: Subscriber + for<'a> LookupSpan<'a>, + { + fn on_close(&self, id: Id, ctx: Context<'_, S>) { + let span = &ctx.span(&id).unwrap(); + let name = span.name(); + if let Ok(mut lock) = self.inner.lock() { + if let Some(next) = lock.pop_front() { + if next != name { + println!( + "expected span \"{}\" to close next, but \"{}\" closed instead!", + next, name + ); + self.okay.store(false, Ordering::Release); + } + } else { + println!( + "span \"{}\" closed when no more spans were expected to close", + name + ); + self.okay.store(false, Ordering::Release); + } + } + } + } + + impl CloseInOrder { + fn new(i: impl IntoIterator) -> (Self, Arc) { + let closes = i.into_iter().collect::>(); + let inner = Mutex::new(closes); + let okay = Arc::new(AtomicBool::new(true)); + let handle = okay.clone(); + (Self { inner, okay }, handle) + } + } + #[test] fn spans_are_removed_from_registry() { let span1_removed = Arc::new(AtomicBool::new(false)); @@ -553,4 +598,46 @@ mod tests { assert!(span2_removed.load(Ordering::Acquire)); }); } + + #[test] + fn child_closes_parent() { + let span1_removed = Arc::new(AtomicBool::new(false)); + let span2_removed = Arc::new(AtomicBool::new(false)); + let (order_layer, closed_in_order) = CloseInOrder::new(vec!["span2", "span1"]); + + let subscriber = order_layer + .and_then(ClosingLayer { + span1_removed: span1_removed.clone(), + span2_removed: span2_removed.clone(), + }) + .with_subscriber(Registry::default()); + + let dispatch = dispatcher::Dispatch::new(subscriber); + + dispatcher::with_default(&dispatch, || { + let span1 = tracing::info_span!("span1"); + let span2 = tracing::info_span!(parent: &span1, "span2"); + + assert!(!span1_removed.load(Ordering::Acquire)); + assert!(!span2_removed.load(Ordering::Acquire)); + + drop(span1); + + assert!( + !span1_removed.load(Ordering::Acquire), + "span1 must not have closed yet (span2 is keeping it open)" + ); + assert!(!span2_removed.load(Ordering::Acquire)); + + drop(span2); + + assert!(span2_removed.load(Ordering::Acquire)); + assert!(span1_removed.load(Ordering::Acquire)); + }); + + assert!( + closed_in_order.load(Ordering::Acquire), + "spans closed out of order!" + ); + } } From 1d70d8a0eaa39a8251a917de17e83ed1f0726fe8 Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Tue, 7 Jan 2020 11:32:30 -0800 Subject: [PATCH 2/6] subscriber: fix spans closed by their children not being removed The issue here is that the `CloseGuard` removes the span from the registry (dropping the `DataInner`) *before* it decrements CLOSE_COUNT. Dropping the `DataInner` will decrement the parent span's ref count, potentially allowing it to close. When the new close for the parent span starts, CLOSE_COUNT will be 1, not 0, and it will not be decremented until after the try_close call completes. This means that although the close is processed and all the layers see `on_close` calls for that span, the span's data is never removed from the registry, effectively leaking it. This commit fixes the problem by decrementing CLOSE_COUNT *before* we trigger the parent to close. Fixes #511 Signed-off-by: Eliza Weisman --- tracing-subscriber/src/registry/sharded.rs | 12 ++++++++---- 1 file changed, 8 insertions(+), 4 deletions(-) diff --git a/tracing-subscriber/src/registry/sharded.rs b/tracing-subscriber/src/registry/sharded.rs index f2302305e0..302a1e376a 100644 --- a/tracing-subscriber/src/registry/sharded.rs +++ b/tracing-subscriber/src/registry/sharded.rs @@ -310,16 +310,20 @@ impl<'a> Drop for CloseGuard<'a> { // except by avoiding a double-panic. let _ = CLOSE_COUNT.try_with(|count| { let c = count.get(); + // Decrement the count to indicate that _this_ guard's + // `on_close` callback has completed. + // + // Note that we *must* do this before we actually remove the span + // from the registry, since dropping the `DataInner` may trigger a + // new close, if this span is the last reference to a parent span. + count.set(c - 1); + // If the current close count is 1, this stack frame is the last // `on_close` call. If the span is closing, it's okay to remove the // span. if c == 1 && self.is_closing { self.registry.spans.remove(id_to_idx(&self.id)); } - - // Decrement the count to indicate that _this_ guard's - // `on_close` callback has completed. - count.set(c - 1); }); } } From ebf88f0058c2b686fd0be7d26cef35db3e5b44d2 Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Tue, 7 Jan 2020 11:38:57 -0800 Subject: [PATCH 3/6] subscriber: test child closing a grandparent This commit adds a test that when a span is kept open by a child which is *itself* kept open by a child, closing the grandchild will close both the parent *and* the grandparent. This is currently broken. --- tracing-subscriber/src/registry/sharded.rs | 53 ++++++++++++++++++++++ 1 file changed, 53 insertions(+) diff --git a/tracing-subscriber/src/registry/sharded.rs b/tracing-subscriber/src/registry/sharded.rs index 302a1e376a..56f62cbdc7 100644 --- a/tracing-subscriber/src/registry/sharded.rs +++ b/tracing-subscriber/src/registry/sharded.rs @@ -644,4 +644,57 @@ mod tests { "spans closed out of order!" ); } + + #[test] + fn child_closes_grandparent() { + let span1_removed = Arc::new(AtomicBool::new(false)); + let span2_removed = Arc::new(AtomicBool::new(false)); + let (order_layer, closed_in_order) = CloseInOrder::new(vec!["span3", "span2", "span1"]); + + let subscriber = order_layer + .and_then(ClosingLayer { + span1_removed: span1_removed.clone(), + span2_removed: span2_removed.clone(), + }) + .with_subscriber(Registry::default()); + + let dispatch = dispatcher::Dispatch::new(subscriber); + + dispatcher::with_default(&dispatch, || { + let span1 = tracing::info_span!("span1"); + let span2 = tracing::info_span!(parent: &span1, "span2"); + let span3 = tracing::info_span!(parent: &span2, "span3"); + + assert!(!span1_removed.load(Ordering::Acquire)); + assert!(!span2_removed.load(Ordering::Acquire)); + + drop(span1); + drop(span2); + + assert!( + !span1_removed.load(Ordering::Acquire), + "span1 must not have closed yet (span2 is keeping it open)" + ); + assert!( + !span2_removed.load(Ordering::Acquire), + "span2 must not have closed yet (span3 is keeping it open)" + ); + + drop(span3); + + assert!( + span2_removed.load(Ordering::Acquire), + "closing span3 should have closed span2" + ); + assert!( + span1_removed.load(Ordering::Acquire), + "closing span2 should have closed span1" + ); + }); + + assert!( + closed_in_order.load(Ordering::Acquire), + "spans closed out of order!" + ); + } } From 942d9cc6fca095aad8afdfe6c4d699d6d9242a8d Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Tue, 7 Jan 2020 14:50:17 -0800 Subject: [PATCH 4/6] subscriber: fix child spans not closing grandparents Currently, in situations where multiple parent spans are kept open by a child, only the first parent will be successfully closed. This is because calling `dispatcher::get_default` unsets the default dispatcher temporarily, so that nested `get_default` calls will receive a no-op subscriber. This was intended to prevent infinite dispatch loops when a subscriber calls into code that emits its own traces. Unfortunately, this means that if dropping the parent span would then trigger an additional span to drop, the dispatcher is now unset. This commit fixes this by cloning the dispatcher out of the `get_default` closure _before_ trying to close the parent span. This means that the `get_default` calls are no longer nested. This does have the disadvantage of introducing an additional `Arc` increment/decrement to the span-closing path. The impact of that shouldn't be too big, but if necessary we can try to optimize this in the future. --- tracing-subscriber/src/registry/sharded.rs | 11 +++++------ 1 file changed, 5 insertions(+), 6 deletions(-) diff --git a/tracing-subscriber/src/registry/sharded.rs b/tracing-subscriber/src/registry/sharded.rs index 56f62cbdc7..f386b8062c 100644 --- a/tracing-subscriber/src/registry/sharded.rs +++ b/tracing-subscriber/src/registry/sharded.rs @@ -13,7 +13,7 @@ use std::{ sync::atomic::{fence, AtomicUsize, Ordering}, }; use tracing_core::{ - dispatcher, + dispatcher::{self, Dispatch}, span::{self, Current, Id}, Event, Interest, Metadata, Subscriber, }; @@ -288,11 +288,10 @@ impl Drop for DataInner { // we must call `try_close` on the entire subscriber stack, rather // than just on the registry. If the registry called `try_close` on // itself directly, the layers wouldn't see the close notification. - dispatcher::get_default(|subscriber| { - if let Some(parent) = self.parent.take() { - let _ = subscriber.try_close(parent); - } - }) + let subscriber = dispatcher::get_default(Dispatch::clone); + if let Some(parent) = self.parent.take() { + let _ = subscriber.try_close(parent); + } } } } From 9cf74183d1d34702964d0603e5fe9f4f72bf9bcb Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Tue, 7 Jan 2020 14:57:58 -0800 Subject: [PATCH 5/6] fix unused import --- tracing-subscriber/src/registry/sharded.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/tracing-subscriber/src/registry/sharded.rs b/tracing-subscriber/src/registry/sharded.rs index f386b8062c..206c1229db 100644 --- a/tracing-subscriber/src/registry/sharded.rs +++ b/tracing-subscriber/src/registry/sharded.rs @@ -353,7 +353,7 @@ impl<'a> SpanData<'a> for Data<'a> { #[cfg(test)] mod tests { - use super::{Registry, CURRENT_SPANS}; + use super::Registry; use crate::{layer::Context, registry::LookupSpan, Layer}; use std::{ collections::VecDeque, From 228f37e53f255e07b15057c62c9c2d613945f336 Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Tue, 7 Jan 2020 15:42:35 -0800 Subject: [PATCH 6/6] document tests for @davidbarsky --- tracing-subscriber/src/registry/sharded.rs | 5 +++-- 1 file changed, 3 insertions(+), 2 deletions(-) diff --git a/tracing-subscriber/src/registry/sharded.rs b/tracing-subscriber/src/registry/sharded.rs index 206c1229db..15ce57d721 100644 --- a/tracing-subscriber/src/registry/sharded.rs +++ b/tracing-subscriber/src/registry/sharded.rs @@ -133,7 +133,7 @@ impl Registry { /// [`CloseGuard`]: ./struct.CloseGuard.html pub(crate) fn start_close(&self, id: Id) -> CloseGuard<'_> { CLOSE_COUNT.with(|count| { - let c = count.get(); + let c = dbg!(count.get()); count.set(c + 1); }); CloseGuard { @@ -243,10 +243,11 @@ impl Subscriber for Registry { }; let refs = span.ref_count.fetch_sub(1, Ordering::Release); + dbg!((span.metadata.name(), refs)); if !std::thread::panicking() { assert!(refs < std::usize::MAX, "reference count overflow!"); } - if refs > 1 { + if dbg!(refs > 1) { return false; }