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