/rust/registry/src/index.crates.io-6f17d22bba15001f/tracing-0.1.40/src/span.rs
Line | Count | Source (jump to first uncovered line) |
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 | 0 | pub fn new(meta: &'static Metadata<'static>, values: &field::ValueSet<'_>) -> Span { |
437 | 0 | dispatcher::get_default(|dispatch| Self::new_with(meta, values, dispatch)) |
438 | 0 | } |
439 | | |
440 | | #[inline] |
441 | | #[doc(hidden)] |
442 | 0 | pub fn new_with( |
443 | 0 | meta: &'static Metadata<'static>, |
444 | 0 | values: &field::ValueSet<'_>, |
445 | 0 | dispatch: &Dispatch, |
446 | 0 | ) -> Span { |
447 | 0 | let new_span = Attributes::new(meta, values); |
448 | 0 | Self::make_with(meta, new_span, dispatch) |
449 | 0 | } |
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 | 0 | pub fn new_root(meta: &'static Metadata<'static>, values: &field::ValueSet<'_>) -> Span { |
461 | 0 | dispatcher::get_default(|dispatch| Self::new_root_with(meta, values, dispatch)) |
462 | 0 | } |
463 | | |
464 | | #[inline] |
465 | | #[doc(hidden)] |
466 | 0 | pub fn new_root_with( |
467 | 0 | meta: &'static Metadata<'static>, |
468 | 0 | values: &field::ValueSet<'_>, |
469 | 0 | dispatch: &Dispatch, |
470 | 0 | ) -> Span { |
471 | 0 | let new_span = Attributes::new_root(meta, values); |
472 | 0 | Self::make_with(meta, new_span, dispatch) |
473 | 0 | } |
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 | 0 | pub fn child_of( |
485 | 0 | parent: impl Into<Option<Id>>, |
486 | 0 | meta: &'static Metadata<'static>, |
487 | 0 | values: &field::ValueSet<'_>, |
488 | 0 | ) -> Span { |
489 | 0 | let mut parent = parent.into(); |
490 | 0 | dispatcher::get_default(move |dispatch| { |
491 | 0 | Self::child_of_with(Option::take(&mut parent), meta, values, dispatch) |
492 | 0 | }) |
493 | 0 | } |
494 | | |
495 | | #[inline] |
496 | | #[doc(hidden)] |
497 | 0 | pub fn child_of_with( |
498 | 0 | parent: impl Into<Option<Id>>, |
499 | 0 | meta: &'static Metadata<'static>, |
500 | 0 | values: &field::ValueSet<'_>, |
501 | 0 | dispatch: &Dispatch, |
502 | 0 | ) -> Span { |
503 | 0 | let new_span = match parent.into() { |
504 | 0 | Some(parent) => Attributes::child_of(parent, meta, values), |
505 | 0 | None => Attributes::new_root(meta, values), |
506 | | }; |
507 | 0 | Self::make_with(meta, new_span, dispatch) |
508 | 0 | } |
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 | 0 | pub const fn none() -> Span { |
534 | 0 | Self { |
535 | 0 | inner: None, |
536 | 0 | meta: None, |
537 | 0 | } |
538 | 0 | } |
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 | 0 | pub fn current() -> Span { |
550 | 0 | dispatcher::get_default(|dispatch| { |
551 | 0 | if let Some((id, meta)) = dispatch.current_span().into_inner() { |
552 | 0 | let id = dispatch.clone_span(&id); |
553 | 0 | Self { |
554 | 0 | inner: Some(Inner::new(id, dispatch)), |
555 | 0 | meta: Some(meta), |
556 | 0 | } |
557 | | } else { |
558 | 0 | Self::none() |
559 | | } |
560 | 0 | }) |
561 | 0 | } |
562 | | |
563 | 0 | fn make_with( |
564 | 0 | meta: &'static Metadata<'static>, |
565 | 0 | new_span: Attributes<'_>, |
566 | 0 | dispatch: &Dispatch, |
567 | 0 | ) -> Span { |
568 | 0 | let attrs = &new_span; |
569 | 0 | let id = dispatch.new_span(attrs); |
570 | 0 | let inner = Some(Inner::new(id, dispatch)); |
571 | 0 |
|
572 | 0 | let span = Self { |
573 | 0 | inner, |
574 | 0 | meta: Some(meta), |
575 | 0 | }; |
576 | 0 |
|
577 | 0 | if_log_enabled! { *meta.level(), { |
578 | 0 | let target = if attrs.is_empty() { |
579 | 0 | LIFECYCLE_LOG_TARGET |
580 | 0 | } else { |
581 | 0 | meta.target() |
582 | 0 | }; |
583 | 0 | let values = attrs.values(); |
584 | 0 | span.log( |
585 | 0 | target, |
586 | 0 | level_to_log!(*meta.level()), |
587 | 0 | format_args!("++ {};{}", meta.name(), crate::log::LogValueSet { values, is_first: false }), |
588 | 0 | ); |
589 | 0 | }} |
590 | 0 |
|
591 | 0 | span |
592 | 0 | } |
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 | 0 | pub fn enter(&self) -> Entered<'_> { |
786 | 0 | self.do_enter(); |
787 | 0 | Entered { span: self } |
788 | 0 | } |
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 | 0 | pub fn or_current(self) -> Self { |
1028 | 0 | if self.is_disabled() { |
1029 | 0 | return Self::current(); |
1030 | 0 | } |
1031 | 0 | self |
1032 | 0 | } |
1033 | | |
1034 | | #[inline(always)] |
1035 | 0 | fn do_enter(&self) { |
1036 | 0 | if let Some(inner) = self.inner.as_ref() { |
1037 | 0 | inner.subscriber.enter(&inner.id); |
1038 | 0 | } |
1039 | | |
1040 | 0 | if_log_enabled! { crate::Level::TRACE, { |
1041 | 0 | if let Some(_meta) = self.meta { |
1042 | 0 | self.log(ACTIVITY_LOG_TARGET, log::Level::Trace, format_args!("-> {};", _meta.name())); |
1043 | 0 | } |
1044 | 0 | }} |
1045 | 0 | } |
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 | 0 | fn do_exit(&self) { |
1053 | 0 | if let Some(inner) = self.inner.as_ref() { |
1054 | 0 | inner.subscriber.exit(&inner.id); |
1055 | 0 | } |
1056 | | |
1057 | 0 | if_log_enabled! { crate::Level::TRACE, { |
1058 | 0 | if let Some(_meta) = self.meta { |
1059 | 0 | self.log(ACTIVITY_LOG_TARGET, log::Level::Trace, format_args!("<- {};", _meta.name())); |
1060 | 0 | } |
1061 | 0 | }} |
1062 | 0 | } |
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 | 0 | pub fn in_scope<F: FnOnce() -> T, T>(&self, f: F) -> T { |
1101 | 0 | let _enter = self.enter(); |
1102 | 0 | f() |
1103 | 0 | } |
1104 | | |
1105 | | /// Returns a [`Field`][super::field::Field] for the field with the |
1106 | | /// given `name`, if one exists, |
1107 | 0 | pub fn field<Q: ?Sized>(&self, field: &Q) -> Option<field::Field> |
1108 | 0 | where |
1109 | 0 | Q: field::AsField, |
1110 | 0 | { |
1111 | 0 | self.metadata().and_then(|meta| field.as_field(meta)) |
1112 | 0 | } |
1113 | | |
1114 | | /// Returns true if this `Span` has a field for the given |
1115 | | /// [`Field`][super::field::Field] or field name. |
1116 | | #[inline] |
1117 | 0 | pub fn has_field<Q: ?Sized>(&self, field: &Q) -> bool |
1118 | 0 | where |
1119 | 0 | Q: field::AsField, |
1120 | 0 | { |
1121 | 0 | self.field(field).is_some() |
1122 | 0 | } |
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 | 0 | pub fn record<Q: ?Sized, V>(&self, field: &Q, value: V) -> &Self |
1195 | 0 | where |
1196 | 0 | Q: field::AsField, |
1197 | 0 | V: field::Value, |
1198 | 0 | { |
1199 | 0 | if let Some(meta) = self.meta { |
1200 | 0 | if let Some(field) = field.as_field(meta) { |
1201 | 0 | self.record_all( |
1202 | 0 | &meta |
1203 | 0 | .fields() |
1204 | 0 | .value_set(&[(&field, Some(&value as &dyn field::Value))]), |
1205 | 0 | ); |
1206 | 0 | } |
1207 | 0 | } |
1208 | | |
1209 | 0 | self |
1210 | 0 | } |
1211 | | |
1212 | | /// Records all the fields in the provided `ValueSet`. |
1213 | 0 | pub fn record_all(&self, values: &field::ValueSet<'_>) -> &Self { |
1214 | 0 | let record = Record::new(values); |
1215 | 0 | if let Some(ref inner) = self.inner { |
1216 | 0 | inner.record(&record); |
1217 | 0 | } |
1218 | | |
1219 | 0 | if let Some(_meta) = self.meta { |
1220 | 0 | if_log_enabled! { *_meta.level(), { |
1221 | 0 | let target = if record.is_empty() { |
1222 | 0 | LIFECYCLE_LOG_TARGET |
1223 | 0 | } else { |
1224 | 0 | _meta.target() |
1225 | 0 | }; |
1226 | 0 | self.log( |
1227 | 0 | target, |
1228 | 0 | level_to_log!(*_meta.level()), |
1229 | 0 | format_args!("{};{}", _meta.name(), crate::log::LogValueSet { values, is_first: false }), |
1230 | 0 | ); |
1231 | 0 | }} |
1232 | 0 | } |
1233 | | |
1234 | 0 | self |
1235 | 0 | } |
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 | 0 | pub fn is_disabled(&self) -> bool { |
1245 | 0 | self.inner.is_none() |
1246 | 0 | } |
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 | 0 | pub fn is_none(&self) -> bool { |
1260 | 0 | self.is_disabled() && self.meta.is_none() |
1261 | 0 | } |
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 | 0 | pub fn follows_from(&self, from: impl Into<Option<Id>>) -> &Self { |
1311 | 0 | if let Some(ref inner) = self.inner { |
1312 | 0 | if let Some(from) = from.into() { |
1313 | 0 | inner.follows_from(&from); |
1314 | 0 | } |
1315 | 0 | } |
1316 | 0 | self |
1317 | 0 | } |
1318 | | |
1319 | | /// Returns this span's `Id`, if it is enabled. |
1320 | 0 | pub fn id(&self) -> Option<Id> { |
1321 | 0 | self.inner.as_ref().map(Inner::id) |
1322 | 0 | } |
1323 | | |
1324 | | /// Returns this span's `Metadata`, if it is enabled. |
1325 | 0 | pub fn metadata(&self) -> Option<&'static Metadata<'static>> { |
1326 | 0 | self.meta |
1327 | 0 | } |
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 | 0 | pub fn with_subscriber<T>(&self, f: impl FnOnce((&Id, &Dispatch)) -> T) -> Option<T> { |
1369 | 0 | self.inner |
1370 | 0 | .as_ref() |
1371 | 0 | .map(|inner| f((&inner.id, &inner.subscriber))) |
1372 | 0 | } |
1373 | | } |
1374 | | |
1375 | | impl cmp::PartialEq for Span { |
1376 | 0 | fn eq(&self, other: &Self) -> bool { |
1377 | 0 | match (&self.meta, &other.meta) { |
1378 | 0 | (Some(this), Some(that)) => { |
1379 | 0 | this.callsite() == that.callsite() && self.inner == other.inner |
1380 | | } |
1381 | 0 | _ => false, |
1382 | | } |
1383 | 0 | } |
1384 | | } |
1385 | | |
1386 | | impl Hash for Span { |
1387 | 0 | fn hash<H: Hasher>(&self, hasher: &mut H) { |
1388 | 0 | self.inner.hash(hasher); |
1389 | 0 | } |
1390 | | } |
1391 | | |
1392 | | impl fmt::Debug for Span { |
1393 | 0 | fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { |
1394 | 0 | let mut span = f.debug_struct("Span"); |
1395 | 0 | if let Some(meta) = self.meta { |
1396 | 0 | span.field("name", &meta.name()) |
1397 | 0 | .field("level", &meta.level()) |
1398 | 0 | .field("target", &meta.target()); |
1399 | | |
1400 | 0 | if let Some(ref inner) = self.inner { |
1401 | 0 | span.field("id", &inner.id()); |
1402 | 0 | } else { |
1403 | 0 | span.field("disabled", &true); |
1404 | 0 | } |
1405 | | |
1406 | 0 | if let Some(ref path) = meta.module_path() { |
1407 | 0 | span.field("module_path", &path); |
1408 | 0 | } |
1409 | | |
1410 | 0 | if let Some(ref line) = meta.line() { |
1411 | 0 | span.field("line", &line); |
1412 | 0 | } |
1413 | | |
1414 | 0 | if let Some(ref file) = meta.file() { |
1415 | 0 | span.field("file", &file); |
1416 | 0 | } |
1417 | 0 | } else { |
1418 | 0 | span.field("none", &true); |
1419 | 0 | } |
1420 | | |
1421 | 0 | span.finish() |
1422 | 0 | } |
1423 | | } |
1424 | | |
1425 | | impl<'a> From<&'a Span> for Option<&'a Id> { |
1426 | 0 | fn from(span: &'a Span) -> Self { |
1427 | 0 | span.inner.as_ref().map(|inner| &inner.id) |
1428 | 0 | } |
1429 | | } |
1430 | | |
1431 | | impl<'a> From<&'a Span> for Option<Id> { |
1432 | 0 | fn from(span: &'a Span) -> Self { |
1433 | 0 | span.inner.as_ref().map(Inner::id) |
1434 | 0 | } |
1435 | | } |
1436 | | |
1437 | | impl From<Span> for Option<Id> { |
1438 | 0 | fn from(span: Span) -> Self { |
1439 | 0 | span.inner.as_ref().map(Inner::id) |
1440 | 0 | } |
1441 | | } |
1442 | | |
1443 | | impl<'a> From<&'a EnteredSpan> for Option<&'a Id> { |
1444 | 0 | fn from(span: &'a EnteredSpan) -> Self { |
1445 | 0 | span.inner.as_ref().map(|inner| &inner.id) |
1446 | 0 | } |
1447 | | } |
1448 | | |
1449 | | impl<'a> From<&'a EnteredSpan> for Option<Id> { |
1450 | 0 | fn from(span: &'a EnteredSpan) -> Self { |
1451 | 0 | span.inner.as_ref().map(Inner::id) |
1452 | 0 | } |
1453 | | } |
1454 | | |
1455 | | impl Drop for Span { |
1456 | | #[inline(always)] |
1457 | 0 | fn drop(&mut self) { |
1458 | | if let Some(Inner { |
1459 | 0 | ref id, |
1460 | 0 | ref subscriber, |
1461 | 0 | }) = self.inner |
1462 | 0 | { |
1463 | 0 | subscriber.try_close(id.clone()); |
1464 | 0 | } |
1465 | | |
1466 | 0 | if_log_enabled! { crate::Level::TRACE, { |
1467 | 0 | if let Some(meta) = self.meta { |
1468 | 0 | self.log( |
1469 | 0 | LIFECYCLE_LOG_TARGET, |
1470 | 0 | log::Level::Trace, |
1471 | 0 | format_args!("-- {};", meta.name()), |
1472 | 0 | ); |
1473 | 0 | } |
1474 | 0 | }} |
1475 | 0 | } |
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 | 0 | fn follows_from(&self, from: &Id) { |
1497 | 0 | self.subscriber.record_follows_from(&self.id, from) |
1498 | 0 | } |
1499 | | |
1500 | | /// Returns the span's ID. |
1501 | 0 | fn id(&self) -> Id { |
1502 | 0 | self.id.clone() |
1503 | 0 | } |
1504 | | |
1505 | 0 | fn record(&self, values: &Record<'_>) { |
1506 | 0 | self.subscriber.record(&self.id, values) |
1507 | 0 | } |
1508 | | |
1509 | 0 | fn new(id: Id, subscriber: &Dispatch) -> Self { |
1510 | 0 | Inner { |
1511 | 0 | id, |
1512 | 0 | subscriber: subscriber.clone(), |
1513 | 0 | } |
1514 | 0 | } |
1515 | | } |
1516 | | |
1517 | | impl cmp::PartialEq for Inner { |
1518 | 0 | fn eq(&self, other: &Self) -> bool { |
1519 | 0 | self.id == other.id |
1520 | 0 | } |
1521 | | } |
1522 | | |
1523 | | impl Hash for Inner { |
1524 | 0 | fn hash<H: Hasher>(&self, state: &mut H) { |
1525 | 0 | self.id.hash(state); |
1526 | 0 | } |
1527 | | } |
1528 | | |
1529 | | impl Clone for Inner { |
1530 | 0 | fn clone(&self) -> Self { |
1531 | 0 | Inner { |
1532 | 0 | id: self.subscriber.clone_span(&self.id), |
1533 | 0 | subscriber: self.subscriber.clone(), |
1534 | 0 | } |
1535 | 0 | } |
1536 | | } |
1537 | | |
1538 | | // ===== impl Entered ===== |
1539 | | |
1540 | | impl EnteredSpan { |
1541 | | /// Returns this span's `Id`, if it is enabled. |
1542 | 0 | pub fn id(&self) -> Option<Id> { |
1543 | 0 | self.inner.as_ref().map(Inner::id) |
1544 | 0 | } |
1545 | | |
1546 | | /// Exits this span, returning the underlying [`Span`]. |
1547 | | #[inline] |
1548 | 0 | pub fn exit(mut self) -> Span { |
1549 | 0 | // One does not simply move out of a struct with `Drop`. |
1550 | 0 | let span = mem::replace(&mut self.span, Span::none()); |
1551 | 0 | span.do_exit(); |
1552 | 0 | span |
1553 | 0 | } |
1554 | | } |
1555 | | |
1556 | | impl Deref for EnteredSpan { |
1557 | | type Target = Span; |
1558 | | |
1559 | | #[inline] |
1560 | 0 | fn deref(&self) -> &Span { |
1561 | 0 | &self.span |
1562 | 0 | } |
1563 | | } |
1564 | | |
1565 | | impl<'a> Drop for Entered<'a> { |
1566 | | #[inline(always)] |
1567 | 0 | fn drop(&mut self) { |
1568 | 0 | self.span.do_exit() |
1569 | 0 | } |
1570 | | } |
1571 | | |
1572 | | impl Drop for EnteredSpan { |
1573 | | #[inline(always)] |
1574 | 0 | fn drop(&mut self) { |
1575 | 0 | self.span.do_exit() |
1576 | 0 | } |
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 | | } |