From 7ca9c864f217182030b56ad41cfa000b6bb28284 Mon Sep 17 00:00:00 2001
From: Greg Heartsfield <scsibug@imap.cc>
Date: Fri, 16 Dec 2022 17:01:49 -0600
Subject: [PATCH] improvement: DB pool logging shows used connections directly

---
 src/db.rs     | 11 ++++++++++-
 src/server.rs | 11 +++++++----
 2 files changed, 17 insertions(+), 5 deletions(-)

diff --git a/src/db.rs b/src/db.rs
index ae6f077..49a92d2 100644
--- a/src/db.rs
+++ b/src/db.rs
@@ -597,6 +597,15 @@ fn query_from_sub(sub: &Subscription) -> (String, Vec<Box<dyn ToSql>>) {
     (query, params)
 }
 
+fn log_pool_stats(pool: &SqlitePool) {
+    let state: r2d2::State = pool.state();
+    let in_use_cxns = state.connections - state.idle_connections;
+    debug!(
+        "DB pool usage (in_use: {}, available: {})",
+        in_use_cxns, state.connections
+    );
+}
+
 /// Perform a database query using a subscription.
 ///
 /// The [`Subscription`] is converted into a SQL query.  Each result
@@ -617,7 +626,7 @@ pub async fn db_query(
         let (q, p) = query_from_sub(&sub);
         trace!("SQL generated in {:?}", start.elapsed());
         // show pool stats
-        debug!("DB pool stats: {:?}", pool.state());
+        log_pool_stats(&pool);
         // cutoff for displaying slow queries
         let slow_cutoff = Duration::from_millis(1000);
         let start = Instant::now();
diff --git a/src/server.rs b/src/server.rs
index 5eb4d3b..b8d72c2 100644
--- a/src/server.rs
+++ b/src/server.rs
@@ -311,6 +311,7 @@ pub fn start_server(settings: Settings, shutdown_rx: MpscReceiver<()>) -> Result
                     controlled_shutdown.send(()).ok();
                 }
                 Err(std::sync::mpsc::RecvError) => {
+                    // FIXME: spurious error on startup?
                     debug!("shutdown requestor is disconnected");
                 }
             };
@@ -431,6 +432,8 @@ async fn nostr_server(
     event_tx: mpsc::Sender<SubmittedEvent>,
     mut shutdown: Receiver<()>,
 ) {
+    // the time this websocket nostr server started
+    let orig_start = Instant::now();
     // get a broadcast channel for clients to communicate on
     let mut bcast_rx = broadcast.subscribe();
     // Track internal client state
@@ -461,7 +464,6 @@ async fn nostr_server(
     let mut running_queries: HashMap<String, oneshot::Sender<()>> = HashMap::new();
     // keep track of the subscriptions we have
     let mut current_subs: Vec<Subscription> = Vec::new();
-
     // for stats, keep track of how many events the client published,
     // and how many it received from queries.
     let mut client_published_event_count: usize = 0;
@@ -473,7 +475,7 @@ async fn nostr_server(
     loop {
         tokio::select! {
             _ = shutdown.recv() => {
-        info!("Close connection down due to shutdown, client: {}, ip: {:?}", cid, conn.ip());
+        info!("Close connection down due to shutdown, client: {}, ip: {:?}, connected: {:?}", cid, conn.ip(), orig_start.elapsed());
                 // server shutting down, exit loop
                 break;
             },
@@ -676,10 +678,11 @@ async fn nostr_server(
         stop_tx.send(()).ok();
     }
     info!(
-        "stopping client connection (cid: {}, ip: {:?}, sent: {} events, recv: {} events)",
+        "stopping client connection (cid: {}, ip: {:?}, sent: {} events, recv: {} events, connected: {:?})",
         cid,
         conn.ip(),
         client_published_event_count,
-        client_received_event_count
+        client_received_event_count,
+	orig_start.elapsed()
     );
 }