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="">&#x26a0; &#xfe0f;<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