Attach more data to CacheTimeout errrors

Author: fetchfern

apps/labrinth/src/database/models/mod.rs

@@ -67,6 +67,13 @@ pub enum DatabaseError {
     SerdeCacheError(#[from] serde_json::Error),
     #[error("Schema error: {0}")]
     SchemaError(String),
-    #[error("Timeout when waiting for cache subscriber")]
-    CacheTimeout,
+    #[error(
+        "Timeout waiting on Redis cache lock ({locks_released}/{locks_waiting} released, spent {time_spent_pool_wait_ms}ms/{time_spent_total_ms}ms waiting on connections from pool)"
+    )]
+    CacheTimeout {
+        locks_released: usize,
+        locks_waiting: usize,
+        time_spent_pool_wait_ms: u64,
+        time_spent_total_ms: u64,
+    },
 }

apps/labrinth/src/database/postgres_database.rs

@@ -35,7 +35,19 @@ pub async fn connect_all() -> Result<(PgPool, ReadOnlyPgPool), sqlx::Error> {
     info!("Initializing database connection");
     let database_url =
         dotenvy::var("DATABASE_URL").expect("`DATABASE_URL` not in .env");
+
+    let acquire_timeout = dotenvy::var("DATABASE_ACQUIRE_TIMEOUT_MS")
+        .ok()
+        .map(|x| {
+            Duration::from_millis(
+                x.parse::<u64>()
+                    .expect("DATABASE_ACQUIRE_TIMEOUT_MS must be a valid u64"),
+            )
+        })
+        .unwrap_or_else(|| Duration::from_millis(30000)); // This is sqlx's default
+
     let pool = PgPoolOptions::new()
+        .acquire_timeout(acquire_timeout)
         .min_connections(
             dotenvy::var("DATABASE_MIN_CONNECTIONS")
                 .ok()
@@ -54,6 +66,7 @@ pub async fn connect_all() -> Result<(PgPool, ReadOnlyPgPool), sqlx::Error> {
 
     if let Ok(url) = dotenvy::var("READONLY_DATABASE_URL") {
         let ro_pool = PgPoolOptions::new()
+            .acquire_timeout(acquire_timeout)
             .min_connections(
                 dotenvy::var("READONLY_DATABASE_MIN_CONNECTIONS")
                     .ok()

apps/labrinth/src/database/redis.rs

@@ -16,6 +16,7 @@ use std::fmt::{Debug, Display};
 use std::future::Future;
 use std::hash::Hash;
 use std::time::Duration;
+use std::time::Instant;
 
 const DEFAULT_EXPIRY: i64 = 60 * 60 * 12; // 12 hours
 const ACTUAL_EXPIRY: i64 = 60 * 30; // 30 minutes
@@ -495,9 +496,13 @@ impl RedisPool {
                 let mut interval =
                     tokio::time::interval(Duration::from_millis(100));
                 let start = Utc::now();
+                let mut redis_budget = Duration::ZERO;
+
                 loop {
                     let results = {
+                        let acquire_start = Instant::now();
                         let mut connection = self.pool.get().await?;
+                        redis_budget += acquire_start.elapsed();
                         cmd("MGET")
                             .arg(
                                 subscribe_ids
@@ -516,12 +521,26 @@ impl RedisPool {
                             .await?
                     };
 
-                    if results.into_iter().all(|x| x.is_none()) {
+                    let none_count =
+                        results.into_iter().filter(|x| x.is_some()).count();
+
+                    // None of the locks exist anymore, we can continue
+                    if none_count == 0 {
                         break;
                     }
 
-                    if (Utc::now() - start) > chrono::Duration::seconds(5) {
-                        return Err(DatabaseError::CacheTimeout);
+                    let spinning = Utc::now() - start;
+                    if spinning > chrono::Duration::seconds(5) {
+                        return Err(DatabaseError::CacheTimeout {
+                            locks_released: none_count,
+                            locks_waiting: subscribe_ids.len(),
+                            time_spent_pool_wait_ms: redis_budget.as_millis()
+                                as u64,
+                            time_spent_total_ms: spinning
+                                .num_milliseconds()
+                                .max(0)
+                                as u64,
+                        });
                     }
 
                     interval.tick().await;