tracing: fix the "log" feature making async block futures !Send

tracing/src/lib.rs

@@ -941,10 +941,6 @@
     while_true
 )]
 
-#[cfg(feature = "log")]
-#[doc(hidden)]
-pub use log;
-
 // Somehow this `use` statement is necessary for us to re-export the `core`
 // macros on Rust 1.26.0. I'm not sure how this makes it work, but it does.
 #[allow(unused_imports)]
@@ -1090,6 +1086,25 @@ pub mod __macro_support {
         pub fn disabled_span(&self) -> crate::Span {
             crate::Span::none()
         }
+
+        #[cfg(feature = "log")]
+        pub fn log(
+            &self,
+            logger: &'static dyn log::Log,
+            log_meta: log::Metadata<'_>,
+            values: &tracing_core::field::ValueSet<'_>,
+        ) {
+            let meta = self.metadata();
+            logger.log(
+                &crate::log::Record::builder()
+                    .file(meta.file())
+                    .module_path(meta.module_path())
+                    .line(meta.line())
+                    .metadata(log_meta)
+                    .args(format_args!("{}", crate::log::LogValueSet(values)))
+                    .build(),
+            );
+        }
     }
 
     impl Callsite for MacroCallsite {
@@ -1118,25 +1133,53 @@ pub mod __macro_support {
                 .finish()
         }
     }
+}
 
-    #[cfg(feature = "log")]
+#[cfg(feature = "log")]
+#[doc(hidden)]
+pub mod log {
+    use core::fmt;
+    pub use log::*;
     use tracing_core::field::{Field, ValueSet, Visit};
 
-    /// Utility to format [`ValueSet`] for logging, used by macro-generated code.
-    ///
-    /// /!\ WARNING: This is *not* a stable API! /!\
-    /// This type, and all code contained in the `__macro_support` module, is
-    /// a *private* API of `tracing`. It is exposed publicly because it is used
-    /// by the `tracing` macros, but it is not part of the stable versioned API.
-    /// Breaking changes to this module may occur in small-numbered versions
-    /// without warning.
-    #[cfg(feature = "log")]
-    #[allow(missing_debug_implementations)]
-    pub struct LogValueSet<'a>(pub &'a ValueSet<'a>);
+    /// Utility to format [`ValueSet`]s for logging.
+    pub(crate) struct LogValueSet<'a>(pub(crate) &'a ValueSet<'a>);
 
-    #[cfg(feature = "log")]
     impl<'a> fmt::Display for LogValueSet<'a> {
+        #[inline]
         fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
+            struct LogVisitor<'a, 'b> {
+                f: &'a mut fmt::Formatter<'b>,
+                is_first: bool,
+                result: fmt::Result,
+            }
+
+            impl Visit for LogVisitor<'_, '_> {
+                fn record_debug(&mut self, field: &Field, value: &dyn fmt::Debug) {
+                    let res = if self.is_first {
+                        self.is_first = false;
+                        if field.name() == "message" {
+                            write!(self.f, "{:?}", value)
+                        } else {
+                            write!(self.f, "{}={:?}", field.name(), value)
+                        }
+                    } else {
+                        write!(self.f, " {}={:?}", field.name(), value)
+                    };
+                    if let Err(err) = res {
+                        self.result = self.result.and(Err(err));
+                    }
+                }
+
+                fn record_str(&mut self, field: &Field, value: &str) {
+                    if field.name() == "message" {
+                        self.record_debug(field, &format_args!("{}", value))
+                    } else {
+                        self.record_debug(field, &value)
+                    }
+                }
+            }
+
             let mut visit = LogVisitor {
                 f,
                 is_first: true,
@@ -1146,40 +1189,6 @@ pub mod __macro_support {
             visit.result
         }
     }
-
-    #[cfg(feature = "log")]
-    struct LogVisitor<'a, 'b> {
-        f: &'a mut fmt::Formatter<'b>,
-        is_first: bool,
-        result: fmt::Result,
-    }
-
-    #[cfg(feature = "log")]
-    impl Visit for LogVisitor<'_, '_> {
-        fn record_debug(&mut self, field: &Field, value: &dyn fmt::Debug) {
-            let res = if self.is_first {
-                self.is_first = false;
-                if field.name() == "message" {
-                    write!(self.f, "{:?}", value)
-                } else {
-                    write!(self.f, "{}={:?}", field.name(), value)
-                }
-            } else {
-                write!(self.f, " {}={:?}", field.name(), value)
-            };
-            if let Err(err) = res {
-                self.result = self.result.and(Err(err));
-            }
-        }
-
-        fn record_str(&mut self, field: &Field, value: &str) {
-            if field.name() == "message" {
-                self.record_debug(field, &format_args!("{}", value))
-            } else {
-                self.record_debug(field, &value)
-            }
-        }
-    }
 }
 
 mod sealed {

tracing/src/macros.rs

@@ -605,8 +605,8 @@ macro_rules! event {
         if enabled {
             (|value_set: $crate::field::ValueSet| {
                 $crate::__tracing_log!(
-                    target: $target,
                     $lvl,
+                    CALLSITE,
                     &value_set
                 );
                 let meta = CALLSITE.metadata();
@@ -619,8 +619,8 @@ macro_rules! event {
             })($crate::valueset!(CALLSITE.metadata().fields(), $($fields)*));
         } else {
             $crate::__tracing_log!(
-                target: $target,
                 $lvl,
+                CALLSITE,
                 &$crate::valueset!(CALLSITE.metadata().fields(), $($fields)*)
             );
         }
@@ -667,15 +667,15 @@ macro_rules! event {
                     &value_set
                 );
                 $crate::__tracing_log!(
-                    target: $target,
                     $lvl,
+                    CALLSITE,
                     &value_set
                 );
             })($crate::valueset!(CALLSITE.metadata().fields(), $($fields)*));
         } else {
             $crate::__tracing_log!(
-                target: $target,
                 $lvl,
+                CALLSITE,
                 &$crate::valueset!(CALLSITE.metadata().fields(), $($fields)*)
             );
         }
@@ -2413,31 +2413,25 @@ macro_rules! __tracing_stringify {
 #[doc(hidden)]
 #[macro_export]
 macro_rules! __tracing_log {
-    (target: $target:expr, $level:expr, $value_set:expr ) => {};
+    ($level:expr, $callsite:expr, $value_set:expr) => {};
 }
 
 #[cfg(feature = "log")]
 #[doc(hidden)]
 #[macro_export]
 macro_rules! __tracing_log {
-    (target: $target:expr, $level:expr, $value_set:expr ) => {
+    ($level:expr, $callsite:expr, $value_set:expr) => {
         $crate::if_log_enabled! { $level, {
             use $crate::log;
             let level = $crate::level_to_log!($level);
             if level <= log::max_level() {
                 let log_meta = log::Metadata::builder()
                     .level(level)
-                    .target($target)
+                    .target(CALLSITE.metadata().target())
                     .build();
                 let logger = log::logger();
                 if logger.enabled(&log_meta) {
-                    logger.log(&log::Record::builder()
-                        .file(Some(file!()))
-                        .module_path(Some(module_path!()))
-                        .line(Some(line!()))
-                        .metadata(log_meta)
-                        .args(format_args!("{}", $crate::__macro_support::LogValueSet($value_set)))
-                        .build());
+                    $callsite.log(logger, log_meta, $value_set)
                 }
             }
         }}

tracing/src/span.rs

@@ -570,7 +570,11 @@ impl Span {
             } else {
                 meta.target()
             };
-            span.log(target, level_to_log!(*meta.level()), format_args!("++ {}{}", meta.name(), FmtAttrs(attrs)));
+            span.log(
+                target,
+                level_to_log!(*meta.level()),
+                format_args!("++ {}{}", meta.name(), crate::log::LogValueSet(attrs.values())),
+            );
         }}
 
         span
@@ -1220,7 +1224,11 @@ impl Span {
                 } else {
                     _meta.target()
                 };
-                self.log(target, level_to_log!(*_meta.level()), format_args!("{}{}", _meta.name(), FmtValues(&record)));
+                self.log(
+                    target,
+                    level_to_log!(*_meta.level()),
+                    format_args!("{}{}", _meta.name(), crate::log::LogValueSet(values)),
+                );
             }}
         }
 
@@ -1581,38 +1589,6 @@ const PhantomNotSend: PhantomNotSend = PhantomNotSend { ghost: PhantomData };
 /// Trivially safe, as `PhantomNotSend` doesn't have any API.
 unsafe impl Sync for PhantomNotSend {}
 
-#[cfg(feature = "log")]
-struct FmtValues<'a>(&'a Record<'a>);
-
-#[cfg(feature = "log")]
-impl<'a> fmt::Display for FmtValues<'a> {
-    fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
-        let mut res = Ok(());
-        let mut is_first = true;
-        self.0.record(&mut |k: &field::Field, v: &dyn fmt::Debug| {
-            res = write!(f, "{} {}={:?}", if is_first { ";" } else { "" }, k, v);
-            is_first = false;
-        });
-        res
-    }
-}
-
-#[cfg(feature = "log")]
-struct FmtAttrs<'a>(&'a Attributes<'a>);
-
-#[cfg(feature = "log")]
-impl<'a> fmt::Display for FmtAttrs<'a> {
-    fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
-        let mut res = Ok(());
-        let mut is_first = true;
-        self.0.record(&mut |k: &field::Field, v: &dyn fmt::Debug| {
-            res = write!(f, "{} {}={:?}", if is_first { ";" } else { "" }, k, v);
-            is_first = false;
-        });
-        res
-    }
-}
-
 #[cfg(test)]
 mod test {
     use super::*;

tracing/tests/future_send.rs

@@ -0,0 +1,23 @@
+// These tests reproduce the following issues:
+// - https://github.com/tokio-rs/tracing/issues/1487
+// - https://github.com/tokio-rs/tracing/issues/1793
+
+use core::future::{self, Future};
+#[test]
+fn async_fn_is_send() {
+    async fn some_async_fn() {
+        tracing::info!("{}", future::ready("test").await);
+    }
+
+    assert_send(some_async_fn())
+}
+
+#[test]
+fn async_block_is_send() {
+    assert_send(async {
+        tracing::info!("{}", future::ready("test").await);
+    })
+}
+
+
+fn assert_send<F: Future + Send>(_f: F) {}