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
launchbadge · Apr 8, 2022 · 6efc39f · 6efc39f
1 parent 0c95fdd
commit 6efc39f
Show file tree

Hide file tree

Showing 6 changed files with 36 additions and 21 deletions.
diff --git 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
@@ -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
@@ -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
@@ -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
@@ -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
@@ -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,
                 };