diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index 65ed43d2..4d22c2f9 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -49,13 +49,10 @@ jobs: mkdir -p ~/.local/share/tlaplus curl -sL -o ~/.local/share/tlaplus/tla2tools.jar \ https://github.com/tlaplus/tlaplus/releases/latest/download/tla2tools.jar - # This audit pass proves bugs exist in CURRENT code and proves correct - # fix designs for them - the fixes are NOT yet applied to the Rust code - # (see node/README.md's "Known gap" sections). These configs model the - # verified fix designs (or a baseline that was never buggy) and must - # always pass. See root README.md's "Formal verification (TLA+)" - # section for what each spec covers. - - name: Run baseline + proposed-fix specs (must pass) + # These configs model the implemented fixes (or a baseline that was + # never buggy) and must always pass. The separate configs below retain + # the pre-fix counterexamples as historical regression documentation. + - name: Run baseline + fixed specs (must pass) working-directory: node/tla run: | set -e @@ -152,7 +149,7 @@ jobs: run: sudo apt update && sudo apt install protobuf-compiler - run: | source ~/.zkm-toolchain/env - cargo clippy --all-targets -- -D warnings + cargo clippy --all-targets --features rpc-debug-endpoints -- -D warnings test: name: Cargo Test needs: tla-plus @@ -173,4 +170,4 @@ jobs: run: | set -e source ~/.zkm-toolchain/env - cargo test -r --all --all-targets + cargo test -r --all --all-targets --features rpc-debug-endpoints diff --git a/.gitignore b/.gitignore index a222e211..3968c89a 100644 --- a/.gitignore +++ b/.gitignore @@ -38,6 +38,7 @@ proof-builder-rpc/*.ckpt node/tla/states/ local_docs/ +local_scripts/ scripts/testnet/ scripts/devnet/ *.DS_Store \ No newline at end of file diff --git a/Cargo.lock b/Cargo.lock index d45f8b19..8707e89c 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -3098,6 +3098,7 @@ dependencies = [ "libp2p-metrics", "libp2p-swarm-derive", "musig2", + "node-macros", "once_cell", "p3-bn254-fr", "p3-field", @@ -8148,6 +8149,15 @@ version = "0.6.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "43794a0ace135be66a25d3ae77d41b91615fb68ae937f904090203e81f755b65" +[[package]] +name = "node-macros" +version = "0.4.0" +dependencies = [ + "proc-macro2", + "quote", + "syn 2.0.117", +] + [[package]] name = "nohash-hasher" version = "0.2.0" diff --git a/Cargo.toml b/Cargo.toml index dcecddcf..3c129ed0 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -10,6 +10,7 @@ members = [ "crates/cbft-rpc", "crates/bitvm-gc", "crates/store", + "crates/node-macros", "crates/client", "crates/util", "crates/header-chain", diff --git a/crates/bitvm-gc/src/timelocks.rs b/crates/bitvm-gc/src/timelocks.rs index 72b930ac..dd38dae6 100644 --- a/crates/bitvm-gc/src/timelocks.rs +++ b/crates/bitvm-gc/src/timelocks.rs @@ -155,6 +155,7 @@ pub fn validate_timelock_config(network: Network, config: &TimelockConfig) -> Re ("operator_commit", config.operator_commit), ("connector_f", config.connector_f), ] { + ensure_bip68_height_based_sequence(name, value)?; if value < budget.reaction_blocks { bail!( "timelock_config.{name} must be at least {} reaction blocks, got {value}", @@ -210,6 +211,17 @@ pub fn validate_timelock_config(network: Network, config: &TimelockConfig) -> Re Ok(()) } +const BIP68_BLOCKS_MASK: u32 = 0x0000_ffff; + +fn ensure_bip68_height_based_sequence(name: &str, value: u32) -> Result<()> { + if value & !BIP68_BLOCKS_MASK != 0 { + bail!( + "timelock_config.{name} must use a BIP68 height-based sequence value, got {value:#010x}" + ); + } + Ok(()) +} + fn ensure_gap_at_least( left_name: &str, left: u32, @@ -291,4 +303,14 @@ mod tests { validate_timelock_config(network, &config).unwrap(); } } + + #[test] + fn rejects_non_height_based_bip68_sequences() { + assert!(ensure_bip68_height_based_sequence("test", BIP68_BLOCKS_MASK).is_ok()); + + for invalid in [1 << 16, 1 << 22, 1 << 31] { + let error = ensure_bip68_height_based_sequence("test", invalid).unwrap_err(); + assert!(error.to_string().contains("BIP68 height-based sequence")); + } + } } diff --git a/crates/node-macros/Cargo.toml b/crates/node-macros/Cargo.toml new file mode 100644 index 00000000..370ac51c --- /dev/null +++ b/crates/node-macros/Cargo.toml @@ -0,0 +1,12 @@ +[package] +name = "node-macros" +version.workspace = true +edition.workspace = true + +[lib] +proc-macro = true + +[dependencies] +proc-macro2 = "1" +quote = "1" +syn = { version = "2", features = ["full"] } diff --git a/crates/node-macros/src/lib.rs b/crates/node-macros/src/lib.rs new file mode 100644 index 00000000..6869b4ea --- /dev/null +++ b/crates/node-macros/src/lib.rs @@ -0,0 +1,210 @@ +use proc_macro::TokenStream; +use quote::quote; +use syn::spanned::Spanned; +use syn::{Attribute, Data, DeriveInput, Fields, Ident, Meta, Result, Variant, parse_macro_input}; + +#[proc_macro_derive(MessageBusinessRef, attributes(business_ref))] +pub fn derive_message_business_ref(input: TokenStream) -> TokenStream { + let input = parse_macro_input!(input as DeriveInput); + match expand_message_business_ref(input) { + Ok(tokens) => tokens.into(), + Err(error) => error.into_compile_error().into(), + } +} + +fn expand_message_business_ref(input: DeriveInput) -> Result { + let enum_name = input.ident; + let Data::Enum(data) = input.data else { + return Err(syn::Error::new( + enum_name.span(), + "MessageBusinessRef can only be derived for enums", + )); + }; + + let match_arms = data.variants.iter().map(expand_variant).collect::>>()?; + + Ok(quote! { + impl HasBusinessRef for #enum_name { + fn business_ref(&self) -> BusinessRef { + match self { + #(#match_arms),* + } + } + } + }) +} + +fn expand_variant(variant: &Variant) -> Result { + let scope = business_ref_scope(variant)?; + let variant_name = &variant.ident; + + match scope.as_str() { + "graph" => { + let binding = tuple_payload_binding(variant)?; + Ok(quote! { + Self::#variant_name(#binding) => BusinessRef::Graph { + instance_id: #binding.instance_id, + graph_id: #binding.graph_id, + } + }) + } + "instance" => { + let binding = tuple_payload_binding(variant)?; + Ok(quote! { + Self::#variant_name(#binding) => BusinessRef::Instance { + instance_id: #binding.instance_id, + } + }) + } + "unscoped" => match &variant.fields { + Fields::Unit => Ok(quote! { + Self::#variant_name => BusinessRef::Unscoped + }), + Fields::Unnamed(_) => Ok(quote! { + Self::#variant_name(..) => BusinessRef::Unscoped + }), + Fields::Named(_) => Ok(quote! { + Self::#variant_name { .. } => BusinessRef::Unscoped + }), + }, + _ => unreachable!("business_ref_scope validates accepted values"), + } +} + +fn tuple_payload_binding(variant: &Variant) -> Result { + match &variant.fields { + Fields::Unnamed(fields) if fields.unnamed.len() == 1 => { + Ok(Ident::new("message", variant.span())) + } + _ => Err(syn::Error::new( + variant.span(), + "graph and instance business references require exactly one payload field", + )), + } +} + +fn business_ref_scope(variant: &Variant) -> Result { + let mut matching = variant + .attrs + .iter() + .filter(|attribute: &&Attribute| attribute.path().is_ident("business_ref")); + let Some(attribute) = matching.next() else { + // Point at the offending variant rather than the derive site, so the + // compiler error names the variant that lacks an attribute. + return Err(syn::Error::new( + variant.ident.span(), + "each message variant must declare #[business_ref(graph)], #[business_ref(instance)], or #[business_ref(unscoped)]", + )); + }; + if matching.next().is_some() { + return Err(syn::Error::new(attribute.span(), "duplicate business_ref attribute")); + } + + let Meta::List(list) = &attribute.meta else { + return Err(syn::Error::new( + attribute.span(), + "business_ref must be written as #[business_ref(graph)], #[business_ref(instance)], or #[business_ref(unscoped)]", + )); + }; + let scope: Ident = list.parse_args()?; + let scope = scope.to_string(); + if matches!(scope.as_str(), "graph" | "instance" | "unscoped") { + Ok(scope) + } else { + Err(syn::Error::new(attribute.span(), "business_ref must be graph, instance, or unscoped")) + } +} + +#[cfg(test)] +mod tests { + use super::*; + use syn::parse_quote; + + fn expand_error(input: DeriveInput) -> String { + expand_message_business_ref(input).unwrap_err().to_string() + } + + #[test] + fn rejects_non_enum_input() { + let input = parse_quote! { + struct Message; + }; + + assert_eq!(expand_error(input), "MessageBusinessRef can only be derived for enums"); + } + + #[test] + fn requires_a_business_ref_scope_for_every_variant() { + let input = parse_quote! { + enum Message { + Missing(Payload), + } + }; + + assert_eq!( + expand_error(input), + "each message variant must declare #[business_ref(graph)], #[business_ref(instance)], or #[business_ref(unscoped)]" + ); + } + + #[test] + fn rejects_invalid_or_duplicate_scopes() { + let invalid = parse_quote! { + enum Message { + #[business_ref(other)] + Invalid(Payload), + } + }; + assert_eq!(expand_error(invalid), "business_ref must be graph, instance, or unscoped"); + + let duplicate = parse_quote! { + enum Message { + #[business_ref(graph)] + #[business_ref(instance)] + Duplicate(Payload), + } + }; + assert_eq!(expand_error(duplicate), "duplicate business_ref attribute"); + } + + #[test] + fn graph_and_instance_scopes_require_one_tuple_payload() { + let named = parse_quote! { + enum Message { + #[business_ref(graph)] + Graph { payload: Payload }, + } + }; + assert_eq!( + expand_error(named), + "graph and instance business references require exactly one payload field" + ); + + let multiple = parse_quote! { + enum Message { + #[business_ref(instance)] + Instance(Payload, Payload), + } + }; + assert_eq!( + expand_error(multiple), + "graph and instance business references require exactly one payload field" + ); + } + + #[test] + fn accepts_all_unscoped_variant_shapes() { + let input = parse_quote! { + enum Message { + #[business_ref(unscoped)] + Unit, + #[business_ref(unscoped)] + Tuple(u8, u16), + #[business_ref(unscoped)] + Named { value: u8 }, + } + }; + + assert!(expand_message_business_ref(input).is_ok()); + } +} diff --git a/crates/node-macros/tests/message_business_ref.rs b/crates/node-macros/tests/message_business_ref.rs new file mode 100644 index 00000000..33d65ca8 --- /dev/null +++ b/crates/node-macros/tests/message_business_ref.rs @@ -0,0 +1,47 @@ +use node_macros::MessageBusinessRef; + +#[derive(Debug, Eq, PartialEq)] +enum BusinessRef { + Instance { instance_id: u64 }, + Graph { instance_id: u64, graph_id: u64 }, + Unscoped, +} + +trait HasBusinessRef { + fn business_ref(&self) -> BusinessRef; +} + +struct Payload { + instance_id: u64, + graph_id: u64, +} + +#[allow(dead_code)] +#[derive(MessageBusinessRef)] +enum Message { + #[business_ref(graph)] + Graph(Payload), + #[business_ref(instance)] + Instance(Payload), + #[business_ref(unscoped)] + Unit, + #[business_ref(unscoped)] + Tuple(u8, u16), + #[business_ref(unscoped)] + Named { value: u8 }, +} + +#[test] +fn derives_the_expected_business_reference_for_every_scope() { + assert_eq!( + Message::Graph(Payload { instance_id: 7, graph_id: 11 }).business_ref(), + BusinessRef::Graph { instance_id: 7, graph_id: 11 } + ); + assert_eq!( + Message::Instance(Payload { instance_id: 7, graph_id: 11 }).business_ref(), + BusinessRef::Instance { instance_id: 7 } + ); + assert_eq!(Message::Unit.business_ref(), BusinessRef::Unscoped); + assert_eq!(Message::Tuple(1, 2).business_ref(), BusinessRef::Unscoped); + assert_eq!(Message::Named { value: 1 }.business_ref(), BusinessRef::Unscoped); +} diff --git a/crates/store/migrations/20260914000000_add_queue_poison_guards.sql b/crates/store/migrations/20260914000000_add_queue_poison_guards.sql new file mode 100644 index 00000000..964e1f85 --- /dev/null +++ b/crates/store/migrations/20260914000000_add_queue_poison_guards.sql @@ -0,0 +1,18 @@ +-- Poison-message guards for the two durable work queues. +-- +-- Both queues previously had no way to tell "the handler returned Err and asked +-- for a retry" apart from "the attempt never finished because the process died". +-- Only the latter indicates a message that reproducibly takes the node down, so +-- it needs its own counter and a much smaller ceiling: a transient RPC or SQLite +-- outage must not push legitimate messages toward quarantine. +-- +-- `abandon_count` is incremented when an expired `Processing` lease is reclaimed, +-- so the next worker durably records that the previous dispatch never finished. + +ALTER TABLE p2p_inbox ADD COLUMN abandon_count BIGINT NOT NULL DEFAULT 0; + +ALTER TABLE message ADD COLUMN attempt_count BIGINT NOT NULL DEFAULT 0; +ALTER TABLE message ADD COLUMN abandon_count BIGINT NOT NULL DEFAULT 0; +ALTER TABLE message ADD COLUMN last_error TEXT; + +CREATE INDEX IF NOT EXISTS idx_message_claimable ON message (state, lock_time_until, created_at); diff --git a/crates/store/src/localdb.rs b/crates/store/src/localdb.rs index aa8e2f9b..f93ff7d6 100644 --- a/crates/store/src/localdb.rs +++ b/crates/store/src/localdb.rs @@ -23,6 +23,16 @@ fn get_current_timestamp_secs() -> i64 { SystemTime::now().duration_since(UNIX_EPOCH).unwrap().as_secs() as i64 } +/// Columns every `message` SELECT must fetch. +const MESSAGE_COLUMNS: &str = "message_id, business_id, from_peer, actor, msg_type, content, \ + message_version, state, weight, lock_time_until, attempt_count, abandon_count, last_error, \ + created_at"; + +/// Columns every `p2p_inbox` SELECT must fetch. +const P2P_INBOX_COLUMNS: &str = "message_id, business_id, actor, from_peer, msg_type, content, \ + content_size, state, attempt_count, abandon_count, next_retry_at, lease_until, lease_token, \ + last_error, created_at, updated_at"; + fn message_from_row(row: &SqliteRow) -> Result { Ok(Message { message_id: row.try_get("message_id")?, @@ -35,6 +45,9 @@ fn message_from_row(row: &SqliteRow) -> Result { message_version: row.try_get("message_version")?, weight: row.try_get("weight")?, lock_time_until: row.try_get("lock_time_until")?, + attempt_count: row.try_get("attempt_count")?, + abandon_count: row.try_get("abandon_count")?, + last_error: row.try_get("last_error")?, created_at: row.try_get("created_at")?, }) } @@ -50,6 +63,7 @@ fn p2p_inbox_message_from_row(row: &SqliteRow) -> Result StorageProcessor<'a> { } } - /// Returns grouped instance, graph, and message state counts for Node metrics. + /// Returns grouped instance, graph, and queue state counts for Node metrics. pub async fn node_metrics_state_counts(&mut self) -> anyhow::Result> { let counts = sqlx::query_as::<_, MetricsStateCount>( r#" @@ -998,6 +1012,15 @@ impl<'a> StorageProcessor<'a> { NULL AS last_success_at FROM message GROUP BY state + UNION ALL + SELECT + 'p2p_inbox' AS category, + state, + COUNT(*) AS count, + MIN(created_at) AS oldest_created_at, + NULL AS last_success_at + FROM p2p_inbox + GROUP BY state ORDER BY category, state "#, ) @@ -1108,65 +1131,61 @@ impl<'a> StorageProcessor<'a> { Ok(counts) } - /// Insert or update an instance - /// - /// Performs an INSERT OR REPLACE operation on the instance table. - /// If an instance with the same instance_id exists, it will be updated. - /// If no instance exists, a new one will be created. + /// Insert an instance only when its ID is not already present. /// /// Parameters: - /// - instance: The complete instance data to insert or update + /// - instance: The complete instance data to insert /// /// Returns: - /// - Ok(true) if the operation affected at least one row - /// - Ok(false) if no rows were affected + /// - Ok(true) if the instance was inserted + /// - Ok(false) if an instance with the same ID already exists /// - Err if the operation failed - pub async fn upsert_instance(&mut self, instance: &Instance) -> anyhow::Result { + pub async fn insert_instance_if_absent(&mut self, instance: &Instance) -> anyhow::Result { let committees_answers_json = serde_json::to_string(&instance.committees_answers)?; - let res = sqlx::query!( - "INSERT OR - REPLACE INTO instance (instance_id, network, from_addr, to_addr, amount, fees, input_utxos, status, goat_tx_hash, goat_tx_height, + let res = sqlx::query( + "INSERT INTO instance (instance_id, network, from_addr, to_addr, amount, fees, input_utxos, status, goat_tx_hash, goat_tx_height, user_xonly_pubkey, user_change_addr, user_refund_addr, btc_txid, pegin_confirm_txid, pegin_cancel_txid, committees_answers, pegin_data_tx_hash, btc_height, parameters, status_updated_at, post_pegin_txhash, created_at, updated_at) - VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?)", - instance.instance_id, - instance.network, - instance.from_addr, - instance.to_addr, - instance.amount, - instance.fees, - instance.input_utxos, - instance.status, - instance.goat_tx_hash, - instance.goat_tx_height, - instance.user_xonly_pubkey, - instance.user_change_addr, - instance.user_refund_addr, - instance.btc_txid, - instance.pegin_confirm_txid, - instance.pegin_cancel_txid, - committees_answers_json, - instance.pegin_data_tx_hash, - instance.btc_height, - instance.parameters, - instance.status_updated_at, - instance.post_pegin_txhash, - instance.created_at, - instance.updated_at + VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?) + ON CONFLICT(instance_id) DO NOTHING", ) - .execute(self.conn()) - .await?; + .bind(instance.instance_id) + .bind(&instance.network) + .bind(&instance.from_addr) + .bind(&instance.to_addr) + .bind(instance.amount) + .bind(instance.fees) + .bind(&instance.input_utxos) + .bind(&instance.status) + .bind(&instance.goat_tx_hash) + .bind(instance.goat_tx_height) + .bind(instance.user_xonly_pubkey) + .bind(&instance.user_change_addr) + .bind(&instance.user_refund_addr) + .bind(&instance.btc_txid) + .bind(&instance.pegin_confirm_txid) + .bind(&instance.pegin_cancel_txid) + .bind(committees_answers_json) + .bind(&instance.pegin_data_tx_hash) + .bind(instance.btc_height) + .bind(&instance.parameters) + .bind(instance.status_updated_at) + .bind(&instance.post_pegin_txhash) + .bind(instance.created_at) + .bind(instance.updated_at) + .execute(self.conn()) + .await?; Ok(res.rows_affected() > 0) } /// Create a bridge-in instance from a pegin request, or refresh one that /// has not moved past the pegin-request stage yet. /// - /// `PeginRequest` is a re-deliverable P2P message, so `upsert_instance` is - /// unsafe here: its `INSERT OR REPLACE` lets a replayed or forged request - /// roll a live instance back to its initial row and clear everything the - /// later stages wrote. The write is therefore a compare-and-swap over the - /// current status, and it only touches the columns a pegin request owns: + /// `PeginRequest` is a re-deliverable P2P message, so a full-row replacement + /// would let a replayed or forged request roll a live instance back to its + /// initial row and clear everything the later stages wrote. The write is + /// therefore a compare-and-swap over the current status, and it only touches + /// the columns a pegin request owns: /// committee answers, instance parameters and the BTC-side fields are never /// overwritten. The caller is responsible for passing canonical request /// metadata - `goat_tx_hash`/`goat_tx_height` are refreshed from it, so that @@ -1301,29 +1320,6 @@ impl<'a> StorageProcessor<'a> { count_query.fetch_one(self.conn()).await?.get::("total_instances"), )) } - /// Get network type by instance ID - /// - /// Retrieves the network type (e.g., "mainnet", "testnet") for a specific instance. - /// - /// Parameters: - /// - instance_id: The UUID of the instance - /// - /// Returns: - /// - Ok(network_string) if the instance was found - /// - Ok("") if no instance with the given ID exists - /// - Err if the query failed - pub async fn get_network_by_instance(&mut self, instance_id: &Uuid) -> anyhow::Result { - if let Some(raw) = - sqlx::query!(r#"SELECT network FROM instance WHERE instance_id = ?"#, instance_id) - .fetch_optional(self.conn()) - .await? - { - Ok(raw.network) - } else { - Ok("".to_string()) - } - } - /// Insert a swap escrow only when its escrow hash is not already present. /// /// The chain-event watcher is the sole writer for Initialize records; @@ -1462,28 +1458,6 @@ impl<'a> StorageProcessor<'a> { Ok(row.rows_affected()) } - /// Update instance status - /// - /// A concise method specifically for updating instance status - pub async fn update_instance_status( - &mut self, - instance_id: &Uuid, - new_status: &str, - ) -> anyhow::Result { - let current_time = get_current_timestamp_secs(); - let result = sqlx::query!( - "UPDATE instance SET status = ?, status_updated_at = ?, updated_at = ? WHERE instance_id = ?", - new_status, - current_time, - current_time, - instance_id - ) - .execute(self.conn()) - .await?; - - Ok(result.rows_affected() > 0) - } - /// Transition an instance only when it is still in the expected status. pub async fn update_instance_status_if_current( &mut self, @@ -1507,48 +1481,6 @@ impl<'a> StorageProcessor<'a> { Ok(result.rows_affected() > 0) } - /// Update instance pegin confirmation information - /// - /// Method specifically for updating pegin confirmation transaction ID and fee - pub async fn update_instance_pegin_confirm( - &mut self, - instance_id: &Uuid, - pegin_confirm_txid: &str, - ) -> anyhow::Result { - let current_time = get_current_timestamp_secs(); - let result = sqlx::query!( - "UPDATE instance SET pegin_confirm_txid = ?, updated_at = ? WHERE instance_id = ?", - pegin_confirm_txid, - current_time, - instance_id - ) - .execute(self.conn()) - .await?; - - Ok(result.rows_affected() > 0) - } - - /// Update instance pegin data transaction ID - /// - /// Method specifically for updating pegin data transaction ID - pub async fn update_instance_pegin_data_txid( - &mut self, - instance_id: &Uuid, - pegin_data_tx_hash: &str, - ) -> anyhow::Result { - let current_time = get_current_timestamp_secs(); - let result = sqlx::query!( - "UPDATE instance SET pegin_data_tx_hash = ?, updated_at = ? WHERE instance_id = ?", - pegin_data_tx_hash, - current_time, - instance_id - ) - .execute(self.conn()) - .await?; - - Ok(result.rows_affected() > 0) - } - /// Update instance fields using builder pattern /// /// This is the most elegant update method, using the InstanceUpdate builder pattern @@ -1593,72 +1525,6 @@ impl<'a> StorageProcessor<'a> { Ok(result.rows_affected() > 0) } - /// Remove a committee answer from an instance - /// - /// This method removes a specific committee's answer from the committees_answers HashMap. - pub async fn remove_instance_committee_answer( - &mut self, - instance_id: &Uuid, - committee: &str, - ) -> anyhow::Result { - // JSON merge-patch removes object members with a null value, so this - // stays atomic with concurrent single-answer additions. - let committee_patch = - serde_json::json!({ (committee): serde_json::Value::Null }).to_string(); - let current_time = get_current_timestamp_secs(); - let result = sqlx::query( - "UPDATE instance \ - SET committees_answers = json_patch(COALESCE(committees_answers, '{}'), json(?)), \ - updated_at = ? \ - WHERE instance_id = ?", - ) - .bind(committee_patch) - .bind(current_time) - .bind(instance_id) - .execute(self.conn()) - .await?; - Ok(result.rows_affected() > 0) - } - - /// Get committees answers for an instance - /// - /// Returns the committees_answers HashMap for a specific instance. - pub async fn get_instance_committees_answers( - &mut self, - instance_id: &Uuid, - ) -> anyhow::Result>>> { - let current_instance = self.find_instance(instance_id).await?; - if let Some(instance) = current_instance { - Ok(Some(instance.committees_answers)) - } else { - Ok(None) - } - } - - /// Replace the complete committee-answer map. - /// - /// Callers that add a single answer should use - /// `update_instance_committee_answer` instead, which merges atomically. - pub async fn update_instance_committees_answers_map( - &mut self, - instance_id: &Uuid, - committees_answers: &IndexMap>, - ) -> anyhow::Result { - let current_time = get_current_timestamp_secs(); - let committees_answers_json = serde_json::to_string(&committees_answers)?; - - let res = sqlx::query!( - "UPDATE instance SET committees_answers = ?, updated_at = ? WHERE instance_id = ?", - committees_answers_json, - current_time, - instance_id - ) - .execute(self.conn()) - .await?; - - Ok(res.rows_affected() > 0) - } - pub async fn update_instance_parameters( &mut self, instance_id: &Uuid, @@ -2003,25 +1869,6 @@ impl<'a> StorageProcessor<'a> { Ok(row) } - pub async fn get_graph_operator(&mut self, graph_id: &Uuid) -> anyhow::Result> { - #[derive(sqlx::FromRow)] - struct OperatorRow { - operator_pubkey: String, - } - if let Some(operator_raw) = sqlx::query_as!( - OperatorRow, - "SELECT operator_pubkey FROM graph WHERE graph_id = ?", - graph_id - ) - .fetch_optional(self.conn()) - .await? - { - Ok(Some(operator_raw.operator_pubkey)) - } else { - Ok(None) - } - } - pub async fn find_graphs(&mut self, params: GraphQuery) -> anyhow::Result<(Vec, i64)> { // Build base query let mut count_params = params.clone(); @@ -2150,31 +1997,6 @@ impl<'a> StorageProcessor<'a> { Ok(res.map(|v| (v.graph_id, v.instance_id, v.cur_prekickoff_txid, v.next_prekickoff))) } - pub async fn get_graphs_ids_and_operator_by_instance_ids( - &mut self, - ids: &[Uuid], - ) -> anyhow::Result> { - #[derive(sqlx::FromRow)] - struct GraphIdRow { - pub graph_id: Uuid, - pub instance_id: Uuid, - pub operator: String, - } - let query_str = format!( - "SELECT graph_id, instance_id, operator - FROM graph - WHERE hex(instance_id) - COLLATE NOCASE IN ({})", - create_place_holders(ids) - ); - let mut update_query = sqlx::query_as::<_, GraphIdRow>(&query_str); - for id in ids { - update_query = update_query.bind(hex::encode(id)); - } - let graph_ids = update_query.fetch_all(self.conn()).await?; - Ok(graph_ids.into_iter().map(|v| (v.graph_id, v.instance_id, v.operator)).collect()) - } - pub async fn get_operator_graphs(&mut self, params: GraphQuery) -> anyhow::Result> { let graph_query_builder = params.get_query_builder("SELECT * FROM graph"); let operator_graph_sql = graph_query_builder.get_sql(); @@ -2183,31 +2005,6 @@ impl<'a> StorageProcessor<'a> { Ok(operator_graphs_query.fetch_all(self.conn()).await?) } - pub async fn get_operator_max_kickoff_index( - &mut self, - operator_pubkey: &str, - ) -> anyhow::Result<(Option, i64)> { - #[derive(sqlx::FromRow)] - struct MaxPreKickoffIndexRow { - pub graph_id: Uuid, - pub kickoff_index: i64, - } - - let record = sqlx::query_as!( - MaxPreKickoffIndexRow, - "SELECT graph_id AS \"graph_id:Uuid\", kickoff_index - FROM graph - WHERE operator_pubkey = ? - ORDER BY kickoff_index DESC - limit 1", - operator_pubkey - ) - .fetch_optional(self.conn()) - .await?; - - Ok(record.map_or((None, 0), |v| (Some(v.graph_id), v.kickoff_index))) - } - pub async fn update_node_timestamp( &mut self, peer_id: &str, @@ -2442,19 +2239,19 @@ impl<'a> StorageProcessor<'a> { Ok((total, alive)) } - pub async fn update_messages_state( + /// Complete the exact local queue claim handed to a worker. + pub async fn complete_local_message( &mut self, message_id: &str, message_version: i64, - state: String, ) -> anyhow::Result { let current_time = get_current_timestamp_secs(); let res = sqlx::query( "UPDATE message \ - SET state = ?, updated_at = ? \ - WHERE message_id = ? AND message_version = ? AND state != 'Cancelled'", + SET state = 'Processed', content = X'', lock_time_until = 0, \ + abandon_count = 0, last_error = NULL, updated_at = ? \ + WHERE message_id = ? AND message_version = ? AND state = 'Processing'", ) - .bind(state) .bind(current_time) .bind(message_id) .bind(message_version) @@ -2464,63 +2261,42 @@ impl<'a> StorageProcessor<'a> { Ok(res.rows_affected() > 0) } - pub async fn update_messages_state_by_business_id( + /// Cancel queued local work for a business object, including work which has + /// already been claimed. Claim completion/defer writes require `Processing`, + /// so an in-flight worker cannot overwrite the terminal cancellation. + pub async fn cancel_messages_by_business_id( &mut self, business_id: &Uuid, msg_type: Option, - old_state: String, - new_state: String, - ) -> anyhow::Result { + ) -> anyhow::Result { let current_time = get_current_timestamp_secs(); let res = match msg_type { Some(msg_type) => { sqlx::query( "UPDATE message \ - SET state = ?, updated_at = ? \ - WHERE business_id = ? AND msg_type = ? AND state = ? AND state != 'Cancelled'", + SET state = 'Cancelled', lock_time_until = 0, updated_at = ? \ + WHERE business_id = ? AND msg_type = ? \ + AND state IN ('Pending', 'Processing')", ) - .bind(new_state) .bind(current_time) .bind(business_id) .bind(msg_type) - .bind(old_state) .execute(self.conn()) .await? } None => { sqlx::query( "UPDATE message \ - SET state = ?, updated_at = ? \ - WHERE business_id = ? AND state = ? AND state != 'Cancelled'", + SET state = 'Cancelled', lock_time_until = 0, updated_at = ? \ + WHERE business_id = ? AND state IN ('Pending', 'Processing')", ) - .bind(new_state) .bind(current_time) .bind(business_id) - .bind(old_state) .execute(self.conn()) .await? } }; - Ok(res.rows_affected() > 0) - } - - pub async fn update_messages_lock_time_until( - &mut self, - message_id: &str, - message_version: i64, - lock_time_until: i64, - ) -> anyhow::Result { - let current_time = get_current_timestamp_secs(); - let res = sqlx::query!( - "Update message Set lock_time_until = ?, updated_at = ? WHERE message_id = ? AND message_version = ?", - lock_time_until, - current_time, - message_id, - message_version - - ).execute(self.conn()).await?; - - Ok(res.rows_affected() > 0) + Ok(res.rows_affected()) } pub async fn set_messages_expired(&mut self, expired: i64) -> anyhow::Result<()> { @@ -2548,21 +2324,9 @@ impl<'a> StorageProcessor<'a> { business_id: &Uuid, msg_type: &str, ) -> anyhow::Result> { - let row = sqlx::query( - "SELECT message_id, - business_id, - from_peer, - actor, - msg_type, - content, - message_version, - state, - weight, - lock_time_until, - created_at - FROM message - WHERE business_id = ? AND msg_type = ?", - ) + let row = sqlx::query(&format!( + "SELECT {MESSAGE_COLUMNS} FROM message WHERE business_id = ? AND msg_type = ?" + )) .bind(business_id) .bind(msg_type) .fetch_optional(self.conn()) @@ -2573,108 +2337,369 @@ impl<'a> StorageProcessor<'a> { &mut self, message_id: &str, ) -> anyhow::Result> { - let row = sqlx::query( - "SELECT message_id, - business_id, - from_peer, - actor, - msg_type, - content, - message_version, - state, - weight, - lock_time_until, - created_at - FROM message - WHERE message_id = ?", + let row = + sqlx::query(&format!("SELECT {MESSAGE_COLUMNS} FROM message WHERE message_id = ?")) + .bind(message_id) + .fetch_optional(self.conn()) + .await?; + Ok(row.map(|row| message_from_row(&row)).transpose()?) + } + + /// Retire local messages whose claims keep failing to report an outcome. + /// + /// A surviving `message` row makes the producer treat the work as already + /// created, so retiring on repeated handler errors would strand it until the + /// reaper; repeated abandons mean the node went down mid-dispatch on this + /// payload, which retrying cannot fix. + pub async fn quarantine_local_messages( + &mut self, + now: i64, + max_abandons: i64, + ) -> anyhow::Result { + let result = sqlx::query( + "UPDATE message \ + SET state = 'Quarantined', \ + abandon_count = abandon_count + CASE WHEN state = 'Processing' THEN 1 ELSE 0 END, \ + lock_time_until = 0, \ + last_error = ?, updated_at = ? \ + WHERE state IN ('Pending', 'Processing') \ + AND lock_time_until <= ? \ + AND abandon_count + CASE WHEN state = 'Processing' THEN 1 ELSE 0 END >= ?", ) - .bind(message_id) - .fetch_optional(self.conn()) + .bind(format!("quarantined: exceeded max abandoned claims ({max_abandons})")) + .bind(now) + .bind(now) + .bind(max_abandons) + .execute(self.conn()) .await?; - Ok(row.map(|row| message_from_row(&row)).transpose()?) + Ok(result.rows_affected()) } - pub async fn filter_messages( + /// Rows the local dispatcher may attempt right now, oldest first. + /// + /// Nothing is written here: the dispatcher claims each row with + /// [`Self::claim_local_message`] immediately before dispatching it. Claiming + /// a whole batch up front meant that an abort or kill mid-dispatch charged + /// an unfinished attempt to every row in the batch, so healthy messages + /// followed the poison message into quarantine. + pub async fn list_claimable_local_messages( &mut self, - state: String, - weight: i64, - lock_time_until: i64, + now: i64, expired: i64, limit: i64, - offset: i64, + max_abandons: i64, ) -> anyhow::Result> { - let rows = sqlx::query( - "SELECT message_id, - business_id, - from_peer, - actor, - msg_type, - content, - message_version, - state, - weight, - lock_time_until, - created_at - FROM message - WHERE state = ? - AND weight >= ? - AND lock_time_until <= ? - AND updated_at >= ? - ORDER BY created_at ASC - LIMIT ? OFFSET ?", - ) - .bind(state) - .bind(weight) - .bind(lock_time_until) + let rows = sqlx::query(&format!( + "SELECT {MESSAGE_COLUMNS} FROM message \ + WHERE state IN ('Pending', 'Processing') \ + AND lock_time_until <= ? \ + AND updated_at >= ? \ + AND abandon_count < ? \ + ORDER BY created_at ASC \ + LIMIT ?" + )) + .bind(now) .bind(expired) + .bind(max_abandons) .bind(limit) - .bind(offset) .fetch_all(self.conn()) .await?; - rows.into_iter() - .map(|row| message_from_row(&row)) - .collect::, _>>() - .map_err(Into::into) + rows.iter().map(message_from_row).collect::, _>>().map_err(Into::into) } - pub async fn get_message_queue_stats( + /// Claim exactly one local message for dispatch. + /// + /// Without a durable claim, a handler that panicked left the row `Pending` + /// with its lock untouched, so the very next tick re-read it and panicked + /// again with no backoff at all. Charging the claim before dispatch means + /// the record survives an abort or a kill, not just an unwinding panic. + /// + /// Re-claiming a row that is still `Processing` means the previous attempt + /// never reported an outcome, which is charged as an abandon. + /// `message_version` is deliberately left alone: callers guard their + /// completion writes with the version they were handed, and bumping it here + /// would make every one of those writes miss. Returns `None` when the row + /// is no longer claimable: cancelled, re-armed under a new version, or + /// locked since it was listed. + pub async fn claim_local_message( &mut self, - actor: &str, + message_id: &str, + message_version: i64, now: i64, - ) -> anyhow::Result { - let row = sqlx::query( - r#"SELECT - COALESCE(SUM(CASE WHEN state = 'Pending' AND lock_time_until <= ? THEN 1 ELSE 0 END), 0) AS pending_ready, - COALESCE(SUM(CASE WHEN state = 'Pending' AND lock_time_until > ? THEN 1 ELSE 0 END), 0) AS pending_locked, - COALESCE(SUM(CASE WHEN state = 'Failed' THEN 1 ELSE 0 END), 0) AS failed, - MIN(CASE WHEN state = 'Pending' THEN created_at END) AS oldest_pending_at - FROM message - WHERE actor = ?"#, - ) + lease_until: i64, + ) -> anyhow::Result> { + let row = sqlx::query(&format!( + "UPDATE message \ + SET state = 'Processing', \ + abandon_count = abandon_count + CASE WHEN state = 'Processing' THEN 1 ELSE 0 END, \ + lock_time_until = ?, updated_at = ? \ + WHERE message_id = ? AND message_version = ? \ + AND state IN ('Pending', 'Processing') \ + AND lock_time_until <= ? \ + RETURNING {MESSAGE_COLUMNS}" + )) + .bind(lease_until) .bind(now) + .bind(message_id) + .bind(message_version) .bind(now) - .bind(actor) - .fetch_one(self.conn()) + .fetch_optional(self.conn()) .await?; - Ok(MessageQueueStats { - pending_ready: row.try_get("pending_ready")?, - pending_locked: row.try_get("pending_locked")?, - failed: row.try_get("failed")?, - oldest_pending_at: row.try_get("oldest_pending_at")?, - }) + Ok(row.map(|row| message_from_row(&row)).transpose()?) } - pub async fn find_message_debug_overviews( + /// List and claim up to `limit` rows in one call. + /// + /// Production dispatchers claim one row at a time; this convenience exists + /// for tests and tooling that need a whole batch held under a lease. + pub async fn claim_local_messages( &mut self, - business_id: &Uuid, - ) -> anyhow::Result> { - Ok(sqlx::query_as::<_, MessageDebugOverview>( - r#"SELECT m.message_id, - m.actor, - m.msg_type, - m.state, - m.lock_time_until, - m.created_at, + now: i64, + lease_until: i64, + expired: i64, + limit: i64, + max_abandons: i64, + ) -> anyhow::Result> { + let candidates = + self.list_claimable_local_messages(now, expired, limit, max_abandons).await?; + let mut claimed = Vec::with_capacity(candidates.len()); + for candidate in candidates { + if let Some(message) = self + .claim_local_message( + &candidate.message_id, + candidate.message_version, + now, + lease_until, + ) + .await? + { + claimed.push(message); + } + } + Ok(claimed) + } + + /// Record a failed dispatch attempt and reschedule it with backoff. + /// + /// `attempt_count` is observability only. Only an unfinished claim increments + /// `abandon_count` and contributes to quarantine. This is for a handler + /// error reported to the dispatcher, which is a completed attempt; a handler + /// rescheduling its own row uses [`Self::self_defer_local_message`]. + pub async fn defer_local_message( + &mut self, + message_id: &str, + message_version: i64, + lock_time_until: i64, + error: &str, + ) -> anyhow::Result { + let result = sqlx::query( + "UPDATE message \ + SET state = 'Pending', attempt_count = attempt_count + 1, \ + abandon_count = 0, lock_time_until = ?, last_error = ?, updated_at = ? \ + WHERE message_id = ? AND message_version = ? AND state = 'Processing'", + ) + .bind(lock_time_until) + .bind(error.chars().take(1024).collect::()) + .bind(get_current_timestamp_secs()) + .bind(message_id) + .bind(message_version) + .execute(self.conn()) + .await?; + Ok(result.rows_affected() > 0) + } + + /// Reschedule the row a handler is currently running, at that handler's + /// own request. + /// + /// Unlike [`Self::defer_local_message`], the consecutive-abandon counter is + /// left untouched: the handler is still running and may yet panic, and + /// resetting here let a handler that reschedules itself and then panics + /// start every round from zero, so it never reached quarantine. The + /// dispatcher resets the counter with + /// [`Self::confirm_local_message_self_defer`] once the handler returned. + pub async fn self_defer_local_message( + &mut self, + message_id: &str, + message_version: i64, + lock_time_until: i64, + reason: &str, + ) -> anyhow::Result { + let result = sqlx::query( + "UPDATE message \ + SET state = 'Pending', attempt_count = attempt_count + 1, \ + lock_time_until = ?, last_error = ?, updated_at = ? \ + WHERE message_id = ? AND message_version = ? AND state = 'Processing'", + ) + .bind(lock_time_until) + .bind(reason.chars().take(1024).collect::()) + .bind(get_current_timestamp_secs()) + .bind(message_id) + .bind(message_version) + .execute(self.conn()) + .await?; + Ok(result.rows_affected() > 0) + } + + /// Acknowledge a self-deferred row once its handler has returned. + /// + /// Only at this point is the attempt known to have reported an outcome, so + /// only here does the consecutive-abandon counter reset. Returns `false` + /// when the row is not `Pending` under this claim version, which means it + /// was not self-deferred by the caller. + pub async fn confirm_local_message_self_defer( + &mut self, + message_id: &str, + message_version: i64, + ) -> anyhow::Result { + let result = sqlx::query( + "UPDATE message SET abandon_count = 0, updated_at = ? \ + WHERE message_id = ? AND message_version = ? AND state = 'Pending'", + ) + .bind(get_current_timestamp_secs()) + .bind(message_id) + .bind(message_version) + .execute(self.conn()) + .await?; + Ok(result.rows_affected() > 0) + } + + /// Record a handler panic before shutting down the process. Unlike a normal + /// defer, this increments the consecutive unfinished-attempt counter and + /// pushes the next attempt out by `backoff_secs` per recorded abandon, so a + /// supervisor restart cannot replay the payload at full speed. + /// + /// A handler may reschedule its own row and then panic, leaving the row + /// `Pending` already. The version guard still identifies the claim, so the + /// abandon is charged either way and the longer of the two delays wins. + pub async fn abandon_local_message( + &mut self, + message_id: &str, + message_version: i64, + now: i64, + backoff_secs: i64, + error: &str, + ) -> anyhow::Result { + let result = sqlx::query( + "UPDATE message \ + SET state = 'Pending', abandon_count = abandon_count + 1, \ + lock_time_until = MAX(lock_time_until, ? + ? * (abandon_count + 1)), \ + last_error = ?, updated_at = ? \ + WHERE message_id = ? AND message_version = ? \ + AND state IN ('Processing', 'Pending')", + ) + .bind(now) + .bind(backoff_secs) + .bind(error.chars().take(1024).collect::()) + .bind(now) + .bind(message_id) + .bind(message_version) + .execute(self.conn()) + .await?; + Ok(result.rows_affected() > 0) + } + + /// Terminally drop a local message whose payload the node can never process. + pub async fn fail_local_message( + &mut self, + message_id: &str, + message_version: i64, + error: &str, + ) -> anyhow::Result { + let result = sqlx::query( + "UPDATE message \ + SET state = 'Failed', content = X'', lock_time_until = 0, \ + last_error = ?, updated_at = ? \ + WHERE message_id = ? AND message_version = ? AND state = 'Processing'", + ) + .bind(error.chars().take(1024).collect::()) + .bind(get_current_timestamp_secs()) + .bind(message_id) + .bind(message_version) + .execute(self.conn()) + .await?; + Ok(result.rows_affected() > 0) + } + + /// Release local claims during a graceful process shutdown. The database is + /// process-local, so every `Processing` row belongs to this node process. + pub async fn release_processing_local_messages(&mut self) -> anyhow::Result { + let result = sqlx::query( + "UPDATE message \ + SET state = 'Pending', lock_time_until = 0, updated_at = ? \ + WHERE state = 'Processing'", + ) + .bind(get_current_timestamp_secs()) + .execute(self.conn()) + .await?; + Ok(result.rows_affected()) + } + + /// Startup sweep for claims left behind by a process that no longer exists. + /// + /// The database is process-local, so at startup every `Processing` row is + /// an attempt that never reported an outcome. Charging it now, rather than + /// when the lease lapses, keeps the row from sitting locked for the whole + /// lease while every producer that touches it backs off with + /// ResourceLocked. The same per-abandon backoff as a panic applies. + pub async fn reclaim_processing_local_messages( + &mut self, + now: i64, + backoff_secs: i64, + ) -> anyhow::Result { + let result = sqlx::query( + "UPDATE message \ + SET state = 'Pending', abandon_count = abandon_count + 1, \ + lock_time_until = ? + ? * (abandon_count + 1), \ + last_error = 'reclaimed at startup: previous process exited mid-dispatch', \ + updated_at = ? \ + WHERE state = 'Processing'", + ) + .bind(now) + .bind(backoff_secs) + .bind(now) + .execute(self.conn()) + .await?; + Ok(result.rows_affected()) + } + + pub async fn get_message_queue_stats( + &mut self, + actor: &str, + now: i64, + ) -> anyhow::Result { + let row = sqlx::query( + r#"SELECT + COALESCE(SUM(CASE WHEN state = 'Pending' AND lock_time_until <= ? THEN 1 ELSE 0 END), 0) AS pending_ready, + COALESCE(SUM(CASE WHEN state = 'Pending' AND lock_time_until > ? THEN 1 ELSE 0 END), 0) AS pending_locked, + COALESCE(SUM(CASE WHEN state IN ('Failed', 'Quarantined') THEN 1 ELSE 0 END), 0) AS failed, + MIN(CASE WHEN state = 'Pending' THEN created_at END) AS oldest_pending_at + FROM message + WHERE actor = ?"#, + ) + .bind(now) + .bind(now) + .bind(actor) + .fetch_one(self.conn()) + .await?; + Ok(MessageQueueStats { + pending_ready: row.try_get("pending_ready")?, + pending_locked: row.try_get("pending_locked")?, + failed: row.try_get("failed")?, + oldest_pending_at: row.try_get("oldest_pending_at")?, + }) + } + + pub async fn find_message_debug_overviews( + &mut self, + business_id: &Uuid, + ) -> anyhow::Result> { + Ok(sqlx::query_as::<_, MessageDebugOverview>( + r#"SELECT m.message_id, + m.actor, + m.msg_type, + m.state, + m.lock_time_until, + m.created_at, m.updated_at, COALESCE(reason_counts.reason_count, 0) AS reason_count, latest_reason.reason_code AS last_reason_code, @@ -2778,6 +2803,13 @@ impl<'a> StorageProcessor<'a> { Ok(()) } + /// Insert a local message, or refresh an existing one. + /// + /// Terminal states are excluded so a retired row stays retired. + /// [`Self::fail_local_message`] and [`Self::quarantine_local_messages`] + /// both mean the payload must not run again automatically; + /// without the exclusion a periodic producer re-upserting the same + /// deterministic message_id would resurrect it on every tick. pub async fn upsert_message(&mut self, msg: Message) -> anyhow::Result { let current_time = get_current_timestamp_secs(); let res = sqlx::query( @@ -2792,8 +2824,9 @@ impl<'a> StorageProcessor<'a> { message_version = message.message_version + 1, lock_time_until = excluded.lock_time_until, weight = excluded.weight, + last_error = NULL, updated_at = excluded.updated_at - WHERE message.state != 'Cancelled'"#, + WHERE message.state NOT IN ('Processing', 'Cancelled', 'Failed', 'Quarantined')"#, ) .bind(msg.message_id) .bind(msg.business_id) @@ -2841,13 +2874,47 @@ impl<'a> StorageProcessor<'a> { Ok(result.rows_affected() > 0) } - /// Claim ready work with a lease. The state predicate on the update keeps - /// this safe when more than one worker observes the same pending rows. - pub async fn claim_p2p_inbox_messages( + /// Move inbox rows that repeatedly abandoned a claim out of the work set. + /// + /// `attempt_count` remains a pure diagnostic counter. Only `abandon_count` + /// is a poison-message signal: the claim + /// charge is committed before dispatch, so it is recorded even when the + /// process is aborted or killed rather than unwinding. + /// + /// Content is retained until the terminal-row TTL so an operator can inspect + /// and manually requeue the message. + pub async fn quarantine_p2p_inbox_messages( + &mut self, + now: i64, + max_abandons: i64, + ) -> anyhow::Result { + let result = sqlx::query( + "UPDATE p2p_inbox \ + SET state = 'Quarantined', \ + abandon_count = abandon_count + CASE WHEN state = 'Processing' THEN 1 ELSE 0 END, \ + lease_until = 0, next_retry_at = 0, \ + last_error = ?, updated_at = ? \ + WHERE state IN ('Pending', 'Processing') \ + AND lease_until <= ? \ + AND abandon_count + CASE WHEN state = 'Processing' THEN 1 ELSE 0 END >= ?", + ) + .bind(format!("quarantined: exceeded max abandoned claims ({max_abandons})")) + .bind(now) + .bind(now) + .bind(max_abandons) + .execute(self.conn()) + .await?; + Ok(result.rows_affected()) + } + + /// Inbox rows the dispatcher may attempt right now, oldest first. Nothing + /// is written; see [`Self::list_claimable_local_messages`] for why rows are + /// claimed one at a time instead of as a batch. + pub async fn list_claimable_p2p_inbox_messages( &mut self, now: i64, - lease_until: i64, limit: i64, + max_abandons: i64, excluded_message_ids: &[String], ) -> anyhow::Result> { let excluded_predicate = if excluded_message_ids.is_empty() { @@ -2856,45 +2923,78 @@ impl<'a> StorageProcessor<'a> { format!(" AND message_id NOT IN ({})", create_place_holders(excluded_message_ids)) }; let query = format!( - "SELECT message_id, business_id, actor, from_peer, msg_type, content, content_size, \ - state, attempt_count, next_retry_at, lease_until, lease_token, last_error, created_at, updated_at \ + "SELECT {P2P_INBOX_COLUMNS} \ FROM p2p_inbox \ WHERE ((state = 'Pending' AND next_retry_at <= ?) \ - OR (state = 'Processing' AND lease_until <= ?)){excluded_predicate} \ + OR (state = 'Processing' AND lease_until <= ?)) \ + AND abandon_count < ?{excluded_predicate} \ ORDER BY created_at ASC \ LIMIT ?" ); - let mut query = sqlx::query(&query).bind(now).bind(now); + let mut query = sqlx::query(&query).bind(now).bind(now).bind(max_abandons); for message_id in excluded_message_ids { query = query.bind(message_id); } let rows = query.bind(limit).fetch_all(self.conn()).await?; + rows.iter() + .map(p2p_inbox_message_from_row) + .collect::, _>>() + .map_err(Into::into) + } - let mut claimed = Vec::with_capacity(rows.len()); - for row in rows { - let mut message = p2p_inbox_message_from_row(&row)?; - let lease_token = Uuid::new_v4().to_string(); - let result = sqlx::query( - "UPDATE p2p_inbox \ - SET state = 'Processing', attempt_count = attempt_count + 1, lease_until = ?, lease_token = ?, updated_at = ? \ - WHERE message_id = ? \ - AND ((state = 'Pending' AND next_retry_at <= ?) \ - OR (state = 'Processing' AND lease_until <= ?))", - ) - .bind(lease_until) - .bind(&lease_token) - .bind(now) - .bind(&message.message_id) - .bind(now) - .bind(now) - .execute(self.conn()) + /// Claim exactly one inbox row under a fresh lease token. + /// + /// Re-claiming a row that is still `Processing` means the previous attempt + /// never reported an outcome: the worker panicked, the process died, or it + /// hung past the lease. That is charged separately from an ordinary handler + /// error so that a transient outage cannot push healthy messages toward + /// quarantine. Returns `None` when the row is no longer claimable. + pub async fn claim_p2p_inbox_message( + &mut self, + message_id: &str, + now: i64, + lease_until: i64, + ) -> anyhow::Result> { + let lease_token = Uuid::new_v4().to_string(); + let row = sqlx::query(&format!( + "UPDATE p2p_inbox \ + SET state = 'Processing', attempt_count = attempt_count + 1, \ + abandon_count = abandon_count + CASE WHEN state = 'Processing' THEN 1 ELSE 0 END, \ + lease_until = ?, lease_token = ?, updated_at = ? \ + WHERE message_id = ? \ + AND ((state = 'Pending' AND next_retry_at <= ?) \ + OR (state = 'Processing' AND lease_until <= ?)) \ + RETURNING {P2P_INBOX_COLUMNS}" + )) + .bind(lease_until) + .bind(&lease_token) + .bind(now) + .bind(message_id) + .bind(now) + .bind(now) + .fetch_optional(self.conn()) + .await?; + Ok(row.map(|row| p2p_inbox_message_from_row(&row)).transpose()?) + } + + /// List and claim up to `limit` inbox rows in one call. Production + /// dispatchers claim one row at a time; this is for tests and tooling. + pub async fn claim_p2p_inbox_messages( + &mut self, + now: i64, + lease_until: i64, + limit: i64, + max_abandons: i64, + excluded_message_ids: &[String], + ) -> anyhow::Result> { + let candidates = self + .list_claimable_p2p_inbox_messages(now, limit, max_abandons, excluded_message_ids) .await?; - if result.rows_affected() > 0 { - message.state = "Processing".to_owned(); - message.attempt_count += 1; - message.lease_until = lease_until; - message.lease_token = lease_token; - message.updated_at = now; + let mut claimed = Vec::with_capacity(candidates.len()); + for candidate in candidates { + if let Some(message) = + self.claim_p2p_inbox_message(&candidate.message_id, now, lease_until).await? + { claimed.push(message); } } @@ -2929,7 +3029,8 @@ impl<'a> StorageProcessor<'a> { ) -> anyhow::Result { let result = sqlx::query( "UPDATE p2p_inbox \ - SET state = 'Pending', lease_until = 0, next_retry_at = ?, last_error = ?, updated_at = ? \ + SET state = 'Pending', abandon_count = 0, lease_until = 0, \ + next_retry_at = ?, last_error = ?, updated_at = ? \ WHERE message_id = ? AND state = 'Processing' AND lease_token = ?", ) .bind(next_retry_at) @@ -2942,6 +3043,35 @@ impl<'a> StorageProcessor<'a> { Ok(result.rows_affected() > 0) } + /// Record a panic from the current lease before terminating the process. + /// The next attempt is pushed out by `backoff_secs` per recorded abandon so + /// a supervisor restart cannot replay the payload at full speed. + pub async fn abandon_p2p_inbox_message( + &mut self, + message_id: &str, + lease_token: &str, + now: i64, + backoff_secs: i64, + error: &str, + ) -> anyhow::Result { + let result = sqlx::query( + "UPDATE p2p_inbox \ + SET state = 'Pending', abandon_count = abandon_count + 1, lease_until = 0, \ + lease_token = '', next_retry_at = ? + ? * (abandon_count + 1), \ + last_error = ?, updated_at = ? \ + WHERE message_id = ? AND state = 'Processing' AND lease_token = ?", + ) + .bind(now) + .bind(backoff_secs) + .bind(error.chars().take(1024).collect::()) + .bind(now) + .bind(message_id) + .bind(lease_token) + .execute(self.conn()) + .await?; + Ok(result.rows_affected() > 0) + } + /// Return claimed work to the queue without charging it as a processing /// attempt. This is used when capacity is unavailable before dispatch. pub async fn defer_p2p_inbox_message( @@ -2975,7 +3105,7 @@ impl<'a> StorageProcessor<'a> { ) -> anyhow::Result { let result = sqlx::query( "UPDATE p2p_inbox \ - SET state = 'Failed', lease_until = 0, next_retry_at = 0, \ + SET state = 'Failed', content = X'', lease_until = 0, next_retry_at = 0, \ last_error = ?, updated_at = ? \ WHERE message_id = ? AND state = 'Processing' AND lease_token = ?", ) @@ -2988,14 +3118,33 @@ impl<'a> StorageProcessor<'a> { Ok(result.rows_affected() > 0) } - pub async fn renew_p2p_inbox_lease( + /// Drop terminal inbox rows once they are older than `expired_before`. + /// + /// Processed/failed payloads are already released. Quarantined payloads are + /// retained only for this bounded inspection/requeue window. Anything still + /// claimable is left alone. + pub async fn purge_terminal_p2p_inbox_messages( &mut self, - message_id: &str, - lease_token: &str, - lease_until: i64, - ) -> anyhow::Result { + expired_before: i64, + ) -> anyhow::Result { let result = sqlx::query( - "UPDATE p2p_inbox SET lease_until = ?, updated_at = ? \ + "DELETE FROM p2p_inbox \ + WHERE state IN ('Processed', 'Failed', 'Quarantined') AND updated_at < ?", + ) + .bind(expired_before) + .execute(self.conn()) + .await?; + Ok(result.rows_affected()) + } + + pub async fn renew_p2p_inbox_lease( + &mut self, + message_id: &str, + lease_token: &str, + lease_until: i64, + ) -> anyhow::Result { + let result = sqlx::query( + "UPDATE p2p_inbox SET lease_until = ?, updated_at = ? \ WHERE message_id = ? AND state = 'Processing' AND lease_token = ?", ) .bind(lease_until) @@ -3007,12 +3156,50 @@ impl<'a> StorageProcessor<'a> { Ok(result.rows_affected() > 0) } + /// Release inbox claims during a graceful process shutdown without charging + /// them as abandoned executions. + pub async fn release_processing_p2p_inbox_messages(&mut self) -> anyhow::Result { + let result = sqlx::query( + "UPDATE p2p_inbox \ + SET state = 'Pending', lease_until = 0, lease_token = '', \ + next_retry_at = 0, updated_at = ? \ + WHERE state = 'Processing'", + ) + .bind(get_current_timestamp_secs()) + .execute(self.conn()) + .await?; + Ok(result.rows_affected()) + } + + /// Startup sweep for inbox claims left behind by a process that no longer + /// exists. See [`Self::reclaim_processing_local_messages`]. + pub async fn reclaim_processing_p2p_inbox_messages( + &mut self, + now: i64, + backoff_secs: i64, + ) -> anyhow::Result { + let result = sqlx::query( + "UPDATE p2p_inbox \ + SET state = 'Pending', abandon_count = abandon_count + 1, lease_until = 0, \ + lease_token = '', next_retry_at = ? + ? * (abandon_count + 1), \ + last_error = 'reclaimed at startup: previous process exited mid-dispatch', \ + updated_at = ? \ + WHERE state = 'Processing'", + ) + .bind(now) + .bind(backoff_secs) + .bind(now) + .execute(self.conn()) + .await?; + Ok(result.rows_affected()) + } + pub async fn requeue_p2p_inbox_message(&mut self, message_id: &str) -> anyhow::Result { let result = sqlx::query( "UPDATE p2p_inbox \ - SET state = 'Pending', attempt_count = 0, next_retry_at = 0, lease_until = 0, \ + SET state = 'Pending', abandon_count = 0, next_retry_at = 0, lease_until = 0, \ lease_token = '', last_error = NULL, updated_at = ? \ - WHERE message_id = ? AND state = 'Failed' AND length(content) > 0", + WHERE message_id = ? AND state = 'Quarantined' AND length(content) > 0", ) .bind(get_current_timestamp_secs()) .bind(message_id) @@ -3288,22 +3475,6 @@ impl<'a> StorageProcessor<'a> { Ok(result.rows_affected() > 0) } - pub async fn has_graph_compensation_marker( - &mut self, - graph_id: Uuid, - message_id: &str, - ) -> anyhow::Result { - let exists: i64 = sqlx::query_scalar( - "SELECT EXISTS(SELECT 1 FROM graph_compensation_marker \ - WHERE graph_id = ? AND message_id = ?)", - ) - .bind(graph_id) - .bind(message_id) - .fetch_one(self.conn()) - .await?; - Ok(exists != 0) - } - pub async fn upsert_pegin_instance_process_data( &mut self, pegin_instance_process_data: &PeginInstanceProcessData, @@ -3392,23 +3563,6 @@ impl<'a> StorageProcessor<'a> { Ok(row) } - pub async fn update_pegin_graph_endorsed( - &mut self, - graph_id: &Uuid, - is_endorsed: bool, - ) -> anyhow::Result<()> { - sqlx::query!( - r#"UPDATE - pegin_graph_process_data - SET is_endorsed = ? - WHERE graph_id = ?"#, - is_endorsed, - graph_id - ) - .execute(self.conn()) - .await?; - Ok(()) - } pub async fn get_pegin_graph_endorsed_len_by_instance_id( &mut self, instance_id: &Uuid, @@ -3744,28 +3898,6 @@ impl<'a> StorageProcessor<'a> { Ok(row) } - pub async fn update_graph_btc_tx_vout_monitor_data( - &mut self, - graph_id: &Uuid, - txid: &SerializableTxid, - monitor_data: String, - ) -> anyhow::Result { - let current_time = get_current_timestamp_secs(); - let res = sqlx::query!( - "UPDATE graph_btc_tx_vout_monitor - SET monitor_data = ?, - updated_at = ? - WHERE graph_id = ? AND txid = ?", - monitor_data, - current_time, - graph_id, - txid - ) - .execute(self.conn()) - .await?; - Ok(res.rows_affected()) - } - pub async fn create_long_running_task_proof( &mut self, long_running_task_proof: &LongRunningTaskProof, @@ -4080,26 +4212,6 @@ impl<'a> StorageProcessor<'a> { Ok(res.rows_affected()) } - pub async fn update_operator_proof_state( - &mut self, - id: i64, - proof_state: i64, - ) -> anyhow::Result { - let current_time = get_current_timestamp_secs(); - let res = sqlx::query!( - "UPDATE operator_proof - SET proof_state = ?, - updated_at = ? - WHERE id = ?", - proof_state, - current_time, - id, - ) - .execute(self.conn()) - .await?; - Ok(res.rows_affected()) - } - pub async fn find_operator_proof_by_instance_and_graph( &mut self, instance_id: &Uuid, @@ -4483,6 +4595,7 @@ pub async fn create_local_db(db_path: &str) -> LocalDB { #[cfg(test)] mod tests { use super::*; + use crate::MessageState; async fn setup_db() -> LocalDB { create_local_db("sqlite::memory:").await @@ -4516,7 +4629,7 @@ mod tests { let mut initing = pegin_instance(instance_id, "UserIniting"); initing.to_addr = "0xuser".to_string(); initing.from_addr = "bcrt1quser".to_string(); - assert!(s.upsert_instance(&initing).await.unwrap()); + assert!(s.insert_instance_if_absent(&initing).await.unwrap()); let mut request = pegin_instance(instance_id, "UserInited"); request.to_addr = "0xuser".to_string(); @@ -4553,7 +4666,7 @@ mod tests { inited.goat_tx_height = 500; inited.committees_answers = IndexMap::from([("0xcommittee".to_string(), vec![1u8, 2, 3])]); inited.parameters = Some("{}".to_string()); - assert!(s.upsert_instance(&inited).await.unwrap()); + assert!(s.insert_instance_if_absent(&inited).await.unwrap()); // A re-delivered request refreshes the row in place; everything the // instance accrued after the request must survive it. @@ -4578,7 +4691,7 @@ mod tests { minted.goat_tx_height = 500; minted.parameters = Some("{}".to_string()); minted.post_pegin_txhash = Some("0xmint".to_string()); - assert!(s.upsert_instance(&minted).await.unwrap()); + assert!(s.insert_instance_if_absent(&minted).await.unwrap()); // Once the instance moves on, a re-delivered request may not pull it back. let replay = pegin_instance(instance_id, "UserInited"); @@ -4593,20 +4706,47 @@ mod tests { } #[tokio::test] - async fn test_upsert_pegin_request_instance_rejects_bridge_out_collision() { + async fn test_upsert_pegin_request_instance_rejects_progressed_instance() { let db = setup_db().await; let mut s = db.acquire().await.unwrap(); let instance_id = Uuid::new_v4(); - let bridge_out = pegin_instance(instance_id, "Initialize"); - assert!(s.upsert_instance(&bridge_out).await.unwrap()); + let progressed = pegin_instance(instance_id, "CommitteesAnswered"); + assert!(s.insert_instance_if_absent(&progressed).await.unwrap()); let request = pegin_instance(instance_id, "UserInited"); assert!( !s.upsert_pegin_request_instance(&request, &pegin_request_statuses()).await.unwrap() ); let stored = s.find_instance(&instance_id).await.unwrap().unwrap(); - assert_eq!(stored.status, "Initialize"); + assert_eq!(stored.status, "CommitteesAnswered"); + } + + #[tokio::test] + async fn test_instance_update_rejects_stale_status_transition() { + let db = setup_db().await; + let instance_id = Uuid::new_v4(); + let mut storage = db.acquire().await.unwrap(); + assert!( + storage + .insert_instance_if_absent(&pegin_instance(instance_id, "RelayerL2Minted")) + .await + .unwrap() + ); + + let updated = storage + .update_instance( + &InstanceUpdate::new_with_instance_id(instance_id) + .with_status("Timeout".to_string()) + .with_only_if_status_in(vec!["Presigned".to_string()]), + ) + .await + .unwrap(); + assert!(!updated); + assert_eq!( + storage.find_instance(&instance_id).await.unwrap().unwrap().status, + "RelayerL2Minted" + ); } #[tokio::test] @@ -4676,6 +4816,719 @@ mod tests { ); } + /// A retired row must stay retired: a periodic producer re-upserting the same + /// deterministic message_id would otherwise resurrect it on every tick. + #[tokio::test] + async fn upsert_does_not_resurrect_a_retired_message() { + let db = setup_db().await; + let mut s = db.acquire().await.unwrap(); + let business_id = Uuid::new_v4(); + let msg = Message { + message_id: "retired-1".to_string(), + business_id, + actor: "Operator".to_string(), + from_peer: "self".to_string(), + msg_type: "AssertReady".to_string(), + content: vec![1, 2], + state: MessageState::Pending.to_string(), + ..Default::default() + }; + assert!(s.upsert_message(msg.clone()).await.unwrap()); + + let claimed = s.claim_local_messages(100, 200, 0, 10, 3).await.unwrap(); + assert_eq!(claimed.len(), 1); + assert!( + s.fail_local_message("retired-1", claimed[0].message_version, "handler panicked") + .await + .unwrap() + ); + + // The producer tries again with the same deterministic id. + assert!(!s.upsert_message(msg).await.unwrap(), "a retired row must not be revived"); + let row = s.find_messages_by_id("retired-1").await.unwrap().unwrap(); + assert_eq!(row.state, "Failed"); + assert!(row.content.is_empty(), "the retired payload must stay released"); + } + + #[tokio::test] + async fn upsert_does_not_replace_an_active_local_claim() { + let db = setup_db().await; + let mut s = db.acquire().await.unwrap(); + let business_id = Uuid::new_v4(); + let mut message = Message { + message_id: "active-1".to_owned(), + business_id, + actor: "Operator".to_owned(), + from_peer: "self".to_owned(), + msg_type: "AssertReady".to_owned(), + content: vec![1, 2], + state: MessageState::Pending.to_string(), + ..Default::default() + }; + assert!(s.upsert_message(message.clone()).await.unwrap()); + let claimed = s.claim_local_messages(100, 200, 0, 10, 3).await.unwrap(); + assert_eq!(claimed.len(), 1); + + message.content = vec![9, 9]; + assert!(!s.upsert_message(message).await.unwrap()); + let stored = s.find_messages_by_id("active-1").await.unwrap().unwrap(); + assert_eq!(stored.state, "Processing"); + assert_eq!(stored.content, vec![1, 2]); + assert_eq!(stored.message_version, claimed[0].message_version); + } + + #[tokio::test] + async fn producer_replay_does_not_forgive_an_abandoned_local_claim() { + let db = setup_db().await; + let mut s = db.acquire().await.unwrap(); + let message = Message { + message_id: "abandoned-replay-1".to_owned(), + business_id: Uuid::new_v4(), + actor: "Operator".to_owned(), + from_peer: "self".to_owned(), + msg_type: "AssertReady".to_owned(), + content: vec![1, 2], + state: MessageState::Pending.to_string(), + ..Default::default() + }; + assert!(s.upsert_message(message.clone()).await.unwrap()); + sqlx::query("UPDATE message SET abandon_count = 2 WHERE message_id = ?") + .bind(&message.message_id) + .execute(s.conn()) + .await + .unwrap(); + + assert!(s.upsert_message(message.clone()).await.unwrap()); + let stored = s.find_messages_by_id(&message.message_id).await.unwrap().unwrap(); + assert_eq!(stored.abandon_count, 2); + } + + #[tokio::test] + async fn self_defer_cannot_be_overwritten_by_stale_completion() { + let db = setup_db().await; + let mut s = db.acquire().await.unwrap(); + let business_id = Uuid::new_v4(); + sqlx::query( + "INSERT INTO message (message_id, business_id, actor, msg_type, content, state, lock_time_until, created_at, updated_at) \ + VALUES ('self-defer-1', ?, 'Operator', 'AssertReady', X'0102', 'Pending', 0, 10, 10)", + ) + .bind(business_id) + .execute(s.conn()) + .await + .unwrap(); + let claimed = s.claim_local_messages(100, 200, 0, 10, 3).await.unwrap(); + assert!( + s.self_defer_local_message( + "self-defer-1", + claimed[0].message_version, + 150, + "not ready" + ) + .await + .unwrap() + ); + assert!( + !s.complete_local_message("self-defer-1", claimed[0].message_version).await.unwrap() + ); + let stored = s.find_messages_by_id("self-defer-1").await.unwrap().unwrap(); + assert_eq!(stored.state, "Pending"); + assert_eq!(stored.attempt_count, 1); + } + + #[tokio::test] + async fn cancellation_reaches_pending_and_processing_local_messages() { + let db = setup_db().await; + let mut s = db.acquire().await.unwrap(); + let business_id = Uuid::new_v4(); + for (message_id, msg_type, state, lock_time_until) in [ + ("cancel-processing", "AssertReady", "Processing", 500), + ("cancel-pending", "PostReady", "Pending", 400), + ("keep-processed", "KickoffReady", "Processed", 0), + ] { + sqlx::query( + "INSERT INTO message \ + (message_id, business_id, actor, msg_type, content, state, lock_time_until, created_at, updated_at) \ + VALUES (?, ?, 'Operator', ?, X'01', ?, ?, 10, 10)", + ) + .bind(message_id) + .bind(business_id) + .bind(msg_type) + .bind(state) + .bind(lock_time_until) + .execute(s.conn()) + .await + .unwrap(); + } + + assert_eq!( + s.cancel_messages_by_business_id(&business_id, Some("AssertReady".to_owned())) + .await + .unwrap(), + 1 + ); + let processing = s.find_messages_by_id("cancel-processing").await.unwrap().unwrap(); + assert_eq!(processing.state, "Cancelled"); + assert_eq!(processing.lock_time_until, 0); + assert_eq!(s.cancel_messages_by_business_id(&business_id, None).await.unwrap(), 1); + assert_eq!( + s.find_messages_by_id("cancel-pending").await.unwrap().unwrap().state, + "Cancelled" + ); + assert_eq!( + s.find_messages_by_id("keep-processed").await.unwrap().unwrap().state, + "Processed" + ); + } + + /// Every `message` SELECT must fetch the full column set `message_from_row` + /// reads. Adding a column and updating only some of the hand-written SELECT + /// lists fails at runtime, not at compile time, so pin all of them here. + #[tokio::test] + async fn every_message_query_hydrates_the_full_row() { + let db = setup_db().await; + let mut s = db.acquire().await.unwrap(); + let business_id = Uuid::new_v4(); + sqlx::query( + "INSERT INTO message (message_id, business_id, actor, msg_type, content, state, lock_time_until, created_at, updated_at) \ + VALUES (?, ?, 'Operator', 'AssertReady', X'0102', 'Pending', 0, 10, 10)", + ) + .bind("hydrate-1") + .bind(business_id) + .execute(s.conn()) + .await + .unwrap(); + + let by_id = s.find_messages_by_id("hydrate-1").await.unwrap().expect("row by id"); + assert_eq!(by_id.attempt_count, 0); + assert_eq!(by_id.abandon_count, 0); + assert!(by_id.last_error.is_none()); + + let by_business = s + .find_message_by_business_id(&business_id, "AssertReady") + .await + .unwrap() + .expect("row by business id"); + assert_eq!(by_business.message_id, "hydrate-1"); + + let claimed = s.claim_local_messages(100, 200, 0, 10, 3).await.unwrap(); + assert_eq!(claimed.len(), 1); + assert_eq!(claimed[0].message_id, "hydrate-1"); + } + + /// A message is only charged an abandon when its previous claim never + /// reported an outcome. An ordinary deferred retry must not count, otherwise + /// a transient outage would drive healthy work into quarantine. + #[tokio::test] + async fn test_inbox_abandon_is_charged_only_for_unfinished_claims() { + let db = setup_db().await; + let mut s = db.acquire().await.unwrap(); + let message = P2pInboxMessage { + message_id: "inbox-abandon-1".to_string(), + actor: "Operator".to_string(), + from_peer: "peer".to_string(), + msg_type: "CreateGraph".to_string(), + content: vec![1, 2, 3], + content_size: 3, + ..Default::default() + }; + assert!(s.insert_p2p_inbox_message(&message).await.unwrap()); + + // First claim of a Pending row: a retry attempt, not an abandon. + let claimed = s.claim_p2p_inbox_messages(100, 200, 10, 3, &[]).await.unwrap(); + assert_eq!(claimed.len(), 1); + assert_eq!(claimed[0].attempt_count, 1); + assert_eq!(claimed[0].abandon_count, 0); + + // The handler returned a retryable error and the row went back to Pending. + assert!( + s.retry_p2p_inbox_message( + &message.message_id, + &claimed[0].lease_token, + 150, + "storage busy" + ) + .await + .unwrap() + ); + let claimed = s.claim_p2p_inbox_messages(160, 260, 10, 3, &[]).await.unwrap(); + assert_eq!(claimed.len(), 1); + assert_eq!(claimed[0].attempt_count, 2, "a retry is recorded"); + assert_eq!(claimed[0].abandon_count, 0, "a retry must not charge the abandon budget"); + + // Now simulate a worker that died mid-dispatch: the row is still + // Processing and its lease has expired. + let claimed = s.claim_p2p_inbox_messages(400, 500, 10, 3, &[]).await.unwrap(); + assert_eq!(claimed.len(), 1); + assert_eq!(claimed[0].attempt_count, 3); + assert_eq!(claimed[0].abandon_count, 1, "an unfinished claim charges the abandon budget"); + + assert!( + s.retry_p2p_inbox_message( + &message.message_id, + &claimed[0].lease_token, + 450, + "dependency pending", + ) + .await + .unwrap() + ); + let claimed = s.claim_p2p_inbox_messages(460, 560, 10, 3, &[]).await.unwrap(); + assert_eq!(claimed[0].abandon_count, 0, "a reported outcome resets consecutive abandons"); + } + + /// A payload that keeps taking the node down is quarantined rather than + /// dispatched again. Its content remains available for manual requeue until + /// terminal-row cleanup removes it. + #[tokio::test] + async fn test_inbox_quarantines_repeatedly_abandoned_message() { + let db = setup_db().await; + let mut s = db.acquire().await.unwrap(); + let message = P2pInboxMessage { + message_id: "inbox-poison-1".to_string(), + actor: "Operator".to_string(), + from_peer: "peer".to_string(), + msg_type: "GraphFinalize".to_string(), + content: vec![9; 64], + content_size: 64, + ..Default::default() + }; + assert!(s.insert_p2p_inbox_message(&message).await.unwrap()); + + // Claims that never report an outcome, each one lease apart. On the + // sweep after the third expired claim, that final abandon is recorded + // as part of the quarantine transition. + let mut now = 100; + for attempt in 1..=3 { + let claimed = s.claim_p2p_inbox_messages(now, now + 10, 10, 3, &[]).await.unwrap(); + assert_eq!(claimed.len(), 1, "claim {attempt} should still be served"); + assert_eq!( + claimed[0].abandon_count, + attempt - 1, + "claim {attempt} charges one abandon per unfinished predecessor" + ); + now += 100; + } + + let quarantined = s.quarantine_p2p_inbox_messages(now, 3).await.unwrap(); + assert_eq!(quarantined, 1); + + let claimed = s.claim_p2p_inbox_messages(now, now + 10, 10, 3, &[]).await.unwrap(); + assert!(claimed.is_empty(), "a quarantined message must not be claimed again"); + + let row = + sqlx::query("SELECT state, content, last_error FROM p2p_inbox WHERE message_id = ?") + .bind(&message.message_id) + .fetch_one(s.conn()) + .await + .unwrap(); + assert_eq!(row.get::("state"), "Quarantined"); + assert_eq!(row.get::, _>("content"), message.content); + assert!(row.get::, _>("last_error").is_some()); + + assert!(s.requeue_p2p_inbox_message(&message.message_id).await.unwrap()); + let requeued = s.claim_p2p_inbox_messages(now, now + 10, 10, 3, &[]).await.unwrap(); + assert_eq!(requeued.len(), 1); + assert_eq!(requeued[0].abandon_count, 0); + } + + /// The local queue used to hand out work without writing anything, so a + /// handler that panicked left the row immediately claimable again. A claim + /// must hold the message for the length of its lease. + #[tokio::test] + async fn test_local_claim_holds_lease_and_charges_abandon() { + let db = setup_db().await; + let mut s = db.acquire().await.unwrap(); + let business_id = Uuid::new_v4(); + sqlx::query( + "INSERT INTO message (message_id, business_id, actor, msg_type, content, state, lock_time_until, created_at, updated_at) \ + VALUES (?, ?, 'Operator', 'AssertReady', X'0102', 'Pending', 0, 10, 10)", + ) + .bind("local-claim-1") + .bind(business_id) + .execute(s.conn()) + .await + .unwrap(); + + let claimed = s.claim_local_messages(100, 200, 0, 10, 3).await.unwrap(); + assert_eq!(claimed.len(), 1); + assert_eq!(claimed[0].abandon_count, 0); + + // Still inside the lease: the message must not be handed out again. + let claimed_again = s.claim_local_messages(150, 250, 0, 10, 3).await.unwrap(); + assert!(claimed_again.is_empty(), "a leased message must not be re-claimed"); + + // Lease expired with no outcome reported: that is an abandon. + let reclaimed = s.claim_local_messages(300, 400, 0, 10, 3).await.unwrap(); + assert_eq!(reclaimed.len(), 1); + assert_eq!(reclaimed[0].abandon_count, 1); + } + + #[tokio::test] + async fn graceful_shutdown_releases_claims_without_charging_abandon() { + let db = setup_db().await; + let mut s = db.acquire().await.unwrap(); + let business_id = Uuid::new_v4(); + sqlx::query( + "INSERT INTO message (message_id, business_id, actor, msg_type, content, state, lock_time_until, created_at, updated_at) \ + VALUES ('shutdown-local', ?, 'Operator', 'AssertReady', X'01', 'Pending', 0, 10, 10)", + ) + .bind(business_id) + .execute(s.conn()) + .await + .unwrap(); + let inbox = P2pInboxMessage { + message_id: "shutdown-inbox".to_owned(), + actor: "Operator".to_owned(), + from_peer: "peer".to_owned(), + msg_type: "CreateGraph".to_owned(), + content: vec![1], + content_size: 1, + ..Default::default() + }; + assert!(s.insert_p2p_inbox_message(&inbox).await.unwrap()); + assert_eq!(s.claim_local_messages(100, 200, 0, 10, 3).await.unwrap().len(), 1); + assert_eq!(s.claim_p2p_inbox_messages(100, 200, 10, 3, &[]).await.unwrap().len(), 1); + + assert_eq!(s.release_processing_local_messages().await.unwrap(), 1); + assert_eq!(s.release_processing_p2p_inbox_messages().await.unwrap(), 1); + + let local = s.find_messages_by_id("shutdown-local").await.unwrap().unwrap(); + assert_eq!(local.state, "Pending"); + assert_eq!(local.abandon_count, 0); + let inbox = sqlx::query( + "SELECT state, abandon_count, lease_token FROM p2p_inbox WHERE message_id = ?", + ) + .bind("shutdown-inbox") + .fetch_one(s.conn()) + .await + .unwrap(); + assert_eq!(inbox.get::("state"), "Pending"); + assert_eq!(inbox.get::("abandon_count"), 0); + assert!(inbox.get::("lease_token").is_empty()); + } + + /// Deferring a local message records the retry, but only abandoned claims + /// contribute to quarantine. + #[tokio::test] + async fn test_local_defer_charges_attempts_but_only_abandons_quarantine() { + let db = setup_db().await; + let mut s = db.acquire().await.unwrap(); + let business_id = Uuid::new_v4(); + sqlx::query( + "INSERT INTO message (message_id, business_id, actor, msg_type, content, state, lock_time_until, created_at, updated_at) \ + VALUES (?, ?, 'Operator', 'AssertReady', X'0102', 'Pending', 0, 10, 10)", + ) + .bind("local-defer-1") + .bind(business_id) + .execute(s.conn()) + .await + .unwrap(); + + let claimed = s.claim_local_messages(100, 200, 0, 10, 3).await.unwrap(); + assert_eq!(claimed.len(), 1); + assert!( + s.defer_local_message(&claimed[0].message_id, claimed[0].message_version, 150, "boom") + .await + .unwrap() + ); + + let reclaimed = s.claim_local_messages(160, 260, 0, 10, 3).await.unwrap(); + assert_eq!(reclaimed.len(), 1); + assert_eq!(reclaimed[0].attempt_count, 1, "defer records the attempt"); + assert_eq!(reclaimed[0].abandon_count, 0, "defer must not charge the abandon budget"); + + // A deferred message is NOT quarantined however many times it errors: + // the local queue has no error budget, because a surviving row makes the + // producer treat the work as already created. + assert_eq!(s.quarantine_local_messages(300, 3).await.unwrap(), 0); + + // Abandoned claims are what retires it. The quarantine sweep counts the + // final expired Processing lease. + let mut now = 400; + for _ in 0..3 { + s.claim_local_messages(now, now + 10, 0, 10, 3).await.unwrap(); + now += 100; + } + assert_eq!(s.quarantine_local_messages(now, 3).await.unwrap(), 1); + let row = sqlx::query("SELECT state, content FROM message WHERE message_id = ?") + .bind("local-defer-1") + .fetch_one(s.conn()) + .await + .unwrap(); + assert_eq!(row.get::("state"), "Quarantined"); + assert_eq!(row.get::, _>("content"), vec![1, 2]); + } + + /// Rows are claimed one at a time immediately before dispatch, so an abort + /// mid-dispatch charges only the row that was actually running. + #[tokio::test] + async fn local_claims_are_taken_per_message_not_per_batch() { + let db = setup_db().await; + let mut s = db.acquire().await.unwrap(); + let business_id = Uuid::new_v4(); + for (message_id, created_at) in [("first", 10), ("second", 20)] { + sqlx::query( + "INSERT INTO message (message_id, business_id, actor, msg_type, content, state, lock_time_until, created_at, updated_at) \ + VALUES (?, ?, 'Operator', 'AssertReady', X'01', 'Pending', 0, ?, ?)", + ) + .bind(message_id) + .bind(business_id) + .bind(created_at) + .bind(created_at) + .execute(s.conn()) + .await + .unwrap(); + } + + let candidates = s.list_claimable_local_messages(100, 0, 10, 3).await.unwrap(); + assert_eq!( + candidates.iter().map(|message| message.message_id.as_str()).collect::>(), + ["first", "second"] + ); + assert!( + candidates.iter().all(|message| message.state == "Pending"), + "listing must not write" + ); + + let claimed = s + .claim_local_message("first", candidates[0].message_version, 100, 200) + .await + .unwrap() + .expect("first claim"); + assert_eq!(claimed.state, "Processing"); + assert_eq!(claimed.lock_time_until, 200); + assert_eq!(s.find_messages_by_id("second").await.unwrap().unwrap().state, "Pending"); + + // Inside the lease the same row is not claimable again. + assert!( + s.claim_local_message("first", claimed.message_version, 150, 250) + .await + .unwrap() + .is_none() + ); + // A row re-armed under a new version since it was listed is skipped too. + assert!( + s.claim_local_message("second", candidates[1].message_version + 1, 100, 200) + .await + .unwrap() + .is_none() + ); + // Once the lease lapses, the reclaim charges the unfinished attempt. + let reclaimed = s + .claim_local_message("first", claimed.message_version, 300, 400) + .await + .unwrap() + .expect("reclaim"); + assert_eq!(reclaimed.abandon_count, 1); + } + + #[tokio::test] + async fn inbox_claims_are_taken_per_message_not_per_batch() { + let db = setup_db().await; + let mut s = db.acquire().await.unwrap(); + for message_id in ["inbox-first", "inbox-second"] { + let message = P2pInboxMessage { + message_id: message_id.to_owned(), + actor: "Operator".to_owned(), + from_peer: "peer".to_owned(), + msg_type: "CreateGraph".to_owned(), + content: vec![1], + content_size: 1, + ..Default::default() + }; + assert!(s.insert_p2p_inbox_message(&message).await.unwrap()); + } + let candidates = s.list_claimable_p2p_inbox_messages(100, 10, 3, &[]).await.unwrap(); + assert_eq!(candidates.len(), 2); + assert!( + candidates + .iter() + .all(|message| message.state == "Pending" && message.lease_token.is_empty()), + "listing must not write" + ); + + let claimed = + s.claim_p2p_inbox_message("inbox-first", 100, 200).await.unwrap().expect("claim"); + assert_eq!(claimed.state, "Processing"); + assert_eq!(claimed.attempt_count, 1); + assert_eq!(claimed.lease_until, 200); + assert!(!claimed.lease_token.is_empty()); + assert!(s.claim_p2p_inbox_message("inbox-first", 150, 250).await.unwrap().is_none()); + let second = sqlx::query("SELECT state FROM p2p_inbox WHERE message_id = 'inbox-second'") + .fetch_one(s.conn()) + .await + .unwrap(); + assert_eq!(second.get::("state"), "Pending"); + } + + /// An unclean exit leaves claims behind. At startup they are provably + /// abandoned, so they are charged and released immediately with a backoff + /// instead of sitting locked until the lease lapses. + #[tokio::test] + async fn startup_reclaim_charges_abandon_and_applies_backoff() { + let db = setup_db().await; + let mut s = db.acquire().await.unwrap(); + let business_id = Uuid::new_v4(); + sqlx::query( + "INSERT INTO message (message_id, business_id, actor, msg_type, content, state, lock_time_until, created_at, updated_at) \ + VALUES ('startup-local', ?, 'Operator', 'AssertReady', X'01', 'Pending', 0, 10, 10)", + ) + .bind(business_id) + .execute(s.conn()) + .await + .unwrap(); + let inbox = P2pInboxMessage { + message_id: "startup-inbox".to_owned(), + actor: "Operator".to_owned(), + from_peer: "peer".to_owned(), + msg_type: "CreateGraph".to_owned(), + content: vec![1], + content_size: 1, + ..Default::default() + }; + assert!(s.insert_p2p_inbox_message(&inbox).await.unwrap()); + assert_eq!(s.claim_local_messages(100, 700, 0, 10, 3).await.unwrap().len(), 1); + assert_eq!(s.claim_p2p_inbox_messages(100, 400, 10, 3, &[]).await.unwrap().len(), 1); + + assert_eq!(s.reclaim_processing_local_messages(1000, 60).await.unwrap(), 1); + assert_eq!(s.reclaim_processing_p2p_inbox_messages(1000, 60).await.unwrap(), 1); + + let local = s.find_messages_by_id("startup-local").await.unwrap().unwrap(); + assert_eq!(local.state, "Pending"); + assert_eq!(local.abandon_count, 1); + assert_eq!(local.lock_time_until, 1060, "the first abandon backs off by one interval"); + let inbox_row = sqlx::query( + "SELECT state, abandon_count, next_retry_at, lease_token FROM p2p_inbox WHERE message_id = 'startup-inbox'", + ) + .fetch_one(s.conn()) + .await + .unwrap(); + assert_eq!(inbox_row.get::("state"), "Pending"); + assert_eq!(inbox_row.get::("abandon_count"), 1); + assert_eq!(inbox_row.get::("next_retry_at"), 1060); + assert!(inbox_row.get::("lease_token").is_empty()); + + // Nothing is claimable until the backoff has passed. + assert!(s.list_claimable_local_messages(1030, 0, 10, 3).await.unwrap().is_empty()); + assert_eq!(s.list_claimable_local_messages(1060, 0, 10, 3).await.unwrap().len(), 1); + assert!(s.list_claimable_p2p_inbox_messages(1030, 10, 3, &[]).await.unwrap().is_empty()); + assert_eq!(s.list_claimable_p2p_inbox_messages(1060, 10, 3, &[]).await.unwrap().len(), 1); + } + + /// A handler that reschedules its own row and then panics must accumulate + /// abandons across restarts. The self-defer must not reset the counter, + /// because the handler is still running when it happens; only the + /// dispatcher's confirmation after a normal return may reset it. + #[tokio::test] + async fn panic_after_self_defer_accumulates_abandons_until_quarantine() { + let db = setup_db().await; + let mut s = db.acquire().await.unwrap(); + let business_id = Uuid::new_v4(); + sqlx::query( + "INSERT INTO message (message_id, business_id, actor, msg_type, content, state, lock_time_until, created_at, updated_at) \ + VALUES ('panic-local', ?, 'Operator', 'AssertReady', X'01', 'Pending', 0, 10, 10)", + ) + .bind(business_id) + .execute(s.conn()) + .await + .unwrap(); + + let mut now = 100; + for round in 1..=3 { + // The row is Pending, so the restart's reclaim sweep leaves it alone + // and the next tick claims it without a charge. + let candidate = s.find_messages_by_id("panic-local").await.unwrap().unwrap(); + let claimed = s + .claim_local_message("panic-local", candidate.message_version, now, now + 600) + .await + .unwrap() + .expect("claim"); + assert_eq!(claimed.abandon_count, round - 1); + // The handler reschedules itself, then panics. + assert!( + s.self_defer_local_message( + "panic-local", + claimed.message_version, + now + 5, + "not ready" + ) + .await + .unwrap() + ); + assert!( + s.abandon_local_message( + "panic-local", + claimed.message_version, + now, + 60, + "panicked" + ) + .await + .unwrap() + ); + let row = s.find_messages_by_id("panic-local").await.unwrap().unwrap(); + assert_eq!(row.state, "Pending"); + assert_eq!(row.abandon_count, round, "round {round} adds to the preserved count"); + assert_eq!(row.lock_time_until, now + 60 * round, "backoff grows with the count"); + now = row.lock_time_until + 1; + } + + // The sweep on the next tick retires it instead of dispatching again. + assert_eq!(s.quarantine_local_messages(now, 3).await.unwrap(), 1); + assert_eq!( + s.find_messages_by_id("panic-local").await.unwrap().unwrap().state, + "Quarantined" + ); + } + + /// A self-defer is only a reported outcome once the handler has returned, + /// so the counter survives the self-defer and resets on confirmation. + #[tokio::test] + async fn self_defer_keeps_abandons_until_the_dispatcher_confirms_it() { + let db = setup_db().await; + let mut s = db.acquire().await.unwrap(); + let business_id = Uuid::new_v4(); + sqlx::query( + "INSERT INTO message (message_id, business_id, actor, msg_type, content, state, lock_time_until, abandon_count, created_at, updated_at) \ + VALUES ('confirm-local', ?, 'Operator', 'AssertReady', X'01', 'Pending', 0, 2, 10, 10)", + ) + .bind(business_id) + .execute(s.conn()) + .await + .unwrap(); + let candidate = s.find_messages_by_id("confirm-local").await.unwrap().unwrap(); + let claimed = s + .claim_local_message("confirm-local", candidate.message_version, 100, 700) + .await + .unwrap() + .expect("claim"); + assert_eq!(claimed.abandon_count, 2, "a claim from Pending is not charged"); + + assert!( + s.self_defer_local_message("confirm-local", claimed.message_version, 150, "not ready") + .await + .unwrap() + ); + let row = s.find_messages_by_id("confirm-local").await.unwrap().unwrap(); + assert_eq!(row.state, "Pending"); + assert_eq!(row.attempt_count, 1); + assert_eq!(row.abandon_count, 2, "the self-defer must not reset the counter"); + + // The dispatcher confirms once the handler returned normally. + assert!( + s.confirm_local_message_self_defer("confirm-local", claimed.message_version) + .await + .unwrap() + ); + assert_eq!(s.find_messages_by_id("confirm-local").await.unwrap().unwrap().abandon_count, 0); + // A different claim generation, or a row that is not Pending, is not confirmed. + assert!( + !s.confirm_local_message_self_defer("confirm-local", claimed.message_version + 1) + .await + .unwrap() + ); + } + #[tokio::test] async fn test_message_debug_reasons_are_deduplicated() { let db = setup_db().await; diff --git a/crates/store/src/schema.rs b/crates/store/src/schema.rs index 21319df2..de2451e6 100644 --- a/crates/store/src/schema.rs +++ b/crates/store/src/schema.rs @@ -208,15 +208,6 @@ pub enum InstanceBridgeInStatus { UserCanceled, // user broadcast Pegin-cancel tx NoEnoughCommitteesAnswered, // no enough committee responsed & window expired UserDiscarded, // pegin prepare tx input uxto been spent in other tx - - // for front end display - Initiated, // UserInited - Verified, // CommitteesAnswered - Submitted, // UserBroadcastPeginPrepare - Failed, // PresignedFailed, RelayerL2MintedFailed, NoEnoughCommitteesAnswered, UserDiscarded - Processing, // Presigned, RelayerL1Broadcasted - Success, // RelayerL2Minted - Canceled, // UserCanceled } /// Lifecycle of a swap-based bridge-out escrow. @@ -325,14 +316,6 @@ pub enum GraphStatus { Skipped, OperatorTake1, OperatorTake2, - - /// frontend use only - Created, - Presigned, - L2Recorded, - OperatorKickOffing, - Challenging, - Disproving, } /// The evidence that authorizes a graph status transition. @@ -477,8 +460,7 @@ impl GraphStatus { OperatorTake1 => TAKE1, OperatorTake2 | Disprove => TAKE2_OR_DISPROVE, Skipped => SKIPPED, - OperatorPresigned | Created | Presigned | L2Recorded | OperatorKickOffing - | Challenging | Disproving => &[], + OperatorPresigned => &[], }, } } @@ -544,8 +526,15 @@ pub struct GraphBtcTxVoutMonitor { #[derive(Clone, Debug, Display, EnumString)] pub enum MessageState { Pending, + /// Claimed by a worker and currently being dispatched. A row left in this + /// state past its `lock_time_until` means the attempt never finished, which + /// is charged as an abandon rather than a retry. + Processing, Processed, Failed, + /// Repeated claims expired without reporting an outcome. Kept separate + /// from deterministic handler failures so operators can inspect/requeue it. + Quarantined, Expired, Cancelled, } @@ -562,6 +551,14 @@ pub struct Message { pub message_version: i64, pub weight: i64, pub lock_time_until: i64, + /// Dispatch attempts that ended in a handler `Err` and were rescheduled. + /// Observability only; this counter never retires a message. + pub attempt_count: i64, + /// Claims whose previous attempt never reported an outcome, i.e. the worker + /// panicked or the process died mid-dispatch. Incremented when an expired + /// `Processing` lease is reclaimed. + pub abandon_count: i64, + pub last_error: Option, pub created_at: i64, } @@ -569,8 +566,8 @@ pub struct Message { /// /// Unlike `Message`, which is used for locally generated compensation work, /// this row retains the original sender and is consumed before dispatching the -/// external message. Processed content is cleared, while failed content is -/// retained for manual requeue and later TTL cleanup. +/// external message. Processed/failed content is cleared; quarantined content is +/// retained temporarily so an operator can inspect or manually requeue it. #[derive(Clone, FromRow, Debug, Serialize, Deserialize, Default)] pub struct P2pInboxMessage { pub message_id: String, @@ -582,6 +579,8 @@ pub struct P2pInboxMessage { pub content_size: i64, pub state: String, pub attempt_count: i64, + /// Claims whose attempt never reported an outcome. See `Message::abandon_count`. + pub abandon_count: i64, pub next_retry_at: i64, pub lease_until: i64, pub lease_token: String, @@ -685,53 +684,6 @@ pub struct PendingGraphInit { pub created_at: i64, } -#[derive(Debug, Clone, PartialEq, Display, EnumString)] -pub enum MessageType { - None, - PeginRequest, - CreateGraph, - ConfirmInstance, - InitGraph, - GenCircuits, - CutCircuits, - SolderingProof, - VerifierGraphParamsEndorsement, - NonceGeneration, - AggNonceConsensus, - CommitteePresign, - GraphFinalize, - EndorseGraph, - PeginConfirmNonce, - PeginConfirmNonceConsensus, - PeginConfirmPartialSig, - PostReady, - KickoffReady, - KickoffSent, - PreKickoffSent, - ChallengeSent, - WatchtowerChallengeInitSent, - WatchtowerChallengeSent, - WatchtowerChallengeTimeout, - NackReady, - OperatorCommitPubinReady, - OperatorCommitPubinTimeout, - AssertReady, - AssertSent, - ChallengeAssertSent, - WronglyChallengeTimeout, - DisproveSent, - Take1Ready, - Take1Sent, - Take2Ready, - Take2Sent, - RequestNodeInfo, - ResponseNodeInfo, - SyncGraphRequest, - SyncGraph, - InstanceDiscarded, - Tick, -} - #[derive(Clone, Debug, Serialize, Deserialize, Default, Display, EnumString)] pub enum WatchContractStatus { #[default] @@ -975,17 +927,16 @@ mod tests { #[test] fn test_graph_status_from_str() { - assert_eq!(GraphStatus::from_str("Created").unwrap(), GraphStatus::Created); assert_eq!( GraphStatus::from_str("OperatorPresigned").unwrap(), GraphStatus::OperatorPresigned ); + assert!(GraphStatus::from_str("Created").is_err()); assert!(GraphStatus::from_str("Invalid").is_err()); } #[test] fn test_graph_status_display() { - assert_eq!(GraphStatus::Created.to_string(), "Created"); assert_eq!(GraphStatus::OperatorPresigned.to_string(), "OperatorPresigned"); } @@ -998,13 +949,6 @@ mod tests { assert!(InstanceBridgeInStatus::from_str("Invalid").is_err()); } - #[test] - fn test_message_type_from_str() { - assert_eq!(MessageType::from_str("PeginRequest").unwrap(), MessageType::PeginRequest); - assert_eq!(MessageType::from_str("CreateGraph").unwrap(), MessageType::CreateGraph); - assert!(MessageType::from_str("Invalid").is_err()); - } - #[test] fn test_byte_array_macro() { let bytes = ByteArray32([1u8; 32]); diff --git a/deployment/regtest/bitvm-noded/stop_nodes.sh b/deployment/regtest/bitvm-noded/stop_nodes.sh index 726eadb4..59225d6b 100644 --- a/deployment/regtest/bitvm-noded/stop_nodes.sh +++ b/deployment/regtest/bitvm-noded/stop_nodes.sh @@ -1 +1,11 @@ -killall -9 bitvm-noded \ No newline at end of file +#!/bin/sh +# SIGTERM lets the node release its queue claims and finish in-flight writes. +# Wait for the processes to exit before returning, so a start_nodes.sh that +# follows does not race a node that is still shutting down. +killall -TERM bitvm-noded 2>/dev/null +for _ in $(seq 1 60); do + pgrep -x bitvm-noded >/dev/null 2>&1 || exit 0 + sleep 1 +done +echo "bitvm-noded did not exit within 60s; sending SIGKILL" >&2 +killall -KILL bitvm-noded 2>/dev/null diff --git a/deployment/testnet4/bitvm-noded/stop_nodes.sh b/deployment/testnet4/bitvm-noded/stop_nodes.sh index 726eadb4..59225d6b 100644 --- a/deployment/testnet4/bitvm-noded/stop_nodes.sh +++ b/deployment/testnet4/bitvm-noded/stop_nodes.sh @@ -1 +1,11 @@ -killall -9 bitvm-noded \ No newline at end of file +#!/bin/sh +# SIGTERM lets the node release its queue claims and finish in-flight writes. +# Wait for the processes to exit before returning, so a start_nodes.sh that +# follows does not race a node that is still shutting down. +killall -TERM bitvm-noded 2>/dev/null +for _ in $(seq 1 60); do + pgrep -x bitvm-noded >/dev/null 2>&1 || exit 0 + sleep 1 +done +echo "bitvm-noded did not exit within 60s; sending SIGKILL" >&2 +killall -KILL bitvm-noded 2>/dev/null diff --git a/node/Cargo.toml b/node/Cargo.toml index e1359f36..1fd58269 100644 --- a/node/Cargo.toml +++ b/node/Cargo.toml @@ -14,6 +14,7 @@ path = "src/bin/send_pegin_request.rs" [[bin]] name = "challenge" path = "src/bin/send_challenge.rs" +required-features = ["rpc-debug-endpoints"] [[bin]] name = "verifier-challenge" @@ -75,6 +76,7 @@ rand = { workspace = true } base64 = { workspace = true } dotenv = { workspace = true } strum = { workspace = true } +node-macros = { path = "../crates/node-macros" } tendermint = { workspace = true } bincode = { workspace = true } serde = { workspace = true } diff --git a/node/src/action.rs b/node/src/action.rs index 7628f734..290501aa 100644 --- a/node/src/action.rs +++ b/node/src/action.rs @@ -3,12 +3,12 @@ #![allow(clippy::collapsible_else_if)] use crate::env::{ - get_local_node_info, get_p2p_graph_setup_retry_interval_secs, + MESSAGE_EXPIRE_TIME, get_local_node_info, get_p2p_graph_setup_retry_interval_secs, get_p2p_graph_setup_retry_window_secs, get_p2p_inbox_batch_size, get_p2p_outbox_batch_size, }; use crate::handle::{ HandlerContext, HeavyTaskContext, dispatch as handle_dispatch, heavy_task_from_content, - is_heavy_task_message_type, run_heavy_task, + run_heavy_task, }; use crate::metrics_service::MetricsState; use crate::middleware::AllBehaviours; @@ -27,9 +27,11 @@ use client::{ btc_chain::{BTCClient, BtcRpcTimeoutError}, goat_chain::GOATClient, }; +use futures::FutureExt; use libp2p::gossipsub::MessageId; use libp2p::{PeerId, Swarm, gossipsub}; use musig2::{PartialSignature, PubNonce}; +use node_macros::MessageBusinessRef; use secp256k1::{ Keypair, Message as SecpMessage, SECP256K1, schnorr::Signature as SchnorrSignature, }; @@ -41,6 +43,7 @@ use std::sync::{Arc, LazyLock, Mutex}; use std::time::{Duration, Instant}; use store::localdb::LocalDB; use store::{MessageState, P2pInboxMessage}; +use strum::{Display, EnumDiscriminants, EnumIter, EnumString, IntoStaticStr}; use tokio_util::sync::CancellationToken; use uuid::Uuid; @@ -56,6 +59,95 @@ const P2P_INBOX_LEASE_SECS: i64 = 5 * 60; const P2P_INBOX_LEASE_RENEW_INTERVAL_SECS: u64 = 60; const P2P_INBOX_ENQUEUE_ATTEMPTS: usize = 3; +/// Budget for claims that never reported an outcome. Small on purpose: reaching +/// this means the node went down mid-dispatch more than once on the same +/// payload, which is the signature of a message that reproducibly kills it. +const QUEUE_MAX_ABANDONS: i64 = 3; +/// How long a claimed local message stays claimed before another tick may take +/// it over. Heavy work is routed through the durable P2P inbox instead, so local +/// handlers are expected to be short. +const LOCAL_MESSAGE_LEASE_SECS: i64 = 10 * 60; +/// Backoff applied to a local message whose handler returned a non-transient error. +const LOCAL_MESSAGE_RETRY_DELAY_SECS: i64 = 600; +const LOCAL_MESSAGE_BATCH_SIZE: i64 = 50; +/// Delay applied per recorded abandon before a payload may run again, so a +/// supervisor restart after a panic or an unclean exit does not replay it at +/// full speed. +const QUEUE_ABANDON_BACKOFF_SECS: i64 = 60; +/// A dispatch future erased behind a box to keep the enclosing task's state +/// machine reasonably small. +type BoxedDispatch<'a> = std::pin::Pin> + 'a>>; + +enum DispatchExecution { + Completed(T), + Shutdown, + Panicked(String), +} + +struct LocalMessageClaim { + message_id: String, + message_version: i64, +} + +tokio::task_local! { + static ACTIVE_LOCAL_MESSAGE_CLAIM: LocalMessageClaim; +} + +fn panic_payload_message(payload: &(dyn std::any::Any + Send)) -> String { + if let Some(message) = payload.downcast_ref::<&'static str>() { + (*message).to_owned() + } else if let Some(message) = payload.downcast_ref::() { + message.clone() + } else { + "non-string panic payload".to_owned() + } +} + +/// Catch only at the worker-supervisor boundary. A panic is returned separately +/// so the caller can record an abandon and stop the node; it is never converted +/// into an ordinary handler error or followed by more business work. +async fn supervise_dispatch(future: F, shutdown: &CancellationToken) -> DispatchExecution +where + F: std::future::Future, +{ + match std::panic::AssertUnwindSafe(async { + tokio::select! { + biased; + _ = shutdown.cancelled() => None, + result = future => Some(result), + } + }) + .catch_unwind() + .await + { + Ok(Some(result)) => DispatchExecution::Completed(result), + Ok(None) => DispatchExecution::Shutdown, + Err(payload) => DispatchExecution::Panicked(panic_payload_message(payload.as_ref())), + } +} + +/// Log a per-message bookkeeping failure without aborting the rest of the batch. +/// +/// Propagating here used to abandon every message still claimed in the batch. +/// Those rows stay `Processing` until their lease lapses and are then charged an +/// abandon they never earned — so one transient storage blip could push a whole +/// batch of healthy messages toward quarantine. +fn log_queue_bookkeeping_failure( + queue: &'static str, + message_id: &str, + operation: &str, + error: &anyhow::Error, +) { + tracing::error!( + event = queue, + outcome = "bookkeeping_failed", + message_id, + operation, + error = %error, + "failed to persist a message outcome; leaving it claimed for its lease to lapse" + ); +} + /// Delivery semantics for externally received P2P messages. /// /// Protocol-state messages remain durable. Ephemeral messages carry @@ -79,6 +171,17 @@ struct HeavyTaskPermit { lease_token: String, } +/// Ensure a panicking background task cannot leave its detached lease renewer +/// running forever. Once renewal stops, the durable row becomes claimable and +/// the unfinished execution is counted as an abandon. +struct LeaseRenewalGuard(CancellationToken); + +impl Drop for LeaseRenewalGuard { + fn drop(&mut self) { + self.0.cancel(); + } +} + impl Drop for HeavyTaskPermit { fn drop(&mut self) { if let Ok(mut active) = ACTIVE_HEAVY_TASK.lock() @@ -266,54 +369,212 @@ impl MessageDeferReason { } } -#[derive(Serialize, Deserialize, Clone)] +#[derive(Clone, Copy, Debug, Eq, PartialEq)] +pub enum BusinessRef { + Instance { instance_id: Uuid }, + Graph { instance_id: Uuid, graph_id: Uuid }, + Unscoped, +} + +impl BusinessRef { + pub const fn primary_id(self) -> Option { + match self { + Self::Instance { instance_id } => Some(instance_id), + Self::Graph { graph_id, .. } => Some(graph_id), + Self::Unscoped => None, + } + } + + fn key_part(self) -> String { + match self { + Self::Instance { instance_id } => format!("instance:{instance_id}"), + Self::Graph { graph_id, .. } => format!("graph:{graph_id}"), + Self::Unscoped => "unscoped".to_owned(), + } + } +} + +pub trait HasBusinessRef { + fn business_ref(&self) -> BusinessRef; +} + +#[derive(Clone, Debug, Eq, PartialEq)] +pub enum MessageQualifier { + Singleton, + Watchtower(usize), + Verifier(usize), + Disprove { kind: DisproveTxType, index: usize }, +} + +impl MessageQualifier { + fn key_part(&self) -> String { + match self { + Self::Singleton => "singleton".to_owned(), + Self::Watchtower(index) => format!("watchtower:{index}"), + Self::Verifier(index) => format!("verifier:{index}"), + Self::Disprove { kind, index } => format!("disprove:{kind}:{index}"), + } + } +} + +#[derive(Clone, Debug, Eq, PartialEq)] +pub struct LocalMessageKey { + actor: Actor, + kind: MessageKind, + business_ref: BusinessRef, + qualifier: MessageQualifier, +} + +impl LocalMessageKey { + pub fn from_content(actor: Actor, content: &GOATMessageContent) -> Result { + let business_ref = content.business_ref(); + if business_ref.primary_id().is_none() { + bail!("cannot persist unscoped {} as a local message", content.event_type()); + } + Ok(Self { actor, kind: content.kind(), business_ref, qualifier: content.qualifier() }) + } + + pub fn business_id(&self) -> Uuid { + match self.business_ref { + BusinessRef::Instance { instance_id } => instance_id, + BusinessRef::Graph { graph_id, .. } => graph_id, + BusinessRef::Unscoped => unreachable!("unscoped messages cannot have a local key"), + } + } + + pub fn message_id(&self) -> String { + format!( + "local:v1:{}:{}:{}:{}", + self.actor, + self.business_ref.key_part(), + self.kind, + self.qualifier.key_part(), + ) + } +} + +#[derive(Serialize, Deserialize, Clone, EnumDiscriminants, MessageBusinessRef)] +#[strum_discriminants(name(MessageKind))] +#[strum_discriminants(derive(Hash, Display, EnumString, EnumIter, IntoStaticStr))] pub enum GOATMessageContent { + #[business_ref(instance)] PeginRequest(PeginRequest), + #[business_ref(graph)] CreateGraph(CreateGraph), + #[business_ref(instance)] ConfirmInstance(ConfirmInstance), + #[business_ref(graph)] InitGraph(InitGraph), + #[business_ref(graph)] GenCircuits(GenCircuits), + #[business_ref(graph)] CutCircuits(CutCircuits), + #[business_ref(graph)] SolderingProofReady(SolderingProofReady), + #[business_ref(graph)] GraphSetupAck(GraphSetupAck), + #[business_ref(graph)] VerifierGraphParamsEndorsement(VerifierGraphParamsEndorsement), + #[business_ref(graph)] NonceGeneration(NonceGeneration), + #[business_ref(graph)] AggNonceConsensus(AggNonceConsensus), + #[business_ref(graph)] CommitteePresign(CommitteePresign), + #[business_ref(graph)] EndorseGraph(EndorseGraph), + #[business_ref(graph)] GraphFinalize(GraphFinalize), + #[business_ref(instance)] PeginConfirmNonce(PeginConfirmNonce), + #[business_ref(instance)] PeginConfirmNonceConsensus(PeginConfirmNonceConsensus), + #[business_ref(instance)] PeginConfirmPartialSig(PeginConfirmPartialSig), + #[business_ref(instance)] PostReady(PostReady), + #[business_ref(graph)] KickoffReady(KickoffReady), + #[business_ref(graph)] KickoffSent(KickoffSent), + #[business_ref(graph)] PreKickoffSent(PreKickoffSent), + #[business_ref(graph)] ChallengeSent(ChallengeSent), + #[business_ref(graph)] WatchtowerChallengeInitSent(WatchtowerChallengeInitSent), + #[business_ref(graph)] WatchtowerChallengeSent(WatchtowerChallengeSent), + #[business_ref(graph)] WatchtowerChallengeTimeout(WatchtowerChallengeTimeout), + #[business_ref(graph)] NackReady(NackReady), + #[business_ref(graph)] OperatorCommitPubinReady(OperatorCommitPubinReady), + #[business_ref(graph)] OperatorCommitPubinTimeout(OperatorCommitPubinTimeout), + #[business_ref(graph)] AssertReady(AssertReady), + #[business_ref(graph)] AssertSent(AssertSent), + #[business_ref(graph)] ChallengeAssertSent(ChallengeAssertSent), + #[business_ref(graph)] WronglyChallengeTimeout(WronglyChallengeTimeout), + #[business_ref(graph)] DisproveSent(DisproveSent), + #[business_ref(graph)] Take1Ready(Take1Ready), + #[business_ref(graph)] Take1Sent(Take1Sent), + #[business_ref(graph)] Take2Ready(Take2Ready), + #[business_ref(graph)] Take2Sent(Take2Sent), + #[business_ref(unscoped)] RequestNodeInfo(NodeInfo), + #[business_ref(unscoped)] ResponseNodeInfo(NodeInfo), + #[business_ref(graph)] SyncGraphRequest(SyncGraphRequest), + #[business_ref(graph)] SyncGraph(SyncGraph), + #[business_ref(unscoped)] InstanceDiscarded(InstanceDiscarded), + #[business_ref(unscoped)] Tick, } +impl MessageKind { + const fn is_pegin(self) -> bool { + matches!( + self, + Self::PeginRequest + | Self::ConfirmInstance + | Self::CreateGraph + | Self::InitGraph + | Self::GenCircuits + | Self::CutCircuits + | Self::SolderingProofReady + | Self::VerifierGraphParamsEndorsement + | Self::NonceGeneration + | Self::AggNonceConsensus + | Self::CommitteePresign + | Self::EndorseGraph + | Self::GraphFinalize + | Self::PeginConfirmNonce + | Self::PeginConfirmNonceConsensus + | Self::PeginConfirmPartialSig + | Self::PostReady + ) + } +} + impl GOATMessageContent { + pub fn kind(&self) -> MessageKind { + self.into() + } + /// New messages default to the durable inbox and must explicitly opt into /// immediate processing when they are safe to drop. pub const fn p2p_delivery(&self) -> P2PMessageDelivery { @@ -327,76 +588,27 @@ impl GOATMessageContent { } } - /// Stable message name for logs/metrics. Keep this independent of `Debug`, whose + /// Stable message name for logs/metrics. Keep this independent of `Debug`, whose /// output can include protocol payloads (and, for proofs, be very large). pub fn event_type(&self) -> &'static str { - match self { - Self::PeginRequest(_) => "PeginRequest", - Self::CreateGraph(_) => "CreateGraph", - Self::ConfirmInstance(_) => "ConfirmInstance", - Self::InitGraph(_) => "InitGraph", - Self::GenCircuits(_) => "GenCircuits", - Self::CutCircuits(_) => "CutCircuits", - Self::SolderingProofReady(_) => "SolderingProofReady", - Self::GraphSetupAck(_) => "GraphSetupAck", - Self::VerifierGraphParamsEndorsement(_) => "VerifierGraphParamsEndorsement", - Self::NonceGeneration(_) => "NonceGeneration", - Self::AggNonceConsensus(_) => "AggNonceConsensus", - Self::CommitteePresign(_) => "CommitteePresign", - Self::EndorseGraph(_) => "EndorseGraph", - Self::GraphFinalize(_) => "GraphFinalize", - Self::PeginConfirmNonce(_) => "PeginConfirmNonce", - Self::PeginConfirmNonceConsensus(_) => "PeginConfirmNonceConsensus", - Self::PeginConfirmPartialSig(_) => "PeginConfirmPartialSig", - Self::PostReady(_) => "PostReady", - Self::KickoffReady(_) => "KickoffReady", - Self::KickoffSent(_) => "KickoffSent", - Self::PreKickoffSent(_) => "PreKickoffSent", - Self::ChallengeSent(_) => "ChallengeSent", - Self::WatchtowerChallengeInitSent(_) => "WatchtowerChallengeInitSent", - Self::WatchtowerChallengeSent(_) => "WatchtowerChallengeSent", - Self::WatchtowerChallengeTimeout(_) => "WatchtowerChallengeTimeout", - Self::NackReady(_) => "NackReady", - Self::OperatorCommitPubinReady(_) => "OperatorCommitPubinReady", - Self::OperatorCommitPubinTimeout(_) => "OperatorCommitPubinTimeout", - Self::AssertReady(_) => "AssertReady", - Self::AssertSent(_) => "AssertSent", - Self::ChallengeAssertSent(_) => "ChallengeAssertSent", - Self::WronglyChallengeTimeout(_) => "WronglyChallengeTimeout", - Self::DisproveSent(_) => "DisproveSent", - Self::Take1Ready(_) => "Take1Ready", - Self::Take1Sent(_) => "Take1Sent", - Self::Take2Ready(_) => "Take2Ready", - Self::Take2Sent(_) => "Take2Sent", - Self::RequestNodeInfo(_) => "RequestNodeInfo", - Self::ResponseNodeInfo(_) => "ResponseNodeInfo", - Self::SyncGraphRequest(_) => "SyncGraphRequest", - Self::SyncGraph(_) => "SyncGraph", - Self::InstanceDiscarded(_) => "InstanceDiscarded", - Self::Tick => "Tick", - } + self.kind().into() } - fn pegin_retry_business_id(&self) -> Option { + pub fn qualifier(&self) -> MessageQualifier { match self { - Self::PeginRequest(message) => Some(message.instance_id), - Self::ConfirmInstance(message) => Some(message.instance_id), - Self::CreateGraph(message) => Some(message.graph_id), - Self::InitGraph(message) => Some(message.graph_id), - Self::GenCircuits(message) => Some(message.graph_id), - Self::CutCircuits(message) => Some(message.graph_id), - Self::SolderingProofReady(message) => Some(message.graph_id), - Self::VerifierGraphParamsEndorsement(message) => Some(message.graph_id), - Self::NonceGeneration(message) => Some(message.graph_id), - Self::AggNonceConsensus(message) => Some(message.graph_id), - Self::CommitteePresign(message) => Some(message.graph_id), - Self::EndorseGraph(message) => Some(message.graph_id), - Self::GraphFinalize(message) => Some(message.graph_id), - Self::PeginConfirmNonce(message) => Some(message.instance_id), - Self::PeginConfirmNonceConsensus(message) => Some(message.instance_id), - Self::PeginConfirmPartialSig(message) => Some(message.instance_id), - Self::PostReady(message) => Some(message.instance_id), - _ => None, + Self::WatchtowerChallengeSent(message) => { + MessageQualifier::Watchtower(message.watchtower_index) + } + Self::ChallengeAssertSent(message) => { + MessageQualifier::Verifier(message.verifier_index) + } + Self::WronglyChallengeTimeout(message) => { + MessageQualifier::Verifier(message.verifier_index) + } + Self::DisproveSent(message) => { + MessageQualifier::Disprove { kind: message.disprove_type, index: message.index } + } + _ => MessageQualifier::Singleton, } } } @@ -410,30 +622,6 @@ fn is_retryable_sqlite_error(error: &anyhow::Error) -> bool { }) } -fn is_pegin_message_type(message_type: &str) -> bool { - matches!( - message_type, - "PeginRequest" - | "ConfirmInstance" - | "CreateGraph" - | "InitGraph" - | "GenCircuits" - | "CutCircuits" - | "SolderingProof" - | "SolderingProofReady" - | "VerifierGraphParamsEndorsement" - | "NonceGeneration" - | "AggNonceConsensus" - | "CommitteePresign" - | "EndorseGraph" - | "GraphFinalize" - | "PeginConfirmNonce" - | "PeginConfirmNonceConsensus" - | "PeginConfirmPartialSig" - | "PostReady" - ) -} - /// Pegin #[derive(Serialize, Deserialize, Clone)] @@ -979,7 +1167,7 @@ async fn enqueue_p2p_message( let message_id = hex::encode(&id.0); let inbox_message = P2pInboxMessage { message_id: message_id.clone(), - business_id: decoded.content.pegin_retry_business_id(), + business_id: decoded.content.business_ref().primary_id(), actor: actor.to_string(), from_peer: from_peer_id.to_string(), msg_type: decoded.content.event_type().to_owned(), @@ -1063,6 +1251,205 @@ fn log_stale_p2p_inbox_lease(message_id: &str, lease_token: &str, operation: &st ); } +async fn fail_p2p_inbox_without_aborting_batch( + local_db: &LocalDB, + message_id: &str, + lease_token: &str, + error: &str, +) { + let result = async { + let mut storage = local_db.acquire().await?; + storage.fail_p2p_inbox_message(message_id, lease_token, error).await + } + .await; + match result { + Ok(true) => {} + Ok(false) => log_stale_p2p_inbox_lease(message_id, lease_token, "fail"), + Err(error) => log_queue_bookkeeping_failure("p2p_inbox", message_id, "fail", &error), + } +} + +async fn defer_p2p_inbox_without_aborting_batch( + local_db: &LocalDB, + message_id: &str, + lease_token: &str, + next_retry_at: i64, + reason: &str, +) { + let result = async { + let mut storage = local_db.acquire().await?; + storage.defer_p2p_inbox_message(message_id, lease_token, next_retry_at, reason).await + } + .await; + match result { + Ok(true) => {} + Ok(false) => log_stale_p2p_inbox_lease(message_id, lease_token, "defer"), + Err(error) => log_queue_bookkeeping_failure("p2p_inbox", message_id, "defer", &error), + } +} + +async fn abandon_p2p_inbox_after_panic( + local_db: &LocalDB, + message_id: &str, + lease_token: &str, + detail: &str, +) { + let error = format!("handler panicked: {detail}"); + let result = async { + let mut storage = local_db.acquire().await?; + storage + .abandon_p2p_inbox_message( + message_id, + lease_token, + current_time_secs(), + QUEUE_ABANDON_BACKOFF_SECS, + &error, + ) + .await + } + .await; + match result { + Ok(true) => {} + Ok(false) => log_stale_p2p_inbox_lease(message_id, lease_token, "abandon"), + Err(error) => log_queue_bookkeeping_failure("p2p_inbox", message_id, "abandon", &error), + } +} + +async fn abandon_local_message_after_panic( + local_db: &LocalDB, + message_id: &str, + message_version: i64, + detail: &str, +) { + let error = format!("handler panicked: {detail}"); + let result = async { + let mut storage = local_db.acquire().await?; + storage + .abandon_local_message( + message_id, + message_version, + current_time_secs(), + QUEUE_ABANDON_BACKOFF_SECS, + &error, + ) + .await + } + .await; + match result { + Ok(true) => {} + Ok(false) => tracing::warn!( + event = "local_message_queue", + outcome = "stale_claim", + message_id, + message_version, + operation = "abandon", + "ignored local message update from a stale claim" + ), + Err(error) => { + log_queue_bookkeeping_failure("local_message_queue", message_id, "abandon", &error) + } + } +} + +/// Claim one listed inbox row immediately before dispatching it. +/// +/// `None` means the row is no longer claimable or the claim could not be +/// persisted; either way it is skipped this tick and listed again on the next. +async fn claim_p2p_inbox_candidate( + local_db: &LocalDB, + message_id: &str, +) -> Option { + let now = current_time_secs(); + let result = async { + let mut storage = local_db.acquire().await?; + storage.claim_p2p_inbox_message(message_id, now, now + P2P_INBOX_LEASE_SECS).await + } + .await; + match result { + Ok(Some(message)) => Some(message), + Ok(None) => { + tracing::debug!( + event = "p2p_inbox", + outcome = "claim_skipped", + message_id, + "listed inbox message is no longer claimable" + ); + None + } + Err(error) => { + tracing::error!( + event = "p2p_inbox", + outcome = "claim_failed", + message_id, + error = %error, + "failed to claim a listed inbox message; it stays queued for the next tick" + ); + None + } + } +} + +/// Claim one listed local message immediately before dispatching it. See +/// [`claim_p2p_inbox_candidate`]. +async fn claim_local_candidate( + local_db: &LocalDB, + candidate: &store::Message, +) -> Option { + let now = current_time_secs(); + let result = async { + let mut storage = local_db.acquire().await?; + storage + .claim_local_message( + &candidate.message_id, + candidate.message_version, + now, + now + LOCAL_MESSAGE_LEASE_SECS, + ) + .await + } + .await; + match result { + Ok(Some(message)) => Some(message), + Ok(None) => { + tracing::debug!( + event = "local_message_queue", + outcome = "claim_skipped", + queued_message_id = %candidate.message_id, + message_version = candidate.message_version, + "listed local message is no longer claimable" + ); + None + } + Err(error) => { + tracing::error!( + event = "local_message_queue", + outcome = "claim_failed", + queued_message_id = %candidate.message_id, + error = %error, + "failed to claim a listed local message; it stays queued for the next tick" + ); + None + } + } +} + +/// Charge and release every queue claim left behind by a previous process. +/// +/// Run once at startup, before any dispatcher starts. The database is +/// process-local, so a `Processing` row at this point is an attempt that never +/// reported an outcome. Waiting for its lease to lapse instead kept the row +/// locked for minutes while every producer touching it backed off with +/// ResourceLocked; a graceful shutdown never leaves such rows behind. +pub async fn reclaim_stale_queue_claims(local_db: &LocalDB) -> Result<(u64, u64)> { + let now = current_time_secs(); + let mut storage = local_db.start_immediate_transaction().await?; + let local = storage.reclaim_processing_local_messages(now, QUEUE_ABANDON_BACKOFF_SECS).await?; + let inbox = + storage.reclaim_processing_p2p_inbox_messages(now, QUEUE_ABANDON_BACKOFF_SECS).await?; + storage.commit().await?; + Ok((local, inbox)) +} + async fn renew_p2p_inbox_lease_until_cancelled( local_db: LocalDB, message_id: String, @@ -1117,82 +1504,78 @@ async fn handle_p2p_inbox_messages( soldering_builder: &Option>, actor: Actor, metrics_state: &MetricsState, + shutdown: &CancellationToken, ) -> Result<()> { let now = current_time_secs(); let active_heavy_task_ids = active_heavy_task_message_ids(); let mut storage = local_db.start_immediate_transaction().await?; - let messages = storage - .claim_p2p_inbox_messages( + // Quarantine rows whose dispatch repeatedly failed to report any outcome. + // Returned retryable errors do not consume this budget. + let quarantined = storage.quarantine_p2p_inbox_messages(now, QUEUE_MAX_ABANDONS).await?; + // Bound terminal metadata and the temporary payload retained for manual + // inspection of quarantined rows. + let purged = storage.purge_terminal_p2p_inbox_messages(now - MESSAGE_EXPIRE_TIME).await?; + // Only list here. Each row is claimed right before its own dispatch so a + // crash mid-dispatch is charged to that row alone. + let candidates = storage + .list_claimable_p2p_inbox_messages( now, - now + P2P_INBOX_LEASE_SECS, get_p2p_inbox_batch_size(), + QUEUE_MAX_ABANDONS, &active_heavy_task_ids, ) .await?; storage.commit().await?; - for message in messages { + if quarantined > 0 { + tracing::warn!( + event = "p2p_inbox", + outcome = "quarantined", + quarantined, + max_abandons = QUEUE_MAX_ABANDONS, + "quarantined inbox messages that repeatedly abandoned their lease" + ); + } + if purged > 0 { + tracing::info!( + event = "p2p_inbox", + outcome = "purged", + purged, + "removed terminal inbox rows past their retention window" + ); + } + + for candidate in candidates { + let Some(message) = claim_p2p_inbox_candidate(local_db, &candidate.message_id).await else { + continue; + }; let from_peer_id = match PeerId::from_str(&message.from_peer) { Ok(peer_id) => peer_id, Err(error) => { - let updated = local_db - .acquire() - .await? - .fail_p2p_inbox_message( - &message.message_id, - &message.lease_token, - &format!("invalid stored source peer: {error}"), - ) - .await?; - if !updated { - log_stale_p2p_inbox_lease(&message.message_id, &message.lease_token, "fail"); - } + fail_p2p_inbox_without_aborting_batch( + local_db, + &message.message_id, + &message.lease_token, + &format!("invalid stored source peer: {error}"), + ) + .await; continue; } }; - let is_heavy_task_message = is_heavy_task_message_type(&message.msg_type, &actor); - let heavy_task = if is_heavy_task_message { - let decoded = match GOATMessage::deserialize_message(&message.content).await { - Ok(message) => message, - Err(error) => { - let updated = local_db - .acquire() - .await? - .fail_p2p_inbox_message( - &message.message_id, - &message.lease_token, - &error.to_string(), - ) - .await?; - if !updated { - log_stale_p2p_inbox_lease( - &message.message_id, - &message.lease_token, - "fail", - ); - } - continue; - } - }; - let Some(task) = heavy_task_from_content(decoded.content(), &actor) else { - let updated = local_db - .acquire() - .await? - .fail_p2p_inbox_message( - &message.message_id, - &message.lease_token, - &format!("inbox message type does not match {} content", message.msg_type), - ) - .await?; - if !updated { - log_stale_p2p_inbox_lease(&message.message_id, &message.lease_token, "fail"); - } + let decoded = match GOATMessage::deserialize_message(&message.content).await { + Ok(message) => message, + Err(error) => { + fail_p2p_inbox_without_aborting_batch( + local_db, + &message.message_id, + &message.lease_token, + &error.to_string(), + ) + .await; continue; - }; - Some(task) - } else { - None + } }; + let heavy_task = heavy_task_from_content(decoded.content(), &actor); if let Some(heavy_task) = heavy_task { let local_db = local_db.clone(); @@ -1203,24 +1586,20 @@ async fn handle_p2p_inbox_messages( let message_id = message.message_id.clone(); let lease_token = message.lease_token.clone(); let attempt_count = message.attempt_count; - let task_type = heavy_task.message_type(); + let task_type = message.msg_type.clone(); + let task_type_for_task = task_type.clone(); let task_kind = heavy_task.kind(); let graph_id = heavy_task.graph_id(); let Some(permit) = try_acquire_heavy_task_permit(&message_id, &lease_token) else { let retry_after_secs = 5; - let updated = local_db - .acquire() - .await? - .defer_p2p_inbox_message( - &message_id, - &lease_token, - current_time_secs() + retry_after_secs, - RetryableDispatchReason::ResourceLocked.code(), - ) - .await?; - if !updated { - log_stale_p2p_inbox_lease(&message.message_id, &message.lease_token, "defer"); - } + defer_p2p_inbox_without_aborting_batch( + &local_db, + &message_id, + &lease_token, + current_time_secs() + retry_after_secs, + RetryableDispatchReason::ResourceLocked.code(), + ) + .await; tracing::debug!( event = "p2p_inbox", outcome = "deferred", @@ -1232,9 +1611,11 @@ async fn handle_p2p_inbox_messages( ); continue; }; + let shutdown = shutdown.clone(); tokio::spawn(async move { let _permit = permit; let lease_cancellation = CancellationToken::new(); + let _lease_guard = LeaseRenewalGuard(lease_cancellation.clone()); let lease_renewal = tokio::spawn(renew_p2p_inbox_lease_until_cancelled( local_db.clone(), message_id.clone(), @@ -1249,7 +1630,8 @@ async fn handle_p2p_inbox_messages( metrics_state: metrics_state.clone(), from_peer_id, }; - let result = run_heavy_task(&context, heavy_task).await; + let execution = + supervise_dispatch(run_heavy_task(&context, heavy_task), &shutdown).await; lease_cancellation.cancel(); let lease_is_current = match lease_renewal.await { Ok(lease_is_current) => lease_is_current, @@ -1258,25 +1640,62 @@ async fn handle_p2p_inbox_messages( false } }; - if !lease_is_current { - return; - } - metrics_state.record_message_dispatch( - task_type, - if result.is_ok() { "success" } else { "failed" }, - ); - if let Err(error) = finish_p2p_inbox_attempt( - &local_db, - &metrics_state, - &message_id, - &lease_token, - task_type, - attempt_count, - result, - ) - .await - { - tracing::error!(error = %error, message_id, "failed to persist heavy task result"); + match execution { + DispatchExecution::Completed(result) => { + if !lease_is_current { + return; + } + metrics_state.record_message_dispatch( + &task_type_for_task, + if result.is_ok() { "success" } else { "failed" }, + ); + if let Err(error) = finish_p2p_inbox_attempt( + &local_db, + &metrics_state, + &message_id, + &lease_token, + &task_type_for_task, + attempt_count, + result, + ) + .await + { + tracing::error!(error = %error, message_id, "failed to persist heavy task result"); + } + } + DispatchExecution::Shutdown => { + if lease_is_current { + defer_p2p_inbox_without_aborting_batch( + &local_db, + &message_id, + &lease_token, + current_time_secs(), + "graceful_shutdown", + ) + .await; + } + } + DispatchExecution::Panicked(detail) => { + metrics_state.record_message_dispatch(&task_type_for_task, "failed"); + tracing::error!( + event = "heavy_task_panic", + outcome = "node_shutdown", + message_id, + graph_id = %graph_id, + message_type = %task_type_for_task, + task_kind, + detail, + "heavy task panicked; recorded an abandon and stopping the node" + ); + abandon_p2p_inbox_after_panic( + &local_db, + &message_id, + &lease_token, + &detail, + ) + .await; + shutdown.cancel(); + } } }); tracing::info!( @@ -1284,7 +1703,7 @@ async fn handle_p2p_inbox_messages( outcome = "heavy_task_started", message_id = %message.message_id, graph_id = %graph_id, - message_type = task_type, + message_type = %task_type, task_kind, "started background heavy task" ); @@ -1293,23 +1712,20 @@ async fn handle_p2p_inbox_messages( let raw_message_id = match hex::decode(&message.message_id) { Ok(message_id) => MessageId(message_id), Err(error) => { - let updated = local_db - .acquire() - .await? - .fail_p2p_inbox_message( - &message.message_id, - &message.lease_token, - &format!("invalid stored message id: {error}"), - ) - .await?; - if !updated { - log_stale_p2p_inbox_lease(&message.message_id, &message.lease_token, "fail"); - } + fail_p2p_inbox_without_aborting_batch( + local_db, + &message.message_id, + &message.lease_token, + &format!("invalid stored message id: {error}"), + ) + .await; continue; } }; - let result = recv_and_dispatch( + // Keep the deeply nested dispatch future out of the enclosing task's + // inline state machine. + let dispatch: BoxedDispatch<'_> = Box::pin(dispatch_decoded_p2p_message( swarm, local_db, btc_client, @@ -1319,80 +1735,58 @@ async fn handle_p2p_inbox_messages( actor.clone(), from_peer_id, raw_message_id, - &message.content, + decoded, metrics_state, - ) - .await; - - let mut storage = local_db.acquire().await?; - match result { - Ok(()) => { - if !storage - .complete_p2p_inbox_message(&message.message_id, &message.lease_token) - .await? - { - log_stale_p2p_inbox_lease( - &message.message_id, - &message.lease_token, - "complete", - ); - } + )); + let result = match supervise_dispatch(dispatch, shutdown).await { + DispatchExecution::Completed(result) => result, + DispatchExecution::Shutdown => { + defer_p2p_inbox_without_aborting_batch( + local_db, + &message.message_id, + &message.lease_token, + current_time_secs(), + "graceful_shutdown", + ) + .await; + return Ok(()); } - Err(error) => { - let Some((reason, requested_retry_after_secs)) = - p2p_retryable_dispatch_error(&error) - else { - if !storage - .fail_p2p_inbox_message( - &message.message_id, - &message.lease_token, - &error.to_string(), - ) - .await? - { - log_stale_p2p_inbox_lease( - &message.message_id, - &message.lease_token, - "fail", - ); - } - tracing::warn!( - event = "p2p_inbox", - outcome = "failed", - message_id = %message.message_id, - message_type = %message.msg_type, - attempt_count = message.attempt_count, - error = %error, - "cached P2P message failed permanently" - ); - continue; - }; - let retry_after_secs = requested_retry_after_secs - .unwrap_or_else(|| p2p_retry_delay_secs(message.attempt_count)); - if !storage - .retry_p2p_inbox_message( - &message.message_id, - &message.lease_token, - current_time_secs() + retry_after_secs, - &error.to_string(), - ) - .await? - { - log_stale_p2p_inbox_lease(&message.message_id, &message.lease_token, "retry"); - } - metrics_state.record_message_retry(); - tracing::warn!( - event = "p2p_inbox", - outcome = "deferred", - reason = reason.code(), + DispatchExecution::Panicked(detail) => { + tracing::error!( + event = "p2p_dispatch_panic", + outcome = "node_shutdown", message_id = %message.message_id, message_type = %message.msg_type, - attempt_count = message.attempt_count, - retry_after_secs, - error = %error, - "deferred cached P2P message for retry" + detail, + "P2P message handler panicked; recorded an abandon and stopping the node" ); + abandon_p2p_inbox_after_panic( + local_db, + &message.message_id, + &message.lease_token, + &detail, + ) + .await; + shutdown.cancel(); + bail!("P2P message handler panicked: {detail}"); } + }; + metrics_state.record_message_dispatch( + &message.msg_type, + if result.is_ok() { "success" } else { "failed" }, + ); + if let Err(error) = finish_p2p_inbox_attempt( + local_db, + metrics_state, + &message.message_id, + &message.lease_token, + &message.msg_type, + message.attempt_count, + result, + ) + .await + { + log_queue_bookkeeping_failure("p2p_inbox", &message.message_id, "finish", &error); } } Ok(()) @@ -1423,6 +1817,15 @@ async fn finish_p2p_inbox_attempt( { log_stale_p2p_inbox_lease(message_id, lease_token, "fail"); } + tracing::warn!( + event = "p2p_inbox", + outcome = "failed", + message_id, + message_type, + attempt_count, + error = %error, + "cached P2P message failed permanently" + ); return Ok(()); }; let retry_after_secs = @@ -1554,6 +1957,7 @@ pub async fn handle_self_p2p_msg( id: MessageId, message: &[u8], metrics_state: &MetricsState, + shutdown: &CancellationToken, ) -> Result<()> { if id != GOATMessage::default_message_id() { tracing::warn!( @@ -1575,42 +1979,106 @@ pub async fn handle_self_p2p_msg( "received local queue trigger" ); - let messages = - pop_batch_local_unhandle_msg(local_db, actor.clone(), current_time_secs(), 0, 50).await?; + let (candidates, quarantined) = + list_batch_local_msg(local_db, QUEUE_MAX_ABANDONS, LOCAL_MESSAGE_BATCH_SIZE).await?; + if quarantined > 0 { + tracing::warn!( + event = "local_message_queue", + outcome = "quarantined", + quarantined, + max_abandons = QUEUE_MAX_ABANDONS, + "retired local messages that kept failing to report an outcome" + ); + } tracing::info!( event = "local_message_queue", - outcome = "batch_loaded", + outcome = "batch_listed", role = %actor, - batch_size = messages.len(), - "loaded pending local messages" + batch_size = candidates.len(), + "listed claimable local messages" ); - for message in messages { + for candidate in candidates { + // Claim right before dispatch so a crash mid-dispatch is charged to + // this row alone, and so a producer that re-armed the row since it was + // listed wins: the stale version is skipped until the next tick. + let Some(message) = claim_local_candidate(local_db, &candidate).await else { + continue; + }; let queue_wait_secs = current_time_secs().saturating_sub(message.created_at); let started_at = Instant::now(); - match recv_and_dispatch( - swarm, - local_db, - btc_client, - goat_client, - http_client, - soldering_builder, - actor.clone(), - from_peer_id, - id.clone(), - &message.content, - metrics_state, - ) - .await - { + let claim = LocalMessageClaim { + message_id: message.message_id.clone(), + message_version: message.message_version, + }; + let dispatch: BoxedDispatch<'_> = Box::pin(ACTIVE_LOCAL_MESSAGE_CLAIM.scope( + claim, + recv_and_dispatch( + swarm, + local_db, + btc_client, + goat_client, + http_client, + soldering_builder, + actor.clone(), + from_peer_id, + id.clone(), + &message.content, + metrics_state, + ), + )); + let result = match supervise_dispatch(dispatch, shutdown).await { + DispatchExecution::Completed(result) => result, + DispatchExecution::Shutdown => return Ok(()), + DispatchExecution::Panicked(detail) => { + tracing::error!( + event = "local_message_dispatch_panic", + outcome = "node_shutdown", + queued_message_id = %message.message_id, + business_id = %message.business_id, + message_type = %message.msg_type, + detail, + "local message handler panicked; recorded an abandon and stopping the node" + ); + abandon_local_message_after_panic( + local_db, + &message.message_id, + message.message_version, + &detail, + ) + .await; + shutdown.cancel(); + bail!("local message handler panicked: {detail}"); + } + }; + match result { Ok(_) => { - let mut storage_processor = local_db.acquire().await?; - let state_updated = storage_processor - .update_messages_state( - &message.message_id, - message.message_version, - MessageState::Processed.to_string(), - ) - .await?; + let mut storage_processor = match local_db.acquire().await { + Ok(storage_processor) => storage_processor, + Err(error) => { + log_queue_bookkeeping_failure( + "local_message_queue", + &message.message_id, + "acquire", + &error, + ); + continue; + } + }; + let state_updated = match storage_processor + .complete_local_message(&message.message_id, message.message_version) + .await + { + Ok(state_updated) => state_updated, + Err(error) => { + log_queue_bookkeeping_failure( + "local_message_queue", + &message.message_id, + "complete", + &error, + ); + continue; + } + }; if state_updated { tracing::info!( event = "local_message_queue", @@ -1624,42 +2092,84 @@ pub async fn handle_self_p2p_msg( "processed local message" ); } else { - tracing::warn!( - event = "local_message_queue", - outcome = "state_update_conflict", - role = %actor, - business_id = %message.business_id, - queued_message_id = %message.message_id, - message_type = %message.msg_type, - queue_wait_secs, - elapsed_ms = started_at.elapsed().as_millis() as u64, - "local message handler completed but its processed state was not persisted" - ); + // A row that is Pending under our claim version was + // rescheduled by the handler itself. Only now, after the + // handler returned, is that a reported outcome, so only now + // does its consecutive-abandon counter reset. + match storage_processor + .confirm_local_message_self_defer( + &message.message_id, + message.message_version, + ) + .await + { + Ok(true) => { + tracing::debug!( + event = "local_message_queue", + outcome = "self_deferred", + role = %actor, + business_id = %message.business_id, + queued_message_id = %message.message_id, + message_type = %message.msg_type, + queue_wait_secs, + elapsed_ms = started_at.elapsed().as_millis() as u64, + "local message handler rescheduled its own queue entry" + ); + } + Ok(false) => { + let current_state = storage_processor + .find_messages_by_id(&message.message_id) + .await + .ok() + .flatten() + .map(|message| message.state); + tracing::warn!( + event = "local_message_queue", + outcome = "state_update_conflict", + role = %actor, + business_id = %message.business_id, + queued_message_id = %message.message_id, + message_type = %message.msg_type, + current_state = ?current_state, + queue_wait_secs, + elapsed_ms = started_at.elapsed().as_millis() as u64, + "local message handler completed but its processed state was not persisted" + ); + } + Err(error) => log_queue_bookkeeping_failure( + "local_message_queue", + &message.message_id, + "confirm_self_defer", + &error, + ), + } } } Err(err) => { - let lock_time: i64 = if is_retryable_sqlite_error(&err) - && is_pegin_message_type(&message.msg_type) - { - TRANSIENT_PEGIN_RETRY_DELAY_SECS as i64 - } else { - 600 + let is_transient = is_retryable_sqlite_error(&err); + let requested_retry_delay = + p2p_retryable_dispatch_error(&err).and_then(|(_, delay)| delay); + let lock_time: i64 = requested_retry_delay.unwrap_or_else(|| { + if is_transient + && MessageKind::from_str(&message.msg_type).is_ok_and(MessageKind::is_pegin) + { + TRANSIENT_PEGIN_RETRY_DELAY_SECS as i64 + } else { + LOCAL_MESSAGE_RETRY_DELAY_SECS + } + }); + let mut storage_processor = match local_db.acquire().await { + Ok(storage_processor) => storage_processor, + Err(error) => { + log_queue_bookkeeping_failure( + "local_message_queue", + &message.message_id, + "acquire", + &error, + ); + continue; + } }; - metrics_state.record_message_retry(); - tracing::warn!( - event = "local_message_queue", - outcome = "deferred", - role = %actor, - business_id = %message.business_id, - queued_message_id = %message.message_id, - message_type = %message.msg_type, - retry_after_secs = lock_time, - queue_wait_secs, - elapsed_ms = started_at.elapsed().as_millis() as u64, - error = %err, - "failed to process local message; deferred for retry" - ); - let mut storage_processor = local_db.acquire().await?; if let Err(reason_error) = storage_processor .upsert_message_debug_reason( &message.message_id, @@ -1676,18 +2186,84 @@ pub async fn handle_self_p2p_msg( "failed to persist local message debug reason" ); } - storage_processor - .update_messages_lock_time_until( + let deferred = storage_processor + .defer_local_message( &message.message_id, message.message_version, current_time_secs() + lock_time, + &err.to_string(), ) - .await?; + .await; + match deferred { + Ok(true) => {} + Ok(false) => { + // The handler may have rescheduled its own row before + // returning the error; that is still a reported outcome. + match storage_processor + .confirm_local_message_self_defer( + &message.message_id, + message.message_version, + ) + .await + { + Ok(true) => tracing::debug!( + event = "local_message_queue", + outcome = "self_deferred", + queued_message_id = %message.message_id, + error = %err, + "local message handler rescheduled its own queue entry before failing" + ), + Ok(false) => tracing::warn!( + event = "local_message_queue", + outcome = "stale_claim", + queued_message_id = %message.message_id, + message_version = message.message_version, + operation = "defer", + "ignored local message update from a stale claim" + ), + Err(error) => log_queue_bookkeeping_failure( + "local_message_queue", + &message.message_id, + "confirm_self_defer", + &error, + ), + } + continue; + } + Err(error) => { + log_queue_bookkeeping_failure( + "local_message_queue", + &message.message_id, + "defer", + &error, + ); + continue; + } + } + metrics_state.record_message_retry(); + tracing::warn!( + event = "local_message_queue", + outcome = "deferred", + role = %actor, + business_id = %message.business_id, + queued_message_id = %message.message_id, + message_type = %message.msg_type, + retry_after_secs = lock_time, + attempt_count = message.attempt_count + 1, + queue_wait_secs, + elapsed_ms = started_at.elapsed().as_millis() as u64, + error = %err, + "failed to process local message; deferred for retry" + ); } } } - handle_p2p_outbox_messages(swarm, local_db).await?; - handle_p2p_inbox_messages( + // The three queues share a tick but must not share a failure: propagating + // here would let one stalled queue starve the other two every tick. + if let Err(error) = handle_p2p_outbox_messages(swarm, local_db).await { + tracing::error!(error = %error, "failed to drain the durable P2P outbox"); + } + if let Err(error) = handle_p2p_inbox_messages( swarm, local_db, btc_client, @@ -1696,8 +2272,15 @@ pub async fn handle_self_p2p_msg( soldering_builder, actor, metrics_state, + shutdown, ) - .await?; + .await + { + tracing::error!(error = %error, "failed to drain the durable P2P inbox"); + if shutdown.is_cancelled() { + return Err(error); + } + } Ok(()) } @@ -1930,42 +2513,88 @@ pub async fn send_to_peer( pub async fn push_local_unhandled_messages_with_reason( local_db: &LocalDB, - business_id: Uuid, message: &GOATMessage, delay_secs: usize, reason: MessageDeferReason, reason_detail: &str, ) -> Result<()> { - let mut storage_processor = local_db.acquire().await?; + let mut storage_processor = local_db.start_immediate_transaction().await?; let actor = message.actor.clone(); let content: GOATMessageContent = message.content().clone(); - upsert_message( - &mut storage_processor, - true, - business_id, - None, - SELF_SENDER.to_string(), - actor, - content, - 0, - delay_secs as i64, - ) - .await?; - let persist_result = match storage_processor - .find_message_by_business_id(&business_id, message.content.event_type()) - .await + let key = LocalMessageKey::from_content(actor.clone(), &content)?; + let business_id = key.business_id(); + let message_type = message.content.event_type(); + let target_message_id = key.message_id(); + let active_claim = ACTIVE_LOCAL_MESSAGE_CLAIM + .try_with(|claim| (claim.message_id.clone(), claim.message_version)) + .ok(); + let claimed_message = if let Some((message_id, _)) = active_claim.as_ref() { + storage_processor.find_messages_by_id(message_id).await? + } else { + None + }; + let owns_requeued_message = claimed_message.as_ref().is_some_and(|existing| { + active_claim.as_ref().is_some_and(|(message_id, message_version)| { + existing.message_id == message_id.as_str() + && existing.message_version == *message_version + && existing.business_id == business_id + && existing.msg_type == message_type + }) + }); + let self_deferred = if let Some(existing) = claimed_message.as_ref() + && existing.state == MessageState::Processing.to_string() + && owns_requeued_message { - Ok(Some(queued_message)) => { + storage_processor + .self_defer_local_message( + &existing.message_id, + existing.message_version, + current_time_secs() + delay_secs as i64, + reason_detail, + ) + .await? + } else { + false + }; + if !self_deferred { + let upserted = upsert_message( + &mut storage_processor, + true, + SELF_SENDER.to_string(), + actor, + content, + 0, + delay_secs as i64, + ) + .await?; + if !upserted { + let current = storage_processor.find_messages_by_id(&target_message_id).await?; + if current + .as_ref() + .is_some_and(|message| message.state == MessageState::Processing.to_string()) + { + return Err(retryable_dispatch_error( + RetryableDispatchReason::ResourceLocked, + Some(delay_secs.max(1) as i64), + format!( + "local message {business_id}:{message_type} is owned by another active claim" + ), + )); + } + } + } + let queued_message_id = if self_deferred { + claimed_message.as_ref().map(|message| message.message_id.as_str()) + } else { + Some(target_message_id.as_str()) + }; + let persist_result = match queued_message_id { + Some(message_id) => { storage_processor - .upsert_message_debug_reason( - &queued_message.message_id, - reason.code(), - reason_detail, - ) + .upsert_message_debug_reason(message_id, reason.code(), reason_detail) .await } - Ok(None) => Ok(()), - Err(error) => Err(error), + None => Ok(()), }; if let Err(error) = persist_result { tracing::warn!( @@ -1975,6 +2604,7 @@ pub async fn push_local_unhandled_messages_with_reason( "failed to persist local message defer reason" ); } + storage_processor.commit().await?; if delay_secs > 0 && let Some(metrics_state) = crate::metrics_service::node_metrics_state() { @@ -2016,7 +2646,6 @@ pub(crate) async fn get_graph_or_defer( let delay_secs: usize = 60; // 1 min default retry if let Err(error) = push_local_unhandled_messages_with_reason( local_db, - graph_id, message, delay_secs, MessageDeferReason::GraphSyncPending, @@ -2093,4 +2722,206 @@ mod tests { assert!(!object.contains_key("setup_package")); assert!(!object.contains_key("verifier_pubkey")); } + + #[tokio::test] + async fn genuine_transient_errors_are_still_retryable() { + let error = anyhow!("database is locked"); + assert!( + p2p_retryable_dispatch_error(&error).is_some(), + "a real SQLite-busy error must remain retryable" + ); + } + + #[tokio::test] + async fn dispatch_supervisor_distinguishes_shutdown_and_panic() { + let shutdown = CancellationToken::new(); + shutdown.cancel(); + assert!(matches!( + supervise_dispatch(std::future::pending::<()>(), &shutdown).await, + DispatchExecution::Shutdown + )); + + let running = CancellationToken::new(); + let result = supervise_dispatch( + async { + panic!("poison message"); + }, + &running, + ) + .await; + assert!(matches!( + result, + DispatchExecution::Panicked(detail) if detail == "poison message" + )); + } + + #[tokio::test] + async fn non_owner_requeue_reports_processing_conflict() { + let local_db = store::create_local_db("sqlite::memory:").await; + let instance_id = Uuid::new_v4(); + let message = GOATMessage::new( + Actor::Operator, + GOATMessageContent::PostReady(PostReady { instance_id }), + ); + push_local_unhandled_messages_with_reason( + &local_db, + &message, + 0, + MessageDeferReason::HandlerError, + "initial", + ) + .await + .unwrap(); + + let claimed = { + let mut storage = local_db.acquire().await.unwrap(); + storage + .claim_local_messages( + current_time_secs() + 1, + current_time_secs() + 300, + 0, + 1, + QUEUE_MAX_ABANDONS, + ) + .await + .unwrap() + }; + assert_eq!(claimed.len(), 1); + + let error = push_local_unhandled_messages_with_reason( + &local_db, + &message, + 30, + MessageDeferReason::HandlerError, + "retry", + ) + .await + .unwrap_err(); + let retryable = error + .chain() + .find_map(|cause| cause.downcast_ref::()) + .expect("Processing conflict must be retryable"); + assert_eq!(retryable.reason, RetryableDispatchReason::ResourceLocked); + assert_eq!(retryable.retry_after_secs, Some(30)); + + let mut storage = local_db.acquire().await.unwrap(); + let stored = storage.find_messages_by_id(&claimed[0].message_id).await.unwrap().unwrap(); + assert_eq!(stored.state, MessageState::Processing.to_string()); + assert_eq!(stored.message_version, claimed[0].message_version); + } + + #[tokio::test] + async fn owner_requeue_uses_content_derived_message_id() { + let local_db = store::create_local_db("sqlite::memory:").await; + let instance_id = Uuid::new_v4(); + let message = GOATMessage::new( + Actor::Operator, + GOATMessageContent::PostReady(PostReady { instance_id }), + ); + let message_id = LocalMessageKey::from_content(message.actor.clone(), &message.content) + .unwrap() + .message_id(); + { + let mut storage = local_db.acquire().await.unwrap(); + assert!( + upsert_message( + &mut storage, + false, + SELF_SENDER.to_owned(), + message.actor.clone(), + message.content.clone(), + 0, + 0, + ) + .await + .unwrap() + ); + } + let claimed = { + let mut storage = local_db.acquire().await.unwrap(); + storage + .claim_local_messages( + current_time_secs() + 1, + current_time_secs() + 300, + 0, + 1, + QUEUE_MAX_ABANDONS, + ) + .await + .unwrap() + .pop() + .unwrap() + }; + assert_eq!(claimed.message_id, message_id); + + // Two earlier attempts died mid-dispatch; the row carries their abandons + // into this claim, and the handler's own reschedule must not erase them. + { + let mut storage = local_db.acquire().await.unwrap(); + for _ in 0..2 { + assert!( + storage + .abandon_local_message( + &message_id, + claimed.message_version, + current_time_secs(), + 0, + "died mid-dispatch", + ) + .await + .unwrap() + ); + } + } + let claimed = { + let mut storage = local_db.acquire().await.unwrap(); + storage + .claim_local_messages( + current_time_secs() + 301, + current_time_secs() + 600, + 0, + 1, + QUEUE_MAX_ABANDONS, + ) + .await + .unwrap() + .pop() + .unwrap() + }; + assert_eq!(claimed.abandon_count, 2); + + ACTIVE_LOCAL_MESSAGE_CLAIM + .scope( + LocalMessageClaim { + message_id: claimed.message_id.clone(), + message_version: claimed.message_version, + }, + push_local_unhandled_messages_with_reason( + &local_db, + &message, + 30, + MessageDeferReason::HandlerError, + "retry subtyped message", + ), + ) + .await + .unwrap(); + + let mut storage = local_db.acquire().await.unwrap(); + let stored = storage.find_messages_by_id(&message_id).await.unwrap().unwrap(); + assert_eq!(stored.state, MessageState::Pending.to_string()); + assert_eq!(stored.abandon_count, 2, "a self-defer must keep the abandon count"); + + // The dispatcher confirms the self-defer once the handler has returned. + assert!( + storage + .confirm_local_message_self_defer(&message_id, claimed.message_version) + .await + .unwrap() + ); + assert_eq!( + storage.find_messages_by_id(&message_id).await.unwrap().unwrap().abandon_count, + 0 + ); + } } diff --git a/node/src/bin/db_inject.rs b/node/src/bin/db_inject.rs index 0dc8b997..f7c08600 100644 --- a/node/src/bin/db_inject.rs +++ b/node/src/bin/db_inject.rs @@ -8,7 +8,6 @@ //! - --db-path: local SQLite path (e.g., sqlite:/tmp/bitvm-node.db) //! - --actor: Committee | Operator | Verifier | Watchtower | All //! - --message-json or --message-file (one required) -//! - --business-id (optional; inferred from content when unambiguous) //! //! Example: //! - cargo run -p bitvm-noded --bin update-db -- \ @@ -21,7 +20,6 @@ use std::str::FromStr; use anyhow::{Context, Result, anyhow}; use clap::Parser; -use uuid::Uuid; use bitvm_lib::actors::Actor; use bitvm_noded::action::*; @@ -39,14 +37,6 @@ struct Args { #[arg(long, value_parser = parse_actor)] actor: Actor, - /// Business id used for message_id (graph_id or instance_id). If omitted, infer it when unambiguous. - #[arg(long)] - business_id: Option, - - /// Optional sub-type used when generating message_id - #[arg(long)] - sub_type: Option, - /// from_peer column, defaults to "Manual" #[arg(long, default_value = "Manual")] from_peer: String, @@ -76,55 +66,6 @@ fn parse_actor(raw: &str) -> std::result::Result { Actor::from_str(raw).map_err(|_| format!("invalid actor: {raw}")) } -fn infer_business_id(content: &GOATMessageContent) -> Option { - match content { - GOATMessageContent::PeginRequest(v) => Some(v.instance_id), - GOATMessageContent::ConfirmInstance(v) => Some(v.instance_id), - GOATMessageContent::InitGraph(v) => Some(v.graph_id), - GOATMessageContent::GenCircuits(v) => Some(v.graph_id), - GOATMessageContent::CutCircuits(v) => Some(v.graph_id), - GOATMessageContent::SolderingProofReady(v) => Some(v.graph_id), - GOATMessageContent::GraphSetupAck(_) => None, - GOATMessageContent::VerifierGraphParamsEndorsement(v) => Some(v.graph_id), - GOATMessageContent::CreateGraph(v) => Some(v.graph_id), - GOATMessageContent::NonceGeneration(v) => Some(v.graph_id), - GOATMessageContent::AggNonceConsensus(v) => Some(v.graph_id), - GOATMessageContent::CommitteePresign(v) => Some(v.graph_id), - GOATMessageContent::EndorseGraph(v) => Some(v.graph_id), - GOATMessageContent::GraphFinalize(v) => Some(v.graph_id), - GOATMessageContent::PeginConfirmNonce(v) => Some(v.instance_id), - GOATMessageContent::PeginConfirmNonceConsensus(v) => Some(v.instance_id), - GOATMessageContent::PeginConfirmPartialSig(v) => Some(v.instance_id), - GOATMessageContent::PostReady(v) => Some(v.instance_id), - GOATMessageContent::KickoffReady(v) => Some(v.graph_id), - GOATMessageContent::KickoffSent(v) => Some(v.graph_id), - GOATMessageContent::PreKickoffSent(v) => Some(v.graph_id), - GOATMessageContent::ChallengeSent(v) => Some(v.graph_id), - GOATMessageContent::WatchtowerChallengeInitSent(v) => Some(v.graph_id), - GOATMessageContent::WatchtowerChallengeSent(v) => Some(v.graph_id), - GOATMessageContent::WatchtowerChallengeTimeout(v) => Some(v.graph_id), - GOATMessageContent::NackReady(v) => Some(v.graph_id), - GOATMessageContent::OperatorCommitPubinReady(v) => Some(v.graph_id), - GOATMessageContent::OperatorCommitPubinTimeout(v) => Some(v.graph_id), - GOATMessageContent::AssertReady(v) => Some(v.graph_id), - GOATMessageContent::AssertSent(v) => Some(v.graph_id), - GOATMessageContent::ChallengeAssertSent(v) => Some(v.graph_id), - GOATMessageContent::WronglyChallengeTimeout(v) => Some(v.graph_id), - GOATMessageContent::DisproveSent(v) => Some(v.graph_id), - GOATMessageContent::Take1Ready(v) => Some(v.graph_id), - GOATMessageContent::Take1Sent(v) => Some(v.graph_id), - GOATMessageContent::Take2Ready(v) => Some(v.graph_id), - GOATMessageContent::Take2Sent(v) => Some(v.graph_id), - GOATMessageContent::SyncGraphRequest(v) => Some(v.graph_id), - GOATMessageContent::SyncGraph(v) => Some(v.graph_id), - // This payload may refer to multiple graphs, so it has no canonical - // business id. Require callers to provide --business-id explicitly. - GOATMessageContent::InstanceDiscarded(_) => None, - GOATMessageContent::RequestNodeInfo(_) | GOATMessageContent::ResponseNodeInfo(_) => None, - GOATMessageContent::Tick => None, - } -} - fn load_message_json(args: &Args) -> Result { if let Some(ref inline) = args.message_json { return Ok(inline.clone()); @@ -143,13 +84,8 @@ async fn main() -> Result<()> { let content: GOATMessageContent = serde_json::from_str(&raw_json).context("parse GOATMessageContent JSON")?; - let business_id = match &args.business_id { - Some(raw) => Uuid::parse_str(raw).context("parse business_id as UUID")?, - None => infer_business_id(&content) - .ok_or_else(|| anyhow!("business_id not provided and cannot be inferred"))?, - }; - let actor = args.actor; + let message_type = content.event_type(); let local_db = create_local_db(&args.db_path).await; let mut storage_processor = local_db.acquire().await?; let is_update = !args.skip_if_exists; @@ -157,8 +93,6 @@ async fn main() -> Result<()> { upsert_message( &mut storage_processor, is_update, - business_id, - args.sub_type.clone(), args.from_peer.clone(), actor.clone(), content, @@ -168,8 +102,8 @@ async fn main() -> Result<()> { .await?; println!( - "Inserted message for actor={actor} business_id={business_id} db_path={} update={} lock_secs={} weight={}", - args.db_path, is_update, args.lock_secs, args.weight + "Inserted message for actor={actor} message_type={} db_path={} update={} lock_secs={} weight={}", + message_type, args.db_path, is_update, args.lock_secs, args.weight ); Ok(()) } diff --git a/node/src/bin/mock_rpc.rs b/node/src/bin/mock_rpc.rs index 6f011f30..cff02fca 100644 --- a/node/src/bin/mock_rpc.rs +++ b/node/src/bin/mock_rpc.rs @@ -336,7 +336,7 @@ async fn seed_mock_data( tx.upsert_node(&node).await?; } for instance in [bridge_in_success, bridge_in_pending] { - tx.upsert_instance(&instance).await?; + tx.insert_instance_if_absent(&instance).await?; } tx.insert_swap_escrow_if_absent(&swap_escrow).await?; for graph in [ready_graph, challenge_graph] { diff --git a/node/src/bin/sequencer-set-publish.rs b/node/src/bin/sequencer-set-publish.rs index 8e1ce96b..acd1f088 100644 --- a/node/src/bin/sequencer-set-publish.rs +++ b/node/src/bin/sequencer-set-publish.rs @@ -759,6 +759,107 @@ async fn update_sequencer_set_on_goat( Ok(()) } +/// Collect the threshold signatures for the update connector in redeem-script order. +/// +/// Witnesses are permissionlessly appended on Goat, so every field must be treated as +/// untrusted. Invalid, stale, duplicate, or unauthorized witnesses are ignored rather +/// than allowing one entry to abort publishing for the whole height. +fn collect_ordered_publisher_signatures( + witnesses: &[SequencerSetUpdateWitness], + btc_public_keys: &[secp256k1::PublicKey], + expected_sighash: [u8; 32], + threshold: usize, + goat_block_number: u64, +) -> anyhow::Result>> { + let secp = Secp256k1::verification_only(); + let message = Message::from_digest_slice(&expected_sighash) + .expect("a Bitcoin sighash is always exactly 32 bytes"); + let mut signatures_by_member = vec![None; btc_public_keys.len()]; + + for (witness_index, witness) in witnesses.iter().enumerate() { + let public_key = match secp256k1::PublicKey::from_slice(&witness.btc_pub_key) { + Ok(public_key) => public_key, + Err(error) => { + tracing::warn!( + goat_block_number, + witness_index, + error = %error, + "Skipping sequencer set witness with an invalid Bitcoin public key" + ); + continue; + } + }; + + let Some(member_index) = btc_public_keys.iter().position(|key| key == &public_key) else { + tracing::warn!( + goat_block_number, + witness_index, + public_key = %public_key, + "Skipping sequencer set witness from an unauthorized Bitcoin public key" + ); + continue; + }; + + if witness.sig_hash != expected_sighash { + tracing::warn!( + goat_block_number, + witness_index, + public_key = %public_key, + "Skipping sequencer set witness for a different transaction sighash" + ); + continue; + } + + let signature = match secp256k1::ecdsa::Signature::from_compact(&witness.btc_sig) { + Ok(signature) => signature, + Err(error) => { + tracing::warn!( + goat_block_number, + witness_index, + public_key = %public_key, + error = %error, + "Skipping sequencer set witness with an invalid compact signature" + ); + continue; + } + }; + + if let Err(error) = secp.verify_ecdsa(&message, &signature, &public_key) { + tracing::warn!( + goat_block_number, + witness_index, + public_key = %public_key, + error = %error, + "Skipping sequencer set witness with a signature that does not match the transaction" + ); + continue; + } + + if signatures_by_member[member_index].is_some() { + tracing::warn!( + goat_block_number, + witness_index, + public_key = %public_key, + "Skipping duplicate sequencer set witness" + ); + continue; + } + + let mut signature_bytes = signature.serialize_der().to_vec(); + signature_bytes.push(EcdsaSighashType::AllPlusAnyoneCanPay as u8); + signatures_by_member[member_index] = Some(signature_bytes); + } + + let mut signatures: Vec<_> = signatures_by_member.into_iter().flatten().collect(); + anyhow::ensure!( + signatures.len() >= threshold, + "only {} valid publisher signatures for Goat height {goat_block_number}; need {threshold}", + signatures.len() + ); + signatures.truncate(threshold); + Ok(signatures) +} + /// Submit sequencer set commitment #[allow(clippy::too_many_arguments)] async fn action_push_sequencer_set_update( @@ -778,23 +879,9 @@ async fn action_push_sequencer_set_update( output_file: &str, ) -> Result<(), Box> { let witnesses = goat_client.ss_get_sequencer_set_update_witness(goat_block_number).await?; - let mut sigs: Vec<_> = witnesses - .iter() - .filter(|x| { - btc_public_keys.contains(&secp256k1::PublicKey::from_slice(&x.btc_pub_key).unwrap()) - }) - .map(|x| { - let sig = secp256k1::ecdsa::Signature::from_compact(&x.btc_sig).expect("Invalid sig"); - let mut sig_bytes = sig.serialize_der().to_vec(); - sig_bytes.push(EcdsaSighashType::AllPlusAnyoneCanPay as u8); - sig_bytes - }) - .collect(); let total = btc_public_keys.len(); let threshold = (2 * total).div_ceil(3); - sigs.resize(threshold, vec![]); - let total = next_btc_public_keys.len(); let next_threshold = (2 * total).div_ceil(3); @@ -802,8 +889,6 @@ async fn action_push_sequencer_set_update( let next_redeem_script = create_sequencer_update_script(&next_btc_public_keys, next_threshold); let next_update_connector_address = Address::p2wsh(&next_redeem_script, btc_client.network()); - println!("sigs: {sigs:?}"); - // update the sequencer set publish tx with multisig signatures let (update_connector, update_connector_value) = match &update_connector_outpoint { Some(update_connector) => { @@ -850,6 +935,24 @@ async fn action_push_sequencer_set_update( Amount::from_sat(RELAYER_FEE), )?; + let publisher_sigs = if let Some(update_connector_value) = update_connector_value { + let sighash = SighashCache::new(&mut sequencer_set_publish_tx).p2wsh_signature_hash( + 0, + &redeem_script, + update_connector_value, + EcdsaSighashType::AllPlusAnyoneCanPay, + )?; + collect_ordered_publisher_signatures( + &witnesses, + &btc_public_keys, + sighash.to_byte_array(), + threshold, + goat_block_number, + )? + } else { + Vec::new() + }; + let secp = secp256k1::Secp256k1::new(); let owner_private_key = PrivateKey::from_wif(owner_btc_key_wif.as_ref().unwrap())?; let owner_p2wpkh = Address::p2wpkh( @@ -865,7 +968,7 @@ async fn action_push_sequencer_set_update( btc_client, &mut sequencer_set_publish_tx, &redeem_script, - sigs, + publisher_sigs, ) .await?; @@ -1119,3 +1222,106 @@ async fn fund_publishers( ); Ok((tx.compute_txid(), current_tx_vout as u32)) } + +#[cfg(test)] +mod tests { + use super::*; + use bitcoin::secp256k1::SecretKey; + + const SIGHASH: [u8; 32] = [42; 32]; + + fn secret_key(value: u8) -> SecretKey { + SecretKey::from_slice(&[value; 32]).expect("valid test secret key") + } + + fn public_key(secret_key: &SecretKey) -> secp256k1::PublicKey { + secp256k1::PublicKey::from_secret_key(&Secp256k1::new(), secret_key) + } + + fn signed_witness(secret_key: &SecretKey, sighash: [u8; 32]) -> SequencerSetUpdateWitness { + let secp = Secp256k1::new(); + let signature = secp.sign_ecdsa( + &Message::from_digest_slice(&sighash).expect("test sighash is 32 bytes"), + secret_key, + ); + SequencerSetUpdateWitness { + sig_hash: sighash, + btc_pub_key: public_key(secret_key).serialize().to_vec(), + btc_sig: signature.serialize_compact().to_vec(), + } + } + + fn expected_signature(secret_key: &SecretKey) -> Vec { + let secp = Secp256k1::new(); + let signature = secp.sign_ecdsa( + &Message::from_digest_slice(&SIGHASH).expect("test sighash is 32 bytes"), + secret_key, + ); + let mut encoded = signature.serialize_der().to_vec(); + encoded.push(EcdsaSighashType::AllPlusAnyoneCanPay as u8); + encoded + } + + #[test] + fn publisher_witnesses_are_filtered_deduplicated_and_reordered() { + let first = secret_key(1); + let second = secret_key(2); + let third = secret_key(3); + let stranger = secret_key(4); + let publishers = vec![public_key(&first), public_key(&second), public_key(&third)]; + + let mut malformed_key = signed_witness(&first, SIGHASH); + malformed_key.btc_pub_key[0] = 0x01; + let mut malformed_signature = signed_witness(&second, SIGHASH); + malformed_signature.btc_sig.clear(); + + let witnesses = vec![ + malformed_key, + signed_witness(&stranger, SIGHASH), + malformed_signature, + signed_witness(&third, SIGHASH), + signed_witness(&first, SIGHASH), + signed_witness(&first, SIGHASH), + ]; + + let signatures = + collect_ordered_publisher_signatures(&witnesses, &publishers, SIGHASH, 2, 123) + .expect("two valid publisher signatures"); + + assert_eq!(signatures, vec![expected_signature(&first), expected_signature(&third)]); + } + + #[test] + fn publisher_witnesses_keep_exactly_threshold_signatures_in_script_order() { + let first = secret_key(1); + let second = secret_key(2); + let third = secret_key(3); + let publishers = vec![public_key(&first), public_key(&second), public_key(&third)]; + let witnesses = vec![ + signed_witness(&third, SIGHASH), + signed_witness(&second, SIGHASH), + signed_witness(&first, SIGHASH), + ]; + + let signatures = + collect_ordered_publisher_signatures(&witnesses, &publishers, SIGHASH, 2, 123) + .expect("three valid signatures meet the threshold of two"); + + assert_eq!(signatures.len(), 2); + assert_eq!(signatures, vec![expected_signature(&first), expected_signature(&second)]); + } + + #[test] + fn publisher_witnesses_require_a_valid_threshold() { + let first = secret_key(1); + let second = secret_key(2); + let third = secret_key(3); + let publishers = vec![public_key(&first), public_key(&second), public_key(&third)]; + + let witnesses = vec![signed_witness(&first, SIGHASH), signed_witness(&second, [7; 32])]; + + let error = collect_ordered_publisher_signatures(&witnesses, &publishers, SIGHASH, 2, 123) + .expect_err("one valid signature is below threshold"); + assert!(error.to_string().contains("only 1 valid publisher signatures")); + } +} diff --git a/node/src/env.rs b/node/src/env.rs index adb399bc..8d4abb55 100644 --- a/node/src/env.rs +++ b/node/src/env.rs @@ -108,10 +108,9 @@ pub const ENV_SEQUENCER_SET_MONITOR_START_COSMOS_BLOCK: &str = pub const ENV_COSMOS_RPC_URL: &str = "COSMOS_RPC_URL"; pub const DEFAULT_COSMOS_RPC_URL: &str = "https://rpc.testnet3.goat.network/goat-rpc"; -// fee estimate -// TODO: more precise fee estimation -pub const CHEKSIG_P2WSH_INPUT_VBYTES: u64 = 100; -pub const CHEKSIG_P2TR_INPUT_VBYTES: u64 = 100; +// Conservative fee-reserve estimates, not exact serialized transaction sizes. +pub const CHECKSIG_P2WSH_INPUT_VBYTES_ESTIMATE: u64 = 100; +pub const CHECKSIG_P2TR_INPUT_VBYTES_ESTIMATE: u64 = 100; pub const P2WSH_OUTPUT_VBYTES: u64 = 50; pub const P2TR_OUTPUT_VBYTES: u64 = 50; pub const P2A_OUTPUT_VBYTES: u64 = 50; @@ -126,8 +125,6 @@ pub const MIN_CHALLENGE_AMOUNT: u64 = 1_000_000; // 0.01 BTC pub const STAKE_RATE: u64 = 0; // 0% pub const CHALLENGE_RATE: u64 = 0; // 0% -pub const RATE_MULTIPLIER: u64 = 10000; - const COMMITTEE_MEMBER_NUMBER: usize = 2; pub const MESSAGE_BROADCAST_MAX_TIMES: i64 = 3; @@ -144,8 +141,6 @@ pub const SYNC_GRAPH_MAX_WAIT_SECS: u64 = 30; // use to judge load history event thread is dead pub const LOAD_HISTORY_EVENT_NO_WOKING_MAX_SECS: i64 = 600; -pub const GATEWAY_RATE_MULTIPLIER: u64 = 10000; - pub const HEARTBEAT_INTERVAL_SECOND: u64 = 60 * 5; pub const REGULAR_TASK_INTERVAL_SECOND: u64 = 20; pub const SEQUENCER_SET_MONITOR_INTERVAL_SECS: u64 = 5; @@ -639,8 +634,16 @@ pub fn get_soldering_proof_payload_store_path() -> anyhow::Result { Ok(value.to_string()) } +pub const fn actor_needs_soldering_builder(actor: &Actor) -> bool { + matches!(actor, Actor::Verifier | Actor::Operator) +} + +pub const fn actor_runs_babe_setup_state_cleanup(actor: &Actor) -> bool { + actor_needs_soldering_builder(actor) +} + pub fn validate_soldering_proof_payload_store_config(actor: &Actor) -> anyhow::Result<()> { - if matches!(actor, Actor::Verifier | Actor::Operator | Actor::All) { + if actor_needs_soldering_builder(actor) { get_soldering_proof_payload_store_path() .map(|_| ()) .map_err(|err| anyhow::anyhow!("{err}; required for actor {actor}")) @@ -772,7 +775,7 @@ mod tests { assert!(validate_soldering_proof_payload_store_config(&Actor::Verifier).is_err()); assert!(validate_soldering_proof_payload_store_config(&Actor::Operator).is_err()); - assert!(validate_soldering_proof_payload_store_config(&Actor::All).is_err()); + assert!(validate_soldering_proof_payload_store_config(&Actor::All).is_ok()); assert!(validate_soldering_proof_payload_store_config(&Actor::Committee).is_ok()); assert!(validate_soldering_proof_payload_store_config(&Actor::Watchtower).is_ok()); assert!(validate_soldering_proof_payload_store_config(&Actor::Publisher).is_ok()); diff --git a/node/src/handle.rs b/node/src/handle.rs index 89d3a202..79833f90 100644 --- a/node/src/handle.rs +++ b/node/src/handle.rs @@ -95,15 +95,6 @@ impl HeavyTask { } } - pub(crate) fn message_type(&self) -> &'static str { - match self { - Self::GenerateVerifierSetup(_) => "InitGraph", - Self::GenerateSolderingProof(_) => "CutCircuits", - Self::ValidateVerifierGraph(_) => "CreateGraph", - Self::VerifySolderingProof(_) => "SolderingProofReady", - } - } - pub(crate) fn graph_id(&self) -> Uuid { match self { Self::GenerateVerifierSetup(message) => message.graph_id, @@ -135,15 +126,6 @@ pub(crate) fn heavy_task_from_content( } } -pub(crate) fn is_heavy_task_message_type(message_type: &str, actor: &Actor) -> bool { - matches!( - (message_type, actor), - ("SolderingProofReady", Actor::Operator) - | ("InitGraph" | "CutCircuits", Actor::Verifier) - | ("CreateGraph", Actor::Verifier) - ) -} - pub(crate) async fn run_heavy_task(context: &HeavyTaskContext, task: HeavyTask) -> Result<()> { match task { HeavyTask::GenerateVerifierSetup(message) => { @@ -1544,7 +1526,6 @@ async fn defer_confirm_instance_until_previous_graph_presigned( else { push_local_unhandled_messages_with_reason( ctx.local_db, - instance_id, &retry_message, 60, MessageDeferReason::PreviousGraphPending, @@ -1573,7 +1554,6 @@ async fn defer_confirm_instance_until_previous_graph_presigned( } push_local_unhandled_messages_with_reason( ctx.local_db, - instance_id, &retry_message, 60, MessageDeferReason::PreviousGraphPending, @@ -1591,7 +1571,6 @@ async fn defer_confirm_instance_until_previous_graph_presigned( push_local_unhandled_messages_with_reason( ctx.local_db, - instance_id, &retry_message, 60, MessageDeferReason::PreviousGraphPending, @@ -3195,7 +3174,6 @@ async fn handle_create_graph_committee( let message = make_message(ctx, content); push_local_unhandled_messages_with_reason( ctx.local_db, - graph_id, &message, 60, MessageDeferReason::PreviousGraphPending, @@ -3211,7 +3189,6 @@ async fn handle_create_graph_committee( let message = make_message(ctx, content); push_local_unhandled_messages_with_reason( ctx.local_db, - graph_id, &message, 60, MessageDeferReason::PreviousGraphPending, @@ -3228,7 +3205,6 @@ async fn handle_create_graph_committee( let message = make_message(ctx, content); push_local_unhandled_messages_with_reason( ctx.local_db, - graph_id, &message, 60, MessageDeferReason::PreviousGraphPending, @@ -3439,7 +3415,6 @@ async fn handle_agg_nonce_consensus_committee( else { push_local_unhandled_messages_with_reason( ctx.local_db, - graph_id, &message, 30, MessageDeferReason::CommitteeNoncesPending, @@ -3597,7 +3572,6 @@ async fn validate_committee_presign_for_graph( if pub_nonces_unchecked.len() != committee_pubkeys.len() { push_local_unhandled_messages_with_reason( ctx.local_db, - graph_id, &message, 30, MessageDeferReason::CommitteeNoncesPending, @@ -4362,7 +4336,6 @@ async fn handle_pegin_confirm_nonce_consensus_committee( else { push_local_unhandled_messages_with_reason( ctx.local_db, - instance_id, &message, 30, MessageDeferReason::CommitteeNoncesPending, @@ -4434,7 +4407,6 @@ async fn handle_pegin_confirm_partial_sig_committee( if pub_nonces_unchecked.len() != committee_pubkeys.len() { push_local_unhandled_messages_with_reason( ctx.local_db, - instance_id, &message, 30, MessageDeferReason::CommitteeNoncesPending, @@ -4490,7 +4462,6 @@ async fn handle_pegin_confirm_partial_sig_committee( { push_local_unhandled_messages_with_reason( ctx.local_db, - instance_id, &message, 30, MessageDeferReason::CommitteeNonceConsensusPending, @@ -4538,7 +4509,6 @@ async fn handle_pegin_confirm_partial_sig_committee( Err(e) => { push_local_unhandled_messages_with_reason( ctx.local_db, - instance_id, &message, 30, MessageDeferReason::ValidationRetry, @@ -4602,7 +4572,6 @@ async fn handle_post_ready(ctx: &mut HandlerContext<'_>, instance_id: Uuid) -> R ); push_local_unhandled_messages_with_reason( ctx.local_db, - instance_id, &message, delay_secs as usize, MessageDeferReason::BitcoinTransactionPending, @@ -4628,7 +4597,6 @@ async fn handle_post_ready(ctx: &mut HandlerContext<'_>, instance_id: Uuid) -> R ); push_local_unhandled_messages_with_reason( ctx.local_db, - instance_id, &message, delay_secs as usize, MessageDeferReason::CommitteeEndorsementsPending, @@ -4651,7 +4619,6 @@ async fn handle_post_ready(ctx: &mut HandlerContext<'_>, instance_id: Uuid) -> R ); push_local_unhandled_messages_with_reason( ctx.local_db, - instance_id, &message, delay_secs as usize, MessageDeferReason::BitcoinConfirmationPending, @@ -4674,7 +4641,6 @@ async fn handle_post_ready(ctx: &mut HandlerContext<'_>, instance_id: Uuid) -> R ); push_local_unhandled_messages_with_reason( ctx.local_db, - instance_id, &message, delay_secs as usize, MessageDeferReason::GoatSpvPending, @@ -4735,7 +4701,6 @@ async fn handle_post_ready(ctx: &mut HandlerContext<'_>, instance_id: Uuid) -> R ); push_local_unhandled_messages_with_reason( ctx.local_db, - instance_id, &message, delay_secs as usize, MessageDeferReason::CommitteeEndorsementsPending, @@ -4866,7 +4831,6 @@ async fn handle_kickoff_ready_operator( let delay_secs = min_pegout_time_secs * nonce_interval; push_local_unhandled_messages_with_reason( ctx.local_db, - graph_id, &message, delay_secs as usize, MessageDeferReason::PreviousGraphPending, @@ -4882,7 +4846,6 @@ async fn handle_kickoff_ready_operator( let delay_secs = avg_block_time_secs(ctx.btc_client.network()); // wait for 1 blocks push_local_unhandled_messages_with_reason( ctx.local_db, - graph_id, &message, delay_secs as usize, MessageDeferReason::ChainStatePending, @@ -4907,7 +4870,6 @@ async fn handle_kickoff_ready_operator( let delay_secs = min_pegout_time_secs * nonce_interval; push_local_unhandled_messages_with_reason( ctx.local_db, - graph_id, &message, delay_secs as usize, MessageDeferReason::PreviousGraphPending, @@ -4923,7 +4885,6 @@ async fn handle_kickoff_ready_operator( let delay_secs = avg_block_time_secs(ctx.btc_client.network()); // wait for 1 blocks push_local_unhandled_messages_with_reason( ctx.local_db, - graph_id, &message, delay_secs as usize, MessageDeferReason::ChainStatePending, @@ -4983,7 +4944,6 @@ async fn handle_kickoff_sent_committee( let message = make_message(ctx, content); push_local_unhandled_messages_with_reason( ctx.local_db, - graph_id, &message, delay_secs as usize, MessageDeferReason::BitcoinConfirmationPending, @@ -5003,7 +4963,6 @@ async fn handle_kickoff_sent_committee( let message = make_message(ctx, content); push_local_unhandled_messages_with_reason( ctx.local_db, - graph_id, &message, delay_secs as usize, MessageDeferReason::GoatSpvPending, @@ -5077,7 +5036,6 @@ async fn handle_kickoff_sent_verifier( * (kickoff_height - goat_confirmed_btc_height) as u64; push_local_unhandled_messages_with_reason( ctx.local_db, - graph_id, &message, delay_secs as usize, MessageDeferReason::GoatSpvPending, @@ -5402,7 +5360,6 @@ async fn handle_watchtower_challenge_init_sent_watchtower( ); push_local_unhandled_messages_with_reason( ctx.local_db, - graph_id, &message, wait_secs, MessageDeferReason::ProofPending, @@ -5721,7 +5678,6 @@ async fn handle_operator_commit_pubin_ready_operator( ); push_local_unhandled_messages_with_reason( ctx.local_db, - graph_id, &message, wait_secs, MessageDeferReason::ProtocolInputsPending, @@ -5746,7 +5702,6 @@ async fn handle_operator_commit_pubin_ready_operator( ); push_local_unhandled_messages_with_reason( ctx.local_db, - graph_id, &message, wait_secs, MessageDeferReason::ProtocolInputsPending, @@ -5877,7 +5832,6 @@ async fn handle_assert_ready_operator( ); push_local_unhandled_messages_with_reason( ctx.local_db, - graph_id, &message, wait_secs, MessageDeferReason::ProofPending, @@ -6042,7 +5996,6 @@ async fn handle_assert_sent_verifier( let message = make_message(ctx, content); push_local_unhandled_messages_with_reason( ctx.local_db, - graph_id, &message, delay_secs as usize, MessageDeferReason::ProtocolInputsPending, @@ -6062,7 +6015,6 @@ async fn handle_assert_sent_verifier( let message = make_message(ctx, content); push_local_unhandled_messages_with_reason( ctx.local_db, - graph_id, &message, delay_secs as usize, MessageDeferReason::ProtocolInputsPending, @@ -6076,7 +6028,6 @@ async fn handle_assert_sent_verifier( let message = make_message(ctx, content); push_local_unhandled_messages_with_reason( ctx.local_db, - graph_id, &message, delay_secs as usize, MessageDeferReason::ProtocolInputsPending, @@ -6107,7 +6058,6 @@ async fn handle_assert_sent_verifier( let message = make_message(ctx, content); push_local_unhandled_messages_with_reason( ctx.local_db, - graph_id, &message, delay_secs as usize, MessageDeferReason::ProtocolInputsPending, @@ -6318,7 +6268,6 @@ async fn handle_challenge_assert_sent_operator( let message = make_message(ctx, content); push_local_unhandled_messages_with_reason( ctx.local_db, - graph_id, &message, delay_secs as usize, MessageDeferReason::BitcoinTransactionPending, @@ -6486,7 +6435,6 @@ async fn handle_wrongly_challenge_timeout_verifier( if ctx.btc_client.get_tx(&challenge_assert_txid).await?.is_none() { push_local_unhandled_messages_with_reason( ctx.local_db, - graph_id, &message, delay_secs as usize, MessageDeferReason::BitcoinTransactionPending, @@ -6509,7 +6457,6 @@ async fn handle_wrongly_challenge_timeout_verifier( None => { push_local_unhandled_messages_with_reason( ctx.local_db, - graph_id, &message, delay_secs as usize, MessageDeferReason::BitcoinConfirmationPending, @@ -6534,7 +6481,6 @@ async fn handle_wrongly_challenge_timeout_verifier( avg_block_time_secs(ctx.btc_client.network()) * (disprove_height - bitcoin_height); push_local_unhandled_messages_with_reason( ctx.local_db, - graph_id, &message, retry_secs as usize, MessageDeferReason::TimelockPending, @@ -6635,7 +6581,6 @@ async fn handle_disprove_sent_committee( let delay_secs = avg_block_time_secs(ctx.btc_client.network()); push_local_unhandled_messages_with_reason( ctx.local_db, - graph_id, &message, delay_secs as usize, MessageDeferReason::BitcoinConfirmationPending, @@ -6654,7 +6599,6 @@ async fn handle_disprove_sent_committee( * (challenge_finish_height - goat_confirmed_height); push_local_unhandled_messages_with_reason( ctx.local_db, - graph_id, &message, delay_secs as usize, MessageDeferReason::GoatSpvPending, @@ -6802,7 +6746,6 @@ async fn handle_take1_sent_committee( let delay_secs = avg_block_time_secs(ctx.btc_client.network()) * 6; // wait for 6 blocks push_local_unhandled_messages_with_reason( ctx.local_db, - graph_id, &message, delay_secs as usize, MessageDeferReason::WithdrawKickoffPending, @@ -6826,7 +6769,6 @@ async fn handle_take1_sent_committee( let delay_secs = avg_block_time_secs(ctx.btc_client.network()); // wait for 1 block push_local_unhandled_messages_with_reason( ctx.local_db, - graph_id, &message, delay_secs as usize, MessageDeferReason::BitcoinConfirmationPending, @@ -6845,7 +6787,6 @@ async fn handle_take1_sent_committee( avg_block_time_secs(ctx.btc_client.network()) * (take1_height - goat_confirmed_height); push_local_unhandled_messages_with_reason( ctx.local_db, - graph_id, &message, delay_secs as usize, MessageDeferReason::GoatSpvPending, @@ -7017,7 +6958,6 @@ async fn handle_take2_sent_committee( let delay_secs = avg_block_time_secs(ctx.btc_client.network()) * 6; // wait for 6 blocks push_local_unhandled_messages_with_reason( ctx.local_db, - graph_id, &message, delay_secs as usize, MessageDeferReason::WithdrawKickoffPending, @@ -7041,7 +6981,6 @@ async fn handle_take2_sent_committee( let delay_secs = avg_block_time_secs(ctx.btc_client.network()); // wait for 1 block push_local_unhandled_messages_with_reason( ctx.local_db, - graph_id, &message, delay_secs as usize, MessageDeferReason::BitcoinConfirmationPending, @@ -7060,7 +6999,6 @@ async fn handle_take2_sent_committee( avg_block_time_secs(ctx.btc_client.network()) * (take2_height - goat_confirmed_height); push_local_unhandled_messages_with_reason( ctx.local_db, - graph_id, &message, delay_secs as usize, MessageDeferReason::GoatSpvPending, diff --git a/node/src/main.rs b/node/src/main.rs index b19d273b..d56312e6 100644 --- a/node/src/main.rs +++ b/node/src/main.rs @@ -3,9 +3,9 @@ use base64::Engine; use bitvm_lib::actors::Actor; use bitvm_lib::babe_adapter::BabeBundleBuilder; use bitvm_noded::env::{ - self, ENV_PEER_KEY, SEQUENCER_SET_MONITOR_INTERVAL_SECS, check_node_info, get_btc_url_from_env, - get_goat_network, get_network, get_node_pubkey, goat_config_from_env, - validate_soldering_proof_payload_store_config, + self, ENV_PEER_KEY, SEQUENCER_SET_MONITOR_INTERVAL_SECS, actor_needs_soldering_builder, + check_node_info, get_btc_url_from_env, get_goat_network, get_network, get_node_pubkey, + goat_config_from_env, validate_soldering_proof_payload_store_config, }; use clap::{Parser, Subcommand}; use client::{btc_chain::BTCClient, goat_chain::GOATClient}; @@ -13,7 +13,7 @@ use libp2p::PeerId; use libp2p_metrics::Registry; use std::error::Error; use std::sync::{Arc, Mutex}; -use std::time::Instant; +use std::time::{Duration, Instant}; use tracing::Instrument; use tracing_subscriber::EnvFilter; @@ -25,6 +25,7 @@ use bitvm_noded::{ }; use anyhow::Result; +use bitvm_noded::action::reclaim_stale_queue_claims; use bitvm_noded::metrics_service::{MetricsState, set_node_metrics_state}; use bitvm_noded::middleware::swarm::{BitvmNetworkManager, BitvmSwarmConfig}; use bitvm_noded::p2p_msg_handler::BitvmNodeProcessor; @@ -196,6 +197,18 @@ async fn main() -> Result<(), Box> { ); let _node_span_guard = node_span.enter(); let local_db = store::create_local_db(&opt.db_path).await; + // Claims left by a previous process are provably abandoned: charge and + // release them before any dispatcher can wait on their leases. + let (reclaimed_local, reclaimed_inbox) = reclaim_stale_queue_claims(&local_db).await?; + if reclaimed_local + reclaimed_inbox > 0 { + tracing::warn!( + event = "message_queue_startup", + outcome = "claims_reclaimed", + reclaimed_local, + reclaimed_inbox, + "reclaimed queue claims left behind by a previous process" + ); + } let metric_registry = Arc::new(Mutex::new(metric_registry)); let metrics_state = MetricsState::new(metric_registry); set_node_metrics_state(metrics_state.clone()); @@ -207,9 +220,10 @@ async fn main() -> Result<(), Box> { env::get_goat_network(), )), http_client: HttpAsyncClient::new(None), - soldering_builder: matches!(actor, Actor::Verifier | Actor::Operator) + soldering_builder: actor_needs_soldering_builder(&actor) .then(|| Arc::new(BabeBundleBuilder::new())), metrics_state: metrics_state.clone(), + shutdown_token: cancellation_token.clone(), }; tracing::info!( @@ -513,8 +527,9 @@ async fn main() -> Result<(), Box> { "all node background tasks have been started" ); - tokio::select! { - (result, index, remaining_handles) = future::select_all(task_handles) => { + let mut core_tasks = future::select_all(task_handles); + let fatal_error = tokio::select! { + (result, index, remaining_handles) = &mut core_tasks => { let task_name = task_names[index]; // Log the specific failure let failure_reason = match &result { @@ -563,14 +578,10 @@ async fn main() -> Result<(), Box> { "triggering node shutdown after background task result" ); - // Initiate graceful shutdown + // Initiate graceful shutdown and let the tasks release their queue + // claims; anything still running after the grace period is aborted. cancellation_token.cancel(); - - // Wait a moment for graceful shutdown, then force abort remaining tasks - tokio::time::sleep(tokio::time::Duration::from_secs(2)).await; - - // Force abort any tasks that didn't respond to cancellation - remaining_handles.into_iter().for_each(|handle| handle.abort()); + wait_for_task_shutdown(remaining_handles).await; tracing::info!( event = "service_shutdown", @@ -581,9 +592,9 @@ async fn main() -> Result<(), Box> { // Handle panic propagation if let Err(join_error) = result && join_error.is_panic() { - std::panic::resume_unwind(join_error.into_panic()); - + std::panic::resume_unwind(join_error.into_panic()); } + Some(anyhow::anyhow!("core task {task_name} stopped: {failure_reason}")) } _ = shutdown_signal() => { tracing::info!( @@ -594,21 +605,62 @@ async fn main() -> Result<(), Box> { "received shutdown signal; initiating graceful shutdown" ); cancellation_token.cancel(); - - // Give tasks some time to shutdown gracefully - tokio::time::sleep(tokio::time::Duration::from_secs(2)).await; + wait_for_task_shutdown(core_tasks.into_inner()).await; tracing::info!( event = "service_shutdown", service = "bitvm-noded", outcome = "completed", "node graceful shutdown completed" ); + None } + }; + + if let Some(error) = fatal_error { + return Err(error.into()); } Ok(()) } +/// Upper bound on how long shutdown waits for the background tasks to exit on +/// their own before aborting them. +const SHUTDOWN_GRACE_SECS: u64 = 30; + +/// Wait for the background tasks to exit after cancellation. +/// +/// The swarm task releases the queue claims of in-flight messages during this +/// window. A fixed two-second sleep was not enough for that release when a +/// heavy task still held the SQLite write lock, which left the rows to be +/// reclaimed and charged as abandoned on the next start. +async fn wait_for_task_shutdown(mut handles: Vec>>) { + let started_at = Instant::now(); + let joined = tokio::time::timeout( + Duration::from_secs(SHUTDOWN_GRACE_SECS), + future::join_all(handles.iter_mut()), + ) + .await; + match joined { + Ok(_) => tracing::info!( + event = "service_shutdown", + outcome = "tasks_exited", + elapsed_ms = started_at.elapsed().as_millis() as u64, + "all node background tasks exited" + ), + Err(_) => { + tracing::warn!( + event = "service_shutdown", + outcome = "grace_period_exceeded", + grace_secs = SHUTDOWN_GRACE_SECS, + "aborting node background tasks that did not exit within the grace period" + ); + for handle in &handles { + handle.abort(); + } + } + } +} + /// Listen for shutdown signals (Ctrl+C, SIGTERM, etc.) async fn shutdown_signal() { let ctrl_c = async { diff --git a/node/src/metrics_service.rs b/node/src/metrics_service.rs index d4ca387c..319c3eaa 100644 --- a/node/src/metrics_service.rs +++ b/node/src/metrics_service.rs @@ -131,6 +131,8 @@ pub struct MetricsState { graphs: Family, messages: Family, oldest_pending_message_age_seconds: Gauge, + p2p_inbox_messages: Family, + oldest_pending_p2p_inbox_age_seconds: Gauge, ready: Gauge, db_busy_retries_total: Counter, db_errors_total: Counter, @@ -191,6 +193,8 @@ impl MetricsState { let graphs = Family::default(); let messages = Family::default(); let oldest_pending_message_age_seconds = Gauge::default(); + let p2p_inbox_messages = Family::default(); + let oldest_pending_p2p_inbox_age_seconds = Gauge::default(); let ready = Gauge::default(); let db_busy_retries_total = Counter::default(); let db_errors_total = Counter::default(); @@ -284,6 +288,16 @@ impl MetricsState { "Age in seconds of the oldest pending message", oldest_pending_message_age_seconds.clone(), ); + registry.register( + "bitvm_node_p2p_inbox_messages", + "Number of durable P2P inbox messages by state", + p2p_inbox_messages.clone(), + ); + registry.register( + "bitvm_node_oldest_pending_p2p_inbox_age_seconds", + "Age in seconds of the oldest pending durable P2P inbox message", + oldest_pending_p2p_inbox_age_seconds.clone(), + ); registry.register( "bitvm_node_ready", "Whether the node is ready to process work", @@ -459,6 +473,8 @@ impl MetricsState { graphs, messages, oldest_pending_message_age_seconds, + p2p_inbox_messages, + oldest_pending_p2p_inbox_age_seconds, ready, db_busy_retries_total, db_errors_total, @@ -685,6 +701,8 @@ impl MetricsState { self.graphs.clear(); self.messages.clear(); self.oldest_pending_message_age_seconds.set(0); + self.p2p_inbox_messages.clear(); + self.oldest_pending_p2p_inbox_age_seconds.set(0); let now = current_time_secs(); for count in counts { @@ -718,6 +736,19 @@ impl MetricsState { ); } } + "p2p_inbox" => { + let status = known_status::(&count.state); + self.p2p_inbox_messages + .get_or_create(&StatusLabels { status: status.clone() }) + .inc_by(count.count); + if status == "Pending" { + self.oldest_pending_p2p_inbox_age_seconds.set( + count + .oldest_created_at + .map_or(0, |created_at| now.saturating_sub(created_at).max(0)), + ); + } + } _ => {} } } @@ -875,6 +906,13 @@ mod tests { oldest_created_at: None, last_success_at: None, }, + store::MetricsStateCount { + category: "p2p_inbox".to_string(), + state: "Pending".to_string(), + count: 4, + oldest_created_at: Some(current_time_secs() - 30), + last_success_at: None, + }, ]); let output = encoded(&state); @@ -885,6 +923,8 @@ mod tests { assert!(!output.contains("bitvm_node_graphs{status=\"OperatorPresigned\"}")); assert!(!output.contains("unexpected-id-like-value")); assert!(!output.contains("another-unexpected-value")); + assert!(output.contains("bitvm_node_p2p_inbox_messages{status=\"Pending\"} 4")); + assert!(output.contains("bitvm_node_oldest_pending_p2p_inbox_age_seconds 30")); } #[test] diff --git a/node/src/middleware/swarm.rs b/node/src/middleware/swarm.rs index 1a01c3ef..bf7b5e50 100644 --- a/node/src/middleware/swarm.rs +++ b/node/src/middleware/swarm.rs @@ -90,6 +90,10 @@ pub trait P2pMessageHandler { actor: Actor, topic: &str, ) -> anyhow::Result<()>; + + async fn graceful_shutdown(&self) -> anyhow::Result<()> { + Ok(()) + } } #[derive(Clone, Debug)] @@ -212,13 +216,20 @@ impl BitvmNetworkManager { select! { _ = cancellation_token.cancelled() => { info!("Swarm received shutdown signal"); + msg_handler.graceful_shutdown().await?; return Ok("swarm_shutdown".to_string()); } _ticker = interval.tick() => { match msg_handler.handle_tick_message(&mut self.swarm, self.peer_id, actor.clone(), TickMessageType::RegularlyAction).await { Ok(_) => {} - Err(e) => { tracing::error!("Fail to handle tick message {e:?}") } + Err(e) => { + tracing::error!("Fail to handle tick message {e:?}"); + if cancellation_token.is_cancelled() { + msg_handler.graceful_shutdown().await?; + return Err(e); + } + } } self.refresh_required_topics_health(&actor); @@ -255,7 +266,11 @@ impl BitvmNetworkManager { data_prefix, data_starts_with_goatbin, "Fail to handle p2p message" - ) + ); + if cancellation_token.is_cancelled() { + msg_handler.graceful_shutdown().await?; + return Err(e); + } } } } diff --git a/node/src/p2p_msg_handler.rs b/node/src/p2p_msg_handler.rs index 303d935c..d8ccdd86 100644 --- a/node/src/p2p_msg_handler.rs +++ b/node/src/p2p_msg_handler.rs @@ -13,6 +13,7 @@ use libp2p::PeerId; use libp2p::gossipsub::MessageId; use std::sync::Arc; use store::localdb::LocalDB; +use tokio_util::sync::CancellationToken; pub struct BitvmNodeProcessor { pub local_db: LocalDB, @@ -21,6 +22,7 @@ pub struct BitvmNodeProcessor { pub http_client: HttpAsyncClient, pub soldering_builder: Option>, pub metrics_state: MetricsState, + pub shutdown_token: CancellationToken, } impl P2pMessageHandler for BitvmNodeProcessor { async fn recv_and_dispatch( @@ -84,6 +86,7 @@ impl P2pMessageHandler for BitvmNodeProcessor { GOATMessage::default_message_id(), &tick_data, &self.metrics_state, + &self.shutdown_token, ) .await } @@ -107,6 +110,21 @@ impl P2pMessageHandler for BitvmNodeProcessor { } Ok(()) } + + async fn graceful_shutdown(&self) -> anyhow::Result<()> { + let mut storage = self.local_db.start_immediate_transaction().await?; + let local_released = storage.release_processing_local_messages().await?; + let inbox_released = storage.release_processing_p2p_inbox_messages().await?; + storage.commit().await?; + tracing::info!( + event = "message_queue_shutdown", + outcome = "claims_released", + local_released, + inbox_released, + "released active queue claims without charging abandon counters" + ); + Ok(()) + } } #[cfg(test)] diff --git a/node/src/rpc_service/bitvm.rs b/node/src/rpc_service/bitvm.rs index b73057bf..9e57ea82 100644 --- a/node/src/rpc_service/bitvm.rs +++ b/node/src/rpc_service/bitvm.rs @@ -41,12 +41,32 @@ const GRAPH_OPERATOR_KICKOFFING_STATUS_DURATION_SECS: i64 = 1800; const GRAPH_OPERATOR_KICKOFF_STATUS_DURATION_SECS: i64 = 3600 * 3; const GRAPH_OPERATOR_CHALLENGE_STATUS_DURATION_SECS: i64 = 3600 * 9; +#[derive(Clone, Copy, Display, EnumString)] +enum GraphDisplayStatus { + Created, + Presigned, + L2Recorded, + OperatorKickOffing, +} + +#[derive(Clone, Copy, Display, EnumString)] +enum InstanceDisplayStatus { + Initiated, + Verified, + Submitted, + Failed, + Processing, + Success, + Canceled, +} + #[derive(Debug, Deserialize, Serialize)] pub struct InstanceSettingResponse { pub bridge_in_amount: Vec, } #[derive(Debug, Deserialize, Serialize)] +#[cfg(feature = "rpc-debug-endpoints")] pub struct SendChallengeResponse { pub challenge_txid: String, } @@ -310,21 +330,17 @@ fn get_bridge_in_status_time_window_secs(status: &str, response_window_blocks: i + INSTANCE_RELAYER_L1_BROADCAST_STATUS_DURATION_SECS; match InstanceBridgeInStatus::from_str(status) { - Ok(InstanceBridgeInStatus::UserIniting) - | Ok(InstanceBridgeInStatus::Initiated) - | Ok(InstanceBridgeInStatus::UserInited) => { + Ok(InstanceBridgeInStatus::UserIniting) | Ok(InstanceBridgeInStatus::UserInited) => { (response_window_blocks_with_margin * GOAT_BLOCK_INTERVAL_SECS, total_time) } - Ok(InstanceBridgeInStatus::CommitteesAnswered) | Ok(InstanceBridgeInStatus::Verified) => { + Ok(InstanceBridgeInStatus::CommitteesAnswered) => { (0, total_time - response_window_blocks_with_margin * GOAT_BLOCK_INTERVAL_SECS) } - Ok(InstanceBridgeInStatus::Submitted) - | Ok(InstanceBridgeInStatus::UserBroadcastPeginPrepare) => ( + Ok(InstanceBridgeInStatus::UserBroadcastPeginPrepare) => ( INSTANCE_USER_BROADCAST_PREPARE_STATUS_DURATION_SECS, total_time - response_window_blocks_with_margin * GOAT_BLOCK_INTERVAL_SECS, ), - Ok(InstanceBridgeInStatus::Processing) - | Ok(InstanceBridgeInStatus::Presigned) + Ok(InstanceBridgeInStatus::Presigned) | Ok(InstanceBridgeInStatus::RelayerL1Broadcasted) => ( INSTANCE_RELAYER_L1_BROADCAST_STATUS_DURATION_SECS, total_time @@ -468,7 +484,7 @@ impl From for GraphQuery { let mut is_init_withdraw_not_null = value .status .as_ref() - .map(|status| status == &GraphStatus::OperatorKickOffing.to_string()) + .map(|status| status == &GraphDisplayStatus::OperatorKickOffing.to_string()) .unwrap_or(false); is_init_withdraw_not_null = is_init_withdraw_not_null || value.is_pegout_started; let mut statuses = vec![]; @@ -643,31 +659,46 @@ trait DisplayStatusConvert { fn parse_display_status(ori_status: &str) -> Vec; } +/// Map a status that is not a display alias onto the stored lifecycle status. +/// +/// An empty filter means "no status filter" downstream, so an unknown status +/// name must not collapse into an empty list: that turned a stale or mistyped +/// status into a full listing. It matches nothing instead. Only an empty +/// parameter still means "no filter". +fn raw_status_filter(ori_status: &str) -> Vec { + if ori_status.trim().is_empty() { + return vec![]; + } + match S::from_str(ori_status) { + Ok(status) => vec![status.to_string()], + Err(_) => vec![ori_status.to_owned()], + } +} + impl DisplayStatusConvert for Graph { fn convert_to_display_status(&self) -> String { match GraphStatus::from_str(&self.status) { - Ok(GraphStatus::OperatorPresigned) => GraphStatus::Created.to_string(), - Ok(GraphStatus::CommitteePresigned) => GraphStatus::Presigned.to_string(), + Ok(GraphStatus::OperatorPresigned) => GraphDisplayStatus::Created.to_string(), + Ok(GraphStatus::CommitteePresigned) => GraphDisplayStatus::Presigned.to_string(), Ok(GraphStatus::OperatorDataPushed) => { if self.init_withdraw_tx_hash.is_some() { - GraphStatus::OperatorKickOffing.to_string() + GraphDisplayStatus::OperatorKickOffing.to_string() } else { - GraphStatus::L2Recorded.to_string() + GraphDisplayStatus::L2Recorded.to_string() } } Ok(_) | Err(_) => self.status.clone(), } } fn parse_display_status(ori_status: &str) -> Vec { - match GraphStatus::from_str(ori_status) { - Ok(GraphStatus::Created) => vec![GraphStatus::OperatorPresigned.to_string()], - Ok(GraphStatus::Presigned) => vec![GraphStatus::CommitteePresigned.to_string()], - Ok(GraphStatus::L2Recorded) => vec![GraphStatus::OperatorDataPushed.to_string()], - Ok(GraphStatus::OperatorKickOffing) => { + match GraphDisplayStatus::from_str(ori_status) { + Ok(GraphDisplayStatus::Created) => vec![GraphStatus::OperatorPresigned.to_string()], + Ok(GraphDisplayStatus::Presigned) => vec![GraphStatus::CommitteePresigned.to_string()], + Ok(GraphDisplayStatus::L2Recorded) => vec![GraphStatus::OperatorDataPushed.to_string()], + Ok(GraphDisplayStatus::OperatorKickOffing) => { vec![GraphStatus::OperatorDataPushed.to_string()] } - Ok(v) => vec![v.to_string()], - Err(_) => vec![], + Err(_) => raw_status_filter::(ori_status), } } } @@ -675,62 +706,61 @@ impl DisplayStatusConvert for Graph { impl DisplayStatusConvert for Instance { fn convert_to_display_status(&self) -> String { match InstanceBridgeInStatus::from_str(&self.status) { - Ok(InstanceBridgeInStatus::UserInited) => InstanceBridgeInStatus::Initiated.to_string(), + Ok(InstanceBridgeInStatus::UserInited) => InstanceDisplayStatus::Initiated.to_string(), Ok(InstanceBridgeInStatus::CommitteesAnswered) => { - InstanceBridgeInStatus::Verified.to_string() + InstanceDisplayStatus::Verified.to_string() } Ok(InstanceBridgeInStatus::UserBroadcastPeginPrepare) => { - InstanceBridgeInStatus::Submitted.to_string() + InstanceDisplayStatus::Submitted.to_string() } - Ok(InstanceBridgeInStatus::Presigned) => InstanceBridgeInStatus::Processing.to_string(), + Ok(InstanceBridgeInStatus::Presigned) => InstanceDisplayStatus::Processing.to_string(), Ok(InstanceBridgeInStatus::RelayerL1Broadcasted) => { - InstanceBridgeInStatus::Processing.to_string() + InstanceDisplayStatus::Processing.to_string() } Ok(InstanceBridgeInStatus::RelayerL2Minted) => { - InstanceBridgeInStatus::Success.to_string() + InstanceDisplayStatus::Success.to_string() } Ok(InstanceBridgeInStatus::PresignedFailed) | Ok(InstanceBridgeInStatus::RelayerL2MintedFailed) - | Ok(InstanceBridgeInStatus::NoEnoughCommitteesAnswered) => { - InstanceBridgeInStatus::Failed.to_string() - } - Ok(InstanceBridgeInStatus::UserCanceled) => { - InstanceBridgeInStatus::Canceled.to_string() + | Ok(InstanceBridgeInStatus::NoEnoughCommitteesAnswered) + | Ok(InstanceBridgeInStatus::UserDiscarded) => { + InstanceDisplayStatus::Failed.to_string() } + Ok(InstanceBridgeInStatus::UserCanceled) => InstanceDisplayStatus::Canceled.to_string(), Ok(_) | Err(_) => self.status.clone(), } } fn parse_display_status(ori_status: &str) -> Vec { - match InstanceBridgeInStatus::from_str(ori_status) { - Ok(InstanceBridgeInStatus::Initiated) => { + match InstanceDisplayStatus::from_str(ori_status) { + Ok(InstanceDisplayStatus::Initiated) => { vec![InstanceBridgeInStatus::UserInited.to_string()] } - Ok(InstanceBridgeInStatus::Verified) => { + Ok(InstanceDisplayStatus::Verified) => { vec![InstanceBridgeInStatus::CommitteesAnswered.to_string()] } - Ok(InstanceBridgeInStatus::Submitted) => { + Ok(InstanceDisplayStatus::Submitted) => { vec![InstanceBridgeInStatus::UserBroadcastPeginPrepare.to_string()] } - Ok(InstanceBridgeInStatus::Processing) => { + Ok(InstanceDisplayStatus::Processing) => { vec![ InstanceBridgeInStatus::RelayerL1Broadcasted.to_string(), InstanceBridgeInStatus::Presigned.to_string(), ] } - Ok(InstanceBridgeInStatus::Success) => { + Ok(InstanceDisplayStatus::Success) => { vec![InstanceBridgeInStatus::RelayerL2Minted.to_string()] } - Ok(InstanceBridgeInStatus::Canceled) => { + Ok(InstanceDisplayStatus::Canceled) => { vec![InstanceBridgeInStatus::UserCanceled.to_string()] } - Ok(InstanceBridgeInStatus::Failed) => vec![ + Ok(InstanceDisplayStatus::Failed) => vec![ InstanceBridgeInStatus::PresignedFailed.to_string(), InstanceBridgeInStatus::RelayerL2MintedFailed.to_string(), InstanceBridgeInStatus::NoEnoughCommitteesAnswered.to_string(), + InstanceBridgeInStatus::UserDiscarded.to_string(), ], - Ok(v) => vec![v.to_string()], - Err(_) => vec![], + Err(_) => raw_status_filter::(ori_status), } } } diff --git a/node/src/rpc_service/handler/bitvm_handler.rs b/node/src/rpc_service/handler/bitvm_handler.rs index 64da9d0c..b216e2ed 100644 --- a/node/src/rpc_service/handler/bitvm_handler.rs +++ b/node/src/rpc_service/handler/bitvm_handler.rs @@ -10,9 +10,11 @@ use crate::rpc_service::response::{ ApiErrorExt, ApiResult, ErrorResponse, error_response, ok_response, }; use crate::rpc_service::validation::InputValidator; +#[cfg(feature = "rpc-debug-endpoints")] +use crate::utils::send_challenge_tx; use crate::utils::{ gen_instance_parameters_local, get_bridge_out_global_stats, load_validated_graph_definition, - obsolete_graph, send_challenge_tx, + obsolete_graph, }; use alloy::primitives::U256; use axum::Json; @@ -1211,6 +1213,7 @@ pub async fn get_unsigned_pegin_txn( /// /// - `200 OK`: Challenge transaction broadcasted successfully, returns txid /// - `500 Internal Server Error`: Graph not found or broadcast failed +#[cfg(feature = "rpc-debug-endpoints")] #[axum::debug_handler] pub async fn send_challenge( Path(graph_id): Path, @@ -1629,15 +1632,6 @@ pub async fn pegout( ), ); } - _ => { - return error_response( - "PEGOUT_ERROR".to_string(), - format!( - "graph {} not ready: previous graph {} has unexpected status {}", - graph.graph_id, previous_graph.graph_id, previous_graph.status - ), - ); - } } } } diff --git a/node/src/rpc_service/mod.rs b/node/src/rpc_service/mod.rs index a16185ef..94fdfc6c 100644 --- a/node/src/rpc_service/mod.rs +++ b/node/src/rpc_service/mod.rs @@ -17,12 +17,12 @@ use crate::rpc_service::handler::{ get_chain_proof_desc, get_graph, get_graph_neighbor_ids, get_graph_tx, get_graph_txn, get_graphs, get_instance, get_instances, get_instances_overview, get_node, get_nodes, get_nodes_overview, get_operator_proof_desc, get_ready_to_kickoff_graph, get_swap, get_swaps, - get_unsigned_pegin_txn, instance_settings, pegout, send_challenge, + get_unsigned_pegin_txn, instance_settings, pegout, }; #[cfg(feature = "rpc-debug-endpoints")] use crate::rpc_service::handler::{ get_debug_message_details, get_debug_status, get_graph_debug_messages, - get_instance_debug_messages, send_verifier_challenge, + get_instance_debug_messages, send_challenge, send_verifier_challenge, }; use anyhow::Context; use axum::body::Body; @@ -172,12 +172,11 @@ pub(crate) fn build_business_router(app_state: Arc) -> Router { .route(routes::v1::DEBUG_INSTANCE_MESSAGES, get(get_instance_debug_messages)) .route(routes::v1::DEBUG_MESSAGE_DETAILS, get(get_debug_message_details)); - let signed_routes = Router::new() - .route(routes::v1::GRAPHS_SEND_CHALLENGE, post(send_challenge)) - .route(routes::v1::PEGOUT, post(pegout)); + let signed_routes = Router::new().route(routes::v1::PEGOUT, post(pegout)); #[cfg(feature = "rpc-debug-endpoints")] let signed_routes = signed_routes + .route(routes::v1::GRAPHS_SEND_CHALLENGE, post(send_challenge)) .route(routes::v1::GRAPHS_SEND_VERIFIER_CHALLENGE, post(send_verifier_challenge)); let signed_routes = signed_routes @@ -536,8 +535,7 @@ mod tests { let keypair = set_test_auth_key(); let cancellation_token = CancellationToken::new(); let (addr, server) = spawn_business_listener(cancellation_token.clone()).await?; - let graph_id = Uuid::new_v4(); - let request_target = format!("/v1/graphs/{graph_id}/send-challenge"); + let request_target = routes::v1::PEGOUT.to_owned(); let url = format!("http://{addr}{request_target}"); let (timestamp, nonce, signature) = sign_request_auth(&keypair, &Method::POST, &request_target, &[]); @@ -550,7 +548,7 @@ mod tests { .header(AUTH_SIGNATURE_HEADER, &signature) .send() .await?; - assert_eq!(first.status().as_u16(), 500); + assert_ne!(first.status().as_u16(), 409); let replay = client .post(&url) @@ -787,7 +785,7 @@ mod tests { ) -> anyhow::Result<()> { let mut tx = local_db.start_transaction().await?; for instance in instances { - tx.upsert_instance(instance).await?; + tx.insert_instance_if_absent(instance).await?; } for graph in graphs { seed_graph_runtime(&mut tx, graph).await?; diff --git a/node/src/rpc_service/routes.rs b/node/src/rpc_service/routes.rs index 61e8fe18..93f150cb 100644 --- a/node/src/rpc_service/routes.rs +++ b/node/src/rpc_service/routes.rs @@ -20,6 +20,7 @@ pub(crate) mod v1 { pub const GRAPHS_TXN_BY_ID: &str = "/v1/graphs/{:id}/txn"; pub const GRAPHS_NEIGHBOR_IDS: &str = "/v1/graphs/{:id}/neighbor-ids"; pub const GRAPHS_TX_BY_ID: &str = "/v1/graphs/{:id}/tx"; + #[cfg(feature = "rpc-debug-endpoints")] pub const GRAPHS_SEND_CHALLENGE: &str = "/v1/graphs/{:id}/send-challenge"; #[cfg(feature = "rpc-debug-endpoints")] pub const GRAPHS_SEND_VERIFIER_CHALLENGE: &str = "/v1/graphs/{:id}/send-verifier-challenge"; diff --git a/node/src/scheduled_tasks/event_watch_task.rs b/node/src/scheduled_tasks/event_watch_task.rs index 2fd39bc9..5066d17a 100644 --- a/node/src/scheduled_tasks/event_watch_task.rs +++ b/node/src/scheduled_tasks/event_watch_task.rs @@ -45,8 +45,8 @@ use store::localdb::{ }; use store::{ GoatTxProcessingStatus, GoatTxRecord, GoatTxType, GraphStatus, GraphStatusSource, - GraphStatusTransitionOutcome, Instance, InstanceBridgeInStatus, MessageState, SwapEscrow, - SwapEscrowStatus, WatchContract, WatchContractStatus, normalize_escrow_hash, + GraphStatusTransitionOutcome, Instance, InstanceBridgeInStatus, SwapEscrow, SwapEscrowStatus, + WatchContract, WatchContractStatus, normalize_escrow_hash, }; use tokio::time::sleep; use tokio_util::sync::CancellationToken; @@ -568,14 +568,7 @@ async fn handle_withdraw_paths_events<'a>( if is_new_event { add_node_reward(storage_processor, &goat_addr.unwrap(), reward_add).await?; } - storage_processor - .update_messages_state_by_business_id( - &graph_id, - None, - MessageState::Pending.to_string(), - MessageState::Cancelled.to_string(), - ) - .await?; + storage_processor.cancel_messages_by_business_id(&graph_id, None).await?; } Ok(()) } @@ -655,14 +648,7 @@ async fn handle_withdraw_disproved_events<'a>( ) .await?; } - storage_processor - .update_messages_state_by_business_id( - &graph_id, - None, - MessageState::Pending.to_string(), - MessageState::Cancelled.to_string(), - ) - .await?; + storage_processor.cancel_messages_by_business_id(&graph_id, None).await?; } Ok(()) } @@ -727,12 +713,13 @@ async fn handle_bridge_in_events<'a>( bridge_in_events: Vec, ) -> anyhow::Result<()> { for event in bridge_in_events { + let post_pegin_txhash = event.transaction_hash.clone(); if let Ok(instance_id) = Uuid::from_str(&strip_hex_prefix_owned(&event.instance_id)) && !storage_processor .update_instance( &InstanceUpdate::new_with_instance_id(instance_id) .with_status(InstanceBridgeInStatus::RelayerL2Minted.to_string()) - .with_post_pegin(event.transaction_hash), + .with_post_pegin(post_pegin_txhash.clone()), ) .await? && let Some(tx_record) = storage_processor @@ -757,7 +744,17 @@ async fn handle_bridge_in_events<'a>( { info!("Instance {instance_id} is created and set status to RelayerL2Minted"); instance.status = InstanceBridgeInStatus::RelayerL2Minted.to_string(); - storage_processor.upsert_instance(&instance).await?; + instance.post_pegin_txhash = Some(post_pegin_txhash.clone()); + if !storage_processor.insert_instance_if_absent(&instance).await? { + info!("Instance {instance_id} was created concurrently; applying mint event"); + storage_processor + .update_instance( + &InstanceUpdate::new_with_instance_id(instance_id) + .with_status(InstanceBridgeInStatus::RelayerL2Minted.to_string()) + .with_post_pegin(post_pegin_txhash.clone()), + ) + .await?; + } } if tx_record.processing_status == GoatTxProcessingStatus::Pending.to_string() { diff --git a/node/src/scheduled_tasks/graph_maintenance_tasks.rs b/node/src/scheduled_tasks/graph_maintenance_tasks.rs index 1cd3b5bc..83a48966 100644 --- a/node/src/scheduled_tasks/graph_maintenance_tasks.rs +++ b/node/src/scheduled_tasks/graph_maintenance_tasks.rs @@ -66,16 +66,11 @@ pub struct ChallengeSubStatus { struct DetectedGraphMessage { actor: Actor, content: GOATMessageContent, - sub_type: Option, } impl DetectedGraphMessage { fn new(actor: Actor, content: GOATMessageContent) -> Self { - Self { actor, content, sub_type: None } - } - - fn with_sub_type(actor: Actor, content: GOATMessageContent, sub_type: String) -> Self { - Self { actor, content, sub_type: Some(sub_type) } + Self { actor, content } } } @@ -115,7 +110,6 @@ impl ChallengeSubStatus { async fn upsert_detected_messages( local_db: &LocalDB, - graph_id: Uuid, messages: Vec, ) -> anyhow::Result<()> { if messages.is_empty() { @@ -127,8 +121,6 @@ async fn upsert_detected_messages( upsert_message( &mut storage_processor, false, - graph_id, - message.sub_type, SELF_SENDER.to_string(), message.actor, message.content, @@ -189,7 +181,7 @@ async fn detect_watchtower_flow_disprove( ) -> anyhow::Result> { for (index, txid) in graph.operator_challenge_nack_txids.iter().enumerate() { if btc_client.get_tx_status(&txid.0).await?.confirmed { - return Ok(Some(DetectedGraphMessage::with_sub_type( + return Ok(Some(DetectedGraphMessage::new( Actor::Committee, GOATMessageContent::DisproveSent(DisproveSent { instance_id: graph.instance_id, @@ -199,7 +191,6 @@ async fn detect_watchtower_flow_disprove( challenge_start_txid: None, challenge_finish_txid: txid.0, }), - index.to_string(), ))); } } @@ -260,8 +251,6 @@ pub async fn detect_init_withdraw_call(local_db: &LocalDB) -> anyhow::Result<()> upsert_message( &mut tx, false, - graph_id, - None, SELF_SENDER.to_string(), Actor::Operator, GOATMessageContent::KickoffReady(KickoffReady { instance_id, graph_id }), @@ -291,8 +280,6 @@ async fn enqueue_kickoff_sent(local_db: &LocalDB, graph: &Graph) -> anyhow::Resu upsert_message( &mut storage_processor, false, - graph.graph_id, - None, SELF_SENDER.to_string(), Actor::All, GOATMessageContent::KickoffSent(KickoffSent { @@ -303,6 +290,7 @@ async fn enqueue_kickoff_sent(local_db: &LocalDB, graph: &Graph) -> anyhow::Resu 0, ) .await + .map(|_| ()) } async fn enqueue_prekickoff_sent(local_db: &LocalDB, graph: &Graph) -> anyhow::Result<()> { @@ -310,8 +298,6 @@ async fn enqueue_prekickoff_sent(local_db: &LocalDB, graph: &Graph) -> anyhow::R upsert_message( &mut storage_processor, false, - graph.graph_id, - None, SELF_SENDER.to_string(), Actor::Verifier, GOATMessageContent::PreKickoffSent(PreKickoffSent { @@ -322,6 +308,7 @@ async fn enqueue_prekickoff_sent(local_db: &LocalDB, graph: &Graph) -> anyhow::R 0, ) .await + .map(|_| ()) } fn is_kickoff_pending_status(status: &str) -> bool { @@ -533,8 +520,6 @@ async fn detect_take1_or_challenge_for_graph( upsert_message( &mut storage_processor, false, - graph.graph_id, - None, SELF_SENDER.to_string(), actor, message_content, @@ -588,7 +573,7 @@ async fn process_graph_challenge_for_graph( "process_graph_challenge detected {} watchtower/pubin flow messages", watchtower_flow_messages.len() ); - upsert_detected_messages(local_db, graph.graph_id, watchtower_flow_messages).await?; + upsert_detected_messages(local_db, watchtower_flow_messages).await?; } let assert_sent_messages = detect_assert_sent_flow(btc_client, local_db, &graph).await?; @@ -597,10 +582,10 @@ async fn process_graph_challenge_for_graph( "process_graph_challenge detected {} assert/challenge-assert messages", assert_sent_messages.len() ); - upsert_detected_messages(local_db, graph.graph_id, assert_sent_messages).await?; + upsert_detected_messages(local_db, assert_sent_messages).await?; } - if let Some((actor, message_content, sub_type)) = + if let Some((actor, message_content)) = detect_assert_disprove_ready(btc_client, local_db, &graph, current_height).await? { info!("process_graph_challenge detect assert disprove ready"); @@ -608,8 +593,6 @@ async fn process_graph_challenge_for_graph( upsert_message( &mut storage_processor, false, - graph.graph_id, - sub_type, SELF_SENDER.to_string(), actor, message_content, @@ -628,8 +611,6 @@ async fn process_graph_challenge_for_graph( upsert_message( &mut storage_processor, false, - graph.graph_id, - None, SELF_SENDER.to_string(), actor, message_content, @@ -757,14 +738,13 @@ async fn detect_watchtower_flow( all_watchtower_branches_resolved = false; } Some(_) if !watchtower_timeout_spent => { - messages.push(DetectedGraphMessage::with_sub_type( + messages.push(DetectedGraphMessage::new( Actor::Operator, GOATMessageContent::WatchtowerChallengeSent(WatchtowerChallengeSent { instance_id: graph.instance_id, graph_id: graph.graph_id, watchtower_index, }), - watchtower_index.to_string(), )); if !ack_spend_confirmed { @@ -920,7 +900,7 @@ async fn detect_assert_sent_flow( continue; }; - messages.push(DetectedGraphMessage::with_sub_type( + messages.push(DetectedGraphMessage::new( Actor::Operator, GOATMessageContent::ChallengeAssertSent(ChallengeAssertSent { instance_id: graph.instance_id, @@ -928,7 +908,6 @@ async fn detect_assert_sent_flow( challenge_assert_txid, verifier_index, }), - verifier_index.to_string(), )); } @@ -941,7 +920,7 @@ async fn detect_assert_disprove_ready( local_db: &LocalDB, graph: &Graph, current_height: i64, -) -> anyhow::Result)>> { +) -> anyhow::Result> { let operator_assert_txid = match graph.operator_assert_txid.clone() { Some(operator_assert_txid) => operator_assert_txid.into(), None => { @@ -1024,7 +1003,6 @@ async fn detect_assert_disprove_ready( challenge_assert_txid: verifier_assert_txid, verifier_index: index, }), - Some(index.to_string()), ))); } } @@ -1249,8 +1227,6 @@ async fn detect_kickoff_ref_disprove_tx( upsert_message( &mut storage_processor, false, - graph.graph_id, - None, SELF_SENDER.to_string(), Actor::Committee, GOATMessageContent::DisproveSent(DisproveSent { @@ -1451,8 +1427,6 @@ async fn check_pre_kickoff_sent( upsert_message( &mut storage_processor, false, - graph_id, - None, SELF_SENDER.to_string(), Actor::Verifier, GOATMessageContent::PreKickoffSent(PreKickoffSent { instance_id, graph_id }), diff --git a/node/src/scheduled_tasks/instance_maintenance_tasks.rs b/node/src/scheduled_tasks/instance_maintenance_tasks.rs index 0126560a..6f94bc06 100644 --- a/node/src/scheduled_tasks/instance_maintenance_tasks.rs +++ b/node/src/scheduled_tasks/instance_maintenance_tasks.rs @@ -1,7 +1,7 @@ use crate::action::{ ConfirmInstance, GOATMessage, GOATMessageContent, MessageDeferReason, PeginConfirmNonce, PeginConfirmNonceConsensus, PeginConfirmPartialSig, PeginRequest, PostReady, - push_local_unhandled_messages_with_reason, + RetryableDispatchError, RetryableDispatchReason, push_local_unhandled_messages_with_reason, }; use crate::env::{ COMMITTEE_INSTANCE_KEYS_DIR, get_bitvm_key, get_committee_instance_key_delete_timelock_blocks, @@ -67,6 +67,34 @@ fn advance_instance_page_state(task_key: &'static str, watermark: i64, last: (i6 state.insert(task_key, InstancePageState { watermark, cursor: Some(last) }); } +fn finish_recovery_enqueue( + result: anyhow::Result<()>, + instance_id: Uuid, + action: &'static str, +) -> anyhow::Result { + match result { + Ok(()) => Ok(true), + Err(error) + if error.chain().any(|cause| { + cause.downcast_ref::().is_some_and(|retryable| { + retryable.reason == RetryableDispatchReason::ResourceLocked + }) + }) => + { + warn!( + event = "pegin_confirm_recovery", + outcome = "resource_locked", + instance_id = %instance_id, + action, + error = %error, + "skip recovery enqueue while the local message is actively claimed" + ); + Ok(false) + } + Err(error) => Err(error), + } +} + async fn find_one_instance_page( local_db: &LocalDB, task_key: &'static str, @@ -112,15 +140,18 @@ async fn find_one_instance_page( async fn update_instance<'a>( storage_processor: &mut StorageProcessor<'a>, params: &InstanceUpdate, -) -> anyhow::Result<()> { +) -> anyhow::Result { match storage_processor.update_instance(params).await { - Ok(true) => info!("update instance with input: {:?}", params), - Ok(false) => info!("skip stale instance update with input: {:?}", params), - Err(err) => { - warn!("update_instance_status with input: {:?} failed {}, will try later", params, err); + Ok(updated) => { + if updated { + info!("update instance with input: {:?}", params); + } else { + info!("skip stale instance update with input: {:?}", params); + } + Ok(updated) } + Err(err) => Err(err.context("update instance")), } - Ok(()) } /// for committee @@ -186,15 +217,25 @@ pub async fn instance_answers_monitor( let mut tx = local_db.start_transaction().await?; if let Some(event) = event { if is_outside_response_window { - if let Some(instance) = discarded_instance { - tx.upsert_instance(&instance).await?; + if let Some(instance) = discarded_instance + && !tx.insert_instance_if_absent(&instance).await? + && !tx + .update_instance( + &InstanceUpdate::new_with_instance_id(instance.instance_id) + .with_status(InstanceBridgeInStatus::UserDiscarded.to_string()) + .with_only_if_status_in(vec![ + InstanceBridgeInStatus::UserIniting.to_string(), + InstanceBridgeInStatus::UserInited.to_string(), + ]), + ) + .await? + { + info!("skip stale UserDiscarded update for instance {}", instance.instance_id); } } else { upsert_message( &mut tx, false, - tx_record.instance_id, - None, SELF_SENDER.to_string(), Actor::All, GOATMessageContent::PeginRequest(PeginRequest { @@ -366,7 +407,8 @@ pub async fn instance_expiration_monitor( update_instance( &mut storage_processor, &InstanceUpdate::new_with_instance_id(instance.instance_id) - .with_status(InstanceBridgeInStatus::Timeout.to_string()), + .with_status(InstanceBridgeInStatus::Timeout.to_string()) + .with_only_if_status_in(vec![instance.status.clone()]), ) .await?; } else { @@ -430,45 +472,46 @@ pub async fn instance_btc_tx_monitor( { let mut tx = local_db.start_transaction().await?; let mut instance_update = InstanceUpdate::new_with_instance_id(instance.instance_id) - .with_status(next_status.to_string()); - match next_status { - InstanceBridgeInStatus::UserBroadcastPeginPrepare => { - instance_update = instance_update - .with_btc_height(status.block_height.unwrap_or_default() as i64); - upsert_message( - &mut tx, - false, - instance.instance_id, - None, - SELF_SENDER.to_string(), - Actor::All, - GOATMessageContent::ConfirmInstance(ConfirmInstance { - instance_id: instance.instance_id, - }), - 0, - 0, - ) - .await?; - } - InstanceBridgeInStatus::RelayerL1Broadcasted => { - upsert_message( - &mut tx, - false, - instance.instance_id, - None, - SELF_SENDER.to_string(), - Actor::All, - GOATMessageContent::PostReady(PostReady { - instance_id: instance.instance_id, - }), - 0, - 0, - ) - .await?; + .with_status(next_status.to_string()) + .with_only_if_status_in(vec![instance.status.clone()]); + if next_status == InstanceBridgeInStatus::UserBroadcastPeginPrepare { + instance_update = + instance_update.with_btc_height(status.block_height.unwrap_or_default() as i64); + } + + if update_instance(&mut tx, &instance_update).await? { + match next_status { + InstanceBridgeInStatus::UserBroadcastPeginPrepare => { + upsert_message( + &mut tx, + false, + SELF_SENDER.to_string(), + Actor::All, + GOATMessageContent::ConfirmInstance(ConfirmInstance { + instance_id: instance.instance_id, + }), + 0, + 0, + ) + .await?; + } + InstanceBridgeInStatus::RelayerL1Broadcasted => { + upsert_message( + &mut tx, + false, + SELF_SENDER.to_string(), + Actor::All, + GOATMessageContent::PostReady(PostReady { + instance_id: instance.instance_id, + }), + 0, + 0, + ) + .await?; + } + _ => {} } - _ => {} } - update_instance(&mut tx, &instance_update).await?; tx.commit().await?; } else { warn!( @@ -497,7 +540,8 @@ pub async fn instance_btc_tx_monitor( update_instance( &mut storage_processor, &InstanceUpdate::new_with_instance_id(instance.instance_id) - .with_status(InstanceBridgeInStatus::UserDiscarded.to_string()), + .with_status(InstanceBridgeInStatus::UserDiscarded.to_string()) + .with_only_if_status_in(vec![instance.status.clone()]), ) .await?; } @@ -580,15 +624,20 @@ pub async fn pegin_confirm_recovery_monitor( endorse_sig, }), ); - push_local_unhandled_messages_with_reason( - local_db, + if !finish_recovery_enqueue( + push_local_unhandled_messages_with_reason( + local_db, + &message, + 0, + MessageDeferReason::RecoveryRepublish, + "re-publishing persisted pegin-confirm partial signature", + ) + .await, instance_id, - &message, - 0, - MessageDeferReason::RecoveryRepublish, - "re-publishing persisted pegin-confirm partial signature", - ) - .await?; + "republish_partial_signature", + )? { + continue; + } tracing::info!( event = "pegin_confirm_recovery", action = "republish_partial_signature", @@ -635,15 +684,20 @@ pub async fn pegin_confirm_recovery_monitor( nonce_sig, }), ); - push_local_unhandled_messages_with_reason( - local_db, + if !finish_recovery_enqueue( + push_local_unhandled_messages_with_reason( + local_db, + &message, + 0, + MessageDeferReason::RecoveryRepublish, + "re-publishing persisted pegin-confirm nonce", + ) + .await, instance_id, - &message, - 0, - MessageDeferReason::RecoveryRepublish, - "re-publishing persisted pegin-confirm nonce", - ) - .await?; + "republish_nonce", + )? { + continue; + } tracing::info!( event = "pegin_confirm_recovery", action = "republish_nonce", @@ -665,15 +719,20 @@ pub async fn pegin_confirm_recovery_monitor( signature, }), ); - push_local_unhandled_messages_with_reason( - local_db, + if !finish_recovery_enqueue( + push_local_unhandled_messages_with_reason( + local_db, + &message, + 0, + MessageDeferReason::RecoveryRepublish, + "re-publishing persisted PeginConfirm nonce consensus", + ) + .await, instance_id, - &message, - 0, - MessageDeferReason::RecoveryRepublish, - "re-publishing persisted PeginConfirm nonce consensus", - ) - .await?; + "republish_nonce_consensus", + )? { + continue; + } tracing::info!( event = "pegin_confirm_recovery", action = "republish_nonce_consensus", diff --git a/node/src/scheduled_tasks/mod.rs b/node/src/scheduled_tasks/mod.rs index 8be12207..719415d9 100644 --- a/node/src/scheduled_tasks/mod.rs +++ b/node/src/scheduled_tasks/mod.rs @@ -6,10 +6,10 @@ mod node_maintenance_tasks; mod sequencer_set_hash_monitor_task; mod spv_maintenance_tasks; -use crate::action::GOATMessageContent; use crate::env::{ - get_maintenance_run_timeout_secs, get_network, get_node_goat_address, get_node_pubkey, - is_enable_babe_setup_state_cleanup, is_enable_update_spv_contract, is_relayer, + actor_runs_babe_setup_state_cleanup, get_maintenance_run_timeout_secs, get_network, + get_node_goat_address, get_node_pubkey, is_enable_babe_setup_state_cleanup, + is_enable_update_spv_contract, is_relayer, }; use crate::metrics_service::MetricsState; use crate::rpc_service::current_time_secs; @@ -33,8 +33,8 @@ pub use sequencer_set_hash_monitor_task::run_sequencer_set_hash_monitor_task; use std::future::Future; use std::sync::Arc; use std::time::{Duration, Instant}; +use store::Graph; use store::localdb::{LocalDB, StorageProcessor}; -use store::{Graph, MessageType}; use tokio_util::sync::CancellationToken; use tracing::{debug, error, info, warn}; @@ -233,9 +233,7 @@ async fn run( let btc_client = btc_client.as_ref(); let goat_client = goat_client.as_ref(); - if is_enable_babe_setup_state_cleanup() - && matches!(&actor, Actor::Verifier | Actor::Operator | Actor::All) - { + if is_enable_babe_setup_state_cleanup() && actor_runs_babe_setup_state_cleanup(&actor) { run_maintenance_subtask( metrics_state, "babe_setup_state_cleanup_monitor", @@ -487,64 +485,6 @@ pub async fn run_maintenance_tasks( } } -pub fn get_goat_message_content_type(content: &GOATMessageContent) -> MessageType { - match content { - GOATMessageContent::PeginRequest(_) => MessageType::PeginRequest, - GOATMessageContent::CreateGraph(_) => MessageType::CreateGraph, - GOATMessageContent::ConfirmInstance(_) => MessageType::ConfirmInstance, - GOATMessageContent::InitGraph(_) => MessageType::InitGraph, - GOATMessageContent::GenCircuits(_) => MessageType::GenCircuits, - GOATMessageContent::CutCircuits(_) => MessageType::CutCircuits, - GOATMessageContent::SolderingProofReady(_) => MessageType::SolderingProof, - GOATMessageContent::GraphSetupAck(_) => MessageType::None, - GOATMessageContent::VerifierGraphParamsEndorsement(_) => { - MessageType::VerifierGraphParamsEndorsement - } - GOATMessageContent::NonceGeneration(_) => MessageType::NonceGeneration, - GOATMessageContent::AggNonceConsensus(_) => MessageType::AggNonceConsensus, - GOATMessageContent::CommitteePresign(_) => MessageType::CommitteePresign, - GOATMessageContent::GraphFinalize(_) => MessageType::GraphFinalize, - GOATMessageContent::EndorseGraph(_) => MessageType::EndorseGraph, - GOATMessageContent::PeginConfirmNonce(_) => MessageType::PeginConfirmNonce, - GOATMessageContent::PeginConfirmNonceConsensus(_) => { - MessageType::PeginConfirmNonceConsensus - } - GOATMessageContent::PeginConfirmPartialSig(_) => MessageType::PeginConfirmPartialSig, - GOATMessageContent::PostReady(_) => MessageType::PostReady, - GOATMessageContent::KickoffReady(_) => MessageType::KickoffReady, - GOATMessageContent::KickoffSent(_) => MessageType::KickoffSent, - GOATMessageContent::PreKickoffSent(_) => MessageType::PreKickoffSent, - GOATMessageContent::ChallengeSent(_) => MessageType::ChallengeSent, - GOATMessageContent::WatchtowerChallengeInitSent(_) => { - MessageType::WatchtowerChallengeInitSent - } - GOATMessageContent::WatchtowerChallengeSent(_) => MessageType::WatchtowerChallengeSent, - GOATMessageContent::WatchtowerChallengeTimeout(_) => { - MessageType::WatchtowerChallengeTimeout - } - GOATMessageContent::NackReady(_) => MessageType::NackReady, - GOATMessageContent::OperatorCommitPubinReady(_) => MessageType::OperatorCommitPubinReady, - GOATMessageContent::OperatorCommitPubinTimeout(_) => { - MessageType::OperatorCommitPubinTimeout - } - GOATMessageContent::AssertReady(_) => MessageType::AssertReady, - GOATMessageContent::AssertSent(_) => MessageType::AssertSent, - GOATMessageContent::ChallengeAssertSent(_) => MessageType::ChallengeAssertSent, - GOATMessageContent::WronglyChallengeTimeout(_) => MessageType::WronglyChallengeTimeout, - GOATMessageContent::DisproveSent(_) => MessageType::DisproveSent, - GOATMessageContent::Take1Ready(_) => MessageType::Take1Ready, - GOATMessageContent::Take1Sent(_) => MessageType::Take1Sent, - GOATMessageContent::Take2Ready(_) => MessageType::Take2Ready, - GOATMessageContent::Take2Sent(_) => MessageType::Take2Sent, - GOATMessageContent::RequestNodeInfo(_) => MessageType::RequestNodeInfo, - GOATMessageContent::ResponseNodeInfo(_) => MessageType::ResponseNodeInfo, - GOATMessageContent::SyncGraphRequest(_) => MessageType::SyncGraphRequest, - GOATMessageContent::SyncGraph(_) => MessageType::SyncGraph, - GOATMessageContent::InstanceDiscarded(_) => MessageType::InstanceDiscarded, - GOATMessageContent::Tick => MessageType::Tick, - } -} - fn get_timestamp_from_contract_data(input: &[u8; 32]) -> i64 { let mut timestamp_bytes = [0u8; 8]; timestamp_bytes.copy_from_slice(&input[24..32]); diff --git a/node/src/utils.rs b/node/src/utils.rs index bb7f8546..dd57ee58 100644 --- a/node/src/utils.rs +++ b/node/src/utils.rs @@ -1,6 +1,7 @@ use crate::action::{ - ChallengeSent, DisproveSent, GOATMessage, GOATMessageContent, KickoffSent, NodeInfo, - PreKickoffSent, SolderingProofReady, Take1Sent, Take2Sent, send_to_peer, + BusinessRef, ChallengeSent, DisproveSent, GOATMessage, GOATMessageContent, HasBusinessRef, + KickoffSent, LocalMessageKey, MessageKind, NodeInfo, PreKickoffSent, SolderingProofReady, + Take1Sent, Take2Sent, send_to_peer, }; use crate::env::*; use crate::error::SpecialError; @@ -78,7 +79,6 @@ use crate::rpc_service::routes::v1::{ NODES_OPERATOR_BASE, NODES_WATCHTOWER_BASE, PROOFS_WATCHTOWER_PROOF_TIMEOUT, }; -use crate::scheduled_tasks::get_goat_message_content_type; use crate::scheduled_tasks::graph_maintenance_tasks::{ ChallengeSubStatus, VerifierChallengeStatus, }; @@ -98,9 +98,8 @@ use proof_builder::{ }; use store::{ BridgeOutGlobalStats, ByteArray32, Graph, GraphRawData, GraphStatus, GraphStatusSource, - GraphStatusTransitionOutcome, Instance, InstanceBridgeInStatus, Message, MessageState, - MessageType, Node, PeginGraphProcessData, PeginInstanceProcessData, SerializableTxid, - UInt64Array3, + GraphStatusTransitionOutcome, Instance, InstanceBridgeInStatus, Message, MessageState, Node, + PeginGraphProcessData, PeginInstanceProcessData, SerializableTxid, UInt64Array3, }; use stun_client::{Attribute, Class, Client}; use tracing::{error, info, warn}; @@ -713,8 +712,8 @@ pub fn challenge_amount() -> Amount { Amount::from_sat(20000) } pub fn prekickoff_fee_amount(replenish_fee_inputs_num: usize) -> Amount { - let tx_vbytes = - PRE_KICKOFF_BASE_VBYTES + (replenish_fee_inputs_num as u64 * CHEKSIG_P2WSH_INPUT_VBYTES); + let tx_vbytes = PRE_KICKOFF_BASE_VBYTES + + (replenish_fee_inputs_num as u64 * CHECKSIG_P2WSH_INPUT_VBYTES_ESTIMATE); Amount::from_sat(tx_vbytes) } pub mod evm_swap_utils { @@ -1754,8 +1753,7 @@ fn compensation_previous_status(status: GraphStatus) -> Option { OperatorKickOff => Some(PreKickoff), OperatorTake1 | Challenge => Some(OperatorKickOff), Disprove | OperatorTake2 => Some(Challenge), - OperatorPresigned | Created | Presigned | L2Recorded | OperatorKickOffing | Challenging - | Disproving => None, + OperatorPresigned => None, } } @@ -1789,13 +1787,15 @@ fn compensation_events_from( async fn upsert_graph_compensate_message( local_db: &LocalDB, - graph_id: Uuid, - sub_type: Option, actor: Actor, message_content: GOATMessageContent, ) -> Result<()> { - let message_type = get_goat_message_content_type(&message_content); - let message_id = generate_message_id(graph_id, message_type.to_string(), sub_type.clone()); + let key = LocalMessageKey::from_content(actor.clone(), &message_content)?; + let graph_id = match message_content.business_ref() { + BusinessRef::Graph { graph_id, .. } => graph_id, + _ => bail!("graph compensation message must be graph-scoped"), + }; + let message_id = key.message_id(); let mut storage_processor = local_db.start_transaction().await?; if !storage_processor.insert_graph_compensation_marker(graph_id, &message_id).await? { storage_processor.commit().await?; @@ -1805,8 +1805,6 @@ async fn upsert_graph_compensate_message( upsert_message( &mut storage_processor, false, - graph_id, - sub_type, SELF_SENDER.to_string(), actor, message_content, @@ -1819,14 +1817,13 @@ async fn upsert_graph_compensate_message( async fn push_graph_compensate_message( local_db: &LocalDB, - graph_id: Uuid, actor: Actor, message_content: GOATMessageContent, ) -> Result<()> { // Unlike an action retry, an inferred chain event must not reset an // existing queued message. This makes compensation safe to retry when the // status write committed before the message was persisted. - upsert_graph_compensate_message(local_db, graph_id, None, actor, message_content).await + upsert_graph_compensate_message(local_db, actor, message_content).await } #[allow(dead_code)] @@ -1875,7 +1872,6 @@ pub(crate) async fn compensate_graph_events( GraphCompensateEventKind::PreKickoffSent => { push_graph_compensate_message( local_db, - graph_id, Actor::Verifier, GOATMessageContent::PreKickoffSent(PreKickoffSent { instance_id, graph_id }), ) @@ -1884,7 +1880,6 @@ pub(crate) async fn compensate_graph_events( GraphCompensateEventKind::KickoffSent => { push_graph_compensate_message( local_db, - graph_id, Actor::All, GOATMessageContent::KickoffSent(KickoffSent { instance_id, graph_id }), ) @@ -1893,7 +1888,6 @@ pub(crate) async fn compensate_graph_events( GraphCompensateEventKind::Take1Sent => { push_graph_compensate_message( local_db, - graph_id, Actor::Committee, GOATMessageContent::Take1Sent(Take1Sent { instance_id, graph_id }), ) @@ -1903,7 +1897,6 @@ pub(crate) async fn compensate_graph_events( if let Some(challenge_txid) = scan.challenge_txid { push_graph_compensate_message( local_db, - graph_id, Actor::Operator, GOATMessageContent::ChallengeSent(ChallengeSent { instance_id, @@ -1922,8 +1915,6 @@ pub(crate) async fn compensate_graph_events( })?; upsert_graph_compensate_message( local_db, - graph_id, - Some(disprove.index.to_string()), Actor::Committee, GOATMessageContent::DisproveSent(DisproveSent { instance_id, @@ -1939,7 +1930,6 @@ pub(crate) async fn compensate_graph_events( GraphCompensateEventKind::Take2Sent => { push_graph_compensate_message( local_db, - graph_id, Actor::Committee, GOATMessageContent::Take2Sent(Take2Sent { instance_id, graph_id }), ) @@ -3066,7 +3056,7 @@ pub async fn get_proper_utxo_set( fn estimate_tx_vbytes(base_vbytes: u64, extra_inputs: usize, extra_outputs: usize) -> u64 { // p2wsh inputs/outputs base_vbytes - + (extra_inputs as u64 * CHEKSIG_P2WSH_INPUT_VBYTES) + + (extra_inputs as u64 * CHECKSIG_P2WSH_INPUT_VBYTES_ESTIMATE) + (extra_outputs as u64 * P2WSH_OUTPUT_VBYTES) } fn to_input(utxos: Vec) -> Vec { @@ -3172,8 +3162,9 @@ pub async fn get_proper_utxo_sets( let n_inputs = tx_ins.len() as u64; let n_outputs = base_outputs.len() as u64 + 1; - let est_vbytes = - 100u64 + n_inputs * CHEKSIG_P2WSH_INPUT_VBYTES + n_outputs * P2WSH_OUTPUT_VBYTES; + let est_vbytes = 100u64 + + n_inputs * CHECKSIG_P2WSH_INPUT_VBYTES_ESTIMATE + + n_outputs * P2WSH_OUTPUT_VBYTES; let est_fee_sat = (est_vbytes as f64 * fee_rate).ceil() as u64; if total_available_sat < total_target_sat + est_fee_sat { @@ -3751,39 +3742,29 @@ pub async fn outpoint_spent_txin( } } -fn generate_message_id(business_id: Uuid, msg_type: String, sub_type: Option) -> String { - match sub_type { - Some(sub_type) => { - format!("{business_id}_{msg_type}_{sub_type}") - } - None => format!("{business_id}_{msg_type}"), - } -} - -#[allow(clippy::too_many_arguments)] pub async fn upsert_message( storage_processor: &mut StorageProcessor<'_>, is_update: bool, - business_id: Uuid, - sub_type: Option, from_peer: String, actor: Actor, message_content: GOATMessageContent, weight: i64, lock_time: i64, -) -> Result<()> { +) -> Result { + let key = LocalMessageKey::from_content(actor.clone(), &message_content)?; + let business_id = key.business_id(); + let message_id = key.message_id(); + let msg_type = message_content.kind(); let message = GOATMessage::new(actor.clone(), message_content.clone()); - let msg_type = get_goat_message_content_type(&message_content); - let message_id = generate_message_id(business_id, msg_type.to_string().clone(), sub_type); if is_update || storage_processor.find_messages_by_id(&message_id).await?.is_none() { if let Some(cancel_msg_type) = match msg_type { - MessageType::AssertSent => Some(MessageType::WatchtowerChallengeInitSent), + MessageKind::AssertSent => Some(MessageKind::WatchtowerChallengeInitSent), _ => None, } { notify_to_cancel_proof_task(storage_processor, business_id, cancel_msg_type).await?; } - storage_processor + return storage_processor .upsert_message(Message { message_id, business_id, @@ -3795,23 +3776,26 @@ pub async fn upsert_message( lock_time_until: current_time_secs() + lock_time, state: MessageState::Pending.to_string(), message_version: 0, + attempt_count: 0, + abandon_count: 0, + last_error: None, created_at: 0, }) - .await?; + .await; } else { info!("{message_id} is already created for create action"); } - Ok(()) + Ok(false) } pub async fn notify_to_cancel_proof_task( storage_processor: &mut StorageProcessor<'_>, business_id: Uuid, - msg_type: MessageType, + msg_type: MessageKind, ) -> Result<()> { // AssertInitSent is removed; update related logic if needed; - if !matches!(msg_type, MessageType::WatchtowerChallengeInitSent) { + if !matches!(msg_type, MessageKind::WatchtowerChallengeInitSent) { warn!("notify_to_cancel_proof_task: input wrong message type:{msg_type}"); return Ok(()); } @@ -3831,7 +3815,7 @@ pub async fn notify_to_cancel_proof_task( storage_processor.find_message_by_business_id(&business_id, &msg_type.to_string()).await? && let Some(graph) = storage_processor.find_graph(&business_id).await? { - if MessageState::Pending.to_string() != message.state { + if !matches!(message.state.as_str(), "Pending" | "Processing") { warn!( "message {business_id}, msg_type: {msg_type} no need to cancel.as state is {}", message.state @@ -3842,7 +3826,7 @@ pub async fn notify_to_cancel_proof_task( // It will only be called a few times under limited conditions, so we just create a new object let http_client = HttpAsyncClient::new(None); let notify_result = match msg_type { - MessageType::WatchtowerChallengeInitSent => { + MessageKind::WatchtowerChallengeInitSent => { let url = host.join(PROOFS_WATCHTOWER_PROOF_TIMEOUT)?; let payload = WatchtowerProofTimeoutUpdateRequest { instance_id: graph.instance_id.to_string(), @@ -3873,12 +3857,7 @@ pub async fn notify_to_cancel_proof_task( if notify_result { // cancel unfinished p2p message; when notify success! storage_processor - .update_messages_state_by_business_id( - &business_id, - Some(msg_type.to_string()), - MessageState::Pending.to_string(), - MessageState::Cancelled.to_string(), - ) + .cancel_messages_by_business_id(&business_id, Some(msg_type.to_string())) .await?; } } else { @@ -4096,7 +4075,7 @@ pub async fn save_node_info(local_db: &LocalDB, node_info: &NodeInfo) -> Result< info!("save_node_info for {}", node_info.peer_id); let current_time = SystemTime::now().duration_since(UNIX_EPOCH).unwrap().as_secs() as i64; let mut storage_process = local_db.acquire().await?; - let _ = storage_process + storage_process .upsert_node(&Node { peer_id: node_info.peer_id.clone(), actor: node_info.actor.clone(), @@ -4110,7 +4089,7 @@ pub async fn save_node_info(local_db: &LocalDB, node_info: &NodeInfo) -> Result< updated_at: current_time, created_at: current_time, }) - .await; + .await?; Ok(()) } @@ -4230,29 +4209,27 @@ pub fn reflect_goat_address(addr_op: Option) -> (bool, Option) { (false, None) } -pub async fn pop_batch_local_unhandle_msg( +/// Sweep the local queue and list the messages the dispatcher may attempt now. +/// +/// Returns `(candidates, quarantined)`. Nothing returned here is claimed yet: +/// the dispatcher claims each row immediately before dispatching it, so a +/// crash mid-dispatch is charged to that one row rather than to the whole +/// batch. Expired rows are retired and exhausted rows quarantined first. +pub async fn list_batch_local_msg( local_db: &LocalDB, - _actor: Actor, - lock_time_until: i64, - offset: i64, + max_abandons: i64, limit: i64, -) -> Result> { +) -> Result<(Vec, u64)> { let mut tx = local_db.start_transaction().await?; let current_time = SystemTime::now().duration_since(UNIX_EPOCH).unwrap().as_secs() as i64; - tx.set_messages_expired(current_time - MESSAGE_EXPIRE_TIME).await?; - tx.delete_old_messages(current_time - MESSAGE_EXPIRE_TIME).await?; - let messages = tx - .filter_messages( - MessageState::Pending.to_string(), - 0, - lock_time_until, - current_time - MESSAGE_EXPIRE_TIME, - limit, - offset, - ) - .await?; + let expired_before = current_time - MESSAGE_EXPIRE_TIME; + tx.set_messages_expired(expired_before).await?; + tx.delete_old_messages(expired_before).await?; + let quarantined = tx.quarantine_local_messages(current_time, max_abandons).await?; + let messages = + tx.list_claimable_local_messages(current_time, expired_before, limit, max_abandons).await?; tx.commit().await?; - Ok(messages) + Ok((messages, quarantined)) } pub async fn operator_scan_ready_proof( @@ -4499,15 +4476,19 @@ pub async fn get_instance_parameters( instance_id: Uuid, ) -> Result> { let mut storage_processor = local_db.acquire().await?; - if let Some(instance) = storage_processor.find_instance(&instance_id).await? { - Ok(if let Some(parameters) = instance.parameters { - Some(serde_json::from_str(¶meters)?) - } else { - gen_instance_parameters_local(&instance).ok() - }) - } else { - Ok(None) + let Some(instance) = storage_processor.find_instance(&instance_id).await? else { + return Ok(None); + }; + + if let Some(parameters) = instance.parameters { + return Ok(Some(serde_json::from_str(¶meters)?)); } + + Ok(Some( + gen_instance_parameters_local(&instance).with_context(|| { + format!("failed to reconstruct parameters for instance {instance_id}") + })?, + )) } fn convert_graph( @@ -5852,14 +5833,7 @@ pub(crate) async fn obsolete_graph( // `None` means no message-type filter: cancel every durable pending message // for this terminal graph so stale retries cannot consume queue capacity or // trigger a later graph action. - storage_processor - .update_messages_state_by_business_id( - &graph_id, - None, - MessageState::Pending.to_string(), - MessageState::Cancelled.to_string(), - ) - .await?; + storage_processor.cancel_messages_by_business_id(&graph_id, None).await?; Ok(true) } @@ -5903,8 +5877,15 @@ pub fn gen_instance_parameters_local( let committee_pubkeys: Vec = instance .committees_answers .iter() - .map(|(_k, v)| PublicKey::from_slice(v).unwrap()) - .collect(); + .map(|(committee, pubkey)| { + PublicKey::from_slice(pubkey).with_context(|| { + format!( + "invalid committee public key for committee {committee} in instance {}", + instance.instance_id + ) + }) + }) + .collect::>()?; let committee_agg_pubkey = generate_n_of_n_public_key(&committee_pubkeys).0; let utxos: Vec = serde_json::from_str(&instance.input_utxos)?; @@ -6033,7 +6014,12 @@ pub async fn get_largest_watchtower_challenge_block( if let Some(block_height) = tx_status.block_height { if block_height > largest_watchtower_challenge_block_height { largest_watchtower_challenge_block_height = block_height; - largest_watchtower_challenge_block_hash = tx_status.block_hash.unwrap(); + largest_watchtower_challenge_block_hash = tx_status.block_hash.ok_or_else(|| { + anyhow!( + "Watchtower challenge tx {txid} for graph {}, index: {watchtower_index} is confirmed at height {block_height} without a block hash", + graph.parameters.graph_id + ) + })?; } } else { anyhow::bail!( diff --git a/node/tla/MessageStateRace.cfg b/node/tla/MessageStateRace.cfg index 13a129bf..17e5d6ae 100644 --- a/node/tla/MessageStateRace.cfg +++ b/node/tla/MessageStateRace.cfg @@ -1,5 +1,5 @@ -\* Models the CURRENT, actual code (upsert_message resurrects unconditionally) -\* - expected to FAIL. This is a live bug, not a historical artifact. +\* Historical pre-fix behavior: an unconditional upsert can resurrect a +\* Cancelled row. This config must continue to produce a counterexample. SPECIFICATION FairSpec CHECK_DEADLOCK FALSE INVARIANT TypeOK diff --git a/node/tla/MessageStateRace.tla b/node/tla/MessageStateRace.tla index 9ab76eab..b8bf3dfd 100644 --- a/node/tla/MessageStateRace.tla +++ b/node/tla/MessageStateRace.tla @@ -1,78 +1,100 @@ ---- MODULE MessageStateRace ---- (***************************************************************************) -(* Formal model of a race found while auditing every remaining stateful *) -(* enum after GraphStatus/InstanceBridgeInStatus (see audit/TLAPlus-*.md). *) +(* Model the local-message cancellation race, including a worker which has *) +(* already claimed a Pending row. The current Rust implementation uses *) +(* state/version CAS operations for claim completion and owner defer, and *) +(* cancel_messages_by_business_id reaches both Pending and Processing. *) (* *) -(* `MessageState` (crates/store/src/schema.rs:431-437: Pending, Processed, *) -(* Failed, Expired, Cancelled) tracks P2P message delivery/processing *) -(* status. Unlike the GraphStatus/InstanceBridgeOutStatus findings, the *) -(* "cancel" writer here IS correctly guarded - `update_messages_state_by_ *) -(* business_id` (crates/store/src/localdb.rs) does a real CAS: `UPDATE ... *) -(* WHERE business_id=? AND state='Pending'`, called from *) -(* node/src/scheduled_tasks/event_watch_task.rs's handle_withdraw_paths_/ *) -(* disproved_events when a graph reaches a closed on-chain status *) -(* (OperatorTake1/OperatorTake2/Disprove) - bulk-cancelling any still- *) -(* Pending message for that graph as moot. *) -(* *) -(* The bug is on the OTHER side: `upsert_message` (node/src/utils.rs, *) -(* called by push_local_unhandled_messages - the generic "defer/retry *) -(* this p2p message" primitive used ~30 times across node/src/handle.rs) *) -(* with `is_update=true` unconditionally sets state back to Pending via *) -(* `INSERT ... ON CONFLICT(message_id) DO UPDATE SET state=excluded.state` *) -(* - no WHERE clause is possible on an upsert, so a message the system *) -(* just administratively marked Cancelled (because its graph is already *) -(* finalized) can be silently resurrected to Pending and re-dispatched *) -(* the next time a handler in the swarm-message task calls a retry/defer *) -(* on it, unrelated to the cancellation. *) +(* FairSpec retains the pre-fix unconditional upsert as a historical bug *) +(* reproduction. FairSpecFixed models the guarded upsert now implemented *) +(* by crates/store/src/localdb.rs. *) (***************************************************************************) -Statuses == {"Pending", "Cancelled"} -\* Cancelled is an administrative "this message is moot, stop touching it" -\* marker tied to its graph reaching a closed status - it must stay final. +Statuses == {"Pending", "Processing", "Processed", "Cancelled"} TerminalStatuses == {"Cancelled"} -VARIABLE status -vars == <> +VARIABLES status, workerActive +vars == <> -TypeOK == status \in Statuses +TypeOK == + /\ status \in Statuses + /\ workerActive \in BOOLEAN -Init == status = "Pending" +Init == + /\ status = "Pending" + /\ workerActive = FALSE --------------------------------------------------------------------------- -\* event_watch_task.rs's handle_withdraw_paths_events / handle_withdraw_ -\* disproved_events, via update_messages_state_by_business_id - a genuine -\* CAS, correctly guarded in the real code. -BulkCancelOnGraphClose == +----------------------------------------------------------------------------- +\* claim_local_messages: only an available Pending row can be claimed. +Claim == /\ status = "Pending" + /\ ~workerActive + /\ status' = "Processing" + /\ workerActive' = TRUE + +\* Terminal graph/instance handling cancels queued and already-claimed work. +BulkCancelOnGraphClose == + /\ status \in {"Pending", "Processing"} /\ status' = "Cancelled" + /\ UNCHANGED workerActive + +\* A live owner may complete or defer only the Processing row it claimed. +WorkerComplete == + /\ workerActive + /\ status = "Processing" + /\ status' = "Processed" + /\ workerActive' = FALSE + +OwnerDefer == + /\ workerActive + /\ status = "Processing" + /\ status' = "Pending" + /\ workerActive' = FALSE + +\* After cancellation, the old worker's guarded write affects zero rows. +StaleWorkerReturns == + /\ workerActive + /\ status # "Processing" + /\ UNCHANGED status + /\ workerActive' = FALSE + +\* Historical behavior: a periodic producer could resurrect any state. +UnconditionalUpsert == + /\ status' = "Pending" + /\ UNCHANGED workerActive -\* push_local_unhandled_messages -> utils::upsert_message(is_update=true) -\* -> store upsert_message's `ON CONFLICT DO UPDATE SET state=excluded.state` -\* - confirmed NO guard of any kind. Fires from ~30 call sites in -\* node/src/handle.rs whenever a message handler needs to defer/retry, -\* with no awareness of whether the message was since cancelled. -ResurrectPendingUnconditional == status' = "Pending" +\* Current behavior: Processing and terminal rows reject fallback upserts. +GuardedUpsert == + /\ status \notin {"Processing", "Cancelled"} + /\ status' = "Pending" + /\ UNCHANGED workerActive Next == + \/ Claim \/ BulkCancelOnGraphClose - \/ ResurrectPendingUnconditional + \/ WorkerComplete + \/ OwnerDefer + \/ StaleWorkerReturns + \/ UnconditionalUpsert Spec == Init /\ [][Next]_vars FairSpec == Spec /\ WF_vars(Next) -\* Proposed fix design (not applied to code): guard the resurrect-to-Pending -\* write the same way - only apply it if the message isn't already in a -\* terminal status, folded into the UPDATE/upsert's WHERE clause. NextFixed == + \/ Claim \/ BulkCancelOnGraphClose - \/ (status \notin TerminalStatuses /\ ResurrectPendingUnconditional) + \/ WorkerComplete + \/ OwnerDefer + \/ StaleWorkerReturns + \/ GuardedUpsert SpecFixed == Init /\ [][NextFixed]_vars FairSpecFixed == SpecFixed /\ WF_vars(NextFixed) --------------------------------------------------------------------------- -\* Safety property: once a message is administratively Cancelled, it must -\* never be resurrected and re-dispatched. -TerminalStatusesAreAbsorbing == [][(status \in TerminalStatuses => status' = status)]_status +----------------------------------------------------------------------------- +\* Once administratively cancelled, neither an old worker nor a producer may +\* make the message dispatchable again. +TerminalStatusesAreAbsorbing == + [][(status \in TerminalStatuses => status' = status)]_status ==== diff --git a/node/tla/MessageStateRaceFixed.cfg b/node/tla/MessageStateRaceFixed.cfg index ffdbda46..3661193d 100644 --- a/node/tla/MessageStateRaceFixed.cfg +++ b/node/tla/MessageStateRaceFixed.cfg @@ -1,4 +1,4 @@ -\* Proposed fix design (verified, NOT applied to code) - expected to pass. +\* Current behavior: claims, cancellation and worker writes are guarded. SPECIFICATION FairSpecFixed CHECK_DEADLOCK FALSE INVARIANT TypeOK