From e321b5cb75eadfcc84063470a989f7985c48fa89 Mon Sep 17 00:00:00 2001 From: CosmicHorror Date: Fri, 10 Feb 2023 18:35:12 -0700 Subject: [PATCH] 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 --- Cargo.lock | 4 + sqlx-core/Cargo.toml | 1 + sqlx-core/src/logger.rs | 111 ++++++++++++++++++------- sqlx-core/src/pool/connection.rs | 16 ++-- sqlx-core/src/pool/inner.rs | 16 ++-- sqlx-mysql/Cargo.toml | 1 + sqlx-mysql/src/connection/tls.rs | 4 +- sqlx-postgres/Cargo.toml | 1 + sqlx-postgres/src/advisory_lock.rs | 14 ++-- sqlx-postgres/src/connection/stream.rs | 43 ++++++---- sqlx-postgres/src/options/parse.rs | 2 +- sqlx-postgres/src/options/pgpass.rs | 10 +-- sqlx-sqlite/Cargo.toml | 1 + sqlx-sqlite/src/connection/describe.rs | 4 +- sqlx-sqlite/src/connection/worker.rs | 8 +- sqlx-sqlite/src/logger.rs | 70 ++++++++-------- 16 files changed, 185 insertions(+), 121 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index b9233fcb0d..4738340651 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -2993,6 +2993,7 @@ dependencies = [ "time 0.3.17", "tokio", "tokio-stream", + "tracing", "url", "uuid", "webpki-roots", @@ -3164,6 +3165,7 @@ dependencies = [ "stringprep", "thiserror", "time 0.3.17", + "tracing", "uuid", "whoami", ] @@ -3208,6 +3210,7 @@ dependencies = [ "stringprep", "thiserror", "time 0.3.17", + "tracing", "uuid", "whoami", ] @@ -3231,6 +3234,7 @@ dependencies = [ "serde", "sqlx-core", "time 0.3.17", + "tracing", "url", "uuid", ] diff --git a/sqlx-core/Cargo.toml b/sqlx-core/Cargo.toml index 8aa4080287..f220c55dd8 100644 --- a/sqlx-core/Cargo.toml +++ b/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 } diff --git a/sqlx-core/src/logger.rs b/sqlx-core/src/logger.rs index ec2175233d..7f9a8ed4ae 100644 --- a/sqlx-core/src/logger.rs +++ b/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); + } } } } diff --git a/sqlx-core/src/pool/connection.rs b/sqlx-core/src/pool/connection.rs index 8f1eded132..9bd0ebb85b 100644 --- a/sqlx-core/src/pool/connection.rs +++ b/sqlx-core/src/pool/connection.rs @@ -235,8 +235,8 @@ impl Floating> { 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 Floating> { // 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 Floating> { } pub async fn close(self) -> DecrementSizeGuard { - 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 } diff --git a/sqlx-core/src/pool/inner.rs b/sqlx-core/src/pool/inner.rs index 589d56145e..ceb4977998 100644 --- a/sqlx-core/src/pool/inner.rs +++ b/sqlx-core/src/pool/inner.rs @@ -259,7 +259,7 @@ impl PoolInner { 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 PoolInner { 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 PoolInner { 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( 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( } 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); } diff --git a/sqlx-mysql/Cargo.toml b/sqlx-mysql/Cargo.toml index 5a1713bc49..7347839645 100644 --- a/sqlx-mysql/Cargo.toml +++ b/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 } diff --git a/sqlx-mysql/src/connection/tls.rs b/sqlx-mysql/src/connection/tls.rs index 883fbcadad..b8cb05c9d3 100644 --- a/sqlx-mysql/src/connection/tls.rs +++ b/sqlx-mysql/src/connection/tls.rs @@ -35,13 +35,13 @@ pub(super) async fn maybe_upgrade( 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()); } } diff --git a/sqlx-postgres/Cargo.toml b/sqlx-postgres/Cargo.toml index 0c9bf4b5d1..9e6d083883 100644 --- a/sqlx-postgres/Cargo.toml +++ b/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"] } diff --git a/sqlx-postgres/src/advisory_lock.rs b/sqlx-postgres/src/advisory_lock.rs index 32e3d742ae..f5684d41f9 100644 --- a/sqlx-postgres/src/advisory_lock.rs +++ b/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> 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", ); } diff --git a/sqlx-postgres/src/connection/stream.rs b/sqlx-postgres/src/connection/stream.rs index 96e33a3150..0bf814fbde 100644 --- a/sqlx-postgres/src/connection/stream.rs +++ b/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 ); } diff --git a/sqlx-postgres/src/options/parse.rs b/sqlx-postgres/src/options/parse.rs index 501e5b52c2..e837a95019 100644 --- a/sqlx-postgres/src/options/parse.rs +++ b/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"), } } diff --git a/sqlx-postgres/src/options/pgpass.rs b/sqlx-postgres/src/options/pgpass.rs index 831020f1c7..6b0a4092d9 100644 --- a/sqlx-postgres/src/options/pgpass.rs +++ b/sqlx-postgres/src/options/pgpass.rs @@ -47,10 +47,10 @@ fn load_password_from_file( let permissions = metadata.permissions(); let mode = permissions.mode(); if mode & 0o77 != 0 { - log::warn!( - "ignoring {}: permissions for not strict enough: {:o}", - path.to_string_lossy(), - mode + tracing::warn!( + path = %path.to_string_lossy(), + permissions = format!("{:o}", mode), + "Ignoring path. Permissions are not strict enough", ); return None; } @@ -136,7 +136,7 @@ fn matches_next_field(whole_line: &str, line: &mut &str, value: &str) -> Option< } } None => { - log::warn!("Malformed line in pgpass file: {}", whole_line); + tracing::warn!(line = whole_line, "Malformed line in pgpass file"); None } } diff --git a/sqlx-sqlite/Cargo.toml b/sqlx-sqlite/Cargo.toml index b0a3ec4dfa..e5749192f8 100644 --- a/sqlx-sqlite/Cargo.toml +++ b/sqlx-sqlite/Cargo.toml @@ -41,6 +41,7 @@ flume = { version = "0.10.9", default-features = false, features = ["async"] } atoi = "1.0" log = "0.4.17" +tracing = { version = "0.1.37", features = ["log"] } serde = { version = "1.0.145", features = ["derive"], optional = true } diff --git a/sqlx-sqlite/src/connection/describe.rs b/sqlx-sqlite/src/connection/describe.rs index 4d35be3446..0f4da33ccc 100644 --- a/sqlx-sqlite/src/connection/describe.rs +++ b/sqlx-sqlite/src/connection/describe.rs @@ -40,8 +40,8 @@ pub(crate) fn describe(conn: &mut ConnectionState, query: &str) -> Result v, - Err(err) => { - log::debug!("describe: explain introspection failed: {}", err); + Err(error) => { + tracing::debug!(%error, "describe: explain introspection failed"); (vec![], vec![]) } diff --git a/sqlx-sqlite/src/connection/worker.rs b/sqlx-sqlite/src/connection/worker.rs index c44770b432..b7f5ef5a0e 100644 --- a/sqlx-sqlite/src/connection/worker.rs +++ b/sqlx-sqlite/src/connection/worker.rs @@ -175,7 +175,7 @@ impl ConnectionWorker { // `Transaction` was created and so there is no way to commit / // rollback this transaction. We need to roll it back // immediately otherwise it would remain started forever. - if let Err(e) = conn + if let Err(error) = conn .handle .exec(rollback_ansi_transaction_sql(depth + 1)) .map(|_| { @@ -185,7 +185,7 @@ impl ConnectionWorker { // The rollback failed. To prevent leaving the connection // in an inconsistent state we shutdown this worker which // causes any subsequent operation on the connection to fail. - log::error!("failed to rollback cancelled transaction: {}", e); + tracing::error!(%error, "failed to rollback cancelled transaction"); break; } } @@ -242,8 +242,8 @@ impl ConnectionWorker { } } Command::CreateCollation { create_collation } => { - if let Err(e) = (create_collation)(&mut conn) { - log::warn!("error applying collation in background worker: {}", e); + if let Err(error) = (create_collation)(&mut conn) { + tracing::warn!(%error, "error applying collation in background worker"); } } Command::ClearCache { tx } => { diff --git a/sqlx-sqlite/src/logger.rs b/sqlx-sqlite/src/logger.rs index 85fcde102c..d605ea13a8 100644 --- a/sqlx-sqlite/src/logger.rs +++ b/sqlx-sqlite/src/logger.rs @@ -1,4 +1,4 @@ -use sqlx_core::connection::LogSettings; +use sqlx_core::{connection::LogSettings, logger}; use std::collections::HashSet; use std::fmt::Debug; use std::hash::Hash; @@ -25,15 +25,13 @@ impl<'q, O: Debug + Hash + Eq, R: Debug, P: Debug> QueryPlanLogger<'q, O, R, P> } pub fn log_enabled(&self) -> bool { - if let Some(_lvl) = self - .settings - .statements_level - .to_level() - .filter(|lvl| log::log_enabled!(target: "sqlx::explain", *lvl)) + if let Some((tracing_level, log_level)) = + logger::private_level_filter_to_levels(self.settings.statements_level) { - return true; + log::log_enabled!(log_level) + || sqlx_core::private_tracing_dynamic_enabled!(tracing_level) } else { - return false; + false } } @@ -48,37 +46,37 @@ impl<'q, O: Debug + Hash + Eq, R: Debug, P: Debug> QueryPlanLogger<'q, O, R, P> pub fn finish(&self) { let lvl = self.settings.statements_level; - if let Some(lvl) = lvl - .to_level() - .filter(|lvl| log::log_enabled!(target: "sqlx::explain", *lvl)) - { - let mut summary = parse_query_summary(&self.sql); + if let Some((tracing_level, log_level)) = logger::private_level_filter_to_levels(lvl) { + let log_is_enabled = log::log_enabled!(target: "sqlx::explain", log_level) + || private_tracing_dynamic_enabled!(target: "sqlx::explain", 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() + }; + + let message = format!( + "{}; program:{:?}, unknown_operations:{:?}, results: {:?}{}", + summary, self.program, self.unknown_operations, self.results, sql + ); - log::logger().log( - &log::Record::builder() - .args(format_args!( - "{}; program:{:?}, unknown_operations:{:?}, results: {:?}{}", - summary, self.program, self.unknown_operations, self.results, sql - )) - .level(lvl) - .module_path_static(Some("sqlx::explain")) - .target("sqlx::explain") - .build(), - ); + sqlx_core::private_tracing_dynamic_event!( + target: "sqlx::explain", + tracing_level, + message, + ); + } } } }