|
| 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 { |
| 21 | + 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 { |
| 30 | + 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 | + |
| 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 | + |
| 54 | + fn enabled(&self, _metadata: &Metadata<'_>) -> bool { |
| 55 | + true |
| 56 | + } |
| 57 | + fn new_span(&self, _span: &span::Attributes<'_>) -> span::Id { |
| 58 | + span::Id::from_u64(0) |
| 59 | + } |
| 60 | + fn record(&self, _span: &span::Id, _values: &span::Record<'_>) {} |
| 61 | + fn record_follows_from(&self, _span: &span::Id, _follows: &span::Id) {} |
| 62 | + fn enter(&self, _span: &tracing_core::span::Id) {} |
| 63 | + fn exit(&self, _span: &tracing_core::span::Id) {} |
| 64 | +} |
| 65 | + |
| 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] |
| 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 | +} |
0 commit comments