tracing, tracing-futures: instrument Future inside Drop (#2562)

## Motivation

Currently it is not possible to disable ANSI in `fmt::Subscriber`
without enabling the "ansi" crate feature. This makes it difficult for
users to implement interoperable settings that are controllable with
crate features without having to pull in the dependencies "ansi" does.

I hit this while writing an application with multiple logging options
set during compile-time and I wanted to cut down on dependencies if
possible.

## Solution

This changes `fmt::Subscriber::with_ansi()` to not require the "ansi"
feature flag. This way, `with_ansi(false)` can be called even when the
"ansi" feature is disabled. Calling `with_ansi(true)` when the "ansi"
feature is not enabled will panic in debug mode, or print a warning if
debug assertions are disabled.

Co-authored-by: daxpedda <daxpedda@gmail.com>
Co-authored-by: Eliza Weisman <eliza@buoyant.io>

tracing-attributes/tests/async_fn.rs

@@ -90,6 +90,8 @@ fn async_fn_only_enters_for_polls() {
         .exit(expect::span().named("test_async_fn"))
         .enter(expect::span().named("test_async_fn"))
         .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"))
         .only()
         .run_with_handle();
@@ -120,8 +122,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 +205,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 +268,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 +345,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 +359,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 +402,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 +439,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 +472,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,6 +58,8 @@ fn follows_from_async_test() {
         .follows_from(consequence.clone(), cause_b)
         .follows_from(consequence.clone(), cause_c)
         .enter(consequence.clone())
+        .exit(consequence.clone())
+        .enter(consequence.clone())
         .exit(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/Cargo.toml

@@ -40,6 +40,7 @@ tokio-threadpool = "0.1.18"
 mio = "0.6.23"
 
 [dev-dependencies]
+futures = "0.3.21"
 tokio-test = "0.4.2"
 tracing-core = { path = "../tracing-core", version = "0.2" }
 tracing-mock = { path = "../tracing-mock", features = ["tokio-test"] }

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.execute(future).map_err(|e| {
+            let kind = e.kind();
+            let future = e.into_future().into_inner();
+            ExecuteError::new(kind, future)
+        })
     }
 }
 
@@ -32,7 +26,11 @@ 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| {
+            let kind = e.kind();
+            let future = e.into_future().inner;
+            ExecuteError::new(kind, future)
+        })
     }
 }