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