From 6efc39f213c641303bae6e6af3475ac9d126c746 Mon Sep 17 00:00:00 2001 From: david-mcgillicuddy-moixa <51170803+david-mcgillicuddy-moixa@users.noreply.github.com> Date: Fri, 8 Apr 2022 20:40:11 +0100 Subject: [PATCH] Include affected rows in logging even when query is done (#1754) * fix logging bug * slight code cleanup * change to split rows affected and rows returned * review comments, and small unreachable bug --- sqlx-core/src/logger.rs | 20 +++++++++++-------- sqlx-core/src/mssql/connection/executor.rs | 10 +++++++--- sqlx-core/src/mssql/protocol/type_info.rs | 8 ++++---- sqlx-core/src/mysql/connection/executor.rs | 6 ++++-- sqlx-core/src/postgres/connection/executor.rs | 6 ++++-- sqlx-core/src/sqlite/connection/execute.rs | 7 +++++-- 6 files changed, 36 insertions(+), 21 deletions(-) diff --git a/sqlx-core/src/logger.rs b/sqlx-core/src/logger.rs index 71255ca46e..6446d14daa 100644 --- a/sqlx-core/src/logger.rs +++ b/sqlx-core/src/logger.rs @@ -3,7 +3,8 @@ use std::time::Instant; pub(crate) struct QueryLogger<'q> { sql: &'q str, - rows: usize, + rows_returned: u64, + rows_affected: u64, start: Instant, settings: LogSettings, } @@ -12,14 +13,19 @@ impl<'q> QueryLogger<'q> { pub(crate) fn new(sql: &'q str, settings: LogSettings) -> Self { Self { sql, - rows: 0, + rows_returned: 0, + rows_affected: 0, start: Instant::now(), settings, } } - pub(crate) fn increment_rows(&mut self) { - self.rows += 1; + pub(crate) fn increment_rows_returned(&mut self) { + self.rows_returned += 1; + } + + pub(crate) fn increase_rows_affected(&mut self, n: u64) { + self.rows_affected += n; } pub(crate) fn finish(&self) { @@ -51,13 +57,11 @@ impl<'q> QueryLogger<'q> { String::new() }; - let rows = self.rows; - log::logger().log( &log::Record::builder() .args(format_args!( - "{}; rows: {}, elapsed: {:.3?}{}", - summary, rows, elapsed, sql + "{}; rows affected: {}, rows returned: {}, elapsed: {:.3?}{}", + summary, self.rows_affected, self.rows_returned, elapsed, sql )) .level(lvl) .module_path_static(Some("sqlx::query")) diff --git a/sqlx-core/src/mssql/connection/executor.rs b/sqlx-core/src/mssql/connection/executor.rs index caa9f6c34c..0c8a2f064d 100644 --- a/sqlx-core/src/mssql/connection/executor.rs +++ b/sqlx-core/src/mssql/connection/executor.rs @@ -92,7 +92,7 @@ impl<'c> Executor<'c> for &'c mut MssqlConnection { let columns = Arc::clone(&self.stream.columns); let column_names = Arc::clone(&self.stream.column_names); - logger.increment_rows(); + logger.increment_rows_returned(); r#yield!(Either::Right(MssqlRow { row, column_names, columns })); } @@ -103,8 +103,10 @@ impl<'c> Executor<'c> for &'c mut MssqlConnection { } if done.status.contains(Status::DONE_COUNT) { + let rows_affected = done.affected_rows; + logger.increase_rows_affected(rows_affected); r#yield!(Either::Left(MssqlQueryResult { - rows_affected: done.affected_rows, + rows_affected, })); } @@ -115,8 +117,10 @@ impl<'c> Executor<'c> for &'c mut MssqlConnection { Message::DoneInProc(done) => { if done.status.contains(Status::DONE_COUNT) { + let rows_affected = done.affected_rows; + logger.increase_rows_affected(rows_affected); r#yield!(Either::Left(MssqlQueryResult { - rows_affected: done.affected_rows, + rows_affected, })); } } diff --git a/sqlx-core/src/mssql/protocol/type_info.rs b/sqlx-core/src/mssql/protocol/type_info.rs index 99a22438c2..3ed7af0ec5 100644 --- a/sqlx-core/src/mssql/protocol/type_info.rs +++ b/sqlx-core/src/mssql/protocol/type_info.rs @@ -498,14 +498,14 @@ impl TypeInfo { 4 => "INT", 8 => "BIGINT", - _ => unreachable!("invalid size {} for int"), + n => unreachable!("invalid size {} for int", n), }, DataType::FloatN => match self.size { 4 => "REAL", 8 => "FLOAT", - _ => unreachable!("invalid size {} for float"), + n => unreachable!("invalid size {} for float", n), }, DataType::VarChar => "VARCHAR", @@ -536,14 +536,14 @@ impl TypeInfo { 4 => "int", 8 => "bigint", - _ => unreachable!("invalid size {} for int"), + n => unreachable!("invalid size {} for int", n), }), DataType::FloatN => s.push_str(match self.size { 4 => "real", 8 => "float", - _ => unreachable!("invalid size {} for float"), + n => unreachable!("invalid size {} for float", n), }), DataType::VarChar diff --git a/sqlx-core/src/mysql/connection/executor.rs b/sqlx-core/src/mysql/connection/executor.rs index 9cb0690bda..8d73794f57 100644 --- a/sqlx-core/src/mysql/connection/executor.rs +++ b/sqlx-core/src/mysql/connection/executor.rs @@ -134,8 +134,10 @@ impl MySqlConnection { // this indicates either a successful query with no rows at all or a failed query let ok = packet.ok()?; + let rows_affected = ok.affected_rows; + logger.increase_rows_affected(rows_affected); let done = MySqlQueryResult { - rows_affected: ok.affected_rows, + rows_affected, last_insert_id: ok.last_insert_id, }; @@ -199,7 +201,7 @@ impl MySqlConnection { column_names: Arc::clone(&column_names), }); - logger.increment_rows(); + logger.increment_rows_returned(); r#yield!(v); } diff --git a/sqlx-core/src/postgres/connection/executor.rs b/sqlx-core/src/postgres/connection/executor.rs index a1e27a6a8b..e3f5b1517e 100644 --- a/sqlx-core/src/postgres/connection/executor.rs +++ b/sqlx-core/src/postgres/connection/executor.rs @@ -278,8 +278,10 @@ impl PgConnection { // a SQL command completed normally let cc: CommandComplete = message.decode()?; + let rows_affected = cc.rows_affected(); + logger.increase_rows_affected(rows_affected); r#yield!(Either::Left(PgQueryResult { - rows_affected: cc.rows_affected(), + rows_affected, })); } @@ -301,7 +303,7 @@ impl PgConnection { } MessageFormat::DataRow => { - logger.increment_rows(); + logger.increment_rows_returned(); // one of the set of rows returned by a SELECT, FETCH, etc query let data: DataRow = message.decode()?; diff --git a/sqlx-core/src/sqlite/connection/execute.rs b/sqlx-core/src/sqlite/connection/execute.rs index f8982bab4b..a5d6fb3e58 100644 --- a/sqlx-core/src/sqlite/connection/execute.rs +++ b/sqlx-core/src/sqlite/connection/execute.rs @@ -85,7 +85,7 @@ impl Iterator for ExecuteIter<'_> { match statement.handle.step() { Ok(true) => { - self.logger.increment_rows(); + self.logger.increment_rows_returned(); Some(Ok(Either::Right(SqliteRow::current( &statement.handle, @@ -96,8 +96,11 @@ impl Iterator for ExecuteIter<'_> { Ok(false) => { let last_insert_rowid = self.handle.last_insert_rowid(); + let changes = statement.handle.changes(); + self.logger.increase_rows_affected(changes); + let done = SqliteQueryResult { - changes: statement.handle.changes(), + changes, last_insert_rowid, };