1 | use tracing_mock::*; |
2 | |
3 | use std::convert::Infallible; |
4 | use std::{future::Future, pin::Pin, sync::Arc}; |
5 | use tracing::subscriber::with_default; |
6 | use tracing_attributes::instrument; |
7 | |
8 | #[instrument ] |
9 | async fn test_async_fn(polls: usize) -> Result<(), ()> { |
10 | let future = PollN::new_ok(polls); |
11 | tracing::trace!(awaiting = true); |
12 | future.await |
13 | } |
14 | |
15 | // Reproduces a compile error when returning an `impl Trait` from an |
16 | // instrumented async fn (see https://github.com/tokio-rs/tracing/issues/1615) |
17 | #[allow (dead_code)] // this is just here to test whether it compiles. |
18 | #[instrument ] |
19 | async fn test_ret_impl_trait(n: i32) -> Result<impl Iterator<Item = i32>, ()> { |
20 | Ok((0..10).filter(move |x| *x < n)) |
21 | } |
22 | |
23 | // Reproduces a compile error when returning an `impl Trait` from an |
24 | // instrumented async fn (see https://github.com/tokio-rs/tracing/issues/1615) |
25 | #[allow (dead_code)] // this is just here to test whether it compiles. |
26 | #[instrument (err)] |
27 | async fn test_ret_impl_trait_err(n: i32) -> Result<impl Iterator<Item = i32>, &'static str> { |
28 | Ok((0..10).filter(move |x| *x < n)) |
29 | } |
30 | |
31 | #[instrument ] |
32 | async fn test_async_fn_empty() {} |
33 | |
34 | // Reproduces a compile error when an instrumented function body contains inner |
35 | // attributes (https://github.com/tokio-rs/tracing/issues/2294). |
36 | #[deny (unused_variables)] |
37 | #[instrument ] |
38 | async fn repro_async_2294() { |
39 | #![allow (unused_variables)] |
40 | let i = 42; |
41 | } |
42 | |
43 | // Reproduces https://github.com/tokio-rs/tracing/issues/1613 |
44 | #[instrument ] |
45 | // LOAD-BEARING `#[rustfmt::skip]`! This is necessary to reproduce the bug; |
46 | // with the rustfmt-generated formatting, the lint will not be triggered! |
47 | #[rustfmt::skip] |
48 | #[deny (clippy::suspicious_else_formatting)] |
49 | async fn repro_1613(var: bool) { |
50 | println!( |
51 | "{}" , |
52 | if var { "true" } else { "false" } |
53 | ); |
54 | } |
55 | |
56 | // Reproduces https://github.com/tokio-rs/tracing/issues/1613 |
57 | // and https://github.com/rust-lang/rust-clippy/issues/7760 |
58 | #[instrument ] |
59 | #[deny (clippy::suspicious_else_formatting)] |
60 | async fn repro_1613_2() { |
61 | // hello world |
62 | // else |
63 | } |
64 | |
65 | // Reproduces https://github.com/tokio-rs/tracing/issues/1831 |
66 | #[allow (dead_code)] // this is just here to test whether it compiles. |
67 | #[instrument ] |
68 | #[deny (unused_braces)] |
69 | fn repro_1831() -> Pin<Box<dyn Future<Output = ()>>> { |
70 | Box::pin(async move {}) |
71 | } |
72 | |
73 | // This replicates the pattern used to implement async trait methods on nightly using the |
74 | // `type_alias_impl_trait` feature |
75 | #[allow (dead_code)] // this is just here to test whether it compiles. |
76 | #[instrument (ret, err)] |
77 | #[deny (unused_braces)] |
78 | #[allow (clippy::manual_async_fn)] |
79 | fn repro_1831_2() -> impl Future<Output = Result<(), Infallible>> { |
80 | async { Ok(()) } |
81 | } |
82 | |
83 | #[test] |
84 | fn async_fn_only_enters_for_polls() { |
85 | let (subscriber, handle) = subscriber::mock() |
86 | .new_span(expect::span().named("test_async_fn" )) |
87 | .enter(expect::span().named("test_async_fn" )) |
88 | .event(expect::event().with_fields(expect::field("awaiting" ).with_value(&true))) |
89 | .exit(expect::span().named("test_async_fn" )) |
90 | .enter(expect::span().named("test_async_fn" )) |
91 | .exit(expect::span().named("test_async_fn" )) |
92 | .enter(expect::span().named("test_async_fn" )) |
93 | .exit(expect::span().named("test_async_fn" )) |
94 | .drop_span(expect::span().named("test_async_fn" )) |
95 | .only() |
96 | .run_with_handle(); |
97 | with_default(subscriber, || { |
98 | block_on_future(async { test_async_fn(2).await }).unwrap(); |
99 | }); |
100 | handle.assert_finished(); |
101 | } |
102 | |
103 | #[test] |
104 | fn async_fn_nested() { |
105 | #[instrument ] |
106 | async fn test_async_fns_nested() { |
107 | test_async_fns_nested_other().await |
108 | } |
109 | |
110 | #[instrument ] |
111 | async fn test_async_fns_nested_other() { |
112 | tracing::trace!(nested = true); |
113 | } |
114 | |
115 | let span = expect::span().named("test_async_fns_nested" ); |
116 | let span2 = expect::span().named("test_async_fns_nested_other" ); |
117 | let (subscriber, handle) = subscriber::mock() |
118 | .new_span(span.clone()) |
119 | .enter(span.clone()) |
120 | .new_span(span2.clone()) |
121 | .enter(span2.clone()) |
122 | .event(expect::event().with_fields(expect::field("nested" ).with_value(&true))) |
123 | .exit(span2.clone()) |
124 | .enter(span2.clone()) |
125 | .exit(span2.clone()) |
126 | .drop_span(span2) |
127 | .exit(span.clone()) |
128 | .enter(span.clone()) |
129 | .exit(span.clone()) |
130 | .drop_span(span) |
131 | .only() |
132 | .run_with_handle(); |
133 | |
134 | with_default(subscriber, || { |
135 | block_on_future(async { test_async_fns_nested().await }); |
136 | }); |
137 | |
138 | handle.assert_finished(); |
139 | } |
140 | |
141 | #[test] |
142 | fn async_fn_with_async_trait() { |
143 | use async_trait::async_trait; |
144 | |
145 | // test the correctness of the metadata obtained by #[instrument] |
146 | // (function name, functions parameters) when async-trait is used |
147 | #[async_trait ] |
148 | pub trait TestA { |
149 | async fn foo(&mut self, v: usize); |
150 | } |
151 | |
152 | // test nesting of async fns with aync-trait |
153 | #[async_trait ] |
154 | pub trait TestB { |
155 | async fn bar(&self); |
156 | } |
157 | |
158 | // test skip(self) with async-await |
159 | #[async_trait ] |
160 | pub trait TestC { |
161 | async fn baz(&self); |
162 | } |
163 | |
164 | #[derive(Debug)] |
165 | struct TestImpl(usize); |
166 | |
167 | #[async_trait ] |
168 | impl TestA for TestImpl { |
169 | #[instrument ] |
170 | async fn foo(&mut self, v: usize) { |
171 | self.baz().await; |
172 | self.0 = v; |
173 | self.bar().await |
174 | } |
175 | } |
176 | |
177 | #[async_trait ] |
178 | impl TestB for TestImpl { |
179 | #[instrument ] |
180 | async fn bar(&self) { |
181 | tracing::trace!(val = self.0); |
182 | } |
183 | } |
184 | |
185 | #[async_trait ] |
186 | impl TestC for TestImpl { |
187 | #[instrument (skip(self))] |
188 | async fn baz(&self) { |
189 | tracing::trace!(val = self.0); |
190 | } |
191 | } |
192 | |
193 | let span = expect::span().named("foo" ); |
194 | let span2 = expect::span().named("bar" ); |
195 | let span3 = expect::span().named("baz" ); |
196 | let (subscriber, handle) = subscriber::mock() |
197 | .new_span( |
198 | span.clone() |
199 | .with_field(expect::field("self" )) |
200 | .with_field(expect::field("v" )), |
201 | ) |
202 | .enter(span.clone()) |
203 | .new_span(span3.clone()) |
204 | .enter(span3.clone()) |
205 | .event(expect::event().with_fields(expect::field("val" ).with_value(&2u64))) |
206 | .exit(span3.clone()) |
207 | .enter(span3.clone()) |
208 | .exit(span3.clone()) |
209 | .drop_span(span3) |
210 | .new_span(span2.clone().with_field(expect::field("self" ))) |
211 | .enter(span2.clone()) |
212 | .event(expect::event().with_fields(expect::field("val" ).with_value(&5u64))) |
213 | .exit(span2.clone()) |
214 | .enter(span2.clone()) |
215 | .exit(span2.clone()) |
216 | .drop_span(span2) |
217 | .exit(span.clone()) |
218 | .enter(span.clone()) |
219 | .exit(span.clone()) |
220 | .drop_span(span) |
221 | .only() |
222 | .run_with_handle(); |
223 | |
224 | with_default(subscriber, || { |
225 | let mut test = TestImpl(2); |
226 | block_on_future(async { test.foo(5).await }); |
227 | }); |
228 | |
229 | handle.assert_finished(); |
230 | } |
231 | |
232 | #[test] |
233 | fn async_fn_with_async_trait_and_fields_expressions() { |
234 | use async_trait::async_trait; |
235 | |
236 | #[async_trait ] |
237 | pub trait Test { |
238 | async fn call(&mut self, v: usize); |
239 | } |
240 | |
241 | #[derive(Clone, Debug)] |
242 | struct TestImpl; |
243 | |
244 | impl TestImpl { |
245 | fn foo(&self) -> usize { |
246 | 42 |
247 | } |
248 | } |
249 | |
250 | #[async_trait ] |
251 | impl Test for TestImpl { |
252 | // check that self is correctly handled, even when using async_trait |
253 | #[instrument (fields(val=self.foo(), val2=Self::clone(self).foo(), test=%_v+5))] |
254 | async fn call(&mut self, _v: usize) {} |
255 | } |
256 | |
257 | let span = expect::span().named("call" ); |
258 | let (subscriber, handle) = subscriber::mock() |
259 | .new_span( |
260 | span.clone().with_field( |
261 | expect::field("_v" ) |
262 | .with_value(&5usize) |
263 | .and(expect::field("test" ).with_value(&tracing::field::debug(10))) |
264 | .and(expect::field("val" ).with_value(&42u64)) |
265 | .and(expect::field("val2" ).with_value(&42u64)), |
266 | ), |
267 | ) |
268 | .enter(span.clone()) |
269 | .exit(span.clone()) |
270 | .enter(span.clone()) |
271 | .exit(span.clone()) |
272 | .drop_span(span) |
273 | .only() |
274 | .run_with_handle(); |
275 | |
276 | with_default(subscriber, || { |
277 | block_on_future(async { TestImpl.call(5).await }); |
278 | }); |
279 | |
280 | handle.assert_finished(); |
281 | } |
282 | |
283 | #[test] |
284 | fn async_fn_with_async_trait_and_fields_expressions_with_generic_parameter() { |
285 | use async_trait::async_trait; |
286 | |
287 | #[async_trait ] |
288 | pub trait Test { |
289 | async fn call(); |
290 | async fn call_with_self(&self); |
291 | async fn call_with_mut_self(&mut self); |
292 | } |
293 | |
294 | #[derive(Clone, Debug)] |
295 | struct TestImpl; |
296 | |
297 | // we also test sync functions that return futures, as they should be handled just like |
298 | // async-trait (>= 0.1.44) functions |
299 | impl TestImpl { |
300 | #[instrument (fields(Self=std::any::type_name::<Self>()))] |
301 | fn sync_fun(&self) -> Pin<Box<dyn Future<Output = ()> + Send + '_>> { |
302 | let val = self.clone(); |
303 | Box::pin(async move { |
304 | let _ = val; |
305 | }) |
306 | } |
307 | } |
308 | |
309 | #[async_trait ] |
310 | impl Test for TestImpl { |
311 | // instrumenting this is currently not possible, see https://github.com/tokio-rs/tracing/issues/864#issuecomment-667508801 |
312 | //#[instrument(fields(Self=std::any::type_name::<Self>()))] |
313 | async fn call() {} |
314 | |
315 | #[instrument (fields(Self=std::any::type_name::<Self>()))] |
316 | async fn call_with_self(&self) { |
317 | self.sync_fun().await; |
318 | } |
319 | |
320 | #[instrument (fields(Self=std::any::type_name::<Self>()))] |
321 | async fn call_with_mut_self(&mut self) {} |
322 | } |
323 | |
324 | //let span = span::mock().named("call"); |
325 | let span2 = expect::span().named("call_with_self" ); |
326 | let span3 = expect::span().named("call_with_mut_self" ); |
327 | let span4 = expect::span().named("sync_fun" ); |
328 | let (subscriber, handle) = subscriber::mock() |
329 | /*.new_span(span.clone() |
330 | .with_field( |
331 | expect::field("Self").with_value(&"TestImpler"))) |
332 | .enter(span.clone()) |
333 | .exit(span.clone()) |
334 | .drop_span(span)*/ |
335 | .new_span( |
336 | span2 |
337 | .clone() |
338 | .with_field(expect::field("Self" ).with_value(&std::any::type_name::<TestImpl>())), |
339 | ) |
340 | .enter(span2.clone()) |
341 | .new_span( |
342 | span4 |
343 | .clone() |
344 | .with_field(expect::field("Self" ).with_value(&std::any::type_name::<TestImpl>())), |
345 | ) |
346 | .enter(span4.clone()) |
347 | .exit(span4.clone()) |
348 | .enter(span4.clone()) |
349 | .exit(span4) |
350 | .exit(span2.clone()) |
351 | .enter(span2.clone()) |
352 | .exit(span2.clone()) |
353 | .drop_span(span2) |
354 | .new_span( |
355 | span3 |
356 | .clone() |
357 | .with_field(expect::field("Self" ).with_value(&std::any::type_name::<TestImpl>())), |
358 | ) |
359 | .enter(span3.clone()) |
360 | .exit(span3.clone()) |
361 | .enter(span3.clone()) |
362 | .exit(span3.clone()) |
363 | .drop_span(span3) |
364 | .only() |
365 | .run_with_handle(); |
366 | |
367 | with_default(subscriber, || { |
368 | block_on_future(async { |
369 | TestImpl::call().await; |
370 | TestImpl.call_with_self().await; |
371 | TestImpl.call_with_mut_self().await |
372 | }); |
373 | }); |
374 | |
375 | handle.assert_finished(); |
376 | } |
377 | |
378 | #[test] |
379 | fn out_of_scope_fields() { |
380 | // Reproduces tokio-rs/tracing#1296 |
381 | |
382 | struct Thing { |
383 | metrics: Arc<()>, |
384 | } |
385 | |
386 | impl Thing { |
387 | #[instrument (skip(self, _req), fields(app_id))] |
388 | fn call(&mut self, _req: ()) -> Pin<Box<dyn Future<Output = Arc<()>> + Send + Sync>> { |
389 | // ... |
390 | let metrics = self.metrics.clone(); |
391 | // ... |
392 | Box::pin(async move { |
393 | // ... |
394 | metrics // cannot find value `metrics` in this scope |
395 | }) |
396 | } |
397 | } |
398 | |
399 | let span = expect::span().named("call" ); |
400 | let (subscriber, handle) = subscriber::mock() |
401 | .new_span(span.clone()) |
402 | .enter(span.clone()) |
403 | .exit(span.clone()) |
404 | .enter(span.clone()) |
405 | .exit(span.clone()) |
406 | .drop_span(span) |
407 | .only() |
408 | .run_with_handle(); |
409 | |
410 | with_default(subscriber, || { |
411 | block_on_future(async { |
412 | let mut my_thing = Thing { |
413 | metrics: Arc::new(()), |
414 | }; |
415 | my_thing.call(()).await; |
416 | }); |
417 | }); |
418 | |
419 | handle.assert_finished(); |
420 | } |
421 | |
422 | #[test] |
423 | fn manual_impl_future() { |
424 | #[allow (clippy::manual_async_fn)] |
425 | #[instrument ] |
426 | fn manual_impl_future() -> impl Future<Output = ()> { |
427 | async { |
428 | tracing::trace!(poll = true); |
429 | } |
430 | } |
431 | |
432 | let span = expect::span().named("manual_impl_future" ); |
433 | let poll_event = || expect::event().with_fields(expect::field("poll" ).with_value(&true)); |
434 | |
435 | let (subscriber, handle) = subscriber::mock() |
436 | // await manual_impl_future |
437 | .new_span(span.clone()) |
438 | .enter(span.clone()) |
439 | .event(poll_event()) |
440 | .exit(span.clone()) |
441 | .enter(span.clone()) |
442 | .exit(span.clone()) |
443 | .drop_span(span) |
444 | .only() |
445 | .run_with_handle(); |
446 | |
447 | with_default(subscriber, || { |
448 | block_on_future(async { |
449 | manual_impl_future().await; |
450 | }); |
451 | }); |
452 | |
453 | handle.assert_finished(); |
454 | } |
455 | |
456 | #[test] |
457 | fn manual_box_pin() { |
458 | #[instrument ] |
459 | fn manual_box_pin() -> Pin<Box<dyn Future<Output = ()>>> { |
460 | Box::pin(async { |
461 | tracing::trace!(poll = true); |
462 | }) |
463 | } |
464 | |
465 | let span = expect::span().named("manual_box_pin" ); |
466 | let poll_event = || expect::event().with_fields(expect::field("poll" ).with_value(&true)); |
467 | |
468 | let (subscriber, handle) = subscriber::mock() |
469 | // await manual_box_pin |
470 | .new_span(span.clone()) |
471 | .enter(span.clone()) |
472 | .event(poll_event()) |
473 | .exit(span.clone()) |
474 | .enter(span.clone()) |
475 | .exit(span.clone()) |
476 | .drop_span(span) |
477 | .only() |
478 | .run_with_handle(); |
479 | |
480 | with_default(subscriber, || { |
481 | block_on_future(async { |
482 | manual_box_pin().await; |
483 | }); |
484 | }); |
485 | |
486 | handle.assert_finished(); |
487 | } |
488 | |