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);
-
-            let sql = if summary != self.sql {
-                summary.push_str(" …");
-                format!(
-                    "\n\n{}\n",
-                    sqlformat::format(
-                        &self.sql,
-                        &sqlformat::QueryParams::None,
-                        sqlformat::FormatOptions::default()
+        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()
+                        )
                     )
-                )
-            } 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(),
-            );
+                } else {
+                    String::new()
+                };
+
+                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);
             }

sqlx-mysql/Cargo.toml

@@ -60,6 +60,7 @@ percent-encoding = "2.1.0"
 smallvec = "1.7.0"
 stringprep = "0.1.2"
 thiserror = "1.0.35"
+tracing = { version = "0.1.37", features = ["log"] }
 whoami = "1.2.1"
 
 serde = { version = "1.0.144", optional = true }

sqlx-mysql/src/connection/tls.rs

@@ -35,13 +35,13 @@ pub(super) async fn maybe_upgrade<S: Socket>(
         MySqlSslMode::Preferred => {
             if !tls::available() {
                 // Client doesn't support TLS
-                log::debug!("not performing TLS upgrade: TLS support not compiled in");
+                tracing::debug!("not performing TLS upgrade: TLS support not compiled in");
                 return Ok(stream.boxed_socket());
             }
 
             if !server_supports_tls {
                 // Server doesn't support TLS
-                log::debug!("not performing TLS upgrade: unsupported by server");
+                tracing::debug!("not performing TLS upgrade: unsupported by server");
                 return Ok(stream.boxed_socket());
             }
         }

sqlx-postgres/Cargo.toml

@@ -61,6 +61,7 @@ once_cell = "1.9.0"
 smallvec = "1.7.0"
 stringprep = "0.1.2"
 thiserror = "1.0.35"
+tracing = { version = "0.1.37", features = ["log"] }
 whoami = "1.2.1"
 
 serde = { version = "1.0.144", features = ["derive"] }

sqlx-postgres/src/advisory_lock.rs

@@ -151,10 +151,10 @@ impl PgAdvisoryLock {
         // architecture for server software, so it should be a no-op there.
         let key = PgAdvisoryLockKey::BigInt(i64::from_le_bytes(output_key_material));
 
-        log::trace!(
-            "generated {:?} from key string {:?}",
-            key,
-            input_key_material
+        tracing::trace!(
+            ?key,
+            key_string = ?input_key_material,
+            "generated key from key string",
         );
 
         Self::with_key(key)
@@ -346,9 +346,9 @@ impl<'lock, C: AsMut<PgConnection>> PgAdvisoryLockGuard<'lock, C> {
             .await?;
 
         if !released {
-            log::warn!(
-                "PgAdvisoryLockGuard: advisory lock {:?} was not held by the contained connection",
-                self.lock.key
+            tracing::warn!(
+                lock = ?self.lock.key,
+                "PgAdvisoryLockGuard: advisory lock was not held by the contained connection",
             );
         }
 

sqlx-postgres/src/connection/stream.rs

@@ -5,7 +5,10 @@ use std::str::FromStr;
 use futures_channel::mpsc::UnboundedSender;
 use futures_util::SinkExt;
 use log::Level;
-use sqlx_core::bytes::{Buf, Bytes};
+use sqlx_core::{
+    bytes::{Buf, Bytes},
+    logger,
+};
 
 use crate::connection::tls::MaybeUpgradeTls;
 use crate::error::Error;
@@ -141,25 +144,29 @@ impl PgStream {
 
                     let notice: Notice = message.decode()?;
 
-                    let lvl = match notice.severity() {
-                        PgSeverity::Fatal | PgSeverity::Panic | PgSeverity::Error => Level::Error,
-                        PgSeverity::Warning => Level::Warn,
-                        PgSeverity::Notice => Level::Info,
-                        PgSeverity::Debug => Level::Debug,
-                        PgSeverity::Info => Level::Trace,
-                        PgSeverity::Log => Level::Trace,
+                    let (log_level, tracing_level) = match notice.severity() {
+                        PgSeverity::Fatal | PgSeverity::Panic | PgSeverity::Error => {
+                            (Level::Error, tracing::Level::ERROR)
+                        }
+                        PgSeverity::Warning => (Level::Warn, tracing::Level::WARN),
+                        PgSeverity::Notice => (Level::Info, tracing::Level::INFO),
+                        PgSeverity::Debug => (Level::Debug, tracing::Level::DEBUG),
+                        PgSeverity::Info | PgSeverity::Log => (Level::Trace, tracing::Level::TRACE),
                     };
 
-                    if log::log_enabled!(target: "sqlx::postgres::notice", lvl) {
-                        log::logger().log(
-                            &log::Record::builder()
-                                .args(format_args!("{}", notice.message()))
-                                .level(lvl)
-                                .module_path_static(Some("sqlx::postgres::notice"))
-                                .target("sqlx::postgres::notice")
-                                .file_static(Some(file!()))
-                                .line(Some(line!()))
-                                .build(),
+                    let log_is_enabled = log::log_enabled!(
+                        target: "sqlx::postgres::notice",
+                        log_level
+                    ) || sqlx_core::private_tracing_dynamic_enabled!(
+                        target: "sqlx::postgres::notice",
+                        tracing_level
+                    );
+                    if log_is_enabled {
+                        let message = format!("{}", notice.message());
+                        sqlx_core::private_tracing_dynamic_event!(
+                            target: "sqlx::postgres::notice",
+                            tracing_level,
+                            message
                         );
                     }
 

sqlx-postgres/src/options/parse.rs

@@ -96,7 +96,7 @@ impl PgConnectOptions {
                     }
                 }
 
-                _ => log::warn!("ignoring unrecognized connect parameter: {}={}", key, value),
+                _ => tracing::warn!(%key, %value, "ignoring unrecognized connect parameter"),
             }
         }