debug: log more

Author: lutter

.github/workflows/ci.yml

@@ -69,7 +69,7 @@ jobs:
           POSTGRES_PASSWORD: postgres
           POSTGRES_DB: graph_node_test
           POSTGRES_INITDB_ARGS: "-E UTF8 --locale=C"
-          POSTGRESQL_EXTRA_FLAGS: "-c max_connections=1000"
+          POSTGRESQL_EXTRA_FLAGS: "-c max_connections=1000 -c log_statement=all"
           POSTGRESQL_REPLICATION_USE_PASSFILE: no
         options: >-
           --health-cmd "pg_isready -U postgres"

store/postgres/src/connection_pool.rs

@@ -1,10 +1,11 @@
 use diesel::r2d2::Builder;
+use diesel::sql_types::Text;
 use diesel::{connection::SimpleConnection, pg::PgConnection};
 use diesel::{
     r2d2::{self, event as e, ConnectionManager, HandleEvent, Pool, PooledConnection},
     Connection,
 };
-use diesel::{sql_query, RunQueryDsl};
+use diesel::{sql_query, OptionalExtension, RunQueryDsl};
 
 use diesel_migrations::{EmbeddedMigrations, HarnessWithOutput};
 use graph::cheap_clone::CheapClone;
@@ -380,13 +381,18 @@ impl PoolState {
 
             use PoolStateInner::*;
             match &*guard {
-                Created(pool, coord) => (pool.cheap_clone(), coord.cheap_clone()),
+                Created(pool, coord) => {
+                    warn!(self.logger, "pool_state: pool not ready; creating");
+                    (pool.cheap_clone(), coord.cheap_clone())
+                }
                 Ready(pool) => return Ok(pool.clone()),
             }
         };
 
         // self is `Created` and needs to have setup run
+        warn!(self.logger, "pool_state: setting up pool");
         let migrated = coord.setup_bg(self.cheap_clone())?;
+        warn!(self.logger, "pool_state: pool is ready");
         if migrated {
             Ok(pool)
         } else {
@@ -1329,6 +1335,7 @@ impl PoolInner {
 
 pub const MIGRATIONS: EmbeddedMigrations = embed_migrations!("./migrations");
 
+#[derive(Debug)]
 struct MigrationCount {
     old: usize,
     new: usize,
@@ -1377,11 +1384,13 @@ fn migrate_schema(logger: &Logger, conn: &mut PgConnection) -> Result<MigrationC
     }
 
     let migrations = catalog::migration_count(conn)?;
-    if migrations != old_count {
-        // Reset the query statistics since a schema change makes them not
-        // all that useful. An error here is not serious and can be ignored.
-        conn.batch_execute("select pg_stat_statements_reset()").ok();
-    }
+    /*
+        if migrations != old_count {
+            // Reset the query statistics since a schema change makes them not
+            // all that useful. An error here is not serious and can be ignored.
+            conn.batch_execute("select pg_stat_statements_reset()").ok();
+        }
+    */
 
     Ok(MigrationCount {
         new: migrations,
@@ -1452,6 +1461,31 @@ impl PoolCoordinator {
     /// code that does _not_ hold the migration lock as it will otherwise
     /// deadlock
     fn propagate(&self, pool: &PoolInner, count: MigrationCount) -> Result<(), StoreError> {
+        #[derive(Debug, QueryableByName)]
+        struct Name {
+            #[diesel(sql_type = Text)]
+            pub name: String,
+        }
+
+        let mut conn = pool.get()?;
+        let db = sql_query("select current_database() as name")
+            .get_result::<Name>(&mut conn)
+            .optional()?;
+        warn!(self.logger, "CURRENT DATABASE {:?}", db);
+
+        match sql_query(
+            "select table_name as name from information_schema.tables where table_schema = 'public' order by 1",
+        )
+        .load::<Name>(&mut conn).optional()? {
+            Some(tables) => {
+                let tables = tables.into_iter().map(|t| t.name).collect::<Vec<_>>();
+                warn!(self.logger, "PUBLIC SCHEMA: tables {:?}", tables);
+            }
+            None => {
+                warn!(self.logger, "PUBLIC SCHEMA: no tables");
+            }
+        }
+
         // We need to remap all these servers into `pool` if the list of
         // tables that are mapped have changed from the code of the previous
         // version. Since dropping and recreating the foreign table
@@ -1547,6 +1581,7 @@ impl PoolCoordinator {
     /// the setup was actually run, i.e. if `pool` was available
     fn setup_bg(self: Arc<Self>, pool: PoolState) -> Result<bool, StoreError> {
         let migrated = graph::spawn_thread("database-setup", move || {
+            std::thread::sleep(Duration::from_secs(1));
             graph::block_on(self.setup(vec![pool.clone()]))
         })
         .join()
@@ -1609,6 +1644,7 @@ impl PoolCoordinator {
                         .cheap_clone()
                         .migrate(servers)
                         .map(|res| (state.cheap_clone(), res))
+                        .inspect(|(state, res)| warn!(state.logger, "MIGRATE RESULT {:?}", res))
                 })
                 .collect::<Vec<_>>();
             join_all(futures)
@@ -1658,6 +1694,10 @@ impl PoolCoordinator {
 
             let migrated = migrate(&pools, self.servers.as_ref()).await?;
 
+            warn!(self.logger, "Sleeping for 20s"; "migrated" => migrated.len());
+            tokio::time::sleep(Duration::from_secs(20)).await;
+            warn!(self.logger, "Waking up");
+
             let propagated = propagate(&self, migrated).await?;
 
             primary.create_cross_shard_views(&self.servers)?;