diff --git a/Justfile b/Justfile index 6377b290db..2f29f5e2a3 100644 --- a/Justfile +++ b/Justfile @@ -461,7 +461,8 @@ test-unit: # `handlers::`: the wider set is mostly Postgres-backed, and five of its # non-postgres_tests cases only "pass" without a database by waiting out # the ~30s sqlx acquire timeout, so they do not belong in the infra-free - # unit job either. + # unit job either. The REQ subscription-lifecycle tests are picked by + # exact name for the same reason: the rest of handlers::req needs a DB. # The third clause adds the NIP-FI HTTP ingress and its router/config # neighbours: nip_fi_http, nip_fi_config, router, api::parse_query_tests, # and the Git transport off_mode_precedence_tests. All are infra-free @@ -472,7 +473,7 @@ test-unit: # because they live in the binary target; the nested # `tests::postgres_tests::` stays in the PostgreSQL lane. cargo nextest run -p buzz-relay --lib --bin buzz-relay \ - -E 'test(/^api::admin::/) + test(/^handlers::channel_authz::/) + test(/^handlers::moderation_authz::/) + test(/^handlers::side_effects::tests::/) + test(/^storage_sweep::tests::/) + test(/^nip_fi_http::tests::/) + test(/^nip_fi_config::tests::/) + test(/^readiness::tests::/) + test(/^router::tests::/) + test(/^api::parse_query_tests::/) + test(/^api::git::transport::off_mode_precedence_tests::/) + test(=state::tests::neither_a_confirmed_inactive_community_nor_a_failed_lookup_admits_the_socket) + (kind(bin) & (test(/^tests::/) + test(/^composition_tests::/)) - test(/^tests::postgres_tests::/))' + -E 'test(/^api::admin::/) + test(/^handlers::channel_authz::/) + test(/^handlers::moderation_authz::/) + test(/^handlers::side_effects::tests::/) + test(/^storage_sweep::tests::/) + test(/^nip_fi_http::tests::/) + test(/^nip_fi_config::tests::/) + test(/^readiness::tests::/) + test(/^router::tests::/) + test(/^api::parse_query_tests::/) + test(/^api::git::transport::off_mode_precedence_tests::/) + test(=state::tests::neither_a_confirmed_inactive_community_nor_a_failed_lookup_admits_the_socket) + test(=handlers::req::tests::timed_out_historical_read_deregisters_before_closed) + test(=handlers::req::tests::superseded_timeout_leaves_replacement_intact) + test(=handlers::req::tests::search_claim_retires_live_and_yields_to_replacement) + test(=handlers::req::tests::concurrent_claims_and_stale_teardowns_keep_the_last_owner) + test(=handlers::req::tests::timeout_closed_is_emitted_before_a_replacement_can_claim) + test(=handlers::req::tests::revoke_then_replacement_keeps_replacement_whole) + test(=handlers::req::tests::claims_after_connection_cleanup_are_refused) + test(=handlers::req::tests::dropped_terminal_frame_cancels_connection) + test(=handlers::req::tests::revoke_dropped_terminal_frame_cancels_connection) + (kind(bin) & (test(/^tests::/) + test(/^composition_tests::/)) - test(/^tests::postgres_tests::/))' # ACP author-gate and queue tests protect the trust boundary between # relay events and agent prompts. They are infra-free; ignored lifecycle # tests remain excluded and run in their dedicated integration lanes. @@ -565,6 +566,10 @@ relay: bootstrap _ensure-migrations set +o allexport cargo run -p buzz-relay +# Post one root + N replies (and a few reactions) to the local dev relay, for eyeballing long threads +seed-long-thread replies="187": + ./scripts/seed-long-thread.sh {{replies}} + # Start the relay with the built web UI served from it relay-web: bootstrap _ensure-migrations #!/usr/bin/env bash diff --git a/PLANS/REPLICA_FULL_READ_ROUTING_DESIGN.md b/PLANS/REPLICA_FULL_READ_ROUTING_DESIGN.md index b6442d4f6d..c64d7e048b 100644 --- a/PLANS/REPLICA_FULL_READ_ROUTING_DESIGN.md +++ b/PLANS/REPLICA_FULL_READ_ROUTING_DESIGN.md @@ -12,8 +12,10 @@ created: 2026-08-28 routing**: the read may be served from a read replica when `BUZZ_REPLICA_READ_MAX_AGE_MS` is set, subject to the soundness predicate `RoutePredicate::for_query` derives from the query shape. The seam fails closed -to the writer at every error and is a genuine no-op until the budget is -configured (`crates/buzz-db/src/lib.rs`). +to the writer on replica errors, with one deliberate exception: a statement +cancelled by `statement_timeout` (SQLSTATE `57014`) is surfaced rather than +re-run, because the writer would run the same slow statement. It is a genuine +no-op until the budget is configured (`crates/buzz-db/src/lib.rs`). ## Routing rule diff --git a/crates/buzz-db/src/error.rs b/crates/buzz-db/src/error.rs index e7d7f2d324..4f15cc2b24 100644 --- a/crates/buzz-db/src/error.rs +++ b/crates/buzz-db/src/error.rs @@ -84,5 +84,17 @@ pub enum DbError { LastOperator, } +impl DbError { + /// Whether Postgres cancelled the statement (SQLSTATE 57014: + /// `statement_timeout` or an explicit cancel). Re-running such a query on + /// the writer would only repeat the same expensive work. + pub fn is_statement_cancelled(&self) -> bool { + matches!( + self, + DbError::Sqlx(sqlx::Error::Database(db)) if db.code().as_deref() == Some("57014") + ) + } +} + /// Convenience alias for `Result`. pub type Result = std::result::Result; diff --git a/crates/buzz-db/src/runtime/migration.rs b/crates/buzz-db/src/runtime/migration.rs index 66e3645915..9eae1dc72b 100644 --- a/crates/buzz-db/src/runtime/migration.rs +++ b/crates/buzz-db/src/runtime/migration.rs @@ -767,6 +767,11 @@ mod postgres_tests { .as_str() .contains("CREATE INDEX idx_events_tags_gin")); assert!(!migrations[0].sql.as_str().contains("idx_events_tags_gin")); + // schema.sql (CI / isolated relay bootstrap) must carry the same index, + // or e-tag reads there run on plans prod never sees. + assert!(include_str!("../../../../schema/schema.sql").contains( + "CREATE INDEX idx_events_tags_gin ON events USING GIN (tags jsonb_path_ops)" + )); // NIP-AM (kind 44200) FTS exclusion: additive migration, never folded // into 0001 — folding would change 0001's checksum and break brownfield diff --git a/crates/buzz-db/src/runtime/mod.rs b/crates/buzz-db/src/runtime/mod.rs index 150c8f4768..bc1e0374c7 100644 --- a/crates/buzz-db/src/runtime/mod.rs +++ b/crates/buzz-db/src/runtime/mod.rs @@ -201,6 +201,8 @@ impl ReadSession { /// /// If the proved replica transaction fails mid-request, the session /// permanently degrades to the writer and the query is re-run there. + /// Exception: a statement cancelled by `statement_timeout` (57014) is + /// returned as-is, since the writer would run the same slow statement. /// The writer is always at or ahead of any replica replay position, so /// the degraded follow-up can only observe *more* than the proof-time /// snapshot, never less — fresher aux rows, the same failure semantics @@ -211,6 +213,9 @@ impl ReadSession { ReadSessionInner::Replica { tx, writer } => { match event::query_events_on(tx, q).await { Ok(rows) => return Ok(rows), + // A cancelled statement (timeout) would be just as slow on + // the writer; surface it instead of doubling the cost. + Err(e) if e.is_statement_cancelled() => return Err(e), Err(e) => { tracing::warn!( error = %e, diff --git a/crates/buzz-db/src/runtime/tests.rs b/crates/buzz-db/src/runtime/tests.rs index 21d0e73823..3aa8e90685 100644 --- a/crates/buzz-db/src/runtime/tests.rs +++ b/crates/buzz-db/src/runtime/tests.rs @@ -3313,5 +3313,302 @@ async fn floor_guard_blocks_updates_that_move_rows_below_the_fence() { drop_scratch_db(&admin, pool, &name).await; } +// ---- Statement-deadline cancellation vs. replica fallback ---------------- +// +// A replica read cancelled by `statement_timeout` (SQLSTATE 57014) must be +// surfaced, not re-run on the writer: the writer would be just as slow and +// the relay maps it to a distinct non-retried "query timed out". Every other +// replica failure keeps failing closed to the writer. + +/// Writer and replica scratch DBs holding one root plus an `e`-tagged reply +/// that mentions `mentioned` — the writer copy says "writer-reply" so a +/// writer re-run is observable. Returns the reply-targeted query shape. +struct EtagFixture { + admin: PgPool, + writer: PgPool, + wname: String, + replica: PgPool, + rname: String, + cid: CommunityId, + root_hex: String, + mentioned_hex: String, +} + +async fn e_tag_fixture(prefix: &str) -> EtagFixture { + let admin = PgPool::connect(&admin_url().await) + .await + .expect("connect admin"); + let (writer, wname) = create_scratch_db(&admin, &format!("{prefix}_w")).await; + let (replica, rname) = create_scratch_db(&admin, &format!("{prefix}_r")).await; + let author = nostr::Keys::generate(); + let mentioned = nostr::Keys::generate(); + let community = Uuid::new_v4(); + let channel = Uuid::new_v4(); + let base = 1_700_000_000u64; + let root = signed_event_at(&author, "root", base); + for (pool, content) in [(&writer, "writer-reply"), (&replica, "replica-reply")] { + seed_community_channel(pool, community, channel, &author).await; + insert_top_level(pool, community, channel, &root).await; + let reply = nostr::EventBuilder::new(nostr::Kind::Custom(9), content) + .tags([ + nostr::Tag::event(root.id), + nostr::Tag::public_key(mentioned.public_key()), + ]) + .custom_created_at(nostr::Timestamp::from(base + 10)) + .sign_with_keys(&author) + .expect("sign reply"); + insert_top_level(pool, community, channel, &reply).await; + crate::insert_mentions( + pool, + CommunityId::from_uuid(community), + &reply, + Some(channel), + ) + .await + .expect("insert mentions"); + } + EtagFixture { + admin, + writer, + wname, + replica, + rname, + cid: CommunityId::from_uuid(community), + root_hex: root.id.to_hex(), + mentioned_hex: mentioned.public_key().to_hex(), + } +} + +impl EtagFixture { + fn e_tag_query(&self) -> EventQuery { + let mut q = EventQuery::for_community(self.cid); + q.e_tags = Some(vec![self.root_hex.clone(), "00".repeat(32)]); + q + } + + /// A routed `Db` whose reader pool connects fresh (so it picks up any + /// `ALTER DATABASE` settings made on the replica), with the fence open + /// and a bounded budget so unpinned reads route to the replica. + async fn routed_db(&self) -> Db { + let base = admin_url().await; + let url = format!("{}/{}", &base[..base.rfind('/').expect("path")], self.rname); + let reader = PgPool::connect(&url).await.expect("connect reader"); + let mut db = Db::from_pools(self.writer.clone(), reader); + db.fence().force_open_for_tests(chrono::Utc::now()); + db.set_replica_read_max_age_for_tests(Some(std::time::Duration::from_secs(5))); + db + } + + async fn drop(self) { + drop_scratch_db(&self.admin, self.replica, &self.rname).await; + drop_scratch_db(&self.admin, self.writer, &self.wname).await; + } +} + +fn contents(rows: &[StoredEvent]) -> Vec<&str> { + rows.iter().map(|e| e.event.content.as_str()).collect() +} + +#[tokio::test] +#[ignore = "requires Postgres"] +async fn replica_statement_cancel_propagates_without_writer_rerun() { + let fx = e_tag_fixture("cxl").await; + // A short operator cap on the replica (kept, not raised, by the e-tag + // deadline), plus a lock that parks every `events` read past it: the + // heartbeat proof still succeeds, then the routed read is cancelled. + sqlx::query(sqlx::AssertSqlSafe(format!( + "ALTER DATABASE {} SET statement_timeout = '300ms'", + fx.rname + ))) + .execute(&fx.admin) + .await + .expect("set replica statement_timeout"); + let db = fx.routed_db().await; + let q = fx.e_tag_query(); + + // Healthy control: the replica serves before it is locked. + let rows = db.query_events_routed("t_cxl", &q).await.expect("healthy"); + assert!( + contents(&rows).contains(&"replica-reply"), + "fixture must route to replica" + ); + + let mut locker = fx.replica.begin().await.expect("begin locker"); + sqlx::query("LOCK TABLE events IN ACCESS EXCLUSIVE MODE") + .execute(&mut *locker) + .await + .expect("lock replica events"); + + let cancelled = |r: crate::Result<()>, what: &str| match r { + Err(e) => assert!(e.is_statement_cancelled(), "{what}: want 57014, got {e}"), + Ok(()) => panic!("{what}: replica cancel was re-run on the writer"), + }; + cancelled( + db.query_events_routed("t_cxl", &q).await.map(drop), + "query_events_routed", + ); + cancelled( + db.query_events_routed_bounded("t_cxl", &q).await.map(drop), + "query_events_routed_bounded", + ); + cancelled( + db.count_events_routed("t_cxl", &q).await.map(drop), + "count_events_routed", + ); + let root_id = hex::decode(&fx.root_hex).expect("hex"); + cancelled( + db.get_events_by_ids_routed("t_cxl", fx.cid, &[root_id.as_slice()]) + .await + .map(drop), + "get_events_by_ids_routed", + ); + + locker.rollback().await.expect("unlock"); + drop(db); + fx.drop().await; +} + +/// [`replica_statement_cancel_propagates_without_writer_rerun`] for the +/// request-scoped [`ReadSession`]: a cancelled aux read inside the proved +/// replica transaction surfaces 57014 and does not degrade to the writer. +#[tokio::test] +#[ignore = "requires Postgres"] +async fn read_session_statement_cancel_propagates_without_writer_rerun() { + let fx = e_tag_fixture("scxl").await; + let db = fx.routed_db().await; + let reader_tx = db + .read_pool + .as_ref() + .expect("reader pool") + .begin() + .await + .expect("begin reader tx"); + let mut session = ReadSession { + inner: ReadSessionInner::Replica { + tx: reader_tx, + writer: fx.writer.clone(), + }, + }; + let rows = session + .query_events(&fx.e_tag_query()) + .await + .expect("healthy"); + assert_eq!(contents(&rows), vec!["replica-reply"]); + + // Force the next statement in the session over a short cap. + let ReadSessionInner::Replica { tx, .. } = &mut session.inner else { + unreachable!() + }; + sqlx::query("SET LOCAL statement_timeout = '50ms'") + .execute(&mut **tx) + .await + .expect("cap session"); + let mut locker = fx.replica.begin().await.expect("begin locker"); + sqlx::query("LOCK TABLE events IN ACCESS EXCLUSIVE MODE") + .execute(&mut *locker) + .await + .expect("lock replica events"); + + match session.query_events(&fx.e_tag_query()).await { + Err(e) => assert!(e.is_statement_cancelled(), "want 57014, got {e}"), + Ok(rows) => panic!("cancel re-ran on the writer: {:?}", contents(&rows)), + } + assert!( + session.is_replica(), + "a cancel must not degrade the session" + ); + + locker.rollback().await.expect("unlock"); + drop(session); + drop(db); + fx.drop().await; +} + +#[tokio::test] +#[ignore = "requires Postgres"] +async fn replica_non_cancel_failure_still_falls_back_to_writer() { + let fx = e_tag_fixture("nfb").await; + let db = fx.routed_db().await; + let q = fx.e_tag_query(); + let rows = db.query_events_routed("t_nfb", &q).await.expect("healthy"); + assert!( + contents(&rows).contains(&"replica-reply"), + "fixture must route to replica" + ); + + // Break the replica after the proof point (heartbeat table intact). + sqlx::query("DROP TABLE events CASCADE") + .execute(&fx.replica) + .await + .expect("drop replica events"); + + for rows in [ + db.query_events_routed("t_nfb", &q).await, + db.query_events_routed_bounded("t_nfb", &q).await, + ] { + let rows = rows.expect("non-cancel failure must fall back"); + assert!( + contents(&rows).contains(&"writer-reply"), + "{:?}", + contents(&rows) + ); + } + assert_eq!( + db.count_events_routed("t_nfb", &q) + .await + .expect("count falls back"), + 1 + ); + + drop(db); + fx.drop().await; +} + +/// The `#p`-joined SELECT (fenced, `e.` column prefix) and the COUNT `ANY` +/// path, executed with real bound values rather than only rendered SQL. +#[tokio::test] +#[ignore = "requires Postgres"] +async fn e_tag_any_runs_with_real_binds_on_p_join_and_count() { + let fx = e_tag_fixture("pjn").await; + let mut q = fx.e_tag_query(); + + let rows = event::query_events(&fx.writer, &q) + .await + .expect("e-tag select"); + assert_eq!(contents(&rows), vec!["writer-reply"]); + assert_eq!( + event::count_events(&fx.writer, &q) + .await + .expect("e-tag count"), + 1 + ); + + q.p_tag_hex = Some(fx.mentioned_hex.clone()); + let rows = event::query_events(&fx.writer, &q) + .await + .expect("#p + e-tag select"); + assert_eq!(contents(&rows), vec!["writer-reply"]); + assert_eq!( + event::count_events(&fx.writer, &q) + .await + .expect("#p + e-tag count"), + 1 + ); + + q.p_tag_hex = Some("11".repeat(32)); + assert!(event::query_events(&fx.writer, &q) + .await + .expect("miss") + .is_empty()); + assert_eq!( + event::count_events(&fx.writer, &q) + .await + .expect("miss count"), + 0 + ); + + fx.drop().await; +} + #[path = "tests/thread_window_postgres_tests.rs"] mod thread_window_postgres_tests; diff --git a/crates/buzz-db/src/store/event.rs b/crates/buzz-db/src/store/event.rs index 6259a02c5d..23082102e9 100644 --- a/crates/buzz-db/src/store/event.rs +++ b/crates/buzz-db/src/store/event.rs @@ -503,13 +503,42 @@ pub(crate) async fn query_events_on( return Ok(vec![]); } + let mut qb = build_query_events_sql(q); + let rows = if q.e_tags.is_some() { + fetch_with_e_tag_deadline(conn, &mut qb).await? + } else { + qb.build().fetch_all(&mut *conn).await? + }; + + let mut out = Vec::with_capacity(rows.len()); + for row in rows { + if let Some(ev) = row_to_stored_event(row)? { + out.push(ev); + } + } + Ok(out) +} + +/// SQL for [`query_events_on`], after its match-nothing early returns. +fn build_query_events_sql(q: &EventQuery) -> QueryBuilder { let clamp = q.max_limit.unwrap_or(DEFAULT_MAX_PAGE_LIMIT); let limit_val = q.limit.unwrap_or(100).min(clamp); let offset_val = q.offset.unwrap_or(0); + // e-tag reads filter inside a MATERIALIZED CTE and sort/limit outside it. + // With `ORDER BY created_at LIMIT n` in the same scope, the planner + // overestimates matches and walks each partition's pkey backward, testing + // every community row against the id set; the fence keeps it on the GIN + // tags index. + let e_tag_fence = q.e_tags.is_some(); let mut qb: QueryBuilder = if let Some(ref p_hex) = q.p_tag_hex { // Join against event_mentions for #p-filtered queries (indexed). - let mut b = QueryBuilder::new( + let mut b = QueryBuilder::new(if e_tag_fence { + "WITH m AS MATERIALIZED (" + } else { + "" + }); + b.push( "SELECT e.id, e.pubkey, e.created_at, e.kind, e.tags, e.content, \ e.sig, e.received_at, e.channel_id \ FROM events e \ @@ -524,7 +553,12 @@ pub(crate) async fn query_events_on( b.push_bind(p_hex.to_ascii_lowercase()); b } else { - let mut b = QueryBuilder::new( + let mut b = QueryBuilder::new(if e_tag_fence { + "WITH m AS MATERIALIZED (" + } else { + "" + }); + b.push( "SELECT id, pubkey, created_at, kind, tags, content, sig, received_at, channel_id \ FROM events WHERE community_id = ", ); @@ -614,17 +648,7 @@ pub(crate) async fn query_events_on( // the dominant scroll-back cost (~1.7s/page on staging). if let Some(ref e_tags) = q.e_tags { if !e_tags.is_empty() { - qb.push(" AND ("); - for (i, hex_id) in e_tags.iter().enumerate() { - if i > 0 { - qb.push(" OR "); - } - // Build the JSONB literal: [["e",""]] - let containment = serde_json::json!([["e", hex_id]]); - qb.push(format!("{col_prefix}tags @> ")); - qb.push_bind(containment); - } - qb.push(")"); + push_e_tag_filter(&mut qb, col_prefix, e_tags); } } @@ -704,21 +728,58 @@ pub(crate) async fn query_events_on( // same second. No existing index covers this trailing column — Postgres // sorts in memory, which is fine at current scale. If query performance // degrades, add a composite index like `(pubkey, kind, created_at DESC, id ASC)`. - qb.push(format!( - " ORDER BY {col_prefix}created_at DESC, {col_prefix}id ASC LIMIT " - )); + if e_tag_fence { + qb.push(") SELECT * FROM m ORDER BY created_at DESC, id ASC LIMIT "); + } else { + qb.push(format!( + " ORDER BY {col_prefix}created_at DESC, {col_prefix}id ASC LIMIT " + )); + } qb.push_bind(limit_val); qb.push(" OFFSET ").push_bind(offset_val); + qb +} - let rows = qb.build().fetch_all(&mut *conn).await?; +/// Server-side deadline for e-tag (aux-closure / `#e`) reads, kept under the +/// desktop's 30 s request timeout so a runaway query is cancelled once no +/// client can still be waiting for it. It only ever tightens the effective +/// `statement_timeout`: a shorter operator cap (`BUZZ_DB_STATEMENT_TIMEOUT_MS`) +/// is kept, and a disabled (`0`) or longer one is lowered to 20 s. The limit is +/// per statement, not per request. +const E_TAG_STATEMENT_TIMEOUT_SQL: &str = "SELECT set_config('statement_timeout', \ + CASE WHEN current_setting('statement_timeout')::interval = interval '0' \ + OR current_setting('statement_timeout')::interval > interval '20s' \ + THEN '20s' ELSE current_setting('statement_timeout') END, true)"; - let mut out = Vec::with_capacity(rows.len()); - for row in rows { - if let Some(ev) = row_to_stored_event(row)? { - out.push(ev); - } - } - Ok(out) +/// Run an e-tag read under [`E_TAG_STATEMENT_TIMEOUT_SQL`] without changing the +/// deadline for anything else on `conn`. `begin()` opens a transaction on an +/// autocommit writer connection or a savepoint inside the replica's read +/// transaction; rolling it back (the read has no writes to keep) reverts the +/// transaction-local `set_config` in both cases. +async fn fetch_with_e_tag_deadline( + conn: &mut sqlx::PgConnection, + qb: &mut QueryBuilder, +) -> Result> { + let mut tx = sqlx::Connection::begin(&mut *conn).await?; + sqlx::query(E_TAG_STATEMENT_TIMEOUT_SQL) + .execute(&mut *tx) + .await?; + let rows = qb.build().fetch_all(&mut *tx).await?; + tx.rollback().await?; + Ok(rows) +} + +/// e-tag pushdown as one array-bound containment test instead of an N-way +/// `OR` chain, so planner cost does not scale with the number of referenced +/// ids (the thread aux hop sends one id per reply). +fn push_e_tag_filter(qb: &mut QueryBuilder, col_prefix: &str, e_tags: &[String]) { + let containments: Vec = e_tags + .iter() + .map(|hex_id| serde_json::json!([["e", hex_id]])) + .collect(); + qb.push(format!(" AND {col_prefix}tags @> ANY(")) + .push_bind(containments) + .push("::jsonb[])"); } pub(crate) fn row_to_stored_event(row: sqlx::postgres::PgRow) -> Result> { @@ -884,16 +945,7 @@ pub(crate) async fn count_events_on(conn: &mut sqlx::PgConnection, q: &EventQuer if let Some(ref e_tags) = q.e_tags { if !e_tags.is_empty() { - qb.push(" AND ("); - for (i, hex_id) in e_tags.iter().enumerate() { - if i > 0 { - qb.push(" OR "); - } - let containment = serde_json::json!([["e", hex_id]]); - qb.push(format!("{col_prefix}tags @> ")); - qb.push_bind(containment); - } - qb.push(")"); + push_e_tag_filter(&mut qb, col_prefix, e_tags); } } @@ -920,7 +972,16 @@ pub(crate) async fn count_events_on(conn: &mut sqlx::PgConnection, q: &EventQuer } } - let row = qb.build().fetch_one(&mut *conn).await?; + let row = if q.e_tags.as_deref().is_some_and(|e| !e.is_empty()) { + // Run under the same transaction-local deadline as `query_events_on` + // so a COUNT over a long thread cannot stall indefinitely either. + let rows = fetch_with_e_tag_deadline(conn, &mut qb).await?; + rows.into_iter() + .next() + .ok_or_else(|| DbError::InvalidData("COUNT returned no rows".to_string()))? + } else { + qb.build().fetch_one(&mut *conn).await? + }; let cnt: i64 = row.try_get("cnt")?; Ok(cnt) @@ -1842,7 +1903,8 @@ impl Db { /// seam is gated on `BUZZ_REPLICA_READ_MAX_AGE_MS` (default off): when /// unset, even covered-eligible queries stay on the writer, so merging /// this seam is a true no-op until the budget is configured. Every - /// failure fails closed to the writer. + /// failure fails closed to the writer, except a statement-timeout cancel + /// (57014), which is surfaced rather than re-run. #[datastore_span(name = "query_events_routed", system = "postgresql")] pub async fn query_events_routed( &self, @@ -1864,6 +1926,12 @@ impl Db { Self::record_route(path, "replica", reason); Ok(events) } + // A cancelled statement (timeout) would be just as slow on the + // writer; surface it instead of doubling the cost. + Err(e) if e.is_statement_cancelled() => { + Self::record_route(path, "replica", "statement_cancelled"); + Err(e) + } Err(e) => { // Mid-query replica failure: fail closed to the // writer rather than surfacing a routed error. @@ -1917,6 +1985,12 @@ impl Db { Self::record_route(path, "replica", reason); Ok(events) } + // A cancelled statement (timeout) would be just as slow on the + // writer; surface it instead of doubling the cost. + Err(e) if e.is_statement_cancelled() => { + Self::record_route(path, "replica", "statement_cancelled"); + Err(e) + } Err(e) => { tracing::warn!(path, "replica read failed; re-running on writer: {e}"); Self::record_route(path, "writer", "replica_error"); @@ -1975,6 +2049,12 @@ impl Db { Self::record_route(path, "replica", reason); Ok(count) } + // A cancelled statement (timeout) would be just as slow on the + // writer; surface it instead of doubling the cost. + Err(e) if e.is_statement_cancelled() => { + Self::record_route(path, "replica", "statement_cancelled"); + Err(e) + } Err(e) => { tracing::warn!(path, "replica count failed; re-running on writer: {e}"); Self::record_route(path, "writer", "replica_error"); @@ -2228,6 +2308,12 @@ impl Db { Self::record_route(path, "replica", reason); Ok(events) } + // A cancelled statement (timeout) would be just as slow on the + // writer; surface it instead of doubling the cost. + Err(e) if e.is_statement_cancelled() => { + Self::record_route(path, "replica", "statement_cancelled"); + Err(e) + } Err(e) => { tracing::warn!(path, "replica read failed; re-running on writer: {e}"); Self::record_route(path, "writer", "replica_error"); @@ -2348,6 +2434,41 @@ impl Db { } } +#[cfg(test)] +mod e_tag_filter_shape_tests { + use super::*; + + /// The aux closure sends one e-tag per reply. The id set must be one + /// array-bound predicate (never an N-way `OR`), and it must be filtered + /// inside a MATERIALIZED CTE with ORDER BY/LIMIT outside: in the same + /// scope the planner flips to a backward pkey walk over the whole + /// community (the long-thread timeout). + #[test] + fn e_tag_query_filters_in_materialized_fence_before_order_limit() { + let mut q = EventQuery::for_community(CommunityId::from_uuid(uuid::Uuid::nil())); + q.kinds = Some(vec![7]); + q.e_tags = Some((0..188).map(|i| format!("{i:064x}")).collect()); + let qb = build_query_events_sql(&q); + let sql = qb.sql().as_str().to_owned(); + + assert!(sql.starts_with("WITH m AS MATERIALIZED (SELECT ")); + assert_eq!(sql.matches("tags @> ANY(").count(), 1); + assert!(!sql.contains(" OR ")); + let fence_end = sql.find(") SELECT * FROM m ").expect("fence closes"); + assert!(sql.contains("::jsonb[])")); + assert!(!sql[..fence_end].contains("ORDER BY")); + assert!(!sql[..fence_end].contains("LIMIT")); + assert!(sql[fence_end..].contains("ORDER BY created_at DESC, id ASC LIMIT ")); + } + + #[test] + fn non_e_tag_query_is_not_fenced() { + let q = EventQuery::for_community(CommunityId::from_uuid(uuid::Uuid::nil())); + let qb = build_query_events_sql(&q); + assert!(!qb.sql().as_str().contains("MATERIALIZED")); + } +} + #[cfg(test)] mod postgres_tests { use super::*; @@ -2401,6 +2522,180 @@ mod postgres_tests { id } + /// Effective `statement_timeout` observed *inside* the e-tag deadline, and + /// the value restored on `conn` afterwards. + async fn deadline_inside_and_after(conn: &mut sqlx::PgConnection) -> (String, String) { + let mut qb = QueryBuilder::new("SELECT current_setting('statement_timeout')"); + let rows = fetch_with_e_tag_deadline(conn, &mut qb) + .await + .expect("deadline read"); + let inside: String = rows[0].get(0); + let after: String = sqlx::query_scalar("SHOW statement_timeout") + .fetch_one(&mut *conn) + .await + .expect("show timeout"); + (inside, after) + } + + #[tokio::test] + #[ignore = "requires Postgres"] + async fn e_tag_deadline_only_tightens_and_restores_timeout() { + let pool = setup_pool().await; + // (operator setting, expected effective value inside the read) + let cases = [("0", "20s"), ("5s", "5s"), ("1min", "20s")]; + for (setting, expected) in cases { + // Autocommit connection (writer path). + let mut conn = pool.acquire().await.expect("acquire"); + sqlx::query("SELECT set_config('statement_timeout', $1, false)") + .bind(setting) + .execute(&mut *conn) + .await + .expect("set session timeout"); + let restored: String = sqlx::query_scalar("SHOW statement_timeout") + .fetch_one(&mut *conn) + .await + .expect("show timeout"); + let (inside, after) = deadline_inside_and_after(&mut conn).await; + assert_eq!(inside, expected, "autocommit, operator {setting}"); + assert_eq!(after, restored, "autocommit restore, operator {setting}"); + + // Nested in an outer read transaction (replica path -> savepoint). + let mut tx = sqlx::Connection::begin(&mut *conn).await.expect("begin"); + let (inside, after) = deadline_inside_and_after(&mut tx).await; + assert_eq!(inside, expected, "savepoint, operator {setting}"); + assert_eq!(after, restored, "savepoint restore, operator {setting}"); + tx.rollback().await.expect("rollback outer"); + + sqlx::query("RESET statement_timeout") + .execute(&mut *conn) + .await + .expect("reset"); + } + } + + #[tokio::test] + #[ignore = "requires Postgres"] + async fn e_tag_deadline_restores_timeout_after_error() { + let pool = setup_pool().await; + let mut conn = pool.acquire().await.expect("acquire"); + sqlx::query("SET statement_timeout = '1min'") + .execute(&mut *conn) + .await + .expect("set session timeout"); + // Autocommit connection (writer path). + let mut qb = QueryBuilder::new("SELECT 1/0"); + let err = fetch_with_e_tag_deadline(&mut conn, &mut qb).await; + assert!(err.is_err(), "division by zero must fail"); + let after: String = sqlx::query_scalar("SHOW statement_timeout") + .fetch_one(&mut *conn) + .await + .expect("connection usable after error"); + assert_eq!(after, "1min", "autocommit restore"); + + // Nested in an outer read transaction (replica path -> savepoint): + // the failed savepoint must roll back and leave the outer tx usable. + let mut tx = sqlx::Connection::begin(&mut *conn).await.expect("begin"); + let mut qb = QueryBuilder::new("SELECT 1/0"); + let err = fetch_with_e_tag_deadline(&mut tx, &mut qb).await; + assert!(err.is_err(), "division by zero must fail"); + let after: String = sqlx::query_scalar("SHOW statement_timeout") + .fetch_one(&mut *tx) + .await + .expect("outer transaction usable after savepoint error"); + assert_eq!(after, "1min", "savepoint restore"); + tx.rollback().await.expect("rollback outer"); + sqlx::query("RESET statement_timeout") + .execute(&mut *conn) + .await + .expect("reset"); + } + + /// Pins the dispatch: an e-tag read through the production + /// `query_events_on` is cancelled at the 20 s deadline even with the + /// session timeout disabled, while `events` is locked. (Slow by design.) + #[tokio::test] + #[ignore = "requires Postgres"] + async fn e_tag_read_is_cancelled_at_deadline_when_timeout_disabled() { + let pool = setup_pool().await; + let community = CommunityId::from_uuid(make_test_community(&pool).await); + let mut locker = pool.begin().await.expect("begin locker"); + sqlx::query("LOCK TABLE events IN ACCESS EXCLUSIVE MODE") + .execute(&mut *locker) + .await + .expect("lock events"); + + let mut conn = pool.acquire().await.expect("acquire"); + sqlx::query("SET statement_timeout = 0") + .execute(&mut *conn) + .await + .expect("disable timeout"); + let mut q = EventQuery::for_community(community); + q.e_tags = Some(vec!["00".repeat(32)]); + let started = std::time::Instant::now(); + let result = tokio::time::timeout( + std::time::Duration::from_secs(40), + query_events_on(&mut conn, &q), + ) + .await + .expect("deadline must fire before the 40 s guard"); + let err = result.expect_err("locked read must be cancelled"); + assert!(err.is_statement_cancelled(), "want 57014, got {err}"); + assert!(started.elapsed() >= std::time::Duration::from_secs(19)); + + locker.rollback().await.expect("unlock"); + sqlx::query("RESET statement_timeout") + .execute(&mut *conn) + .await + .expect("reset"); + } + + /// Pins the dispatch: a COUNT with an e-tag filter through the production + /// `count_events_on` is cancelled at the 20 s deadline even with the + /// session timeout disabled, while `events` is locked. Connection and + /// setting are restored afterwards. (Slow by design.) + #[tokio::test] + #[ignore = "requires Postgres"] + async fn count_events_cancels_at_e_tag_deadline_when_timeout_disabled() { + let pool = setup_pool().await; + let community = CommunityId::from_uuid(make_test_community(&pool).await); + let mut locker = pool.begin().await.expect("begin locker"); + sqlx::query("LOCK TABLE events IN ACCESS EXCLUSIVE MODE") + .execute(&mut *locker) + .await + .expect("lock events"); + + let mut conn = pool.acquire().await.expect("acquire"); + sqlx::query("SET statement_timeout = 0") + .execute(&mut *conn) + .await + .expect("disable timeout"); + let mut q = EventQuery::for_community(community); + q.e_tags = Some(vec!["00".repeat(32)]); + let started = std::time::Instant::now(); + let result = tokio::time::timeout( + std::time::Duration::from_secs(40), + count_events_on(&mut conn, &q), + ) + .await + .expect("deadline must fire before the 40 s guard"); + let err = result.expect_err("locked COUNT must be cancelled"); + assert!(err.is_statement_cancelled(), "want 57014, got {err}"); + assert!(started.elapsed() >= std::time::Duration::from_secs(19)); + + // Connection and session timeout are restored after the error. + let after: String = sqlx::query_scalar("SHOW statement_timeout") + .fetch_one(&mut *conn) + .await + .expect("connection usable after cancellation"); + assert_eq!(after, "0", "timeout must be restored to disabled"); + + locker.rollback().await.expect("unlock"); + sqlx::query("RESET statement_timeout") + .execute(&mut *conn) + .await + .expect("reset"); + } + #[tokio::test] #[ignore = "requires Postgres"] async fn event_insert_in_existing_transaction_rolls_back_with_caller() { diff --git a/crates/buzz-relay/src/api/bridge.rs b/crates/buzz-relay/src/api/bridge.rs index 13437d9c0d..b5aa6d553b 100644 --- a/crates/buzz-relay/src/api/bridge.rs +++ b/crates/buzz-relay/src/api/bridge.rs @@ -22,7 +22,7 @@ use crate::handlers::ingest::{IngestAuth, IngestError}; use crate::nip_fi_http::{admit_nip_fi_http_on_state, Nip98Proof}; use crate::state::AppState; -use super::{api_error, internal_error, not_found, parse_query_or_400}; +use super::{api_error, db_read_error, internal_error, not_found, parse_query_or_400}; mod thread_roots; mod thread_window; @@ -772,7 +772,7 @@ async fn handle_channel_window_filter( &mut AuxReader::Session(&mut session), ) .await - .map_err(|e| internal_error(&format!("window aux error: {e}")))?; + .map_err(|e| db_read_error("window aux error", &e))?; for se in aux_events { if !seen_aux.insert(se.event.id) { continue; @@ -1635,7 +1635,7 @@ async fn query_events_authed( &mut AuxReader::Routed(&state.db, "bridge_thread_aux"), ) .await - .map_err(|e| internal_error(&format!("thread aux query error: {e}")))?; + .map_err(|e| db_read_error("thread aux query error", &e))?; for se in aux_events { if !seen_aux.insert(se.event.id) || !event_in_accessible_channel(&se, &accessible_channels) @@ -1792,7 +1792,7 @@ async fn query_events_authed( } } Err(e) => { - return Err(internal_error(&format!("query error: {e}"))); + return Err(db_read_error("query error", &e)); } } } @@ -2058,7 +2058,7 @@ async fn count_events_authed( match state.db.count_events_routed("bridge_count", &query).await { Ok(n) => total += n as u64, Err(e) => { - return Err(internal_error(&format!("count error: {e}"))); + return Err(db_read_error("count error", &e)); } } } else { @@ -2093,7 +2093,7 @@ async fn count_events_authed( } } Err(e) => { - return Err(internal_error(&format!("count error: {e}"))); + return Err(db_read_error("count error", &e)); } } } @@ -2129,7 +2129,7 @@ async fn count_events_authed( match state.db.count_events_routed("bridge_count", &query).await { Ok(n) => total += n as u64, Err(e) => { - return Err(internal_error(&format!("count error: {e}"))); + return Err(db_read_error("count error", &e)); } } } else { @@ -2163,7 +2163,7 @@ async fn count_events_authed( } } Err(e) => { - return Err(internal_error(&format!("count error: {e}"))); + return Err(db_read_error("count error", &e)); } } } @@ -2314,7 +2314,7 @@ async fn handle_bridge_search( .db .get_events_by_ids_routed("bridge_search_hydrate", tenant.community(), &id_refs) .await - .map_err(|e| internal_error(&format!("search fetch error: {e}")))?; + .map_err(|e| db_read_error("search fetch error", &e))?; // Build lookup map to preserve FTS relevance ordering. let event_map: std::collections::HashMap<[u8; 32], &buzz_core::StoredEvent> = stored_events @@ -7606,4 +7606,459 @@ mod postgres_tests { drop_scratch(&admin2, replica_pool, &replica_name).await; }); } + + // ── Statement-cancel propagation through every routed-read caller ───────── + // + // A replica whose `events` table is locked past its 300ms operator + // `statement_timeout` cancels every routed read with 57014, which the + // routed helpers now propagate instead of re-running on the writer. Every + // COUNT arm (fast/fallback × with/without `#h`) and search hydrate must + // then answer with the stable timeout contract on both transports: + // HTTP 503 `query timed out`, WS CLOSED `error: query timed out`. The + // ordinary-error controls rename `events` so reads fail with 42P01 and + // must stay a generic 500 / raw WS error. + + struct CancelFixture { + admin: sqlx::PgPool, + writer: sqlx::PgPool, + replica: sqlx::PgPool, + names: [String; 2], + state: Arc, + host: String, + community: buzz_core::CommunityId, + channel: String, + root: String, + reader: Keys, + } + + async fn cancel_fixture() -> CancelFixture { + use buzz_db::channel::{ChannelType, ChannelVisibility}; + let admin_url = crate::test_support::database_url(); + let admin = sqlx::PgPool::connect(&admin_url).await.expect("admin pool"); + let base = &admin_url[..admin_url.rfind('/').expect("db path")]; + let community = uuid::Uuid::new_v4(); + let channel = uuid::Uuid::new_v4(); + let host = format!("cancel-{}.local", community.simple()); + let author = Keys::generate(); + let root = EventBuilder::new(Kind::Custom(9), "root needle") + .tag(Tag::parse(["h", &channel.to_string()]).expect("h")) + .sign_with_keys(&author) + .expect("sign root"); + let mut pools = Vec::new(); + let mut names = Vec::new(); + for role in ["w", "r"] { + let name = format!("cancel_{role}_{}", uuid::Uuid::new_v4().simple()); + sqlx::query(sqlx::AssertSqlSafe(format!("CREATE DATABASE {name}"))) + .execute(&admin) + .await + .expect("create scratch db"); + if role == "r" { + sqlx::query(sqlx::AssertSqlSafe(format!( + "ALTER DATABASE {name} SET statement_timeout = '300ms'" + ))) + .execute(&admin) + .await + .expect("replica statement_timeout"); + } + let pool = sqlx::PgPool::connect(&format!("{base}/{name}")) + .await + .expect("connect scratch"); + buzz_db::migration::run_migrations(&pool) + .await + .expect("migrate"); + sqlx::query("INSERT INTO communities (id, host) VALUES ($1, $2)") + .bind(community) + .bind(&host) + .execute(&pool) + .await + .expect("seed community"); + let cid = buzz_core::CommunityId::from_uuid(community); + buzz_db::channel::create_channel_with_id( + &pool, + cid, + channel, + &format!("cancel-{}", channel.simple()), + ChannelType::Stream, + ChannelVisibility::Open, + None, + author.public_key().to_bytes().as_slice(), + None, + ) + .await + .expect("create channel"); + buzz_db::Db::from_pool(pool.clone()) + .insert_event(cid, &root, Some(channel)) + .await + .expect("insert root"); + pools.push(pool); + names.push(name); + } + let replica = pools.pop().expect("replica"); + let writer = pools.pop().expect("writer"); + + let mut config = crate::config::Config::from_env().expect("config"); + config.redis_url = + std::env::var("REDIS_URL").unwrap_or_else(|_| "redis://127.0.0.1:6379".to_string()); + config.relay_url = "wss://cancel-test.local".to_string(); + config.require_auth_token = false; + config.require_relay_membership = false; + let mut db = buzz_db::Db::from_pools(writer.clone(), replica.clone()); + db.fence().force_open_for_tests(chrono::Utc::now()); + db.set_replica_read_max_age_for_tests(Some(std::time::Duration::from_secs(5))); + let redis_pool = deadpool_redis::Config::from_url(&config.redis_url) + .create_pool(Some(deadpool_redis::Runtime::Tokio1)) + .expect("redis pool"); + let pubsub = Arc::new( + buzz_pubsub::PubSubManager::new(&config.redis_url, redis_pool.clone()) + .await + .expect("pubsub"), + ); + let (mut state, _audit_shutdown) = crate::state::AppState::new( + config.clone(), + db.clone(), + redis_pool, + buzz_audit::AuditService::new(writer.clone()), + pubsub, + buzz_auth::AuthService::new(config.auth.clone()), + buzz_search::SearchService::new(writer.clone()), + Arc::new(buzz_workflow::WorkflowEngine::new( + db, + buzz_workflow::WorkflowConfig::default(), + )), + Keys::generate(), + buzz_media::MediaStorage::new(&config.media).expect("media storage"), + ); + state.nip98_replay = Arc::new(AlwaysFreshReplayGuard); + CancelFixture { + admin, + writer, + replica, + names: [names[0].clone(), names[1].clone()], + state: Arc::new(state), + host, + community: buzz_core::CommunityId::from_uuid(community), + channel: channel.to_string(), + root: root.id.to_hex(), + reader: Keys::generate(), + } + } + + impl CancelFixture { + /// The four COUNT arms: fast (fully pushable) and fallback (`#t` is + /// not pushable, `#e` still reaches SQL), each with and without `#h`. + fn count_cases(&self) -> Vec<(&'static str, serde_json::Value)> { + let e = [&self.root]; + let h = [&self.channel]; + vec![ + ( + "fast #h", + serde_json::json!({"kinds": [9], "#h": h, "#e": e}), + ), + ( + "fallback #h", + serde_json::json!({"kinds": [9], "#h": h, "#e": e, "#t": ["x"]}), + ), + ("fast no-#h", serde_json::json!({"kinds": [9], "#e": e})), + ( + "fallback no-#h", + serde_json::json!({"kinds": [9], "#e": e, "#t": ["x"]}), + ), + ] + } + + fn search_filter(&self) -> serde_json::Value { + serde_json::json!({"kinds": [9], "#h": [&self.channel], "search": "needle"}) + } + + async fn http(&self, uri: &str, filter: &serde_json::Value) -> (StatusCode, Value) { + use axum::body::Body; + use axum::http::{header, Request}; + use tower::ServiceExt; + let resp = crate::router::build_router(self.state.clone()) + .oneshot( + Request::builder() + .method("POST") + .uri(uri) + .header(header::HOST, &self.host) + .header("x-pubkey", self.reader.public_key().to_hex()) + .header("content-type", "application/json") + .body(Body::from(serde_json::to_vec(&[filter]).expect("json"))) + .expect("request"), + ) + .await + .expect("oneshot"); + let status = resp.status(); + let bytes = axum::body::to_bytes(resp.into_body(), usize::MAX) + .await + .expect("body"); + ( + status, + serde_json::from_slice(&bytes).unwrap_or(Value::Null), + ) + } + + /// Drive a WS frame handler and return the first frame it sends. + async fn ws(&self, drive: F) -> String + where + F: FnOnce(Arc) -> Fut, + Fut: std::future::Future, + { + let (conn, mut send_rx) = self.ws_conn(); + drive(conn).await; + match send_rx.try_recv().expect("handler sent a frame") { + axum::extract::ws::Message::Text(t) => t.to_string(), + other => panic!("expected text frame, got {other:?}"), + } + } + + /// An authenticated reader connection and its outbound frame queue. + fn ws_conn( + &self, + ) -> ( + Arc, + tokio::sync::mpsc::Receiver, + ) { + let (send_tx, send_rx) = tokio::sync::mpsc::channel(64); + let (ctrl_tx, _ctrl_rx) = tokio::sync::mpsc::channel(4); + let conn = Arc::new(crate::connection::ConnectionState { + conn_id: uuid::Uuid::new_v4(), + tenant: TenantContext::resolved(self.community, self.host.clone()), + remote_addr: "127.0.0.1:1234".parse().expect("addr"), + auth_state: std::sync::Mutex::new(crate::connection::AuthState::Authenticated( + buzz_auth::AuthContext { + pubkey: self.reader.public_key(), + scopes: Vec::new(), + channel_ids: None, + auth_method: buzz_auth::AuthMethod::Nip42, + agent_owner_pubkey: None, + }, + )), + subscriptions: Arc::new(tokio::sync::Mutex::new(Default::default())), + send_tx, + ctrl_tx, + cancel: tokio_util::sync::CancellationToken::new(), + backpressure_count: Arc::new(std::sync::atomic::AtomicU8::new(0)), + grace_limit: 3, + }); + (conn, send_rx) + } + + async fn ws_count(&self, filter: &serde_json::Value) -> String { + let filter: nostr::Filter = serde_json::from_value(filter.clone()).expect("filter"); + let state = self.state.clone(); + self.ws(|conn| { + crate::handlers::count::handle_count("c".into(), vec![filter], conn, state) + }) + .await + } + + async fn ws_search(&self) -> String { + let filter: nostr::Filter = + serde_json::from_value(self.search_filter()).expect("filter"); + let state = self.state.clone(); + self.ws(|conn| { + crate::handlers::req::handle_req("s".into(), vec![filter], vec![None], conn, state) + }) + .await + } + + async fn drop(self) { + drop(self.state); + for (pool, name) in [ + (self.writer, &self.names[0]), + (self.replica, &self.names[1]), + ] { + pool.close().await; + let _ = sqlx::query(sqlx::AssertSqlSafe(format!( + "DROP DATABASE IF EXISTS {name} WITH (FORCE)" + ))) + .execute(&self.admin) + .await; + } + } + } + + #[tokio::test] + #[ignore = "requires Postgres"] + async fn routed_read_cancel_maps_to_timeout_contract_on_count_and_search() { + let fx = cancel_fixture().await; + + // Healthy controls: every arm and search hydrate serve before the lock. + for (arm, filter) in fx.count_cases() { + let (status, body) = fx.http("/count", &filter).await; + assert_eq!(status, StatusCode::OK, "healthy HTTP COUNT {arm}: {body}"); + let frame = fx.ws_count(&filter).await; + assert!( + frame.starts_with(r#"["COUNT""#), + "healthy WS COUNT {arm}: {frame}" + ); + } + let (status, body) = fx.http("/query", &fx.search_filter()).await; + assert_eq!(status, StatusCode::OK, "healthy HTTP search: {body}"); + assert!( + body.to_string().contains("root needle"), + "search hit: {body}" + ); + let frame = fx.ws_search().await; + assert!(frame.contains("root needle"), "healthy WS search: {frame}"); + + let mut locker = fx.replica.begin().await.expect("begin locker"); + sqlx::query("LOCK TABLE events IN ACCESS EXCLUSIVE MODE") + .execute(&mut *locker) + .await + .expect("lock replica events"); + + let closed = |sub: &str| { + format!( + r#"["CLOSED","{sub}","{}"]"#, + crate::handlers::req::QUERY_TIMED_OUT_CLOSED + ) + }; + for (arm, filter) in fx.count_cases() { + let (status, body) = fx.http("/count", &filter).await; + assert_eq!( + (status, body["error"].as_str()), + ( + StatusCode::SERVICE_UNAVAILABLE, + Some(super::super::QUERY_TIMED_OUT) + ), + "HTTP COUNT {arm}" + ); + assert_eq!(fx.ws_count(&filter).await, closed("c"), "WS COUNT {arm}"); + } + let (status, body) = fx.http("/query", &fx.search_filter()).await; + assert_eq!( + (status, body["error"].as_str()), + ( + StatusCode::SERVICE_UNAVAILABLE, + Some(super::super::QUERY_TIMED_OUT) + ), + "HTTP search hydrate" + ); + assert_eq!(fx.ws_search().await, closed("s"), "WS search hydrate"); + locker.rollback().await.expect("unlock"); + + // Ordinary-error controls: `events` gone on both pools → 42P01 on the + // replica, writer re-run, 42P01 again. Not a timeout. + for pool in [&fx.writer, &fx.replica] { + sqlx::query("ALTER TABLE events RENAME TO events_gone") + .execute(pool) + .await + .expect("rename events"); + } + let (arm, filter) = fx.count_cases().swap_remove(0); + let (status, body) = fx.http("/count", &filter).await; + assert_eq!( + (status, body["error"].as_str()), + ( + StatusCode::INTERNAL_SERVER_ERROR, + Some("internal server error") + ), + "HTTP COUNT {arm} ordinary error" + ); + let frame = fx.ws_count(&filter).await; + assert!( + frame.starts_with(r#"["CLOSED","c","error: "#) && !frame.contains("query timed out"), + "WS COUNT {arm} ordinary error: {frame}" + ); + + fx.drop().await; + } + + /// A search REQ reusing a live subscription's ID retires it (NIP-01 + /// replacement) before its hydrate is cancelled, so the timeout CLOSED + /// leaves nothing registered under the ID. + #[tokio::test] + #[ignore = "requires Postgres"] + async fn search_reusing_live_id_retires_it_before_timeout_closed() { + use crate::handlers::req::handle_req; + let fx = cancel_fixture().await; + let (conn, mut rx) = fx.ws_conn(); + let frames = |rx: &mut tokio::sync::mpsc::Receiver| { + std::iter::from_fn(|| rx.try_recv().ok()) + .map(|msg| match msg { + axum::extract::ws::Message::Text(t) => t.to_string(), + other => panic!("expected text frame, got {other:?}"), + }) + .collect::>() + }; + let channel: uuid::Uuid = fx.channel.parse().expect("channel uuid"); + let topic = buzz_pubsub::EventTopic::Channel(channel); + let tenant = TenantContext::resolved(fx.community, fx.host.clone()); + let live: nostr::Filter = + serde_json::from_value(serde_json::json!({"kinds": [9], "#h": [&fx.channel]})) + .expect("live filter"); + handle_req( + "x".into(), + vec![live], + vec![None], + conn.clone(), + fx.state.clone(), + ) + .await; + assert!( + frames(&mut rx) + .last() + .is_some_and(|f| f == r#"["EOSE","x"]"#), + "live x served" + ); + assert!(conn.subscriptions.lock().await.contains_key("x")); + assert!(fx + .state + .sub_registry + .get_filters(conn.conn_id, "x") + .is_some()); + assert_eq!(fx.state.pubsub.topic_refcount(&tenant, topic).await, 1); + + let mut locker = fx.replica.begin().await.expect("begin locker"); + sqlx::query("LOCK TABLE events IN ACCESS EXCLUSIVE MODE") + .execute(&mut *locker) + .await + .expect("lock replica events"); + let search: nostr::Filter = + serde_json::from_value(fx.search_filter()).expect("search filter"); + let live_owner = *conn.subscriptions.lock().await.get("x").expect("x owned"); + let task = tokio::spawn(handle_req( + "x".into(), + vec![search], + vec![None], + conn.clone(), + fx.state.clone(), + )); + // Once search has claimed `x` its hydrate blocks on the lock. The old + // live fan-out must already be retired then, not only at final cleanup. + while conn.subscriptions.lock().await.get("x") == Some(&live_owner) { + tokio::task::yield_now().await; + } + assert!( + fx.state + .sub_registry + .get_filters(conn.conn_id, "x") + .is_none(), + "accepting search must retire live fan-out" + ); + assert_eq!(fx.state.pubsub.topic_refcount(&tenant, topic).await, 0); + task.await.expect("search task"); + locker.rollback().await.expect("unlock"); + + assert_eq!( + frames(&mut rx), + vec![format!( + r#"["CLOSED","x","{}"]"#, + crate::handlers::req::QUERY_TIMED_OUT_CLOSED + )] + ); + assert!(conn.subscriptions.lock().await.is_empty(), "conn map"); + assert!( + fx.state + .sub_registry + .get_filters(conn.conn_id, "x") + .is_none(), + "fan-out registration must be retired" + ); + assert_eq!(fx.state.pubsub.topic_refcount(&tenant, topic).await, 0); + + drop(conn); + fx.drop().await; + } } diff --git a/crates/buzz-relay/src/api/mod.rs b/crates/buzz-relay/src/api/mod.rs index c84192a6e6..460f7f70b8 100644 --- a/crates/buzz-relay/src/api/mod.rs +++ b/crates/buzz-relay/src/api/mod.rs @@ -27,6 +27,24 @@ pub(crate) fn internal_error(msg: &str) -> (StatusCode, Json) api_error(StatusCode::INTERNAL_SERVER_ERROR, "internal server error") } +/// Stable client-visible body for a read cancelled by its server-side +/// statement deadline. Clients match this string to skip retrying: a retry +/// would re-run the same expensive query. +pub(crate) const QUERY_TIMED_OUT: &str = "query timed out"; + +/// Map a DB read failure: a statement-deadline cancel becomes a distinct +/// 503 `query timed out`; anything else stays a generic 500. +pub(crate) fn db_read_error( + context: &str, + e: &buzz_db::DbError, +) -> (StatusCode, Json) { + if e.is_statement_cancelled() { + tracing::warn!("{context}: {e}"); + return api_error(StatusCode::SERVICE_UNAVAILABLE, QUERY_TIMED_OUT); + } + internal_error(&format!("{context}: {e}")) +} + #[allow(dead_code)] pub(crate) fn not_found(msg: &str) -> (StatusCode, Json) { api_error(StatusCode::NOT_FOUND, msg) @@ -406,6 +424,46 @@ pub mod relay_members { } } +#[cfg(test)] +mod db_read_error_tests { + use super::*; + + #[test] + fn non_cancel_db_error_stays_generic_500() { + let (status, body) = db_read_error("ctx", &buzz_db::DbError::NotFound("x".into())); + assert_eq!(status, StatusCode::INTERNAL_SERVER_ERROR); + assert_eq!(body.0["error"], "internal server error"); + } +} + +#[cfg(test)] +mod postgres_tests { + use super::*; + + #[tokio::test] + #[ignore = "requires Postgres"] + async fn statement_timeout_maps_to_distinct_503() { + let pool = sqlx::PgPool::connect(&crate::test_support::database_url()) + .await + .expect("connect to test DB"); + let mut tx = pool.begin().await.expect("begin"); + sqlx::query("SET LOCAL statement_timeout = '10ms'") + .execute(&mut *tx) + .await + .expect("set timeout"); + let err: buzz_db::DbError = sqlx::query("SELECT pg_sleep(1)") + .execute(&mut *tx) + .await + .expect_err("statement must be cancelled") + .into(); + assert!(err.is_statement_cancelled()); + + let (status, body) = db_read_error("ctx", &err); + assert_eq!(status, StatusCode::SERVICE_UNAVAILABLE); + assert_eq!(body.0["error"], QUERY_TIMED_OUT); + } +} + // ── parse_query_or_400 regression tests ────────────────────────────────────── #[cfg(test)] diff --git a/crates/buzz-relay/src/connection.rs b/crates/buzz-relay/src/connection.rs index 12a450861e..63060fe0be 100644 --- a/crates/buzz-relay/src/connection.rs +++ b/crates/buzz-relay/src/connection.rs @@ -16,7 +16,6 @@ use uuid::Uuid; use buzz_auth::{generate_challenge, AuthContext}; use buzz_core::tenant::TenantContext; -use nostr::Filter; use crate::handlers; use crate::metrics::AuthOutcome; @@ -34,8 +33,9 @@ const AUTH_TIMEOUT: Duration = Duration::from_secs(5); /// This stays well inside the process-wide 30-second hard drain. const WS_TERMINAL_FLUSH_TIMEOUT: Duration = Duration::from_secs(1); -/// Shared mutable subscription map for a single WebSocket connection. -pub(crate) type ConnectionSubscriptions = Arc>>>; +/// Shared mutable subscription map for a single WebSocket connection: sub ID → +/// owner token of the request that currently holds it (see `close::next_owner`). +pub(crate) type ConnectionSubscriptions = Arc>>; /// Request for the writer to flush a restart close and report the result. pub(crate) struct RestartClose { @@ -447,20 +447,7 @@ async fn handle_active_connection( let _ = auth_timeout_task.await; let _ = auth_cancel_task.await; - for removed in state.sub_registry.remove_connection(conn.conn_id) { - if removed.scope.is_global() { - state - .pubsub - .release_topic(&conn.tenant, buzz_pubsub::EventTopic::Global) - .await; - } - for &channel_id in removed.scope.channel_ids() { - state - .pubsub - .release_topic(&conn.tenant, buzz_pubsub::EventTopic::Channel(channel_id)) - .await; - } - } + crate::handlers::close::release_connection_subscriptions(&conn, &state).await; state.conn_manager.deregister(conn.conn_id); if let Some(auth_ctx) = authenticated { let remaining = state.conn_manager.connection_ids_for_pubkey_in_community( diff --git a/crates/buzz-relay/src/handlers/close.rs b/crates/buzz-relay/src/handlers/close.rs index 86f3d0da79..0fdb4dd167 100644 --- a/crates/buzz-relay/src/handlers/close.rs +++ b/crates/buzz-relay/src/handlers/close.rs @@ -1,35 +1,137 @@ +use std::collections::HashMap; +use std::sync::atomic::{AtomicU64, Ordering}; use std::sync::Arc; +use buzz_core::tenant::TenantContext; +use buzz_pubsub::EventTopic; + use tracing::debug; use crate::connection::ConnectionState; use crate::protocol::RelayMessage; use crate::state::AppState; +use crate::subscription::SubscriptionScope; /// Handle a CLOSE command — remove the subscription and send CLOSED acknowledgement. pub async fn handle_close(sub_id: String, conn: Arc, state: Arc) { - let conn_id = conn.conn_id; + // Client CLOSE targets whatever currently holds the ID, so it is + // unconditional. Retiring before CLOSED means nothing is routed to this + // sub after the acknowledgement. + let mut subs = conn.subscriptions.lock().await; + retire_locked(&mut subs, &sub_id, &conn, &state).await; + conn.send(RelayMessage::closed(&sub_id, "")); + drop(subs); - conn.subscriptions.lock().await.remove(&sub_id); + debug!(conn_id = %conn.conn_id, sub_id = %sub_id, "Subscription closed"); +} - // Deregister from the fan-out index before sending CLOSED so no new - // messages are routed to this sub after the client's CLOSE is acknowledged. - if let Some(removed) = state.sub_registry.remove_subscription(conn_id, &sub_id) { - if removed.scope.is_global() { - state - .pubsub - .release_topic(&conn.tenant, buzz_pubsub::EventTopic::Global) - .await; - } - for &channel_id in removed.scope.channel_ids() { - state - .pubsub - .release_topic(&conn.tenant, buzz_pubsub::EventTopic::Channel(channel_id)) - .await; +/// Monotonic source of subscription owner tokens. Each REQ claims its sub ID +/// with a fresh token, so a superseded request can tell it no longer owns it. +static NEXT_OWNER: AtomicU64 = AtomicU64::new(1); + +pub(crate) fn next_owner() -> u64 { + NEXT_OWNER.fetch_add(1, Ordering::Relaxed) +} + +// Lifecycle lock: `conn.subscriptions` serializes every change to a +// connection's subscription state — map token, registry entry, topic +// retention, and the terminal CLOSED frame. Neither the registry nor pubsub +// takes it, so holding it across their awaits cannot invert lock order. + +/// Drop `sub_id` from the map, the fan-out index, and its topic retention. +/// The caller holds the lifecycle lock (`subs`). +pub(crate) async fn retire_locked( + subs: &mut HashMap, + sub_id: &str, + conn: &ConnectionState, + state: &AppState, +) { + subs.remove(sub_id); + if let Some(removed) = state.sub_registry.remove_subscription(conn.conn_id, sub_id) { + release_scope_topics(state, &conn.tenant, &removed.scope).await; + } +} + +/// Retire `sub_id` only if the request holding `owner` still owns it, then +/// send `closed` (if any) before releasing the lifecycle lock, so a replacing +/// REQ can never claim the ID between the teardown and its terminal frame. +/// Returns whether this request still owned the ID. A superseded request +/// touches nothing and says nothing. +pub(crate) async fn close_if_owner( + sub_id: &str, + owner: u64, + closed: Option<&str>, + conn: &ConnectionState, + state: &AppState, +) -> bool { + let mut subs = conn.subscriptions.lock().await; + if subs.get(sub_id) != Some(&owner) { + return false; + } + retire_locked(&mut subs, sub_id, conn, state).await; + #[cfg(test)] + test_seam::pause().await; + if let Some(reason) = closed { + if !conn.send(RelayMessage::closed(sub_id, reason)) { + // The outbound channel is full or closed: the terminal frame is + // lost. Cancel the connection so the subscription is not silently + // orphaned — the client will reconnect and resubscribe. + conn.cancel.cancel(); + } + } + true +} + +/// Final subscription cleanup for a closed connection. Its cancellation token +/// must already be cancelled: claims check it under the lifecycle lock, so no +/// detached REQ task can register after this runs. +pub(crate) async fn release_connection_subscriptions(conn: &ConnectionState, state: &AppState) { + debug_assert!(conn.cancel.is_cancelled()); + let mut subs = conn.subscriptions.lock().await; + subs.clear(); + for removed in state.sub_registry.remove_connection(conn.conn_id) { + release_scope_topics(state, &conn.tenant, &removed.scope).await; + } +} + +/// Release the pubsub topics a subscription scope retained. +pub(crate) async fn release_scope_topics( + state: &AppState, + tenant: &TenantContext, + scope: &SubscriptionScope, +) { + if scope.is_global() { + state.pubsub.release_topic(tenant, EventTopic::Global).await; + } + for &channel_id in scope.channel_ids() { + state + .pubsub + .release_topic(tenant, EventTopic::Channel(channel_id)) + .await; + } +} + +/// Test-only pause point inside `close_if_owner`, between teardown and the +/// terminal frame, scoped to one task so parallel tests don't interfere. +#[cfg(test)] +pub(crate) mod test_seam { + use std::sync::Arc; + use tokio::sync::Notify; + + #[derive(Default)] + pub(crate) struct Pause { + pub(crate) reached: Notify, + pub(crate) resume: Notify, + } + + tokio::task_local! { + pub(crate) static PAUSE: Arc; + } + + pub(super) async fn pause() { + if let Ok(pause) = PAUSE.try_with(Arc::clone) { + pause.reached.notify_one(); + pause.resume.notified().await; } } - - conn.send(RelayMessage::closed(&sub_id, "")); - - debug!(conn_id = %conn_id, sub_id = %sub_id, "Subscription closed"); } diff --git a/crates/buzz-relay/src/handlers/count.rs b/crates/buzz-relay/src/handlers/count.rs index 5ea30b238b..50a77e42ef 100644 --- a/crates/buzz-relay/src/handlers/count.rs +++ b/crates/buzz-relay/src/handlers/count.rs @@ -198,7 +198,10 @@ pub async fn handle_count( match state.db.count_events_routed("count_req", &query).await { Ok(n) => total += n as u64, Err(e) => { - conn.send(RelayMessage::closed(&sub_id, &format!("error: {e}"))); + conn.send(RelayMessage::closed( + &sub_id, + &super::req::db_read_closed_reason(&e), + )); return; } } @@ -232,7 +235,10 @@ pub async fn handle_count( } } Err(e) => { - conn.send(RelayMessage::closed(&sub_id, &format!("error: {e}"))); + conn.send(RelayMessage::closed( + &sub_id, + &super::req::db_read_closed_reason(&e), + )); return; } } @@ -272,7 +278,10 @@ pub async fn handle_count( match state.db.count_events_routed("count_req", &query).await { Ok(n) => total += n as u64, Err(e) => { - conn.send(RelayMessage::closed(&sub_id, &format!("error: {e}"))); + conn.send(RelayMessage::closed( + &sub_id, + &super::req::db_read_closed_reason(&e), + )); return; } } @@ -305,7 +314,10 @@ pub async fn handle_count( } } Err(e) => { - conn.send(RelayMessage::closed(&sub_id, &format!("error: {e}"))); + conn.send(RelayMessage::closed( + &sub_id, + &super::req::db_read_closed_reason(&e), + )); return; } } diff --git a/crates/buzz-relay/src/handlers/req.rs b/crates/buzz-relay/src/handlers/req.rs index 97d252cb7e..a428f1e821 100644 --- a/crates/buzz-relay/src/handlers/req.rs +++ b/crates/buzz-relay/src/handlers/req.rs @@ -267,8 +267,12 @@ pub async fn handle_req( )); return; } + let Some(owner) = claim_search_subscription(&sub_id, &conn, &state).await else { + return; + }; handle_search_req( &sub_id, + owner, &filters, &accessible_channels, token_channel_ids.is_none(), @@ -279,47 +283,22 @@ pub async fn handle_req( trace_state.as_ref(), ) .await; + // One-shot: drop the claim unless a newer REQ already took the ID. + super::close::close_if_owner(&sub_id, owner, None, &conn, &state).await; return; } - { - let mut subs = conn.subscriptions.lock().await; - subs.insert(sub_id.clone(), filters.clone()); - } - - let replaced = if let Some(channel_ids) = authorized_requested_channels.as_ref() { - state.sub_registry.register_channels_scoped( - conn.tenant.community(), - conn_id, - sub_id.clone(), - filters.clone(), - channel_ids.clone(), - ) - } else { - state.sub_registry.register_scoped( - conn.tenant.community(), - conn_id, - sub_id.clone(), - filters.clone(), - None, - ) + let Some(owner) = claim_live_subscription( + &sub_id, + &filters, + authorized_requested_channels.as_deref(), + &conn, + &state, + ) + .await + else { + return; }; - if let Some(replaced) = replaced { - release_subscription_topics(&state, &conn.tenant, &replaced.scope).await; - } - if let Some(channel_ids) = authorized_requested_channels.as_ref() { - for &channel_id in channel_ids { - state - .pubsub - .retain_topic(&conn.tenant, EventTopic::Channel(channel_id)) - .await; - } - } else { - state - .pubsub - .retain_topic(&conn.tenant, EventTopic::Global) - .await; - } debug!(conn_id = %conn_id, sub_id = %sub_id, "Subscription registered"); @@ -396,7 +375,11 @@ pub async fn handle_req( Ok(evs) => evs, Err(e) => { warn!(conn_id = %conn_id, sub_id = %sub_id, "Historical query failed: {e}"); - conn.send(RelayMessage::eose(&sub_id)); + if e.is_statement_cancelled() { + close_timed_out_subscription(&sub_id, owner, &conn, &state).await; + } else { + conn.send(RelayMessage::eose(&sub_id)); + } return; } }; @@ -597,6 +580,7 @@ pub(crate) fn build_search_channel_scope_filter( #[allow(clippy::too_many_arguments)] async fn handle_search_req( sub_id: &str, + owner: u64, filters: &[Filter], accessible_channels: &[uuid::Uuid], include_global: bool, @@ -724,6 +708,12 @@ async fn handle_search_req( .await { Ok(evs) => evs, + Err(e) if e.is_statement_cancelled() => { + // CLOSED (not EOSE) keeps partial results from reading as complete. + warn!(sub_id = %sub_id, "NIP-50 batch fetch timed out: {e}"); + close_timed_out_subscription(sub_id, owner, conn, state).await; + return; + } Err(e) => { warn!(sub_id = %sub_id, "NIP-50 batch fetch failed: {e}"); break; @@ -1269,21 +1259,107 @@ async fn handle_huddle_liveness_req( conn.send(RelayMessage::eose(sub_id)); } -async fn release_subscription_topics( +/// Claim `sub_id` for a live REQ under the lifecycle lock: record a fresh +/// owner token, register for fan-out (replacing any same-ID entry), retain its +/// topics, and release the replaced scope's. Returns the owner token, or +/// `None` once the connection is closing — the caller then exits silently. +async fn claim_live_subscription( + sub_id: &str, + filters: &[Filter], + channel_ids: Option<&[uuid::Uuid]>, + conn: &ConnectionState, state: &AppState, - tenant: &TenantContext, - scope: &crate::subscription::SubscriptionScope, -) { - if scope.is_global() { - state.pubsub.release_topic(tenant, EventTopic::Global).await; - } else { - for &channel_id in scope.channel_ids() { +) -> Option { + let mut subs = conn.subscriptions.lock().await; + if conn.cancel.is_cancelled() { + return None; + } + let owner = super::close::next_owner(); + subs.insert(sub_id.to_string(), owner); + let community = conn.tenant.community(); + let replaced = match channel_ids { + Some(ids) => state.sub_registry.register_channels_scoped( + community, + conn.conn_id, + sub_id.to_string(), + filters.to_vec(), + ids.to_vec(), + ), + None => state.sub_registry.register_scoped( + community, + conn.conn_id, + sub_id.to_string(), + filters.to_vec(), + None, + ), + }; + match channel_ids { + Some(ids) => { + for &channel_id in ids { + state + .pubsub + .retain_topic(&conn.tenant, EventTopic::Channel(channel_id)) + .await; + } + } + None => { state .pubsub - .release_topic(tenant, EventTopic::Channel(channel_id)) + .retain_topic(&conn.tenant, EventTopic::Global) .await; } } + if let Some(replaced) = replaced { + super::close::release_scope_topics(state, &conn.tenant, &replaced.scope).await; + } + Some(owner) +} + +/// Claim `sub_id` for a one-shot search REQ under the lifecycle lock. +/// Accepting it retires whatever holds the ID (NIP-01 replacement), even +/// though search never registers for fan-out. `None` once the connection is +/// closing. +async fn claim_search_subscription( + sub_id: &str, + conn: &ConnectionState, + state: &AppState, +) -> Option { + let mut subs = conn.subscriptions.lock().await; + if conn.cancel.is_cancelled() { + return None; + } + super::close::retire_locked(&mut subs, sub_id, conn, state).await; + let owner = super::close::next_owner(); + subs.insert(sub_id.to_string(), owner); + Some(owner) +} + +/// A read hit the server statement deadline. Sends `CLOSED` rather than `EOSE` +/// so clients don't treat the empty result as complete. CLOSED means the relay +/// dropped the sub (NIP-01) and clients won't `CLOSE` it, so it is retired in +/// the same lifecycle-lock critical section. A request a newer same-ID REQ +/// superseded owns nothing and says nothing. +async fn close_timed_out_subscription( + sub_id: &str, + owner: u64, + conn: &ConnectionState, + state: &AppState, +) { + super::close::close_if_owner(sub_id, owner, Some(QUERY_TIMED_OUT_CLOSED), conn, state).await; +} + +/// Stable CLOSED reason for a read cancelled by its server statement deadline. +/// Clients match it to skip retrying the same expensive query. +pub(crate) const QUERY_TIMED_OUT_CLOSED: &str = "error: query timed out"; + +/// CLOSED reason for a failed one-shot DB read (COUNT): a statement cancel gets +/// the stable timeout reason; anything else keeps the raw error. +pub(crate) fn db_read_closed_reason(e: &buzz_db::DbError) -> String { + if e.is_statement_cancelled() { + QUERY_TIMED_OUT_CLOSED.to_string() + } else { + format!("error: {e}") + } } fn extract_channel_id_from_filters(filters: &[Filter]) -> Option { @@ -1554,6 +1630,491 @@ mod tests { use super::*; use nostr::{Alphabet, Filter, SingleLetterTag}; + fn lifecycle_conn() -> ( + ConnectionState, + tokio::sync::mpsc::Receiver, + ) { + use std::sync::atomic::AtomicU8; + let (send_tx, send_rx) = tokio::sync::mpsc::channel(8); + let (ctrl_tx, _ctrl_rx) = tokio::sync::mpsc::channel(1); + let community = buzz_core::tenant::CommunityId::from_uuid(uuid::Uuid::new_v4()); + let conn = ConnectionState { + conn_id: uuid::Uuid::new_v4(), + tenant: buzz_core::tenant::TenantContext::resolved(community, "t.local".to_string()), + remote_addr: "127.0.0.1:1234".parse().expect("addr"), + auth_state: std::sync::Mutex::new(AuthState::Failed), + subscriptions: Arc::new(tokio::sync::Mutex::new(std::collections::HashMap::new())), + send_tx, + ctrl_tx, + cancel: tokio_util::sync::CancellationToken::new(), + backpressure_count: Arc::new(AtomicU8::new(0)), + grace_limit: 3, + }; + (conn, send_rx) + } + + fn text_filters() -> Vec { + vec![Filter::new().kind(nostr::Kind::TextNote)] + } + + fn registered(state: &AppState, conn: &ConnectionState, sub_id: &str) -> bool { + state + .sub_registry + .get_filters(conn.conn_id, sub_id) + .is_some() + } + + fn closed_frames( + rx: &mut tokio::sync::mpsc::Receiver, + ) -> Vec { + std::iter::from_fn(|| rx.try_recv().ok()) + .map(|msg| match msg { + axum::extract::ws::Message::Text(t) => t.to_string(), + other => panic!("expected text frame, got {other:?}"), + }) + .collect() + } + + #[tokio::test] + async fn timed_out_historical_read_deregisters_before_closed() { + let state = crate::state::tests::test_state().await; + let (conn, mut send_rx) = lifecycle_conn(); + let channel = uuid::Uuid::new_v4(); + let topic = EventTopic::Channel(channel); + let owner = + claim_live_subscription("thread", &text_filters(), Some(&[channel]), &conn, &state) + .await + .expect("claim"); + assert_eq!(state.pubsub.topic_refcount(&conn.tenant, topic).await, 1); + + close_timed_out_subscription("thread", owner, &conn, &state).await; + + assert!(conn.subscriptions.lock().await.is_empty()); + assert!( + !registered(&state, &conn, "thread"), + "fan-out registration must be gone" + ); + assert_eq!( + state.pubsub.topic_refcount(&conn.tenant, topic).await, + 0, + "retained topic must be released" + ); + assert_eq!( + closed_frames(&mut send_rx), + vec![format!(r#"["CLOSED","thread","{QUERY_TIMED_OUT_CLOSED}"]"#)] + ); + } + + /// A superseded REQ's late timeout must not tear down, or send a terminal + /// CLOSED for, the same-ID replacement that now owns the ID. + #[tokio::test] + async fn superseded_timeout_leaves_replacement_intact() { + let state = crate::state::tests::test_state().await; + let (conn, mut send_rx) = lifecycle_conn(); + let (old_channel, new_channel) = (uuid::Uuid::new_v4(), uuid::Uuid::new_v4()); + let (old_topic, new_topic) = ( + EventTopic::Channel(old_channel), + EventTopic::Channel(new_channel), + ); + let old = + claim_live_subscription("x", &text_filters(), Some(&[old_channel]), &conn, &state) + .await + .expect("claim"); + let new = + claim_live_subscription("x", &text_filters(), Some(&[new_channel]), &conn, &state) + .await + .expect("claim"); + assert_eq!( + state.pubsub.topic_refcount(&conn.tenant, old_topic).await, + 0 + ); + + close_timed_out_subscription("x", old, &conn, &state).await; + + assert_eq!(conn.subscriptions.lock().await.get("x"), Some(&new)); + assert!( + registered(&state, &conn, "x"), + "replacement must stay registered" + ); + assert_eq!( + state.pubsub.topic_refcount(&conn.tenant, new_topic).await, + 1, + "replacement topic must stay retained" + ); + assert!( + closed_frames(&mut send_rx).is_empty(), + "superseded request must say nothing" + ); + } + + /// Accepting a search REQ retires the live subscription holding its ID, and + /// a search that a newer live REQ supersedes cannot close that REQ. + #[tokio::test] + async fn search_claim_retires_live_and_yields_to_replacement() { + let state = crate::state::tests::test_state().await; + let (conn, mut send_rx) = lifecycle_conn(); + let channel = uuid::Uuid::new_v4(); + let topic = EventTopic::Channel(channel); + claim_live_subscription("x", &text_filters(), Some(&[channel]), &conn, &state) + .await + .expect("claim"); + + let search = claim_search_subscription("x", &conn, &state) + .await + .expect("claim"); + assert!( + !registered(&state, &conn, "x"), + "search must retire live fan-out" + ); + assert_eq!(state.pubsub.topic_refcount(&conn.tenant, topic).await, 0); + + let live = claim_live_subscription("x", &text_filters(), Some(&[channel]), &conn, &state) + .await + .expect("claim"); + close_timed_out_subscription("x", search, &conn, &state).await; + + assert_eq!(conn.subscriptions.lock().await.get("x"), Some(&live)); + assert!(registered(&state, &conn, "x")); + assert_eq!(state.pubsub.topic_refcount(&conn.tenant, topic).await, 1); + assert!(closed_frames(&mut send_rx).is_empty()); + } + + /// Concurrent same-ID claims and stale teardowns: whichever claim lands + /// last owns the ID, and every stale teardown is a silent no-op. + #[tokio::test] + async fn concurrent_claims_and_stale_teardowns_keep_the_last_owner() { + let state = crate::state::tests::test_state().await; + let (conn, mut send_rx) = lifecycle_conn(); + let conn = Arc::new(conn); + let channel = uuid::Uuid::new_v4(); + let topic = EventTopic::Channel(channel); + let stale = claim_live_subscription("x", &text_filters(), Some(&[channel]), &conn, &state) + .await + .expect("claim"); + + let tasks = (0..16).map(|i| { + let (conn, state) = (Arc::clone(&conn), Arc::clone(&state)); + tokio::spawn(async move { + if i % 2 == 0 { + claim_live_subscription("x", &text_filters(), Some(&[channel]), &conn, &state) + .await + .expect("claim"); + } else { + close_timed_out_subscription("x", stale, &conn, &state).await; + } + }) + }); + for task in tasks.collect::>() { + task.await.expect("task"); + } + + let owner = *conn.subscriptions.lock().await.get("x").expect("x owned"); + assert_ne!(owner, stale); + assert!(registered(&state, &conn, "x")); + assert_eq!(state.pubsub.topic_refcount(&conn.tenant, topic).await, 1); + close_timed_out_subscription("x", owner, &conn, &state).await; + assert_eq!(state.pubsub.topic_refcount(&conn.tenant, topic).await, 0); + assert_eq!( + closed_frames(&mut send_rx), + vec![format!(r#"["CLOSED","x","{QUERY_TIMED_OUT_CLOSED}"]"#)], + "only the final owner's teardown may close" + ); + } + + fn subscribed(state: &AppState, conn: &ConnectionState, channel: uuid::Uuid) -> bool { + state + .sub_registry + .channel_subscriber_conns_scoped(conn.tenant.community(), channel) + .contains(&conn.conn_id) + } + + /// Poll `fut` exactly once and require it to park. A contender for a held + /// tokio mutex enqueues its waiter and returns `Pending` on that poll, so + /// this proves it reached its lock attempt without relying on scheduling. + async fn assert_parked(fut: &mut F, what: &str) { + let parked = std::future::poll_fn(|cx| { + std::task::Poll::Ready(std::pin::Pin::new(&mut *fut).poll(cx).is_pending()) + }) + .await; + assert!(parked, "{what} must be waiting on the lifecycle lock"); + } + + /// The owner's teardown and its terminal CLOSED are one critical section: + /// a replacement claiming meanwhile waits, so it can never be the target of + /// the old request's CLOSED. + #[tokio::test] + async fn timeout_closed_is_emitted_before_a_replacement_can_claim() { + use super::super::close::test_seam::{Pause, PAUSE}; + let state = crate::state::tests::test_state().await; + let (conn, mut send_rx) = lifecycle_conn(); + let conn = Arc::new(conn); + let (a, b) = (uuid::Uuid::new_v4(), uuid::Uuid::new_v4()); + let old = claim_live_subscription("x", &text_filters(), Some(&[a]), &conn, &state) + .await + .expect("claim"); + + let pause = Arc::new(Pause::default()); + let teardown = tokio::spawn(PAUSE.scope(Arc::clone(&pause), { + let (conn, state) = (Arc::clone(&conn), Arc::clone(&state)); + async move { close_timed_out_subscription("x", old, &conn, &state).await } + })); + pause.reached.notified().await; + let (filters, b_scope) = (text_filters(), [b]); + let mut replacement = Box::pin(claim_live_subscription( + "x", + &filters, + Some(&b_scope), + &conn, + &state, + )); + assert_parked(&mut replacement, "replacement").await; + assert!( + !subscribed(&state, &conn, b), + "replacement must not claim between teardown and CLOSED" + ); + assert!(closed_frames(&mut send_rx).is_empty()); + + pause.resume.notify_one(); + teardown.await.expect("teardown"); + let new = replacement.await.expect("claim"); + + assert_eq!( + closed_frames(&mut send_rx), + vec![format!(r#"["CLOSED","x","{QUERY_TIMED_OUT_CLOSED}"]"#)] + ); + assert_eq!(conn.subscriptions.lock().await.get("x"), Some(&new)); + assert!(subscribed(&state, &conn, b) && !subscribed(&state, &conn, a)); + let refcount = |c| { + state + .pubsub + .topic_refcount(&conn.tenant, EventTopic::Channel(c)) + }; + assert_eq!((refcount(a).await, refcount(b).await), (0, 1)); + } + + /// Revoke selects and removes registry entries under the lifecycle lock, so + /// a same-ID replacement queued behind it keeps its token, scope and topic. + #[tokio::test] + async fn revoke_then_replacement_keeps_replacement_whole() { + let state = crate::state::tests::test_state().await; + let (conn, mut send_rx) = lifecycle_conn(); + let conn = Arc::new(conn); + state.conn_manager.register( + conn.conn_id, + conn.send_tx.clone(), + conn.ctrl_tx.clone(), + None, + conn.cancel.clone(), + conn.tenant.community(), + Arc::clone(&conn.backpressure_count), + Arc::clone(&conn.subscriptions), + 3, + ); + let (a, b) = (uuid::Uuid::new_v4(), uuid::Uuid::new_v4()); + claim_live_subscription("x", &text_filters(), Some(&[a]), &conn, &state) + .await + .expect("claim"); + + let guard = conn.subscriptions.lock().await; + let mut revoke = Box::pin( + crate::handlers::side_effects::evict_conn_channel_subscriptions( + &conn.tenant, + &state, + a, + conn.conn_id, + ), + ); + assert_parked(&mut revoke, "revoke").await; + let (filters, b_scope) = (text_filters(), [b]); + let mut replacement = Box::pin(claim_live_subscription( + "x", + &filters, + Some(&b_scope), + &conn, + &state, + )); + assert_parked(&mut replacement, "replacement").await; + assert!( + subscribed(&state, &conn, a), + "revoke must not touch the registry before taking the lifecycle lock" + ); + drop(guard); + // The tokio mutex is FIFO: revoke queued first, so it runs first. + revoke.await; + let new = replacement.await.expect("claim"); + + assert_eq!(conn.subscriptions.lock().await.get("x"), Some(&new)); + assert!(subscribed(&state, &conn, b) && !subscribed(&state, &conn, a)); + let refcount = |c| { + state + .pubsub + .topic_refcount(&conn.tenant, EventTopic::Channel(c)) + }; + assert_eq!((refcount(a).await, refcount(b).await), (0, 1)); + assert_eq!( + closed_frames(&mut send_rx), + vec![r#"["CLOSED","x","restricted: channel access revoked"]"#.to_string()] + ); + state.conn_manager.deregister(conn.conn_id); + } + + /// Connection cleanup fences later claims: a detached REQ task resuming + /// after it gets `None` and leaves nothing behind. + #[tokio::test] + async fn claims_after_connection_cleanup_are_refused() { + let state = crate::state::tests::test_state().await; + let (conn, mut send_rx) = lifecycle_conn(); + let channel = uuid::Uuid::new_v4(); + let topic = EventTopic::Channel(channel); + claim_live_subscription("live", &text_filters(), Some(&[channel]), &conn, &state) + .await + .expect("claim"); + + conn.cancel.cancel(); + super::super::close::release_connection_subscriptions(&conn, &state).await; + let late_live = + claim_live_subscription("late", &text_filters(), Some(&[channel]), &conn, &state).await; + let late_search = claim_search_subscription("search", &conn, &state).await; + + assert_eq!((late_live, late_search), (None, None)); + assert!(conn.subscriptions.lock().await.is_empty()); + for sub in ["live", "late", "search"] { + assert!( + !registered(&state, &conn, sub), + "{sub} must not be registered" + ); + } + assert_eq!(state.pubsub.topic_refcount(&conn.tenant, topic).await, 0); + assert!(closed_frames(&mut send_rx).is_empty()); + } + + /// A terminal CLOSED that fails to enqueue after retirement cancels the + /// connection, so the subscription is never silently orphaned on a + /// congested connection. + /// + /// Regression for P2-2: before this fix, a `false` from `conn.send` was + /// silently ignored after retirement, leaving the subscription retired but + /// the connection alive without a CLOSED delivered to the client. + #[tokio::test] + async fn dropped_terminal_frame_cancels_connection() { + use std::sync::atomic::AtomicU8; + let state = crate::state::tests::test_state().await; + // Capacity-1 channel: one dummy message fills it, so the CLOSED + // `try_send` returns Full (below the grace_limit=3 auto-cancel) and + // the fix's explicit cancel must fire. + let (send_tx, mut send_rx) = tokio::sync::mpsc::channel(1); + let (ctrl_tx, _ctrl_rx) = tokio::sync::mpsc::channel(1); + let community = buzz_core::tenant::CommunityId::from_uuid(uuid::Uuid::new_v4()); + let conn = Arc::new(ConnectionState { + conn_id: uuid::Uuid::new_v4(), + tenant: buzz_core::tenant::TenantContext::resolved(community, "t.local".to_string()), + remote_addr: "127.0.0.1:1234".parse().expect("addr"), + auth_state: std::sync::Mutex::new(AuthState::Failed), + subscriptions: Arc::new(tokio::sync::Mutex::new(std::collections::HashMap::new())), + send_tx, + ctrl_tx, + cancel: tokio_util::sync::CancellationToken::new(), + backpressure_count: Arc::new(AtomicU8::new(0)), + grace_limit: 3, + }); + + // Claim, then fill the send buffer so the next `send` returns false. + let owner = claim_live_subscription("x", &text_filters(), None, &conn, &state) + .await + .expect("claim"); + // Occupy the one slot so try_send returns Full on the CLOSED. + send_rx.try_recv().ok(); // drain any prior messages + let _ = conn.send_tx.try_send(axum::extract::ws::Message::Text( + "filler".to_string().into(), + )); + assert!(!conn.cancel.is_cancelled(), "must not be cancelled yet"); + + // `close_timed_out_subscription` retires the sub and tries to send CLOSED. + // With the buffer full the frame is dropped and the fix must cancel. + close_timed_out_subscription("x", owner, &conn, &state).await; + + assert!( + conn.cancel.is_cancelled(), + "connection must be cancelled when the terminal frame is dropped" + ); + // The subscription is still retired — the map is empty. + assert!(conn.subscriptions.lock().await.is_empty()); + assert!(!registered(&state, &conn, "x")); + } + + /// A revoke `CLOSED restricted` that fails to enqueue after the map remove + /// cancels the connection, same as the timeout path. + /// + /// Regression for P2-2 (revoke branch): before this fix, a `false` from + /// `send_to` in `evict_conn_channel_subscriptions` was silently ignored + /// after retirement, leaving the subscription orphaned on a congested + /// connection. + #[tokio::test] + async fn revoke_dropped_terminal_frame_cancels_connection() { + use std::sync::atomic::AtomicU8; + let state = crate::state::tests::test_state().await; + // Capacity-1 channel: one dummy message fills it so the CLOSED + // restricted `try_send` returns Full (below grace_limit=3) and the + // fix's explicit cancel_conn must fire. + let (send_tx, mut send_rx) = tokio::sync::mpsc::channel(1); + let (ctrl_tx, _ctrl_rx) = tokio::sync::mpsc::channel(1); + let community = buzz_core::tenant::CommunityId::from_uuid(uuid::Uuid::new_v4()); + let conn = Arc::new(ConnectionState { + conn_id: uuid::Uuid::new_v4(), + tenant: buzz_core::tenant::TenantContext::resolved(community, "t.local".to_string()), + remote_addr: "127.0.0.1:1234".parse().expect("addr"), + auth_state: std::sync::Mutex::new(AuthState::Failed), + subscriptions: Arc::new(tokio::sync::Mutex::new(std::collections::HashMap::new())), + send_tx: send_tx.clone(), + ctrl_tx, + cancel: tokio_util::sync::CancellationToken::new(), + backpressure_count: Arc::new(AtomicU8::new(0)), + grace_limit: 3, + }); + // Register in conn_manager so evict_conn_channel_subscriptions can + // find the connection for cancel_conn. + state.conn_manager.register( + conn.conn_id, + send_tx, + conn.ctrl_tx.clone(), + None, + conn.cancel.clone(), + conn.tenant.community(), + Arc::clone(&conn.backpressure_count), + Arc::clone(&conn.subscriptions), + 3, + ); + + let channel = uuid::Uuid::new_v4(); + claim_live_subscription("x", &text_filters(), Some(&[channel]), &conn, &state) + .await + .expect("claim"); + + // Fill the one send slot so the CLOSED restricted try_send returns Full. + send_rx.try_recv().ok(); // drain any earlier messages + let _ = conn.send_tx.try_send(axum::extract::ws::Message::Text( + "filler".to_string().into(), + )); + assert!(!conn.cancel.is_cancelled(), "must not be cancelled yet"); + + crate::handlers::side_effects::evict_conn_channel_subscriptions( + &conn.tenant, + &state, + channel, + conn.conn_id, + ) + .await; + + assert!( + conn.cancel.is_cancelled(), + "connection must be cancelled when the revoke terminal frame is dropped" + ); + assert!(conn.subscriptions.lock().await.is_empty()); + assert!(!subscribed(&state, &conn, channel)); + + state.conn_manager.deregister(conn.conn_id); + } + #[test] fn huddle_liveness_filters_require_only_the_snapshot_kind() { let liveness = Filter::new().kind(nostr::Kind::Custom(KIND_HUDDLE_LIVENESS as u16)); diff --git a/crates/buzz-relay/src/handlers/side_effects.rs b/crates/buzz-relay/src/handlers/side_effects.rs index f63c174d96..c2131b1a55 100644 --- a/crates/buzz-relay/src/handlers/side_effects.rs +++ b/crates/buzz-relay/src/handlers/side_effects.rs @@ -231,41 +231,42 @@ async fn disable_departed_member_workflows( } /// Close every live channel-scoped subscription on `conn_id`, removing them from -/// the connection's local map and sending `CLOSED restricted` for each. -async fn evict_conn_channel_subscriptions( +/// the connection's local map and sending `CLOSED restricted` for each. Runs +/// under the connection's lifecycle lock so a concurrent same-ID claim is +/// either fully before (and revoked) or fully after (and untouched). +pub(crate) async fn evict_conn_channel_subscriptions( tenant: &TenantContext, state: &Arc, channel_id: Uuid, conn_id: uuid::Uuid, ) { + // No map means the connection already ran its final cleanup, which + // removed its registry entries under this same lock. + let Some(subscriptions) = state.conn_manager.subscriptions_for(conn_id) else { + return; + }; + let mut conn_subscriptions = subscriptions.lock().await; let removed = state.sub_registry.remove_channel_subscriptions_scoped( tenant.community(), conn_id, channel_id, ); - if removed.is_empty() { - return; - } - - if let Some(subscriptions) = state.conn_manager.subscriptions_for(conn_id) { - let mut conn_subscriptions = subscriptions.lock().await; - for update in &removed { - if update.removed { - conn_subscriptions.remove(&update.sub_id); - } - } - } - for update in removed { + // A multi-channel sub keeps its other channels (and its map token). state .pubsub .release_topic(tenant, buzz_pubsub::EventTopic::Channel(channel_id)) .await; if update.removed { - let _ = state.conn_manager.send_to( + conn_subscriptions.remove(&update.sub_id); + if !state.conn_manager.send_to( conn_id, RelayMessage::closed(&update.sub_id, "restricted: channel access revoked"), - ); + ) { + // Terminal frame lost — cancel so the subscription is not + // silently orphaned on a congested connection. + state.conn_manager.cancel_conn(conn_id); + } } } } diff --git a/crates/buzz-relay/src/state.rs b/crates/buzz-relay/src/state.rs index 0bcab5d63a..417e9bb763 100644 --- a/crates/buzz-relay/src/state.rs +++ b/crates/buzz-relay/src/state.rs @@ -459,6 +459,14 @@ impl ConnectionManager { .and_then(|entry| entry.authenticated_pubkey.read().ok()?.clone()) } + /// Cancel a single connection by ID. A no-op if the connection is not + /// registered (already deregistered or never known). + pub(crate) fn cancel_conn(&self, conn_id: Uuid) { + if let Some(entry) = self.connections.get(&conn_id) { + entry.cancel.cancel(); + } + } + /// Disconnect every live connection authenticated as `pubkey` **in /// `community`**, delivering a final `OK false` frame carrying `reason` /// before closing. diff --git a/desktop/src-tauri/src/native_relay_client_finite_tests.rs b/desktop/src-tauri/src/native_relay_client_finite_tests.rs index 913d17f5fd..7b236b98ac 100644 --- a/desktop/src-tauri/src/native_relay_client_finite_tests.rs +++ b/desktop/src-tauri/src/native_relay_client_finite_tests.rs @@ -101,6 +101,7 @@ async fn terminal_refusal_and_deadline_do_not_become_empty_success() { for message in [ "restricted: denied", "error: transient", + "error: query timed out", "rate-limited: quota exceeded; retry in 10s", "rate-limited: quota exceeded", "rate-limited: quota exceeded; retry in 18446744073709551615s", diff --git a/desktop/src-tauri/src/native_relay_client_tests.rs b/desktop/src-tauri/src/native_relay_client_tests.rs index f12a689449..ee284be518 100644 --- a/desktop/src-tauri/src/native_relay_client_tests.rs +++ b/desktop/src-tauri/src/native_relay_client_tests.rs @@ -328,6 +328,32 @@ async fn a_closed_subscription_reopens_without_a_desired_set_change() { session.shutdown(); } +/// A statement deadline on a persistent subscription is transient (archive +/// subs are `limit: 0` live tails), so it backs off and reopens rather than +/// latching terminal. Finite requests still fail on it; see +/// `native_relay_client_finite_tests.rs`. +#[tokio::test] +async fn a_deadline_closed_subscription_reopens_after_backoff() { + let (relay_url, mut frames, closed) = stub_relay().await; + let (session, _events) = start(relay_url, Keys::generate(), None).await; + + session.set_subscriptions(vec![probe_subscription()]).await; + assert_eq!(next_req(&mut frames, "the initial REQ").await, PROBE_ID); + settle().await; + + closed + .send(StubCommand::Closed( + PROBE_ID.into(), + "error: query timed out".into(), + )) + .await + .expect("stub relay accepts the closed command"); + + assert_eq!(next_req(&mut frames, "the reopened REQ").await, PROBE_ID); + + session.shutdown(); +} + /// A relay that rejects on policy must not be re-asked in a tight loop. #[tokio::test] async fn a_terminal_closed_is_not_retried_on_the_same_socket() { diff --git a/desktop/src/features/messages/lib/renderScopedReactions.test.mjs b/desktop/src/features/messages/lib/renderScopedReactions.test.mjs index 6429ecf811..37d971b268 100644 --- a/desktop/src/features/messages/lib/renderScopedReactions.test.mjs +++ b/desktop/src/features/messages/lib/renderScopedReactions.test.mjs @@ -174,3 +174,30 @@ test("failed hydration releases ids so the next render can retry", async () => { [messageId], ); }); + +for (const message of [ + "error: query timed out", + "relay returned 503 Service Unavailable: query timed out", +]) { + test(`deadline-failed hydration keeps ids claimed: ${message}`, async () => { + const messageId = hex("1"); + const queryClient = makeQueryClientStub([event(messageId, 9)]); + + await hydrateRenderScopedReactions({ + channelId: CHANNEL_ID, + messageIds: [messageId], + queryClient, + deps: { + fetchReactionEventsForMessages: async () => { + throw new Error(message); + }, + }, + }); + + // Still claimed: the next render must not re-send the same slow read. + assert.deepEqual( + claimUnhydratedRenderScopedReactionIds(CHANNEL_ID, [messageId]), + [], + ); + }); +} diff --git a/desktop/src/features/messages/lib/renderScopedReactions.ts b/desktop/src/features/messages/lib/renderScopedReactions.ts index 2c35cdf79e..e5128770e8 100644 --- a/desktop/src/features/messages/lib/renderScopedReactions.ts +++ b/desktop/src/features/messages/lib/renderScopedReactions.ts @@ -6,6 +6,7 @@ import type { TimelineMessage } from "../types"; import { relayClient } from "@/shared/api/relayClient"; import { buildChannelReactionAuxFilter } from "@/shared/api/relayChannelFilters"; import type { RelayEvent } from "@/shared/api/types"; +import { isQueryDeadlineError } from "@/shared/lib/relayError"; export type RenderScopedReactionDeps = { fetchReactionEventsForMessages: ( @@ -24,9 +25,22 @@ const defaultDeps: RenderScopedReactionDeps = { }; const hydratedMessageIdsByChannel = new Map>(); +// Ids held claimed after a relay deadline, so automatic re-renders skip them +// until the user reopens the channel. +const deadlineClaimedIdsByChannel = new Map>(); export function resetRenderScopedReactionHydration() { hydratedMessageIdsByChannel.clear(); + deadlineClaimedIdsByChannel.clear(); +} + +export function releaseDeadlineClaimedReactionIds(channelId: string) { + const ids = deadlineClaimedIdsByChannel.get(channelId); + if (!ids) { + return; + } + deadlineClaimedIdsByChannel.delete(channelId); + releaseRenderScopedReactionIds(channelId, [...ids]); } function hydratedSetForChannel(channelId: string): Set { @@ -130,7 +144,19 @@ export async function hydrateRenderScopedReactions(input: { (current = []) => sortMessages([...current, ...reactionEvents]), ); } catch (error) { - releaseRenderScopedReactionIds(input.channelId, messageIds); + // Keep deadline-failed ids claimed: releasing them lets the next render + // re-send the same slow `#e` read. Reopening the channel releases them; + // other failures stay retryable immediately. + if (isQueryDeadlineError(error)) { + let held = deadlineClaimedIdsByChannel.get(input.channelId); + if (!held) { + held = new Set(); + deadlineClaimedIdsByChannel.set(input.channelId, held); + } + for (const id of messageIds) held.add(id); + } else { + releaseRenderScopedReactionIds(input.channelId, messageIds); + } console.error( "Failed to hydrate visible reactions for channel", input.channelId, diff --git a/desktop/src/features/messages/lib/useRenderScopedReactionHydration.jsdom-test.mjs b/desktop/src/features/messages/lib/useRenderScopedReactionHydration.jsdom-test.mjs new file mode 100644 index 0000000000..97d3d6d2af --- /dev/null +++ b/desktop/src/features/messages/lib/useRenderScopedReactionHydration.jsdom-test.mjs @@ -0,0 +1,124 @@ +/** + * Reopen recovery for deadline-held reactions, through the production hook. + * + * A reaction fetch that hits the relay deadline keeps its ids claimed so + * automatic re-renders do not re-send the slow read. Reopening the channel is + * the explicit retry: the hook's `channelId` effect releases the held ids. + * + * Falsifiability: deleting the release effect in + * `useRenderScopedReactionHydration.ts` leaves the reopen with no fetch. + */ + +import assert from "node:assert/strict"; +import { afterEach, mock, test } from "node:test"; + +import React, { act } from "react"; +import { createRoot } from "react-dom/client"; +import { QueryClient, QueryClientProvider } from "@tanstack/react-query"; + +import { relayClient } from "@/shared/api/relayClient"; +import { channelMessagesKey } from "./messageQueryKeys.ts"; +import { resetRenderScopedReactionHydration } from "./renderScopedReactions.ts"; +import { useRenderScopedReactionHydration } from "./useRenderScopedReactionHydration.ts"; + +const CHANNEL_A = "36411e44-0e2d-4cfe-bd6e-567eb169db9f"; +const CHANNEL_B = "8a1c3f52-6d0e-4b7a-9c21-0f5e7d3b2a10"; +const MESSAGE_ID = "1".repeat(64); +const REACTION = { + id: "9".repeat(64), + pubkey: "a".repeat(64), + kind: 7, + created_at: 1_700_000_000, + content: "✅", + tags: [["e", MESSAGE_ID]], + sig: "sig", +}; + +afterEach(() => { + mock.restoreAll(); + resetRenderScopedReactionHydration(); +}); + +function Harness({ channelId, entries }) { + useRenderScopedReactionHydration({ + activeChannel: { id: channelId, channelType: "stream" }, + mainTimelineEntries: entries, + threadHeadMessage: null, + threadMessages: [], + }); + return null; +} + +async function flush() { + // Hydration is deferred with window.setTimeout(0). + await act(async () => { + await new Promise((resolve) => setTimeout(resolve, 10)); + }); +} + +test("reopening a channel refetches deadline-held reactions; same-channel re-renders do not", async () => { + const requests = []; + let failWithDeadline = true; + mock.method(relayClient, "fetchAuxEventsByReference", async (channelId) => { + requests.push(channelId); + if (channelId === CHANNEL_A && failWithDeadline) { + throw new Error("error: query timed out"); + } + return channelId === CHANNEL_A ? [REACTION] : []; + }); + mock.method(console, "error", () => {}); + + const queryClient = new QueryClient(); + queryClient.setQueryData(channelMessagesKey(CHANNEL_A), []); + const container = document.createElement("div"); + const root = createRoot(container); + const render = (channelId) => + act(() => { + root.render( + React.createElement( + QueryClientProvider, + { client: queryClient }, + React.createElement(Harness, { + channelId, + // Fresh array each render, as a live timeline update produces. + entries: [{ message: { id: MESSAGE_ID }, summary: null }], + }), + ), + ); + }); + + await render(CHANNEL_A); + await flush(); + assert.deepEqual( + requests, + [CHANNEL_A], + "first open fetches and hits the deadline", + ); + + failWithDeadline = false; + await render(CHANNEL_A); + await flush(); + assert.deepEqual( + requests, + [CHANNEL_A], + "same-channel re-render keeps ids held", + ); + + await render(CHANNEL_B); + await flush(); + await render(CHANNEL_A); + await flush(); + assert.deepEqual( + requests, + [CHANNEL_A, CHANNEL_B, CHANNEL_A], + "reopening channel A refetches its held ids", + ); + assert.ok( + queryClient + .getQueryData(channelMessagesKey(CHANNEL_A)) + .some((event) => event.id === REACTION.id), + "recovered reaction lands in the channel cache", + ); + + act(() => root.unmount()); +}); diff --git a/desktop/src/features/messages/lib/useRenderScopedReactionHydration.ts b/desktop/src/features/messages/lib/useRenderScopedReactionHydration.ts index 8bc3f7724c..641bf80cde 100644 --- a/desktop/src/features/messages/lib/useRenderScopedReactionHydration.ts +++ b/desktop/src/features/messages/lib/useRenderScopedReactionHydration.ts @@ -7,6 +7,7 @@ import type { Channel } from "@/shared/api/types"; import { collectRenderScopedReactionMessageIds, hydrateRenderScopedReactions, + releaseDeadlineClaimedReactionIds, } from "./renderScopedReactions"; export function useRenderScopedReactionHydration(input: { @@ -16,6 +17,13 @@ export function useRenderScopedReactionHydration(input: { threadMessages: MainTimelineEntry[]; }) { const queryClient = useQueryClient(); + const channelId = input.activeChannel?.id; + + // Opening a channel is the explicit retry for reactions a relay deadline + // held back. Declared first so it runs before this render's hydration. + React.useEffect(() => { + if (channelId) releaseDeadlineClaimedReactionIds(channelId); + }, [channelId]); React.useEffect(() => { const channelId = input.activeChannel?.id; diff --git a/desktop/src/features/messages/queryDeadlineRetry.test.mjs b/desktop/src/features/messages/queryDeadlineRetry.test.mjs new file mode 100644 index 0000000000..c8dd559bfa --- /dev/null +++ b/desktop/src/features/messages/queryDeadlineRetry.test.mjs @@ -0,0 +1,154 @@ +/** + * Deadline-retry contract, exercised under the production QueryClient: + * a read that hit the relay's `query timed out` deadline is fetched once; an + * ordinary failure, including a client-side request timeout, keeps its retries. + * Removing the predicate from `createBuzzQueryClient` or `useThreadReplies` + * makes the deadline cases here fetch more than once. + */ + +import assert from "node:assert/strict"; +import { mock } from "node:test"; +import test from "node:test"; +import { registerHooks } from "node:module"; + +import { JSDOM } from "jsdom"; + +globalThis.__tauriGetThreadReplies = async () => ({ + events: [], + nextCursor: null, +}); + +registerHooks({ + resolve(specifier, context, nextResolve) { + if (specifier === "@/shared/api/tauri") { + return { shortCircuit: true, url: "buzz-deadline-stub:tauri" }; + } + return nextResolve(specifier, context); + }, + load(url, context, nextLoad) { + if (url === "buzz-deadline-stub:tauri") { + return { + format: "module", + shortCircuit: true, + source: `export async function getThreadReplies(...args) { + return globalThis.__tauriGetThreadReplies(...args); +} +export default {};`, + }; + } + return nextLoad(url, context); + }, +}); + +const dom = new JSDOM("", { + url: "http://localhost", + pretendToBeVisual: true, +}); +dom.window.document.hasFocus = () => true; +Object.assign(globalThis, { + IS_REACT_ACT_ENVIRONMENT: true, + document: dom.window.document, + HTMLElement: dom.window.HTMLElement, + window: dom.window, +}); + +const { act, cleanup, renderHook } = await import("@testing-library/react"); +const { createElement } = await import("react"); +const { QueryClientProvider, useQuery } = await import("@tanstack/react-query"); +const { createBuzzQueryClient } = await import("@/shared/api/queryClient"); +const { useThreadReplies, useThreadRepliesForRoots } = await import( + "./useThreadReplies.ts" +); + +const CASES = [ + { + name: "client request timeout", + message: "relay unreachable: request timed out", + deadline: false, + }, + { + name: "relay deadline", + message: "relay returned 503 Service Unavailable: query timed out", + deadline: true, + }, + { + name: "ordinary error", + message: "relay returned 500: internal server error", + deadline: false, + }, +]; + +// Mount `useHook` under the production client, drive every retry delay with +// fake timers until the query settles in error, and return the fetch count. +async function fetchCountUntilError(useHook, isSettled) { + mock.timers.enable({ apis: ["setTimeout"] }); + const queryClient = createBuzzQueryClient(); + const wrapper = ({ children }) => + createElement(QueryClientProvider, { client: queryClient }, children); + try { + const { result, unmount } = renderHook(useHook, { wrapper }); + for (let i = 0; i < 20 && !isSettled(result.current); i++) { + mock.timers.tick(60_000); + await act(async () => { + await new Promise((resolve) => setImmediate(resolve)); + }); + } + assert.ok(isSettled(result.current), "query never settled in error"); + unmount(); + } finally { + cleanup(); + queryClient.clear(); + mock.timers.reset(); + } +} + +for (const { name, message, deadline } of CASES) { + test(`createBuzzQueryClient default retry: ${name}`, async () => { + let calls = 0; + await fetchCountUntilError( + () => + useQuery({ + queryKey: ["deadline-default", name], + queryFn: async () => { + calls += 1; + throw new Error(message); + }, + }), + (r) => r.isError, + ); + assert.equal(calls, deadline ? 1 : 2); + }); + + test(`useThreadRepliesForRoots (3 roots) retry: ${name}`, async () => { + const calls = new Map(); + globalThis.__tauriGetThreadReplies = async (rootId) => { + calls.set(rootId, (calls.get(rootId) ?? 0) + 1); + throw new Error(message); + }; + const channel = { id: `chan-roots-${name}`, channelType: "group" }; + const roots = ["root-a", "root-b", "root-c"]; + await fetchCountUntilError( + () => useThreadRepliesForRoots(channel, roots), + (r) => r.isError && !r.isPending, + ); + assert.deepEqual( + Object.fromEntries(calls), + Object.fromEntries(roots.map((root) => [root, deadline ? 1 : 2])), + ); + }); + + test(`useThreadReplies single-root retry: ${name}`, async () => { + let calls = 0; + globalThis.__tauriGetThreadReplies = async () => { + calls += 1; + throw new Error(message); + }; + const channel = { id: `chan-single-${name}`, channelType: "group" }; + await fetchCountUntilError( + () => useThreadReplies(channel, "root-single"), + (r) => r.isError, + ); + // useThreadReplies keeps its own `< 3` retries for ordinary failures. + assert.equal(calls, deadline ? 1 : 4); + }); +} diff --git a/desktop/src/features/messages/useThreadReplies.ts b/desktop/src/features/messages/useThreadReplies.ts index 9ad86e46a8..e23eb2a189 100644 --- a/desktop/src/features/messages/useThreadReplies.ts +++ b/desktop/src/features/messages/useThreadReplies.ts @@ -11,6 +11,7 @@ import { sortMessages, } from "@/features/messages/lib/messageQueryKeys"; import { getThreadReplies } from "@/shared/api/tauri"; +import { isQueryDeadlineError } from "@/shared/lib/relayError"; import type { Channel, RelayEvent, @@ -163,7 +164,10 @@ export function useThreadReplies( // throws on attempts 1 and 2; attempt 3 records exhaustion first so // loadThreadReplies returns data directly — the terminal attempt always // resolves to success. - retry: 3, + // A read that hit the relay's statement deadline is not retried: + // each retry would re-run the same slow server-side query. + retry: (failureCount, error) => + failureCount < 3 && !isQueryDeadlineError(error), retryDelay: (attempt) => Math.min(1_000 * 2 ** attempt, 30_000), }); diff --git a/desktop/src/features/profile/profileBatchResilience.test.mjs b/desktop/src/features/profile/profileBatchResilience.test.mjs index 53f8c1ff11..7939581600 100644 --- a/desktop/src/features/profile/profileBatchResilience.test.mjs +++ b/desktop/src/features/profile/profileBatchResilience.test.mjs @@ -43,8 +43,13 @@ test("useUsersBatchQuery: global queryClient defaults are unchanged", async () = new URL("../../shared/api/queryClient.ts", import.meta.url), "utf8", ); - // Global retry must remain 1 — other queries chose that semantics. - assert.match(source, /retry:\s*1/, "global retry default must remain 1"); + // Global retry budget must remain 1 — other queries chose that semantics. + // Query-deadline failures are exempt so a slow server query is not re-run. + assert.match( + source, + /failureCount < 1 && !isQueryDeadlineError\(error\)/, + "global retry default must remain 1, skipping query deadlines", + ); // Global refetchOnWindowFocus must remain false. assert.match( source, diff --git a/desktop/src/shared/api/queryClient.ts b/desktop/src/shared/api/queryClient.ts index 6302f4e064..5590f1d967 100644 --- a/desktop/src/shared/api/queryClient.ts +++ b/desktop/src/shared/api/queryClient.ts @@ -1,5 +1,6 @@ import { focusManager, QueryClient } from "@tanstack/react-query"; +import { isQueryDeadlineError } from "@/shared/lib/relayError"; import { isAppFocused, subscribeAppFocus, @@ -25,7 +26,10 @@ export function createBuzzQueryClient() { return new QueryClient({ defaultOptions: { queries: { - retry: 1, + // One retry, except after the relay's `query timed out` answer: that + // would re-run the same slow server-side query. + retry: (failureCount, error) => + failureCount < 1 && !isQueryDeadlineError(error), refetchOnWindowFocus: false, networkMode: "always", gcTime: 5 * 60 * 1_000, diff --git a/desktop/src/shared/api/relayClosedPolicy.test.mjs b/desktop/src/shared/api/relayClosedPolicy.test.mjs index 2e5cad4b7c..49f8189cca 100644 --- a/desktop/src/shared/api/relayClosedPolicy.test.mjs +++ b/desktop/src/shared/api/relayClosedPolicy.test.mjs @@ -26,6 +26,7 @@ test("classifyRelayClosed: terminal messages return terminal", () => { "unsupported: filter", "error: mixed search and non-search filters not supported", "error: too many subscriptions", + "error: query timed out", ]) { assert.equal(classifyRelayClosed(message), "terminal", message); } diff --git a/desktop/src/shared/api/relayClosedPolicy.ts b/desktop/src/shared/api/relayClosedPolicy.ts index 9e747a2df1..a5ff5372ef 100644 --- a/desktop/src/shared/api/relayClosedPolicy.ts +++ b/desktop/src/shared/api/relayClosedPolicy.ts @@ -32,7 +32,10 @@ export function classifyRelayClosed(message: string): RelayClosedClass { normalized.startsWith("duplicate:") || normalized.startsWith("unsupported:") || normalized.startsWith("error: mixed search") || - normalized.startsWith("error: too many subscriptions") + normalized.startsWith("error: too many subscriptions") || + // Server statement deadline: re-sending the same REQ re-runs the same + // slow query, so a live retry loop would hammer the database. + normalized.startsWith("error: query timed out") ) { return "terminal"; } diff --git a/desktop/src/shared/api/relayClosedRecovery.test.mjs b/desktop/src/shared/api/relayClosedRecovery.test.mjs index de75aad3ba..c09b90e4c5 100644 --- a/desktop/src/shared/api/relayClosedRecovery.test.mjs +++ b/desktop/src/shared/api/relayClosedRecovery.test.mjs @@ -670,6 +670,35 @@ test("terminal CLOSED deletes subscription and does not retry", () => { assert.equal(firedAt.length, 0, "terminal CLOSED must not retry"); }); +test("live CLOSED query deadline retries with backoff instead of removing", () => { + resetAll(0); + const firedAt = []; + const subscriptions = new Map([ + [ + "live-1", + { + mode: "live", + filter: { kinds: [9], "#h": ["ch-1"], limit: 1000 }, + onEvent: () => {}, + resolveReady: () => {}, + }, + ], + ]); + handleRelayClosed({ + subscriptions, + subId: "live-1", + message: "error: query timed out", + sendReq: () => { + firedAt.push(fakeNow); + return Promise.resolve(); + }, + }); + assert.equal(subscriptions.has("live-1"), true, "live sub must survive"); + assert.equal(firedAt.length, 0, "retry waits for backoff"); + tickTo(10_000); + assert.equal(firedAt.length, 1, "live sub must be re-sent after backoff"); +}); + // ── Test: rejecting closeSubscription does not produce an unhandled rejection ─ // // Load-bearing for the `.catch(() => {})` guard on the op-timeout CLOSE send. diff --git a/desktop/src/shared/api/relayClosedRecovery.ts b/desktop/src/shared/api/relayClosedRecovery.ts index cf04d83126..348d55e299 100644 --- a/desktop/src/shared/api/relayClosedRecovery.ts +++ b/desktop/src/shared/api/relayClosedRecovery.ts @@ -1,4 +1,5 @@ import { classifyRelayClosed } from "@/shared/api/relayClosedPolicy"; +import { isQueryDeadlineError } from "@/shared/lib/relayError"; import { activateRateLimit, parseRateLimitHint, @@ -132,7 +133,13 @@ function recoverLiveSubscriptionFromClosed({ subscription.resolveReady?.("closed"); subscription.resolveReady = undefined; - const closedClass = classifyRelayClosed(message); + // A deadline on a live sub is treated as retryable: resubscribe with the + // same filter under the 1-30s backoff, which can keep retrying at the cap. + // `since` is deliberately not advanced to now; that could skip events + // missed while the sub was closed. + const closedClass = isQueryDeadlineError(message) + ? "retryable" + : classifyRelayClosed(message); if (closedClass === "terminal") { // Auth/access/filter failure — permanently remove the subscription so it diff --git a/desktop/src/shared/lib/relayError.test.mjs b/desktop/src/shared/lib/relayError.test.mjs index 7ae121f2b5..07b018b9b1 100644 --- a/desktop/src/shared/lib/relayError.test.mjs +++ b/desktop/src/shared/lib/relayError.test.mjs @@ -1,7 +1,7 @@ import assert from "node:assert/strict"; import test from "node:test"; -import { isRelayUnreachableError } from "./relayError.ts"; +import { isQueryDeadlineError, isRelayUnreachableError } from "./relayError.ts"; test("isRelayUnreachableError: Error with prefix returns true", () => { assert.equal( @@ -55,3 +55,39 @@ test("isRelayUnreachableError: plain object returns false", () => { false, ); }); + +test("isQueryDeadlineError: relay statement deadline, HTTP and WS forms", () => { + assert.equal( + isQueryDeadlineError( + new Error("relay returned 503 Service Unavailable: query timed out"), + ), + true, + ); + assert.equal(isQueryDeadlineError("error: query timed out"), true); +}); + +test("isQueryDeadlineError: client-side timeouts stay retryable", () => { + for (const message of [ + "relay unreachable: request timed out", + "relay request timed out", + "relay request timed out or cancelled", + ]) { + assert.equal(isQueryDeadlineError(new Error(message)), false, message); + } +}); + +test("isQueryDeadlineError: other relay errors stay retryable", () => { + assert.equal( + isQueryDeadlineError( + new Error( + "relay returned 500 Internal Server Error: internal server error", + ), + ), + false, + ); + assert.equal( + isQueryDeadlineError(new Error("relay unreachable: 403")), + false, + ); + assert.equal(isQueryDeadlineError(undefined), false); +}); diff --git a/desktop/src/shared/lib/relayError.ts b/desktop/src/shared/lib/relayError.ts index ca16aa41e2..285a8651fd 100644 --- a/desktop/src/shared/lib/relayError.ts +++ b/desktop/src/shared/lib/relayError.ts @@ -32,3 +32,14 @@ export function isRelayUnreachableError(error: unknown): boolean { } return false; } + +/** + * Returns true only for the relay's own statement-deadline answer: HTTP 503 + * `query timed out` or WS CLOSED `error: query timed out`. Retrying re-runs + * the same expensive query, so callers should not. Client-side timeouts + * (`request timed out`) are network stalls and stay retryable. + */ +export function isQueryDeadlineError(error: unknown): boolean { + const message = error instanceof Error ? error.message : String(error); + return message.includes("query timed out"); +} diff --git a/mobile/lib/features/channels/channel_detail_page.dart b/mobile/lib/features/channels/channel_detail_page.dart index 468dbb0486..d518bd1878 100644 --- a/mobile/lib/features/channels/channel_detail_page.dart +++ b/mobile/lib/features/channels/channel_detail_page.dart @@ -25,6 +25,7 @@ import '../../shared/widgets/frosted_app_bar.dart'; import '../../shared/widgets/frosted_scaffold.dart'; import '../../shared/widgets/flapping_bee.dart'; import '../../shared/widgets/keyboard_dismiss_on_drag.dart'; +import '../../shared/widgets/load_error_view.dart'; import '../../shared/widgets/ios_glass_navigation_button.dart'; import '../../shared/widgets/masked_avatar_badge.dart'; import '../../shared/widgets/message_author_meta.dart'; @@ -715,12 +716,10 @@ class ChannelDetailPage extends HookConsumerWidget { titleContentHeight: appBarTitleContentHeight, ), ), - child: Center( - child: Text( - 'Failed to load messages', - style: context.textTheme.bodyMedium?.copyWith( - color: context.colors.error, - ), + child: LoadErrorView( + message: 'Failed to load messages', + onRetry: () => ref.invalidate( + channelMessagesProvider(channel.id), ), ), ), diff --git a/mobile/lib/features/channels/channel_messages_provider.dart b/mobile/lib/features/channels/channel_messages_provider.dart index 221aef367a..a87fdf7c7f 100644 --- a/mobile/lib/features/channels/channel_messages_provider.dart +++ b/mobile/lib/features/channels/channel_messages_provider.dart @@ -247,6 +247,8 @@ class ChannelMessagesNotifier extends Notifier>> { } catch (error) { _initialWindowQueryInFlight = false; _liveSummaryRootsDuringInitialWindowQuery.clear(); + // Legacy history would re-run the timed-out work another way. + if (isRelayDeadlineError(error)) rethrow; debugPrint( '[ChannelMessagesNotifier] channel window unavailable for $channelId, falling back to WS history: $error', ); diff --git a/mobile/lib/features/channels/channel_messages_provider/thread_summaries.dart b/mobile/lib/features/channels/channel_messages_provider/thread_summaries.dart index 7fa36c2b14..7d22de342b 100644 --- a/mobile/lib/features/channels/channel_messages_provider/thread_summaries.dart +++ b/mobile/lib/features/channels/channel_messages_provider/thread_summaries.dart @@ -332,7 +332,8 @@ extension _ThreadSummaryState on ChannelMessagesNotifier { } } catch (error) { if (!current()) return; - if (attempt < 2) { + // Re-sending a timed-out recount re-runs the same slow scan. + if (attempt < 2 && !isRelayDeadlineError(error)) { // Retain this active queue slot during backoff, so retries share the // same concurrency budget and stop when newer work supersedes them. await Future.delayed(Duration(milliseconds: 500 << attempt)); diff --git a/mobile/lib/features/channels/channels_provider.dart b/mobile/lib/features/channels/channels_provider.dart index c5a77ba930..982e39fa2a 100644 --- a/mobile/lib/features/channels/channels_provider.dart +++ b/mobile/lib/features/channels/channels_provider.dart @@ -338,8 +338,18 @@ class ChannelsNotifier extends AsyncNotifier> { _fetchLastMessageEvents(session, activeChannels), ); final lastMessageMap = {}; + // An unavailable batch keeps the timestamps already known rather than + // installing channels whose latest message looks absent. + if (events == null) { + for (final channel in state.value ?? const []) { + final at = channel.lastMessageAt; + if (at != null) { + lastMessageMap[channel.id] = at.millisecondsSinceEpoch ~/ 1000; + } + } + } final mutedChannelIds = _mutedChannelIds(); - for (final event in events) { + for (final event in events ?? const []) { final channelId = event.channelId; if (channelId == null) continue; final channel = channelById[channelId]; @@ -423,7 +433,7 @@ class ChannelsNotifier extends AsyncNotifier> { /// bridge request. The relay preserves NIP-01 per-filter limits while /// executing the filters with bounded concurrency, avoiding an unbounded /// burst of websocket REQs on communities with many channels. - Future> _fetchLastMessageEvents( + Future?> _fetchLastMessageEvents( RelaySessionNotifier session, List channels, ) async { @@ -447,7 +457,8 @@ class ChannelsNotifier extends AsyncNotifier> { ); } - Future> _fetchChannelHistoryBatch( + /// Returns null when the batch is unavailable: it hit a relay deadline. + Future?> _fetchChannelHistoryBatch( RelaySessionNotifier session, List filters, { required String operation, @@ -457,6 +468,11 @@ class ChannelsNotifier extends AsyncNotifier> { try { return await session.queryRelay(filters); } catch (error) { + // Per-filter fallback would re-run the timed-out work another way. + if (isRelayDeadlineError(error)) { + debugPrint('[ChannelsNotifier] batched $operation hit the deadline'); + return null; + } debugPrint( '[ChannelsNotifier] batched $operation failed; ' 'using bounded websocket fallback: $error', @@ -465,13 +481,19 @@ class ChannelsNotifier extends AsyncNotifier> { const fallbackConcurrency = 4; final events = []; + var deadline = false; for (var start = 0; start < filters.length; start += fallbackConcurrency) { + // Stop sending once a filter hit the deadline; partial events are not + // a result. + if (deadline) return null; final end = min(start + fallbackConcurrency, filters.length); final results = await Future.wait( filters.sublist(start, end).map((filter) async { try { return await session.fetchHistory(filter); - } catch (_) { + } catch (error) { + // A timed-out filter makes the batch unavailable, not empty. + if (isRelayDeadlineError(error)) deadline = true; return const []; } }), @@ -480,6 +502,7 @@ class ChannelsNotifier extends AsyncNotifier> { events.addAll(result); } } + if (deadline) return null; return events; } @@ -592,6 +615,8 @@ class ChannelsNotifier extends AsyncNotifier> { filters, operation: 'unread catch-up', ); + // Unavailable: keep the unread state already observed. + if (events == null) return; // The relay round-trip above is the window Jed's probes park in: a newer // refresh, a community switch or an identity switch here means every // write below belongs to a channel list the user has left. @@ -605,7 +630,7 @@ class ChannelsNotifier extends AsyncNotifier> { } } - var recorded = false; + final recordedAtByChannel = {}; for (final event in events) { final channelId = event.channelId; if (channelId == null) continue; @@ -626,15 +651,25 @@ class ChannelsNotifier extends AsyncNotifier> { continue; } _recordUnreadEvent(channel, event, myPk); - recorded = true; + recordedAtByChannel[channelId] = max( + recordedAtByChannel[channelId] ?? 0, + event.createdAt, + ); } // Republish only when this catch-up actually changed unread state. A // batch that recorded nothing has nothing to show, and a failed or // superseded batch must not repaint another refresh's list: the retired // check above already returned in that case, and no await separates it // from here, so a second check would be dead code. - if (recorded) { - state = state.whenData((channels) => List.of(channels)); + // Recorded events also advance `lastMessageAt`, as live events do: a + // deadline-unavailable latest-message batch leaves it unset. + if (recordedAtByChannel.isNotEmpty) { + state = state.whenData( + (channels) => [ + for (final channel in channels) + _advanceLastMessageAt(channel, recordedAtByChannel[channel.id]), + ], + ); } } catch (error) { if (!ref.mounted) return; @@ -642,6 +677,17 @@ class ChannelsNotifier extends AsyncNotifier> { } } + static Channel _advanceLastMessageAt(Channel channel, int? createdAt) { + if (createdAt == null) return channel; + final at = DateTime.fromMillisecondsSinceEpoch( + createdAt * 1000, + isUtc: true, + ); + final current = channel.lastMessageAt; + if (current != null && !at.isAfter(current)) return channel; + return channel.copyWith(lastMessageAt: at); + } + void _handleLiveEvent(NostrEvent event) { final channelId = event.channelId; if (channelId == null) return; diff --git a/mobile/lib/features/channels/thread_detail_helpers.dart b/mobile/lib/features/channels/thread_detail_helpers.dart index 7ff39fac53..fdb92f6020 100644 --- a/mobile/lib/features/channels/thread_detail_helpers.dart +++ b/mobile/lib/features/channels/thread_detail_helpers.dart @@ -173,3 +173,23 @@ class _ThreadTypingIndicator extends StatelessWidget { ); } } + +/// Display evidence while the authoritative thread query has no value (still +/// loading, or failed on first load): the route snapshot plus live, cached +/// and optimistic replies. The page keeps the query's loading/error status, +/// so this list is never presented as complete, and nothing is re-queried. +List _provisionalThreadMessages( + List routeSnapshot, + List observed, + List liveChannelEvents, +) { + final byId = { + for (final message in routeSnapshot) + if (!_isDeletedBy(liveChannelEvents, message.id)) message.id: message, + for (final message in observed) message.id: message, + }; + return byId.values.toList()..sort((a, b) { + final order = a.createdAt.compareTo(b.createdAt); + return order != 0 ? order : a.id.compareTo(b.id); + }); +} diff --git a/mobile/lib/features/channels/thread_detail_page.dart b/mobile/lib/features/channels/thread_detail_page.dart index 0bb4cedb34..56d7015b0f 100644 --- a/mobile/lib/features/channels/thread_detail_page.dart +++ b/mobile/lib/features/channels/thread_detail_page.dart @@ -4,6 +4,7 @@ import 'dart:math' as math; import 'package:flutter/material.dart'; import 'package:flutter_hooks/flutter_hooks.dart'; import 'package:hooks_riverpod/hooks_riverpod.dart'; +import 'package:lucide_icons_flutter/lucide_icons.dart'; import 'package:scrollable_positioned_list/scrollable_positioned_list.dart'; import '../../shared/mentions/agent_identity_provider.dart'; @@ -148,8 +149,13 @@ class ThreadDetailPage extends HookConsumerWidget { liveChannelEvents, threadHead.id, ); - final allMsgs = fetchedReplies == null - ? allMessages + final allMsgs = fetchedReplies == null || !relayRepliesAvailable + ? _provisionalThreadMessages( + allMessages, + fetchedReplies ?? + formatTimeline(liveChannelEvents, currentPubkey: currentPubkey), + liveChannelEvents, + ) : [ // Only fall back to the pushed-route snapshot when neither source // carries the head, and no live deletion has suppressed it. That @@ -894,6 +900,8 @@ class ThreadDetailPage extends HookConsumerWidget { bottomInset: timelineBottomInset, replies: replies, relayReplyState: relayReplyState, + onRetryReplies: () => + ref.invalidate(threadRepliesProvider(repliesArgs)), localSendAnimations: localSendAnimations, trackActiveScrollPosition: trackActiveScrollPosition, headIsDeleted: liveDeletionHidesHead, diff --git a/mobile/lib/features/channels/thread_detail_page/message_list.dart b/mobile/lib/features/channels/thread_detail_page/message_list.dart index a33aa9a4ee..28160ee88b 100644 --- a/mobile/lib/features/channels/thread_detail_page/message_list.dart +++ b/mobile/lib/features/channels/thread_detail_page/message_list.dart @@ -10,6 +10,7 @@ class _ThreadMessageList extends StatelessWidget { final double bottomInset; final List replies; final AsyncValue> relayReplyState; + final VoidCallback onRetryReplies; final Map localSendAnimations; final Widget Function(Widget child) trackActiveScrollPosition; final bool headIsDeleted; @@ -36,6 +37,7 @@ class _ThreadMessageList extends StatelessWidget { required this.bottomInset, required this.replies, required this.relayReplyState, + required this.onRetryReplies, required this.localSendAnimations, required this.trackActiveScrollPosition, required this.headIsDeleted, @@ -164,6 +166,17 @@ class _ThreadMessageList extends StatelessWidget { ), ), ), + if (relayReplyState.hasError && + !relayReplyState.isLoading) + IconButton( + key: const ValueKey('thread-replies-retry'), + onPressed: onRetryReplies, + tooltip: 'Retry', + icon: const Icon( + LucideIcons.refreshCcw, + size: 16, + ), + ), const SizedBox(width: Grid.xxs), Expanded( child: Divider( diff --git a/mobile/lib/features/forum/forum_posts_view.dart b/mobile/lib/features/forum/forum_posts_view.dart index 13880427cf..352c1bc73f 100644 --- a/mobile/lib/features/forum/forum_posts_view.dart +++ b/mobile/lib/features/forum/forum_posts_view.dart @@ -5,9 +5,11 @@ import 'package:flutter_hooks/flutter_hooks.dart'; import 'package:hooks_riverpod/hooks_riverpod.dart'; import 'package:lucide_icons_flutter/lucide_icons.dart'; +import '../../shared/relay/relay_closed_policy.dart'; import '../../shared/theme/theme.dart'; import '../../shared/widgets/buzz_loading_indicator.dart'; import '../../shared/widgets/frosted_app_bar.dart'; +import '../../shared/widgets/load_error_view.dart'; import '../../shared/widgets/bee_refresh_indicator.dart'; import '../channels/channel.dart'; import '../channels/compose_bar.dart'; @@ -39,10 +41,22 @@ class ForumPostsView extends HookConsumerWidget { final providerContainer = ProviderScope.containerOf(context, listen: false); final forumDelivery = ForumEventDelivery.capture(providerContainer); - // Periodic refresh (every 15s, matching desktop). + // Periodic refresh (every 15s, matching desktop). A settled deadline + // pauses polling; reopening the forum is the explicit retry. useEffect(() { + final provider = forumPostsProvider(channel.id); + // Only a deadline already settled when this surface mounts is a + // reopen; a first load that fails after mounting is not retried. + // Hooks run effects during build, so defer the invalidation past it. + if (isSettledRelayDeadline(ref.read(provider))) { + Future.microtask(() { + if (context.mounted) ref.invalidate(provider); + }); + } final timer = Stream.periodic(const Duration(seconds: 15)).listen((_) { - ref.invalidate(forumPostsProvider(channel.id)); + if (!isSettledRelayDeadline(ref.read(provider))) { + ref.invalidate(provider); + } }); return timer.cancel; }, [channel.id]); @@ -65,6 +79,8 @@ class ForumPostsView extends HookConsumerWidget { ) : null, body: postsAsync.when( + // A retry from an error shows loading, not the stale error and its Retry. + skipLoadingOnRefresh: !postsAsync.hasError, loading: () => Padding( padding: EdgeInsets.only(top: frostedAppBarHeight(context)), child: const Center( @@ -76,13 +92,9 @@ class ForumPostsView extends HookConsumerWidget { ), error: (e, _) => Padding( padding: EdgeInsets.only(top: frostedAppBarHeight(context)), - child: Center( - child: Text( - 'Failed to load posts', - style: context.textTheme.bodyMedium?.copyWith( - color: context.colors.error, - ), - ), + child: LoadErrorView( + message: 'Failed to load posts', + onRetry: () => ref.invalidate(forumPostsProvider(channel.id)), ), ), data: (response) { diff --git a/mobile/lib/features/forum/forum_thread_page.dart b/mobile/lib/features/forum/forum_thread_page.dart index 298630b42c..8b802bac4a 100644 --- a/mobile/lib/features/forum/forum_thread_page.dart +++ b/mobile/lib/features/forum/forum_thread_page.dart @@ -7,11 +7,13 @@ import 'package:hooks_riverpod/hooks_riverpod.dart'; import 'package:lucide_icons_flutter/lucide_icons.dart'; import '../../shared/mentions/agent_identity_provider.dart'; +import '../../shared/relay/relay_closed_policy.dart'; import '../../shared/theme/theme.dart'; import '../../shared/widgets/avatar_image.dart'; import '../../shared/widgets/buzz_loading_indicator.dart'; import '../../shared/widgets/frosted_app_bar.dart'; import '../../shared/widgets/frosted_scaffold.dart'; +import '../../shared/widgets/load_error_view.dart'; import '../../shared/widgets/modal_presentation.dart'; import '../channels/compose_bar.dart'; import '../channels/message_content.dart'; @@ -45,12 +47,25 @@ class ForumThreadPage extends HookConsumerWidget { forumThreadProvider((channelId: channelId, eventId: postEventId)), ); - // Periodic refresh (every 10s, matching desktop). + // Periodic refresh (every 10s, matching desktop). A settled deadline + // pauses polling; reopening the thread is the explicit retry. useEffect(() { + final provider = forumThreadProvider(( + channelId: channelId, + eventId: postEventId, + )); + // Only a deadline already settled when this surface mounts is a + // reopen; a first load that fails after mounting is not retried. + // Hooks run effects during build, so defer the invalidation past it. + if (isSettledRelayDeadline(ref.read(provider))) { + Future.microtask(() { + if (context.mounted) ref.invalidate(provider); + }); + } final timer = Stream.periodic(const Duration(seconds: 10)).listen((_) { - ref.invalidate( - forumThreadProvider((channelId: channelId, eventId: postEventId)), - ); + if (!isSettledRelayDeadline(ref.read(provider))) { + ref.invalidate(provider); + } }); return timer.cancel; }, [channelId, postEventId]); @@ -79,6 +94,8 @@ class ForumThreadPage extends HookConsumerWidget { ], ), body: threadAsync.when( + // A retry from an error shows loading, not the stale error and its Retry. + skipLoadingOnRefresh: !threadAsync.hasError, loading: () => Padding( padding: EdgeInsets.only(top: frostedAppBarHeight(context)), child: const Center( @@ -90,12 +107,10 @@ class ForumThreadPage extends HookConsumerWidget { ), error: (e, _) => Padding( padding: EdgeInsets.only(top: frostedAppBarHeight(context)), - child: Center( - child: Text( - 'Failed to load thread', - style: context.textTheme.bodyMedium?.copyWith( - color: context.colors.error, - ), + child: LoadErrorView( + message: 'Failed to load thread', + onRetry: () => ref.invalidate( + forumThreadProvider((channelId: channelId, eventId: postEventId)), ), ), ), diff --git a/mobile/lib/main.dart b/mobile/lib/main.dart index 5b40be40d3..6c1aa734df 100644 --- a/mobile/lib/main.dart +++ b/mobile/lib/main.dart @@ -6,6 +6,7 @@ import 'app.dart'; import 'features/age_gate/age_signal_push_bootstrap.dart'; import 'features/invites/invite_join_provider.dart'; import 'shared/push/push_bridge.dart'; +import 'shared/relay/relay_closed_policy.dart'; import 'shared/theme/theme_provider.dart'; void main() => runBuzzApp(const App()); @@ -18,16 +19,26 @@ Future runBuzzApp(Widget app) async { // Pre-load preferences so the first frame uses the saved theme/accent. final prefs = await SharedPreferences.getInstance(); - runApp( - ProviderScope( - overrides: [ - savedPrefsProvider.overrideWithValue(prefs), - inviteJoinRecoveryProvider.overrideWith( - (ref) => - (scope) => buildMobileInviteJoinRecovery(ref, scope), - ), - ], - child: AgeSignalPushBootstrap(child: app), - ), - ); + runApp(buildRootProviderScope(prefs: prefs, child: app)); } + +/// The app's root scope, shared with tests so its production wiring is +/// asserted rather than re-declared. +ProviderScope buildRootProviderScope({ + required SharedPreferences prefs, + required Widget child, +}) => ProviderScope( + // A relay statement deadline cannot resolve on retry — the same expensive + // query would re-run and hit the same limit. Return null (no retry) for + // deadline errors and fall through to the default exponential backoff for + // everything else. + retry: relayProviderRetry, + overrides: [ + savedPrefsProvider.overrideWithValue(prefs), + inviteJoinRecoveryProvider.overrideWith( + (ref) => + (scope) => buildMobileInviteJoinRecovery(ref, scope), + ), + ], + child: AgeSignalPushBootstrap(child: child), +); diff --git a/mobile/lib/shared/relay/relay_closed_policy.dart b/mobile/lib/shared/relay/relay_closed_policy.dart index d39084b189..4013470c7c 100644 --- a/mobile/lib/shared/relay/relay_closed_policy.dart +++ b/mobile/lib/shared/relay/relay_closed_policy.dart @@ -1,3 +1,50 @@ +import 'dart:convert'; + +import 'package:hooks_riverpod/hooks_riverpod.dart'; + +import 'relay_client.dart'; + +// Shared constant so [isRelayDeadlineError] and [classifyRelayClosed] cannot +// drift apart. +const _queryTimedOutPrefix = 'error: query timed out'; + +/// Returns true when [error] is a relay server-side statement deadline that +/// cannot be resolved by retrying the same query. +/// +/// Two surfaces carry the same deadline signal: +/// - HTTP `/query` or `/count`: [RelayException] with status 503 and a JSON +/// body containing `"error": "query timed out"`. +/// - WebSocket CLOSED: a plain [Exception] whose message is +/// `"error: query timed out"` (the relay's stable CLOSED reason string). +/// +/// Both surfaces are checked so the caller (e.g. a Riverpod retry hook) does +/// not need to distinguish which transport produced the error. +bool isRelayDeadlineError(Object error) { + if (error is RelayException && error.statusCode == 503) { + try { + final decoded = jsonDecode(error.body); + if (decoded is Map) { + final message = decoded['error']; + if (message is String && + message.trim().toLowerCase() == 'query timed out') { + return true; + } + } + } on FormatException { + // Non-JSON 503 — not a deadline. + } + return false; + } + // WebSocket history CLOSED: Exception("error: query timed out") + // Strip the "Exception: " prefix Flutter adds to Exception.toString(), then + // check via classifyRelayClosed so this path shares the same source of truth. + var message = error.toString().trim().toLowerCase(); + const prefix = 'exception: '; + if (message.startsWith(prefix)) message = message.substring(prefix.length); + return classifyRelayClosed(message) == RelayClosedClass.terminal && + message.startsWith(_queryTimedOutPrefix); +} + /// Recovery policy for a relay `CLOSED` subscription message. enum RelayClosedClass { /// A transient failure that may recover when the same REQ is retried. @@ -24,7 +71,10 @@ RelayClosedClass classifyRelayClosed(String message) { normalized.startsWith('duplicate:') || normalized.startsWith('unsupported:') || normalized.startsWith('error: mixed search') || - normalized.startsWith('error: too many subscriptions')) { + normalized.startsWith('error: too many subscriptions') || + // Server statement deadline: re-sending the same REQ re-runs the same + // slow query. + normalized.startsWith(_queryTimedOutPrefix)) { return RelayClosedClass.terminal; } return RelayClosedClass.retryable; @@ -37,3 +87,25 @@ int? parseRateLimitRetrySeconds(String message) { final match = _rateLimitRetryPattern.firstMatch(message); return match == null ? null : int.tryParse(match.group(1)!); } + +/// Whether [value] has settled on a relay deadline. +/// +/// The forum periodic poll timers pause while a query is in this state; +/// reopening the view is the explicit retry. Other refresh paths (reconnect, +/// resume, live events, unread backstop) still re-send, each bounded by the +/// relay's 20s statement deadline. +bool isSettledRelayDeadline(AsyncValue value) => + value.hasError && !value.isLoading && isRelayDeadlineError(value.error!); + +/// Production Riverpod retry policy for relay providers. +/// +/// A relay statement deadline cannot resolve on retry — the same expensive +/// query would re-run and hit the same limit. Returns `null` (no retry) for +/// deadline errors and falls through to [ProviderContainer.defaultRetry] for +/// everything else. +/// +/// Pass this to [ProviderScope.retry] at the root of the widget tree. +Duration? relayProviderRetry(int retryCount, Object error) { + if (isRelayDeadlineError(error)) return null; + return ProviderContainer.defaultRetry(retryCount, error); +} diff --git a/mobile/lib/shared/relay/relay_session.dart b/mobile/lib/shared/relay/relay_session.dart index 51fb8bf51d..ece4b9266b 100644 --- a/mobile/lib/shared/relay/relay_session.dart +++ b/mobile/lib/shared/relay/relay_session.dart @@ -730,7 +730,12 @@ class RelaySessionNotifier extends Notifier { final liveSub = _liveSubscriptions[subId]; if (liveSub == null) return; final readyCompleter = liveSub.readyCompleter; - if (closedClass == RelayClosedClass.terminal) { + // A deadline is terminal for one-shot history, but a live subscription + // retries it: same filter under backoff, which can keep retrying at the + // cap. `since` is not advanced, so events missed while closed aren't + // skipped. + if (closedClass == RelayClosedClass.terminal && + !isRelayDeadlineError(message)) { if (readyCompleter != null && !readyCompleter.isCompleted) { readyCompleter.completeError(Exception(message)); } diff --git a/mobile/lib/shared/widgets/load_error_view.dart b/mobile/lib/shared/widgets/load_error_view.dart new file mode 100644 index 0000000000..50952e3cb8 --- /dev/null +++ b/mobile/lib/shared/widgets/load_error_view.dart @@ -0,0 +1,47 @@ +import 'package:flutter/material.dart'; +import 'package:lucide_icons_flutter/lucide_icons.dart'; + +import '../theme/theme.dart'; + +/// Settled load failure with an explicit Retry. After a relay deadline, +/// Riverpod does not auto-retry, so this is the user's way to re-send. +class LoadErrorView extends StatelessWidget { + final String message; + final VoidCallback onRetry; + + const LoadErrorView({ + super.key, + required this.message, + required this.onRetry, + }); + + @override + Widget build(BuildContext context) { + return Center( + child: Column( + mainAxisSize: MainAxisSize.min, + children: [ + Icon( + LucideIcons.triangleAlert, + size: Grid.lg, + color: context.colors.error, + ), + const SizedBox(height: Grid.xxs), + Text( + message, + style: context.textTheme.bodyMedium?.copyWith( + color: context.colors.onSurfaceVariant, + ), + ), + const SizedBox(height: Grid.xs), + FilledButton.icon( + key: const ValueKey('load-error-retry'), + onPressed: onRetry, + icon: const Icon(LucideIcons.refreshCcw, size: 16), + label: const Text('Retry'), + ), + ], + ), + ); + } +} diff --git a/mobile/test/features/channels/channel_detail_page_test.dart b/mobile/test/features/channels/channel_detail_page_test.dart index 20251f2195..4feaa96732 100644 --- a/mobile/test/features/channels/channel_detail_page_test.dart +++ b/mobile/test/features/channels/channel_detail_page_test.dart @@ -10187,6 +10187,62 @@ void main() { }); group('Error and loading states', () { + Widget errorScope(ChannelMessagesNotifier notifier) => ProviderScope( + overrides: [ + channelMessagesProvider(_channelId).overrideWith(() => notifier), + channelTypingProvider( + _channelId, + ).overrideWith(() => _FakeTypingNotifier([])), + userCacheProvider.overrideWith(() => _FakeUserCacheNotifier({})), + channelsProvider.overrideWith( + () => _FakeChannelsNotifier([_testChannel]), + ), + relayClientProvider.overrideWithValue( + RelayClient(baseUrl: 'http://localhost:3000'), + ), + savedPrefsProvider.overrideWithValue(_testPrefs), + ], + child: MaterialApp( + theme: AppTheme.light(), + home: ChannelDetailPage(channel: _testChannel), + ), + ); + final retry = find.byKey(const ValueKey('load-error-retry')); + + for (final (name, error) in [ + ( + 'deadline', + RelayException(503, '{"error":"query timed out"}') as Object, + ), + ('ordinary error', Exception('bridge down') as Object), + ]) { + testWidgets('Retry after a $name loads once', (tester) async { + final notifier = _RetryCountingMessagesNotifier( + () => AsyncError(error, StackTrace.current), + ); + await tester.pumpWidget(errorScope(notifier)); + await tester.pumpAndSettle(); + expect(find.text('Failed to load messages'), findsOneWidget); + expect(notifier.loads, 1); + final before = notifier.loads; + notifier.nextResult = () => const AsyncData([]); + await tester.tap(retry); + await tester.pumpAndSettle(); + expect(notifier.loads, before + 1); + expect(retry, findsNothing); + }); + } + + testWidgets('no Retry while messages load', (tester) async { + final notifier = _RetryCountingMessagesNotifier( + () => const AsyncLoading(), + ); + await tester.pumpWidget(errorScope(notifier)); + await tester.pump(); + expect(retry, findsNothing); + expect(find.text('Failed to load messages'), findsNothing); + }); + testWidgets('shows error message on failure', (tester) async { await tester.pumpWidget( ProviderScope( @@ -10891,6 +10947,225 @@ void main() { expect(highlightedDecoration.color!.a, lessThan(0.12)); }); + group('after a first-load deadline', () { + final root = _textMsg( + id: 'root', + pubkey: 'alice', + content: 'Thread root', + createdAt: 1000, + ); + final mid = _textMsg( + id: 'mid', + pubkey: 'bob', + content: 'Nested parent', + createdAt: 1100, + extraTags: const [ + ['e', 'root', '', 'reply'], + ], + ); + + Future<(_FakeMessagesNotifier, int Function())> openDeadlined( + WidgetTester tester, + NostrEvent head, + ) async { + var attempts = 0; + final messages = _FakeMessagesNotifier([root, mid]); + final timeline = formatTimeline([root, mid]); + await tester.pumpWidget( + _buildTestable( + messages: [root, mid], + messagesNotifier: messages, + disableRetries: true, + threadReplyLoaders: { + 'root': () { + attempts++; + return Future.error( + RelayException(503, '{"error":"query timed out"}'), + ); + }, + }, + home: ThreadDetailPage( + threadHead: timeline.firstWhere((m) => m.id == head.id), + allMessages: timeline, + channelId: _testChannel.id, + currentPubkey: 'me', + isMember: true, + isArchived: false, + ), + ), + ); + await tester.pumpAndSettle(); + expect(attempts, 1); + return (messages, () => attempts); + } + + NostrEvent liveReply(String id, List> tags) => _textMsg( + id: id, + pubkey: 'carol', + content: 'Live $id', + createdAt: 1200, + extraTags: tags, + ); + + testWidgets('shows an incoming direct reply', (tester) async { + final (messages, attempts) = await openDeadlined(tester, root); + messages.setMessages([ + root, + mid, + liveReply('direct', const [ + ['e', 'root', '', 'reply'], + ]), + ]); + await tester.pumpAndSettle(); + expect(find.text('Live direct'), findsOneWidget); + expect(find.textContaining('Couldn’t refresh'), findsOneWidget); + expect(attempts(), 1); + }); + + for (final provisional in [false, true]) { + testWidgets( + 'Retry ${provisional ? 'beside provisional replies' : 'in the empty state'} ' + 'loads once', + (tester) async { + // The empty variant has no reply at all, cached or provisional. + final seed = provisional ? [root, mid] : [root]; + final timeline = formatTimeline(seed); + var fail = true; + var loads = 0; + final messages = _FakeMessagesNotifier(seed); + await tester.pumpWidget( + _buildTestable( + messages: seed, + messagesNotifier: messages, + disableRetries: true, + threadReplyLoaders: { + 'root': () { + loads++; + if (!fail) return Future.value(const []); + return Future.error( + RelayException(503, '{"error":"query timed out"}'), + ); + }, + }, + home: ThreadDetailPage( + threadHead: timeline.firstWhere((m) => m.id == 'root'), + allMessages: timeline, + channelId: _testChannel.id, + currentPubkey: 'me', + isMember: true, + isArchived: false, + ), + ), + ); + await tester.pumpAndSettle(); + final retry = find.byKey(const ValueKey('thread-replies-retry')); + if (provisional) { + messages.setMessages([ + root, + mid, + liveReply('direct', const [ + ['e', 'root', '', 'reply'], + ]), + ]); + await tester.pumpAndSettle(); + expect(find.text('Live direct'), findsOneWidget); + } else { + expect(find.text('Couldn’t load replies'), findsOneWidget); + } + expect(retry, findsOneWidget); + final target = tester.getSize(retry); + expect( + target.width, + greaterThanOrEqualTo(kMinInteractiveDimension), + ); + expect( + target.height, + greaterThanOrEqualTo(kMinInteractiveDimension), + ); + final before = loads; + fail = false; + await tester.tap(retry); + await tester.pumpAndSettle(); + expect(loads, before + 1); + expect(retry, findsNothing); + }, + ); + } + + testWidgets('no replies Retry while the scan loads', (tester) async { + final timeline = formatTimeline([root, mid]); + await tester.pumpWidget( + _buildTestable( + messages: [root, mid], + threadReplyLoaders: { + 'root': () => Completer>().future, + }, + home: ThreadDetailPage( + threadHead: timeline.firstWhere((m) => m.id == 'root'), + allMessages: timeline, + channelId: _testChannel.id, + currentPubkey: 'me', + isMember: true, + isArchived: false, + ), + ), + ); + await tester.pump(); + await tester.pump(); + expect(find.textContaining('Couldn’t'), findsNothing); + expect( + find.byKey(const ValueKey('thread-replies-retry')), + findsNothing, + ); + }); + + testWidgets('shows an incoming nested reply', (tester) async { + final (messages, attempts) = await openDeadlined(tester, mid); + messages.setMessages([ + root, + mid, + liveReply('nested', const [ + ['e', 'root', '', 'root'], + ['e', 'mid', '', 'reply'], + ]), + ]); + await tester.pumpAndSettle(); + expect(find.text('Live nested'), findsOneWidget); + expect(attempts(), 1); + }); + + testWidgets('keeps a sent reply visible after acceptance', ( + tester, + ) async { + final (messages, attempts) = await openDeadlined(tester, root); + final sent = _textMsg( + id: 'sent', + pubkey: 'me', + content: 'My reply', + createdAt: 1300, + extraTags: const [ + ['e', 'root', '', 'reply'], + ], + ); + final container = ProviderScope.containerOf( + tester.element(find.byType(ThreadDetailPage)), + ); + const args = ThreadRepliesArgs(channelId: _channelId, rootId: 'root'); + container.read(threadLocalRepliesProvider(args).notifier).add(sent); + await tester.pumpAndSettle(); + expect(find.text('My reply'), findsOneWidget); + // Acceptance: the confirmed reply moves from the optimistic overlay + // into the channel cache (cacheConfirmedThreadReplies). + messages.setMessages([root, mid, sent]); + container.read(threadLocalRepliesProvider(args).notifier).confirm({ + 'sent', + }); + await tester.pumpAndSettle(); + expect(find.text('My reply'), findsOneWidget); + expect(attempts(), 1); + }); + }); + testWidgets('opens a nested reply in its direct-parent thread', ( tester, ) async { @@ -14650,6 +14925,23 @@ class _FakeMessagesNotifier extends ChannelMessagesNotifier { } } +/// Counts loads; each settles after mount, like the real network load. +class _RetryCountingMessagesNotifier extends ChannelMessagesNotifier { + _RetryCountingMessagesNotifier(this.nextResult) : super(_channelId); + + AsyncValue> Function() nextResult; + int loads = 0; + + @override + AsyncValue> build() { + loads++; + final result = nextResult(); + if (result is AsyncLoading) return result; + Future(() => state = result); + return const AsyncLoading(); + } +} + class _ErrorMessagesNotifier extends ChannelMessagesNotifier { _ErrorMessagesNotifier() : super(_channelId); diff --git a/mobile/test/features/channels/channel_messages_provider_test.dart b/mobile/test/features/channels/channel_messages_provider_test.dart index 729bf45fc7..bc6f1dab1d 100644 --- a/mobile/test/features/channels/channel_messages_provider_test.dart +++ b/mobile/test/features/channels/channel_messages_provider_test.dart @@ -312,6 +312,57 @@ void main() { ); }); + group('relay deadline owners', () { + RelayException deadline() => + RelayException(503, '{"error":"query timed out"}'); + int threadScans(_RecordingRelaySessionNotifier session) => session + .queryFilters + .where((filter) => filter.extensions.containsKey('depth_limit')) + .length; + NostrEvent reply(int i) => _event( + id: 'reply-$i', + createdAt: 20 + i, + extraTags: const [ + ['e', 'root', '', 'reply'], + ], + ); + + test('a window deadline does not fall back to websocket history', () async { + final session = _RecordingRelaySessionNotifier( + queryResults: [deadline()], + ); + final container = _buildContainer(session); + addTearDown(container.dispose); + container.listen(channelMessagesProvider(_channelId), (_, _) {}); + await session.subscribed; + await _pumpEventQueue(); + expect(session.operations, ['subscribe', 'query']); + expect( + container.read(channelMessagesProvider(_channelId)).hasError, + true, + ); + }); + + test('a recount deadline ends its retry backoff', () async { + final session = _RecordingRelaySessionNotifier( + queryResults: [ + [_event(id: 'root', createdAt: 10), _bounds()], + deadline(), + deadline(), + ], + ); + final container = _buildContainer(session); + addTearDown(container.dispose); + container.listen(channelMessagesProvider(_channelId), (_, _) {}); + await _pumpEventQueue(); + for (var i = 0; i < 300; i++) { + session.emit(reply(i)); + } + await Future.delayed(const Duration(milliseconds: 2000)); + expect(threadScans(session), 1); + }); + }); + test('still loads history when live subscription fails', () async { final relaySession = _RecordingRelaySessionNotifier(failSubscribe: true); final container = _buildContainer(relaySession); diff --git a/mobile/test/features/channels/channels_provider_test.dart b/mobile/test/features/channels/channels_provider_test.dart index 3bb1be5beb..e277a4dfb3 100644 --- a/mobile/test/features/channels/channels_provider_test.dart +++ b/mobile/test/features/channels/channels_provider_test.dart @@ -1632,6 +1632,168 @@ void main() { expect(channels.single.lastMessageAt?.millisecondsSinceEpoch, 20 * 1000); }); + group('latest-message batch failure', () { + Future> fallbackFilters(Object error) async { + final session = _FakeRelaySession( + memberships: [_membership(_channelA, myPk)], + metadata: [_meta(id: _channelA, name: 'general')], + )..messageBatchError = error; + final container = _buildContainer(session: session); + addTearDown(container.dispose); + await container.read(channelsProvider.future); + await _waitUntil(() => session.queryBatches.isNotEmpty); + await Future.delayed(Duration.zero); + return session.historyFilters + .where( + (filter) => + filter.kinds.contains(EventKind.streamMessageV2) && + (filter.tags['#h']?.contains(_channelA) ?? false), + ) + .toList(); + } + + test('a relay deadline never reaches the websocket fallback', () async { + expect( + await fallbackFilters( + RelayException(503, '{"error":"query timed out"}'), + ), + isEmpty, + ); + }); + + test('an ordinary failure still uses the websocket fallback', () async { + expect(await fallbackFilters(Exception('bridge down')), isNotEmpty); + }); + }); + + group('deadline-unavailable channel batches', () { + Object deadline() => RelayException(503, '{"error":"query timed out"}'); + bool isUnread(List batch) => + batch.isNotEmpty && batch.every((filter) => filter.since != null); + NostrEvent message(String id, int createdAt, {bool mention = false}) => + NostrEvent( + id: id, + pubkey: 'alice', + createdAt: createdAt, + kind: EventKind.streamMessageV2, + tags: [ + const ['h', _channelA], + if (mention) const ['p', myPk], + ], + content: 'hi', + sig: 'sig', + ); + + test('a latest-message deadline keeps known timestamps', () async { + final session = _FakeRelaySession( + memberships: [_membership(_channelA, myPk)], + metadata: [_meta(id: _channelA, name: 'general')], + recentMessages: [message('m1', 30)], + ); + final container = _buildContainer(session: session); + addTearDown(container.dispose); + await container.read(channelsProvider.future); + await _settle(); + session.latestBatchError = deadline(); + await container.read(channelsProvider.notifier).refresh(); + await _settle(); + expect( + container.read(channelsProvider).value!.single.lastMessageAt, + DateTime.fromMillisecondsSinceEpoch(30 * 1000, isUtc: true), + ); + expect(session.messageHistoryCount, 0); + }); + + test( + 'a cold-start latest-message deadline is filled by unread catch-up', + () async { + final session = _FakeRelaySession( + memberships: [_membership(_channelA, myPk)], + metadata: [_meta(id: _channelA, name: 'general')], + recentMessages: [message('mention', 30, mention: true)], + )..latestBatchError = deadline(); + final container = _buildContainer(session: session); + addTearDown(container.dispose); + await container.read(channelsProvider.future); + await _waitUntil(() => session.queryBatches.any(isUnread)); + await _settle(); + final notifier = container.read(channelsProvider.notifier); + expect(notifier.observedUnreadEventsByChannel[_channelA]?.keys, [ + 'mention', + ]); + expect( + container.read(channelsProvider).value!.single.lastMessageAt, + DateTime.fromMillisecondsSinceEpoch(30 * 1000, isUtc: true), + ); + expect(session.messageHistoryCount, 0); + }, + ); + + test('unread catch-up never moves lastMessageAt backward', () async { + final session = _FakeRelaySession( + memberships: [_membership(_channelA, myPk)], + metadata: [_meta(id: _channelA, name: 'general')], + recentMessages: [message('older', 30, mention: true)], + )..pauseNextUnreadCatchUpQuery(); + final container = _buildContainer(session: session); + addTearDown(container.dispose); + await container.read(channelsProvider.future); + await session.nextUnreadCatchUpQueryStarted; + // A newer live event lands while the catch-up is in flight. + session.emit(message('newer', 60, mention: true)); + session.resumePausedUnreadCatchUpQuery(); + await _settle(); + expect( + container + .read(channelsProvider.notifier) + .observedUnreadEventsByChannel[_channelA] + ?.keys, + containsAll(['older', 'newer']), + ); + expect( + container.read(channelsProvider).value!.single.lastMessageAt, + DateTime.fromMillisecondsSinceEpoch(60 * 1000, isUtc: true), + ); + }); + + // HTTP fails ordinarily, then a per-filter websocket fallback times out: + // the batch is unavailable and no later chunk is sent. + test('a websocket fallback deadline makes the batch unavailable', () async { + final ids = [for (var i = 0; i < 6; i++) 'chunk-channel-$i']; + final session = _FakeRelaySession( + memberships: [ + _membership(_channelA, myPk), + for (final id in ids) _membership(id, myPk), + ], + metadata: [ + _meta(id: _channelA, name: 'general'), + for (final id in ids) _meta(id: id, name: id), + ], + recentMessages: [message('m1', 30)], + ); + final container = _buildContainer(session: session); + addTearDown(container.dispose); + await container.read(channelsProvider.future); + await _settle(); + general() => container + .read(channelsProvider) + .value! + .firstWhere((channel) => channel.id == _channelA); + final lastMessageAt = general().lastMessageAt; + expect(lastMessageAt, isNotNull); + session + ..messageBatchError = Exception('bridge down') + ..messageHistoryError = deadline(); + await container.read(channelsProvider.notifier).refresh(); + await _settle(); + // Unavailable, not empty: known timestamps survive. + expect(general().lastMessageAt, lastMessageAt); + // Each batch stops after its first chunk of four filters. + expect(session.messageHistoryCount % 4, 0); + expect(session.messageHistoryCount, lessThan(2 * ids.length)); + }); + }); + test( 'loads all channel timestamps through one batched relay query', () async { @@ -2261,6 +2423,11 @@ class _FakeRelaySession extends RelaySessionNotifier { final List historyFilters = []; final List> queryBatches = []; + Object? messageBatchError; + Object? latestBatchError; + Object? messageHistoryError; + int messageHistoryCount = 0; + final List directoryQueryFilters = []; final List membershipQueryFilters = []; final List subscribeFilters = []; @@ -2536,6 +2703,9 @@ class _FakeRelaySession extends RelaySessionNotifier { // Member metadata query — return only matching `d` tags. return metadata.where((e) => ids.contains(e.getTagValue('d'))).toList(); } + // Per-filter websocket fallback of a message batch. + messageHistoryCount++; + if (messageHistoryError case final error?) throw error; return const []; } @@ -2614,11 +2784,13 @@ class _FakeRelaySession extends RelaySessionNotifier { return filter.until == null ? directorySnapshot : const []; } queryBatches.add(filters); + if (messageBatchError case final error?) throw error; // The unread catch-up is the only batch that carries `since` on every // filter; the latest-message batch leaves it null. Snapshot the messages at // request time so a parked response reflects the scope that asked for it. final isUnreadCatchUp = filters.isNotEmpty && filters.every((filter) => filter.since != null); + if (!isUnreadCatchUp && latestBatchError != null) throw latestBatchError!; final messageSnapshot = List.of(recentMessages); if (isUnreadCatchUp) { // Claim the parked slot so the refresh that follows the switch can run diff --git a/mobile/test/features/forum/forum_widgets_test.dart b/mobile/test/features/forum/forum_widgets_test.dart index 2d22026530..690ada9317 100644 --- a/mobile/test/features/forum/forum_widgets_test.dart +++ b/mobile/test/features/forum/forum_widgets_test.dart @@ -1,3 +1,5 @@ +import 'dart:async'; + import 'package:flutter/material.dart'; import 'package:flutter_test/flutter_test.dart'; import 'package:hooks_riverpod/hooks_riverpod.dart'; @@ -164,6 +166,56 @@ Widget _buildThreadPage({ ); } +class _CountingForumSession extends RelaySessionNotifier { + _CountingForumSession(this.error); + + Object? error; + int fetchCount = 0; + Completer? park; + + /// Forum-surface attempts only: the posts list (45001) or thread replies + /// (`#e`), excluding shared sub-providers such as profiles and emoji. + int forumAttempts = 0; + + @override + SessionState build() => const SessionState(status: SessionStatus.connected); + + @override + Future> fetchHistory( + NostrFilter filter, { + Duration timeout = const Duration(seconds: 8), + }) async { + fetchCount++; + if (filter.ids == null && + (filter.kinds.contains(45001) || filter.tags.containsKey('#e'))) { + forumAttempts++; + if (park case final park?) await park.future; + } + if (error case final error?) throw error; + return const []; + } +} + +Widget _buildLiveForum(_CountingForumSession session, Widget child) => + ProviderScope( + // Isolate the timers from Riverpod's own error retry. + retry: (_, _) => null, + overrides: [ + relaySessionProvider.overrideWith(() => session), + userCacheProvider.overrideWith(() => _FakeUserCacheNotifier(const {})), + knownAgentPubkeysProvider.overrideWithValue(const {}), + profileProvider.overrideWith(() => _FakeProfileNotifier()), + savedPrefsProvider.overrideWithValue(_testPrefs), + relayClientProvider.overrideWithValue( + RelayClient(baseUrl: 'http://localhost:3000'), + ), + ], + child: MaterialApp( + theme: AppTheme.light(), + home: Scaffold(body: child), + ), + ); + void main() { setUp(() async { SharedPreferences.setMockInitialValues({}); @@ -194,6 +246,134 @@ void main() { ); }); + group('forum polling after a relay deadline', () { + final deadline = RelayException(503, '{"error":"query timed out"}'); + final surfaces = { + 'posts view (15s)': ( + ForumPostsView(channel: _forumChannel, currentPubkey: 'self'), + const Duration(seconds: 15), + ), + 'thread page (10s)': ( + const ForumThreadPage( + channelId: _channelId, + postEventId: 'post1', + currentPubkey: 'self', + isMember: true, + isArchived: false, + ), + const Duration(seconds: 10), + ), + }; + for (final MapEntry(key: name, value: (surface, interval)) + in surfaces.entries) { + testWidgets('$name pauses on a deadline', (tester) async { + final session = _CountingForumSession(deadline); + await tester.pumpWidget(_buildLiveForum(session, surface)); + await tester.pump(); + final settled = session.fetchCount; + expect(session.forumAttempts, 1); + for (var tick = 0; tick < 4; tick++) { + await tester.pump(interval); + } + expect(session.fetchCount, settled); + await tester.pumpWidget(const SizedBox()); + }); + + testWidgets('$name keeps polling after an ordinary error', ( + tester, + ) async { + final session = _CountingForumSession(Exception('reset')); + await tester.pumpWidget(_buildLiveForum(session, surface)); + await tester.pump(); + final settled = session.fetchCount; + await tester.pump(interval); + await tester.pump(); + expect(session.fetchCount, greaterThan(settled)); + await tester.pumpWidget(const SizedBox()); + }); + + for (final (kind, error) in [ + ('deadline', deadline as Object), + ('ordinary error', Exception('reset') as Object), + ]) { + testWidgets('$name Retry after a $kind loads once', (tester) async { + final session = _CountingForumSession(error); + await tester.pumpWidget(_buildLiveForum(session, surface)); + await tester.pump(); + await tester.pump(); + final retry = find.byKey(const ValueKey('load-error-retry')); + expect(retry, findsOneWidget); + final before = session.forumAttempts; + session.error = null; + await tester.tap(retry); + await tester.pump(); + await tester.pump(); + expect(session.forumAttempts, before + 1); + // The post list settles empty; the thread page has no fake post, + // so it settles on not-found again (the count shows the reload). + if (surface is ForumPostsView) expect(retry, findsNothing); + await tester.pumpWidget(const SizedBox()); + }); + + testWidgets('$name hides Retry while a $kind retry is pending', ( + tester, + ) async { + final session = _CountingForumSession(error); + await tester.pumpWidget(_buildLiveForum(session, surface)); + await tester.pump(); + await tester.pump(); + final retry = find.byKey(const ValueKey('load-error-retry')); + expect(retry, findsOneWidget); + final before = session.forumAttempts; + final park = session.park = Completer(); + await tester.tap(retry); + await tester.pump(); + await tester.pump(); + expect(retry, findsNothing); + expect(session.forumAttempts, before + 1); + // The replacement fails the same way and settles on Retry again. + park.complete(); + await tester.pump(); + await tester.pump(); + expect(retry, findsOneWidget); + expect(session.forumAttempts, before + 1); + await tester.pumpWidget(const SizedBox()); + }); + } + + testWidgets('$name shows no Retry while loading', (tester) async { + final session = _CountingForumSession(deadline) + ..park = Completer(); + await tester.pumpWidget(_buildLiveForum(session, surface)); + await tester.pump(); + expect(session.forumAttempts, 1); + expect(find.byKey(const ValueKey('load-error-retry')), findsNothing); + session.park!.complete(); + await tester.pump(); + await tester.pump(); + expect(find.byKey(const ValueKey('load-error-retry')), findsOneWidget); + await tester.pumpWidget(const SizedBox()); + }); + + testWidgets('$name reopening retries a deadline', (tester) async { + final session = _CountingForumSession(deadline); + await tester.pumpWidget(_buildLiveForum(session, surface)); + await tester.pump(); + expect(session.forumAttempts, 1); + await tester.pumpWidget(_buildLiveForum(session, const SizedBox())); + await tester.pumpWidget(_buildLiveForum(session, surface)); + await tester.pump(); + await tester.pump(); + expect(session.forumAttempts, 2); + for (var tick = 0; tick < 4; tick++) { + await tester.pump(interval); + } + expect(session.forumAttempts, 2); + await tester.pumpWidget(const SizedBox()); + }); + } + }); + group('ForumPostCard', () { testWidgets('renders author name and content', (tester) async { await tester.pumpWidget( diff --git a/mobile/test/shared/relay/relay_closed_policy_test.dart b/mobile/test/shared/relay/relay_closed_policy_test.dart index ff78ea89ef..d83f658f40 100644 --- a/mobile/test/shared/relay/relay_closed_policy_test.dart +++ b/mobile/test/shared/relay/relay_closed_policy_test.dart @@ -16,6 +16,7 @@ void main() { 'unsupported: filter extension': RelayClosedClass.terminal, 'error: mixed search and channel filter': RelayClosedClass.terminal, 'error: too many subscriptions': RelayClosedClass.terminal, + 'error: query timed out': RelayClosedClass.terminal, 'error: relay temporarily unavailable': RelayClosedClass.retryable, 'subscription closed by relay': RelayClosedClass.retryable, }; diff --git a/mobile/test/shared/relay/relay_deadline_provider_retry_test.dart b/mobile/test/shared/relay/relay_deadline_provider_retry_test.dart new file mode 100644 index 0000000000..c2b53103c0 --- /dev/null +++ b/mobile/test/shared/relay/relay_deadline_provider_retry_test.dart @@ -0,0 +1,226 @@ +import 'dart:async'; + +import 'package:buzz/features/channels/thread_replies_provider.dart'; +import 'package:buzz/features/forum/forum_provider.dart'; +import 'package:buzz/main.dart'; +import 'package:buzz/shared/relay/relay.dart'; +import 'package:flutter/widgets.dart'; +import 'package:flutter_test/flutter_test.dart'; +import 'package:hooks_riverpod/hooks_riverpod.dart'; +import 'package:shared_preferences/shared_preferences.dart'; + +// --------------------------------------------------------------------------- +// Fake sessions +// --------------------------------------------------------------------------- + +class _DeadlineHttpSession extends RelaySessionNotifier { + int queryCount = 0; + + @override + SessionState build() => const SessionState(status: SessionStatus.connected); + + @override + Future> queryRelay( + List filters, { + Duration timeout = const Duration(seconds: 8), + }) async { + queryCount++; + // Relay HTTP 503 with JSON body: {"error":"query timed out"} + throw RelayException(503, '{"error":"query timed out"}'); + } +} + +class _DeadlineWsSession extends RelaySessionNotifier { + int historyCount = 0; + + @override + SessionState build() => const SessionState(status: SessionStatus.connected); + + @override + Future> fetchHistory( + NostrFilter filter, { + Duration timeout = const Duration(seconds: 8), + }) async { + historyCount++; + // WebSocket CLOSED: Exception("error: query timed out") + throw Exception('error: query timed out'); + } +} + +class _OrdinaryErrorSession extends RelaySessionNotifier { + int queryCount = 0; + + @override + SessionState build() => const SessionState(status: SessionStatus.connected); + + @override + Future> queryRelay( + List filters, { + Duration timeout = const Duration(seconds: 8), + }) async { + queryCount++; + throw RelayException(500, '{"error":"internal server error"}'); + } + + @override + Future> fetchHistory( + NostrFilter filter, { + Duration timeout = const Duration(seconds: 8), + }) async { + queryCount++; + throw RelayException(500, '{"error":"internal server error"}'); + } +} + +// --------------------------------------------------------------------------- +// isRelayDeadlineError unit tests +// --------------------------------------------------------------------------- + +void main() { + test('the production root scope uses relayProviderRetry', () async { + SharedPreferences.setMockInitialValues({}); + final scope = buildRootProviderScope( + prefs: await SharedPreferences.getInstance(), + child: const SizedBox(), + ); + expect(scope.retry, same(relayProviderRetry)); + }); + + group('isRelayDeadlineError', () { + test('matches HTTP 503 query timed out', () { + expect( + isRelayDeadlineError( + RelayException(503, '{"error":"query timed out"}'), + ), + isTrue, + ); + }); + + test('matches HTTP 503 with whitespace in body value', () { + expect( + isRelayDeadlineError( + RelayException(503, '{"error":" Query Timed Out "}'), + ), + isTrue, + ); + }); + + test('does not match HTTP 503 with different error', () { + expect( + isRelayDeadlineError( + RelayException(503, '{"error":"service unavailable"}'), + ), + isFalse, + ); + }); + + test('does not match HTTP 503 with non-JSON body', () { + expect(isRelayDeadlineError(RelayException(503, 'plain text')), isFalse); + }); + + test('does not match HTTP 500', () { + expect( + isRelayDeadlineError( + RelayException(500, '{"error":"query timed out"}'), + ), + isFalse, + ); + }); + + test('matches WebSocket CLOSED exception string', () { + expect(isRelayDeadlineError(Exception('error: query timed out')), isTrue); + }); + + test('does not match ordinary exception', () { + expect(isRelayDeadlineError(Exception('connection refused')), isFalse); + }); + + test('does not match TimeoutException', () { + expect( + isRelayDeadlineError( + TimeoutException( + 'Relay history request timed out after 0:00:08.000000', + ), + ), + isFalse, + ); + }); + }); + + // ------------------------------------------------------------------------- + // threadRepliesProvider — HTTP path + // ------------------------------------------------------------------------- + + group('threadRepliesProvider deadline retry suppression', () { + const args = ThreadRepliesArgs(channelId: 'chan', rootId: 'root'); + + test( + 'deadline: settles error in exactly one call and does not rebuild', + () async { + final session = _DeadlineHttpSession(); + final container = ProviderContainer( + retry: relayProviderRetry, + overrides: [relaySessionProvider.overrideWith(() => session)], + ); + addTearDown(container.dispose); + + final sub = container.listen(threadRepliesProvider(args), (_, _) {}); + addTearDown(sub.close); + + await container.pump(); + await Future.delayed(const Duration(milliseconds: 500)); + + expect(container.read(threadRepliesProvider(args)).hasError, isTrue); + expect(session.queryCount, 1); + }, + ); + + test( + 'ordinary error: retries at least once with production retry policy', + () async { + final session = _OrdinaryErrorSession(); + final container = ProviderContainer( + retry: relayProviderRetry, + overrides: [relaySessionProvider.overrideWith(() => session)], + ); + addTearDown(container.dispose); + + final sub = container.listen(threadRepliesProvider(args), (_, _) {}); + addTearDown(sub.close); + + await container.pump(); + await Future.delayed(const Duration(milliseconds: 400)); + + // At least 2 calls means Riverpod issued at least one retry. + expect(session.queryCount, greaterThanOrEqualTo(2)); + }, + ); + }); + + // ------------------------------------------------------------------------- + // forumPostsProvider — WebSocket history path + // ------------------------------------------------------------------------- + + group('forumPostsProvider deadline retry suppression', () { + test( + 'deadline: settles error in exactly one call and does not rebuild', + () async { + final session = _DeadlineWsSession(); + final container = ProviderContainer( + retry: relayProviderRetry, + overrides: [relaySessionProvider.overrideWith(() => session)], + ); + addTearDown(container.dispose); + + final sub = container.listen(forumPostsProvider('chan'), (_, _) {}); + addTearDown(sub.close); + + await container.pump(); + await Future.delayed(const Duration(milliseconds: 500)); + + expect(container.read(forumPostsProvider('chan')).hasError, isTrue); + expect(session.historyCount, 1); + }, + ); + }); +} diff --git a/mobile/test/shared/relay/relay_session_test.dart b/mobile/test/shared/relay/relay_session_test.dart index 413f12a82e..50bdb5201d 100644 --- a/mobile/test/shared/relay/relay_session_test.dart +++ b/mobile/test/shared/relay/relay_session_test.dart @@ -1100,6 +1100,38 @@ void main() { expect(_reqs(socket).where((req) => req[1] == 'l-1'), hasLength(1)); }); + test('a deadline CLOSED retries a live sub but fails history', () async { + final timers = <_ManualTimer>[]; + final socket = _RecordingRelaySocket(); + final statuses = []; + final session = RelaySessionNotifier( + retryTimerFactory: (duration, callback) { + final timer = _ManualTimer(duration, callback); + timers.add(timer); + return timer; + }, + ); + session.debugAttachSocketForTest(socket); + final subscribe = session.subscribeWithStatus( + _channelFilter, + (_) {}, + onStatusChanged: statuses.add, + ); + session.debugHandleMessage(['EOSE', 'l-1']); + await subscribe; + + session.debugHandleMessage(['CLOSED', 'l-1', 'error: query timed out']); + expect(statuses.last, RelaySubscriptionStatus.retrying); + timers.single.fire(); + await Future.delayed(Duration.zero); + expect(_reqs(socket).where((req) => req[1] == 'l-1'), hasLength(2)); + + final history = session.fetchHistory(_channelFilter); + final historyId = _reqs(socket).last[1] as String; + session.debugHandleMessage(['CLOSED', historyId, 'error: query timed out']); + await expectLater(history, throwsA(isA())); + }); + test('unsubscribe and dispose cancel CLOSED retry timers', () async { final timers = <_ManualTimer>[]; final socket = _RecordingRelaySocket(); diff --git a/schema/schema.sql b/schema/schema.sql index fdd382f463..37112cc670 100644 --- a/schema/schema.sql +++ b/schema/schema.sql @@ -278,6 +278,10 @@ CREATE INDEX idx_events_not_before ON events (community_id, not_before) -- EXPLAIN before its work lands (Quinn option A; Max's index-spelling caveat). CREATE INDEX idx_events_search_tsv ON events USING GIN (search_tsv); +-- e-tag containment (`tags @> '[["e",""]]'`) for the aux closure and #e +-- reads. Mirrors migrations/0004; jsonb_path_ops supports exactly @>. +CREATE INDEX idx_events_tags_gin ON events USING GIN (tags jsonb_path_ops); + -- ── Event mentions ──────────────────────────────────────────────────────────── -- Conformance: "Channel-less global events and DMs" (#p fan-out). The join to -- events MUST carry the community tuple (e.community_id = m.community_id AND diff --git a/scripts/run-tests.sh b/scripts/run-tests.sh index 32bfa1c94b..ff18a07fd1 100755 --- a/scripts/run-tests.sh +++ b/scripts/run-tests.sh @@ -157,7 +157,7 @@ run_unit_tests() { # Mirror the relay filters from `just test-unit`: the three handler modules, # storage-snapshot helpers, readiness and router unit suites, and the single - # scoped admission regression in state::tests. + # scoped admission regression in state::tests, plus the REQ lifecycle tests. run_test_step "buzz-relay channel authorization tests" \ cargo test -p buzz-relay --lib handlers::channel_authz:: -- --nocapture @@ -170,6 +170,20 @@ run_unit_tests() { run_test_step "buzz-relay storage snapshot tests" \ cargo test -p buzz-relay --lib storage_sweep::tests:: -- --nocapture + # Infra-free REQ subscription-lifecycle tests, by exact name: the rest of + # handlers::req needs a database. + run_test_step "buzz-relay REQ subscription lifecycle tests" \ + cargo test -p buzz-relay --lib -- --exact --nocapture \ + handlers::req::tests::timed_out_historical_read_deregisters_before_closed \ + handlers::req::tests::superseded_timeout_leaves_replacement_intact \ + handlers::req::tests::search_claim_retires_live_and_yields_to_replacement \ + handlers::req::tests::concurrent_claims_and_stale_teardowns_keep_the_last_owner \ + handlers::req::tests::timeout_closed_is_emitted_before_a_replacement_can_claim \ + handlers::req::tests::revoke_then_replacement_keeps_replacement_whole \ + handlers::req::tests::claims_after_connection_cleanup_are_refused \ + handlers::req::tests::dropped_terminal_frame_cancels_connection \ + handlers::req::tests::revoke_dropped_terminal_frame_cancels_connection + run_test_step "buzz-relay readiness tests" \ cargo test -p buzz-relay --lib readiness::tests:: -- --nocapture diff --git a/scripts/seed-long-thread.sh b/scripts/seed-long-thread.sh new file mode 100755 index 0000000000..70e0d18297 --- /dev/null +++ b/scripts/seed-long-thread.sh @@ -0,0 +1,62 @@ +#!/usr/bin/env bash +# Seed one long thread on the local dev relay, for reproducing and eyeballing +# long-thread loading in the apps. +# +# just relay # stock local relay on ws://localhost:3000 +# just seed-long-thread 187 # or: scripts/seed-long-thread.sh [replies] +# +# Targets SEED_RELAY_URL (default: .env RELAY_URL, else ws://localhost:3000) +# and refuses non-loopback relays. Ambient BUZZ_RELAY_URL/BUZZ_PRIVATE_KEY are +# ignored so an agent or shell session can never seed its real relay. Posts +# with SEED_PRIVATE_KEY (default: a fresh throwaway key) into a new open stream +# channel, or into SEED_CHANNEL if that key may post there. +# +# Every write (channel, root, replies, reactions) counts against the relay's +# 60 human messages/min, so writes are paced SEED_DELAY seconds apart (default +# 1.05): the default run takes ~3-4 minutes on a stock relay. Set SEED_DELAY=0 +# when BUZZ_RATE_LIMIT_HUMAN_MESSAGES_PER_MIN is raised on the relay. +set -euo pipefail + +SCRIPT_DIR="$(cd "$(dirname "${BASH_SOURCE[0]}")" && pwd)" +REPO_ROOT="$(cd "${SCRIPT_DIR}/.." && pwd)" +cd "${REPO_ROOT}" + +if [[ -f ".env" ]]; then + set -o allexport + # shellcheck disable=SC1091 + source .env + set +o allexport +fi + +REPLIES="${1:-187}" +REACTIONS="${SEED_REACTIONS:-20}" +export BUZZ_RELAY_URL="${SEED_RELAY_URL:-${RELAY_URL:-ws://localhost:3000}}" +export BUZZ_PRIVATE_KEY="${SEED_PRIVATE_KEY:-$(openssl rand -hex 32)}" +unset BUZZ_AUTH_TAG +if [[ ! "$BUZZ_RELAY_URL" =~ ^wss?://(localhost|127\.0\.0\.1|\[::1\])(:[0-9]+)?/?$ ]]; then + echo "refusing non-local relay: $BUZZ_RELAY_URL" >&2 + exit 1 +fi +BUZZ="${BUZZ_CLI:-cargo run -q -p buzz-cli --}" +DELAY="${SEED_DELAY:-1.05}" +write() { $BUZZ "$@"; sleep "$DELAY"; } + +channel="${SEED_CHANNEL:-}" +if [[ -z "$channel" ]]; then + channel="$(write channels create --name "long-thread-$$" --type stream --visibility open | jq -er .channel_id)" +fi +root="$(write messages send --channel "$channel" --content "long thread root ($REPLIES replies)" | jq -er .event_id)" + +ids=() +for i in $(seq 1 "$REPLIES"); do + ids+=("$(write messages send --channel "$channel" --reply-to "$root" --content "reply $i" | jq -er .event_id)") +done +if (( REPLIES > 0 )); then + for i in $(seq 1 "$REACTIONS"); do + write reactions add --event "${ids[$(( (i * 7) % REPLIES ))]}" --emoji "👍" >/dev/null + done +fi + +echo "channel=$channel" +echo "root=$root" +echo "replies=$REPLIES reactions=$(( REPLIES > 0 ? REACTIONS : 0 ))"