use bb8 error sink to log more errors (#3232)

nexus/db-queries/src/db/collection_attach.rs

@@ -854,7 +854,7 @@ mod test {
             dev::test_setup_log("test_attach_missing_collection_fails");
         let mut db = test_setup_database(&logctx.log).await;
         let cfg = db::Config { url: db.pg_config().clone() };
-        let pool = db::Pool::new(&cfg);
+        let pool = db::Pool::new(&logctx.log, &cfg);
 
         setup_db(&pool).await;
 
@@ -883,7 +883,7 @@ mod test {
         let logctx = dev::test_setup_log("test_attach_missing_resource_fails");
         let mut db = test_setup_database(&logctx.log).await;
         let cfg = db::Config { url: db.pg_config().clone() };
-        let pool = db::Pool::new(&cfg);
+        let pool = db::Pool::new(&logctx.log, &cfg);
 
         setup_db(&pool).await;
 
@@ -920,7 +920,7 @@ mod test {
         let logctx = dev::test_setup_log("test_attach_once");
         let mut db = test_setup_database(&logctx.log).await;
         let cfg = db::Config { url: db.pg_config().clone() };
-        let pool = db::Pool::new(&cfg);
+        let pool = db::Pool::new(&logctx.log, &cfg);
 
         setup_db(&pool).await;
 
@@ -968,7 +968,7 @@ mod test {
         let logctx = dev::test_setup_log("test_attach_once_synchronous");
         let mut db = test_setup_database(&logctx.log).await;
         let cfg = db::Config { url: db.pg_config().clone() };
-        let pool = db::Pool::new(&cfg);
+        let pool = db::Pool::new(&logctx.log, &cfg);
 
         setup_db(&pool).await;
 
@@ -1028,7 +1028,7 @@ mod test {
         let logctx = dev::test_setup_log("test_attach_multiple_times");
         let mut db = test_setup_database(&logctx.log).await;
         let cfg = db::Config { url: db.pg_config().clone() };
-        let pool = db::Pool::new(&cfg);
+        let pool = db::Pool::new(&logctx.log, &cfg);
 
         setup_db(&pool).await;
 
@@ -1084,7 +1084,7 @@ mod test {
         let logctx = dev::test_setup_log("test_attach_beyond_capacity_fails");
         let mut db = test_setup_database(&logctx.log).await;
         let cfg = db::Config { url: db.pg_config().clone() };
-        let pool = db::Pool::new(&cfg);
+        let pool = db::Pool::new(&logctx.log, &cfg);
 
         setup_db(&pool).await;
 
@@ -1148,7 +1148,7 @@ mod test {
         let logctx = dev::test_setup_log("test_attach_while_already_attached");
         let mut db = test_setup_database(&logctx.log).await;
         let cfg = db::Config { url: db.pg_config().clone() };
-        let pool = db::Pool::new(&cfg);
+        let pool = db::Pool::new(&logctx.log, &cfg);
 
         setup_db(&pool).await;
 
@@ -1255,7 +1255,7 @@ mod test {
         let logctx = dev::test_setup_log("test_attach_once");
         let mut db = test_setup_database(&logctx.log).await;
         let cfg = db::Config { url: db.pg_config().clone() };
-        let pool = db::Pool::new(&cfg);
+        let pool = db::Pool::new(&logctx.log, &cfg);
 
         setup_db(&pool).await;
 
@@ -1310,7 +1310,7 @@ mod test {
         let logctx = dev::test_setup_log("test_attach_deleted_resource_fails");
         let mut db = test_setup_database(&logctx.log).await;
         let cfg = db::Config { url: db.pg_config().clone() };
-        let pool = db::Pool::new(&cfg);
+        let pool = db::Pool::new(&logctx.log, &cfg);
 
         setup_db(&pool).await;
 
@@ -1355,7 +1355,7 @@ mod test {
         let logctx = dev::test_setup_log("test_attach_without_update_filter");
         let mut db = test_setup_database(&logctx.log).await;
         let cfg = db::Config { url: db.pg_config().clone() };
-        let pool = db::Pool::new(&cfg);
+        let pool = db::Pool::new(&logctx.log, &cfg);
 
         setup_db(&pool).await;
 

nexus/db-queries/src/db/collection_detach.rs

@@ -775,7 +775,7 @@ mod test {
             dev::test_setup_log("test_detach_missing_collection_fails");
         let mut db = test_setup_database(&logctx.log).await;
         let cfg = db::Config { url: db.pg_config().clone() };
-        let pool = db::Pool::new(&cfg);
+        let pool = db::Pool::new(&logctx.log, &cfg);
 
         setup_db(&pool).await;
 
@@ -803,7 +803,7 @@ mod test {
         let logctx = dev::test_setup_log("test_detach_missing_resource_fails");
         let mut db = test_setup_database(&logctx.log).await;
         let cfg = db::Config { url: db.pg_config().clone() };
-        let pool = db::Pool::new(&cfg);
+        let pool = db::Pool::new(&logctx.log, &cfg);
 
         setup_db(&pool).await;
 
@@ -839,7 +839,7 @@ mod test {
         let logctx = dev::test_setup_log("test_detach_once");
         let mut db = test_setup_database(&logctx.log).await;
         let cfg = db::Config { url: db.pg_config().clone() };
-        let pool = db::Pool::new(&cfg);
+        let pool = db::Pool::new(&logctx.log, &cfg);
 
         setup_db(&pool).await;
 
@@ -879,7 +879,7 @@ mod test {
         let logctx = dev::test_setup_log("test_detach_while_already_detached");
         let mut db = test_setup_database(&logctx.log).await;
         let cfg = db::Config { url: db.pg_config().clone() };
-        let pool = db::Pool::new(&cfg);
+        let pool = db::Pool::new(&logctx.log, &cfg);
 
         setup_db(&pool).await;
 
@@ -943,7 +943,7 @@ mod test {
         let logctx = dev::test_setup_log("test_detach_deleted_resource_fails");
         let mut db = test_setup_database(&logctx.log).await;
         let cfg = db::Config { url: db.pg_config().clone() };
-        let pool = db::Pool::new(&cfg);
+        let pool = db::Pool::new(&logctx.log, &cfg);
 
         setup_db(&pool).await;
 
@@ -987,7 +987,7 @@ mod test {
         let logctx = dev::test_setup_log("test_detach_without_update_filter");
         let mut db = test_setup_database(&logctx.log).await;
         let cfg = db::Config { url: db.pg_config().clone() };
-        let pool = db::Pool::new(&cfg);
+        let pool = db::Pool::new(&logctx.log, &cfg);
 
         setup_db(&pool).await;
 

nexus/db-queries/src/db/collection_detach_many.rs

@@ -773,7 +773,7 @@ mod test {
             dev::test_setup_log("test_detach_missing_collection_fails");
         let mut db = test_setup_database(&logctx.log).await;
         let cfg = db::Config { url: db.pg_config().clone() };
-        let pool = db::Pool::new(&cfg);
+        let pool = db::Pool::new(&logctx.log, &cfg);
 
         setup_db(&pool).await;
 
@@ -803,7 +803,7 @@ mod test {
             dev::test_setup_log("test_detach_missing_resource_succeeds");
         let mut db = test_setup_database(&logctx.log).await;
         let cfg = db::Config { url: db.pg_config().clone() };
-        let pool = db::Pool::new(&cfg);
+        let pool = db::Pool::new(&logctx.log, &cfg);
 
         setup_db(&pool).await;
 
@@ -844,7 +844,7 @@ mod test {
         let logctx = dev::test_setup_log("test_detach_once");
         let mut db = test_setup_database(&logctx.log).await;
         let cfg = db::Config { url: db.pg_config().clone() };
-        let pool = db::Pool::new(&cfg);
+        let pool = db::Pool::new(&logctx.log, &cfg);
 
         setup_db(&pool).await;
 
@@ -887,7 +887,7 @@ mod test {
         let logctx = dev::test_setup_log("test_detach_once_synchronous");
         let mut db = test_setup_database(&logctx.log).await;
         let cfg = db::Config { url: db.pg_config().clone() };
-        let pool = db::Pool::new(&cfg);
+        let pool = db::Pool::new(&logctx.log, &cfg);
 
         setup_db(&pool).await;
 
@@ -942,7 +942,7 @@ mod test {
         let logctx = dev::test_setup_log("test_detach_while_already_detached");
         let mut db = test_setup_database(&logctx.log).await;
         let cfg = db::Config { url: db.pg_config().clone() };
-        let pool = db::Pool::new(&cfg);
+        let pool = db::Pool::new(&logctx.log, &cfg);
 
         setup_db(&pool).await;
 
@@ -998,7 +998,7 @@ mod test {
         let logctx = dev::test_setup_log("test_detach_filter_collection");
         let mut db = test_setup_database(&logctx.log).await;
         let cfg = db::Config { url: db.pg_config().clone() };
-        let pool = db::Pool::new(&cfg);
+        let pool = db::Pool::new(&logctx.log, &cfg);
 
         setup_db(&pool).await;
 
@@ -1049,7 +1049,7 @@ mod test {
         let logctx = dev::test_setup_log("test_detach_deleted_resource");
         let mut db = test_setup_database(&logctx.log).await;
         let cfg = db::Config { url: db.pg_config().clone() };
-        let pool = db::Pool::new(&cfg);
+        let pool = db::Pool::new(&logctx.log, &cfg);
 
         setup_db(&pool).await;
 
@@ -1107,7 +1107,7 @@ mod test {
         let logctx = dev::test_setup_log("test_detach_many");
         let mut db = test_setup_database(&logctx.log).await;
         let cfg = db::Config { url: db.pg_config().clone() };
-        let pool = db::Pool::new(&cfg);
+        let pool = db::Pool::new(&logctx.log, &cfg);
 
         setup_db(&pool).await;
 

nexus/db-queries/src/db/collection_insert.rs

@@ -548,7 +548,7 @@ mod test {
         let logctx = dev::test_setup_log("test_collection_not_present");
         let mut db = test_setup_database(&logctx.log).await;
         let cfg = db::Config { url: db.pg_config().clone() };
-        let pool = db::Pool::new(&cfg);
+        let pool = db::Pool::new(&logctx.log, &cfg);
 
         setup_db(&pool).await;
 
@@ -578,7 +578,7 @@ mod test {
         let logctx = dev::test_setup_log("test_collection_present");
         let mut db = test_setup_database(&logctx.log).await;
         let cfg = db::Config { url: db.pg_config().clone() };
-        let pool = db::Pool::new(&cfg);
+        let pool = db::Pool::new(&logctx.log, &cfg);
 
         setup_db(&pool).await;
 

nexus/db-queries/src/db/datastore/mod.rs

@@ -244,7 +244,7 @@ pub async fn datastore_test(
     use crate::authn;
 
     let cfg = db::Config { url: db.pg_config().clone() };
-    let pool = Arc::new(db::Pool::new(&cfg));
+    let pool = Arc::new(db::Pool::new(&logctx.log, &cfg));
     let datastore = Arc::new(DataStore::new(pool));
 
     // Create an OpContext with the credentials of "db-init" just for the
@@ -895,7 +895,7 @@ mod test {
             dev::test_setup_log("test_queries_do_not_require_full_table_scan");
         let mut db = test_setup_database(&logctx.log).await;
         let cfg = db::Config { url: db.pg_config().clone() };
-        let pool = db::Pool::new(&cfg);
+        let pool = db::Pool::new(&logctx.log, &cfg);
         let datastore = DataStore::new(Arc::new(pool));
 
         let explanation = DataStore::get_allocated_regions_query(Uuid::nil())
@@ -944,7 +944,7 @@ mod test {
         let logctx = dev::test_setup_log("test_sled_ipv6_address_allocation");
         let mut db = test_setup_database(&logctx.log).await;
         let cfg = db::Config { url: db.pg_config().clone() };
-        let pool = Arc::new(db::Pool::new(&cfg));
+        let pool = Arc::new(db::Pool::new(&logctx.log, &cfg));
         let datastore = Arc::new(DataStore::new(Arc::clone(&pool)));
         let opctx =
             OpContext::for_tests(logctx.log.new(o!()), datastore.clone());

nexus/db-queries/src/db/explain.rs

@@ -166,7 +166,7 @@ mod test {
         let logctx = dev::test_setup_log("test_explain_async");
         let mut db = test_setup_database(&logctx.log).await;
         let cfg = db::Config { url: db.pg_config().clone() };
-        let pool = db::Pool::new(&cfg);
+        let pool = db::Pool::new(&logctx.log, &cfg);
 
         create_schema(&pool).await;
 
@@ -189,7 +189,7 @@ mod test {
         let logctx = dev::test_setup_log("test_explain_full_table_scan");
         let mut db = test_setup_database(&logctx.log).await;
         let cfg = db::Config { url: db.pg_config().clone() };
-        let pool = db::Pool::new(&cfg);
+        let pool = db::Pool::new(&logctx.log, &cfg);
 
         create_schema(&pool).await;
 

nexus/db-queries/src/db/pagination.rs

@@ -263,7 +263,7 @@ mod test {
             dev::test_setup_log("test_paginated_single_column_ascending");
         let mut db = test_setup_database(&logctx.log).await;
         let cfg = db::Config { url: db.pg_config().clone() };
-        let pool = db::Pool::new(&cfg);
+        let pool = db::Pool::new(&logctx.log, &cfg);
 
         use schema::test_users::dsl;
 
@@ -298,7 +298,7 @@ mod test {
             dev::test_setup_log("test_paginated_single_column_descending");
         let mut db = test_setup_database(&logctx.log).await;
         let cfg = db::Config { url: db.pg_config().clone() };
-        let pool = db::Pool::new(&cfg);
+        let pool = db::Pool::new(&logctx.log, &cfg);
 
         use schema::test_users::dsl;
 
@@ -333,7 +333,7 @@ mod test {
             dev::test_setup_log("test_paginated_multicolumn_ascending");
         let mut db = test_setup_database(&logctx.log).await;
         let cfg = db::Config { url: db.pg_config().clone() };
-        let pool = db::Pool::new(&cfg);
+        let pool = db::Pool::new(&logctx.log, &cfg);
 
         use schema::test_users::dsl;
 
@@ -387,7 +387,7 @@ mod test {
             dev::test_setup_log("test_paginated_multicolumn_descending");
         let mut db = test_setup_database(&logctx.log).await;
         let cfg = db::Config { url: db.pg_config().clone() };
-        let pool = db::Pool::new(&cfg);
+        let pool = db::Pool::new(&logctx.log, &cfg);
 
         use schema::test_users::dsl;
 

nexus/db-queries/src/db/pool.rs

@@ -44,21 +44,38 @@ pub struct Pool {
 }
 
 impl Pool {
-    pub fn new(db_config: &DbConfig) -> Self {
-        let manager =
-            ConnectionManager::<DbConnection>::new(&db_config.url.url());
-        let pool = bb8::Builder::new()
-            .connection_customizer(Box::new(DisallowFullTableScans {}))
-            .build_unchecked(manager);
-        Pool { pool }
+    pub fn new(log: &slog::Logger, db_config: &DbConfig) -> Self {
+        Self::new_builder(log, db_config, bb8::Builder::new())
+    }
+
+    pub fn new_failfast_for_tests(
+        log: &slog::Logger,
+        db_config: &DbConfig,
+    ) -> Self {
+        Self::new_builder(
+            log,
+            db_config,
+            bb8::Builder::new()
+                .connection_timeout(std::time::Duration::from_millis(1)),
+        )
     }
 
-    pub fn new_failfast_for_tests(db_config: &DbConfig) -> Self {
-        let manager =
-            ConnectionManager::<DbConnection>::new(&db_config.url.url());
-        let pool = bb8::Builder::new()
+    fn new_builder(
+        log: &slog::Logger,
+        db_config: &DbConfig,
+        builder: bb8::Builder<ConnectionManager<DbConnection>>,
+    ) -> Self {
+        let url = db_config.url.url();
+        let log = log.new(o!(
+            "database_url" => url.clone(),
+            "component" => "db::Pool"
+        ));
+        info!(&log, "database connection pool");
+        let error_sink = LoggingErrorSink::new(log);
+        let manager = ConnectionManager::<DbConnection>::new(url);
+        let pool = builder
             .connection_customizer(Box::new(DisallowFullTableScans {}))
-            .connection_timeout(std::time::Duration::from_millis(1))
+            .error_sink(Box::new(error_sink))
             .build_unchecked(manager);
         Pool { pool }
     }
@@ -85,3 +102,28 @@ impl CustomizeConnection<Connection<DbConnection>, ConnectionError>
         conn.batch_execute_async(DISALLOW_FULL_TABLE_SCAN_SQL).await
     }
 }
+
+#[derive(Clone, Debug)]
+struct LoggingErrorSink {
+    log: slog::Logger,
+}
+
+impl LoggingErrorSink {
+    fn new(log: slog::Logger) -> LoggingErrorSink {
+        LoggingErrorSink { log }
+    }
+}
+
+impl bb8::ErrorSink<ConnectionError> for LoggingErrorSink {
+    fn sink(&self, error: ConnectionError) {
+        error!(
+            &self.log,
+            "database connection error";
+            "error_message" => #%error
+        );
+    }
+
+    fn boxed_clone(&self) -> Box<dyn bb8::ErrorSink<ConnectionError>> {
+        Box::new(self.clone())
+    }
+}