1 //! Spans represent periods of time in which a program was executing in a 2 //! particular context. 3 //! 4 //! A span consists of [fields], user-defined key-value pairs of arbitrary data 5 //! that describe the context the span represents, and a set of fixed attributes 6 //! that describe all `tracing` spans and events. Attributes describing spans 7 //! include: 8 //! 9 //! - An [`Id`] assigned by the subscriber that uniquely identifies it in relation 10 //! to other spans. 11 //! - The span's [parent] in the trace tree. 12 //! - [Metadata] that describes static characteristics of all spans 13 //! originating from that callsite, such as its name, source code location, 14 //! [verbosity level], and the names of its fields. 15 //! 16 //! # Creating Spans 17 //! 18 //! Spans are created using the [`span!`] macro. This macro is invoked with the 19 //! following arguments, in order: 20 //! 21 //! - The [`target`] and/or [`parent`][parent] attributes, if the user wishes to 22 //! override their default values. 23 //! - The span's [verbosity level] 24 //! - A string literal providing the span's name. 25 //! - Finally, zero or more arbitrary key/value fields. 26 //! 27 //! [`target`]: super::Metadata::target 28 //! 29 //! For example: 30 //! ```rust 31 //! use tracing::{span, Level}; 32 //! 33 //! /// Construct a new span at the `INFO` level named "my_span", with a single 34 //! /// field named answer , with the value `42`. 35 //! let my_span = span!(Level::INFO, "my_span", answer = 42); 36 //! ``` 37 //! 38 //! The documentation for the [`span!`] macro provides additional examples of 39 //! the various options that exist when creating spans. 40 //! 41 //! The [`trace_span!`], [`debug_span!`], [`info_span!`], [`warn_span!`], and 42 //! [`error_span!`] exist as shorthand for constructing spans at various 43 //! verbosity levels. 44 //! 45 //! ## Recording Span Creation 46 //! 47 //! The [`Attributes`] type contains data associated with a span, and is 48 //! provided to the [`Subscriber`] when a new span is created. It contains 49 //! the span's metadata, the ID of [the span's parent][parent] if one was 50 //! explicitly set, and any fields whose values were recorded when the span was 51 //! constructed. The subscriber, which is responsible for recording `tracing` 52 //! data, can then store or record these values. 53 //! 54 //! # The Span Lifecycle 55 //! 56 //! ## Entering a Span 57 //! 58 //! A thread of execution is said to _enter_ a span when it begins executing, 59 //! and _exit_ the span when it switches to another context. Spans may be 60 //! entered through the [`enter`], [`entered`], and [`in_scope`] methods. 61 //! 62 //! The [`enter`] method enters a span, returning a [guard] that exits the span 63 //! when dropped 64 //! ``` 65 //! # use tracing::{span, Level}; 66 //! let my_var: u64 = 5; 67 //! let my_span = span!(Level::TRACE, "my_span", my_var); 68 //! 69 //! // `my_span` exists but has not been entered. 70 //! 71 //! // Enter `my_span`... 72 //! let _enter = my_span.enter(); 73 //! 74 //! // Perform some work inside of the context of `my_span`... 75 //! // Dropping the `_enter` guard will exit the span. 76 //!``` 77 //! 78 //! <div class="example-wrap" style="display:inline-block"><pre class="compile_fail" style="white-space:normal;font:inherit;"> 79 //! <strong>Warning</strong>: In asynchronous code that uses async/await syntax, 80 //! <code>Span::enter</code> may produce incorrect traces if the returned drop 81 //! guard is held across an await point. See 82 //! <a href="struct.Span.html#in-asynchronous-code">the method documentation</a> 83 //! for details. 84 //! </pre></div> 85 //! 86 //! The [`entered`] method is analogous to [`enter`], but moves the span into 87 //! the returned guard, rather than borrowing it. This allows creating and 88 //! entering a span in a single expression: 89 //! 90 //! ``` 91 //! # use tracing::{span, Level}; 92 //! // Create a span and enter it, returning a guard: 93 //! let span = span!(Level::INFO, "my_span").entered(); 94 //! 95 //! // We are now inside the span! Like `enter()`, the guard returned by 96 //! // `entered()` will exit the span when it is dropped... 97 //! 98 //! // ...but, it can also be exited explicitly, returning the `Span` 99 //! // struct: 100 //! let span = span.exit(); 101 //! ``` 102 //! 103 //! Finally, [`in_scope`] takes a closure or function pointer and executes it 104 //! inside the span: 105 //! 106 //! ``` 107 //! # use tracing::{span, Level}; 108 //! let my_var: u64 = 5; 109 //! let my_span = span!(Level::TRACE, "my_span", my_var = &my_var); 110 //! 111 //! my_span.in_scope(|| { 112 //! // perform some work in the context of `my_span`... 113 //! }); 114 //! 115 //! // Perform some work outside of the context of `my_span`... 116 //! 117 //! my_span.in_scope(|| { 118 //! // Perform some more work in the context of `my_span`. 119 //! }); 120 //! ``` 121 //! 122 //! <pre class="ignore" style="white-space:normal;font:inherit;"> 123 //! <strong>Note</strong>: Since entering a span takes <code>&self</code>, and 124 //! <code>Span</code>s are <code>Clone</code>, <code>Send</code>, and 125 //! <code>Sync</code>, it is entirely valid for multiple threads to enter the 126 //! same span concurrently. 127 //! </pre> 128 //! 129 //! ## Span Relationships 130 //! 131 //! Spans form a tree structure — unless it is a root span, all spans have a 132 //! _parent_, and may have one or more _children_. When a new span is created, 133 //! the current span becomes the new span's parent. The total execution time of 134 //! a span consists of the time spent in that span and in the entire subtree 135 //! represented by its children. Thus, a parent span always lasts for at least 136 //! as long as the longest-executing span in its subtree. 137 //! 138 //! ``` 139 //! # use tracing::{Level, span}; 140 //! // this span is considered the "root" of a new trace tree: 141 //! span!(Level::INFO, "root").in_scope(|| { 142 //! // since we are now inside "root", this span is considered a child 143 //! // of "root": 144 //! span!(Level::DEBUG, "outer_child").in_scope(|| { 145 //! // this span is a child of "outer_child", which is in turn a 146 //! // child of "root": 147 //! span!(Level::TRACE, "inner_child").in_scope(|| { 148 //! // and so on... 149 //! }); 150 //! }); 151 //! // another span created here would also be a child of "root". 152 //! }); 153 //!``` 154 //! 155 //! In addition, the parent of a span may be explicitly specified in 156 //! the `span!` macro. For example: 157 //! 158 //! ```rust 159 //! # use tracing::{Level, span}; 160 //! // Create, but do not enter, a span called "foo". 161 //! let foo = span!(Level::INFO, "foo"); 162 //! 163 //! // Create and enter a span called "bar". 164 //! let bar = span!(Level::INFO, "bar"); 165 //! let _enter = bar.enter(); 166 //! 167 //! // Although we have currently entered "bar", "baz"'s parent span 168 //! // will be "foo". 169 //! let baz = span!(parent: &foo, Level::INFO, "baz"); 170 //! ``` 171 //! 172 //! A child span should typically be considered _part_ of its parent. For 173 //! example, if a subscriber is recording the length of time spent in various 174 //! spans, it should generally include the time spent in a span's children as 175 //! part of that span's duration. 176 //! 177 //! In addition to having zero or one parent, a span may also _follow from_ any 178 //! number of other spans. This indicates a causal relationship between the span 179 //! and the spans that it follows from, but a follower is *not* typically 180 //! considered part of the duration of the span it follows. Unlike the parent, a 181 //! span may record that it follows from another span after it is created, using 182 //! the [`follows_from`] method. 183 //! 184 //! As an example, consider a listener task in a server. As the listener accepts 185 //! incoming connections, it spawns new tasks that handle those connections. We 186 //! might want to have a span representing the listener, and instrument each 187 //! spawned handler task with its own span. We would want our instrumentation to 188 //! record that the handler tasks were spawned as a result of the listener task. 189 //! However, we might not consider the handler tasks to be _part_ of the time 190 //! spent in the listener task, so we would not consider those spans children of 191 //! the listener span. Instead, we would record that the handler tasks follow 192 //! from the listener, recording the causal relationship but treating the spans 193 //! as separate durations. 194 //! 195 //! ## Closing Spans 196 //! 197 //! Execution may enter and exit a span multiple times before that span is 198 //! _closed_. Consider, for example, a future which has an associated 199 //! span and enters that span every time it is polled: 200 //! ```rust 201 //! # use std::future::Future; 202 //! # use std::task::{Context, Poll}; 203 //! # use std::pin::Pin; 204 //! struct MyFuture { 205 //! // data 206 //! span: tracing::Span, 207 //! } 208 //! 209 //! impl Future for MyFuture { 210 //! type Output = (); 211 //! 212 //! fn poll(self: Pin<&mut Self>, _cx: &mut Context<'_>) -> Poll<Self::Output> { 213 //! let _enter = self.span.enter(); 214 //! // Do actual future work... 215 //! # Poll::Ready(()) 216 //! } 217 //! } 218 //! ``` 219 //! 220 //! If this future was spawned on an executor, it might yield one or more times 221 //! before `poll` returns [`Poll::Ready`]. If the future were to yield, then 222 //! the executor would move on to poll the next future, which may _also_ enter 223 //! an associated span or series of spans. Therefore, it is valid for a span to 224 //! be entered repeatedly before it completes. Only the time when that span or 225 //! one of its children was the current span is considered to be time spent in 226 //! that span. A span which is not executing and has not yet been closed is said 227 //! to be _idle_. 228 //! 229 //! Because spans may be entered and exited multiple times before they close, 230 //! [`Subscriber`]s have separate trait methods which are called to notify them 231 //! of span exits and when span handles are dropped. When execution exits a 232 //! span, [`exit`] will always be called with that span's ID to notify the 233 //! subscriber that the span has been exited. When span handles are dropped, the 234 //! [`drop_span`] method is called with that span's ID. The subscriber may use 235 //! this to determine whether or not the span will be entered again. 236 //! 237 //! If there is only a single handle with the capacity to exit a span, dropping 238 //! that handle "closes" the span, since the capacity to enter it no longer 239 //! exists. For example: 240 //! ``` 241 //! # use tracing::{Level, span}; 242 //! { 243 //! span!(Level::TRACE, "my_span").in_scope(|| { 244 //! // perform some work in the context of `my_span`... 245 //! }); // --> Subscriber::exit(my_span) 246 //! 247 //! // The handle to `my_span` only lives inside of this block; when it is 248 //! // dropped, the subscriber will be informed via `drop_span`. 249 //! 250 //! } // --> Subscriber::drop_span(my_span) 251 //! ``` 252 //! 253 //! However, if multiple handles exist, the span can still be re-entered even if 254 //! one or more is dropped. For determining when _all_ handles to a span have 255 //! been dropped, `Subscriber`s have a [`clone_span`] method, which is called 256 //! every time a span handle is cloned. Combined with `drop_span`, this may be 257 //! used to track the number of handles to a given span — if `drop_span` has 258 //! been called one more time than the number of calls to `clone_span` for a 259 //! given ID, then no more handles to the span with that ID exist. The 260 //! subscriber may then treat it as closed. 261 //! 262 //! # When to use spans 263 //! 264 //! As a rule of thumb, spans should be used to represent discrete units of work 265 //! (e.g., a given request's lifetime in a server) or periods of time spent in a 266 //! given context (e.g., time spent interacting with an instance of an external 267 //! system, such as a database). 268 //! 269 //! Which scopes in a program correspond to new spans depend somewhat on user 270 //! intent. For example, consider the case of a loop in a program. Should we 271 //! construct one span and perform the entire loop inside of that span, like: 272 //! 273 //! ```rust 274 //! # use tracing::{Level, span}; 275 //! # let n = 1; 276 //! let span = span!(Level::TRACE, "my_loop"); 277 //! let _enter = span.enter(); 278 //! for i in 0..n { 279 //! # let _ = i; 280 //! // ... 281 //! } 282 //! ``` 283 //! Or, should we create a new span for each iteration of the loop, as in: 284 //! ```rust 285 //! # use tracing::{Level, span}; 286 //! # let n = 1u64; 287 //! for i in 0..n { 288 //! let span = span!(Level::TRACE, "my_loop", iteration = i); 289 //! let _enter = span.enter(); 290 //! // ... 291 //! } 292 //! ``` 293 //! 294 //! Depending on the circumstances, we might want to do either, or both. For 295 //! example, if we want to know how long was spent in the loop overall, we would 296 //! create a single span around the entire loop; whereas if we wanted to know how 297 //! much time was spent in each individual iteration, we would enter a new span 298 //! on every iteration. 299 //! 300 //! [fields]: super::field 301 //! [Metadata]: super::Metadata 302 //! [verbosity level]: super::Level 303 //! [`Poll::Ready`]: std::task::Poll::Ready 304 //! [`span!`]: super::span! 305 //! [`trace_span!`]: super::trace_span! 306 //! [`debug_span!`]: super::debug_span! 307 //! [`info_span!`]: super::info_span! 308 //! [`warn_span!`]: super::warn_span! 309 //! [`error_span!`]: super::error_span! 310 //! [`clone_span`]: super::subscriber::Subscriber::clone_span() 311 //! [`drop_span`]: super::subscriber::Subscriber::drop_span() 312 //! [`exit`]: super::subscriber::Subscriber::exit 313 //! [`Subscriber`]: super::subscriber::Subscriber 314 //! [`enter`]: Span::enter() 315 //! [`entered`]: Span::entered() 316 //! [`in_scope`]: Span::in_scope() 317 //! [`follows_from`]: Span::follows_from() 318 //! [guard]: Entered 319 //! [parent]: #span-relationships 320 pub use tracing_core::span::{Attributes, Id, Record}; 321 322 use crate::stdlib::{ 323 cmp, fmt, 324 hash::{Hash, Hasher}, 325 marker::PhantomData, 326 mem, 327 ops::Deref, 328 }; 329 use crate::{ 330 dispatcher::{self, Dispatch}, 331 field, Metadata, 332 }; 333 334 /// Trait implemented by types which have a span `Id`. 335 pub trait AsId: crate::sealed::Sealed { 336 /// Returns the `Id` of the span that `self` corresponds to, or `None` if 337 /// this corresponds to a disabled span. as_id(&self) -> Option<&Id>338 fn as_id(&self) -> Option<&Id>; 339 } 340 341 /// A handle representing a span, with the capability to enter the span if it 342 /// exists. 343 /// 344 /// If the span was rejected by the current `Subscriber`'s filter, entering the 345 /// span will silently do nothing. Thus, the handle can be used in the same 346 /// manner regardless of whether or not the trace is currently being collected. 347 #[derive(Clone)] 348 pub struct Span { 349 /// A handle used to enter the span when it is not executing. 350 /// 351 /// If this is `None`, then the span has either closed or was never enabled. 352 inner: Option<Inner>, 353 /// Metadata describing the span. 354 /// 355 /// This might be `Some` even if `inner` is `None`, in the case that the 356 /// span is disabled but the metadata is needed for `log` support. 357 meta: Option<&'static Metadata<'static>>, 358 } 359 360 /// A handle representing the capacity to enter a span which is known to exist. 361 /// 362 /// Unlike `Span`, this type is only constructed for spans which _have_ been 363 /// enabled by the current filter. This type is primarily used for implementing 364 /// span handles; users should typically not need to interact with it directly. 365 #[derive(Debug)] 366 pub(crate) struct Inner { 367 /// The span's ID, as provided by `subscriber`. 368 id: Id, 369 370 /// The subscriber that will receive events relating to this span. 371 /// 372 /// This should be the same subscriber that provided this span with its 373 /// `id`. 374 subscriber: Dispatch, 375 } 376 377 /// A guard representing a span which has been entered and is currently 378 /// executing. 379 /// 380 /// When the guard is dropped, the span will be exited. 381 /// 382 /// This is returned by the [`Span::enter`] function. 383 /// 384 /// [`Span::enter`]: super::Span::enter 385 #[derive(Debug)] 386 #[must_use = "once a span has been entered, it should be exited"] 387 pub struct Entered<'a> { 388 span: &'a Span, 389 } 390 391 /// An owned version of [`Entered`], a guard representing a span which has been 392 /// entered and is currently executing. 393 /// 394 /// When the guard is dropped, the span will be exited. 395 /// 396 /// This is returned by the [`Span::entered`] function. 397 /// 398 /// [`Span::entered`]: super::Span::entered() 399 #[derive(Debug)] 400 #[must_use = "once a span has been entered, it should be exited"] 401 pub struct EnteredSpan { 402 span: Span, 403 404 /// ```compile_fail 405 /// use tracing::span::*; 406 /// trait AssertSend: Send {} 407 /// 408 /// impl AssertSend for EnteredSpan {} 409 /// ``` 410 _not_send: PhantomNotSend, 411 } 412 413 /// `log` target for all span lifecycle (creation/enter/exit/close) records. 414 #[cfg(feature = "log")] 415 const LIFECYCLE_LOG_TARGET: &str = "tracing::span"; 416 /// `log` target for span activity (enter/exit) records. 417 #[cfg(feature = "log")] 418 const ACTIVITY_LOG_TARGET: &str = "tracing::span::active"; 419 420 // ===== impl Span ===== 421 422 impl Span { 423 /// Constructs a new `Span` with the given [metadata] and set of 424 /// [field values]. 425 /// 426 /// The new span will be constructed by the currently-active [`Subscriber`], 427 /// with the current span as its parent (if one exists). 428 /// 429 /// After the span is constructed, [field values] and/or [`follows_from`] 430 /// annotations may be added to it. 431 /// 432 /// [metadata]: super::Metadata 433 /// [`Subscriber`]: super::subscriber::Subscriber 434 /// [field values]: super::field::ValueSet 435 /// [`follows_from`]: super::Span::follows_from new(meta: &'static Metadata<'static>, values: &field::ValueSet<'_>) -> Span436 pub fn new(meta: &'static Metadata<'static>, values: &field::ValueSet<'_>) -> Span { 437 dispatcher::get_default(|dispatch| Self::new_with(meta, values, dispatch)) 438 } 439 440 #[inline] 441 #[doc(hidden)] new_with( meta: &'static Metadata<'static>, values: &field::ValueSet<'_>, dispatch: &Dispatch, ) -> Span442 pub fn new_with( 443 meta: &'static Metadata<'static>, 444 values: &field::ValueSet<'_>, 445 dispatch: &Dispatch, 446 ) -> Span { 447 let new_span = Attributes::new(meta, values); 448 Self::make_with(meta, new_span, dispatch) 449 } 450 451 /// Constructs a new `Span` as the root of its own trace tree, with the 452 /// given [metadata] and set of [field values]. 453 /// 454 /// After the span is constructed, [field values] and/or [`follows_from`] 455 /// annotations may be added to it. 456 /// 457 /// [metadata]: super::Metadata 458 /// [field values]: super::field::ValueSet 459 /// [`follows_from`]: super::Span::follows_from new_root(meta: &'static Metadata<'static>, values: &field::ValueSet<'_>) -> Span460 pub fn new_root(meta: &'static Metadata<'static>, values: &field::ValueSet<'_>) -> Span { 461 dispatcher::get_default(|dispatch| Self::new_root_with(meta, values, dispatch)) 462 } 463 464 #[inline] 465 #[doc(hidden)] new_root_with( meta: &'static Metadata<'static>, values: &field::ValueSet<'_>, dispatch: &Dispatch, ) -> Span466 pub fn new_root_with( 467 meta: &'static Metadata<'static>, 468 values: &field::ValueSet<'_>, 469 dispatch: &Dispatch, 470 ) -> Span { 471 let new_span = Attributes::new_root(meta, values); 472 Self::make_with(meta, new_span, dispatch) 473 } 474 475 /// Constructs a new `Span` as child of the given parent span, with the 476 /// given [metadata] and set of [field values]. 477 /// 478 /// After the span is constructed, [field values] and/or [`follows_from`] 479 /// annotations may be added to it. 480 /// 481 /// [metadata]: super::Metadata 482 /// [field values]: super::field::ValueSet 483 /// [`follows_from`]: super::Span::follows_from child_of( parent: impl Into<Option<Id>>, meta: &'static Metadata<'static>, values: &field::ValueSet<'_>, ) -> Span484 pub fn child_of( 485 parent: impl Into<Option<Id>>, 486 meta: &'static Metadata<'static>, 487 values: &field::ValueSet<'_>, 488 ) -> Span { 489 let mut parent = parent.into(); 490 dispatcher::get_default(move |dispatch| { 491 Self::child_of_with(Option::take(&mut parent), meta, values, dispatch) 492 }) 493 } 494 495 #[inline] 496 #[doc(hidden)] child_of_with( parent: impl Into<Option<Id>>, meta: &'static Metadata<'static>, values: &field::ValueSet<'_>, dispatch: &Dispatch, ) -> Span497 pub fn child_of_with( 498 parent: impl Into<Option<Id>>, 499 meta: &'static Metadata<'static>, 500 values: &field::ValueSet<'_>, 501 dispatch: &Dispatch, 502 ) -> Span { 503 let new_span = match parent.into() { 504 Some(parent) => Attributes::child_of(parent, meta, values), 505 None => Attributes::new_root(meta, values), 506 }; 507 Self::make_with(meta, new_span, dispatch) 508 } 509 510 /// Constructs a new disabled span with the given `Metadata`. 511 /// 512 /// This should be used when a span is constructed from a known callsite, 513 /// but the subscriber indicates that it is disabled. 514 /// 515 /// Entering, exiting, and recording values on this span will not notify the 516 /// `Subscriber` but _may_ record log messages if the `log` feature flag is 517 /// enabled. 518 #[inline(always)] new_disabled(meta: &'static Metadata<'static>) -> Span519 pub fn new_disabled(meta: &'static Metadata<'static>) -> Span { 520 Self { 521 inner: None, 522 meta: Some(meta), 523 } 524 } 525 526 /// Constructs a new span that is *completely disabled*. 527 /// 528 /// This can be used rather than `Option<Span>` to represent cases where a 529 /// span is not present. 530 /// 531 /// Entering, exiting, and recording values on this span will do nothing. 532 #[inline(always)] none() -> Span533 pub const fn none() -> Span { 534 Self { 535 inner: None, 536 meta: None, 537 } 538 } 539 540 /// Returns a handle to the span [considered by the `Subscriber`] to be the 541 /// current span. 542 /// 543 /// If the subscriber indicates that it does not track the current span, or 544 /// that the thread from which this function is called is not currently 545 /// inside a span, the returned span will be disabled. 546 /// 547 /// [considered by the `Subscriber`]: 548 /// super::subscriber::Subscriber::current_span current() -> Span549 pub fn current() -> Span { 550 dispatcher::get_default(|dispatch| { 551 if let Some((id, meta)) = dispatch.current_span().into_inner() { 552 let id = dispatch.clone_span(&id); 553 Self { 554 inner: Some(Inner::new(id, dispatch)), 555 meta: Some(meta), 556 } 557 } else { 558 Self::none() 559 } 560 }) 561 } 562 make_with( meta: &'static Metadata<'static>, new_span: Attributes<'_>, dispatch: &Dispatch, ) -> Span563 fn make_with( 564 meta: &'static Metadata<'static>, 565 new_span: Attributes<'_>, 566 dispatch: &Dispatch, 567 ) -> Span { 568 let attrs = &new_span; 569 let id = dispatch.new_span(attrs); 570 let inner = Some(Inner::new(id, dispatch)); 571 572 let span = Self { 573 inner, 574 meta: Some(meta), 575 }; 576 577 if_log_enabled! { *meta.level(), { 578 let target = if attrs.is_empty() { 579 LIFECYCLE_LOG_TARGET 580 } else { 581 meta.target() 582 }; 583 let values = attrs.values(); 584 span.log( 585 target, 586 level_to_log!(*meta.level()), 587 format_args!("++ {};{}", meta.name(), crate::log::LogValueSet { values, is_first: false }), 588 ); 589 }} 590 591 span 592 } 593 594 /// Enters this span, returning a guard that will exit the span when dropped. 595 /// 596 /// If this span is enabled by the current subscriber, then this function will 597 /// call [`Subscriber::enter`] with the span's [`Id`], and dropping the guard 598 /// will call [`Subscriber::exit`]. If the span is disabled, this does 599 /// nothing. 600 /// 601 /// # In Asynchronous Code 602 /// 603 /// **Warning**: in asynchronous code that uses [async/await syntax][syntax], 604 /// `Span::enter` should be used very carefully or avoided entirely. Holding 605 /// the drop guard returned by `Span::enter` across `.await` points will 606 /// result in incorrect traces. For example, 607 /// 608 /// ``` 609 /// # use tracing::info_span; 610 /// # async fn some_other_async_function() {} 611 /// async fn my_async_function() { 612 /// let span = info_span!("my_async_function"); 613 /// 614 /// // WARNING: This span will remain entered until this 615 /// // guard is dropped... 616 /// let _enter = span.enter(); 617 /// // ...but the `await` keyword may yield, causing the 618 /// // runtime to switch to another task, while remaining in 619 /// // this span! 620 /// some_other_async_function().await 621 /// 622 /// // ... 623 /// } 624 /// ``` 625 /// 626 /// The drop guard returned by `Span::enter` exits the span when it is 627 /// dropped. When an async function or async block yields at an `.await` 628 /// point, the current scope is _exited_, but values in that scope are 629 /// **not** dropped (because the async block will eventually resume 630 /// execution from that await point). This means that _another_ task will 631 /// begin executing while _remaining_ in the entered span. This results in 632 /// an incorrect trace. 633 /// 634 /// Instead of using `Span::enter` in asynchronous code, prefer the 635 /// following: 636 /// 637 /// * To enter a span for a synchronous section of code within an async 638 /// block or function, prefer [`Span::in_scope`]. Since `in_scope` takes a 639 /// synchronous closure and exits the span when the closure returns, the 640 /// span will always be exited before the next await point. For example: 641 /// ``` 642 /// # use tracing::info_span; 643 /// # async fn some_other_async_function(_: ()) {} 644 /// async fn my_async_function() { 645 /// let span = info_span!("my_async_function"); 646 /// 647 /// let some_value = span.in_scope(|| { 648 /// // run some synchronous code inside the span... 649 /// }); 650 /// 651 /// // This is okay! The span has already been exited before we reach 652 /// // the await point. 653 /// some_other_async_function(some_value).await; 654 /// 655 /// // ... 656 /// } 657 /// ``` 658 /// * For instrumenting asynchronous code, `tracing` provides the 659 /// [`Future::instrument` combinator][instrument] for 660 /// attaching a span to a future (async function or block). This will 661 /// enter the span _every_ time the future is polled, and exit it whenever 662 /// the future yields. 663 /// 664 /// `Instrument` can be used with an async block inside an async function: 665 /// ```ignore 666 /// # use tracing::info_span; 667 /// use tracing::Instrument; 668 /// 669 /// # async fn some_other_async_function() {} 670 /// async fn my_async_function() { 671 /// let span = info_span!("my_async_function"); 672 /// async move { 673 /// // This is correct! If we yield here, the span will be exited, 674 /// // and re-entered when we resume. 675 /// some_other_async_function().await; 676 /// 677 /// //more asynchronous code inside the span... 678 /// 679 /// } 680 /// // instrument the async block with the span... 681 /// .instrument(span) 682 /// // ...and await it. 683 /// .await 684 /// } 685 /// ``` 686 /// 687 /// It can also be used to instrument calls to async functions at the 688 /// callsite: 689 /// ```ignore 690 /// # use tracing::debug_span; 691 /// use tracing::Instrument; 692 /// 693 /// # async fn some_other_async_function() {} 694 /// async fn my_async_function() { 695 /// let some_value = some_other_async_function() 696 /// .instrument(debug_span!("some_other_async_function")) 697 /// .await; 698 /// 699 /// // ... 700 /// } 701 /// ``` 702 /// 703 /// * The [`#[instrument]` attribute macro][attr] can automatically generate 704 /// correct code when used on an async function: 705 /// 706 /// ```ignore 707 /// # async fn some_other_async_function() {} 708 /// #[tracing::instrument(level = "info")] 709 /// async fn my_async_function() { 710 /// 711 /// // This is correct! If we yield here, the span will be exited, 712 /// // and re-entered when we resume. 713 /// some_other_async_function().await; 714 /// 715 /// // ... 716 /// 717 /// } 718 /// ``` 719 /// 720 /// [syntax]: https://rust-lang.github.io/async-book/01_getting_started/04_async_await_primer.html 721 /// [`Span::in_scope`]: Span::in_scope() 722 /// [instrument]: crate::Instrument 723 /// [attr]: macro@crate::instrument 724 /// 725 /// # Examples 726 /// 727 /// ``` 728 /// # use tracing::{span, Level}; 729 /// let span = span!(Level::INFO, "my_span"); 730 /// let guard = span.enter(); 731 /// 732 /// // code here is within the span 733 /// 734 /// drop(guard); 735 /// 736 /// // code here is no longer within the span 737 /// 738 /// ``` 739 /// 740 /// Guards need not be explicitly dropped: 741 /// 742 /// ``` 743 /// # use tracing::trace_span; 744 /// fn my_function() -> String { 745 /// // enter a span for the duration of this function. 746 /// let span = trace_span!("my_function"); 747 /// let _enter = span.enter(); 748 /// 749 /// // anything happening in functions we call is still inside the span... 750 /// my_other_function(); 751 /// 752 /// // returning from the function drops the guard, exiting the span. 753 /// return "Hello world".to_owned(); 754 /// } 755 /// 756 /// fn my_other_function() { 757 /// // ... 758 /// } 759 /// ``` 760 /// 761 /// Sub-scopes may be created to limit the duration for which the span is 762 /// entered: 763 /// 764 /// ``` 765 /// # use tracing::{info, info_span}; 766 /// let span = info_span!("my_great_span"); 767 /// 768 /// { 769 /// let _enter = span.enter(); 770 /// 771 /// // this event occurs inside the span. 772 /// info!("i'm in the span!"); 773 /// 774 /// // exiting the scope drops the guard, exiting the span. 775 /// } 776 /// 777 /// // this event is not inside the span. 778 /// info!("i'm outside the span!") 779 /// ``` 780 /// 781 /// [`Subscriber::enter`]: super::subscriber::Subscriber::enter() 782 /// [`Subscriber::exit`]: super::subscriber::Subscriber::exit() 783 /// [`Id`]: super::Id 784 #[inline(always)] enter(&self) -> Entered<'_>785 pub fn enter(&self) -> Entered<'_> { 786 self.do_enter(); 787 Entered { span: self } 788 } 789 790 /// Enters this span, consuming it and returning a [guard][`EnteredSpan`] 791 /// that will exit the span when dropped. 792 /// 793 /// <pre class="compile_fail" style="white-space:normal;font:inherit;"> 794 /// <strong>Warning</strong>: In asynchronous code that uses async/await syntax, 795 /// <code>Span::entered</code> may produce incorrect traces if the returned drop 796 /// guard is held across an await point. See <a href="#in-asynchronous-code">the 797 /// <code>Span::enter</code> documentation</a> for details. 798 /// </pre> 799 /// 800 /// 801 /// If this span is enabled by the current subscriber, then this function will 802 /// call [`Subscriber::enter`] with the span's [`Id`], and dropping the guard 803 /// will call [`Subscriber::exit`]. If the span is disabled, this does 804 /// nothing. 805 /// 806 /// This is similar to the [`Span::enter`] method, except that it moves the 807 /// span by value into the returned guard, rather than borrowing it. 808 /// Therefore, this method can be used to create and enter a span in a 809 /// single expression, without requiring a `let`-binding. For example: 810 /// 811 /// ``` 812 /// # use tracing::info_span; 813 /// let _span = info_span!("something_interesting").entered(); 814 /// ``` 815 /// rather than: 816 /// ``` 817 /// # use tracing::info_span; 818 /// let span = info_span!("something_interesting"); 819 /// let _e = span.enter(); 820 /// ``` 821 /// 822 /// Furthermore, `entered` may be used when the span must be stored in some 823 /// other struct or be passed to a function while remaining entered. 824 /// 825 /// <pre class="ignore" style="white-space:normal;font:inherit;"> 826 /// <strong>Note</strong>: The returned <a href="../struct.EnteredSpan.html"> 827 /// <code>EnteredSpan</code></a> guard does not implement <code>Send</code>. 828 /// Dropping the guard will exit <em>this</em> span, and if the guard is sent 829 /// to another thread and dropped there, that thread may never have entered 830 /// this span. Thus, <code>EnteredSpan</code>s should not be sent between threads. 831 /// </pre> 832 /// 833 /// [syntax]: https://rust-lang.github.io/async-book/01_getting_started/04_async_await_primer.html 834 /// 835 /// # Examples 836 /// 837 /// The returned guard can be [explicitly exited][EnteredSpan::exit], 838 /// returning the un-entered span: 839 /// 840 /// ``` 841 /// # use tracing::{Level, span}; 842 /// let span = span!(Level::INFO, "doing_something").entered(); 843 /// 844 /// // code here is within the span 845 /// 846 /// // explicitly exit the span, returning it 847 /// let span = span.exit(); 848 /// 849 /// // code here is no longer within the span 850 /// 851 /// // enter the span again 852 /// let span = span.entered(); 853 /// 854 /// // now we are inside the span once again 855 /// ``` 856 /// 857 /// Guards need not be explicitly dropped: 858 /// 859 /// ``` 860 /// # use tracing::trace_span; 861 /// fn my_function() -> String { 862 /// // enter a span for the duration of this function. 863 /// let span = trace_span!("my_function").entered(); 864 /// 865 /// // anything happening in functions we call is still inside the span... 866 /// my_other_function(); 867 /// 868 /// // returning from the function drops the guard, exiting the span. 869 /// return "Hello world".to_owned(); 870 /// } 871 /// 872 /// fn my_other_function() { 873 /// // ... 874 /// } 875 /// ``` 876 /// 877 /// Since the [`EnteredSpan`] guard can dereference to the [`Span`] itself, 878 /// the span may still be accessed while entered. For example: 879 /// 880 /// ```rust 881 /// # use tracing::info_span; 882 /// use tracing::field; 883 /// 884 /// // create the span with an empty field, and enter it. 885 /// let span = info_span!("my_span", some_field = field::Empty).entered(); 886 /// 887 /// // we can still record a value for the field while the span is entered. 888 /// span.record("some_field", &"hello world!"); 889 /// ``` 890 /// 891 892 /// [`Subscriber::enter`]: super::subscriber::Subscriber::enter() 893 /// [`Subscriber::exit`]: super::subscriber::Subscriber::exit() 894 /// [`Id`]: super::Id 895 #[inline(always)] entered(self) -> EnteredSpan896 pub fn entered(self) -> EnteredSpan { 897 self.do_enter(); 898 EnteredSpan { 899 span: self, 900 _not_send: PhantomNotSend, 901 } 902 } 903 904 /// Returns this span, if it was [enabled] by the current [`Subscriber`], or 905 /// the [current span] (whose lexical distance may be further than expected), 906 /// if this span [is disabled]. 907 /// 908 /// This method can be useful when propagating spans to spawned threads or 909 /// [async tasks]. Consider the following: 910 /// 911 /// ``` 912 /// let _parent_span = tracing::info_span!("parent").entered(); 913 /// 914 /// // ... 915 /// 916 /// let child_span = tracing::debug_span!("child"); 917 /// 918 /// std::thread::spawn(move || { 919 /// let _entered = child_span.entered(); 920 /// 921 /// tracing::info!("spawned a thread!"); 922 /// 923 /// // ... 924 /// }); 925 /// ``` 926 /// 927 /// If the current [`Subscriber`] enables the [`DEBUG`] level, then both 928 /// the "parent" and "child" spans will be enabled. Thus, when the "spawaned 929 /// a thread!" event occurs, it will be inside of the "child" span. Because 930 /// "parent" is the parent of "child", the event will _also_ be inside of 931 /// "parent". 932 /// 933 /// However, if the [`Subscriber`] only enables the [`INFO`] level, the "child" 934 /// span will be disabled. When the thread is spawned, the 935 /// `child_span.entered()` call will do nothing, since "child" is not 936 /// enabled. In this case, the "spawned a thread!" event occurs outside of 937 /// *any* span, since the "child" span was responsible for propagating its 938 /// parent to the spawned thread. 939 /// 940 /// If this is not the desired behavior, `Span::or_current` can be used to 941 /// ensure that the "parent" span is propagated in both cases, either as a 942 /// parent of "child" _or_ directly. For example: 943 /// 944 /// ``` 945 /// let _parent_span = tracing::info_span!("parent").entered(); 946 /// 947 /// // ... 948 /// 949 /// // If DEBUG is enabled, then "child" will be enabled, and `or_current` 950 /// // returns "child". Otherwise, if DEBUG is not enabled, "child" will be 951 /// // disabled, and `or_current` returns "parent". 952 /// let child_span = tracing::debug_span!("child").or_current(); 953 /// 954 /// std::thread::spawn(move || { 955 /// let _entered = child_span.entered(); 956 /// 957 /// tracing::info!("spawned a thread!"); 958 /// 959 /// // ... 960 /// }); 961 /// ``` 962 /// 963 /// When spawning [asynchronous tasks][async tasks], `Span::or_current` can 964 /// be used similarly, in combination with [`instrument`]: 965 /// 966 /// ``` 967 /// use tracing::Instrument; 968 /// # // lol 969 /// # mod tokio { 970 /// # pub(super) fn spawn(_: impl std::future::Future) {} 971 /// # } 972 /// 973 /// let _parent_span = tracing::info_span!("parent").entered(); 974 /// 975 /// // ... 976 /// 977 /// let child_span = tracing::debug_span!("child"); 978 /// 979 /// tokio::spawn( 980 /// async { 981 /// tracing::info!("spawned a task!"); 982 /// 983 /// // ... 984 /// 985 /// }.instrument(child_span.or_current()) 986 /// ); 987 /// ``` 988 /// 989 /// In general, `or_current` should be preferred over nesting an 990 /// [`instrument`] call inside of an [`in_current_span`] call, as using 991 /// `or_current` will be more efficient. 992 /// 993 /// ``` 994 /// use tracing::Instrument; 995 /// # // lol 996 /// # mod tokio { 997 /// # pub(super) fn spawn(_: impl std::future::Future) {} 998 /// # } 999 /// async fn my_async_fn() { 1000 /// // ... 1001 /// } 1002 /// 1003 /// let _parent_span = tracing::info_span!("parent").entered(); 1004 /// 1005 /// // Do this: 1006 /// tokio::spawn( 1007 /// my_async_fn().instrument(tracing::debug_span!("child").or_current()) 1008 /// ); 1009 /// 1010 /// // ...rather than this: 1011 /// tokio::spawn( 1012 /// my_async_fn() 1013 /// .instrument(tracing::debug_span!("child")) 1014 /// .in_current_span() 1015 /// ); 1016 /// ``` 1017 /// 1018 /// [enabled]: crate::Subscriber::enabled 1019 /// [`Subscriber`]: crate::Subscriber 1020 /// [current span]: Span::current 1021 /// [is disabled]: Span::is_disabled 1022 /// [`INFO`]: crate::Level::INFO 1023 /// [`DEBUG`]: crate::Level::DEBUG 1024 /// [async tasks]: std::task 1025 /// [`instrument`]: crate::instrument::Instrument::instrument 1026 /// [`in_current_span`]: crate::instrument::Instrument::in_current_span or_current(self) -> Self1027 pub fn or_current(self) -> Self { 1028 if self.is_disabled() { 1029 return Self::current(); 1030 } 1031 self 1032 } 1033 1034 #[inline(always)] do_enter(&self)1035 fn do_enter(&self) { 1036 if let Some(inner) = self.inner.as_ref() { 1037 inner.subscriber.enter(&inner.id); 1038 } 1039 1040 if_log_enabled! { crate::Level::TRACE, { 1041 if let Some(_meta) = self.meta { 1042 self.log(ACTIVITY_LOG_TARGET, log::Level::Trace, format_args!("-> {};", _meta.name())); 1043 } 1044 }} 1045 } 1046 1047 // Called from [`Entered`] and [`EnteredSpan`] drops. 1048 // 1049 // Running this behaviour on drop rather than with an explicit function 1050 // call means that spans may still be exited when unwinding. 1051 #[inline(always)] do_exit(&self)1052 fn do_exit(&self) { 1053 if let Some(inner) = self.inner.as_ref() { 1054 inner.subscriber.exit(&inner.id); 1055 } 1056 1057 if_log_enabled! { crate::Level::TRACE, { 1058 if let Some(_meta) = self.meta { 1059 self.log(ACTIVITY_LOG_TARGET, log::Level::Trace, format_args!("<- {};", _meta.name())); 1060 } 1061 }} 1062 } 1063 1064 /// Executes the given function in the context of this span. 1065 /// 1066 /// If this span is enabled, then this function enters the span, invokes `f` 1067 /// and then exits the span. If the span is disabled, `f` will still be 1068 /// invoked, but in the context of the currently-executing span (if there is 1069 /// one). 1070 /// 1071 /// Returns the result of evaluating `f`. 1072 /// 1073 /// # Examples 1074 /// 1075 /// ``` 1076 /// # use tracing::{trace, span, Level}; 1077 /// let my_span = span!(Level::TRACE, "my_span"); 1078 /// 1079 /// my_span.in_scope(|| { 1080 /// // this event occurs within the span. 1081 /// trace!("i'm in the span!"); 1082 /// }); 1083 /// 1084 /// // this event occurs outside the span. 1085 /// trace!("i'm not in the span!"); 1086 /// ``` 1087 /// 1088 /// Calling a function and returning the result: 1089 /// ``` 1090 /// # use tracing::{info_span, Level}; 1091 /// fn hello_world() -> String { 1092 /// "Hello world!".to_owned() 1093 /// } 1094 /// 1095 /// let span = info_span!("hello_world"); 1096 /// // the span will be entered for the duration of the call to 1097 /// // `hello_world`. 1098 /// let a_string = span.in_scope(hello_world); 1099 /// in_scope<F: FnOnce() -> T, T>(&self, f: F) -> T1100 pub fn in_scope<F: FnOnce() -> T, T>(&self, f: F) -> T { 1101 let _enter = self.enter(); 1102 f() 1103 } 1104 1105 /// Returns a [`Field`][super::field::Field] for the field with the 1106 /// given `name`, if one exists, field<Q: ?Sized>(&self, field: &Q) -> Option<field::Field> where Q: field::AsField,1107 pub fn field<Q: ?Sized>(&self, field: &Q) -> Option<field::Field> 1108 where 1109 Q: field::AsField, 1110 { 1111 self.metadata().and_then(|meta| field.as_field(meta)) 1112 } 1113 1114 /// Returns true if this `Span` has a field for the given 1115 /// [`Field`][super::field::Field] or field name. 1116 #[inline] has_field<Q: ?Sized>(&self, field: &Q) -> bool where Q: field::AsField,1117 pub fn has_field<Q: ?Sized>(&self, field: &Q) -> bool 1118 where 1119 Q: field::AsField, 1120 { 1121 self.field(field).is_some() 1122 } 1123 1124 /// Records that the field described by `field` has the value `value`. 1125 /// 1126 /// This may be used with [`field::Empty`] to declare fields whose values 1127 /// are not known when the span is created, and record them later: 1128 /// ``` 1129 /// use tracing::{trace_span, field}; 1130 /// 1131 /// // Create a span with two fields: `greeting`, with the value "hello world", and 1132 /// // `parting`, without a value. 1133 /// let span = trace_span!("my_span", greeting = "hello world", parting = field::Empty); 1134 /// 1135 /// // ... 1136 /// 1137 /// // Now, record a value for parting as well. 1138 /// // (note that the field name is passed as a string slice) 1139 /// span.record("parting", "goodbye world!"); 1140 /// ``` 1141 /// However, it may also be used to record a _new_ value for a field whose 1142 /// value was already recorded: 1143 /// ``` 1144 /// use tracing::info_span; 1145 /// # fn do_something() -> Result<(), ()> { Err(()) } 1146 /// 1147 /// // Initially, let's assume that our attempt to do something is going okay... 1148 /// let span = info_span!("doing_something", is_okay = true); 1149 /// let _e = span.enter(); 1150 /// 1151 /// match do_something() { 1152 /// Ok(something) => { 1153 /// // ... 1154 /// } 1155 /// Err(_) => { 1156 /// // Things are no longer okay! 1157 /// span.record("is_okay", false); 1158 /// } 1159 /// } 1160 /// ``` 1161 /// 1162 /// <pre class="ignore" style="white-space:normal;font:inherit;"> 1163 /// <strong>Note</strong>: The fields associated with a span are part 1164 /// of its <a href="../struct.Metadata.html"><code>Metadata</code></a>. 1165 /// The <a href="../struct.Metadata.html"><code>Metadata</code></a> 1166 /// describing a particular span is constructed statically when the span 1167 /// is created and cannot be extended later to add new fields. Therefore, 1168 /// you cannot record a value for a field that was not specified when the 1169 /// span was created: 1170 /// </pre> 1171 /// 1172 /// ``` 1173 /// use tracing::{trace_span, field}; 1174 /// 1175 /// // Create a span with two fields: `greeting`, with the value "hello world", and 1176 /// // `parting`, without a value. 1177 /// let span = trace_span!("my_span", greeting = "hello world", parting = field::Empty); 1178 /// 1179 /// // ... 1180 /// 1181 /// // Now, you try to record a value for a new field, `new_field`, which was not 1182 /// // declared as `Empty` or populated when you created `span`. 1183 /// // You won't get any error, but the assignment will have no effect! 1184 /// span.record("new_field", "interesting_value_you_really_need"); 1185 /// 1186 /// // Instead, all fields that may be recorded after span creation should be declared up front, 1187 /// // using field::Empty when a value is not known, as we did for `parting`. 1188 /// // This `record` call will indeed replace field::Empty with "you will be remembered". 1189 /// span.record("parting", "you will be remembered"); 1190 /// ``` 1191 /// 1192 /// [`field::Empty`]: super::field::Empty 1193 /// [`Metadata`]: super::Metadata record<Q: ?Sized, V>(&self, field: &Q, value: V) -> &Self where Q: field::AsField, V: field::Value,1194 pub fn record<Q: ?Sized, V>(&self, field: &Q, value: V) -> &Self 1195 where 1196 Q: field::AsField, 1197 V: field::Value, 1198 { 1199 if let Some(meta) = self.meta { 1200 if let Some(field) = field.as_field(meta) { 1201 self.record_all( 1202 &meta 1203 .fields() 1204 .value_set(&[(&field, Some(&value as &dyn field::Value))]), 1205 ); 1206 } 1207 } 1208 1209 self 1210 } 1211 1212 /// Records all the fields in the provided `ValueSet`. record_all(&self, values: &field::ValueSet<'_>) -> &Self1213 pub fn record_all(&self, values: &field::ValueSet<'_>) -> &Self { 1214 let record = Record::new(values); 1215 if let Some(ref inner) = self.inner { 1216 inner.record(&record); 1217 } 1218 1219 if let Some(_meta) = self.meta { 1220 if_log_enabled! { *_meta.level(), { 1221 let target = if record.is_empty() { 1222 LIFECYCLE_LOG_TARGET 1223 } else { 1224 _meta.target() 1225 }; 1226 self.log( 1227 target, 1228 level_to_log!(*_meta.level()), 1229 format_args!("{};{}", _meta.name(), crate::log::LogValueSet { values, is_first: false }), 1230 ); 1231 }} 1232 } 1233 1234 self 1235 } 1236 1237 /// Returns `true` if this span was disabled by the subscriber and does not 1238 /// exist. 1239 /// 1240 /// See also [`is_none`]. 1241 /// 1242 /// [`is_none`]: Span::is_none() 1243 #[inline] is_disabled(&self) -> bool1244 pub fn is_disabled(&self) -> bool { 1245 self.inner.is_none() 1246 } 1247 1248 /// Returns `true` if this span was constructed by [`Span::none`] and is 1249 /// empty. 1250 /// 1251 /// If `is_none` returns `true` for a given span, then [`is_disabled`] will 1252 /// also return `true`. However, when a span is disabled by the subscriber 1253 /// rather than constructed by `Span::none`, this method will return 1254 /// `false`, while `is_disabled` will return `true`. 1255 /// 1256 /// [`Span::none`]: Span::none() 1257 /// [`is_disabled`]: Span::is_disabled() 1258 #[inline] is_none(&self) -> bool1259 pub fn is_none(&self) -> bool { 1260 self.is_disabled() && self.meta.is_none() 1261 } 1262 1263 /// Indicates that the span with the given ID has an indirect causal 1264 /// relationship with this span. 1265 /// 1266 /// This relationship differs somewhat from the parent-child relationship: a 1267 /// span may have any number of prior spans, rather than a single one; and 1268 /// spans are not considered to be executing _inside_ of the spans they 1269 /// follow from. This means that a span may close even if subsequent spans 1270 /// that follow from it are still open, and time spent inside of a 1271 /// subsequent span should not be included in the time its precedents were 1272 /// executing. This is used to model causal relationships such as when a 1273 /// single future spawns several related background tasks, et cetera. 1274 /// 1275 /// If this span is disabled, or the resulting follows-from relationship 1276 /// would be invalid, this function will do nothing. 1277 /// 1278 /// # Examples 1279 /// 1280 /// Setting a `follows_from` relationship with a `Span`: 1281 /// ``` 1282 /// # use tracing::{span, Id, Level, Span}; 1283 /// let span1 = span!(Level::INFO, "span_1"); 1284 /// let span2 = span!(Level::DEBUG, "span_2"); 1285 /// span2.follows_from(span1); 1286 /// ``` 1287 /// 1288 /// Setting a `follows_from` relationship with the current span: 1289 /// ``` 1290 /// # use tracing::{span, Id, Level, Span}; 1291 /// let span = span!(Level::INFO, "hello!"); 1292 /// span.follows_from(Span::current()); 1293 /// ``` 1294 /// 1295 /// Setting a `follows_from` relationship with a `Span` reference: 1296 /// ``` 1297 /// # use tracing::{span, Id, Level, Span}; 1298 /// let span = span!(Level::INFO, "hello!"); 1299 /// let curr = Span::current(); 1300 /// span.follows_from(&curr); 1301 /// ``` 1302 /// 1303 /// Setting a `follows_from` relationship with an `Id`: 1304 /// ``` 1305 /// # use tracing::{span, Id, Level, Span}; 1306 /// let span = span!(Level::INFO, "hello!"); 1307 /// let id = span.id(); 1308 /// span.follows_from(id); 1309 /// ``` follows_from(&self, from: impl Into<Option<Id>>) -> &Self1310 pub fn follows_from(&self, from: impl Into<Option<Id>>) -> &Self { 1311 if let Some(ref inner) = self.inner { 1312 if let Some(from) = from.into() { 1313 inner.follows_from(&from); 1314 } 1315 } 1316 self 1317 } 1318 1319 /// Returns this span's `Id`, if it is enabled. id(&self) -> Option<Id>1320 pub fn id(&self) -> Option<Id> { 1321 self.inner.as_ref().map(Inner::id) 1322 } 1323 1324 /// Returns this span's `Metadata`, if it is enabled. metadata(&self) -> Option<&'static Metadata<'static>>1325 pub fn metadata(&self) -> Option<&'static Metadata<'static>> { 1326 self.meta 1327 } 1328 1329 #[cfg(feature = "log")] 1330 #[inline] log(&self, target: &str, level: log::Level, message: fmt::Arguments<'_>)1331 fn log(&self, target: &str, level: log::Level, message: fmt::Arguments<'_>) { 1332 if let Some(meta) = self.meta { 1333 if level_to_log!(*meta.level()) <= log::max_level() { 1334 let logger = log::logger(); 1335 let log_meta = log::Metadata::builder().level(level).target(target).build(); 1336 if logger.enabled(&log_meta) { 1337 if let Some(ref inner) = self.inner { 1338 logger.log( 1339 &log::Record::builder() 1340 .metadata(log_meta) 1341 .module_path(meta.module_path()) 1342 .file(meta.file()) 1343 .line(meta.line()) 1344 .args(format_args!("{} span={}", message, inner.id.into_u64())) 1345 .build(), 1346 ); 1347 } else { 1348 logger.log( 1349 &log::Record::builder() 1350 .metadata(log_meta) 1351 .module_path(meta.module_path()) 1352 .file(meta.file()) 1353 .line(meta.line()) 1354 .args(message) 1355 .build(), 1356 ); 1357 } 1358 } 1359 } 1360 } 1361 } 1362 1363 /// Invokes a function with a reference to this span's ID and subscriber. 1364 /// 1365 /// if this span is enabled, the provided function is called, and the result is returned. 1366 /// If the span is disabled, the function is not called, and this method returns `None` 1367 /// instead. with_subscriber<T>(&self, f: impl FnOnce((&Id, &Dispatch)) -> T) -> Option<T>1368 pub fn with_subscriber<T>(&self, f: impl FnOnce((&Id, &Dispatch)) -> T) -> Option<T> { 1369 self.inner 1370 .as_ref() 1371 .map(|inner| f((&inner.id, &inner.subscriber))) 1372 } 1373 } 1374 1375 impl cmp::PartialEq for Span { eq(&self, other: &Self) -> bool1376 fn eq(&self, other: &Self) -> bool { 1377 match (&self.meta, &other.meta) { 1378 (Some(this), Some(that)) => { 1379 this.callsite() == that.callsite() && self.inner == other.inner 1380 } 1381 _ => false, 1382 } 1383 } 1384 } 1385 1386 impl Hash for Span { hash<H: Hasher>(&self, hasher: &mut H)1387 fn hash<H: Hasher>(&self, hasher: &mut H) { 1388 self.inner.hash(hasher); 1389 } 1390 } 1391 1392 impl fmt::Debug for Span { fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result1393 fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { 1394 let mut span = f.debug_struct("Span"); 1395 if let Some(meta) = self.meta { 1396 span.field("name", &meta.name()) 1397 .field("level", &meta.level()) 1398 .field("target", &meta.target()); 1399 1400 if let Some(ref inner) = self.inner { 1401 span.field("id", &inner.id()); 1402 } else { 1403 span.field("disabled", &true); 1404 } 1405 1406 if let Some(ref path) = meta.module_path() { 1407 span.field("module_path", &path); 1408 } 1409 1410 if let Some(ref line) = meta.line() { 1411 span.field("line", &line); 1412 } 1413 1414 if let Some(ref file) = meta.file() { 1415 span.field("file", &file); 1416 } 1417 } else { 1418 span.field("none", &true); 1419 } 1420 1421 span.finish() 1422 } 1423 } 1424 1425 impl<'a> From<&'a Span> for Option<&'a Id> { from(span: &'a Span) -> Self1426 fn from(span: &'a Span) -> Self { 1427 span.inner.as_ref().map(|inner| &inner.id) 1428 } 1429 } 1430 1431 impl<'a> From<&'a Span> for Option<Id> { from(span: &'a Span) -> Self1432 fn from(span: &'a Span) -> Self { 1433 span.inner.as_ref().map(Inner::id) 1434 } 1435 } 1436 1437 impl From<Span> for Option<Id> { from(span: Span) -> Self1438 fn from(span: Span) -> Self { 1439 span.inner.as_ref().map(Inner::id) 1440 } 1441 } 1442 1443 impl<'a> From<&'a EnteredSpan> for Option<&'a Id> { from(span: &'a EnteredSpan) -> Self1444 fn from(span: &'a EnteredSpan) -> Self { 1445 span.inner.as_ref().map(|inner| &inner.id) 1446 } 1447 } 1448 1449 impl<'a> From<&'a EnteredSpan> for Option<Id> { from(span: &'a EnteredSpan) -> Self1450 fn from(span: &'a EnteredSpan) -> Self { 1451 span.inner.as_ref().map(Inner::id) 1452 } 1453 } 1454 1455 impl Drop for Span { 1456 #[inline(always)] drop(&mut self)1457 fn drop(&mut self) { 1458 if let Some(Inner { 1459 ref id, 1460 ref subscriber, 1461 }) = self.inner 1462 { 1463 subscriber.try_close(id.clone()); 1464 } 1465 1466 if_log_enabled! { crate::Level::TRACE, { 1467 if let Some(meta) = self.meta { 1468 self.log( 1469 LIFECYCLE_LOG_TARGET, 1470 log::Level::Trace, 1471 format_args!("-- {};", meta.name()), 1472 ); 1473 } 1474 }} 1475 } 1476 } 1477 1478 // ===== impl Inner ===== 1479 1480 impl Inner { 1481 /// Indicates that the span with the given ID has an indirect causal 1482 /// relationship with this span. 1483 /// 1484 /// This relationship differs somewhat from the parent-child relationship: a 1485 /// span may have any number of prior spans, rather than a single one; and 1486 /// spans are not considered to be executing _inside_ of the spans they 1487 /// follow from. This means that a span may close even if subsequent spans 1488 /// that follow from it are still open, and time spent inside of a 1489 /// subsequent span should not be included in the time its precedents were 1490 /// executing. This is used to model causal relationships such as when a 1491 /// single future spawns several related background tasks, et cetera. 1492 /// 1493 /// If this span is disabled, this function will do nothing. Otherwise, it 1494 /// returns `Ok(())` if the other span was added as a precedent of this 1495 /// span, or an error if this was not possible. follows_from(&self, from: &Id)1496 fn follows_from(&self, from: &Id) { 1497 self.subscriber.record_follows_from(&self.id, from) 1498 } 1499 1500 /// Returns the span's ID. id(&self) -> Id1501 fn id(&self) -> Id { 1502 self.id.clone() 1503 } 1504 record(&self, values: &Record<'_>)1505 fn record(&self, values: &Record<'_>) { 1506 self.subscriber.record(&self.id, values) 1507 } 1508 new(id: Id, subscriber: &Dispatch) -> Self1509 fn new(id: Id, subscriber: &Dispatch) -> Self { 1510 Inner { 1511 id, 1512 subscriber: subscriber.clone(), 1513 } 1514 } 1515 } 1516 1517 impl cmp::PartialEq for Inner { eq(&self, other: &Self) -> bool1518 fn eq(&self, other: &Self) -> bool { 1519 self.id == other.id 1520 } 1521 } 1522 1523 impl Hash for Inner { hash<H: Hasher>(&self, state: &mut H)1524 fn hash<H: Hasher>(&self, state: &mut H) { 1525 self.id.hash(state); 1526 } 1527 } 1528 1529 impl Clone for Inner { clone(&self) -> Self1530 fn clone(&self) -> Self { 1531 Inner { 1532 id: self.subscriber.clone_span(&self.id), 1533 subscriber: self.subscriber.clone(), 1534 } 1535 } 1536 } 1537 1538 // ===== impl Entered ===== 1539 1540 impl EnteredSpan { 1541 /// Returns this span's `Id`, if it is enabled. id(&self) -> Option<Id>1542 pub fn id(&self) -> Option<Id> { 1543 self.inner.as_ref().map(Inner::id) 1544 } 1545 1546 /// Exits this span, returning the underlying [`Span`]. 1547 #[inline] exit(mut self) -> Span1548 pub fn exit(mut self) -> Span { 1549 // One does not simply move out of a struct with `Drop`. 1550 let span = mem::replace(&mut self.span, Span::none()); 1551 span.do_exit(); 1552 span 1553 } 1554 } 1555 1556 impl Deref for EnteredSpan { 1557 type Target = Span; 1558 1559 #[inline] deref(&self) -> &Span1560 fn deref(&self) -> &Span { 1561 &self.span 1562 } 1563 } 1564 1565 impl<'a> Drop for Entered<'a> { 1566 #[inline(always)] drop(&mut self)1567 fn drop(&mut self) { 1568 self.span.do_exit() 1569 } 1570 } 1571 1572 impl Drop for EnteredSpan { 1573 #[inline(always)] drop(&mut self)1574 fn drop(&mut self) { 1575 self.span.do_exit() 1576 } 1577 } 1578 1579 /// Technically, `EnteredSpan` _can_ implement both `Send` *and* 1580 /// `Sync` safely. It doesn't, because it has a `PhantomNotSend` field, 1581 /// specifically added in order to make it `!Send`. 1582 /// 1583 /// Sending an `EnteredSpan` guard between threads cannot cause memory unsafety. 1584 /// However, it *would* result in incorrect behavior, so we add a 1585 /// `PhantomNotSend` to prevent it from being sent between threads. This is 1586 /// because it must be *dropped* on the same thread that it was created; 1587 /// otherwise, the span will never be exited on the thread where it was entered, 1588 /// and it will attempt to exit the span on a thread that may never have entered 1589 /// it. However, we still want them to be `Sync` so that a struct holding an 1590 /// `Entered` guard can be `Sync`. 1591 /// 1592 /// Thus, this is totally safe. 1593 #[derive(Debug)] 1594 struct PhantomNotSend { 1595 ghost: PhantomData<*mut ()>, 1596 } 1597 1598 #[allow(non_upper_case_globals)] 1599 const PhantomNotSend: PhantomNotSend = PhantomNotSend { ghost: PhantomData }; 1600 1601 /// # Safety 1602 /// 1603 /// Trivially safe, as `PhantomNotSend` doesn't have any API. 1604 unsafe impl Sync for PhantomNotSend {} 1605 1606 #[cfg(test)] 1607 mod test { 1608 use super::*; 1609 1610 trait AssertSend: Send {} 1611 impl AssertSend for Span {} 1612 1613 trait AssertSync: Sync {} 1614 impl AssertSync for Span {} 1615 impl AssertSync for Entered<'_> {} 1616 impl AssertSync for EnteredSpan {} 1617 1618 #[test] test_record_backwards_compat()1619 fn test_record_backwards_compat() { 1620 Span::current().record("some-key", "some text"); 1621 Span::current().record("some-key", false); 1622 } 1623 } 1624