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`] and [`in_scope`] methods. 61 //! 62 //! The `enter` method enters a span, returning a [guard] that exits the span 63 //! when dropped 64 //! ``` 65 //! # #[macro_use] extern crate tracing; 66 //! # use tracing::Level; 67 //! let my_var: u64 = 5; 68 //! let my_span = span!(Level::TRACE, "my_span", my_var); 69 //! 70 //! // `my_span` exists but has not been entered. 71 //! 72 //! // Enter `my_span`... 73 //! let _enter = my_span.enter(); 74 //! 75 //! // Perform some work inside of the context of `my_span`... 76 //! // Dropping the `_enter` guard will exit the span. 77 //!``` 78 //! 79 //! <div class="information"> 80 //! <div class="tooltip compile_fail" style="">⚠ ️<span class="tooltiptext">Warning</span></div> 81 //! </div><div class="example-wrap" style="display:inline-block"><pre class="compile_fail" style="white-space:normal;font:inherit;"> 82 //! <strong>Warning</strong>: In asynchronous code that uses async/await syntax, 83 //! <code>Span::enter</code> may produce incorrect traces if the returned drop 84 //! guard is held across an await point. See 85 //! <a href="struct.Span.html#in-asynchronous-code">the method documentation</a> 86 //! for details. 87 //! </pre></div> 88 //! 89 //! `in_scope` takes a closure or function pointer and executes it inside the 90 //! span. 91 //! ``` 92 //! # #[macro_use] extern crate tracing; 93 //! # use tracing::Level; 94 //! let my_var: u64 = 5; 95 //! let my_span = span!(Level::TRACE, "my_span", my_var = &my_var); 96 //! 97 //! my_span.in_scope(|| { 98 //! // perform some work in the context of `my_span`... 99 //! }); 100 //! 101 //! // Perform some work outside of the context of `my_span`... 102 //! 103 //! my_span.in_scope(|| { 104 //! // Perform some more work in the context of `my_span`. 105 //! }); 106 //! ``` 107 //! 108 //! <div class="information"> 109 //! <div class="tooltip ignore" style="">ⓘ<span class="tooltiptext">Note</span></div> 110 //! </div> 111 //! <div class="example-wrap" style="display:inline-block"> 112 //! <pre class="ignore" style="white-space:normal;font:inherit;"> 113 //! <strong>Note</strong>: Since entering a span takes <code>&self</code<, and 114 //! <code>Span</code>s are <code>Clone</code>, <code>Send</code>, and 115 //! <code>Sync</code>, it is entirely valid for multiple threads to enter the 116 //! same span concurrently. 117 //! </pre></div> 118 //! 119 //! ## Span Relationships 120 //! 121 //! Spans form a tree structure — unless it is a root span, all spans have a 122 //! _parent_, and may have one or more _children_. When a new span is created, 123 //! the current span becomes the new span's parent. The total execution time of 124 //! a span consists of the time spent in that span and in the entire subtree 125 //! represented by its children. Thus, a parent span always lasts for at least 126 //! as long as the longest-executing span in its subtree. 127 //! 128 //! ``` 129 //! # #[macro_use] extern crate tracing; 130 //! # use tracing::Level; 131 //! // this span is considered the "root" of a new trace tree: 132 //! span!(Level::INFO, "root").in_scope(|| { 133 //! // since we are now inside "root", this span is considered a child 134 //! // of "root": 135 //! span!(Level::DEBUG, "outer_child").in_scope(|| { 136 //! // this span is a child of "outer_child", which is in turn a 137 //! // child of "root": 138 //! span!(Level::TRACE, "inner_child").in_scope(|| { 139 //! // and so on... 140 //! }); 141 //! }); 142 //! // another span created here would also be a child of "root". 143 //! }); 144 //!``` 145 //! 146 //! In addition, the parent of a span may be explicitly specified in 147 //! the `span!` macro. For example: 148 //! 149 //! ```rust 150 //! # #[macro_use] extern crate tracing; 151 //! # use tracing::Level; 152 //! // Create, but do not enter, a span called "foo". 153 //! let foo = span!(Level::INFO, "foo"); 154 //! 155 //! // Create and enter a span called "bar". 156 //! let bar = span!(Level::INFO, "bar"); 157 //! let _enter = bar.enter(); 158 //! 159 //! // Although we have currently entered "bar", "baz"'s parent span 160 //! // will be "foo". 161 //! let baz = span!(parent: &foo, Level::INFO, "baz"); 162 //! ``` 163 //! 164 //! A child span should typically be considered _part_ of its parent. For 165 //! example, if a subscriber is recording the length of time spent in various 166 //! spans, it should generally include the time spent in a span's children as 167 //! part of that span's duration. 168 //! 169 //! In addition to having zero or one parent, a span may also _follow from_ any 170 //! number of other spans. This indicates a causal relationship between the span 171 //! and the spans that it follows from, but a follower is *not* typically 172 //! considered part of the duration of the span it follows. Unlike the parent, a 173 //! span may record that it follows from another span after it is created, using 174 //! the [`follows_from`] method. 175 //! 176 //! As an example, consider a listener task in a server. As the listener accepts 177 //! incoming connections, it spawns new tasks that handle those connections. We 178 //! might want to have a span representing the listener, and instrument each 179 //! spawned handler task with its own span. We would want our instrumentation to 180 //! record that the handler tasks were spawned as a result of the listener task. 181 //! However, we might not consider the handler tasks to be _part_ of the time 182 //! spent in the listener task, so we would not consider those spans children of 183 //! the listener span. Instead, we would record that the handler tasks follow 184 //! from the listener, recording the causal relationship but treating the spans 185 //! as separate durations. 186 //! 187 //! ## Closing Spans 188 //! 189 //! Execution may enter and exit a span multiple times before that span is 190 //! _closed_. Consider, for example, a future which has an associated 191 //! span and enters that span every time it is polled: 192 //! ```rust 193 //! # extern crate tracing; 194 //! # extern crate futures; 195 //! # use futures::{Future, Poll, Async}; 196 //! struct MyFuture { 197 //! // data 198 //! span: tracing::Span, 199 //! } 200 //! 201 //! impl Future for MyFuture { 202 //! type Item = (); 203 //! type Error = (); 204 //! 205 //! fn poll(&mut self) -> Poll<Self::Item, Self::Error> { 206 //! let _enter = self.span.enter(); 207 //! // Do actual future work... 208 //! # Ok(Async::Ready(())) 209 //! } 210 //! } 211 //! ``` 212 //! 213 //! If this future was spawned on an executor, it might yield one or more times 214 //! before `poll` returns `Ok(Async::Ready)`. If the future were to yield, then 215 //! the executor would move on to poll the next future, which may _also_ enter 216 //! an associated span or series of spans. Therefore, it is valid for a span to 217 //! be entered repeatedly before it completes. Only the time when that span or 218 //! one of its children was the current span is considered to be time spent in 219 //! that span. A span which is not executing and has not yet been closed is said 220 //! to be _idle_. 221 //! 222 //! Because spans may be entered and exited multiple times before they close, 223 //! [`Subscriber`]s have separate trait methods which are called to notify them 224 //! of span exits and when span handles are dropped. When execution exits a 225 //! span, [`exit`] will always be called with that span's ID to notify the 226 //! subscriber that the span has been exited. When span handles are dropped, the 227 //! [`drop_span`] method is called with that span's ID. The subscriber may use 228 //! this to determine whether or not the span will be entered again. 229 //! 230 //! If there is only a single handle with the capacity to exit a span, dropping 231 //! that handle "closes" the span, since the capacity to enter it no longer 232 //! exists. For example: 233 //! ``` 234 //! # #[macro_use] extern crate tracing; 235 //! # use tracing::Level; 236 //! { 237 //! span!(Level::TRACE, "my_span").in_scope(|| { 238 //! // perform some work in the context of `my_span`... 239 //! }); // --> Subscriber::exit(my_span) 240 //! 241 //! // The handle to `my_span` only lives inside of this block; when it is 242 //! // dropped, the subscriber will be informed via `drop_span`. 243 //! 244 //! } // --> Subscriber::drop_span(my_span) 245 //! ``` 246 //! 247 //! However, if multiple handles exist, the span can still be re-entered even if 248 //! one or more is dropped. For determining when _all_ handles to a span have 249 //! been dropped, `Subscriber`s have a [`clone_span`] method, which is called 250 //! every time a span handle is cloned. Combined with `drop_span`, this may be 251 //! used to track the number of handles to a given span — if `drop_span` has 252 //! been called one more time than the number of calls to `clone_span` for a 253 //! given ID, then no more handles to the span with that ID exist. The 254 //! subscriber may then treat it as closed. 255 //! 256 //! # When to use spans 257 //! 258 //! As a rule of thumb, spans should be used to represent discrete units of work 259 //! (e.g., a given request's lifetime in a server) or periods of time spent in a 260 //! given context (e.g., time spent interacting with an instance of an external 261 //! system, such as a database). 262 //! 263 //! Which scopes in a program correspond to new spans depend somewhat on user 264 //! intent. For example, consider the case of a loop in a program. Should we 265 //! construct one span and perform the entire loop inside of that span, like: 266 //! 267 //! ```rust 268 //! # #[macro_use] extern crate tracing; 269 //! # use tracing::Level; 270 //! # let n = 1; 271 //! let span = span!(Level::TRACE, "my_loop"); 272 //! let _enter = span.enter(); 273 //! for i in 0..n { 274 //! # let _ = i; 275 //! // ... 276 //! } 277 //! ``` 278 //! Or, should we create a new span for each iteration of the loop, as in: 279 //! ```rust 280 //! # #[macro_use] extern crate tracing; 281 //! # use tracing::Level; 282 //! # let n = 1u64; 283 //! for i in 0..n { 284 //! let span = span!(Level::TRACE, "my_loop", iteration = i); 285 //! let _enter = span.enter(); 286 //! // ... 287 //! } 288 //! ``` 289 //! 290 //! Depending on the circumstances, we might want to do either, or both. For 291 //! example, if we want to know how long was spent in the loop overall, we would 292 //! create a single span around the entire loop; whereas if we wanted to know how 293 //! much time was spent in each individual iteration, we would enter a new span 294 //! on every iteration. 295 //! 296 //! [fields]: ../field/index.html 297 //! [Metadata]: ../struct.Metadata.html 298 //! [`Id`]: struct.Id.html 299 //! [verbosity level]: ../struct.Level.html 300 //! [`span!`]: ../macro.span.html 301 //! [`trace_span!`]: ../macro.trace_span.html 302 //! [`debug_span!`]: ../macro.debug_span.html 303 //! [`info_span!`]: ../macro.info_span.html 304 //! [`warn_span!`]: ../macro.warn_span.html 305 //! [`error_span!`]: ../macro.error_span.html 306 //! [`clone_span`]: ../subscriber/trait.Subscriber.html#method.clone_span 307 //! [`drop_span`]: ../subscriber/trait.Subscriber.html#method.drop_span 308 //! [`exit`]: ../subscriber/trait.Subscriber.html#tymethod.exit 309 //! [`Subscriber`]: ../subscriber/trait.Subscriber.html 310 //! [`Attributes`]: struct.Attributes.html 311 //! [`enter`]: struct.Span.html#method.enter 312 //! [`in_scope`]: struct.Span.html#method.in_scope 313 //! [`follows_from`]: struct.Span.html#method.follows_from 314 //! [guard]: struct.Entered.html 315 //! [parent]: #span-relationships 316 pub use tracing_core::span::{Attributes, Id, Record}; 317 318 use crate::stdlib::{ 319 cmp, fmt, 320 hash::{Hash, Hasher}, 321 }; 322 use crate::{ 323 dispatcher::{self, Dispatch}, 324 field, Metadata, 325 }; 326 327 /// Trait implemented by types which have a span `Id`. 328 pub trait AsId: crate::sealed::Sealed { 329 /// Returns the `Id` of the span that `self` corresponds to, or `None` if 330 /// this corresponds to a disabled span. as_id(&self) -> Option<&Id>331 fn as_id(&self) -> Option<&Id>; 332 } 333 334 /// A handle representing a span, with the capability to enter the span if it 335 /// exists. 336 /// 337 /// If the span was rejected by the current `Subscriber`'s filter, entering the 338 /// span will silently do nothing. Thus, the handle can be used in the same 339 /// manner regardless of whether or not the trace is currently being collected. 340 #[derive(Clone)] 341 pub struct Span { 342 /// A handle used to enter the span when it is not executing. 343 /// 344 /// If this is `None`, then the span has either closed or was never enabled. 345 inner: Option<Inner>, 346 /// Metadata describing the span. 347 /// 348 /// This might be `Some` even if `inner` is `None`, in the case that the 349 /// span is disabled but the metadata is needed for `log` support. 350 meta: Option<&'static Metadata<'static>>, 351 } 352 353 /// A handle representing the capacity to enter a span which is known to exist. 354 /// 355 /// Unlike `Span`, this type is only constructed for spans which _have_ been 356 /// enabled by the current filter. This type is primarily used for implementing 357 /// span handles; users should typically not need to interact with it directly. 358 #[derive(Debug)] 359 pub(crate) struct Inner { 360 /// The span's ID, as provided by `subscriber`. 361 id: Id, 362 363 /// The subscriber that will receive events relating to this span. 364 /// 365 /// This should be the same subscriber that provided this span with its 366 /// `id`. 367 subscriber: Dispatch, 368 } 369 370 /// A guard representing a span which has been entered and is currently 371 /// executing. 372 /// 373 /// When the guard is dropped, the span will be exited. 374 /// 375 /// This is returned by the [`Span::enter`] function. 376 /// 377 /// [`Span::enter`]: ../struct.Span.html#method.enter 378 #[derive(Debug)] 379 #[must_use = "once a span has been entered, it should be exited"] 380 pub struct Entered<'a> { 381 span: &'a Span, 382 } 383 384 /// `log` target for all span lifecycle (creation/enter/exit/close) records. 385 #[cfg(feature = "log")] 386 const LIFECYCLE_LOG_TARGET: &str = "tracing::span"; 387 /// `log` target for span activity (enter/exit) records. 388 #[cfg(feature = "log")] 389 const ACTIVITY_LOG_TARGET: &str = "tracing::span::active"; 390 391 // ===== impl Span ===== 392 393 impl Span { 394 /// Constructs a new `Span` with the given [metadata] and set of 395 /// [field values]. 396 /// 397 /// The new span will be constructed by the currently-active [`Subscriber`], 398 /// with the current span as its parent (if one exists). 399 /// 400 /// After the span is constructed, [field values] and/or [`follows_from`] 401 /// annotations may be added to it. 402 /// 403 /// [metadata]: ../metadata 404 /// [`Subscriber`]: ../subscriber/trait.Subscriber.html 405 /// [field values]: ../field/struct.ValueSet.html 406 /// [`follows_from`]: ../struct.Span.html#method.follows_from 407 #[inline] new(meta: &'static Metadata<'static>, values: &field::ValueSet<'_>) -> Span408 pub fn new(meta: &'static Metadata<'static>, values: &field::ValueSet<'_>) -> Span { 409 let new_span = Attributes::new(meta, values); 410 Self::make(meta, new_span) 411 } 412 413 /// Constructs a new `Span` as the root of its own trace tree, with the 414 /// given [metadata] and set of [field values]. 415 /// 416 /// After the span is constructed, [field values] and/or [`follows_from`] 417 /// annotations may be added to it. 418 /// 419 /// [metadata]: ../metadata 420 /// [field values]: ../field/struct.ValueSet.html 421 /// [`follows_from`]: ../struct.Span.html#method.follows_from 422 #[inline] new_root(meta: &'static Metadata<'static>, values: &field::ValueSet<'_>) -> Span423 pub fn new_root(meta: &'static Metadata<'static>, values: &field::ValueSet<'_>) -> Span { 424 Self::make(meta, Attributes::new_root(meta, values)) 425 } 426 427 /// Constructs a new `Span` as child of the given parent span, with the 428 /// given [metadata] and set of [field values]. 429 /// 430 /// After the span is constructed, [field values] and/or [`follows_from`] 431 /// annotations may be added to it. 432 /// 433 /// [metadata]: ../metadata 434 /// [field values]: ../field/struct.ValueSet.html 435 /// [`follows_from`]: ../struct.Span.html#method.follows_from child_of( parent: impl Into<Option<Id>>, meta: &'static Metadata<'static>, values: &field::ValueSet<'_>, ) -> Span436 pub fn child_of( 437 parent: impl Into<Option<Id>>, 438 meta: &'static Metadata<'static>, 439 values: &field::ValueSet<'_>, 440 ) -> Span { 441 let new_span = match parent.into() { 442 Some(parent) => Attributes::child_of(parent, meta, values), 443 None => Attributes::new_root(meta, values), 444 }; 445 Self::make(meta, new_span) 446 } 447 448 /// Constructs a new disabled span with the given `Metadata`. 449 /// 450 /// This should be used when a span is constructed from a known callsite, 451 /// but the subscriber indicates that it is disabled. 452 /// 453 /// Entering, exiting, and recording values on this span will not notify the 454 /// `Subscriber` but _may_ record log messages if the `log` feature flag is 455 /// enabled. 456 #[inline(always)] new_disabled(meta: &'static Metadata<'static>) -> Span457 pub fn new_disabled(meta: &'static Metadata<'static>) -> Span { 458 Self { 459 inner: None, 460 meta: Some(meta), 461 } 462 } 463 464 /// Constructs a new span that is *completely disabled*. 465 /// 466 /// This can be used rather than `Option<Span>` to represent cases where a 467 /// span is not present. 468 /// 469 /// Entering, exiting, and recording values on this span will do nothing. 470 #[inline(always)] none() -> Span471 pub const fn none() -> Span { 472 Self { 473 inner: None, 474 meta: None, 475 } 476 } 477 478 /// Returns a handle to the span [considered by the `Subscriber`] to be the 479 /// current span. 480 /// 481 /// If the subscriber indicates that it does not track the current span, or 482 /// that the thread from which this function is called is not currently 483 /// inside a span, the returned span will be disabled. 484 /// 485 /// [considered by the `Subscriber`]: ../subscriber/trait.Subscriber.html#method.current current() -> Span486 pub fn current() -> Span { 487 dispatcher::get_default(|dispatch| { 488 if let Some((id, meta)) = dispatch.current_span().into_inner() { 489 let id = dispatch.clone_span(&id); 490 Self { 491 inner: Some(Inner::new(id, dispatch)), 492 meta: Some(meta), 493 } 494 } else { 495 Self::none() 496 } 497 }) 498 } 499 make(meta: &'static Metadata<'static>, new_span: Attributes<'_>) -> Span500 fn make(meta: &'static Metadata<'static>, new_span: Attributes<'_>) -> Span { 501 let attrs = &new_span; 502 let inner = dispatcher::get_default(move |dispatch| { 503 let id = dispatch.new_span(attrs); 504 Some(Inner::new(id, dispatch)) 505 }); 506 507 let span = Self { 508 inner, 509 meta: Some(meta), 510 }; 511 512 if_log_enabled! {{ 513 let target = if attrs.is_empty() { 514 LIFECYCLE_LOG_TARGET 515 } else { 516 meta.target() 517 }; 518 span.log(target, level_to_log!(meta.level()), format_args!("++ {}{}", meta.name(), FmtAttrs(attrs))); 519 }} 520 521 span 522 } 523 524 /// Enters this span, returning a guard that will exit the span when dropped. 525 /// 526 /// If this span is enabled by the current subscriber, then this function will 527 /// call [`Subscriber::enter`] with the span's [`Id`], and dropping the guard 528 /// will call [`Subscriber::exit`]. If the span is disabled, this does 529 /// nothing. 530 /// 531 /// # In Asynchronous Code 532 /// 533 /// **Warning**: in asynchronous code that uses [async/await syntax][syntax], 534 /// `Span::enter` should be used very carefully or avoided entirely. Holding 535 /// the drop guard returned by `Span::enter` across `.await` points will 536 /// result in incorrect traces. 537 /// 538 /// For example, 539 /// 540 /// ``` 541 /// # use tracing::info_span; 542 /// # async fn some_other_async_function() {} 543 /// async fn my_async_function() { 544 /// let span = info_span!("my_async_function"); 545 /// 546 /// // THIS WILL RESULT IN INCORRECT TRACES 547 /// let _enter = span.enter(); 548 /// some_other_async_function().await; 549 /// 550 /// // ... 551 /// } 552 /// ``` 553 /// 554 /// The drop guard returned by `Span::enter` exits the span when it is 555 /// dropped. When an async function or async block yields at an `.await` 556 /// point, the current scope is _exited_, but values in that scope are 557 /// **not** dropped (because the async block will eventually resume 558 /// execution from that await point). This means that _another_ task will 559 /// begin executing while _remaining_ in the entered span. This results in 560 /// an incorrect trace. 561 /// 562 /// Instead of using `Span::enter` in asynchronous code, prefer the 563 /// following: 564 /// 565 /// * To enter a span for a synchronous section of code within an async 566 /// block or function, prefer [`Span::in_scope`]. Since `in_scope` takes a 567 /// synchronous closure and exits the span when the closure returns, the 568 /// span will always be exited before the next await point. For example: 569 /// ``` 570 /// # use tracing::info_span; 571 /// # async fn some_other_async_function(_: ()) {} 572 /// async fn my_async_function() { 573 /// let span = info_span!("my_async_function"); 574 /// 575 /// let some_value = span.in_scope(|| { 576 /// // run some synchronous code inside the span... 577 /// }); 578 /// 579 /// // This is okay! The span has already been exited before we reach 580 /// // the await point. 581 /// some_other_async_function(some_value).await; 582 /// 583 /// // ... 584 /// } 585 /// ``` 586 /// * For instrumenting asynchronous code, the [`tracing-futures` crate] 587 /// provides the [`Future::instrument` combinator][instrument] for 588 /// attaching a span to a future (async function or block). This will 589 /// enter the span _every_ time the future is polled, and exit it whenever 590 /// the future yields. 591 /// 592 /// `Instrument` can be used with an async block inside an async function: 593 /// ```ignore 594 /// # use tracing::info_span; 595 /// use tracing_futures::Instrument; 596 /// 597 /// # async fn some_other_async_function() {} 598 /// async fn my_async_function() { 599 /// let span = info_span!("my_async_function"); 600 /// async move { 601 /// // This is correct! If we yield here, the span will be exited, 602 /// // and re-entered when we resume. 603 /// some_other_async_function().await; 604 /// 605 /// //more asynchronous code inside the span... 606 /// 607 /// } 608 /// // instrument the async block with the span... 609 /// .instrument(span) 610 /// // ...and await it. 611 /// .await 612 /// } 613 /// ``` 614 /// 615 /// It can also be used to instrument calls to async functions at the 616 /// callsite: 617 /// ```ignore 618 /// # use tracing::debug_span; 619 /// use tracing_futures::Instrument; 620 /// 621 /// # async fn some_other_async_function() {} 622 /// async fn my_async_function() { 623 /// let some_value = some_other_async_function() 624 /// .instrument(debug_span!("some_other_async_function")) 625 /// .await; 626 /// 627 /// // ... 628 /// } 629 /// ``` 630 /// 631 /// * Finally, if your crate depends on the `tracing-futures` crate, the 632 /// [`#[instrument]` attribute macro][attr] will automatically generate 633 /// correct code when used on an async function: 634 /// 635 /// ```ignore 636 /// # async fn some_other_async_function() {} 637 /// #[tracing::instrument(level = "info")] 638 /// async fn my_async_function() { 639 /// 640 /// // This is correct! If we yield here, the span will be exited, 641 /// // and re-entered when we resume. 642 /// some_other_async_function().await; 643 /// 644 /// // ... 645 /// 646 /// } 647 /// ``` 648 /// 649 /// [syntax]: https://rust-lang.github.io/async-book/01_getting_started/04_async_await_primer.html 650 /// [`Span::in_scope`]: #method.in_scope 651 /// [`tracing-futures` crate]: https://docs.rs/tracing-futures/ 652 /// [instrument]: https://docs.rs/tracing-futures/latest/tracing_futures/trait.Instrument.html 653 /// [attr]: ../../attr.instrument.html 654 /// 655 /// # Examples 656 /// 657 /// ``` 658 /// #[macro_use] extern crate tracing; 659 /// # use tracing::Level; 660 /// let span = span!(Level::INFO, "my_span"); 661 /// let guard = span.enter(); 662 /// 663 /// // code here is within the span 664 /// 665 /// drop(guard); 666 /// 667 /// // code here is no longer within the span 668 /// 669 /// ``` 670 /// 671 /// Guards need not be explicitly dropped: 672 /// 673 /// ``` 674 /// #[macro_use] extern crate tracing; 675 /// fn my_function() -> String { 676 /// // enter a span for the duration of this function. 677 /// let span = trace_span!("my_function"); 678 /// let _enter = span.enter(); 679 /// 680 /// // anything happening in functions we call is still inside the span... 681 /// my_other_function(); 682 /// 683 /// // returning from the function drops the guard, exiting the span. 684 /// return "Hello world".to_owned(); 685 /// } 686 /// 687 /// fn my_other_function() { 688 /// // ... 689 /// } 690 /// ``` 691 /// 692 /// Sub-scopes may be created to limit the duration for which the span is 693 /// entered: 694 /// 695 /// ``` 696 /// #[macro_use] extern crate tracing; 697 /// let span = info_span!("my_great_span"); 698 /// 699 /// { 700 /// let _enter = span.enter(); 701 /// 702 /// // this event occurs inside the span. 703 /// info!("i'm in the span!"); 704 /// 705 /// // exiting the scope drops the guard, exiting the span. 706 /// } 707 /// 708 /// // this event is not inside the span. 709 /// info!("i'm outside the span!") 710 /// ``` 711 /// 712 /// [`Subscriber::enter`]: ../subscriber/trait.Subscriber.html#method.enter 713 /// [`Subscriber::exit`]: ../subscriber/trait.Subscriber.html#method.exit 714 /// [`Id`]: ../struct.Id.html enter(&self) -> Entered<'_>715 pub fn enter(&self) -> Entered<'_> { 716 if let Some(ref inner) = self.inner.as_ref() { 717 inner.subscriber.enter(&inner.id); 718 } 719 720 if_log_enabled! {{ 721 if let Some(ref meta) = self.meta { 722 self.log(ACTIVITY_LOG_TARGET, log::Level::Trace, format_args!("-> {}", meta.name())); 723 } 724 }} 725 726 Entered { span: self } 727 } 728 729 /// Executes the given function in the context of this span. 730 /// 731 /// If this span is enabled, then this function enters the span, invokes `f` 732 /// and then exits the span. If the span is disabled, `f` will still be 733 /// invoked, but in the context of the currently-executing span (if there is 734 /// one). 735 /// 736 /// Returns the result of evaluating `f`. 737 /// 738 /// # Examples 739 /// 740 /// ``` 741 /// # #[macro_use] extern crate tracing; 742 /// # use tracing::Level; 743 /// let my_span = span!(Level::TRACE, "my_span"); 744 /// 745 /// my_span.in_scope(|| { 746 /// // this event occurs within the span. 747 /// trace!("i'm in the span!"); 748 /// }); 749 /// 750 /// // this event occurs outside the span. 751 /// trace!("i'm not in the span!"); 752 /// ``` 753 /// 754 /// Calling a function and returning the result: 755 /// ``` 756 /// # use tracing::{info_span, Level}; 757 /// fn hello_world() -> String { 758 /// "Hello world!".to_owned() 759 /// } 760 /// 761 /// let span = info_span!("hello_world"); 762 /// // the span will be entered for the duration of the call to 763 /// // `hello_world`. 764 /// let a_string = span.in_scope(hello_world); 765 /// in_scope<F: FnOnce() -> T, T>(&self, f: F) -> T766 pub fn in_scope<F: FnOnce() -> T, T>(&self, f: F) -> T { 767 let _enter = self.enter(); 768 f() 769 } 770 771 /// Returns a [`Field`](../field/struct.Field.html) for the field with the 772 /// given `name`, if one exists, field<Q: ?Sized>(&self, field: &Q) -> Option<field::Field> where Q: field::AsField,773 pub fn field<Q: ?Sized>(&self, field: &Q) -> Option<field::Field> 774 where 775 Q: field::AsField, 776 { 777 self.metadata().and_then(|meta| field.as_field(meta)) 778 } 779 780 /// Returns true if this `Span` has a field for the given 781 /// [`Field`](../field/struct.Field.html) or field name. 782 #[inline] has_field<Q: ?Sized>(&self, field: &Q) -> bool where Q: field::AsField,783 pub fn has_field<Q: ?Sized>(&self, field: &Q) -> bool 784 where 785 Q: field::AsField, 786 { 787 self.field(field).is_some() 788 } 789 790 /// Records that the field described by `field` has the value `value`. 791 /// 792 /// This may be used with [`field::Empty`] to declare fields whose values 793 /// are not known when the span is created, and record them later: 794 /// ``` 795 /// use tracing::{trace_span, field}; 796 /// 797 /// // Create a span with two fields: `greeting`, with the value "hello world", and 798 /// // `parting`, without a value. 799 /// let span = trace_span!("my_span", greeting = "hello world", parting = field::Empty); 800 /// 801 /// // ... 802 /// 803 /// // Now, record a value for parting as well. 804 /// // (note that the field name is passed as a string slice) 805 /// span.record("parting", &"goodbye world!"); 806 /// ``` 807 /// However, it may also be used to record a _new_ value for a field whose 808 /// value was already recorded: 809 /// ``` 810 /// use tracing::info_span; 811 /// # fn do_something() -> Result<(), ()> { Err(()) } 812 /// 813 /// // Initially, let's assume that our attempt to do something is going okay... 814 /// let span = info_span!("doing_something", is_okay = true); 815 /// let _e = span.enter(); 816 /// 817 /// match do_something() { 818 /// Ok(something) => { 819 /// // ... 820 /// } 821 /// Err(_) => { 822 /// // Things are no longer okay! 823 /// span.record("is_okay", &false); 824 /// } 825 /// } 826 /// ``` 827 /// 828 /// <div class="information"> 829 /// <div class="tooltip ignore" style="">ⓘ<span class="tooltiptext">Note</span></div> 830 /// </div> 831 /// <div class="example-wrap" style="display:inline-block"> 832 /// <pre class="ignore" style="white-space:normal;font:inherit;"> 833 /// <strong>Note</strong>: The fields associated with a span are part of its 834 /// <a href="../struct.Metadata.html"><code>Metadata</code></a>. 835 /// The <a href="../struct.Metadata.html"><code>Metadata</code></a>. describing a particular 836 /// span is constructed statically when the span is created and cannot be extended later to 837 /// add new fields. Therefore, you cannot record a value for a field that was not specified 838 /// when the span was created:</pre></div> 839 /// 840 /// ``` 841 /// use tracing::{trace_span, field}; 842 /// 843 /// // Create a span with two fields: `greeting`, with the value "hello world", and 844 /// // `parting`, without a value. 845 /// let span = trace_span!("my_span", greeting = "hello world", parting = field::Empty); 846 /// 847 /// // ... 848 /// 849 /// // Now, you try to record a value for a new field, `new_field`, which was not 850 /// // declared as `Empty` or populated when you created `span`. 851 /// // You won't get any error, but the assignment will have no effect! 852 /// span.record("new_field", &"interesting_value_you_really_need"); 853 /// 854 /// // Instead, all fields that may be recorded after span creation should be declared up front, 855 /// // using field::Empty when a value is not known, as we did for `parting`. 856 /// // This `record` call will indeed replace field::Empty with "you will be remembered". 857 /// span.record("parting", &"you will be remembered"); 858 /// ``` 859 /// 860 /// [`field::Empty`]: ../field/struct.Empty.html 861 /// [`Metadata`]: ../struct.Metadata.html record<Q: ?Sized, V>(&self, field: &Q, value: &V) -> &Self where Q: field::AsField, V: field::Value,862 pub fn record<Q: ?Sized, V>(&self, field: &Q, value: &V) -> &Self 863 where 864 Q: field::AsField, 865 V: field::Value, 866 { 867 if let Some(ref meta) = self.meta { 868 if let Some(field) = field.as_field(meta) { 869 self.record_all( 870 &meta 871 .fields() 872 .value_set(&[(&field, Some(value as &dyn field::Value))]), 873 ); 874 } 875 } 876 877 self 878 } 879 880 /// Records all the fields in the provided `ValueSet`. record_all(&self, values: &field::ValueSet<'_>) -> &Self881 pub fn record_all(&self, values: &field::ValueSet<'_>) -> &Self { 882 let record = Record::new(values); 883 if let Some(ref inner) = self.inner { 884 inner.record(&record); 885 } 886 887 if_log_enabled! {{ 888 if let Some(ref meta) = self.meta { 889 let target = if record.is_empty() { 890 LIFECYCLE_LOG_TARGET 891 } else { 892 meta.target() 893 }; 894 self.log(target, level_to_log!(meta.level()), format_args!("{}{}", meta.name(), FmtValues(&record))); 895 } 896 }} 897 898 self 899 } 900 901 /// Returns `true` if this span was disabled by the subscriber and does not 902 /// exist. 903 /// 904 /// See also [`is_none`]. 905 /// 906 /// [`is_none`]: #method.is_none 907 #[inline] is_disabled(&self) -> bool908 pub fn is_disabled(&self) -> bool { 909 self.inner.is_none() 910 } 911 912 /// Returns `true` if this span was constructed by [`Span::none`] and is 913 /// empty. 914 /// 915 /// If `is_none` returns `true` for a given span, then [`is_disabled`] will 916 /// also return `true`. However, when a span is disabled by the subscriber 917 /// rather than constructed by `Span::none`, this method will return 918 /// `false`, while `is_disabled` will return `true`. 919 /// 920 /// [`Span::none`]: #method.none 921 /// [`is_disabled`]: #method.is_disabled 922 #[inline] is_none(&self) -> bool923 pub fn is_none(&self) -> bool { 924 self.is_disabled() && self.meta.is_none() 925 } 926 927 /// Indicates that the span with the given ID has an indirect causal 928 /// relationship with this span. 929 /// 930 /// This relationship differs somewhat from the parent-child relationship: a 931 /// span may have any number of prior spans, rather than a single one; and 932 /// spans are not considered to be executing _inside_ of the spans they 933 /// follow from. This means that a span may close even if subsequent spans 934 /// that follow from it are still open, and time spent inside of a 935 /// subsequent span should not be included in the time its precedents were 936 /// executing. This is used to model causal relationships such as when a 937 /// single future spawns several related background tasks, et cetera. 938 /// 939 /// If this span is disabled, or the resulting follows-from relationship 940 /// would be invalid, this function will do nothing. 941 /// 942 /// # Examples 943 /// 944 /// Setting a `follows_from` relationship with a `Span`: 945 /// ``` 946 /// # use tracing::{span, Id, Level, Span}; 947 /// let span1 = span!(Level::INFO, "span_1"); 948 /// let span2 = span!(Level::DEBUG, "span_2"); 949 /// span2.follows_from(span1); 950 /// ``` 951 /// 952 /// Setting a `follows_from` relationship with the current span: 953 /// ``` 954 /// # use tracing::{span, Id, Level, Span}; 955 /// let span = span!(Level::INFO, "hello!"); 956 /// span.follows_from(Span::current()); 957 /// ``` 958 /// 959 /// Setting a `follows_from` relationship with a `Span` reference: 960 /// ``` 961 /// # use tracing::{span, Id, Level, Span}; 962 /// let span = span!(Level::INFO, "hello!"); 963 /// let curr = Span::current(); 964 /// span.follows_from(&curr); 965 /// ``` 966 /// 967 /// Setting a `follows_from` relationship with an `Id`: 968 /// ``` 969 /// # use tracing::{span, Id, Level, Span}; 970 /// let span = span!(Level::INFO, "hello!"); 971 /// let id = span.id(); 972 /// span.follows_from(id); 973 /// ``` follows_from(&self, from: impl Into<Option<Id>>) -> &Self974 pub fn follows_from(&self, from: impl Into<Option<Id>>) -> &Self { 975 if let Some(ref inner) = self.inner { 976 if let Some(from) = from.into() { 977 inner.follows_from(&from); 978 } 979 } 980 self 981 } 982 983 /// Returns this span's `Id`, if it is enabled. id(&self) -> Option<Id>984 pub fn id(&self) -> Option<Id> { 985 self.inner.as_ref().map(Inner::id) 986 } 987 988 /// Returns this span's `Metadata`, if it is enabled. metadata(&self) -> Option<&'static Metadata<'static>>989 pub fn metadata(&self) -> Option<&'static Metadata<'static>> { 990 self.meta 991 } 992 993 #[cfg(feature = "log")] 994 #[inline] log(&self, target: &str, level: log::Level, message: fmt::Arguments<'_>)995 fn log(&self, target: &str, level: log::Level, message: fmt::Arguments<'_>) { 996 if let Some(ref meta) = self.meta { 997 let logger = log::logger(); 998 let log_meta = log::Metadata::builder().level(level).target(target).build(); 999 if logger.enabled(&log_meta) { 1000 if let Some(ref inner) = self.inner { 1001 logger.log( 1002 &log::Record::builder() 1003 .metadata(log_meta) 1004 .module_path(meta.module_path()) 1005 .file(meta.file()) 1006 .line(meta.line()) 1007 .args(format_args!("{}; span={}", message, inner.id.into_u64())) 1008 .build(), 1009 ); 1010 } else { 1011 logger.log( 1012 &log::Record::builder() 1013 .metadata(log_meta) 1014 .module_path(meta.module_path()) 1015 .file(meta.file()) 1016 .line(meta.line()) 1017 .args(message) 1018 .build(), 1019 ); 1020 } 1021 } 1022 } 1023 } 1024 1025 /// Invokes a function with a reference to this span's ID and subscriber. 1026 /// 1027 /// if this span is enabled, the provided function is called, and the result is returned. 1028 /// If the span is disabled, the function is not called, and this method returns `None` 1029 /// instead. with_subscriber<T>(&self, f: impl FnOnce((&Id, &Dispatch)) -> T) -> Option<T>1030 pub fn with_subscriber<T>(&self, f: impl FnOnce((&Id, &Dispatch)) -> T) -> Option<T> { 1031 self.inner 1032 .as_ref() 1033 .map(|inner| f((&inner.id, &inner.subscriber))) 1034 } 1035 } 1036 1037 impl cmp::PartialEq for Span { eq(&self, other: &Self) -> bool1038 fn eq(&self, other: &Self) -> bool { 1039 match (&self.meta, &other.meta) { 1040 (Some(this), Some(that)) => { 1041 this.callsite() == that.callsite() && self.inner == other.inner 1042 } 1043 _ => false, 1044 } 1045 } 1046 } 1047 1048 impl Hash for Span { hash<H: Hasher>(&self, hasher: &mut H)1049 fn hash<H: Hasher>(&self, hasher: &mut H) { 1050 self.inner.hash(hasher); 1051 } 1052 } 1053 1054 impl fmt::Debug for Span { fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result1055 fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { 1056 let mut span = f.debug_struct("Span"); 1057 if let Some(ref meta) = self.meta { 1058 span.field("name", &meta.name()) 1059 .field("level", &meta.level()) 1060 .field("target", &meta.target()); 1061 1062 if let Some(ref inner) = self.inner { 1063 span.field("id", &inner.id()); 1064 } else { 1065 span.field("disabled", &true); 1066 } 1067 1068 if let Some(ref path) = meta.module_path() { 1069 span.field("module_path", &path); 1070 } 1071 1072 if let Some(ref line) = meta.line() { 1073 span.field("line", &line); 1074 } 1075 1076 if let Some(ref file) = meta.file() { 1077 span.field("file", &file); 1078 } 1079 } else { 1080 span.field("none", &true); 1081 } 1082 1083 span.finish() 1084 } 1085 } 1086 1087 impl<'a> Into<Option<&'a Id>> for &'a Span { into(self) -> Option<&'a Id>1088 fn into(self) -> Option<&'a Id> { 1089 self.inner.as_ref().map(|inner| &inner.id) 1090 } 1091 } 1092 1093 impl<'a> Into<Option<Id>> for &'a Span { into(self) -> Option<Id>1094 fn into(self) -> Option<Id> { 1095 self.inner.as_ref().map(Inner::id) 1096 } 1097 } 1098 1099 impl Into<Option<Id>> for Span { into(self) -> Option<Id>1100 fn into(self) -> Option<Id> { 1101 self.inner.as_ref().map(Inner::id) 1102 } 1103 } 1104 1105 impl Drop for Span { drop(&mut self)1106 fn drop(&mut self) { 1107 if let Some(Inner { 1108 ref id, 1109 ref subscriber, 1110 }) = self.inner 1111 { 1112 subscriber.try_close(id.clone()); 1113 } 1114 1115 if_log_enabled!({ 1116 if let Some(ref meta) = self.meta { 1117 self.log( 1118 LIFECYCLE_LOG_TARGET, 1119 log::Level::Trace, 1120 format_args!("-- {}", meta.name()), 1121 ); 1122 } 1123 }) 1124 } 1125 } 1126 1127 // ===== impl Inner ===== 1128 1129 impl Inner { 1130 /// Indicates that the span with the given ID has an indirect causal 1131 /// relationship with this span. 1132 /// 1133 /// This relationship differs somewhat from the parent-child relationship: a 1134 /// span may have any number of prior spans, rather than a single one; and 1135 /// spans are not considered to be executing _inside_ of the spans they 1136 /// follow from. This means that a span may close even if subsequent spans 1137 /// that follow from it are still open, and time spent inside of a 1138 /// subsequent span should not be included in the time its precedents were 1139 /// executing. This is used to model causal relationships such as when a 1140 /// single future spawns several related background tasks, et cetera. 1141 /// 1142 /// If this span is disabled, this function will do nothing. Otherwise, it 1143 /// returns `Ok(())` if the other span was added as a precedent of this 1144 /// span, or an error if this was not possible. follows_from(&self, from: &Id)1145 fn follows_from(&self, from: &Id) { 1146 self.subscriber.record_follows_from(&self.id, &from) 1147 } 1148 1149 /// Returns the span's ID. id(&self) -> Id1150 fn id(&self) -> Id { 1151 self.id.clone() 1152 } 1153 record(&self, values: &Record<'_>)1154 fn record(&self, values: &Record<'_>) { 1155 self.subscriber.record(&self.id, values) 1156 } 1157 new(id: Id, subscriber: &Dispatch) -> Self1158 fn new(id: Id, subscriber: &Dispatch) -> Self { 1159 Inner { 1160 id, 1161 subscriber: subscriber.clone(), 1162 } 1163 } 1164 } 1165 1166 impl cmp::PartialEq for Inner { eq(&self, other: &Self) -> bool1167 fn eq(&self, other: &Self) -> bool { 1168 self.id == other.id 1169 } 1170 } 1171 1172 impl Hash for Inner { hash<H: Hasher>(&self, state: &mut H)1173 fn hash<H: Hasher>(&self, state: &mut H) { 1174 self.id.hash(state); 1175 } 1176 } 1177 1178 impl Clone for Inner { clone(&self) -> Self1179 fn clone(&self) -> Self { 1180 Inner { 1181 id: self.subscriber.clone_span(&self.id), 1182 subscriber: self.subscriber.clone(), 1183 } 1184 } 1185 } 1186 1187 // ===== impl Entered ===== 1188 1189 impl<'a> Drop for Entered<'a> { 1190 #[inline] drop(&mut self)1191 fn drop(&mut self) { 1192 // Dropping the guard exits the span. 1193 // 1194 // Running this behaviour on drop rather than with an explicit function 1195 // call means that spans may still be exited when unwinding. 1196 if let Some(inner) = self.span.inner.as_ref() { 1197 inner.subscriber.exit(&inner.id); 1198 } 1199 1200 if_log_enabled! {{ 1201 if let Some(ref meta) = self.span.meta { 1202 self.span.log(ACTIVITY_LOG_TARGET, log::Level::Trace, format_args!("<- {}", meta.name())); 1203 } 1204 }} 1205 } 1206 } 1207 1208 #[cfg(feature = "log")] 1209 struct FmtValues<'a>(&'a Record<'a>); 1210 1211 #[cfg(feature = "log")] 1212 impl<'a> fmt::Display for FmtValues<'a> { fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result1213 fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { 1214 let mut res = Ok(()); 1215 let mut is_first = true; 1216 self.0.record(&mut |k: &field::Field, v: &dyn fmt::Debug| { 1217 res = write!(f, "{} {}={:?}", if is_first { ";" } else { "" }, k, v); 1218 is_first = false; 1219 }); 1220 res 1221 } 1222 } 1223 1224 #[cfg(feature = "log")] 1225 struct FmtAttrs<'a>(&'a Attributes<'a>); 1226 1227 #[cfg(feature = "log")] 1228 impl<'a> fmt::Display for FmtAttrs<'a> { fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result1229 fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { 1230 let mut res = Ok(()); 1231 let mut is_first = true; 1232 self.0.record(&mut |k: &field::Field, v: &dyn fmt::Debug| { 1233 res = write!(f, "{} {}={:?}", if is_first { ";" } else { "" }, k, v); 1234 is_first = false; 1235 }); 1236 res 1237 } 1238 } 1239 1240 #[cfg(test)] 1241 mod test { 1242 use super::*; 1243 1244 trait AssertSend: Send {} 1245 impl AssertSend for Span {} 1246 1247 trait AssertSync: Sync {} 1248 impl AssertSync for Span {} 1249 } 1250