From 4d144f3463b2f2a3aa484fd95023d21edb114793 Mon Sep 17 00:00:00 2001 From: Scott Gerring Date: Wed, 19 Mar 2025 13:27:13 +0100 Subject: [PATCH 01/13] test: bit more coverage on context --- opentelemetry/src/context.rs | 108 +++++++++++++++++++++++++++++++++-- 1 file changed, 102 insertions(+), 6 deletions(-) diff --git a/opentelemetry/src/context.rs b/opentelemetry/src/context.rs index a107741f56..0ab15de21b 100644 --- a/opentelemetry/src/context.rs +++ b/opentelemetry/src/context.rs @@ -653,20 +653,116 @@ mod tests { for _ in 0..16 { let cx_guard = Context::current().with_value(ValueA(1)).attach(); assert_eq!(cx_guard.cx_pos, ContextStack::MAX_POS); - assert_eq!(Context::current().get(), Some(&ValueA(2))); + assert_eq!(Context::current().get::(), Some(&ValueA(2))); assert_eq!(Context::current().get(), Some(&ValueB(stack_max_pos - 2))); guards.push(cx_guard); } } + + + /// Tests that a new ContextStack is created with the correct initial capacity. + #[test] + fn test_initial_capacity() { + let stack = ContextStack::default(); + assert_eq!(stack.stack.capacity(), ContextStack::INITIAL_CAPACITY); + } + + /// Tests that map_current_cx correctly accesses the current context. + + #[test] + fn test_map_current_cx() { + let mut stack = ContextStack::default(); + let test_value = ValueA(42); + stack.current_cx = Context::new().with_value(test_value); + + let result = stack.map_current_cx(|cx| { + assert_eq!(cx.get::(), Some(&ValueA(42))); + true + }); + assert!(result); + } + + /// Tests popping contexts in non-sequential order. + + #[test] + fn test_pop_id_out_of_order() { + let mut stack = ContextStack::default(); + + // Push three contexts + let cx1 = Context::new().with_value(ValueA(1)); + let cx2 = Context::new().with_value(ValueA(2)); + let cx3 = Context::new().with_value(ValueA(3)); + + let id1 = stack.push(cx1); + let id2 = stack.push(cx2); + let id3 = stack.push(cx3); + + // Pop middle context first - should not affect current context + stack.pop_id(id2); + assert_eq!(stack.current_cx.get::(), Some(&ValueA(3))); + assert_eq!(stack.stack.len(), 3); // Length unchanged for middle pops + + // Pop last context - should restore previous valid context + stack.pop_id(id3); + assert_eq!(stack.current_cx.get::(), Some(&ValueA(1))); + assert_eq!(stack.stack.len(), 1); + + // Pop first context - should restore to empty state + stack.pop_id(id1); + assert_eq!(stack.current_cx.get::(), None); + assert_eq!(stack.stack.len(), 0); + } + + /// Tests edge cases in context stack operations. IRL these should log + /// warnings, and definitely not panic. #[test] - fn context_stack_pop_id() { - // This is to get full line coverage of the `pop_id` function. - // In real life the `Drop`` implementation of `ContextGuard` ensures that - // the ids are valid and inside the bounds. + fn test_pop_id_edge_cases() { let mut stack = ContextStack::default(); + + // Test popping BASE_POS - should be no-op stack.pop_id(ContextStack::BASE_POS); + assert_eq!(stack.stack.len(), 0); + + // Test popping MAX_POS - should be no-op stack.pop_id(ContextStack::MAX_POS); - stack.pop_id(4711); + assert_eq!(stack.stack.len(), 0); + + // Test popping invalid position - should be no-op + stack.pop_id(1000); + assert_eq!(stack.stack.len(), 0); + + // Test popping from empty stack - should be safe + stack.pop_id(1); + assert_eq!(stack.stack.len(), 0); + } + + /// Tests stack behavior when reaching maximum capacity. + /// Once we push beyond this point, we should end up with a context + /// that points _somewhere_, but mutating it should not affect the current + /// active context. + #[test] + fn test_push_overflow() { + let mut stack = ContextStack::default(); + let max_pos = ContextStack::MAX_POS as usize; + + // Fill stack up to max position + for i in 0..max_pos { + let cx = Context::new().with_value(ValueA(i as u64)); + let id = stack.push(cx); + assert_eq!(id, (i + 1) as u16); + } + + // Try to push beyond capacity + let cx = Context::new().with_value(ValueA(max_pos as u64)); + let id = stack.push(cx); + assert_eq!(id, ContextStack::MAX_POS); + + // Verify current context remains unchanged after overflow + assert_eq!( + stack.current_cx.get::(), + Some(&ValueA((max_pos - 2) as u64)) + ); } + } From 408ff96ad91cfc6776c73f0f45e1b1a277e68a90 Mon Sep 17 00:00:00 2001 From: Scott Gerring Date: Wed, 19 Mar 2025 13:31:48 +0100 Subject: [PATCH 02/13] chore: add log for invalid pops --- opentelemetry/src/context.rs | 15 +++++++++++++++ 1 file changed, 15 insertions(+) diff --git a/opentelemetry/src/context.rs b/opentelemetry/src/context.rs index 0ab15de21b..23190733ba 100644 --- a/opentelemetry/src/context.rs +++ b/opentelemetry/src/context.rs @@ -460,6 +460,15 @@ impl ContextStack { // The empty context is always at the bottom of the [`ContextStack`] // and cannot be popped, and the overflow position is invalid, so do // nothing. + otel_warn!( + name: "Context.PopInvalidPosition", + position = pos, + message = if pos == ContextStack::BASE_POS { + "Attempted to pop the base context which is not allowed" + } else { + "Attempted to pop the overflow position which is not allowed" + } + ); return; } let len: u16 = self.stack.len() as u16; @@ -479,6 +488,12 @@ impl ContextStack { // This is an out of order pop. if pos >= len { // This is an invalid id, ignore it. + otel_warn!( + name: "Context.PopOutOfBounds", + position = pos, + stack_length = len, + message = "Attempted to pop beyond the end of the context stack" + ); return; } // Clear out the entry at the given id. From 1ecd2fbbb0b12d44eed657ce69a9714f3d303767 Mon Sep 17 00:00:00 2001 From: Scott Gerring Date: Wed, 19 Mar 2025 14:03:46 +0100 Subject: [PATCH 03/13] validate context behaviour across async boundaries --- opentelemetry/Cargo.toml | 2 ++ opentelemetry/src/context.rs | 65 ++++++++++++++++++++++++++++++++---- 2 files changed, 60 insertions(+), 7 deletions(-) diff --git a/opentelemetry/Cargo.toml b/opentelemetry/Cargo.toml index 497af21b46..a82d263b14 100644 --- a/opentelemetry/Cargo.toml +++ b/opentelemetry/Cargo.toml @@ -43,6 +43,8 @@ internal-logs = ["tracing"] opentelemetry_sdk = { path = "../opentelemetry-sdk", features = ["spec_unstable_logs_enabled"]} # for documentation tests criterion = { workspace = true } rand = { workspace = true, features = ["os_rng", "thread_rng"] } +tokio = { version = "1.0", features = ["full"] } +futures = "0.3" [[bench]] name = "metrics" diff --git a/opentelemetry/src/context.rs b/opentelemetry/src/context.rs index 23190733ba..90269fd19b 100644 --- a/opentelemetry/src/context.rs +++ b/opentelemetry/src/context.rs @@ -520,6 +520,8 @@ impl Default for ContextStack { #[cfg(test)] mod tests { use super::*; + use std::time::Duration; + use tokio::time::sleep; #[derive(Debug, PartialEq)] struct ValueA(u64); @@ -588,7 +590,7 @@ mod tests { assert!(Context::map_current(|cx| { assert_eq!(cx.get(), Some(&ValueA(1))); - assert_eq!(cx.get::(), None); + assert_eq!(cx.get(), Some(&ValueB(42))); true })); } @@ -661,7 +663,7 @@ mod tests { // Push a new context and see that it works let cx_guard = Context::current().with_value(ValueA(2)).attach(); assert_eq!(cx_guard.cx_pos, ContextStack::MAX_POS - 1); - assert_eq!(Context::current().get(), Some(&ValueA(2))); + assert_eq!(Context::current().get::(), Some(&ValueA(2))); assert_eq!(Context::current().get(), Some(&ValueB(stack_max_pos - 2))); guards.push(cx_guard); // Let's overflow the stack a couple of times again @@ -674,8 +676,6 @@ mod tests { } } - - /// Tests that a new ContextStack is created with the correct initial capacity. #[test] fn test_initial_capacity() { @@ -684,7 +684,6 @@ mod tests { } /// Tests that map_current_cx correctly accesses the current context. - #[test] fn test_map_current_cx() { let mut stack = ContextStack::default(); @@ -699,7 +698,6 @@ mod tests { } /// Tests popping contexts in non-sequential order. - #[test] fn test_pop_id_out_of_order() { let mut stack = ContextStack::default(); @@ -779,5 +777,58 @@ mod tests { Some(&ValueA((max_pos - 2) as u64)) ); } - + + /// Tests that: + /// 1. Parent context values are properly propagated to async operations + /// 2. Values added during async operations are captured by telemetry but don't affect parent + #[tokio::test] + async fn test_async_context_propagation() { + // Set up initial context with ValueA + let parent_cx = Context::new().with_value(ValueA(42)); + + // Create and run async operation with the parent context + async { + // Verify we can see the parent context's value + assert_eq!(Context::current().get::(), Some(&ValueA(42)), + "Parent context value should be available in async operation"); + + // Create new context with both values + let cx_with_both = Context::current().with_value(ValueB(24)); + + // Run nested async operation with both values + async { + // Verify both values are available + assert_eq!(Context::current().get::(), Some(&ValueA(42)), + "Parent value should still be available after adding new value"); + assert_eq!(Context::current().get::(), Some(&ValueB(24)), + "New value should be available in async operation"); + + // Do some async work to simulate real-world scenario + sleep(Duration::from_millis(10)).await; + + // Values should still be available after async work + assert_eq!(Context::current().get::(), Some(&ValueA(42)), + "Parent value should persist across await points"); + assert_eq!(Context::current().get::(), Some(&ValueB(24)), + "New value should persist across await points"); + } + .with_context(cx_with_both) + .await; + } + .with_context(parent_cx.clone()) // Propagate the parent context to the async operation + .await; + + // After async operation completes: + // 1. Parent context should be unchanged + assert_eq!(parent_cx.get::(), Some(&ValueA(42)), + "Parent context should be unchanged"); + assert_eq!(parent_cx.get::(), None, + "Parent context should not see values added in async operation"); + + // 2. Current context should be back to default + assert_eq!(Context::current().get::(), None, + "Current context should be back to default"); + assert_eq!(Context::current().get::(), None, + "Current context should not have async operation's values"); + } } From 012d2132e01d3465c9f3e5b996f4606c4e0e6259 Mon Sep 17 00:00:00 2001 From: Scott Gerring Date: Wed, 19 Mar 2025 14:08:21 +0100 Subject: [PATCH 04/13] fix regression --- opentelemetry/src/context.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/opentelemetry/src/context.rs b/opentelemetry/src/context.rs index 90269fd19b..4b3e2be565 100644 --- a/opentelemetry/src/context.rs +++ b/opentelemetry/src/context.rs @@ -590,7 +590,7 @@ mod tests { assert!(Context::map_current(|cx| { assert_eq!(cx.get(), Some(&ValueA(1))); - assert_eq!(cx.get(), Some(&ValueB(42))); + assert_eq!(cx.get::(), None); true })); } From aba04a9543f92d856886718bd6b0d197ea6f9501 Mon Sep 17 00:00:00 2001 From: Scott Gerring Date: Wed, 19 Mar 2025 14:10:16 +0100 Subject: [PATCH 05/13] . --- opentelemetry/src/context.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/opentelemetry/src/context.rs b/opentelemetry/src/context.rs index 4b3e2be565..3383da5729 100644 --- a/opentelemetry/src/context.rs +++ b/opentelemetry/src/context.rs @@ -670,7 +670,7 @@ mod tests { for _ in 0..16 { let cx_guard = Context::current().with_value(ValueA(1)).attach(); assert_eq!(cx_guard.cx_pos, ContextStack::MAX_POS); - assert_eq!(Context::current().get::(), Some(&ValueA(2))); + assert_eq!(Context::current().get(), Some(&ValueA(2))); assert_eq!(Context::current().get(), Some(&ValueB(stack_max_pos - 2))); guards.push(cx_guard); } From 753d0d9c16da08b1d6d10f70049ba5947fdf4916 Mon Sep 17 00:00:00 2001 From: Scott Gerring Date: Wed, 19 Mar 2025 14:10:55 +0100 Subject: [PATCH 06/13] . --- opentelemetry/src/context.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/opentelemetry/src/context.rs b/opentelemetry/src/context.rs index 3383da5729..22504bc612 100644 --- a/opentelemetry/src/context.rs +++ b/opentelemetry/src/context.rs @@ -663,7 +663,7 @@ mod tests { // Push a new context and see that it works let cx_guard = Context::current().with_value(ValueA(2)).attach(); assert_eq!(cx_guard.cx_pos, ContextStack::MAX_POS - 1); - assert_eq!(Context::current().get::(), Some(&ValueA(2))); + assert_eq!(Context::current().get(), Some(&ValueA(2))); assert_eq!(Context::current().get(), Some(&ValueB(stack_max_pos - 2))); guards.push(cx_guard); // Let's overflow the stack a couple of times again From 782a4d412540fdcb88c911b3b694dea949d79f17 Mon Sep 17 00:00:00 2001 From: Scott Gerring Date: Wed, 19 Mar 2025 14:11:46 +0100 Subject: [PATCH 07/13] . --- opentelemetry/src/context.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/opentelemetry/src/context.rs b/opentelemetry/src/context.rs index 22504bc612..dc75f3db3f 100644 --- a/opentelemetry/src/context.rs +++ b/opentelemetry/src/context.rs @@ -780,7 +780,7 @@ mod tests { /// Tests that: /// 1. Parent context values are properly propagated to async operations - /// 2. Values added during async operations are captured by telemetry but don't affect parent + /// 2. Values added during async operations do not affect parent context #[tokio::test] async fn test_async_context_propagation() { // Set up initial context with ValueA From eaeefdbb6d0d77783101b5d6dbb938dddaa22451 Mon Sep 17 00:00:00 2001 From: Scott Gerring Date: Wed, 19 Mar 2025 14:59:20 +0100 Subject: [PATCH 08/13] formatting --- opentelemetry/src/context.rs | 79 ++++++++++++++++++++++++------------ 1 file changed, 53 insertions(+), 26 deletions(-) diff --git a/opentelemetry/src/context.rs b/opentelemetry/src/context.rs index dc75f3db3f..248bbe99be 100644 --- a/opentelemetry/src/context.rs +++ b/opentelemetry/src/context.rs @@ -728,7 +728,7 @@ mod tests { } /// Tests edge cases in context stack operations. IRL these should log - /// warnings, and definitely not panic. + /// warnings, and definitely not panic. #[test] fn test_pop_id_edge_cases() { let mut stack = ContextStack::default(); @@ -753,7 +753,7 @@ mod tests { /// Tests stack behavior when reaching maximum capacity. /// Once we push beyond this point, we should end up with a context /// that points _somewhere_, but mutating it should not affect the current - /// active context. + /// active context. #[test] fn test_push_overflow() { let mut stack = ContextStack::default(); @@ -780,37 +780,52 @@ mod tests { /// Tests that: /// 1. Parent context values are properly propagated to async operations - /// 2. Values added during async operations do not affect parent context + /// 2. Values added during async operations do not affect parent context #[tokio::test] async fn test_async_context_propagation() { // Set up initial context with ValueA let parent_cx = Context::new().with_value(ValueA(42)); - + // Create and run async operation with the parent context async { // Verify we can see the parent context's value - assert_eq!(Context::current().get::(), Some(&ValueA(42)), - "Parent context value should be available in async operation"); - + assert_eq!( + Context::current().get::(), + Some(&ValueA(42)), + "Parent context value should be available in async operation" + ); + // Create new context with both values let cx_with_both = Context::current().with_value(ValueB(24)); - + // Run nested async operation with both values async { // Verify both values are available - assert_eq!(Context::current().get::(), Some(&ValueA(42)), - "Parent value should still be available after adding new value"); - assert_eq!(Context::current().get::(), Some(&ValueB(24)), - "New value should be available in async operation"); - + assert_eq!( + Context::current().get::(), + Some(&ValueA(42)), + "Parent value should still be available after adding new value" + ); + assert_eq!( + Context::current().get::(), + Some(&ValueB(24)), + "New value should be available in async operation" + ); + // Do some async work to simulate real-world scenario sleep(Duration::from_millis(10)).await; - + // Values should still be available after async work - assert_eq!(Context::current().get::(), Some(&ValueA(42)), - "Parent value should persist across await points"); - assert_eq!(Context::current().get::(), Some(&ValueB(24)), - "New value should persist across await points"); + assert_eq!( + Context::current().get::(), + Some(&ValueA(42)), + "Parent value should persist across await points" + ); + assert_eq!( + Context::current().get::(), + Some(&ValueB(24)), + "New value should persist across await points" + ); } .with_context(cx_with_both) .await; @@ -820,15 +835,27 @@ mod tests { // After async operation completes: // 1. Parent context should be unchanged - assert_eq!(parent_cx.get::(), Some(&ValueA(42)), - "Parent context should be unchanged"); - assert_eq!(parent_cx.get::(), None, - "Parent context should not see values added in async operation"); + assert_eq!( + parent_cx.get::(), + Some(&ValueA(42)), + "Parent context should be unchanged" + ); + assert_eq!( + parent_cx.get::(), + None, + "Parent context should not see values added in async operation" + ); // 2. Current context should be back to default - assert_eq!(Context::current().get::(), None, - "Current context should be back to default"); - assert_eq!(Context::current().get::(), None, - "Current context should not have async operation's values"); + assert_eq!( + Context::current().get::(), + None, + "Current context should be back to default" + ); + assert_eq!( + Context::current().get::(), + None, + "Current context should not have async operation's values" + ); } } From 013bc4b492dd579a8d8992a801f5999d112ee63d Mon Sep 17 00:00:00 2001 From: Scott Gerring Date: Thu, 20 Mar 2025 08:52:26 +0100 Subject: [PATCH 09/13] address review comments --- opentelemetry/src/context.rs | 30 +++++++++++++++++------------- 1 file changed, 17 insertions(+), 13 deletions(-) diff --git a/opentelemetry/src/context.rs b/opentelemetry/src/context.rs index 248bbe99be..2773adc2b0 100644 --- a/opentelemetry/src/context.rs +++ b/opentelemetry/src/context.rs @@ -461,7 +461,7 @@ impl ContextStack { // and cannot be popped, and the overflow position is invalid, so do // nothing. otel_warn!( - name: "Context.PopInvalidPosition", + name: "Context.OutOfOrderDrop", position = pos, message = if pos == ContextStack::BASE_POS { "Attempted to pop the base context which is not allowed" @@ -783,11 +783,9 @@ mod tests { /// 2. Values added during async operations do not affect parent context #[tokio::test] async fn test_async_context_propagation() { - // Set up initial context with ValueA - let parent_cx = Context::new().with_value(ValueA(42)); - // Create and run async operation with the parent context - async { + // A nested async operation we'll use to test propagation + async fn nested_operation() { // Verify we can see the parent context's value assert_eq!( Context::current().get::(), @@ -795,15 +793,17 @@ mod tests { "Parent context value should be available in async operation" ); - // Create new context with both values - let cx_with_both = Context::current().with_value(ValueB(24)); + // Create new context + let cx_with_both = Context::current() + .with_value(ValueA(43))// override ValueA + .with_value(ValueB(24)); // Add new ValueB // Run nested async operation with both values async { // Verify both values are available assert_eq!( Context::current().get::(), - Some(&ValueA(42)), + Some(&ValueA(43)), "Parent value should still be available after adding new value" ); assert_eq!( @@ -818,7 +818,7 @@ mod tests { // Values should still be available after async work assert_eq!( Context::current().get::(), - Some(&ValueA(42)), + Some(&ValueA(43)), "Parent value should persist across await points" ); assert_eq!( @@ -827,11 +827,15 @@ mod tests { "New value should persist across await points" ); } - .with_context(cx_with_both) - .await; + .with_context(cx_with_both) + .await; } - .with_context(parent_cx.clone()) // Propagate the parent context to the async operation - .await; + + // Set up initial context with ValueA + let parent_cx = Context::new().with_value(ValueA(42)); + + // Create and run async operation with the parent context explicitly propagated + nested_operation().with_context(parent_cx.clone()).await; // After async operation completes: // 1. Parent context should be unchanged From ec167c5f4c76d7f69431dad267c02bedf24c451e Mon Sep 17 00:00:00 2001 From: Scott Gerring Date: Thu, 20 Mar 2025 09:24:30 +0100 Subject: [PATCH 10/13] add another test for out-of-order async drops --- opentelemetry/src/context.rs | 40 +++++++++++++++++++++++++++++++----- 1 file changed, 35 insertions(+), 5 deletions(-) diff --git a/opentelemetry/src/context.rs b/opentelemetry/src/context.rs index 2773adc2b0..b81173dc22 100644 --- a/opentelemetry/src/context.rs +++ b/opentelemetry/src/context.rs @@ -670,7 +670,7 @@ mod tests { for _ in 0..16 { let cx_guard = Context::current().with_value(ValueA(1)).attach(); assert_eq!(cx_guard.cx_pos, ContextStack::MAX_POS); - assert_eq!(Context::current().get(), Some(&ValueA(2))); + assert_eq!(Context::current().get::(), Some(&ValueA(2))); assert_eq!(Context::current().get(), Some(&ValueB(stack_max_pos - 2))); guards.push(cx_guard); } @@ -783,7 +783,6 @@ mod tests { /// 2. Values added during async operations do not affect parent context #[tokio::test] async fn test_async_context_propagation() { - // A nested async operation we'll use to test propagation async fn nested_operation() { // Verify we can see the parent context's value @@ -795,7 +794,7 @@ mod tests { // Create new context let cx_with_both = Context::current() - .with_value(ValueA(43))// override ValueA + .with_value(ValueA(43)) // override ValueA .with_value(ValueB(24)); // Add new ValueB // Run nested async operation with both values @@ -827,8 +826,8 @@ mod tests { "New value should persist across await points" ); } - .with_context(cx_with_both) - .await; + .with_context(cx_with_both) + .await; } // Set up initial context with ValueA @@ -862,4 +861,35 @@ mod tests { "Current context should not have async operation's values" ); } + + #[tokio::test] + async fn test_out_of_order_context_detachment_futures() { + // This function returns a future, but doesn't await it + // It will complete before the future that it creates. + async fn create_a_future() -> impl std::future::Future { + // Create a future that will do some work, referencing our current + // context, but don't await it. + async { + let _guard = Context::new().with_value(ValueB(2)).attach(); + // Longer work + sleep(Duration::from_millis(50)).await; + } + .with_context(Context::current()) + } + + // Create our base context + let parent_cx = Context::new().with_value(ValueA(42)); + + // await our nested function, which will create and detach a context + let future = create_a_future().with_context(parent_cx).await; + + // Execute the future. The completion of the future will result in an out-of-order drop, + // as the parent context created by create_a_future was already dropped earlier. + future.await; + + // Nothing terrible (e.g., panics!) should happen, and we should definitely not have any + // values attached to our current context that were set in the nested operations. + assert_eq!(Context::current().get::(), None); + assert_eq!(Context::current().get::(), None); + } } From 36c750bb2a38ce1db7346752f16954a140ceb9f3 Mon Sep 17 00:00:00 2001 From: Scott Gerring Date: Thu, 20 Mar 2025 11:39:06 +0100 Subject: [PATCH 11/13] Add an extra assertion on the out of order detachment test --- opentelemetry/src/context.rs | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/opentelemetry/src/context.rs b/opentelemetry/src/context.rs index b81173dc22..e2479cb177 100644 --- a/opentelemetry/src/context.rs +++ b/opentelemetry/src/context.rs @@ -870,6 +870,8 @@ mod tests { // Create a future that will do some work, referencing our current // context, but don't await it. async { + assert_eq!(Context::current().get::(), Some(&ValueA(42))); + let _guard = Context::new().with_value(ValueB(2)).attach(); // Longer work sleep(Duration::from_millis(50)).await; @@ -885,7 +887,7 @@ mod tests { // Execute the future. The completion of the future will result in an out-of-order drop, // as the parent context created by create_a_future was already dropped earlier. - future.await; + let _a = future.await; // Nothing terrible (e.g., panics!) should happen, and we should definitely not have any // values attached to our current context that were set in the nested operations. From 5aed1d617e94b8ae5fef9f88af600a0825bfe2b3 Mon Sep 17 00:00:00 2001 From: Scott Gerring Date: Thu, 20 Mar 2025 11:39:44 +0100 Subject: [PATCH 12/13] setup testing macros to print to stdout for test purposes --- opentelemetry/src/global/internal_logging.rs | 83 ++++++++++++++++++-- 1 file changed, 75 insertions(+), 8 deletions(-) diff --git a/opentelemetry/src/global/internal_logging.rs b/opentelemetry/src/global/internal_logging.rs index dad083ac1f..3629f63eb7 100644 --- a/opentelemetry/src/global/internal_logging.rs +++ b/opentelemetry/src/global/internal_logging.rs @@ -4,6 +4,9 @@ /// **internally within OpenTelemetry code** or for **custom exporters, processors and other plugins**. They are not designed /// for general application logging and should not be used for that purpose. /// +/// When running tests with `--nocapture`, these macros will print their output to stdout. This is useful for debugging +/// test failures and understanding the flow of operations during testing. +/// /// Macro for logging informational messages in OpenTelemetry. /// /// # Fields: @@ -25,7 +28,13 @@ macro_rules! otel_info { { tracing::info!( name: $name, target: env!("CARGO_PKG_NAME"), name = $name, ""); } - #[cfg(not(feature = "internal-logs"))] + + #[cfg(test)] + { + print!("otel_info: name={}\n", $name); + } + + #[cfg(all(not(feature = "internal-logs"), not(test)))] { let _ = $name; // Compiler will optimize this out as it's unused. } @@ -35,7 +44,17 @@ macro_rules! otel_info { { tracing::info!(name: $name, target: env!("CARGO_PKG_NAME"), name = $name, $($key = $value),+, ""); } - #[cfg(not(feature = "internal-logs"))] + + #[cfg(test)] + { + print!("otel_info: name={}", $name); + $( + print!(", {}={}", stringify!($key), $value); + )+ + print!("\n"); + } + + #[cfg(all(not(feature = "internal-logs"), not(test)))] { let _ = ($name, $($value),+); // Compiler will optimize this out as it's unused. } @@ -60,7 +79,13 @@ macro_rules! otel_warn { { tracing::warn!(name: $name, target: env!("CARGO_PKG_NAME"), name = $name, ""); } - #[cfg(not(feature = "internal-logs"))] + + #[cfg(test)] + { + print!("otel_warn: name={}\n", $name); + } + + #[cfg(all(not(feature = "internal-logs"), not(test)))] { let _ = $name; // Compiler will optimize this out as it's unused. } @@ -77,7 +102,17 @@ macro_rules! otel_warn { "" ) } - #[cfg(not(feature = "internal-logs"))] + + #[cfg(test)] + { + print!("otel_warn: name={}", $name); + $( + print!(", {}={}", stringify!($key), $value); + )+ + print!("\n"); + } + + #[cfg(all(not(feature = "internal-logs"), not(test)))] { let _ = ($name, $($value),+); // Compiler will optimize this out as it's unused. } @@ -102,7 +137,13 @@ macro_rules! otel_debug { { tracing::debug!(name: $name, target: env!("CARGO_PKG_NAME"), name = $name, ""); } - #[cfg(not(feature = "internal-logs"))] + + #[cfg(test)] + { + print!("otel_debug: name={}\n", $name); + } + + #[cfg(all(not(feature = "internal-logs"), not(test)))] { let _ = $name; // Compiler will optimize this out as it's unused. } @@ -112,7 +153,17 @@ macro_rules! otel_debug { { tracing::debug!(name: $name, target: env!("CARGO_PKG_NAME"), name = $name, $($key = $value),+, ""); } - #[cfg(not(feature = "internal-logs"))] + + #[cfg(test)] + { + print!("otel_debug: name={}", $name); + $( + print!(", {}={}", stringify!($key), $value); + )+ + print!("\n"); + } + + #[cfg(all(not(feature = "internal-logs"), not(test)))] { let _ = ($name, $($value),+); // Compiler will optimize this out as it's unused. } @@ -137,7 +188,13 @@ macro_rules! otel_error { { tracing::error!(name: $name, target: env!("CARGO_PKG_NAME"), name = $name, ""); } - #[cfg(not(feature = "internal-logs"))] + + #[cfg(test)] + { + print!("otel_error: name={}\n", $name); + } + + #[cfg(all(not(feature = "internal-logs"), not(test)))] { let _ = $name; // Compiler will optimize this out as it's unused. } @@ -154,7 +211,17 @@ macro_rules! otel_error { "" ) } - #[cfg(not(feature = "internal-logs"))] + + #[cfg(test)] + { + print!("otel_error: name={}", $name); + $( + print!(", {}={}", stringify!($key), $value); + )+ + print!("\n"); + } + + #[cfg(all(not(feature = "internal-logs"), not(test)))] { let _ = ($name, $($value),+); // Compiler will optimize this out as it's unused. } From aae46ee7444e3b4c2a507a24cfa112148578afd1 Mon Sep 17 00:00:00 2001 From: Scott Gerring Date: Thu, 20 Mar 2025 13:12:26 +0100 Subject: [PATCH 13/13] some cleanup --- opentelemetry/src/context.rs | 9 ++++++--- opentelemetry/src/global/internal_logging.rs | 2 +- 2 files changed, 7 insertions(+), 4 deletions(-) diff --git a/opentelemetry/src/context.rs b/opentelemetry/src/context.rs index e2479cb177..e7a45277b4 100644 --- a/opentelemetry/src/context.rs +++ b/opentelemetry/src/context.rs @@ -862,6 +862,10 @@ mod tests { ); } + /// + /// Tests that unnatural parent->child relationships in nested async + /// operations behave properly. + /// #[tokio::test] async fn test_out_of_order_context_detachment_futures() { // This function returns a future, but doesn't await it @@ -872,7 +876,6 @@ mod tests { async { assert_eq!(Context::current().get::(), Some(&ValueA(42))); - let _guard = Context::new().with_value(ValueB(2)).attach(); // Longer work sleep(Duration::from_millis(50)).await; } @@ -885,8 +888,8 @@ mod tests { // await our nested function, which will create and detach a context let future = create_a_future().with_context(parent_cx).await; - // Execute the future. The completion of the future will result in an out-of-order drop, - // as the parent context created by create_a_future was already dropped earlier. + // Execute the future. The future that created it is long gone, but this shouldn't + // cause issues. let _a = future.await; // Nothing terrible (e.g., panics!) should happen, and we should definitely not have any diff --git a/opentelemetry/src/global/internal_logging.rs b/opentelemetry/src/global/internal_logging.rs index 3629f63eb7..012a9c98ce 100644 --- a/opentelemetry/src/global/internal_logging.rs +++ b/opentelemetry/src/global/internal_logging.rs @@ -142,7 +142,7 @@ macro_rules! otel_debug { { print!("otel_debug: name={}\n", $name); } - + #[cfg(all(not(feature = "internal-logs"), not(test)))] { let _ = $name; // Compiler will optimize this out as it's unused.