build: bump version to 0.7.13

I have observed backups running for a very long time under heavy load,
this introduces some artificial delay to give the online backup enough
time to make progress.

Cargo.lock

@@ -1096,7 +1096,7 @@ checksum = "38bf9645c8b145698bb0b18a4637dcacbc421ea49bef2317e4fd8065a387cf21"
 
 [[package]]
 name = "nostr-rs-relay"
-version = "0.7.12"
+version = "0.7.13"
 dependencies = [
  "anyhow",
  "bitcoin_hashes",

Cargo.toml

@@ -1,6 +1,6 @@
 [package]
 name = "nostr-rs-relay"
-version = "0.7.12"
+version = "0.7.13"
 edition = "2021"
 authors = ["Greg Heartsfield <scsibug@imap.cc>"]
 description = "A relay implementation for the Nostr protocol"

rustfmt.toml

@@ -1 +1,4 @@
 edition = "2021"
+#max_width = 140
+#chain_width = 100
+#fn_call_width = 100

src/conn.rs

@@ -5,7 +5,7 @@ use crate::error::Result;
 
 use crate::subscription::Subscription;
 use std::collections::HashMap;
-use tracing::{debug, info};
+use tracing::{debug, trace};
 use uuid::Uuid;
 
 /// A subscription identifier has a maximum length
@@ -74,7 +74,7 @@ impl ClientConn {
         // prevent arbitrarily long subscription identifiers from
         // being used.
         if sub_id_len > MAX_SUBSCRIPTION_ID_LEN {
-            info!(
+            debug!(
                 "ignoring sub request with excessive length: ({})",
                 sub_id_len
             );
@@ -84,7 +84,7 @@ impl ClientConn {
         if self.subscriptions.contains_key(&k) {
             self.subscriptions.remove(&k);
             self.subscriptions.insert(k, s.clone());
-            debug!(
+            trace!(
                 "replaced existing subscription (cid: {}, sub: {:?})",
                 self.get_client_prefix(),
                 s.get_id()
@@ -98,7 +98,7 @@ impl ClientConn {
         }
         // add subscription
         self.subscriptions.insert(k, s);
-        debug!(
+        trace!(
             "registered new subscription, currently have {} active subs (cid: {})",
             self.subscriptions.len(),
             self.get_client_prefix(),
@@ -110,7 +110,7 @@ impl ClientConn {
     pub fn unsubscribe(&mut self, c: &Close) {
         // TODO: return notice if subscription did not exist.
         self.subscriptions.remove(&c.id);
-        debug!(
+        trace!(
             "removed subscription, currently have {} active subs (cid: {})",
             self.subscriptions.len(),
             self.get_client_prefix(),

src/db.rs

@@ -38,8 +38,14 @@ pub struct SubmittedEvent {
 
 /// Database file
 pub const DB_FILE: &str = "nostr.db";
-/// How many persisted events before optimization is triggered
+
-pub const EVENT_COUNT_OPTIMIZE_TRIGGER: usize = 500;
+/// How frequently to run maintenance
+/// How many persisted events before DB maintenannce is triggered.
+pub const EVENT_MAINTENANCE_FREQ_SEC: u64 = 60;
+
+/// How many persisted events before we pause for backups.
+/// It isn't clear this is enough to make the online backup API work yet.
+pub const EVENT_COUNT_BACKUP_PAUSE_TRIGGER: usize = 1000;
 
 /// Build a database connection pool.
 /// # Panics
@@ -78,7 +84,7 @@ pub fn build_pool(
         .test_on_check_out(true) // no noticeable performance hit
         .min_idle(Some(min_size))
         .max_size(max_size)
-        .max_lifetime(Some(Duration::from_secs(60)))
+        .max_lifetime(Some(Duration::from_secs(30)))
         .build(manager)
         .unwrap();
     info!(
@@ -90,7 +96,41 @@ pub fn build_pool(
 
 /// Perform normal maintenance
 pub fn optimize_db(conn: &mut PooledConnection) -> Result<()> {
+    let start = Instant::now();
     conn.execute_batch("PRAGMA optimize;")?;
+    info!("optimize ran in {:?}", start.elapsed());
+    Ok(())
+}
+#[derive(Debug)]
+enum SqliteReturnStatus {
+    SqliteOk,
+    SqliteBusy,
+    SqliteError,
+    SqliteOther(u64),
+}
+
+/// Checkpoint/Truncate WAL
+pub fn checkpoint_db(conn: &mut PooledConnection) -> Result<()> {
+    let query = "PRAGMA wal_checkpoint(TRUNCATE);";
+    let start = Instant::now();
+    let (cp_result, wal_size, _frames_checkpointed) = conn.query_row(query, [], |row| {
+        let checkpoint_result: u64 = row.get(0)?;
+        let wal_size: u64 = row.get(1)?;
+        let frames_checkpointed: u64 = row.get(2)?;
+        Ok((checkpoint_result, wal_size, frames_checkpointed))
+    })?;
+    let result = match cp_result {
+        0 => SqliteReturnStatus::SqliteOk,
+        1 => SqliteReturnStatus::SqliteBusy,
+        2 => SqliteReturnStatus::SqliteError,
+        x => SqliteReturnStatus::SqliteOther(x),
+    };
+    info!(
+        "checkpoint ran in {:?} (result: {:?}, WAL size: {})",
+        start.elapsed(),
+        result,
+        wal_size
+    );
     Ok(())
 }
 
@@ -133,8 +173,10 @@ pub async fn db_writer(
         let rps_setting = settings.limits.messages_per_sec;
         let mut most_recent_rate_limit = Instant::now();
         let mut lim_opt = None;
-        // Keep rough track of events so we can run optimize eventually.
+        // Constant writing has interfered with online backups.  Keep
-        let mut optimize_counter: usize = 0;
+        // track of how long since we've given the backups a chance to
+        // run.
+        let mut backup_pause_counter: usize = 0;
         let clock = governor::clock::QuantaClock::default();
         if let Some(rps) = rps_setting {
             if rps > 0 {
@@ -199,7 +241,8 @@ pub async fn db_writer(
                                 event.get_author_prefix()
                             );
                         } else {
-                            info!("rejecting event, author ({:?} / {:?}) verification invalid (expired/wrong domain)",
+                            info!(
+                                "rejecting event, author ({:?} / {:?}) verification invalid (expired/wrong domain)",
                                 uv.name.to_string(),
                                 event.get_author_prefix()
                             );
@@ -243,6 +286,7 @@ pub async fn db_writer(
                 );
                 event_write = true
             } else {
+                log_pool_stats("writer", &pool);
                 match write_event(&mut pool.get()?, &event) {
                     Ok(updated) => {
                         if updated == 0 {
@@ -267,12 +311,11 @@ pub async fn db_writer(
                         notice_tx.try_send(Notice::error(event.id, msg)).ok();
                     }
                 }
-                // Use this as a trigger to do optimization
+                backup_pause_counter += 1;
-                optimize_counter += 1;
+                if backup_pause_counter > EVENT_COUNT_BACKUP_PAUSE_TRIGGER {
-                if optimize_counter > EVENT_COUNT_OPTIMIZE_TRIGGER {
+                    info!("pausing db write thread for a moment...");
-                    info!("running database optimizer");
+                    thread::sleep(Duration::from_millis(500));
-                    optimize_counter = 0;
+                    backup_pause_counter = 0
-                    optimize_db(&mut pool.get()?).ok();
                 }
             }
 
@@ -320,7 +363,8 @@ pub fn write_event(conn: &mut PooledConnection, e: &Event) -> Result<usize> {
     )?;
     if ins_count == 0 {
         // if the event was a duplicate, no need to insert event or
-        // pubkey references.  This will abort the txn.
+        // pubkey references.
+        tx.rollback().ok();
         return Ok(ins_count);
     }
     // remember primary key of the event most recently inserted.
@@ -555,7 +599,10 @@ fn query_from_filter(f: &ReqFilter) -> (String, Vec<Box<dyn ToSql>>) {
             let str_clause = format!("value IN ({})", repeat_vars(str_vals.len()));
             let blob_clause = format!("value_hex IN ({})", repeat_vars(blob_vals.len()));
             // find evidence of the target tag name/value existing for this event.
-            let tag_clause = format!("e.id IN (SELECT e.id FROM event e LEFT JOIN tag t on e.id=t.event_id WHERE hidden!=TRUE and (name=? AND ({} OR {})))", str_clause, blob_clause);
+            let tag_clause = format!(
+                "e.id IN (SELECT e.id FROM event e LEFT JOIN tag t on e.id=t.event_id WHERE hidden!=TRUE and (name=? AND ({} OR {})))",
+                str_clause, blob_clause
+            );
             // add the tag name as the first parameter
             params.push(Box::new(key.to_string()));
             // add all tag values that are plain strings as params
@@ -614,13 +661,47 @@ fn query_from_sub(sub: &Subscription) -> (String, Vec<Box<dyn ToSql>>) {
     (query, params)
 }
 
-fn log_pool_stats(pool: &SqlitePool) {
+/// Check if the pool is fully utilized
+fn _pool_at_capacity(pool: &SqlitePool) -> bool {
+    let state: r2d2::State = pool.state();
+    state.idle_connections == 0
+}
+
+/// Log pool stats
+fn log_pool_stats(name: &str, pool: &SqlitePool) {
     let state: r2d2::State = pool.state();
     let in_use_cxns = state.connections - state.idle_connections;
-    debug!(
+    trace!(
-        "DB pool usage (in_use: {}, available: {})",
+        "DB pool {:?} usage (in_use: {}, available: {})",
-        in_use_cxns, state.connections
+        name,
+        in_use_cxns,
+        state.connections
     );
+    if state.connections == in_use_cxns {
+        debug!("DB pool {:?} is empty (in_use: {})", name, in_use_cxns);
+    }
+}
+
+/// Perform database maintenance on a regular basis
+pub async fn db_maintenance(pool: SqlitePool) {
+    tokio::task::spawn(async move {
+        loop {
+            tokio::select! {
+                    _ = tokio::time::sleep(Duration::from_secs(EVENT_MAINTENANCE_FREQ_SEC)) => {
+                        if let Ok(mut conn) = pool.get() {
+                // the busy timer will block writers, so don't set
+                // this any higher than you want max latency for event
+                // writes.
+                conn.busy_timeout(Duration::from_secs(1)).ok();
+                            debug!("running database optimizer");
+                            optimize_db(&mut conn).ok();
+                            debug!("running wal_checkpoint(TRUNCATE)");
+                            checkpoint_db(&mut conn).ok();
+                        }
+            }
+                };
+        }
+    });
 }
 
 /// Perform a database query using a subscription.
@@ -639,8 +720,16 @@ pub async fn db_query(
     let pre_spawn_start = Instant::now();
     task::spawn_blocking(move || {
         let db_queue_time = pre_spawn_start.elapsed();
-        // report queuing time if it is slow
+        // if the queue time was very long (>5 seconds), spare the DB and abort.
-        if db_queue_time > Duration::from_secs(1) {
+        if db_queue_time > Duration::from_secs(5) {
+            info!(
+                "shedding DB query load from {:?} (cid: {}, sub: {:?})",
+                db_queue_time, client_id, sub.id
+            );
+            return Ok(());
+        }
+        // otherwise, report queuing time if it is slow
+        else if db_queue_time > Duration::from_secs(1) {
             debug!(
                 "(slow) DB query queued for {:?} (cid: {}, sub: {:?})",
                 db_queue_time, client_id, sub.id
@@ -650,9 +739,12 @@ pub async fn db_query(
         let mut row_count: usize = 0;
         // generate SQL query
         let (q, p) = query_from_sub(&sub);
-        debug!("SQL generated in {:?}", start.elapsed());
+        let sql_gen_elapsed = start.elapsed();
+        if sql_gen_elapsed > Duration::from_millis(10) {
+            debug!("SQL (slow) generated in {:?}", start.elapsed());
+        }
         // show pool stats
-        log_pool_stats(&pool);
+        log_pool_stats("reader", &pool);
         // cutoff for displaying slow queries
         let slow_cutoff = Duration::from_millis(2000);
         // any client that doesn't cause us to generate new rows in 5
@@ -678,7 +770,7 @@ pub async fn db_query(
                 }
                 // logging for slow queries; show sub and SQL.
                 // to reduce logging; only show 1/16th of clients (leading 0)
-                if slow_first_event && client_id.starts_with("00") {
+                if row_count == 0 && slow_first_event && client_id.starts_with("0") {
                     debug!(
                         "query req (slow): {:?} (cid: {}, sub: {:?})",
                         sub, client_id, sub.id

src/nip05.rs

@@ -517,7 +517,7 @@ impl Verifier {
                 Ok(updated) => {
                     if updated != 0 {
                         info!(
-                            "persisted event: {:?} in {:?}",
+                            "persisted event (new verified pubkey): {:?} in {:?}",
                             event.get_event_id_prefix(),
                             start.elapsed()
                         );
@@ -721,7 +721,7 @@ pub fn query_oldest_user_verification(
     earliest: u64,
 ) -> Result<VerificationRecord> {
     let tx = conn.transaction()?;
-    let query = "SELECT v.id, v.name, e.event_hash, e.author, e.created_at, v.verified_at, v.failed_at, v.failure_count FROM user_verification v LEFT JOIN event e ON e.id=v.metadata_event WHERE (v.verified_at < ? OR v.verified_at IS NULL) AND (v.failed_at < ? OR v.failed_at IS NULL) ORDER BY v.verified_at ASC, v.failed_at ASC LIMIT 1;";
+    let query = "SELECT v.id, v.name, e.event_hash, e.author, e.created_at, v.verified_at, v.failed_at, v.failure_count FROM user_verification v INNER JOIN event e ON e.id=v.metadata_event WHERE (v.verified_at < ? OR v.verified_at IS NULL) AND (v.failed_at < ? OR v.failed_at IS NULL) ORDER BY v.verified_at ASC, v.failed_at ASC LIMIT 1;";
     let mut stmt = tx.prepare_cached(query)?;
     let fields = stmt.query_row(params![earliest, earliest], |r| {
         let rowid: u64 = r.get(0)?;

src/server.rs

@@ -22,6 +22,7 @@ use hyper::upgrade::Upgraded;
 use hyper::{
     header, server::conn::AddrStream, upgrade, Body, Request, Response, Server, StatusCode,
 };
+use rusqlite::OpenFlags;
 use serde::{Deserialize, Serialize};
 use serde_json::json;
 use std::collections::HashMap;
@@ -248,10 +249,10 @@ pub fn start_server(settings: Settings, shutdown_rx: MpscReceiver<()>) -> Result
         // limit concurrent SQLite blocking threads
         .max_blocking_threads(settings.limits.max_blocking_threads)
         .on_thread_start(|| {
-            debug!("started new thread");
+            trace!("started new thread");
         })
         .on_thread_stop(|| {
-            debug!("stopping thread");
+            trace!("stopping thread");
         })
         .build()
         .unwrap();
@@ -310,6 +311,17 @@ pub fn start_server(settings: Settings, shutdown_rx: MpscReceiver<()>) -> Result
                 }
             }
         }
+        // build a connection pool for DB maintenance
+        let maintenance_pool = db::build_pool(
+            "maintenance writer",
+            &settings,
+            OpenFlags::SQLITE_OPEN_READ_WRITE | OpenFlags::SQLITE_OPEN_CREATE,
+            1,
+            1,
+            false,
+        );
+        db::db_maintenance(maintenance_pool).await;
+
         // listen for (external to tokio) shutdown request
         let controlled_shutdown = invoke_shutdown.clone();
         tokio::spawn(async move {
@@ -538,7 +550,7 @@ async fn nostr_server(
                     // TODO: serialize at broadcast time, instead of
                     // once for each consumer.
                     if let Ok(event_str) = serde_json::to_string(&global_event) {
-                        debug!("sub match for client: {}, sub: {:?}, event: {:?}",
+                        trace!("sub match for client: {}, sub: {:?}, event: {:?}",
                                cid, s,
                                global_event.get_event_id_prefix());
                         // create an event response and send it