Initial work to switch to tracing (#2185)

* Add tracing dep

* Switch over basic events

* Switch over dynamically enabled events

* Fix missing SocketAddr formatting

* More format fixing

* refactor: Apply tracing changes to new crate structure

sqlx-core/Cargo.toml

@@ -85,6 +85,7 @@ sha2 = { version = "0.10.0", default-features = false, optional = true }
 sqlformat = "0.2.0"
 thiserror = "1.0.30"
 tokio-stream = { version = "0.1.8", features = ["fs"], optional = true }
+tracing = { version = "0.1.37", features = ["log"] }
 smallvec = "1.7.0"
 url = { version = "2.2.2", default-features = false }
 bstr = { version = "0.2.17", default-features = false, features = ["std"], optional = true }

sqlx-core/src/logger.rs

@@ -1,6 +1,59 @@
 use crate::connection::LogSettings;
 use std::time::Instant;
 
+// Yes these look silly. `tracing` doesn't currently support dynamic levels
+// https://github.com/tokio-rs/tracing/issues/372
+#[doc(hidden)]
+#[macro_export]
+macro_rules! private_tracing_dynamic_enabled {
+    (target: $target:expr, $level:expr) => {{
+        use ::tracing::Level;
+
+        match $level {
+            Level::ERROR => ::tracing::enabled!(target: $target, Level::ERROR),
+            Level::WARN => ::tracing::enabled!(target: $target, Level::WARN),
+            Level::INFO => ::tracing::enabled!(target: $target, Level::INFO),
+            Level::DEBUG => ::tracing::enabled!(target: $target, Level::DEBUG),
+            Level::TRACE => ::tracing::enabled!(target: $target, Level::TRACE),
+        }
+    }};
+    ($level:expr) => {{
+        $crate::private_tracing_dynamic_enabled!(target: module_path!(), $level)
+    }};
+}
+
+#[doc(hidden)]
+#[macro_export]
+macro_rules! private_tracing_dynamic_event {
+    (target: $target:expr, $level:expr, $($args:tt)*) => {{
+        use ::tracing::Level;
+
+        match $level {
+            Level::ERROR => ::tracing::event!(target: $target, Level::ERROR, $($args)*),
+            Level::WARN => ::tracing::event!(target: $target, Level::WARN, $($args)*),
+            Level::INFO => ::tracing::event!(target: $target, Level::INFO, $($args)*),
+            Level::DEBUG => ::tracing::event!(target: $target, Level::DEBUG, $($args)*),
+            Level::TRACE => ::tracing::event!(target: $target, Level::TRACE, $($args)*),
+        }
+    }};
+}
+
+#[doc(hidden)]
+pub fn private_level_filter_to_levels(
+    filter: log::LevelFilter,
+) -> Option<(tracing::Level, log::Level)> {
+    let tracing_level = match filter {
+        log::LevelFilter::Error => Some(tracing::Level::ERROR),
+        log::LevelFilter::Warn => Some(tracing::Level::WARN),
+        log::LevelFilter::Info => Some(tracing::Level::INFO),
+        log::LevelFilter::Debug => Some(tracing::Level::DEBUG),
+        log::LevelFilter::Trace => Some(tracing::Level::TRACE),
+        log::LevelFilter::Off => None,
+    };
+
+    tracing_level.zip(filter.to_level())
+}
+
 pub use sqlformat;
 
 pub struct QueryLogger<'q> {
@@ -39,37 +92,35 @@ impl<'q> QueryLogger<'q> {
             self.settings.statements_level
         };
 
-        if let Some(lvl) = lvl
-            .to_level()
-            .filter(|lvl| log::log_enabled!(target: "sqlx::query", *lvl))
-        {
-            let mut summary = parse_query_summary(&self.sql);
+        if let Some((tracing_level, log_level)) = private_level_filter_to_levels(lvl) {
+            // The enabled level could be set from either tracing world or log world, so check both
+            // to see if logging should be enabled for our level
+            let log_is_enabled = log::log_enabled!(target: "sqlx::query", log_level)
+                || private_tracing_dynamic_enabled!(target: "sqlx::query", tracing_level);
+            if log_is_enabled {
+                let mut summary = parse_query_summary(&self.sql);
 
-            let sql = if summary != self.sql {
-                summary.push_str(" …");
-                format!(
-                    "\n\n{}\n",
-                    sqlformat::format(
-                        &self.sql,
-                        &sqlformat::QueryParams::None,
-                        sqlformat::FormatOptions::default()
+                let sql = if summary != self.sql {
+                    summary.push_str(" …");
+                    format!(
+                        "\n\n{}\n",
+                        sqlformat::format(
+                            &self.sql,
+                            &sqlformat::QueryParams::None,
+                            sqlformat::FormatOptions::default()
+                        )
                     )
-                )
-            } else {
-                String::new()
-            };
+                } else {
+                    String::new()
+                };
 
-            log::logger().log(
-                &log::Record::builder()
-                    .args(format_args!(
-                        "{}; rows affected: {}, rows returned: {}, elapsed: {:.3?}{}",
-                        summary, self.rows_affected, self.rows_returned, elapsed, sql
-                    ))
-                    .level(lvl)
-                    .module_path_static(Some("sqlx::query"))
-                    .target("sqlx::query")
-                    .build(),
-            );
+                let message = format!(
+                    "{}; rows affected: {}, rows returned: {}, elapsed: {:.3?}{}",
+                    summary, self.rows_affected, self.rows_returned, elapsed, sql
+                );
+
+                private_tracing_dynamic_event!(target: "sqlx::query", tracing_level, message);
+            }
         }
     }
 }

sqlx-core/src/pool/connection.rs

@@ -235,8 +235,8 @@ impl<DB: Database> Floating<DB, Live<DB>> {
                     self.close().await;
                     return false;
                 }
-                Err(e) => {
-                    log::warn!("error from after_release: {}", e);
+                Err(error) => {
+                    tracing::warn!(%error, "error from `after_release`");
                     // Connection is broken, don't try to gracefully close as
                     // something weird might happen.
                     self.close_hard().await;
@@ -252,10 +252,10 @@ impl<DB: Database> Floating<DB, Live<DB>> {
         // returned to the pool; also of course, if it was dropped due to an error
         // this is simply a band-aid as SQLx-next connections should be able
         // to recover from cancellations
-        if let Err(e) = self.raw.ping().await {
-            log::warn!(
-                "error occurred while testing the connection on-release: {}",
-                e
+        if let Err(error) = self.raw.ping().await {
+            tracing::warn!(
+                %error,
+                "error occurred while testing the connection on-release",
             );
 
             // Connection is broken, don't try to gracefully close.
@@ -322,8 +322,8 @@ impl<DB: Database> Floating<DB, Idle<DB>> {
     }
 
     pub async fn close(self) -> DecrementSizeGuard<DB> {
-        if let Err(e) = self.inner.live.raw.close().await {
-            log::debug!("error occurred while closing the pool connection: {}", e);
+        if let Err(error) = self.inner.live.raw.close().await {
+            tracing::debug!(%error, "error occurred while closing the pool connection");
         }
         self.guard
     }

sqlx-core/src/pool/inner.rs

@@ -259,7 +259,7 @@ impl<DB: Database> PoolInner<DB> {
                             guard
                         } else {
                             // This can happen for a child pool that's at its connection limit.
-                            log::debug!("woke but was unable to acquire idle connection or open new one; retrying");
+                            tracing::debug!("woke but was unable to acquire idle connection or open new one; retrying");
                             // If so, we're likely in the current-thread runtime if it's Tokio
                             // and so we should yield to let any spawned release_to_pool() tasks
                             // execute.
@@ -319,8 +319,8 @@ impl<DB: Database> PoolInner<DB> {
 
                     match res {
                         Ok(()) => return Ok(Floating::new_live(raw, guard)),
-                        Err(e) => {
-                            log::error!("error returned from after_connect: {:?}", e);
+                        Err(error) => {
+                            tracing::error!(%error, "error returned from after_connect");
                             // The connection is broken, don't try to close nicely.
                             let _ = raw.close_hard().await;
 
@@ -386,9 +386,9 @@ impl<DB: Database> PoolInner<DB> {
             Ok(()) => (),
             Err(Error::PoolClosed) => (),
             Err(Error::PoolTimedOut) => {
-                log::debug!("unable to complete `min_connections` maintenance before deadline")
+                tracing::debug!("unable to complete `min_connections` maintenance before deadline")
             }
-            Err(e) => log::debug!("error while maintaining min_connections: {:?}", e),
+            Err(error) => tracing::debug!(%error, "error while maintaining min_connections"),
         }
     }
 }
@@ -428,11 +428,11 @@ async fn check_idle_conn<DB: Database>(
 
     if options.test_before_acquire {
         // Check that the connection is still live
-        if let Err(e) = conn.ping().await {
+        if let Err(error) = conn.ping().await {
             // an error here means the other end has hung up or we lost connectivity
             // either way we're fine to just discard the connection
             // the error itself here isn't necessarily unexpected so WARN is too strong
-            log::info!("ping on idle connection returned error: {}", e);
+            tracing::info!(%error, "ping on idle connection returned error");
             // connection is broken so don't try to close nicely
             return Err(conn.close_hard().await);
         }
@@ -447,7 +447,7 @@ async fn check_idle_conn<DB: Database>(
             }
 
             Err(error) => {
-                log::warn!("error from `before_acquire`: {}", error);
+                tracing::warn!(%error, "error from `before_acquire`");
                 // connection is broken so don't try to close nicely
                 return Err(conn.close_hard().await);
             }