1 use std::{
2 ptr,
3 sync::atomic::{AtomicPtr, Ordering},
4 thread::{self, JoinHandle},
5 time::Duration,
6 };
7
8 use tracing_core::{
9 callsite::{Callsite as _, DefaultCallsite},
10 dispatcher::set_default,
11 field::{FieldSet, Value},
12 span, Dispatch, Event, Kind, Level, Metadata, Subscriber,
13 };
14
15 struct TestSubscriber {
16 sleep: Duration,
17 callsite: AtomicPtr<Metadata<'static>>,
18 }
19
20 impl TestSubscriber {
new(sleep_micros: u64) -> Self21 fn new(sleep_micros: u64) -> Self {
22 Self {
23 sleep: Duration::from_micros(sleep_micros),
24 callsite: AtomicPtr::new(ptr::null_mut()),
25 }
26 }
27 }
28
29 impl Subscriber for TestSubscriber {
register_callsite(&self, metadata: &'static Metadata<'static>) -> tracing_core::Interest30 fn register_callsite(&self, metadata: &'static Metadata<'static>) -> tracing_core::Interest {
31 if !self.sleep.is_zero() {
32 thread::sleep(self.sleep);
33 }
34
35 self.callsite
36 .store(metadata as *const _ as *mut _, Ordering::SeqCst);
37
38 tracing_core::Interest::always()
39 }
40
event(&self, event: &tracing_core::Event<'_>)41 fn event(&self, event: &tracing_core::Event<'_>) {
42 let stored_callsite = self.callsite.load(Ordering::SeqCst);
43 let event_callsite: *mut Metadata<'static> = event.metadata() as *const _ as *mut _;
44
45 // This assert is the actual test.
46 assert_eq!(
47 stored_callsite, event_callsite,
48 "stored callsite: {stored_callsite:#?} does not match event \
49 callsite: {event_callsite:#?}. Was `event` called before \
50 `register_callsite`?"
51 );
52 }
53
enabled(&self, _metadata: &Metadata<'_>) -> bool54 fn enabled(&self, _metadata: &Metadata<'_>) -> bool {
55 true
56 }
new_span(&self, _span: &span::Attributes<'_>) -> span::Id57 fn new_span(&self, _span: &span::Attributes<'_>) -> span::Id {
58 span::Id::from_u64(0)
59 }
record(&self, _span: &span::Id, _values: &span::Record<'_>)60 fn record(&self, _span: &span::Id, _values: &span::Record<'_>) {}
record_follows_from(&self, _span: &span::Id, _follows: &span::Id)61 fn record_follows_from(&self, _span: &span::Id, _follows: &span::Id) {}
enter(&self, _span: &tracing_core::span::Id)62 fn enter(&self, _span: &tracing_core::span::Id) {}
exit(&self, _span: &tracing_core::span::Id)63 fn exit(&self, _span: &tracing_core::span::Id) {}
64 }
65
subscriber_thread(idx: usize, register_sleep_micros: u64) -> JoinHandle<()>66 fn subscriber_thread(idx: usize, register_sleep_micros: u64) -> JoinHandle<()> {
67 thread::Builder::new()
68 .name(format!("subscriber-{idx}"))
69 .spawn(move || {
70 // We use a sleep to ensure the starting order of the 2 threads.
71 let subscriber = TestSubscriber::new(register_sleep_micros);
72 let _dispatch_guard = set_default(&Dispatch::new(subscriber));
73
74 static CALLSITE: DefaultCallsite = {
75 // The values of the metadata are unimportant
76 static META: Metadata<'static> = Metadata::new(
77 "event ",
78 "module::path",
79 Level::INFO,
80 None,
81 None,
82 None,
83 FieldSet::new(&["message"], tracing_core::callsite::Identifier(&CALLSITE)),
84 Kind::EVENT,
85 );
86 DefaultCallsite::new(&META)
87 };
88 let _interest = CALLSITE.interest();
89
90 let meta = CALLSITE.metadata();
91 let field = meta.fields().field("message").unwrap();
92 let message = format!("event-from-{idx}", idx = idx);
93 let values = [(&field, Some(&message as &dyn Value))];
94 let value_set = CALLSITE.metadata().fields().value_set(&values);
95
96 Event::dispatch(meta, &value_set);
97
98 // Wait a bit for everything to end (we don't want to remove the subscriber
99 // immediately because that will influence the test).
100 thread::sleep(Duration::from_millis(10));
101 })
102 .expect("failed to spawn thread")
103 }
104
105 /// Regression test for missing register_callsite call (#2743)
106 ///
107 /// This test provokes the race condition which causes the second subscriber to not receive a
108 /// call to `register_callsite` before it receives a call to `event`.
109 ///
110 /// Because the test depends on the interaction of multiple dispatchers in different threads,
111 /// it needs to be in a test file by itself.
112 #[test]
event_before_register()113 fn event_before_register() {
114 let subscriber_1_register_sleep_micros = 100;
115 let subscriber_2_register_sleep_micros = 0;
116
117 let jh1 = subscriber_thread(1, subscriber_1_register_sleep_micros);
118
119 // This delay ensures that the event callsite has interest() called first.
120 thread::sleep(Duration::from_micros(50));
121 let jh2 = subscriber_thread(2, subscriber_2_register_sleep_micros);
122
123 jh1.join().expect("failed to join thread");
124 jh2.join().expect("failed to join thread");
125 }
126