tracing, tracing-futures: instrument futures with Spans in Drop

tracing-attributes/tests/async_fn.rs

@@ -83,14 +83,17 @@ fn repro_1831_2() -> impl Future<Output = Result<(), Infallible>> {
 
 #[test]
 fn async_fn_only_enters_for_polls() {
+ let span = expect::span().named("test_async_fn");
  let (collector, handle) = collector::mock()
- .new_span(expect::span().named("test_async_fn"))
- .enter(expect::span().named("test_async_fn"))
+ .new_span(span.clone())
+ .enter(span.clone())
  .event(expect::event().with_fields(expect::field("awaiting").with_value(&true)))
- .exit(expect::span().named("test_async_fn"))
- .enter(expect::span().named("test_async_fn"))
- .exit(expect::span().named("test_async_fn"))
- .drop_span(expect::span().named("test_async_fn"))
+ .exit(span.clone())
+ .enter(span.clone())
+ .exit(span.clone())
+ .enter(span.clone())
+ .exit(span.clone())
+ .drop_span(span)
  .only()
  .run_with_handle();
  with_default(collector, || {
@@ -120,8 +123,12 @@ fn async_fn_nested() {
  .enter(span2.clone())
  .event(expect::event().with_fields(expect::field("nested").with_value(&true)))
  .exit(span2.clone())
+ .enter(span2.clone())
+ .exit(span2.clone())
  .drop_span(span2)
  .exit(span.clone())
+ .enter(span.clone())
+ .exit(span.clone())
  .drop_span(span)
  .only()
  .run_with_handle();
@@ -199,13 +206,19 @@ fn async_fn_with_async_trait() {
  .enter(span3.clone())
  .event(expect::event().with_fields(expect::field("val").with_value(&2u64)))
  .exit(span3.clone())
+ .enter(span3.clone())
+ .exit(span3.clone())
  .drop_span(span3)
  .new_span(span2.clone().with_field(expect::field("self")))
  .enter(span2.clone())
  .event(expect::event().with_fields(expect::field("val").with_value(&5u64)))
  .exit(span2.clone())
+ .enter(span2.clone())
+ .exit(span2.clone())
  .drop_span(span2)
  .exit(span.clone())
+ .enter(span.clone())
+ .exit(span.clone())
  .drop_span(span)
  .only()
  .run_with_handle();
@@ -256,6 +269,8 @@ fn async_fn_with_async_trait_and_fields_expressions() {
  )
  .enter(span.clone())
  .exit(span.clone())
+ .enter(span.clone())
+ .exit(span.clone())
  .drop_span(span)
  .only()
  .run_with_handle();
@@ -331,8 +346,12 @@ fn async_fn_with_async_trait_and_fields_expressions_with_generic_parameter() {
  .with_field(expect::field("Self").with_value(&std::any::type_name::<TestImpl>())),
  )
  .enter(span4.clone())
+ .exit(span4.clone())
+ .enter(span4.clone())
  .exit(span4)
  .exit(span2.clone())
+ .enter(span2.clone())
+ .exit(span2.clone())
  .drop_span(span2)
  .new_span(
  span3
@@ -341,6 +360,8 @@ fn async_fn_with_async_trait_and_fields_expressions_with_generic_parameter() {
  )
  .enter(span3.clone())
  .exit(span3.clone())
+ .enter(span3.clone())
+ .exit(span3.clone())
  .drop_span(span3)
  .only()
  .run_with_handle();
@@ -382,6 +403,8 @@ fn out_of_scope_fields() {
  .new_span(span.clone())
  .enter(span.clone())
  .exit(span.clone())
+ .enter(span.clone())
+ .exit(span.clone())
  .drop_span(span)
  .only()
  .run_with_handle();
@@ -417,6 +440,8 @@ fn manual_impl_future() {
  .enter(span.clone())
  .event(poll_event())
  .exit(span.clone())
+ .enter(span.clone())
+ .exit(span.clone())
  .drop_span(span)
  .only()
  .run_with_handle();
@@ -448,6 +473,8 @@ fn manual_box_pin() {
  .enter(span.clone())
  .event(poll_event())
  .exit(span.clone())
+ .enter(span.clone())
+ .exit(span.clone())
  .drop_span(span)
  .only()
  .run_with_handle();

tracing-attributes/tests/err.rs

@@ -78,6 +78,8 @@ fn test_async() {
  .enter(span.clone())
  .event(expect::event().at_level(Level::ERROR))
  .exit(span.clone())
+ .enter(span.clone())
+ .exit(span.clone())
  .drop_span(span)
  .only()
  .run_with_handle();
@@ -132,6 +134,8 @@ fn test_mut_async() {
  .enter(span.clone())
  .event(expect::event().at_level(Level::ERROR))
  .exit(span.clone())
+ .enter(span.clone())
+ .exit(span.clone())
  .drop_span(span)
  .only()
  .run_with_handle();

tracing-attributes/tests/follows_from.rs

@@ -58,7 +58,10 @@ fn follows_from_async_test() {
  .follows_from(consequence.clone(), cause_b)
  .follows_from(consequence.clone(), cause_c)
  .enter(consequence.clone())
- .exit(consequence)
+ .exit(consequence.clone())
+ .enter(consequence.clone())
+ .exit(consequence.clone())
+ .drop_span(consequence)
  .only()
  .run_with_handle();
 

tracing-attributes/tests/ret.rs

@@ -138,6 +138,8 @@ fn test_async() {
  .at_level(Level::INFO),
  )
  .exit(span.clone())
+ .enter(span.clone())
+ .exit(span.clone())
  .drop_span(span)
  .only()
  .run_with_handle();

tracing-futures/src/executor/futures_01.rs

@@ -4,24 +4,18 @@ use futures_01::{
  Future,
 };
 
-macro_rules! deinstrument_err {
- ($e:expr) => {
- $e.map_err(|e| {
- let kind = e.kind();
- let future = e.into_future().inner;
- ExecuteError::new(kind, future)
- })
- };
-}
-
 impl<T, F> Executor<F> for Instrumented<T>
 where
  T: Executor<Instrumented<F>>,
  F: Future<Item = (), Error = ()>,
 {
  fn execute(&self, future: F) -> Result<(), ExecuteError<F>> {
  let future = future.instrument(self.span.clone());
- deinstrument_err!(self.inner.execute(future))
+ self.inner
+ .as_ref()
+ .unwrap()
+ .execute(future)
+ .map_err(|e| ExecuteError::new(e.kind(), e.into_future().inner.take().unwrap()))
  }
 }
 
@@ -32,7 +26,9 @@ where
 {
  fn execute(&self, future: F) -> Result<(), ExecuteError<F>> {
  let future = self.with_dispatch(future);
- deinstrument_err!(self.inner.execute(future))
+ self.inner
+ .execute(future)
+ .map_err(|e| ExecuteError::new(e.kind(), e.into_future().inner))
  }
 }
 
@@ -59,7 +55,7 @@ mod tokio {
  ) -> Result<(), SpawnError> {
  // TODO: get rid of double box somehow?
  let future = Box::new(future.instrument(self.span.clone()));
- self.inner.spawn(future)
+ self.inner.as_mut().unwrap().spawn(future)
  }
  }
 
@@ -68,11 +64,14 @@ mod tokio {
  T: TypedExecutor<Instrumented<F>>,
  {
  fn spawn(&mut self, future: F) -> Result<(), SpawnError> {
- self.inner.spawn(future.instrument(self.span.clone()))
+ self.inner
+ .as_mut()
+ .unwrap()
+ .spawn(future.instrument(self.span.clone()))
  }
 
  fn status(&self) -> Result<(), SpawnError> {
- self.inner.status()
+ self.inner.as_ref().unwrap().status()
  }
  }
 
@@ -90,7 +89,7 @@ mod tokio {
  F: Future<Item = (), Error = ()> + Send + 'static,
  {
  let future = future.instrument(self.span.clone());
- self.inner.spawn(future);
+ self.inner.as_mut().unwrap().spawn(future);
  self
  }
 
@@ -116,7 +115,7 @@ mod tokio {
  E: Send + 'static,
  {
  let future = future.instrument(self.span.clone());
- self.inner.block_on(future)
+ self.inner.as_mut().unwrap().block_on(future)
  }
 
  /// Return an instrumented handle to the runtime's executor.
@@ -127,7 +126,11 @@ mod tokio {
  /// `tokio::runtime::TaskExecutor`, but instruments the spawned
  /// futures prior to spawning them.
  pub fn executor(&self) -> Instrumented<TaskExecutor> {
- self.inner.executor().instrument(self.span.clone())
+ self.inner
+ .as_ref()
+ .unwrap()
+ .executor()
+ .instrument(self.span.clone())
  }
  }
 
@@ -141,7 +144,7 @@ mod tokio {
  F: Future<Item = (), Error = ()> + 'static,
  {
  let future = future.instrument(self.span.clone());
- self.inner.spawn(future);
+ self.inner.as_mut().unwrap().spawn(future);
  self
  }
 
@@ -176,7 +179,7 @@ mod tokio {
  E: 'static,
  {
  let future = future.instrument(self.span.clone());
- self.inner.block_on(future)
+ self.inner.as_mut().unwrap().block_on(future)
  }
 
  /// Get a new instrumented handle to spawn futures on the single-threaded
@@ -189,7 +192,11 @@ mod tokio {
  /// `tokio::runtime::current_thread::Handle`, but instruments the spawned
  /// futures prior to spawning them.
  pub fn handle(&self) -> Instrumented<current_thread::Handle> {
- self.inner.handle().instrument(self.span.clone())
+ self.inner
+ .as_ref()
+ .unwrap()
+ .handle()
+ .instrument(self.span.clone())
  }
  }
 

tracing-futures/src/executor/futures_03.rs

@@ -15,7 +15,10 @@ where
  /// tasks.
  fn spawn_obj(&self, future: FutureObj<'static, ()>) -> Result<(), SpawnError> {
  let future = future.instrument(self.span.clone());
- self.inner.spawn_obj(FutureObj::new(Box::new(future)))
+ self.inner
+ .as_ref()
+ .unwrap()
+ .spawn_obj(FutureObj::new(Box::new(future)))
  }
 
  /// Determines whether the executor is able to spawn new tasks.
@@ -26,7 +29,7 @@ where
  /// not guaranteed, to yield an error.
  #[inline]
  fn status(&self) -> Result<(), SpawnError> {
- self.inner.status()
+ self.inner.as_ref().unwrap().status()
  }
 }
 
@@ -74,6 +77,8 @@ where
  fn spawn_local_obj(&self, future: LocalFutureObj<'static, ()>) -> Result<(), SpawnError> {
  let future = future.instrument(self.span.clone());
  self.inner
+ .as_ref()
+ .unwrap()
  .spawn_local_obj(LocalFutureObj::new(Box::new(future)))
  }
 
@@ -85,7 +90,7 @@ where
  /// not guaranteed, to yield an error.
  #[inline]
  fn status_local(&self) -> Result<(), SpawnError> {
- self.inner.status_local()
+ self.inner.as_ref().unwrap().status_local()
  }
 }