From d92e25ab5d434fc1961b40a5a599f7c24260b81f Mon Sep 17 00:00:00 2001 From: ethan Date: Fri, 7 Aug 2026 10:57:37 +0800 Subject: [PATCH 1/8] add blake3 compile-time check --- .cargo/config.toml | 2 + node/Cargo.toml | 3 ++ node/src/handle.rs | 13 +------ node/src/utils.rs | 54 ++++++++++++++++++++++++-- node/testdata/test-operator-proof.bin | Bin 0 -> 1498 bytes 5 files changed, 56 insertions(+), 16 deletions(-) create mode 100644 .cargo/config.toml create mode 100644 node/testdata/test-operator-proof.bin diff --git a/.cargo/config.toml b/.cargo/config.toml new file mode 100644 index 00000000..2f55f1cf --- /dev/null +++ b/.cargo/config.toml @@ -0,0 +1,2 @@ +[env] +ZKM_IMM_WRAP_VK = "1" diff --git a/node/Cargo.toml b/node/Cargo.toml index 74e81fc6..e34be8c1 100644 --- a/node/Cargo.toml +++ b/node/Cargo.toml @@ -134,3 +134,6 @@ header-chain = { workspace = true } state-chain = { workspace = true } verifier = { workspace = true } cbft-rpc = { workspace = true } + +[dev-dependencies] +blake3 = "=1.8.5" diff --git a/node/src/handle.rs b/node/src/handle.rs index 042029e9..8ec19e60 100644 --- a/node/src/handle.rs +++ b/node/src/handle.rs @@ -4843,18 +4843,7 @@ async fn handle_assert_ready_operator( let operator_master_key = OperatorMasterKey::new(get_bitvm_key()?); let assert_secret_key = operator_master_key.assert_wots_keypair_for_graph(graph_id).0; - if operator_proof.public_inputs.len() != 2 { - bail!( - "operator proof has {} public inputs; expected 2", - operator_proof.public_inputs.len() - ); - } - let dynamic_input = operator_proof.public_inputs.get(1).copied().ok_or_else(|| { - anyhow!( - "operator proof has {} public inputs; expected dynamic input at index 1", - operator_proof.public_inputs.len() - ) - })?; + let dynamic_input = operator_assert_dynamic_input(&operator_proof.public_inputs)?; let assert_witness = build_assert_witness(&operator_proof.proof, &assert_secret_key, dynamic_input)?; let assert_message = assert_wots_message(&assert_witness)?; diff --git a/node/src/utils.rs b/node/src/utils.rs index f064a3ce..55a34479 100644 --- a/node/src/utils.rs +++ b/node/src/utils.rs @@ -2585,6 +2585,22 @@ fn load_part_stark_vk_for_zkm_version(zkm_version: &str) -> Result> { Ok(Vec::from(zkm_verifier::Groth16Verifier::get_part_stark_vk(zkm_version))) } +fn convert_operator_proof_to_ark( + proof: &ZKMProofWithPublicValues, + vk_hash: &str, +) -> Result { + let part_stark_vk = load_part_stark_vk_for_zkm_version(&proof.zkm_version)?; + convert_ark_imm_wrap_vk(proof, vk_hash, &IMM_GROTH16_VK_BYTES, &part_stark_vk) + .map_err(|err| anyhow!("failed to convert operator proof to ark format: {err}")) +} + +pub fn operator_assert_dynamic_input(public_inputs: &[ark_bn254::Fr]) -> Result { + if public_inputs.len() != 2 { + bail!("operator proof has {} public inputs; expected 2", public_inputs.len()); + } + Ok(public_inputs[1]) +} + fn combined_operator_vk_hash(operator_vk_hash: &str, zkm_version: &str) -> Result<[u8; 32]> { if !operator_vk_hash.starts_with("0x") { bail!("configured operator vk hash must use 0x-prefixed Ziren encoding"); @@ -2758,10 +2774,7 @@ pub async fn get_operator_proof( bail!("operator proof constant does not match graph setup"); } - let part_stark_vk = load_part_stark_vk_for_zkm_version(&proof.zkm_version)?; - let ark_proof = - convert_ark_imm_wrap_vk(&proof, &proof_data.vk, &IMM_GROTH16_VK_BYTES, &part_stark_vk) - .map_err(|e| anyhow!("failed to convert operator proof to ark format: {e}"))?; + let ark_proof = convert_operator_proof_to_ark(&proof, &proof_data.vk)?; let Some(static_input) = ark_proof.public_inputs.first() else { bail!("operator proof has no public inputs"); }; @@ -6038,11 +6051,17 @@ pub struct OperatorBabeSetupState { #[cfg(test)] mod commit_pubin_tests { use super::*; + use ark_serialize::CanonicalSerialize; use bitcoin::BlockHash; use client::btc_chain::BTCClient; use esplora_client::{Tx, TxStatus, Vin}; use store::SerializableTxid; + const TEST_OPERATOR_PROOF_FIXTURE: &[u8] = + include_bytes!("../testdata/test-operator-proof.bin"); + const TEST_OPERATOR_PROOF_FIXTURE_VK: &str = + "0x00ba1ff974eb6e5890f238f8a11c1aeff2d5f4a68a860274bcb602c3c5c681b7"; + fn make_txid(byte: u8) -> Txid { Txid::from_slice(&[byte; 32]).unwrap() } @@ -6086,6 +6105,33 @@ mod commit_pubin_tests { } } + #[test] + fn assert_ready_extracts_blake3_xd_from_operator_proof() { + assert_eq!(TEST_OPERATOR_PROOF_FIXTURE.len(), 1_498); + let proof: ZKMProofWithPublicValues = + bincode::deserialize(TEST_OPERATOR_PROOF_FIXTURE).unwrap(); + + let ark_proof = + convert_operator_proof_to_ark(&proof, TEST_OPERATOR_PROOF_FIXTURE_VK).unwrap(); + let public_inputs: PublicInputs = ark_proof.public_inputs.into(); + let dynamic_input = operator_assert_dynamic_input(&public_inputs).unwrap(); + + let outputs = decode_operator_public_outputs(&proof.public_values.to_vec()).unwrap(); + let mut pubin = [0u8; 96]; + pubin[..32].copy_from_slice(&outputs.btc_best_block_hash); + pubin[32..64].copy_from_slice(&outputs.constant); + pubin[64..].copy_from_slice(&outputs.included_watchtowers); + + let mut expected_xd = *blake3::hash(&pubin).as_bytes(); + expected_xd[0] &= 0x1f; + let mut actual_xd = Vec::new(); + dynamic_input.serialize_uncompressed(&mut actual_xd).unwrap(); + // `pi1_xd_to_wots96_msg` serializes the field element most-significant byte first, + // whereas the public-input digest is defined in little-endian order. + actual_xd.reverse(); + assert_eq!(actual_xd, expected_xd); + } + #[tokio::test] async fn test_get_watchtower_challenge_info_partial_inclusion() { let (btc_client, mock_adaptor) = BTCClient::new_mock_client(); diff --git a/node/testdata/test-operator-proof.bin b/node/testdata/test-operator-proof.bin new file mode 100644 index 0000000000000000000000000000000000000000..9bbd6f73d4fc819d5c4787363e2e253bec25f373 GIT binary patch literal 1498 zcmeH{JFA~X5XS%UKne?yXi%FRwLC(c`=yh#2Fw>o%w9VY8yhP@FufoF(<(yH!dgFo zmoy=bSfub11m!d~&M~pHx5&cF^6u=;Jilj$Jvtl?SL-_)%IION6ljW`#2AhaAi<~x z;&7wz zL^hC2EHP0+0>$a@%wwH2A`ocrDowT~>!?FisS+Tj(u&>&jkR-HX==;aEw}Vi;}zc` z%VAg(8e15J(xYu?Z43D5PTB%F2GE#e`wpgp@;zrj|C2&fC*4auhQTBR&JtjlHB=-%UBo_F8Cj z(rDtD+M`vJCwM{AptbrO1~X_w@uHO@TS+oXRJk&{3S^OQFUm0@)z;v0W+kVy%7R^- zb+YbFW^v|_NmVhjYIht#Jqd`~z=<)v6-u>5fknqPm%?V=ytp8J=iXMn%87z`JwoQR@HD|I@S6IDk$12SPIJLp8r+x6W52_FTFGEir-TLhP z=ihkw;;UDG`2Nbx8xOzz?XC9OCvX1x#oMPJ9qi`gXX|k7Yx(Q<7jOUa<&W3DdFQJ? zp8M&&3zx3lX?GvIa`exR<9ioRU;pm-g>!%2KkkPs@1C4~{L=YLCm$T;&!2z#?A_bv Rp5*zj>HL$xhj^JT>))S+c)0)o literal 0 HcmV?d00001 From b7e871f24dc1eb4cee8054b0756986eb51722c0b Mon Sep 17 00:00:00 2001 From: ethan Date: Fri, 7 Aug 2026 12:51:11 +0800 Subject: [PATCH 2/8] update timelock verify logic --- crates/bitvm-gc/src/timelocks.rs | 163 +++++++++++++++++++++++-------- node/src/handle.rs | 6 +- 2 files changed, 124 insertions(+), 45 deletions(-) diff --git a/crates/bitvm-gc/src/timelocks.rs b/crates/bitvm-gc/src/timelocks.rs index 835ab487..72b930ac 100644 --- a/crates/bitvm-gc/src/timelocks.rs +++ b/crates/bitvm-gc/src/timelocks.rs @@ -19,13 +19,13 @@ pub const NODE_BITCOIN_TIMELOCK_CONFIG: TimelockConfig = TimelockConfig { }; pub const NODE_TESTNET_TIMELOCK_CONFIG: TimelockConfig = TimelockConfig { connector_z: 100, - connector_a: 16, - prover_connector: 20, - connector_d: 40, + connector_a: 6, + prover_connector: 16, + connector_d: 32, watchtower_challenge: 20, - operator_ack: 32, - operator_commit: 40, - connector_f: 52, + operator_ack: 28, + operator_commit: 42, + connector_f: 56, }; pub const NODE_SIGNET_TIMELOCK_CONFIG: TimelockConfig = TimelockConfig { connector_z: 6, @@ -66,20 +66,85 @@ pub fn estimated_block_interval_secs(network: Network) -> i64 { } } -const MIN_REACTION_SECS: i64 = 3600; +/// Non-serialized timing policy used to validate the on-chain timelock config. +/// +/// A graph commits to the CSV values, while every node applies this local network +/// policy before accepting those values. +#[derive(Clone, Copy, Debug, PartialEq, Eq)] +pub struct ProtocolTimingBudget { + /// Confirmation depth required before downstream Bitcoin evidence is used. + pub evidence_confirmations: u32, + /// Event discovery, P2P propagation, scheduling, and local signing. + pub reaction_blocks: u32, + /// P99 time for a watchtower to retrieve and prepare its proof commitment. + pub watchtower_proof_blocks: u32, + /// Target blocks for a transaction to be included, including fee bumping. + pub inclusion_blocks: u32, + /// Reorg and transient service failure allowance. + pub safety_blocks: u32, +} + +impl ProtocolTimingBudget { + const fn action_window(self) -> u32 { + self.reaction_blocks + .saturating_add(self.inclusion_blocks) + .saturating_add(self.safety_blocks) + } + + const fn watchtower_proof_window(self) -> u32 { + self.action_window().saturating_add(self.watchtower_proof_blocks) + } + + const fn confirmed_action_window(self) -> u32 { + self.evidence_confirmations + .saturating_add(self.inclusion_blocks) + .saturating_add(self.safety_blocks) + } +} + +const BITCOIN_TIMING_BUDGET: ProtocolTimingBudget = ProtocolTimingBudget { + evidence_confirmations: 6, + reaction_blocks: 6, + watchtower_proof_blocks: 24, + inclusion_blocks: 6, + safety_blocks: 6, +}; -fn min_reaction_blocks(network: Network) -> u32 { +const TESTNET_TIMING_BUDGET: ProtocolTimingBudget = ProtocolTimingBudget { + evidence_confirmations: 10, + reaction_blocks: 2, + watchtower_proof_blocks: 12, + inclusion_blocks: 2, + safety_blocks: 2, +}; + +const SIGNET_TIMING_BUDGET: ProtocolTimingBudget = ProtocolTimingBudget { + evidence_confirmations: 1, + reaction_blocks: 1, + watchtower_proof_blocks: 2, + inclusion_blocks: 1, + safety_blocks: 1, +}; + +const REGTEST_TIMING_BUDGET: ProtocolTimingBudget = ProtocolTimingBudget { + evidence_confirmations: 0, + reaction_blocks: 1, + watchtower_proof_blocks: 0, + inclusion_blocks: 0, + safety_blocks: 0, +}; + +pub fn protocol_timing_budget(network: Network) -> ProtocolTimingBudget { match network { - Network::Bitcoin | Network::Testnet | Network::Testnet4 => { - let interval = estimated_block_interval_secs(network); - ((MIN_REACTION_SECS + interval - 1) / interval) as u32 - } - Network::Signet | Network::Regtest => 1, + Network::Bitcoin => BITCOIN_TIMING_BUDGET, + Network::Testnet | Network::Testnet4 => TESTNET_TIMING_BUDGET, + Network::Signet => SIGNET_TIMING_BUDGET, + Network::Regtest => REGTEST_TIMING_BUDGET, } } pub fn validate_timelock_config(network: Network, config: &TimelockConfig) -> Result<()> { - let min_blocks = min_reaction_blocks(network); + let budget = protocol_timing_budget(network); for (name, value) in [ ("connector_z", config.connector_z), ("connector_a", config.connector_a), @@ -90,10 +155,10 @@ pub fn validate_timelock_config(network: Network, config: &TimelockConfig) -> Re ("operator_commit", config.operator_commit), ("connector_f", config.connector_f), ] { - if value < min_blocks { + if value < budget.reaction_blocks { bail!( - "timelock_config.{name} must be at least {min_blocks} blocks \ - (~{MIN_REACTION_SECS}s reaction window), got {value}" + "timelock_config.{name} must be at least {} reaction blocks, got {value}", + budget.reaction_blocks, ); } } @@ -105,52 +170,66 @@ pub fn validate_timelock_config(network: Network, config: &TimelockConfig) -> Re ); } - ensure_reaction_margin( - "prover_connector", - config.prover_connector, - "connector_d", - config.connector_d, - min_blocks, + let action_window = budget.action_window(); + ensure_at_least("connector_a", config.connector_a, action_window)?; + ensure_at_least( + "watchtower_challenge", + config.watchtower_challenge, + budget.watchtower_proof_window(), )?; - ensure_gt("connector_a", config.connector_a, "min_reaction_blocks", min_blocks)?; - ensure_lt( + ensure_gap_at_least( "watchtower_challenge", config.watchtower_challenge, "operator_ack", config.operator_ack, + action_window, + )?; + ensure_gap_at_least( + "max(watchtower_challenge, operator_ack)", + config.watchtower_challenge.max(config.operator_ack), + "operator_commit", + config.operator_commit, + budget.confirmed_action_window(), + )?; + ensure_at_least("prover_connector", config.prover_connector, action_window)?; + ensure_gap_at_least( + "prover_connector", + config.prover_connector, + "connector_d", + config.connector_d, + action_window, + )?; + ensure_gap_at_least( + "operator_commit", + config.operator_commit, + "connector_f", + config.connector_f, + budget.confirmed_action_window(), )?; - ensure_lt("operator_ack", config.operator_ack, "operator_commit", config.operator_commit)?; - ensure_lt("operator_commit", config.operator_commit, "connector_f", config.connector_f)?; Ok(()) } -fn ensure_reaction_margin( +fn ensure_gap_at_least( left_name: &str, left: u32, right_name: &str, right: u32, - min_margin: u32, + required_blocks: u32, ) -> Result<()> { - if left.saturating_add(min_margin) >= right { + let actual_blocks = right.saturating_sub(left); + if actual_blocks < required_blocks { bail!( - "timelock_config.{left_name} must be more than {min_margin} blocks less than \ - timelock_config.{right_name}" + "timelock_config.{right_name} - timelock_config.{left_name} must be at least \ + {required_blocks} blocks, got {actual_blocks}" ); } Ok(()) } -fn ensure_lt(left_name: &str, left: u32, right_name: &str, right: u32) -> Result<()> { - if left >= right { - bail!("timelock_config.{left_name} must be < timelock_config.{right_name}"); - } - Ok(()) -} - -fn ensure_gt(left_name: &str, left: u32, right_name: &str, right: u32) -> Result<()> { - if left <= right { - bail!("timelock_config.{left_name} must be > {right_name} ({right})"); +fn ensure_at_least(name: &str, value: u32, required_blocks: u32) -> Result<()> { + if value < required_blocks { + bail!("timelock_config.{name} must be at least {required_blocks} blocks, got {value}"); } Ok(()) } diff --git a/node/src/handle.rs b/node/src/handle.rs index 8ec19e60..31482260 100644 --- a/node/src/handle.rs +++ b/node/src/handle.rs @@ -5432,10 +5432,10 @@ async fn handle_wrongly_challenge_timeout_verifier( graph.parameters.instance_parameters.network, &graph.parameters.timelock_config, ) as u64; - let goat_confirmed_height = ctx.goat_client.btc_spv_latest_height().await?; - if goat_confirmed_height < disprove_height { + let bitcoin_height = ctx.btc_client.get_height().await? as u64; + if bitcoin_height < disprove_height { let retry_secs = todo_funcs::avg_block_time_secs(ctx.btc_client.network()) - * (disprove_height - goat_confirmed_height); + * (disprove_height - bitcoin_height); push_local_unhandled_messages(ctx.local_db, graph_id, &message, retry_secs as usize) .await?; tracing::info!( From 701e2f9b3e24780db4fad51d2760f1352709622c Mon Sep 17 00:00:00 2001 From: ethan Date: Fri, 7 Aug 2026 13:30:11 +0800 Subject: [PATCH 3/8] add debug api for graph --- ...60807130000_create_message_debug_table.sql | 9 + crates/store/src/localdb.rs | 170 ++++++++- crates/store/src/schema.rs | 24 ++ node/src/action.rs | 111 +++++- node/src/handle.rs | 349 +++++++++++++++--- .../src/rpc_service/handler/bitvm2_handler.rs | 6 + node/src/rpc_service/handler/debug_handler.rs | 187 ++++++++++ node/src/rpc_service/handler/mod.rs | 2 + node/src/rpc_service/mod.rs | 15 +- node/src/rpc_service/routes.rs | 10 + 10 files changed, 817 insertions(+), 66 deletions(-) create mode 100644 crates/store/migrations/20260807130000_create_message_debug_table.sql create mode 100644 node/src/rpc_service/handler/debug_handler.rs diff --git a/crates/store/migrations/20260807130000_create_message_debug_table.sql b/crates/store/migrations/20260807130000_create_message_debug_table.sql new file mode 100644 index 00000000..7c16af20 --- /dev/null +++ b/crates/store/migrations/20260807130000_create_message_debug_table.sql @@ -0,0 +1,9 @@ +CREATE TABLE IF NOT EXISTS message_debug_reason ( + message_id TEXT NOT NULL, + reason_code TEXT NOT NULL, + reason_detail TEXT NOT NULL, + first_seen_at BIGINT NOT NULL, + last_seen_at BIGINT NOT NULL, + occurrences BIGINT NOT NULL DEFAULT 1, + PRIMARY KEY (message_id, reason_code, reason_detail) +); diff --git a/crates/store/src/localdb.rs b/crates/store/src/localdb.rs index f0b6ef3a..0e7a3683 100644 --- a/crates/store/src/localdb.rs +++ b/crates/store/src/localdb.rs @@ -2,10 +2,10 @@ use crate::utils::{QueryBuilder, QueryParam, create_place_holders}; use crate::{ BridgeOutGlobalStats, EventWatchMetricsSnapshot, GoatTxRecord, Graph, GraphBtcTxVoutMonitor, GraphRawData, GraphStatus, GraphStatusSource, GraphStatusTransitionOutcome, Instance, - LongRunningTaskProof, Message, MetricsStateCount, Node, NodeAlertMetricsSnapshot, - NodesOverview, OperatorProof, PeginGraphProcessData, PeginInstanceProcessData, - PendingGraphInit, SequencerSetHashChange, SequencerSetScanState, SerializableTxid, - WatchContract, WatchtowerProof, + LongRunningTaskProof, Message, MessageDebugOverview, MessageDebugReason, MetricsStateCount, + Node, NodeAlertMetricsSnapshot, NodesOverview, OperatorProof, PeginGraphProcessData, + PeginInstanceProcessData, PendingGraphInit, SequencerSetHashChange, SequencerSetScanState, + SerializableTxid, WatchContract, WatchtowerProof, }; use indexmap::IndexMap; @@ -2421,6 +2421,120 @@ impl<'a> StorageProcessor<'a> { }) } + 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, + latest_reason.reason_detail AS last_reason_detail, + latest_reason.last_seen_at AS last_reason_seen_at + FROM message m + LEFT JOIN ( + SELECT message_id, COUNT(*) AS reason_count + FROM message_debug_reason + GROUP BY message_id + ) reason_counts ON reason_counts.message_id = m.message_id + LEFT JOIN message_debug_reason latest_reason + ON latest_reason.rowid = ( + SELECT rowid + FROM message_debug_reason + WHERE message_id = m.message_id + ORDER BY last_seen_at DESC, occurrences DESC, reason_code ASC + LIMIT 1 + ) + WHERE m.business_id = ? + ORDER BY m.updated_at DESC"#, + ) + .bind(business_id) + .fetch_all(self.conn()) + .await?) + } + + pub async fn find_message_debug_overview( + &mut self, + message_id: &str, + ) -> 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, + latest_reason.reason_detail AS last_reason_detail, + latest_reason.last_seen_at AS last_reason_seen_at + FROM message m + LEFT JOIN ( + SELECT message_id, COUNT(*) AS reason_count + FROM message_debug_reason + GROUP BY message_id + ) reason_counts ON reason_counts.message_id = m.message_id + LEFT JOIN message_debug_reason latest_reason + ON latest_reason.rowid = ( + SELECT rowid + FROM message_debug_reason + WHERE message_id = m.message_id + ORDER BY last_seen_at DESC, occurrences DESC, reason_code ASC + LIMIT 1 + ) + WHERE m.message_id = ?"#, + ) + .bind(message_id) + .fetch_optional(self.conn()) + .await?) + } + + pub async fn find_message_debug_reasons( + &mut self, + message_id: &str, + ) -> anyhow::Result> { + Ok(sqlx::query_as::<_, MessageDebugReason>( + "SELECT reason_code, reason_detail, first_seen_at, last_seen_at, occurrences \ + FROM message_debug_reason WHERE message_id = ? \ + ORDER BY last_seen_at DESC, reason_code ASC", + ) + .bind(message_id) + .fetch_all(self.conn()) + .await?) + } + + pub async fn upsert_message_debug_reason( + &mut self, + message_id: &str, + reason_code: &str, + reason_detail: &str, + ) -> anyhow::Result<()> { + let now = get_current_timestamp_secs(); + sqlx::query( + "INSERT INTO message_debug_reason \ + (message_id, reason_code, reason_detail, first_seen_at, last_seen_at, occurrences) \ + VALUES (?, ?, ?, ?, ?, 1) \ + ON CONFLICT(message_id, reason_code, reason_detail) DO UPDATE SET \ + last_seen_at = excluded.last_seen_at, \ + occurrences = message_debug_reason.occurrences + 1", + ) + .bind(message_id) + .bind(reason_code) + .bind(reason_detail.chars().take(512).collect::()) + .bind(now) + .bind(now) + .execute(self.conn()) + .await?; + Ok(()) + } + pub async fn upsert_message(&mut self, msg: Message) -> anyhow::Result { let current_time = get_current_timestamp_secs(); let res = sqlx::query( @@ -3710,6 +3824,54 @@ mod tests { ); } + #[tokio::test] + async fn test_message_debug_reasons_are_deduplicated() { + 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'00', 'Pending', 30, 10, 20)", + ) + .bind("message-debug-1") + .bind(business_id) + .execute(s.conn()) + .await + .unwrap(); + + for _ in 0..2 { + s.upsert_message_debug_reason( + "message-debug-1", + "operator_proof_pending", + "operator proof is not ready", + ) + .await + .unwrap(); + } + s.upsert_message_debug_reason( + "message-debug-1", + "handler_error", + "proof RPC request timed out", + ) + .await + .unwrap(); + + let messages = s.find_message_debug_overviews(&business_id).await.unwrap(); + assert_eq!(messages.len(), 1); + assert_eq!(messages[0].reason_count, 2); + + let reasons = s.find_message_debug_reasons("message-debug-1").await.unwrap(); + assert_eq!(reasons.len(), 2); + assert!(reasons.iter().any(|reason| { + reason.reason_code == "operator_proof_pending" && reason.occurrences == 2 + })); + assert!( + reasons + .iter() + .any(|reason| reason.reason_code == "handler_error" && reason.occurrences == 1) + ); + } + #[tokio::test] async fn test_proof_metrics_state_counts() { let db = setup_db().await; diff --git a/crates/store/src/schema.rs b/crates/store/src/schema.rs index f9d990c5..11f4697d 100644 --- a/crates/store/src/schema.rs +++ b/crates/store/src/schema.rs @@ -524,6 +524,30 @@ pub struct Message { pub created_at: i64, } +#[derive(Clone, Debug, FromRow)] +pub struct MessageDebugOverview { + pub message_id: String, + pub actor: String, + pub msg_type: String, + pub state: String, + pub lock_time_until: i64, + pub created_at: i64, + pub updated_at: i64, + pub reason_count: i64, + pub last_reason_code: Option, + pub last_reason_detail: Option, + pub last_reason_seen_at: Option, +} + +#[derive(Clone, Debug, FromRow)] +pub struct MessageDebugReason { + pub reason_code: String, + pub reason_detail: String, + pub first_seen_at: i64, + pub last_seen_at: i64, + pub occurrences: i64, +} + #[derive(Clone, Debug, FromRow, PartialEq, Eq)] pub struct MetricsStateCount { pub category: String, diff --git a/node/src/action.rs b/node/src/action.rs index 9bf50fab..630986b7 100644 --- a/node/src/action.rs +++ b/node/src/action.rs @@ -38,6 +38,47 @@ pub struct GOATMessage { const GOAT_MESSAGE_BIN_PREFIX: &[u8] = b"GOATBIN1"; const TRANSIENT_PEGIN_RETRY_DELAY_SECS: usize = 30; +#[derive(Clone, Copy, Debug)] +pub enum MessageDeferReason { + RetryScheduled, + PreviousGraphPending, + CommitteeNoncesPending, + CommitteeEndorsementsPending, + BitcoinTransactionPending, + BitcoinConfirmationPending, + GoatSpvPending, + ProofPending, + ProtocolInputsPending, + TimelockPending, + WithdrawKickoffPending, + ChainStatePending, + ValidationRetry, + GraphSyncPending, + HandlerError, +} + +impl MessageDeferReason { + pub const fn code(self) -> &'static str { + match self { + Self::RetryScheduled => "retry_scheduled", + Self::PreviousGraphPending => "previous_graph_pending", + Self::CommitteeNoncesPending => "committee_nonces_pending", + Self::CommitteeEndorsementsPending => "committee_endorsements_pending", + Self::BitcoinTransactionPending => "bitcoin_transaction_pending", + Self::BitcoinConfirmationPending => "bitcoin_confirmation_pending", + Self::GoatSpvPending => "goat_spv_pending", + Self::ProofPending => "proof_pending", + Self::ProtocolInputsPending => "protocol_inputs_pending", + Self::TimelockPending => "timelock_pending", + Self::WithdrawKickoffPending => "withdraw_kickoff_pending", + Self::ChainStatePending => "chain_state_pending", + Self::ValidationRetry => "validation_retry", + Self::GraphSyncPending => "graph_sync_pending", + Self::HandlerError => "handler_error", + } + } +} + #[derive(Serialize, Deserialize, Clone)] pub enum GOATMessageContent { PeginRequest(PeginRequest), @@ -598,6 +639,22 @@ pub async fn handle_self_p2p_msg( "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, + MessageDeferReason::HandlerError.code(), + &err.to_string(), + ) + .await + { + tracing::warn!( + event = "local_message_queue", + outcome = "debug_reason_store_failed", + queued_message_id = %message.message_id, + error = %reason_error, + "failed to persist local message debug reason" + ); + } storage_processor .update_messages_lock_time_until( &message.message_id, @@ -858,6 +915,25 @@ pub async fn push_local_unhandled_messages( business_id: Uuid, message: &GOATMessage, delay_secs: usize, +) -> Result<()> { + push_local_unhandled_messages_with_reason( + local_db, + business_id, + message, + delay_secs, + MessageDeferReason::RetryScheduled, + "retry scheduled without a more specific reason", + ) + .await +} + +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 actor = message.actor.clone(); @@ -874,6 +950,30 @@ pub async fn push_local_unhandled_messages( delay_secs as i64, ) .await?; + let persist_result = match storage_processor + .find_message_by_business_id(&business_id, message.content.event_type()) + .await + { + Ok(Some(queued_message)) => { + storage_processor + .upsert_message_debug_reason( + &queued_message.message_id, + reason.code(), + reason_detail, + ) + .await + } + Ok(None) => Ok(()), + Err(error) => Err(error), + }; + if let Err(error) = persist_result { + tracing::warn!( + event = "local_message_queue", + outcome = "debug_reason_store_failed", + error = %error, + "failed to persist local message defer reason" + ); + } if delay_secs > 0 && let Some(metrics_state) = crate::metrics_service::node_metrics_state() { @@ -913,8 +1013,15 @@ pub(crate) async fn get_graph_or_defer( "submitted" }; let delay_secs: usize = 60; // 1 min default retry - if let Err(error) = - push_local_unhandled_messages(local_db, graph_id, message, delay_secs).await + if let Err(error) = push_local_unhandled_messages_with_reason( + local_db, + graph_id, + message, + delay_secs, + MessageDeferReason::GraphSyncPending, + "graph is missing locally; requested SyncGraph from a relayer", + ) + .await { tracing::error!( event = "graph_resolution", diff --git a/node/src/handle.rs b/node/src/handle.rs index 31482260..421414b7 100644 --- a/node/src/handle.rs +++ b/node/src/handle.rs @@ -1236,7 +1236,15 @@ async fn defer_confirm_instance_until_previous_graph_presigned( let Some((previous_instance_id, previous_graph_id)) = get_graph_id_by_nonce(ctx.local_db, previous_nonce, operator_pubkey).await? else { - push_local_unhandled_messages(ctx.local_db, instance_id, &retry_message, 60).await?; + push_local_unhandled_messages_with_reason( + ctx.local_db, + instance_id, + &retry_message, + 60, + MessageDeferReason::PreviousGraphPending, + "previous graph nonce is not available locally", + ) + .await?; tracing::warn!( "Defer ConfirmInstance for {instance_id}: previous graph with nonce {previous_nonce} is not available locally" ); @@ -1257,7 +1265,15 @@ async fn defer_confirm_instance_until_previous_graph_presigned( "Failed to send SyncGraphRequest for previous graph {previous_instance_id}:{previous_graph_id}: {error}" ); } - push_local_unhandled_messages(ctx.local_db, instance_id, &retry_message, 60).await?; + push_local_unhandled_messages_with_reason( + ctx.local_db, + instance_id, + &retry_message, + 60, + MessageDeferReason::PreviousGraphPending, + "previous graph definition is not available locally", + ) + .await?; tracing::info!( "Defer ConfirmInstance for {instance_id}: waiting for previous graph raw data {previous_instance_id}:{previous_graph_id}" ); @@ -1267,7 +1283,15 @@ async fn defer_confirm_instance_until_previous_graph_presigned( return Ok(false); } - push_local_unhandled_messages(ctx.local_db, instance_id, &retry_message, 60).await?; + push_local_unhandled_messages_with_reason( + ctx.local_db, + instance_id, + &retry_message, + 60, + MessageDeferReason::PreviousGraphPending, + "previous graph is waiting for committee pre-signatures", + ) + .await?; let message_content = GOATMessageContent::CreateGraph(CreateGraph { instance_id: previous_instance_id, graph_id: previous_graph_id, @@ -2458,7 +2482,15 @@ async fn handle_create_graph_committee( ); } let message = make_message(ctx, content); - push_local_unhandled_messages(ctx.local_db, graph_id, &message, 60).await?; + push_local_unhandled_messages_with_reason( + ctx.local_db, + graph_id, + &message, + 60, + MessageDeferReason::PreviousGraphPending, + "previous graph definition is not available locally", + ) + .await?; tracing::info!( "Defer CreateGraph for {instance_id}:{graph_id}: waiting for previous graph raw data {previous_instance_id}:{previous_graph_id}" ); @@ -2466,7 +2498,15 @@ async fn handle_create_graph_committee( }; if !previous_graph.committee_pre_signed() { let message = make_message(ctx, content); - push_local_unhandled_messages(ctx.local_db, graph_id, &message, 60).await?; + push_local_unhandled_messages_with_reason( + ctx.local_db, + graph_id, + &message, + 60, + MessageDeferReason::PreviousGraphPending, + "previous graph is waiting for committee pre-signatures", + ) + .await?; tracing::info!( "Defer CreateGraph for {instance_id}:{graph_id}: waiting for previous graph {previous_instance_id}:{previous_graph_id} to be committee pre-signed" ); @@ -2475,7 +2515,15 @@ async fn handle_create_graph_committee( } None => { let message = make_message(ctx, content); - push_local_unhandled_messages(ctx.local_db, graph_id, &message, 60).await?; + push_local_unhandled_messages_with_reason( + ctx.local_db, + graph_id, + &message, + 60, + MessageDeferReason::PreviousGraphPending, + "previous graph nonce is not available locally", + ) + .await?; tracing::info!( "Defer CreateGraph for {instance_id}:{graph_id}: previous graph with nonce {previous_nonce} is not available locally" ); @@ -2842,7 +2890,15 @@ async fn validate_committee_presign_for_graph( let pub_nonces_unchecked = get_committee_pub_nonces_for_graph(ctx.local_db, instance_id, graph_id).await?; if pub_nonces_unchecked.len() != committee_pubkeys.len() { - push_local_unhandled_messages(ctx.local_db, graph_id, &message, 30).await?; + push_local_unhandled_messages_with_reason( + ctx.local_db, + graph_id, + &message, + 30, + MessageDeferReason::CommitteeNoncesPending, + "waiting for committee public nonces", + ) + .await?; tracing::info!( "Defer CommitteePresign for {instance_id}:{graph_id}: waiting for committee pub nonces" ); @@ -3489,7 +3545,15 @@ async fn handle_pegin_confirm_partial_sig_committee( let pub_nonces_unchecked = get_committee_pub_nonces_for_instance(ctx.local_db, instance_id).await?; if pub_nonces_unchecked.len() != committee_pubkeys.len() { - push_local_unhandled_messages(ctx.local_db, instance_id, &message, 30).await?; + push_local_unhandled_messages_with_reason( + ctx.local_db, + instance_id, + &message, + 30, + MessageDeferReason::CommitteeNoncesPending, + "waiting for committee public nonces", + ) + .await?; tracing::info!( "Defer PeginConfirmPartialSig for {instance_id}: waiting for committee pub nonces" ); @@ -3561,7 +3625,15 @@ async fn handle_pegin_confirm_partial_sig_committee( return Ok(()); } Err(e) => { - push_local_unhandled_messages(ctx.local_db, instance_id, &message, 30).await?; + push_local_unhandled_messages_with_reason( + ctx.local_db, + instance_id, + &message, + 30, + MessageDeferReason::ValidationRetry, + &format!("failed to verify committee endorsement signature: {e}"), + ) + .await?; tracing::warn!( "Retry PeginConfirmPartialSig later for {instance_id} from {}: failed to verify endorsement signature: {e}", received_committee_pubkey @@ -3649,11 +3721,13 @@ async fn handle_post_ready(ctx: &mut HandlerContext<'_>, instance_id: Uuid) -> R ctx.actor.clone(), GOATMessageContent::PostReady(PostReady { instance_id }), ); - push_local_unhandled_messages( + push_local_unhandled_messages_with_reason( ctx.local_db, instance_id, &message, delay_secs as usize, + MessageDeferReason::BitcoinTransactionPending, + "pegin-confirm transaction is not available from the Bitcoin backend", ) .await?; tracing::warn!( @@ -3673,8 +3747,15 @@ async fn handle_post_ready(ctx: &mut HandlerContext<'_>, instance_id: Uuid) -> R ctx.actor.clone(), GOATMessageContent::PostReady(PostReady { instance_id }), ); - push_local_unhandled_messages(ctx.local_db, instance_id, &message, delay_secs as usize) - .await?; + push_local_unhandled_messages_with_reason( + ctx.local_db, + instance_id, + &message, + delay_secs as usize, + MessageDeferReason::CommitteeEndorsementsPending, + "waiting for all committee endorsements of the pegin-confirm transaction", + ) + .await?; tracing::warn!( "Retry postPeginData later for {instance_id}: not enough endorse sigs for pegin confirm tx: {}", endorse_sigs.len() @@ -3689,11 +3770,13 @@ async fn handle_post_ready(ctx: &mut HandlerContext<'_>, instance_id: Uuid) -> R ctx.actor.clone(), GOATMessageContent::PostReady(PostReady { instance_id }), ); - push_local_unhandled_messages( + push_local_unhandled_messages_with_reason( ctx.local_db, instance_id, &message, delay_secs as usize, + MessageDeferReason::BitcoinConfirmationPending, + "pegin-confirm transaction is not confirmed on Bitcoin", ) .await?; tracing::info!( @@ -3710,8 +3793,15 @@ async fn handle_post_ready(ctx: &mut HandlerContext<'_>, instance_id: Uuid) -> R ctx.actor.clone(), GOATMessageContent::PostReady(PostReady { instance_id }), ); - push_local_unhandled_messages(ctx.local_db, instance_id, &message, delay_secs as usize) - .await?; + push_local_unhandled_messages_with_reason( + ctx.local_db, + instance_id, + &message, + delay_secs as usize, + MessageDeferReason::GoatSpvPending, + "pegin-confirm block is not available through GOAT SPV", + ) + .await?; tracing::info!( "Retry postPeginData later for {instance_id}: pegin confirm tx block not posted to goat spv contract yet" ); @@ -3764,8 +3854,15 @@ async fn handle_post_ready(ctx: &mut HandlerContext<'_>, instance_id: Uuid) -> R ctx.actor.clone(), GOATMessageContent::PostReady(PostReady { instance_id }), ); - push_local_unhandled_messages(ctx.local_db, instance_id, &message, delay_secs as usize) - .await?; + push_local_unhandled_messages_with_reason( + ctx.local_db, + instance_id, + &message, + delay_secs as usize, + MessageDeferReason::CommitteeEndorsementsPending, + "waiting for committee graph endorsements", + ) + .await?; tracing::info!( "Retry postGraphData later for {instance_id}: waiting for committee graph endorsements" ); @@ -3888,11 +3985,13 @@ async fn handle_kickoff_ready_operator( ) as u64 * todo_funcs::avg_block_time_secs(ctx.btc_client.network()); let delay_secs = min_pegout_time_secs * nonce_interval; - push_local_unhandled_messages( + push_local_unhandled_messages_with_reason( ctx.local_db, current_graph_id, &message, delay_secs as usize, + MessageDeferReason::PreviousGraphPending, + "previous graph has an active pegout flow", ) .await?; return Ok(()); @@ -3902,11 +4001,13 @@ async fn handle_kickoff_ready_operator( "Operator {operator_pubkey} skipped obsoleted graph {current_instance_id}:{current_graph_id}" ); let delay_secs = todo_funcs::avg_block_time_secs(ctx.btc_client.network()); // wait for 1 blocks - push_local_unhandled_messages( + push_local_unhandled_messages_with_reason( ctx.local_db, current_graph_id, &message, delay_secs as usize, + MessageDeferReason::ChainStatePending, + "waiting for the previous obsoleted graph skip transaction to propagate", ) .await?; return Ok(()); @@ -3925,11 +4026,13 @@ async fn handle_kickoff_ready_operator( ) as u64 * todo_funcs::avg_block_time_secs(ctx.btc_client.network()); let delay_secs = min_pegout_time_secs * nonce_interval; - push_local_unhandled_messages( + push_local_unhandled_messages_with_reason( ctx.local_db, current_graph_id, &message, delay_secs as usize, + MessageDeferReason::PreviousGraphPending, + "previous graph is available for pegout", ) .await?; return Ok(()); @@ -3939,11 +4042,13 @@ async fn handle_kickoff_ready_operator( "Operator {operator_pubkey} skipped non-posted graph {current_instance_id}:{current_graph_id}" ); let delay_secs = todo_funcs::avg_block_time_secs(ctx.btc_client.network()); // wait for 1 blocks - push_local_unhandled_messages( + push_local_unhandled_messages_with_reason( ctx.local_db, current_graph_id, &message, delay_secs as usize, + MessageDeferReason::ChainStatePending, + "waiting for the previous graph skip transaction to propagate", ) .await?; return Ok(()); @@ -3997,8 +4102,15 @@ async fn handle_kickoff_sent_committee( None => { let delay_secs = todo_funcs::avg_block_time_secs(ctx.btc_client.network()); let message = make_message(ctx, content); - push_local_unhandled_messages(ctx.local_db, graph_id, &message, delay_secs as usize) - .await?; + push_local_unhandled_messages_with_reason( + ctx.local_db, + graph_id, + &message, + delay_secs as usize, + MessageDeferReason::BitcoinConfirmationPending, + "kickoff transaction is not confirmed on Bitcoin", + ) + .await?; tracing::info!( "Retry proceedWithdraw later for {instance_id}:{graph_id}: kickoff tx not confirmed on btc yet" ); @@ -4010,8 +4122,15 @@ async fn handle_kickoff_sent_committee( let delay_secs = todo_funcs::avg_block_time_secs(ctx.btc_client.network()) * (kickoff_height - goat_confirmed_btc_height); let message = make_message(ctx, content); - push_local_unhandled_messages(ctx.local_db, graph_id, &message, delay_secs as usize) - .await?; + push_local_unhandled_messages_with_reason( + ctx.local_db, + graph_id, + &message, + delay_secs as usize, + MessageDeferReason::GoatSpvPending, + "kickoff block is not available through GOAT SPV", + ) + .await?; tracing::info!( "Retry proceedWithdraw later for {instance_id}:{graph_id}: kickoff tx block not posted to goat spv contract yet" ); @@ -4382,7 +4501,15 @@ async fn handle_watchtower_challenge_init_sent_watchtower( tracing::warn!( "Retry WatchtowerChallengeInitSent for {instance_id}:{graph_id} later: watchtower proof not ready, retry after {wait_secs} seconds" ); - push_local_unhandled_messages(ctx.local_db, graph_id, &message, wait_secs).await?; + push_local_unhandled_messages_with_reason( + ctx.local_db, + graph_id, + &message, + wait_secs, + MessageDeferReason::ProofPending, + "watchtower proof commitment is not ready", + ) + .await?; return Ok(()); } }; @@ -4693,7 +4820,15 @@ async fn handle_operator_commit_pubin_ready_operator( tracing::info!( "Retry OperatorCommitPubinReady later for {instance_id}:{graph_id}: challenge info is not ready: {e}" ); - push_local_unhandled_messages(ctx.local_db, graph_id, &message, wait_secs).await?; + push_local_unhandled_messages_with_reason( + ctx.local_db, + graph_id, + &message, + wait_secs, + MessageDeferReason::ProtocolInputsPending, + "watchtower challenge branches are not resolved yet", + ) + .await?; return Ok(()); } }; @@ -4710,7 +4845,15 @@ async fn handle_operator_commit_pubin_ready_operator( tracing::info!( "Retry OperatorCommitPubinReady later for {instance_id}:{graph_id}: operator pubin inputs are not ready: {e}" ); - push_local_unhandled_messages(ctx.local_db, graph_id, &message, wait_secs).await?; + push_local_unhandled_messages_with_reason( + ctx.local_db, + graph_id, + &message, + wait_secs, + MessageDeferReason::ProtocolInputsPending, + &e.to_string(), + ) + .await?; return Ok(()); } }; @@ -4833,7 +4976,15 @@ async fn handle_assert_ready_operator( tracing::info!( "Retry AssertReady later for {instance_id}:{graph_id}: operator proof is not ready" ); - push_local_unhandled_messages(ctx.local_db, graph_id, &message, wait_secs).await?; + push_local_unhandled_messages_with_reason( + ctx.local_db, + graph_id, + &message, + wait_secs, + MessageDeferReason::ProofPending, + "operator proof is not ready", + ) + .await?; return Ok(()); } @@ -5002,11 +5153,13 @@ async fn handle_assert_sent_verifier( Err(e) => { let delay_secs = todo_funcs::avg_block_time_secs(ctx.btc_client.network()); let message = make_message(ctx, content); - push_local_unhandled_messages( + push_local_unhandled_messages_with_reason( ctx.local_db, graph_id, &message, delay_secs as usize, + MessageDeferReason::ProtocolInputsPending, + &format!("operator ACK inputs are not ready: {e}"), ) .await?; tracing::info!( @@ -5059,11 +5212,13 @@ async fn handle_assert_sent_verifier( Err(e) => { let delay_secs = todo_funcs::avg_block_time_secs(ctx.btc_client.network()); let message = make_message(ctx, content); - push_local_unhandled_messages( + push_local_unhandled_messages_with_reason( ctx.local_db, graph_id, &message, delay_secs as usize, + MessageDeferReason::ValidationRetry, + &format!("PubinDisprove validation could not complete: {e}"), ) .await?; tracing::warn!( @@ -5237,8 +5392,15 @@ async fn handle_challenge_assert_sent_operator( let Some(challenge_assert_tx) = ctx.btc_client.get_tx(&challenge_assert_txid).await? else { let delay_secs = todo_funcs::avg_block_time_secs(ctx.btc_client.network()); let message = make_message(ctx, content); - push_local_unhandled_messages(ctx.local_db, graph_id, &message, delay_secs as usize) - .await?; + push_local_unhandled_messages_with_reason( + ctx.local_db, + graph_id, + &message, + delay_secs as usize, + MessageDeferReason::BitcoinTransactionPending, + "ChallengeAssert transaction is not available from the Bitcoin backend", + ) + .await?; tracing::info!( "Retry ChallengeAssertSent later for {instance_id}:{graph_id}: challenge assert tx {challenge_assert_txid} not found on chain" ); @@ -5402,8 +5564,15 @@ async fn handle_wrongly_challenge_timeout_verifier( let delay_secs = todo_funcs::avg_block_time_secs(ctx.btc_client.network()); let message = make_message(ctx, content); if ctx.btc_client.get_tx(&challenge_assert_txid).await?.is_none() { - push_local_unhandled_messages(ctx.local_db, graph_id, &message, delay_secs as usize) - .await?; + push_local_unhandled_messages_with_reason( + ctx.local_db, + graph_id, + &message, + delay_secs as usize, + MessageDeferReason::BitcoinTransactionPending, + "ChallengeAssert transaction is not available from the Bitcoin backend", + ) + .await?; tracing::info!( "Retry WronglyChallengeTimeout later for {instance_id}:{graph_id}: challenge assert tx {challenge_assert_txid} not found on chain" ); @@ -5418,8 +5587,15 @@ async fn handle_wrongly_challenge_timeout_verifier( { Some(height) => height as u64, None => { - push_local_unhandled_messages(ctx.local_db, graph_id, &message, delay_secs as usize) - .await?; + push_local_unhandled_messages_with_reason( + ctx.local_db, + graph_id, + &message, + delay_secs as usize, + MessageDeferReason::BitcoinConfirmationPending, + "ChallengeAssert transaction is not confirmed on Bitcoin", + ) + .await?; tracing::info!( "Retry WronglyChallengeTimeout later for {instance_id}:{graph_id}: challenge assert tx {challenge_assert_txid} is not confirmed" ); @@ -5436,8 +5612,15 @@ async fn handle_wrongly_challenge_timeout_verifier( if bitcoin_height < disprove_height { let retry_secs = todo_funcs::avg_block_time_secs(ctx.btc_client.network()) * (disprove_height - bitcoin_height); - push_local_unhandled_messages(ctx.local_db, graph_id, &message, retry_secs as usize) - .await?; + push_local_unhandled_messages_with_reason( + ctx.local_db, + graph_id, + &message, + retry_secs as usize, + MessageDeferReason::TimelockPending, + "disprove timelock has not expired", + ) + .await?; tracing::info!( "Retry WronglyChallengeTimeout later for {instance_id}:{graph_id}: disprove timelock has not expired" ); @@ -5530,8 +5713,15 @@ async fn handle_disprove_sent_committee( Some(height) => height as u64, None => { let delay_secs = todo_funcs::avg_block_time_secs(ctx.btc_client.network()); - push_local_unhandled_messages(ctx.local_db, graph_id, &message, delay_secs as usize) - .await?; + push_local_unhandled_messages_with_reason( + ctx.local_db, + graph_id, + &message, + delay_secs as usize, + MessageDeferReason::BitcoinConfirmationPending, + "challenge finish transaction is not confirmed on Bitcoin", + ) + .await?; tracing::info!( "Retry finishWithdrawDisproved later for {instance_id}:{graph_id}: challenge finish tx not confirmed on btc yet" ); @@ -5542,8 +5732,15 @@ async fn handle_disprove_sent_committee( if goat_confirmed_height < challenge_finish_height { let delay_secs = todo_funcs::avg_block_time_secs(ctx.btc_client.network()) * (challenge_finish_height - goat_confirmed_height); - push_local_unhandled_messages(ctx.local_db, graph_id, &message, delay_secs as usize) - .await?; + push_local_unhandled_messages_with_reason( + ctx.local_db, + graph_id, + &message, + delay_secs as usize, + MessageDeferReason::GoatSpvPending, + "challenge finish block is not available through GOAT SPV", + ) + .await?; tracing::info!( "Retry finishWithdrawDisproved later for {instance_id}:{graph_id}: challenge finish tx block not posted to goat spv contract yet" ); @@ -5683,8 +5880,15 @@ async fn handle_take1_sent_committee( if withdraw_status == WithdrawStatus::Initialized { // Kickoff not posted yet, wait for it let delay_secs = todo_funcs::avg_block_time_secs(ctx.btc_client.network()) * 6; // wait for 6 blocks - push_local_unhandled_messages(ctx.local_db, graph_id, &message, delay_secs as usize) - .await?; + push_local_unhandled_messages_with_reason( + ctx.local_db, + graph_id, + &message, + delay_secs as usize, + MessageDeferReason::WithdrawKickoffPending, + "withdraw is initialized but kickoff has not been posted", + ) + .await?; tracing::info!( "Retry finishWithdrawHappyPath later for {instance_id}:{graph_id} as kickoff not posted yet" ); @@ -5700,8 +5904,15 @@ async fn handle_take1_sent_committee( Some(height) => height as u64, None => { let delay_secs = todo_funcs::avg_block_time_secs(ctx.btc_client.network()); // wait for 1 block - push_local_unhandled_messages(ctx.local_db, graph_id, &message, delay_secs as usize) - .await?; + push_local_unhandled_messages_with_reason( + ctx.local_db, + graph_id, + &message, + delay_secs as usize, + MessageDeferReason::BitcoinConfirmationPending, + "take1 transaction is not confirmed on Bitcoin", + ) + .await?; tracing::info!( "Retry finishWithdrawHappyPath later for {instance_id}:{graph_id} as take1 tx not confirmed on btc yet" ); @@ -5712,8 +5923,15 @@ async fn handle_take1_sent_committee( if goat_confirmed_height < take1_height { let delay_secs = todo_funcs::avg_block_time_secs(ctx.btc_client.network()) * (take1_height - goat_confirmed_height); - push_local_unhandled_messages(ctx.local_db, graph_id, &message, delay_secs as usize) - .await?; + push_local_unhandled_messages_with_reason( + ctx.local_db, + graph_id, + &message, + delay_secs as usize, + MessageDeferReason::GoatSpvPending, + "take1 block is not available through GOAT SPV", + ) + .await?; tracing::info!( "Retry finishWithdrawHappyPath later for {instance_id}:{graph_id} as take1 tx block not posted to goat spv contract yet" ); @@ -5877,8 +6095,15 @@ async fn handle_take2_sent_committee( if withdraw_status == WithdrawStatus::Initialized { // Kickoff not posted yet, wait for it let delay_secs = todo_funcs::avg_block_time_secs(ctx.btc_client.network()) * 6; // wait for 6 blocks - push_local_unhandled_messages(ctx.local_db, graph_id, &message, delay_secs as usize) - .await?; + push_local_unhandled_messages_with_reason( + ctx.local_db, + graph_id, + &message, + delay_secs as usize, + MessageDeferReason::WithdrawKickoffPending, + "withdraw is initialized but kickoff has not been posted", + ) + .await?; tracing::info!( "Retry finishWithdrawUnhappyPath later for {instance_id}:{graph_id} as kickoff not posted yet" ); @@ -5894,8 +6119,15 @@ async fn handle_take2_sent_committee( Some(height) => height as u64, None => { let delay_secs = todo_funcs::avg_block_time_secs(ctx.btc_client.network()); // wait for 1 block - push_local_unhandled_messages(ctx.local_db, graph_id, &message, delay_secs as usize) - .await?; + push_local_unhandled_messages_with_reason( + ctx.local_db, + graph_id, + &message, + delay_secs as usize, + MessageDeferReason::BitcoinConfirmationPending, + "take2 transaction is not confirmed on Bitcoin", + ) + .await?; tracing::info!( "Retry finishWithdrawUnhappyPath later for {instance_id}:{graph_id} as take2 tx not confirmed on btc yet" ); @@ -5906,8 +6138,15 @@ async fn handle_take2_sent_committee( if goat_confirmed_height < take2_height { let delay_secs = todo_funcs::avg_block_time_secs(ctx.btc_client.network()) * (take2_height - goat_confirmed_height); - push_local_unhandled_messages(ctx.local_db, graph_id, &message, delay_secs as usize) - .await?; + push_local_unhandled_messages_with_reason( + ctx.local_db, + graph_id, + &message, + delay_secs as usize, + MessageDeferReason::GoatSpvPending, + "take2 block is not available through GOAT SPV", + ) + .await?; tracing::info!( "Retry finishWithdrawUnhappyPath later for {instance_id}:{graph_id} as take2 tx block not posted to goat spv contract yet" ); diff --git a/node/src/rpc_service/handler/bitvm2_handler.rs b/node/src/rpc_service/handler/bitvm2_handler.rs index 834964d7..8963dc17 100644 --- a/node/src/rpc_service/handler/bitvm2_handler.rs +++ b/node/src/rpc_service/handler/bitvm2_handler.rs @@ -147,6 +147,7 @@ pub async fn instance_settings( /// {} /// ``` #[axum::debug_handler] +// TODO(auth): Add caller authorization or rate limiting before exposing this write endpoint publicly. pub async fn bridge_in_request_tag( State(app_state): State>, Json(payload): Json, @@ -269,6 +270,7 @@ pub async fn bridge_in_request_tag( /// {} /// ``` #[axum::debug_handler] +// TODO(auth): Add caller authorization or rate limiting before exposing this write endpoint publicly. pub async fn bridge_out_init_tag( State(app_state): State>, Json(payload): Json, @@ -1571,6 +1573,7 @@ pub async fn get_graph_neighbor_ids( /// } /// ``` #[axum::debug_handler] +// TODO(auth): Require authorization before returning a locally constructed cancellation PSBT. pub async fn get_unsigned_pegin_txn( Path(instance_id): Path, State(app_state): State>, @@ -1628,6 +1631,7 @@ pub async fn send_challenge( Path(graph_id): Path, State(app_state): State>, ) -> ApiResult { + // TODO(auth): Replace shared node-key authentication with caller-scoped authorization. verify_request_auth(&headers)?; let graph_id_uuid = InputValidator::validate_uuid(&graph_id, "graph_id")?; @@ -1682,6 +1686,7 @@ pub async fn send_verifier_challenge( Path(graph_id): Path, State(app_state): State>, ) -> ApiResult { + // TODO(auth): Replace shared node-key authentication with caller-scoped authorization. verify_request_auth(&headers)?; let graph_id_uuid = InputValidator::validate_uuid(&graph_id, "graph_id")?; @@ -1795,6 +1800,7 @@ pub async fn pegout( State(app_state): State>, Json(payload): Json, ) -> ApiResult { + // TODO(auth): Replace shared node-key authentication with caller-scoped authorization. verify_request_auth(&headers)?; let operator_pubkey = get_node_pubkey().api_error("PEGOUT_ERROR")?.to_string(); let operator_goat_addr = get_node_goat_address() diff --git a/node/src/rpc_service/handler/debug_handler.rs b/node/src/rpc_service/handler/debug_handler.rs new file mode 100644 index 00000000..60abbe33 --- /dev/null +++ b/node/src/rpc_service/handler/debug_handler.rs @@ -0,0 +1,187 @@ +use crate::rpc_service::response::{ApiErrorExt, ApiResult, ErrorResponse, ok_response}; +use crate::rpc_service::validation::InputValidator; +use crate::rpc_service::{AppState, current_time_secs}; +use axum::Json; +use axum::extract::{Path, State}; +use http::StatusCode; +use serde::Serialize; +use std::sync::Arc; +use store::MessageDebugOverview; + +#[derive(Serialize)] +pub struct DebugStatusResponse { + pub checked_at: i64, + pub actor: String, + pub peer_id: String, + pub bitcoin_height: Option, + pub goat_height: Option, + pub goat_spv_height: Option, + pub message_queue: DebugMessageQueue, +} + +#[derive(Serialize)] +pub struct DebugMessageQueue { + pub pending_ready: i64, + pub pending_locked: i64, + pub failed: i64, + pub oldest_pending_at: Option, +} + +#[derive(Serialize)] +pub struct GraphDebugMessagesResponse { + pub graph_id: String, + pub messages: Vec, +} + +#[derive(Serialize)] +pub struct GraphDebugMessageOverview { + pub message_id: String, + pub actor: String, + pub message_type: String, + pub state: String, + pub lock_time_until: i64, + pub created_at: i64, + pub updated_at: i64, + pub reason_count: i64, + pub last_reason: Option, +} + +#[derive(Serialize)] +pub struct DebugMessageDetailsResponse { + pub message: GraphDebugMessageOverview, + pub reasons: Vec, +} + +#[derive(Serialize)] +pub struct GraphDebugReasonSummary { + pub code: String, + pub detail: String, + pub last_seen_at: i64, +} + +#[derive(Serialize)] +pub struct GraphDebugReason { + pub code: String, + pub detail: String, + pub first_seen_at: i64, + pub last_seen_at: i64, + pub occurrences: i64, +} + +fn graph_debug_message_overview(message: MessageDebugOverview) -> GraphDebugMessageOverview { + GraphDebugMessageOverview { + message_id: message.message_id, + actor: message.actor, + message_type: message.msg_type, + state: message.state, + lock_time_until: message.lock_time_until, + created_at: message.created_at, + updated_at: message.updated_at, + reason_count: message.reason_count, + last_reason: match ( + message.last_reason_code, + message.last_reason_detail, + message.last_reason_seen_at, + ) { + (Some(code), Some(detail), Some(last_seen_at)) => { + Some(GraphDebugReasonSummary { code, detail, last_seen_at }) + } + _ => None, + }, + } +} + +// TODO(auth): Require operator authentication before exposing local debug state. +#[axum::debug_handler] +pub async fn get_debug_status( + State(app_state): State>, +) -> ApiResult { + let checked_at = current_time_secs(); + let (bitcoin_height, goat_height, goat_spv_height) = tokio::join!( + app_state.btc_client.get_height(), + app_state.goat_client.get_latest_block_number(), + app_state.goat_client.btc_spv_latest_height(), + ); + let mut storage_processor = + app_state.local_db.acquire().await.api_error("GET_DEBUG_STATUS_ERROR")?; + let queue = storage_processor + .get_message_queue_stats(&app_state.actor.to_string(), checked_at) + .await + .api_error("GET_DEBUG_STATUS_ERROR")?; + + ok_response(DebugStatusResponse { + checked_at, + actor: app_state.actor.to_string(), + peer_id: app_state.peer_id.clone(), + bitcoin_height: bitcoin_height.ok(), + goat_height: goat_height.ok(), + goat_spv_height: goat_spv_height.ok(), + message_queue: DebugMessageQueue { + pending_ready: queue.pending_ready, + pending_locked: queue.pending_locked, + failed: queue.failed, + oldest_pending_at: queue.oldest_pending_at, + }, + }) +} + +// TODO(auth): Require operator authentication before exposing local debug state. +#[axum::debug_handler] +pub async fn get_graph_debug_messages( + Path(graph_id): Path, + State(app_state): State>, +) -> ApiResult { + let graph_id = InputValidator::validate_uuid(&graph_id, "graph_id")?; + let mut storage_processor = + app_state.local_db.acquire().await.api_error("GET_GRAPH_DEBUG_MESSAGES_ERROR")?; + let messages = storage_processor + .find_message_debug_overviews(&graph_id) + .await + .api_error("GET_GRAPH_DEBUG_MESSAGES_ERROR")? + .into_iter() + .map(graph_debug_message_overview) + .collect(); + + ok_response(GraphDebugMessagesResponse { graph_id: graph_id.to_string(), messages }) +} + +// TODO(auth): Require operator authentication before exposing local debug state. +#[axum::debug_handler] +pub async fn get_debug_message_details( + Path(message_id): Path, + State(app_state): State>, +) -> ApiResult { + let mut storage_processor = + app_state.local_db.acquire().await.api_error("GET_DEBUG_MESSAGE_DETAILS_ERROR")?; + let message = storage_processor + .find_message_debug_overview(&message_id) + .await + .api_error("GET_DEBUG_MESSAGE_DETAILS_ERROR")? + .ok_or_else(|| { + ( + StatusCode::NOT_FOUND, + Json(ErrorResponse { + error: "DEBUG_MESSAGE_NOT_FOUND".to_string(), + message: format!("message {message_id} not found"), + }), + ) + })?; + let reasons = storage_processor + .find_message_debug_reasons(&message_id) + .await + .api_error("GET_DEBUG_MESSAGE_DETAILS_ERROR")? + .into_iter() + .map(|reason| GraphDebugReason { + code: reason.reason_code, + detail: reason.reason_detail, + first_seen_at: reason.first_seen_at, + last_seen_at: reason.last_seen_at, + occurrences: reason.occurrences, + }) + .collect(); + + ok_response(DebugMessageDetailsResponse { + message: graph_debug_message_overview(message), + reasons, + }) +} diff --git a/node/src/rpc_service/handler/mod.rs b/node/src/rpc_service/handler/mod.rs index bce85d73..d951a7c6 100644 --- a/node/src/rpc_service/handler/mod.rs +++ b/node/src/rpc_service/handler/mod.rs @@ -1,8 +1,10 @@ pub mod bitvm2_handler; +pub mod debug_handler; pub mod node_handler; pub mod proof_handler; // Re-export all handler functions for better documentation visibility pub use bitvm2_handler::*; +pub use debug_handler::*; pub use node_handler::*; pub use proof_handler::*; diff --git a/node/src/rpc_service/mod.rs b/node/src/rpc_service/mod.rs index d920828b..0bba1f76 100644 --- a/node/src/rpc_service/mod.rs +++ b/node/src/rpc_service/mod.rs @@ -12,11 +12,12 @@ use crate::env::{get_btc_url_from_env, get_goat_network, get_network, goat_confi use crate::metrics_service::{MetricsState, metrics_handler, metrics_middleware}; use crate::rpc_service::cors_config::CorsConfig; use crate::rpc_service::handler::{ - bridge_in_request_tag, bridge_out_init_tag, get_chain_proof_desc, get_graph, - get_graph_neighbor_ids, get_graph_tx, get_graph_txn, get_graphs, get_instance, - get_instance_escrow_data, get_instances, get_instances_overview, get_node, get_nodes, - get_nodes_overview, get_operator_proof_desc, get_ready_to_kickoff_graph, - get_unsigned_pegin_txn, instance_settings, pegout, send_challenge, send_verifier_challenge, + bridge_in_request_tag, bridge_out_init_tag, get_chain_proof_desc, get_debug_message_details, + get_debug_status, get_graph, get_graph_debug_messages, get_graph_neighbor_ids, get_graph_tx, + get_graph_txn, get_graphs, get_instance, get_instance_escrow_data, get_instances, + get_instances_overview, get_node, get_nodes, get_nodes_overview, get_operator_proof_desc, + get_ready_to_kickoff_graph, get_unsigned_pegin_txn, instance_settings, pegout, send_challenge, + send_verifier_challenge, }; use anyhow::Context; use axum::body::Body; @@ -159,6 +160,10 @@ pub async fn serve_with_app_state( .route(routes::v1::GRAPHS_TXN_BY_ID, get(get_graph_txn)) .route(routes::v1::GRAPHS_TX_BY_ID, get(get_graph_tx)) .route(routes::v1::GRAPHS_NEIGHBOR_IDS, get(get_graph_neighbor_ids)) + // TODO(auth): Restrict debug endpoints before exposing the RPC outside trusted operators. + .route(routes::v1::DEBUG_STATUS, get(get_debug_status)) + .route(routes::v1::DEBUG_GRAPH_MESSAGES, get(get_graph_debug_messages)) + .route(routes::v1::DEBUG_MESSAGE_DETAILS, get(get_debug_message_details)) .route(routes::v1::GRAPHS_SEND_CHALLENGE, post(send_challenge)) .route(routes::v1::GRAPHS_SEND_VERIFIER_CHALLENGE, post(send_verifier_challenge)) .route(routes::v1::PEGOUT, post(pegout)) diff --git a/node/src/rpc_service/routes.rs b/node/src/rpc_service/routes.rs index 5b4b082b..80a97714 100644 --- a/node/src/rpc_service/routes.rs +++ b/node/src/rpc_service/routes.rs @@ -12,6 +12,7 @@ pub(crate) mod v1 { pub const INSTANCES_BRIDGE_OUT_INIT_TAG: &str = "/v1/instances/bridge-out-init-tag"; pub const INSTANCES_BY_ID: &str = "/v1/instances/{:id}"; pub const INSTANCES_OVERVIEW: &str = "/v1/instances/overview"; + // TODO(auth): Restrict access before returning locally constructed cancellation PSBTs. pub const INSTANCES_UNSIGNED_PEGIN_TXN: &str = "/v1/instances/{:id}/unsigned-pegin-txn"; pub const INSTANCES_ESCROW_DATA: &str = "/v1/instances/{:id}/escrow-data"; pub const GRAPHS_BASE: &str = "/v1/graphs"; @@ -20,9 +21,18 @@ 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"; + // TODO(auth): Restrict this transaction-broadcasting endpoint to authorized operators. pub const GRAPHS_SEND_CHALLENGE: &str = "/v1/graphs/{:id}/send-challenge"; + // TODO(auth): Restrict this test transaction-broadcasting endpoint to authorized operators. pub const GRAPHS_SEND_VERIFIER_CHALLENGE: &str = "/v1/graphs/{:id}/send-verifier-challenge"; + // TODO(auth): Restrict this transaction-broadcasting endpoint to authorized operators. pub const PEGOUT: &str = "/v1/graphs/pegout"; + // TODO(auth): Restrict debug endpoints before exposing the RPC outside trusted operators. + pub const DEBUG_STATUS: &str = "/v1/debug/status"; + // TODO(auth): Restrict debug endpoints before exposing the RPC outside trusted operators. + pub const DEBUG_GRAPH_MESSAGES: &str = "/v1/debug/graphs/{:id}/messages"; + // TODO(auth): Restrict debug endpoints before exposing the RPC outside trusted operators. + pub const DEBUG_MESSAGE_DETAILS: &str = "/v1/debug/messages/{:id}"; // pub const PROOFS_BASE: &str = "/v1/proofs"; pub const PROOFS_CHAIN_PROOFS_DESC: &str = "/v1/proofs/chain_proofs_desc"; pub const NODES_WATCHTOWER_BASE: &str = "/v1/proofs/watchtower_proofs"; From 2cc68248803c29102ca194749940591456bf018a Mon Sep 17 00:00:00 2001 From: ethan Date: Fri, 7 Aug 2026 13:51:08 +0800 Subject: [PATCH 4/8] add instance debug api & update graph debug api --- node/src/action.rs | 27 +--- node/src/bin/db_inject.rs | 18 +-- node/src/handle.rs | 8 +- node/src/rpc_service/handler/debug_handler.rs | 128 +++++++++++++++++- node/src/rpc_service/mod.rs | 9 +- node/src/rpc_service/routes.rs | 2 + .../instance_maintenance_tasks.rs | 24 +++- 7 files changed, 171 insertions(+), 45 deletions(-) diff --git a/node/src/action.rs b/node/src/action.rs index 630986b7..3630265a 100644 --- a/node/src/action.rs +++ b/node/src/action.rs @@ -40,7 +40,8 @@ const TRANSIENT_PEGIN_RETRY_DELAY_SECS: usize = 30; #[derive(Clone, Copy, Debug)] pub enum MessageDeferReason { - RetryScheduled, + TransientStorageRetry, + RecoveryRepublish, PreviousGraphPending, CommitteeNoncesPending, CommitteeEndorsementsPending, @@ -60,7 +61,8 @@ pub enum MessageDeferReason { impl MessageDeferReason { pub const fn code(self) -> &'static str { match self { - Self::RetryScheduled => "retry_scheduled", + Self::TransientStorageRetry => "transient_storage_retry", + Self::RecoveryRepublish => "recovery_republish", Self::PreviousGraphPending => "previous_graph_pending", Self::CommitteeNoncesPending => "committee_nonces_pending", Self::CommitteeEndorsementsPending => "committee_endorsements_pending", @@ -727,11 +729,13 @@ pub async fn recv_and_dispatch( let result = match handle_dispatch(&mut handler_ctx, message.content()).await { Err(error) if !is_local_queue_message && is_retryable_sqlite_error(&error) => { if let Some(business_id) = message.content.pegin_retry_business_id() { - match push_local_unhandled_messages( + match push_local_unhandled_messages_with_reason( local_db, business_id, &message, TRANSIENT_PEGIN_RETRY_DELAY_SECS, + MessageDeferReason::TransientStorageRetry, + &format!("transient SQLite failure: {error}"), ) .await { @@ -910,23 +914,6 @@ pub async fn send_to_peer( } } -pub async fn push_local_unhandled_messages( - local_db: &LocalDB, - business_id: Uuid, - message: &GOATMessage, - delay_secs: usize, -) -> Result<()> { - push_local_unhandled_messages_with_reason( - local_db, - business_id, - message, - delay_secs, - MessageDeferReason::RetryScheduled, - "retry scheduled without a more specific reason", - ) - .await -} - pub async fn push_local_unhandled_messages_with_reason( local_db: &LocalDB, business_id: Uuid, diff --git a/node/src/bin/db_inject.rs b/node/src/bin/db_inject.rs index 07abf24a..442fdca3 100644 --- a/node/src/bin/db_inject.rs +++ b/node/src/bin/db_inject.rs @@ -8,7 +8,7 @@ //! - --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 possible) +//! - --business-id (optional; inferred from content when unambiguous) //! //! Example: //! - cargo run -p bitvm-noded --bin update-db -- \ @@ -39,7 +39,7 @@ struct Args { #[arg(long, value_parser = parse_actor)] actor: Actor, - /// Business id used for message_id (graph_id or instance_id). If omitted, try to infer from content. + /// Business id used for message_id (graph_id or instance_id). If omitted, infer it when unambiguous. #[arg(long)] business_id: Option, @@ -80,10 +80,10 @@ 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.instance_id), - GOATMessageContent::GenCircuits(v) => Some(v.instance_id), - GOATMessageContent::CutCircuits(v) => Some(v.instance_id), - GOATMessageContent::SolderingProofReady(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::VerifierGraphParamsEndorsement(v) => Some(v.graph_id), GOATMessageContent::CreateGraph(v) => Some(v.graph_id), GOATMessageContent::NonceGeneration(v) => Some(v.graph_id), @@ -114,9 +114,9 @@ fn infer_business_id(content: &GOATMessageContent) -> Option { GOATMessageContent::Take2Sent(v) => Some(v.graph_id), GOATMessageContent::SyncGraphRequest(v) => Some(v.graph_id), GOATMessageContent::SyncGraph(v) => Some(v.graph_id), - GOATMessageContent::InstanceDiscarded(v) => { - v.graph_infos.first().map(|(graph_id, _, _)| *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, } diff --git a/node/src/handle.rs b/node/src/handle.rs index 421414b7..2d1e2d0c 100644 --- a/node/src/handle.rs +++ b/node/src/handle.rs @@ -3987,7 +3987,7 @@ async fn handle_kickoff_ready_operator( let delay_secs = min_pegout_time_secs * nonce_interval; push_local_unhandled_messages_with_reason( ctx.local_db, - current_graph_id, + graph_id, &message, delay_secs as usize, MessageDeferReason::PreviousGraphPending, @@ -4003,7 +4003,7 @@ async fn handle_kickoff_ready_operator( let delay_secs = todo_funcs::avg_block_time_secs(ctx.btc_client.network()); // wait for 1 blocks push_local_unhandled_messages_with_reason( ctx.local_db, - current_graph_id, + graph_id, &message, delay_secs as usize, MessageDeferReason::ChainStatePending, @@ -4028,7 +4028,7 @@ async fn handle_kickoff_ready_operator( let delay_secs = min_pegout_time_secs * nonce_interval; push_local_unhandled_messages_with_reason( ctx.local_db, - current_graph_id, + graph_id, &message, delay_secs as usize, MessageDeferReason::PreviousGraphPending, @@ -4044,7 +4044,7 @@ async fn handle_kickoff_ready_operator( let delay_secs = todo_funcs::avg_block_time_secs(ctx.btc_client.network()); // wait for 1 blocks push_local_unhandled_messages_with_reason( ctx.local_db, - current_graph_id, + graph_id, &message, delay_secs as usize, MessageDeferReason::ChainStatePending, diff --git a/node/src/rpc_service/handler/debug_handler.rs b/node/src/rpc_service/handler/debug_handler.rs index 60abbe33..8a246b9a 100644 --- a/node/src/rpc_service/handler/debug_handler.rs +++ b/node/src/rpc_service/handler/debug_handler.rs @@ -2,11 +2,11 @@ use crate::rpc_service::response::{ApiErrorExt, ApiResult, ErrorResponse, ok_res use crate::rpc_service::validation::InputValidator; use crate::rpc_service::{AppState, current_time_secs}; use axum::Json; -use axum::extract::{Path, State}; +use axum::extract::{Path, Query, State}; use http::StatusCode; -use serde::Serialize; +use serde::{Deserialize, Serialize}; use std::sync::Arc; -use store::MessageDebugOverview; +use store::{Graph, GraphStatus, MessageDebugOverview}; #[derive(Serialize)] pub struct DebugStatusResponse { @@ -30,6 +30,69 @@ pub struct DebugMessageQueue { #[derive(Serialize)] pub struct GraphDebugMessagesResponse { pub graph_id: String, + pub status: Option, + pub flow: String, + pub messages: Vec, +} + +#[derive(Deserialize)] +#[serde(rename_all = "lowercase")] +pub enum GraphMessageFlow { + Pegin, + Pegout, +} + +#[derive(Default, Deserialize)] +pub struct GraphDebugMessagesQuery { + /// Optional message-flow filter: `pegin` or `pegout`. + pub flow: Option, +} + +impl GraphMessageFlow { + fn matches_message_type(&self, message_type: &str) -> bool { + match self { + Self::Pegin => matches!( + message_type, + "CreateGraph" + | "InitGraph" + | "GenCircuits" + | "CutCircuits" + | "SolderingProofReady" + | "VerifierGraphParamsEndorsement" + | "NonceGeneration" + | "CommitteePresign" + | "EndorseGraph" + | "GraphFinalize" + ), + Self::Pegout => matches!( + message_type, + "KickoffReady" + | "KickoffSent" + | "PreKickoffSent" + | "ChallengeSent" + | "WatchtowerChallengeInitSent" + | "WatchtowerChallengeSent" + | "WatchtowerChallengeTimeout" + | "NackReady" + | "OperatorCommitPubinReady" + | "OperatorCommitPubinTimeout" + | "AssertReady" + | "AssertSent" + | "ChallengeAssertSent" + | "WronglyChallengeTimeout" + | "DisproveSent" + | "Take1Ready" + | "Take1Sent" + | "Take2Ready" + | "Take2Sent" + ), + } + } +} + +#[derive(Serialize)] +pub struct InstanceDebugMessagesResponse { + pub instance_id: String, pub messages: Vec, } @@ -91,6 +154,28 @@ fn graph_debug_message_overview(message: MessageDebugOverview) -> GraphDebugMess } } +fn graph_debug_flow(graph: Option<&Graph>) -> &'static str { + let Some(graph) = graph else { + return "unknown"; + }; + if graph.init_withdraw_tx_hash.is_some() + || graph.bridge_out_start_at > 0 + || matches!( + graph.status.parse::(), + Ok(GraphStatus::PreKickoff + | GraphStatus::OperatorKickOff + | GraphStatus::Challenge + | GraphStatus::Disprove + | GraphStatus::OperatorTake1 + | GraphStatus::OperatorTake2) + ) + { + "pegout" + } else { + "pegin" + } +} + // TODO(auth): Require operator authentication before exposing local debug state. #[axum::debug_handler] pub async fn get_debug_status( @@ -129,20 +214,55 @@ pub async fn get_debug_status( #[axum::debug_handler] pub async fn get_graph_debug_messages( Path(graph_id): Path, + Query(query): Query, State(app_state): State>, ) -> ApiResult { let graph_id = InputValidator::validate_uuid(&graph_id, "graph_id")?; let mut storage_processor = app_state.local_db.acquire().await.api_error("GET_GRAPH_DEBUG_MESSAGES_ERROR")?; + let graph = storage_processor + .find_graph(&graph_id) + .await + .api_error("GET_GRAPH_DEBUG_MESSAGES_ERROR")?; + let flow = graph_debug_flow(graph.as_ref()).to_string(); + let status = graph.map(|graph| graph.status); let messages = storage_processor .find_message_debug_overviews(&graph_id) .await .api_error("GET_GRAPH_DEBUG_MESSAGES_ERROR")? .into_iter() + .filter(|message| { + query.flow.as_ref().is_none_or(|flow| flow.matches_message_type(&message.msg_type)) + }) + .map(graph_debug_message_overview) + .collect(); + + ok_response(GraphDebugMessagesResponse { + graph_id: graph_id.to_string(), + status, + flow, + messages, + }) +} + +// TODO(auth): Require operator authentication before exposing local debug state. +#[axum::debug_handler] +pub async fn get_instance_debug_messages( + Path(instance_id): Path, + State(app_state): State>, +) -> ApiResult { + let instance_id = InputValidator::validate_uuid(&instance_id, "instance_id")?; + let mut storage_processor = + app_state.local_db.acquire().await.api_error("GET_INSTANCE_DEBUG_MESSAGES_ERROR")?; + let messages = storage_processor + .find_message_debug_overviews(&instance_id) + .await + .api_error("GET_INSTANCE_DEBUG_MESSAGES_ERROR")? + .into_iter() .map(graph_debug_message_overview) .collect(); - ok_response(GraphDebugMessagesResponse { graph_id: graph_id.to_string(), messages }) + ok_response(InstanceDebugMessagesResponse { instance_id: instance_id.to_string(), messages }) } // TODO(auth): Require operator authentication before exposing local debug state. diff --git a/node/src/rpc_service/mod.rs b/node/src/rpc_service/mod.rs index 0bba1f76..2387b379 100644 --- a/node/src/rpc_service/mod.rs +++ b/node/src/rpc_service/mod.rs @@ -14,10 +14,10 @@ use crate::rpc_service::cors_config::CorsConfig; use crate::rpc_service::handler::{ bridge_in_request_tag, bridge_out_init_tag, get_chain_proof_desc, get_debug_message_details, get_debug_status, get_graph, get_graph_debug_messages, get_graph_neighbor_ids, get_graph_tx, - get_graph_txn, get_graphs, get_instance, get_instance_escrow_data, get_instances, - get_instances_overview, get_node, get_nodes, get_nodes_overview, get_operator_proof_desc, - get_ready_to_kickoff_graph, get_unsigned_pegin_txn, instance_settings, pegout, send_challenge, - send_verifier_challenge, + get_graph_txn, get_graphs, get_instance, get_instance_debug_messages, get_instance_escrow_data, + get_instances, get_instances_overview, get_node, get_nodes, get_nodes_overview, + get_operator_proof_desc, get_ready_to_kickoff_graph, get_unsigned_pegin_txn, instance_settings, + pegout, send_challenge, send_verifier_challenge, }; use anyhow::Context; use axum::body::Body; @@ -163,6 +163,7 @@ pub async fn serve_with_app_state( // TODO(auth): Restrict debug endpoints before exposing the RPC outside trusted operators. .route(routes::v1::DEBUG_STATUS, get(get_debug_status)) .route(routes::v1::DEBUG_GRAPH_MESSAGES, get(get_graph_debug_messages)) + .route(routes::v1::DEBUG_INSTANCE_MESSAGES, get(get_instance_debug_messages)) .route(routes::v1::DEBUG_MESSAGE_DETAILS, get(get_debug_message_details)) .route(routes::v1::GRAPHS_SEND_CHALLENGE, post(send_challenge)) .route(routes::v1::GRAPHS_SEND_VERIFIER_CHALLENGE, post(send_verifier_challenge)) diff --git a/node/src/rpc_service/routes.rs b/node/src/rpc_service/routes.rs index 80a97714..62d75ad9 100644 --- a/node/src/rpc_service/routes.rs +++ b/node/src/rpc_service/routes.rs @@ -32,6 +32,8 @@ pub(crate) mod v1 { // TODO(auth): Restrict debug endpoints before exposing the RPC outside trusted operators. pub const DEBUG_GRAPH_MESSAGES: &str = "/v1/debug/graphs/{:id}/messages"; // TODO(auth): Restrict debug endpoints before exposing the RPC outside trusted operators. + pub const DEBUG_INSTANCE_MESSAGES: &str = "/v1/debug/instances/{:id}/messages"; + // TODO(auth): Restrict debug endpoints before exposing the RPC outside trusted operators. pub const DEBUG_MESSAGE_DETAILS: &str = "/v1/debug/messages/{:id}"; // pub const PROOFS_BASE: &str = "/v1/proofs"; pub const PROOFS_CHAIN_PROOFS_DESC: &str = "/v1/proofs/chain_proofs_desc"; diff --git a/node/src/scheduled_tasks/instance_maintenance_tasks.rs b/node/src/scheduled_tasks/instance_maintenance_tasks.rs index 8d7bb0e0..e5195e94 100644 --- a/node/src/scheduled_tasks/instance_maintenance_tasks.rs +++ b/node/src/scheduled_tasks/instance_maintenance_tasks.rs @@ -1,6 +1,6 @@ use crate::action::{ - ConfirmInstance, GOATMessage, GOATMessageContent, PeginConfirmNonce, PeginConfirmPartialSig, - PeginRequest, PostReady, push_local_unhandled_messages, + ConfirmInstance, GOATMessage, GOATMessageContent, MessageDeferReason, PeginConfirmNonce, + PeginConfirmPartialSig, PeginRequest, PostReady, push_local_unhandled_messages_with_reason, }; use crate::env::{ COMMITTEE_INSTANCE_KEYS_DIR, get_bitvm_key, get_committee_instance_key_delete_timelock_blocks, @@ -589,7 +589,15 @@ pub async fn pegin_confirm_recovery_monitor( endorse_sig, }), ); - push_local_unhandled_messages(local_db, instance_id, &message, 0).await?; + push_local_unhandled_messages_with_reason( + local_db, + instance_id, + &message, + 0, + MessageDeferReason::RecoveryRepublish, + "re-publishing persisted pegin-confirm partial signature", + ) + .await?; tracing::info!( event = "pegin_confirm_recovery", action = "republish_partial_signature", @@ -641,7 +649,15 @@ pub async fn pegin_confirm_recovery_monitor( nonce_sig, }), ); - push_local_unhandled_messages(local_db, instance_id, &message, 0).await?; + push_local_unhandled_messages_with_reason( + local_db, + instance_id, + &message, + 0, + MessageDeferReason::RecoveryRepublish, + "re-publishing persisted pegin-confirm nonce", + ) + .await?; tracing::info!( event = "pegin_confirm_recovery", action = "republish_nonce", From cc516f3293edbbf7a753131942c8748ea3058740 Mon Sep 17 00:00:00 2001 From: ethan Date: Sat, 8 Aug 2026 14:34:03 +0800 Subject: [PATCH 5/8] add debug logs --- node/src/handle.rs | 87 ++++++++++++++++++++++++++++++++++++++++++++++ 1 file changed, 87 insertions(+) diff --git a/node/src/handle.rs b/node/src/handle.rs index 2d1e2d0c..ae8215e4 100644 --- a/node/src/handle.rs +++ b/node/src/handle.rs @@ -40,6 +40,7 @@ use goat::wots::{Wots, Wots96}; use libp2p::gossipsub::MessageId; use libp2p::{PeerId, Swarm}; use std::sync::Arc; +use std::time::Instant; use store::localdb::LocalDB; use store::{GraphStatus, SerializableTxid}; use uuid::Uuid; @@ -1863,7 +1864,24 @@ pub(crate) async fn handle_soldering_proof_payload_operator( soldering_proof_ready: &SolderingProofReady, payload: &[u8], ) -> Result<()> { + let decode_started_at = Instant::now(); + tracing::info!( + event = "operator_soldering_proof", + stage = "payload_decode", + outcome = "started", + verifier_index = soldering_proof_ready.verifier_index, + payload_len = payload.len(), + "decoding soldering proof payload" + ); let payload = decode_soldering_proof_payload(soldering_proof_ready, payload)?; + tracing::info!( + event = "operator_soldering_proof", + stage = "payload_decode", + outcome = "completed", + verifier_index = soldering_proof_ready.verifier_index, + elapsed_ms = decode_started_at.elapsed().as_millis(), + "decoded soldering proof payload" + ); handle_compact_soldering_proof_operator(ctx, soldering_proof_ready, payload).await } @@ -1918,8 +1936,26 @@ async fn handle_compact_soldering_proof_operator( } let setup_package = candidate.setup_package.clone(); let claimed_finalized_indices = candidate.selected_circuit_indexes.clone(); + let expand_started_at = Instant::now(); + tracing::info!( + event = "operator_soldering_proof", + stage = "payload_expand", + outcome = "started", + verifier_index, + "expanding compact soldering proof" + ); let (opened, finalized, soldering) = expand_compact_soldering_proof_payload(payload) .context("expand compact soldering proof payload")?; + tracing::info!( + event = "operator_soldering_proof", + stage = "payload_expand", + outcome = "completed", + verifier_index, + opened_instances = opened.len(), + finalized_instances = finalized.len(), + elapsed_ms = expand_started_at.elapsed().as_millis(), + "expanded compact soldering proof" + ); let vk = crate::vk::get_vk().await.context("load Groth16 verifying key for BABE validation")?; let static_input = derive_operator_static_input()?; @@ -1933,6 +1969,16 @@ async fn handle_compact_soldering_proof_operator( .context("BABE soldering builder is not initialized for Operator")?, ); + let verification_started_at = Instant::now(); + tracing::info!( + event = "operator_soldering_proof", + stage = "setup_verify", + outcome = "started", + verifier_index, + opened_instances = opened.len(), + finalized_instances = finalized.len(), + "verifying verifier soldering proof" + ); tokio::task::spawn_blocking(move || { verify_real_setup( &soldering_builder, @@ -1947,6 +1993,14 @@ async fn handle_compact_soldering_proof_operator( }) .await .context("real BABE setup verification task failed")??; + tracing::info!( + event = "operator_soldering_proof", + stage = "setup_verify", + outcome = "completed", + verifier_index, + elapsed_ms = verification_started_at.elapsed().as_millis(), + "verified verifier soldering proof" + ); tracing::info!( event = "operator_graph_creation", @@ -1962,8 +2016,24 @@ async fn handle_compact_soldering_proof_operator( bail!("each verifier must contribute exactly {BABE_M_CC} finalized BABE instances"); } let epk = &setup_package.commits[finalized[0].index].epk; + let gc_data_started_at = Instant::now(); + tracing::info!( + event = "operator_soldering_proof", + stage = "gc_data_extract", + outcome = "started", + verifier_index, + "building BABE prover state and extracting GC data" + ); let prover_state = build_babe_prover_state(&setup_package, finalized, soldering)?; let gc_data = extract_gc_circuit_data(verifier_pubkey, epk, &prover_state.h_msgs)?; + tracing::info!( + event = "operator_soldering_proof", + stage = "gc_data_extract", + outcome = "completed", + verifier_index, + elapsed_ms = gc_data_started_at.elapsed().as_millis(), + "extracted GC data from soldering proof" + ); let Some(bitvm_gc_circuit_datas) = record_candidate_gc_data( operator_state, verifier_pubkey, @@ -2031,6 +2101,15 @@ async fn handle_compact_soldering_proof_operator( let prekickoff_params = build_prekickoff_params(ctx.btc_client, graph_nonce, cur_prekickoff_txn).await?; + let graph_build_started_at = Instant::now(); + tracing::info!( + event = "operator_soldering_proof", + stage = "graph_build", + outcome = "started", + verifier_slots = bitvm_gc_circuit_datas.len(), + graph_nonce, + "building graph parameters from verified soldering proofs" + ); let mut graph_params = build_graph_params( ctx.local_db, ctx.goat_client, @@ -2057,6 +2136,14 @@ async fn handle_compact_soldering_proof_operator( operator_pre_sign(operator_master_key.master_keypair(), &mut graph)?; let graph = graph.to_simplified()?; + tracing::info!( + event = "operator_soldering_proof", + stage = "graph_build", + outcome = "completed", + graph_nonce, + elapsed_ms = graph_build_started_at.elapsed().as_millis(), + "built operator-pre-signed graph" + ); let definition_hash = hex::encode(graph.parameters_hash()?); tracing::info!( event = "operator_graph_creation", From 08c1e497061f36c6f3346538aad74cc75aefc027 Mon Sep 17 00:00:00 2001 From: ethan Date: Wed, 12 Aug 2026 13:52:59 +0800 Subject: [PATCH 6/8] add retry logic for p2p message --- Cargo.lock | 7 +- Cargo.toml | 6 +- .../src/btc_chain/esplora_bitcoin_adaptor.rs | 29 +- crates/client/src/btc_chain/mod.rs | 1 + .../20260812120000_create_p2p_inbox_table.sql | 19 + crates/store/src/localdb.rs | 158 +++++- crates/store/src/schema.rs | 24 + node/src/action.rs | 489 +++++++++++++++--- node/src/handle.rs | 139 ++--- node/src/p2p_msg_handler.rs | 20 +- 10 files changed, 735 insertions(+), 157 deletions(-) create mode 100644 crates/store/migrations/20260812120000_create_p2p_inbox_table.sql diff --git a/Cargo.lock b/Cargo.lock index b8a782ae..650dcc46 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -3079,6 +3079,7 @@ dependencies = [ "bitcoin-script", "bitvm 0.1.0 (git+https://github.com/GOATNetwork/BitVM.git?branch=gc-v2)", "bitvm-gc", + "blake3", "borsh", "cbft-rpc", "clap", @@ -5568,7 +5569,7 @@ dependencies = [ [[package]] name = "garbled-snark-verifier" version = "0.1.0" -source = "git+https://github.com/GOATNetwork/bitvm2-gc?branch=feat%2Fgoat-bitvm3#f1999e03899ae43d46f191d288d898151653e6dc" +source = "git+https://github.com/KSlashh/bitvm2-gc?branch=patch-deps#f61f30e43be8c68b95421a14462ad95d36250e2e" dependencies = [ "ark-bn254", "ark-crypto-primitives", @@ -12200,7 +12201,7 @@ dependencies = [ [[package]] name = "soldering-host" version = "1.1.0" -source = "git+https://github.com/GOATNetwork/bitvm2-gc?branch=feat%2Fgoat-bitvm3#f1999e03899ae43d46f191d288d898151653e6dc" +source = "git+https://github.com/KSlashh/bitvm2-gc?branch=patch-deps#f61f30e43be8c68b95421a14462ad95d36250e2e" dependencies = [ "ark-bn254", "ark-crypto-primitives", @@ -13901,7 +13902,7 @@ dependencies = [ [[package]] name = "verifiable-circuit-babe" version = "0.0.1" -source = "git+https://github.com/GOATNetwork/bitvm2-gc?branch=feat%2Fgoat-bitvm3#f1999e03899ae43d46f191d288d898151653e6dc" +source = "git+https://github.com/KSlashh/bitvm2-gc?branch=patch-deps#f61f30e43be8c68b95421a14462ad95d36250e2e" dependencies = [ "aes", "ark-bn254", diff --git a/Cargo.toml b/Cargo.toml index c3efd591..b68c8c11 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -106,9 +106,9 @@ p3-field = { git = "https://github.com/ProjectZKM/Plonky3" } #zkm-verifier = { path = "../Ziren/crates/verifier" } bitvm-lib = { package = "bitvm-gc", path = "crates/bitvm-gc" } -verifiable-circuit-babe = { git = "https://github.com/GOATNetwork/bitvm2-gc", branch = "feat/goat-bitvm3" } -garbled-snark-verifier = { git = "https://github.com/GOATNetwork/bitvm2-gc", branch = "feat/goat-bitvm3" } -soldering-host = { git = "https://github.com/GOATNetwork/bitvm2-gc", branch = "feat/goat-bitvm3" } +verifiable-circuit-babe = { git = "https://github.com/KSlashh/bitvm2-gc", branch = "patch-deps" } +garbled-snark-verifier = { git = "https://github.com/KSlashh/bitvm2-gc", branch = "patch-deps" } +soldering-host = { git = "https://github.com/KSlashh/bitvm2-gc", branch = "patch-deps" } #verifiable-circuit-babe = { path = "../bitvm2-gc/verifiable-circuit-babe"} #garbled-snark-verifier = { path = "../bitvm2-gc/garbled-snark-verifier"} diff --git a/crates/client/src/btc_chain/esplora_bitcoin_adaptor.rs b/crates/client/src/btc_chain/esplora_bitcoin_adaptor.rs index 693d194b..a3785a0d 100644 --- a/crates/client/src/btc_chain/esplora_bitcoin_adaptor.rs +++ b/crates/client/src/btc_chain/esplora_bitcoin_adaptor.rs @@ -1,9 +1,9 @@ use crate::btc_chain::bitcoin_adaptor::BitcoinAdaptor; use crate::timeout_config::get_btc_request_timeout_secs; -use anyhow::anyhow; use bitcoin::block::Header; use bitcoin::{Address as BtcAddress, Block, Network, Transaction, Txid}; use esplora_client::{AsyncClient, Builder, MerkleProof, Tx, Utxo}; +use std::fmt; use std::future::Future; use std::time::Duration; use tracing::warn; @@ -11,6 +11,24 @@ use tracing::warn; const TEST_URL: &str = "https://mempool.space/testnet/api"; const MAIN_URL: &str = "https://mempool.space/api"; +#[derive(Debug)] +pub struct BtcRpcTimeoutError { + pub request_name: &'static str, + pub timeout_secs: u64, +} + +impl fmt::Display for BtcRpcTimeoutError { + fn fmt(&self, formatter: &mut fmt::Formatter<'_>) -> fmt::Result { + write!( + formatter, + "esplora request timeout: {}, timeout_secs={}", + self.request_name, self.timeout_secs + ) + } +} + +impl std::error::Error for BtcRpcTimeoutError {} + pub fn get_esplora_url(network: Network) -> &'static str { match network { Network::Bitcoin => MAIN_URL, @@ -49,10 +67,11 @@ impl EsploraBitcoinAdaptor { timeout_secs = self.request_timeout.as_secs(), "esplora request timeout" ); - Err(anyhow!( - "esplora request timeout: {request_name}, timeout_secs={} ", - self.request_timeout.as_secs() - )) + Err(BtcRpcTimeoutError { + request_name, + timeout_secs: self.request_timeout.as_secs(), + } + .into()) } } } diff --git a/crates/client/src/btc_chain/mod.rs b/crates/client/src/btc_chain/mod.rs index 7bf7551c..fc452836 100644 --- a/crates/client/src/btc_chain/mod.rs +++ b/crates/client/src/btc_chain/mod.rs @@ -9,6 +9,7 @@ use std::str::FromStr; pub mod bitcoin_adaptor; pub mod bitcoin_chain; mod esplora_bitcoin_adaptor; +pub use esplora_bitcoin_adaptor::BtcRpcTimeoutError; pub mod mempool_v1_type; mod mock_bitcoin_adaptor; diff --git a/crates/store/migrations/20260812120000_create_p2p_inbox_table.sql b/crates/store/migrations/20260812120000_create_p2p_inbox_table.sql new file mode 100644 index 00000000..6cdceaff --- /dev/null +++ b/crates/store/migrations/20260812120000_create_p2p_inbox_table.sql @@ -0,0 +1,19 @@ +CREATE TABLE IF NOT EXISTS p2p_inbox ( + message_id TEXT NOT NULL PRIMARY KEY, + business_id TEXT, + actor TEXT NOT NULL, + from_peer TEXT NOT NULL, + msg_type TEXT NOT NULL, + content BLOB NOT NULL, + content_size BIGINT NOT NULL, + state TEXT NOT NULL DEFAULT 'Pending', + attempt_count BIGINT NOT NULL DEFAULT 0, + next_retry_at BIGINT NOT NULL DEFAULT 0, + lease_until BIGINT NOT NULL DEFAULT 0, + last_error TEXT, + created_at BIGINT NOT NULL, + updated_at BIGINT NOT NULL +); + +CREATE INDEX IF NOT EXISTS idx_p2p_inbox_ready + ON p2p_inbox (state, next_retry_at, created_at); diff --git a/crates/store/src/localdb.rs b/crates/store/src/localdb.rs index 0e7a3683..8575d660 100644 --- a/crates/store/src/localdb.rs +++ b/crates/store/src/localdb.rs @@ -3,9 +3,9 @@ use crate::{ BridgeOutGlobalStats, EventWatchMetricsSnapshot, GoatTxRecord, Graph, GraphBtcTxVoutMonitor, GraphRawData, GraphStatus, GraphStatusSource, GraphStatusTransitionOutcome, Instance, LongRunningTaskProof, Message, MessageDebugOverview, MessageDebugReason, MetricsStateCount, - Node, NodeAlertMetricsSnapshot, NodesOverview, OperatorProof, PeginGraphProcessData, - PeginInstanceProcessData, PendingGraphInit, SequencerSetHashChange, SequencerSetScanState, - SerializableTxid, WatchContract, WatchtowerProof, + Node, NodeAlertMetricsSnapshot, NodesOverview, OperatorProof, P2pInboxMessage, + PeginGraphProcessData, PeginInstanceProcessData, PendingGraphInit, SequencerSetHashChange, + SequencerSetScanState, SerializableTxid, WatchContract, WatchtowerProof, }; use indexmap::IndexMap; @@ -38,6 +38,25 @@ fn message_from_row(row: &SqliteRow) -> Result { }) } +fn p2p_inbox_message_from_row(row: &SqliteRow) -> Result { + Ok(P2pInboxMessage { + message_id: row.try_get("message_id")?, + business_id: row.try_get("business_id")?, + actor: row.try_get("actor")?, + from_peer: row.try_get("from_peer")?, + msg_type: row.try_get("msg_type")?, + content: row.try_get("content")?, + content_size: row.try_get("content_size")?, + state: row.try_get("state")?, + attempt_count: row.try_get("attempt_count")?, + next_retry_at: row.try_get("next_retry_at")?, + lease_until: row.try_get("lease_until")?, + last_error: row.try_get("last_error")?, + created_at: row.try_get("created_at")?, + updated_at: row.try_get("updated_at")?, + }) +} + #[derive(Clone, Debug)] pub struct LocalDB { pub path: String, @@ -2569,6 +2588,139 @@ impl<'a> StorageProcessor<'a> { Ok(res.rows_affected() > 0) } + /// Persist an externally received P2P message before it is dispatched. + /// Replays of the same gossipsub message are deliberately ignored so a + /// terminal row cannot be repopulated with its (potentially large) content. + pub async fn insert_p2p_inbox_message( + &mut self, + message: &P2pInboxMessage, + ) -> anyhow::Result { + let now = get_current_timestamp_secs(); + let result = sqlx::query( + "INSERT INTO p2p_inbox \ + (message_id, business_id, actor, from_peer, msg_type, content, content_size, \ + state, attempt_count, next_retry_at, lease_until, created_at, updated_at) \ + VALUES (?, ?, ?, ?, ?, ?, ?, 'Pending', 0, 0, 0, ?, ?) \ + ON CONFLICT(message_id) DO NOTHING", + ) + .bind(&message.message_id) + .bind(message.business_id) + .bind(&message.actor) + .bind(&message.from_peer) + .bind(&message.msg_type) + .bind(&message.content) + .bind(message.content_size) + .bind(now) + .bind(now) + .execute(self.conn()) + .await?; + 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( + &mut self, + now: i64, + lease_until: i64, + limit: i64, + ) -> anyhow::Result> { + let rows = sqlx::query( + "SELECT message_id, business_id, actor, from_peer, msg_type, content, content_size, \ + state, attempt_count, next_retry_at, lease_until, last_error, created_at, updated_at \ + FROM p2p_inbox \ + WHERE (state = 'Pending' AND next_retry_at <= ?) \ + OR (state = 'Processing' AND lease_until <= ?) \ + ORDER BY created_at ASC \ + LIMIT ?", + ) + .bind(now) + .bind(now) + .bind(limit) + .fetch_all(self.conn()) + .await?; + + let mut claimed = Vec::with_capacity(rows.len()); + for row in rows { + let mut message = p2p_inbox_message_from_row(&row)?; + let result = sqlx::query( + "UPDATE p2p_inbox \ + SET state = 'Processing', attempt_count = attempt_count + 1, lease_until = ?, updated_at = ? \ + WHERE message_id = ? \ + AND ((state = 'Pending' AND next_retry_at <= ?) \ + OR (state = 'Processing' AND lease_until <= ?))", + ) + .bind(lease_until) + .bind(now) + .bind(&message.message_id) + .bind(now) + .bind(now) + .execute(self.conn()) + .await?; + if result.rows_affected() > 0 { + message.state = "Processing".to_owned(); + message.attempt_count += 1; + message.lease_until = lease_until; + message.updated_at = now; + claimed.push(message); + } + } + Ok(claimed) + } + + pub async fn complete_p2p_inbox_message(&mut self, message_id: &str) -> anyhow::Result { + let result = sqlx::query( + "UPDATE p2p_inbox \ + SET state = 'Processed', content = X'', lease_until = 0, next_retry_at = 0, \ + updated_at = ? \ + WHERE message_id = ? AND state = 'Processing'", + ) + .bind(get_current_timestamp_secs()) + .bind(message_id) + .execute(self.conn()) + .await?; + Ok(result.rows_affected() > 0) + } + + pub async fn retry_p2p_inbox_message( + &mut self, + message_id: &str, + next_retry_at: i64, + error: &str, + ) -> anyhow::Result { + let result = sqlx::query( + "UPDATE p2p_inbox \ + SET state = 'Pending', lease_until = 0, next_retry_at = ?, last_error = ?, updated_at = ? \ + WHERE message_id = ? AND state = 'Processing'", + ) + .bind(next_retry_at) + .bind(error.chars().take(1024).collect::()) + .bind(get_current_timestamp_secs()) + .bind(message_id) + .execute(self.conn()) + .await?; + Ok(result.rows_affected() > 0) + } + + pub async fn fail_p2p_inbox_message( + &mut self, + message_id: &str, + error: &str, + ) -> anyhow::Result { + let result = sqlx::query( + "UPDATE p2p_inbox \ + SET state = 'Failed', content = X'', lease_until = 0, next_retry_at = 0, \ + last_error = ?, updated_at = ? \ + WHERE message_id = ? AND state = 'Processing'", + ) + .bind(error.chars().take(1024).collect::()) + .bind(get_current_timestamp_secs()) + .bind(message_id) + .execute(self.conn()) + .await?; + Ok(result.rows_affected() > 0) + } + /// Record that a chain-derived graph message has been durably enqueued. /// /// Queue rows are intentionally pruned after their retention period, but diff --git a/crates/store/src/schema.rs b/crates/store/src/schema.rs index 11f4697d..00bc5d97 100644 --- a/crates/store/src/schema.rs +++ b/crates/store/src/schema.rs @@ -524,6 +524,30 @@ pub struct Message { pub created_at: i64, } +/// A durable copy of a message received from the P2P network. +/// +/// Unlike `Message`, which is used for locally generated compensation work, +/// this row retains the original sender and is consumed before dispatching the +/// external message. `content` is cleared once the task reaches a terminal +/// state; the remaining columns are kept for operational debugging. +#[derive(Clone, FromRow, Debug, Serialize, Deserialize, Default)] +pub struct P2pInboxMessage { + pub message_id: String, + pub business_id: Option, + pub actor: String, + pub from_peer: String, + pub msg_type: String, + pub content: Vec, + pub content_size: i64, + pub state: String, + pub attempt_count: i64, + pub next_retry_at: i64, + pub lease_until: i64, + pub last_error: Option, + pub created_at: i64, + pub updated_at: i64, +} + #[derive(Clone, Debug, FromRow)] pub struct MessageDebugOverview { pub message_id: String, diff --git a/node/src/action.rs b/node/src/action.rs index 3630265a..b5ad879b 100644 --- a/node/src/action.rs +++ b/node/src/action.rs @@ -17,16 +17,22 @@ use bitvm_lib::committee::*; use bitvm_lib::types::{BitvmGcGraph, SimplifiedBitvmGcGraph}; use client::goat_chain::DisproveTxType; use client::http_client::async_client::HttpAsyncClient; -use client::{btc_chain::BTCClient, goat_chain::GOATClient}; +use client::{ + btc_chain::{BTCClient, BtcRpcTimeoutError}, + goat_chain::GOATClient, +}; use libp2p::gossipsub::MessageId; use libp2p::{PeerId, Swarm, gossipsub}; use musig2::{PartialSignature, PubNonce}; use secp256k1::schnorr::Signature as SchnorrSignature; use serde::{Deserialize, Serialize}; -use std::sync::Arc; -use std::time::Instant; -use store::MessageState; +use std::collections::HashSet; +use std::fmt; +use std::str::FromStr; +use std::sync::{Arc, LazyLock, Mutex}; +use std::time::{Duration, Instant}; use store::localdb::LocalDB; +use store::{MessageState, P2pInboxMessage}; use uuid::Uuid; #[derive(Serialize, Deserialize, Clone)] @@ -37,6 +43,143 @@ pub struct GOATMessage { const GOAT_MESSAGE_BIN_PREFIX: &[u8] = b"GOATBIN1"; const TRANSIENT_PEGIN_RETRY_DELAY_SECS: usize = 30; +const P2P_INBOX_BATCH_SIZE: i64 = 8; +const P2P_INBOX_LEASE_SECS: i64 = 30 * 60; +const P2P_INBOX_MAX_ATTEMPTS: i64 = 10; +const P2P_INBOX_ENQUEUE_ATTEMPTS: usize = 3; + +static SOLDERING_PROOF_GRAPH_LOCKS: LazyLock>> = + LazyLock::new(|| Mutex::new(HashSet::new())); + +struct SolderingProofGraphLock { + graph_id: Uuid, +} + +impl Drop for SolderingProofGraphLock { + fn drop(&mut self) { + if let Ok(mut locks) = SOLDERING_PROOF_GRAPH_LOCKS.lock() { + locks.remove(&self.graph_id); + } + } +} + +fn try_acquire_soldering_proof_graph_lock(graph_id: Uuid) -> Option { + let mut locks = SOLDERING_PROOF_GRAPH_LOCKS.lock().ok()?; + if !locks.insert(graph_id) { + return None; + } + Some(SolderingProofGraphLock { graph_id }) +} + +/// Stable retry categories shared by P2P inbox consumers and protocol +/// handlers. A handler must opt into retrying; all other failures are treated +/// as terminal and retained as `Failed` inbox records. +#[derive(Clone, Copy, Debug, Eq, PartialEq)] +pub enum RetryableDispatchReason { + StorageBusy, + ExternalRpcUnavailable, + PayloadNotReady, + DependencyPending, + PublishFailed, + ResourceLocked, +} + +impl RetryableDispatchReason { + pub const fn code(self) -> &'static str { + match self { + Self::StorageBusy => "storage_busy", + Self::ExternalRpcUnavailable => "external_rpc_unavailable", + Self::PayloadNotReady => "payload_not_ready", + Self::DependencyPending => "dependency_pending", + Self::PublishFailed => "publish_failed", + Self::ResourceLocked => "resource_locked", + } + } +} + +#[derive(Debug)] +pub struct RetryableDispatchError { + pub reason: RetryableDispatchReason, + pub retry_after_secs: Option, + detail: String, +} + +impl fmt::Display for RetryableDispatchError { + fn fmt(&self, formatter: &mut fmt::Formatter<'_>) -> fmt::Result { + write!(formatter, "retryable {}: {}", self.reason.code(), self.detail) + } +} + +impl std::error::Error for RetryableDispatchError {} + +pub fn retryable_dispatch_error( + reason: RetryableDispatchReason, + retry_after_secs: Option, + detail: impl fmt::Display, +) -> anyhow::Error { + anyhow::Error::new(RetryableDispatchError { + reason, + retry_after_secs, + detail: detail.to_string(), + }) +} + +fn is_retryable_http_status(status: u16) -> bool { + status == 429 || (500..=599).contains(&status) +} + +fn is_retryable_reqwest_error(error: &reqwest::Error) -> bool { + error.is_timeout() + || error.is_connect() + || error.status().is_some_and(|status| is_retryable_http_status(status.as_u16())) +} + +/// Only classify transport-level RPC failures. Contract reverts, malformed +/// responses and application errors are intentionally left terminal. +fn is_retryable_external_rpc_error(error: &anyhow::Error) -> bool { + error.chain().any(|cause| { + if let Some(error) = cause.downcast_ref::() { + return is_retryable_reqwest_error(error); + } + if cause.downcast_ref::().is_some() { + return true; + } + if let Some(error) = cause.downcast_ref::() { + return match error { + // esplora-client uses reqwest 0.11 while this crate uses + // reqwest 0.12, so this check must remain inline instead of + // sharing the 0.12 helper above. + esplora_client::Error::Reqwest(error) => { + error.is_timeout() + || error.is_connect() + || error + .status() + .is_some_and(|status| is_retryable_http_status(status.as_u16())) + } + esplora_client::Error::HttpResponse { status, .. } => { + is_retryable_http_status(*status) + } + _ => false, + }; + } + if let Some(error) = cause.downcast_ref::() { + // GOAT uses an HTTP Alloy provider. A transport error means the + // request did not receive a valid RPC result; RPC ErrorResp is + // deliberately excluded by this predicate. + return error.is_transport_error(); + } + false + }) +} + +fn classify_retryable_dispatch_error(error: anyhow::Error) -> anyhow::Error { + if error.chain().any(|cause| cause.downcast_ref::().is_some()) + || !is_retryable_external_rpc_error(&error) + { + return error; + } + retryable_dispatch_error(RetryableDispatchReason::ExternalRpcUnavailable, None, error) +} #[derive(Clone, Copy, Debug)] pub enum MessageDeferReason { @@ -521,6 +664,267 @@ impl GOATMessage { .await? } } + +/// Persist externally received P2P messages before dispatching them. The +/// network event loop only decodes and enqueues; protocol work runs from the +/// durable inbox on a regular tick. +pub async fn enqueue_p2p_message( + local_db: &LocalDB, + actor: Actor, + from_peer_id: PeerId, + id: MessageId, + message: &[u8], + metrics_state: &MetricsState, +) -> Result<()> { + let decoded = match GOATMessage::deserialize_message(message).await { + Ok(message) => { + metrics_state.record_p2p_receive(true); + message + } + Err(error) => { + metrics_state.record_p2p_receive(false); + return Err(error).context("decode inbound P2P message before enqueue"); + } + }; + let message_id = hex::encode(&id.0); + let inbox_message = P2pInboxMessage { + message_id: message_id.clone(), + business_id: decoded.content.pegin_retry_business_id(), + actor: actor.to_string(), + from_peer: from_peer_id.to_string(), + msg_type: decoded.content.event_type().to_owned(), + content: message.to_vec(), + content_size: message.len() as i64, + ..Default::default() + }; + let mut inserted = None; + for attempt in 1..=P2P_INBOX_ENQUEUE_ATTEMPTS { + let result = async { + let mut storage = local_db.acquire().await?; + storage.insert_p2p_inbox_message(&inbox_message).await + } + .await; + match result { + Ok(value) => { + inserted = Some(value); + break; + } + Err(error) + if is_retryable_sqlite_error(&error) && attempt < P2P_INBOX_ENQUEUE_ATTEMPTS => + { + tracing::warn!( + event = "p2p_inbox", + outcome = "enqueue_retry", + message_id = %message_id, + attempt, + error = %error, + "retrying transient P2P inbox insert" + ); + tokio::time::sleep(Duration::from_millis(50 * attempt as u64)).await; + } + Err(error) => return Err(error).context("persist inbound P2P message"), + } + } + let inserted = inserted.expect("P2P inbox insert loop exits only after success or error"); + if let Err(error) = update_node_timestamp(local_db, &from_peer_id.to_string()).await { + tracing::warn!( + event = "p2p_inbox", + outcome = "peer_timestamp_update_failed", + message_id = %message_id, + from_peer_id = %from_peer_id, + error = %error, + "stored inbound P2P message but failed to update peer timestamp" + ); + } + tracing::info!( + event = "p2p_inbox", + outcome = if inserted { "enqueued" } else { "duplicate" }, + message_id = %message_id, + message_type = %inbox_message.msg_type, + from_peer_id = %from_peer_id, + content_size = message.len(), + "received P2P message" + ); + Ok(()) +} + +fn p2p_retry_delay_secs(attempt_count: i64) -> i64 { + match attempt_count { + ..=1 => 10, + 2 => 30, + 3 => 60, + 4 => 120, + _ => 300, + } +} + +fn p2p_retryable_dispatch_error( + error: &anyhow::Error, +) -> Option<(RetryableDispatchReason, Option)> { + if let Some(retryable) = + error.chain().find_map(|cause| cause.downcast_ref::()) + { + return Some((retryable.reason, retryable.retry_after_secs)); + } + if is_retryable_sqlite_error(error) { + return Some((RetryableDispatchReason::StorageBusy, None)); + } + None +} + +#[allow(clippy::too_many_arguments)] +async fn handle_p2p_inbox_messages( + swarm: &mut Swarm, + local_db: &LocalDB, + btc_client: &BTCClient, + goat_client: &GOATClient, + http_client: &HttpAsyncClient, + soldering_builder: &Option>, + actor: Actor, + metrics_state: &MetricsState, +) -> Result<()> { + let now = current_time_secs(); + let mut storage = local_db.start_immediate_transaction().await?; + let messages = storage + .claim_p2p_inbox_messages(now, now + P2P_INBOX_LEASE_SECS, P2P_INBOX_BATCH_SIZE) + .await?; + storage.commit().await?; + + for message in messages { + let from_peer_id = match PeerId::from_str(&message.from_peer) { + Ok(peer_id) => peer_id, + Err(error) => { + local_db + .acquire() + .await? + .fail_p2p_inbox_message( + &message.message_id, + &format!("invalid stored source peer: {error}"), + ) + .await?; + continue; + } + }; + let raw_message_id = match hex::decode(&message.message_id) { + Ok(message_id) => MessageId(message_id), + Err(error) => { + local_db + .acquire() + .await? + .fail_p2p_inbox_message( + &message.message_id, + &format!("invalid stored message id: {error}"), + ) + .await?; + continue; + } + }; + + let soldering_lock = if message.msg_type == "SolderingProofReady" { + match message.business_id.and_then(try_acquire_soldering_proof_graph_lock) { + Some(lock) => Some(lock), + None => { + let retry_after_secs = 5; + local_db + .acquire() + .await? + .retry_p2p_inbox_message( + &message.message_id, + current_time_secs() + retry_after_secs, + RetryableDispatchReason::ResourceLocked.code(), + ) + .await?; + tracing::debug!( + event = "p2p_inbox", + outcome = "deferred", + reason = RetryableDispatchReason::ResourceLocked.code(), + message_id = %message.message_id, + retry_after_secs, + "deferred soldering proof while its graph lock is held" + ); + continue; + } + } + } else { + None + }; + + let result = recv_and_dispatch( + swarm, + local_db, + btc_client, + goat_client, + http_client, + soldering_builder, + actor.clone(), + from_peer_id, + raw_message_id, + &message.content, + metrics_state, + ) + .await; + drop(soldering_lock); + + let mut storage = local_db.acquire().await?; + match result { + Ok(()) => { + storage.complete_p2p_inbox_message(&message.message_id).await?; + } + Err(error) if message.attempt_count < P2P_INBOX_MAX_ATTEMPTS => { + let Some((reason, requested_retry_after_secs)) = + p2p_retryable_dispatch_error(&error) + else { + storage.fail_p2p_inbox_message(&message.message_id, &error.to_string()).await?; + 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)); + storage + .retry_p2p_inbox_message( + &message.message_id, + current_time_secs() + retry_after_secs, + &error.to_string(), + ) + .await?; + metrics_state.record_message_retry(); + tracing::warn!( + event = "p2p_inbox", + outcome = "deferred", + reason = reason.code(), + 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" + ); + } + Err(error) => { + storage.fail_p2p_inbox_message(&message.message_id, &error.to_string()).await?; + 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" + ); + } + } + } + Ok(()) +} + #[allow(clippy::too_many_arguments)] pub async fn handle_self_p2p_msg( swarm: &mut Swarm, @@ -579,7 +983,6 @@ pub async fn handle_self_p2p_msg( id.clone(), &message.content, metrics_state, - false, ) .await { @@ -667,6 +1070,17 @@ pub async fn handle_self_p2p_msg( } } } + handle_p2p_inbox_messages( + swarm, + local_db, + btc_client, + goat_client, + http_client, + soldering_builder, + actor, + metrics_state, + ) + .await?; Ok(()) } @@ -687,28 +1101,10 @@ pub async fn recv_and_dispatch( id: MessageId, message: &[u8], metrics_state: &MetricsState, - is_p2p_receive: bool, ) -> Result<()> { - let is_local_queue_message = id == GOATMessage::default_message_id(); - if !is_local_queue_message { - update_node_timestamp(local_db, &from_peer_id.to_string()).await?; - } // Determine whether the message comes from this node itself to optionally skip validations let is_self_peer = get_local_node_info().peer_id == from_peer_id.to_string(); - let message = match GOATMessage::deserialize_message(message).await { - Ok(message) => { - if is_p2p_receive { - metrics_state.record_p2p_receive(true); - } - message - } - Err(error) => { - if is_p2p_receive { - metrics_state.record_p2p_receive(false); - } - return Err(error); - } - }; + let message = GOATMessage::deserialize_message(message).await?; let message_type = message.content.event_type(); let role = actor.to_string(); let from_peer_id_string = from_peer_id.to_string(); @@ -726,42 +1122,9 @@ pub async fn recv_and_dispatch( id, is_self_peer, }; - let result = match handle_dispatch(&mut handler_ctx, message.content()).await { - Err(error) if !is_local_queue_message && is_retryable_sqlite_error(&error) => { - if let Some(business_id) = message.content.pegin_retry_business_id() { - match push_local_unhandled_messages_with_reason( - local_db, - business_id, - &message, - TRANSIENT_PEGIN_RETRY_DELAY_SECS, - MessageDeferReason::TransientStorageRetry, - &format!("transient SQLite failure: {error}"), - ) - .await - { - Ok(()) => { - tracing::warn!( - event = "pegin_message_retry", - outcome = "deferred", - role = %role, - message_type, - business_id = %business_id, - retry_after_secs = TRANSIENT_PEGIN_RETRY_DELAY_SECS, - error = %error, - "deferred pegin message after a transient SQLite failure" - ); - Ok(()) - } - Err(queue_error) => Err(error.context(format!( - "failed to enqueue transient pegin message retry: {queue_error}" - ))), - } - } else { - Err(error) - } - } - result => result, - }; + let result = handle_dispatch(&mut handler_ctx, message.content()) + .await + .map_err(classify_retryable_dispatch_error); metrics_state .record_message_dispatch(message_type, if result.is_ok() { "success" } else { "failed" }); match &result { @@ -909,7 +1272,11 @@ pub async fn send_to_peer( error = %err, "failed to publish protocol message" ); - Err(err.into()) + Err(retryable_dispatch_error( + RetryableDispatchReason::PublishFailed, + Some(10), + format!("publish {message_type} to {target_actor}: {err}"), + )) } } } diff --git a/node/src/handle.rs b/node/src/handle.rs index ae8215e4..bc6bf51f 100644 --- a/node/src/handle.rs +++ b/node/src/handle.rs @@ -1745,16 +1745,27 @@ async fn handle_soldering_proof_ready_operator( return Ok(()); } - let state = load_babe_setup_state(ctx.local_db, instance_id, graph_id)? - .ok_or_else(|| anyhow!("missing BABE setup state for pending graph {graph_id}"))?; - let operator_state = state - .operator - .as_ref() - .ok_or_else(|| anyhow!("missing operator BABE setup state for pending graph {graph_id}"))?; - let frozen = operator_state - .frozen_verifier_pubkeys - .as_ref() - .ok_or_else(|| anyhow!("operator verifier membership is not frozen"))?; + let state = load_babe_setup_state(ctx.local_db, instance_id, graph_id)?.ok_or_else(|| { + retryable_dispatch_error( + RetryableDispatchReason::DependencyPending, + Some(30), + format!("missing BABE setup state for pending graph {graph_id}"), + ) + })?; + let operator_state = state.operator.as_ref().ok_or_else(|| { + retryable_dispatch_error( + RetryableDispatchReason::DependencyPending, + Some(30), + format!("missing operator BABE setup state for pending graph {graph_id}"), + ) + })?; + let frozen = operator_state.frozen_verifier_pubkeys.as_ref().ok_or_else(|| { + retryable_dispatch_error( + RetryableDispatchReason::DependencyPending, + Some(30), + "operator verifier membership is not frozen", + ) + })?; let verifier_pubkey = frozen.get(verifier_index).ok_or_else(|| { anyhow!("SolderingProofReady verifier index {verifier_index} out of range") })?; @@ -1804,7 +1815,11 @@ async fn handle_soldering_proof_ready_operator( error = %err, "failed to read soldering proof payload from store" ); - return Err(err).context("read soldering proof payload from store"); + return Err(retryable_dispatch_error( + RetryableDispatchReason::PayloadNotReady, + Some(30), + format!("read soldering proof payload from store: {err}"), + )); } }; tracing::info!( @@ -1912,16 +1927,28 @@ async fn handle_compact_soldering_proof_operator( return Ok(()); } - let mut state = load_babe_setup_state(ctx.local_db, instance_id, graph_id)? - .ok_or_else(|| anyhow!("missing BABE setup state for pending graph {graph_id}"))?; - let operator_state = state - .operator - .as_mut() - .ok_or_else(|| anyhow!("missing operator BABE setup state for pending graph {graph_id}"))?; - let frozen = operator_state - .frozen_verifier_pubkeys - .as_ref() - .ok_or_else(|| anyhow!("operator verifier membership is not frozen"))?; + let mut state = + load_babe_setup_state(ctx.local_db, instance_id, graph_id)?.ok_or_else(|| { + retryable_dispatch_error( + RetryableDispatchReason::DependencyPending, + Some(30), + format!("missing BABE setup state for pending graph {graph_id}"), + ) + })?; + let operator_state = state.operator.as_mut().ok_or_else(|| { + retryable_dispatch_error( + RetryableDispatchReason::DependencyPending, + Some(30), + format!("missing operator BABE setup state for pending graph {graph_id}"), + ) + })?; + let frozen = operator_state.frozen_verifier_pubkeys.as_ref().ok_or_else(|| { + retryable_dispatch_error( + RetryableDispatchReason::DependencyPending, + Some(30), + "operator verifier membership is not frozen", + ) + })?; let verifier_pubkey = *frozen .get(verifier_index) .ok_or_else(|| anyhow!("SolderingProof verifier index {verifier_index} out of range"))?; @@ -2174,50 +2201,6 @@ async fn handle_compact_soldering_proof_operator( "stored operator-pre-signed graph definition" ); - let mut storage = match ctx.local_db.acquire().await { - Ok(storage) => storage, - Err(error) => { - tracing::error!( - event = "operator_graph_creation", - outcome = "failed", - stage = "pending_session_delete", - graph_nonce, - definition_hash = %definition_hash, - error = %error, - "failed to acquire database connection to delete pending graph session" - ); - return Err(error) - .context("acquire database connection to delete pending graph session"); - } - }; - let deleted_pending_sessions = match storage - .delete_pending_graph_init(&instance_id, &local_operator_pubkey.to_string()) - .await - { - Ok(rows) => rows, - Err(error) => { - tracing::error!( - event = "operator_graph_creation", - outcome = "failed", - stage = "pending_session_delete", - graph_nonce, - definition_hash = %definition_hash, - error = %error, - "failed to delete pending graph session after definition persistence" - ); - return Err(error).context("delete pending graph session after definition persistence"); - } - }; - tracing::info!( - event = "operator_graph_creation", - outcome = "completed", - stage = "pending_session_delete", - graph_nonce, - definition_hash = %definition_hash, - deleted_pending_sessions, - "deleted pending graph session after definition persistence" - ); - let message_content = GOATMessageContent::CreateGraph(CreateGraph { instance_id, graph_id, graph_nonce, graph }); let message_id = @@ -2233,7 +2216,11 @@ async fn handle_compact_soldering_proof_operator( error = %error, "failed to publish CreateGraph" ); - return Err(error).context("publish CreateGraph"); + return Err(retryable_dispatch_error( + RetryableDispatchReason::PublishFailed, + Some(30), + format!("publish CreateGraph: {error}"), + )); } }; tracing::info!( @@ -2246,6 +2233,26 @@ async fn handle_compact_soldering_proof_operator( "published CreateGraph to the local gossipsub mesh" ); + // Keep the pending session until the graph notification has been accepted + // by gossipsub. If publishing fails, the inbox retry can rebuild from the + // persisted BABE state instead of losing the only recovery trigger. + let mut storage = ctx.local_db.acquire().await.context( + "acquire database connection to delete pending graph session after CreateGraph publish", + )?; + let deleted_pending_sessions = storage + .delete_pending_graph_init(&instance_id, &local_operator_pubkey.to_string()) + .await + .context("delete pending graph session after CreateGraph publish")?; + tracing::info!( + event = "operator_graph_creation", + outcome = "completed", + stage = "pending_session_delete", + graph_nonce, + definition_hash = %definition_hash, + deleted_pending_sessions, + "deleted pending graph session after CreateGraph publish" + ); + Ok(()) } diff --git a/node/src/p2p_msg_handler.rs b/node/src/p2p_msg_handler.rs index 49bba59b..b8ee8899 100644 --- a/node/src/p2p_msg_handler.rs +++ b/node/src/p2p_msg_handler.rs @@ -1,5 +1,5 @@ use crate::action::{ - GOATMessage, GOATMessageContent, handle_self_p2p_msg, recv_and_dispatch, send_to_peer, + GOATMessage, GOATMessageContent, enqueue_p2p_message, handle_self_p2p_msg, send_to_peer, }; use crate::env::get_local_node_info; use crate::metrics_service::MetricsState; @@ -31,21 +31,9 @@ impl P2pMessageHandler for BitvmNodeProcessor { id: MessageId, message: &[u8], ) -> anyhow::Result<()> { - recv_and_dispatch( - swarm, - &self.local_db, - &self.btc_client, - &self.goat_client, - &self.http_client, - &self.soldering_builder, - actor, - from_peer_id, - id, - message, - &self.metrics_state, - true, - ) - .await + let _ = swarm; + enqueue_p2p_message(&self.local_db, actor, from_peer_id, id, message, &self.metrics_state) + .await } async fn handle_tick_message( From a204f0d41355e9bb9e15c25203580da7121181a1 Mon Sep 17 00:00:00 2001 From: ethan Date: Wed, 12 Aug 2026 17:47:47 +0800 Subject: [PATCH 7/8] refactor(node): introduce durable heavy task dispatcher --- ...20260812121000_create_p2p_outbox_table.sql | 15 + crates/store/src/localdb.rs | 185 ++++++++++- crates/store/src/schema.rs | 13 + node/src/action.rs | 289 +++++++++++++--- node/src/handle.rs | 313 +++++++++++------- node/src/main.rs | 7 +- node/src/p2p_msg_handler.rs | 4 +- 7 files changed, 644 insertions(+), 182 deletions(-) create mode 100644 crates/store/migrations/20260812121000_create_p2p_outbox_table.sql diff --git a/crates/store/migrations/20260812121000_create_p2p_outbox_table.sql b/crates/store/migrations/20260812121000_create_p2p_outbox_table.sql new file mode 100644 index 00000000..7dd97ed4 --- /dev/null +++ b/crates/store/migrations/20260812121000_create_p2p_outbox_table.sql @@ -0,0 +1,15 @@ +CREATE TABLE IF NOT EXISTS p2p_outbox ( + message_id TEXT NOT NULL PRIMARY KEY, + msg_type TEXT NOT NULL, + content BLOB NOT NULL, + state TEXT NOT NULL DEFAULT 'Pending', + attempt_count BIGINT NOT NULL DEFAULT 0, + next_retry_at BIGINT NOT NULL DEFAULT 0, + lease_until BIGINT NOT NULL DEFAULT 0, + last_error TEXT, + created_at BIGINT NOT NULL, + updated_at BIGINT NOT NULL +); + +CREATE INDEX IF NOT EXISTS idx_p2p_outbox_ready + ON p2p_outbox (state, next_retry_at, created_at); diff --git a/crates/store/src/localdb.rs b/crates/store/src/localdb.rs index 8575d660..27d54336 100644 --- a/crates/store/src/localdb.rs +++ b/crates/store/src/localdb.rs @@ -4,8 +4,9 @@ use crate::{ GraphRawData, GraphStatus, GraphStatusSource, GraphStatusTransitionOutcome, Instance, LongRunningTaskProof, Message, MessageDebugOverview, MessageDebugReason, MetricsStateCount, Node, NodeAlertMetricsSnapshot, NodesOverview, OperatorProof, P2pInboxMessage, - PeginGraphProcessData, PeginInstanceProcessData, PendingGraphInit, SequencerSetHashChange, - SequencerSetScanState, SerializableTxid, WatchContract, WatchtowerProof, + P2pOutboxMessage, PeginGraphProcessData, PeginInstanceProcessData, PendingGraphInit, + SequencerSetHashChange, SequencerSetScanState, SerializableTxid, WatchContract, + WatchtowerProof, }; use indexmap::IndexMap; @@ -57,6 +58,20 @@ fn p2p_inbox_message_from_row(row: &SqliteRow) -> Result Result { + Ok(P2pOutboxMessage { + message_id: row.try_get("message_id")?, + msg_type: row.try_get("msg_type")?, + content: row.try_get("content")?, + state: row.try_get("state")?, + attempt_count: row.try_get("attempt_count")?, + next_retry_at: row.try_get("next_retry_at")?, + lease_until: row.try_get("lease_until")?, + last_error: row.try_get("last_error")?, + created_at: row.try_get("created_at")?, + }) +} + #[derive(Clone, Debug)] pub struct LocalDB { pub path: String, @@ -2702,6 +2717,29 @@ impl<'a> StorageProcessor<'a> { 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( + &mut self, + message_id: &str, + next_retry_at: i64, + reason: &str, + ) -> anyhow::Result { + let result = sqlx::query( + "UPDATE p2p_inbox \ + SET state = 'Pending', attempt_count = MAX(attempt_count - 1, 0), lease_until = 0, \ + next_retry_at = ?, last_error = ?, updated_at = ? \ + WHERE message_id = ? AND state = 'Processing'", + ) + .bind(next_retry_at) + .bind(reason) + .bind(get_current_timestamp_secs()) + .bind(message_id) + .execute(self.conn()) + .await?; + Ok(result.rows_affected() > 0) + } + pub async fn fail_p2p_inbox_message( &mut self, message_id: &str, @@ -2721,6 +2759,149 @@ impl<'a> StorageProcessor<'a> { Ok(result.rows_affected() > 0) } + pub async fn insert_p2p_outbox_message( + &mut self, + message_id: &str, + msg_type: &str, + content: &[u8], + ) -> anyhow::Result { + let now = get_current_timestamp_secs(); + let result = sqlx::query( + "INSERT INTO p2p_outbox \ + (message_id, msg_type, content, state, attempt_count, next_retry_at, lease_until, created_at, updated_at) \ + VALUES (?, ?, ?, 'Pending', 0, 0, 0, ?, ?) \ + ON CONFLICT(message_id) DO NOTHING", + ) + .bind(message_id) + .bind(msg_type) + .bind(content) + .bind(now) + .bind(now) + .execute(self.conn()) + .await?; + Ok(result.rows_affected() > 0) + } + + /// Enqueue an outbound message, allowing a terminal message to be + /// deliberately announced again while preserving an in-flight attempt. + pub async fn enqueue_p2p_outbox_message( + &mut self, + message_id: &str, + msg_type: &str, + content: &[u8], + ) -> anyhow::Result { + let now = get_current_timestamp_secs(); + let result = sqlx::query( + "INSERT INTO p2p_outbox \ + (message_id, msg_type, content, state, attempt_count, next_retry_at, lease_until, created_at, updated_at) \ + VALUES (?, ?, ?, 'Pending', 0, 0, 0, ?, ?) \ + ON CONFLICT(message_id) DO UPDATE SET \ + msg_type = excluded.msg_type, content = excluded.content, state = 'Pending', \ + attempt_count = 0, next_retry_at = 0, lease_until = 0, last_error = NULL, updated_at = excluded.updated_at \ + WHERE p2p_outbox.state IN ('Processed', 'Failed')", + ) + .bind(message_id) + .bind(msg_type) + .bind(content) + .bind(now) + .bind(now) + .execute(self.conn()) + .await?; + Ok(result.rows_affected() > 0) + } + + pub async fn claim_p2p_outbox_messages( + &mut self, + now: i64, + lease_until: i64, + limit: i64, + ) -> anyhow::Result> { + let rows = sqlx::query( + "SELECT message_id, msg_type, content, state, attempt_count, next_retry_at, lease_until, last_error, created_at \ + FROM p2p_outbox \ + WHERE (state = 'Pending' AND next_retry_at <= ?) \ + OR (state = 'Processing' AND lease_until <= ?) \ + ORDER BY created_at ASC LIMIT ?", + ) + .bind(now) + .bind(now) + .bind(limit) + .fetch_all(self.conn()) + .await?; + let mut claimed = Vec::with_capacity(rows.len()); + for row in rows { + let mut message = p2p_outbox_message_from_row(&row)?; + let result = sqlx::query( + "UPDATE p2p_outbox SET state = 'Processing', attempt_count = attempt_count + 1, lease_until = ?, updated_at = ? \ + WHERE message_id = ? AND ((state = 'Pending' AND next_retry_at <= ?) \ + OR (state = 'Processing' AND lease_until <= ?))", + ) + .bind(lease_until) + .bind(now) + .bind(&message.message_id) + .bind(now) + .bind(now) + .execute(self.conn()) + .await?; + if result.rows_affected() > 0 { + message.state = "Processing".to_owned(); + message.attempt_count += 1; + message.lease_until = lease_until; + claimed.push(message); + } + } + Ok(claimed) + } + + pub async fn complete_p2p_outbox_message(&mut self, message_id: &str) -> anyhow::Result { + let result = sqlx::query( + "UPDATE p2p_outbox SET state = 'Processed', content = X'', lease_until = 0, next_retry_at = 0, updated_at = ? \ + WHERE message_id = ? AND state = 'Processing'", + ) + .bind(get_current_timestamp_secs()) + .bind(message_id) + .execute(self.conn()) + .await?; + Ok(result.rows_affected() > 0) + } + + pub async fn retry_p2p_outbox_message( + &mut self, + message_id: &str, + next_retry_at: i64, + error: &str, + ) -> anyhow::Result { + let result = sqlx::query( + "UPDATE p2p_outbox SET state = 'Pending', lease_until = 0, next_retry_at = ?, last_error = ?, updated_at = ? \ + WHERE message_id = ? AND state = 'Processing'", + ) + .bind(next_retry_at) + .bind(error.chars().take(1024).collect::()) + .bind(get_current_timestamp_secs()) + .bind(message_id) + .execute(self.conn()) + .await?; + Ok(result.rows_affected() > 0) + } + + pub async fn fail_p2p_outbox_message( + &mut self, + message_id: &str, + error: &str, + ) -> anyhow::Result { + let result = sqlx::query( + "UPDATE p2p_outbox SET state = 'Failed', content = X'', lease_until = 0, next_retry_at = 0, \ + last_error = ?, updated_at = ? \ + WHERE message_id = ? AND state = 'Processing'", + ) + .bind(error.chars().take(1024).collect::()) + .bind(get_current_timestamp_secs()) + .bind(message_id) + .execute(self.conn()) + .await?; + Ok(result.rows_affected() > 0) + } + /// Record that a chain-derived graph message has been durably enqueued. /// /// Queue rows are intentionally pruned after their retention period, but diff --git a/crates/store/src/schema.rs b/crates/store/src/schema.rs index 00bc5d97..6fd14c1a 100644 --- a/crates/store/src/schema.rs +++ b/crates/store/src/schema.rs @@ -548,6 +548,19 @@ pub struct P2pInboxMessage { pub updated_at: i64, } +#[derive(Clone, FromRow, Debug, Serialize, Deserialize, Default)] +pub struct P2pOutboxMessage { + pub message_id: String, + pub msg_type: String, + pub content: Vec, + pub state: String, + pub attempt_count: i64, + pub next_retry_at: i64, + pub lease_until: i64, + pub last_error: Option, + pub created_at: i64, +} + #[derive(Clone, Debug, FromRow)] pub struct MessageDebugOverview { pub message_id: String, diff --git a/node/src/action.rs b/node/src/action.rs index b5ad879b..f71c3302 100644 --- a/node/src/action.rs +++ b/node/src/action.rs @@ -3,7 +3,10 @@ #![allow(clippy::collapsible_else_if)] use crate::env::get_local_node_info; -use crate::handle::{HandlerContext, dispatch as handle_dispatch}; +use crate::handle::{ + HandlerContext, HeavyTaskContext, dispatch as handle_dispatch, heavy_task_from_content, + is_heavy_task_message_type, run_heavy_task, +}; use crate::metrics_service::MetricsState; use crate::middleware::AllBehaviours; use crate::rpc_service::current_time_secs; @@ -26,7 +29,6 @@ use libp2p::{PeerId, Swarm, gossipsub}; use musig2::{PartialSignature, PubNonce}; use secp256k1::schnorr::Signature as SchnorrSignature; use serde::{Deserialize, Serialize}; -use std::collections::HashSet; use std::fmt; use std::str::FromStr; use std::sync::{Arc, LazyLock, Mutex}; @@ -48,27 +50,25 @@ const P2P_INBOX_LEASE_SECS: i64 = 30 * 60; const P2P_INBOX_MAX_ATTEMPTS: i64 = 10; const P2P_INBOX_ENQUEUE_ATTEMPTS: usize = 3; -static SOLDERING_PROOF_GRAPH_LOCKS: LazyLock>> = - LazyLock::new(|| Mutex::new(HashSet::new())); +static HEAVY_TASK_WORKER_ACTIVE: LazyLock> = LazyLock::new(|| Mutex::new(false)); -struct SolderingProofGraphLock { - graph_id: Uuid, -} +struct HeavyTaskPermit; -impl Drop for SolderingProofGraphLock { +impl Drop for HeavyTaskPermit { fn drop(&mut self) { - if let Ok(mut locks) = SOLDERING_PROOF_GRAPH_LOCKS.lock() { - locks.remove(&self.graph_id); + if let Ok(mut active) = HEAVY_TASK_WORKER_ACTIVE.lock() { + *active = false; } } } -fn try_acquire_soldering_proof_graph_lock(graph_id: Uuid) -> Option { - let mut locks = SOLDERING_PROOF_GRAPH_LOCKS.lock().ok()?; - if !locks.insert(graph_id) { +fn try_acquire_heavy_task_permit() -> Option { + let mut active = HEAVY_TASK_WORKER_ACTIVE.lock().ok()?; + if *active { return None; } - Some(SolderingProofGraphLock { graph_id }) + *active = true; + Some(HeavyTaskPermit) } /// Stable retry categories shared by P2P inbox consumers and protocol @@ -776,8 +776,8 @@ fn p2p_retryable_dispatch_error( async fn handle_p2p_inbox_messages( swarm: &mut Swarm, local_db: &LocalDB, - btc_client: &BTCClient, - goat_client: &GOATClient, + btc_client: &Arc, + goat_client: &Arc, http_client: &HttpAsyncClient, soldering_builder: &Option>, actor: Actor, @@ -805,6 +805,107 @@ async fn handle_p2p_inbox_messages( 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) => { + local_db + .acquire() + .await? + .fail_p2p_inbox_message(&message.message_id, &error.to_string()) + .await?; + continue; + } + }; + let Some(task) = heavy_task_from_content(decoded.content(), &actor) else { + local_db + .acquire() + .await? + .fail_p2p_inbox_message( + &message.message_id, + &format!("inbox message type does not match {} content", message.msg_type), + ) + .await?; + continue; + }; + Some(task) + } else { + None + }; + + if let Some(heavy_task) = heavy_task { + let local_db = local_db.clone(); + let btc_client = Arc::clone(btc_client); + let goat_client = Arc::clone(goat_client); + let soldering_builder = soldering_builder.clone(); + let metrics_state = metrics_state.clone(); + let message_id = message.message_id.clone(); + let attempt_count = message.attempt_count; + let task_type = heavy_task.message_type(); + let task_kind = heavy_task.kind(); + let graph_id = heavy_task.graph_id(); + let Some(permit) = try_acquire_heavy_task_permit() else { + let retry_after_secs = 5; + local_db + .acquire() + .await? + .defer_p2p_inbox_message( + &message_id, + current_time_secs() + retry_after_secs, + RetryableDispatchReason::ResourceLocked.code(), + ) + .await?; + tracing::debug!( + event = "p2p_inbox", + outcome = "deferred", + reason = RetryableDispatchReason::ResourceLocked.code(), + message_id, + retry_after_secs, + task_kind, + "deferred heavy task while the worker is busy" + ); + continue; + }; + tokio::spawn(async move { + let _permit = permit; + let context = HeavyTaskContext { + local_db: local_db.clone(), + btc_client, + goat_client, + soldering_builder, + metrics_state: metrics_state.clone(), + from_peer_id, + }; + let result = run_heavy_task(&context, heavy_task).await; + 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, + task_type, + attempt_count, + result, + ) + .await + { + tracing::error!(error = %error, message_id, "failed to persist heavy task result"); + } + }); + tracing::info!( + event = "p2p_inbox", + outcome = "heavy_task_started", + message_id = %message.message_id, + graph_id = %graph_id, + message_type = task_type, + task_kind, + "started background heavy task" + ); + continue; + } let raw_message_id = match hex::decode(&message.message_id) { Ok(message_id) => MessageId(message_id), Err(error) => { @@ -820,35 +921,6 @@ async fn handle_p2p_inbox_messages( } }; - let soldering_lock = if message.msg_type == "SolderingProofReady" { - match message.business_id.and_then(try_acquire_soldering_proof_graph_lock) { - Some(lock) => Some(lock), - None => { - let retry_after_secs = 5; - local_db - .acquire() - .await? - .retry_p2p_inbox_message( - &message.message_id, - current_time_secs() + retry_after_secs, - RetryableDispatchReason::ResourceLocked.code(), - ) - .await?; - tracing::debug!( - event = "p2p_inbox", - outcome = "deferred", - reason = RetryableDispatchReason::ResourceLocked.code(), - message_id = %message.message_id, - retry_after_secs, - "deferred soldering proof while its graph lock is held" - ); - continue; - } - } - } else { - None - }; - let result = recv_and_dispatch( swarm, local_db, @@ -863,7 +935,6 @@ async fn handle_p2p_inbox_messages( metrics_state, ) .await; - drop(soldering_lock); let mut storage = local_db.acquire().await?; match result { @@ -925,12 +996,129 @@ async fn handle_p2p_inbox_messages( Ok(()) } +async fn finish_p2p_inbox_attempt( + local_db: &LocalDB, + metrics_state: &MetricsState, + message_id: &str, + message_type: &str, + attempt_count: i64, + result: Result<()>, +) -> Result<()> { + let mut storage = local_db.acquire().await?; + match result { + Ok(()) => { + storage.complete_p2p_inbox_message(message_id).await?; + } + Err(error) if attempt_count < P2P_INBOX_MAX_ATTEMPTS => { + let Some((reason, requested_retry_after_secs)) = p2p_retryable_dispatch_error(&error) + else { + storage.fail_p2p_inbox_message(message_id, &error.to_string()).await?; + return Ok(()); + }; + let retry_after_secs = + requested_retry_after_secs.unwrap_or_else(|| p2p_retry_delay_secs(attempt_count)); + storage + .retry_p2p_inbox_message( + message_id, + current_time_secs() + retry_after_secs, + &error.to_string(), + ) + .await?; + metrics_state.record_message_retry(); + tracing::warn!( + event = "p2p_inbox", + outcome = "deferred", + reason = reason.code(), + message_id, + message_type, + attempt_count, + retry_after_secs, + error = %error, + "deferred cached P2P message for retry" + ); + } + Err(error) => { + storage.fail_p2p_inbox_message(message_id, &error.to_string()).await?; + } + } + Ok(()) +} + +async fn handle_p2p_outbox_messages( + swarm: &mut Swarm, + local_db: &LocalDB, +) -> Result<()> { + let now = current_time_secs(); + let mut storage = local_db.start_immediate_transaction().await?; + let messages = storage + .claim_p2p_outbox_messages(now, now + P2P_INBOX_LEASE_SECS, P2P_INBOX_BATCH_SIZE) + .await?; + storage.commit().await?; + + for message in messages { + let outbound = match GOATMessage::deserialize_message(&message.content).await { + Ok(message) => message, + Err(error) => { + local_db + .acquire() + .await? + .fail_p2p_outbox_message(&message.message_id, &error.to_string()) + .await?; + tracing::error!( + event = "p2p_outbox", + outcome = "failed", + message_id = %message.message_id, + message_type = %message.msg_type, + error = %error, + "discarded corrupt durable outbound P2P message" + ); + continue; + } + }; + let result = send_to_peer(swarm, outbound).await; + let mut storage = local_db.acquire().await?; + match result { + Ok(_) => { + storage.complete_p2p_outbox_message(&message.message_id).await?; + tracing::info!( + event = "p2p_outbox", + outcome = "published", + message_id = %message.message_id, + message_type = %message.msg_type, + "published durable outbound P2P message" + ); + } + Err(error) => { + let retry_after_secs = p2p_retry_delay_secs(message.attempt_count); + storage + .retry_p2p_outbox_message( + &message.message_id, + current_time_secs() + retry_after_secs, + &error.to_string(), + ) + .await?; + tracing::warn!( + event = "p2p_outbox", + outcome = "deferred", + message_id = %message.message_id, + message_type = %message.msg_type, + attempt_count = message.attempt_count, + retry_after_secs, + error = %error, + "deferred outbound P2P message" + ); + } + } + } + Ok(()) +} + #[allow(clippy::too_many_arguments)] pub async fn handle_self_p2p_msg( swarm: &mut Swarm, local_db: &LocalDB, - btc_client: &BTCClient, - goat_client: &GOATClient, + btc_client: &Arc, + goat_client: &Arc, http_client: &HttpAsyncClient, soldering_builder: &Option>, actor: Actor, @@ -1070,6 +1258,7 @@ pub async fn handle_self_p2p_msg( } } } + handle_p2p_outbox_messages(swarm, local_db).await?; handle_p2p_inbox_messages( swarm, local_db, @@ -1092,8 +1281,8 @@ pub async fn handle_self_p2p_msg( pub async fn recv_and_dispatch( swarm: &mut Swarm, local_db: &LocalDB, - btc_client: &BTCClient, - goat_client: &GOATClient, + btc_client: &Arc, + goat_client: &Arc, http_client: &HttpAsyncClient, soldering_builder: &Option>, actor: Actor, diff --git a/node/src/handle.rs b/node/src/handle.rs index bc6bf51f..c3638c16 100644 --- a/node/src/handle.rs +++ b/node/src/handle.rs @@ -48,8 +48,8 @@ use uuid::Uuid; pub struct HandlerContext<'a> { pub swarm: &'a mut Swarm, pub local_db: &'a LocalDB, - pub btc_client: &'a BTCClient, - pub goat_client: &'a GOATClient, + pub btc_client: &'a Arc, + pub goat_client: &'a Arc, pub http_client: &'a HttpAsyncClient, pub soldering_builder: &'a Option>, pub metrics_state: &'a MetricsState, @@ -59,6 +59,95 @@ pub struct HandlerContext<'a> { pub is_self_peer: bool, } +/// Owned resources for work that must not run on the swarm event loop. It +/// deliberately excludes `Swarm`: heavy work persists its follow-up protocol +/// notifications to the durable P2P outbox instead. +pub(crate) struct HeavyTaskContext { + pub local_db: LocalDB, + pub btc_client: Arc, + pub goat_client: Arc, + pub soldering_builder: Option>, + pub metrics_state: MetricsState, + pub from_peer_id: PeerId, +} + +pub(crate) enum HeavyTask { + GenerateSolderingProof(CutCircuits), + VerifySolderingProof(SolderingProofReady), +} + +impl HeavyTask { + pub(crate) fn kind(&self) -> &'static str { + match self { + Self::GenerateSolderingProof(_) => "generate_soldering_proof", + Self::VerifySolderingProof(_) => "verify_soldering_proof", + } + } + + pub(crate) fn message_type(&self) -> &'static str { + match self { + Self::GenerateSolderingProof(_) => "CutCircuits", + Self::VerifySolderingProof(_) => "SolderingProofReady", + } + } + + pub(crate) fn graph_id(&self) -> Uuid { + match self { + Self::GenerateSolderingProof(message) => message.graph_id, + Self::VerifySolderingProof(message) => message.graph_id, + } + } +} + +pub(crate) fn heavy_task_from_content( + content: &GOATMessageContent, + actor: &Actor, +) -> Option { + match (content, actor) { + (GOATMessageContent::CutCircuits(message), Actor::Verifier) => { + Some(HeavyTask::GenerateSolderingProof(message.clone())) + } + (GOATMessageContent::SolderingProofReady(message), Actor::Operator) => { + Some(HeavyTask::VerifySolderingProof(message.clone())) + } + _ => None, + } +} + +pub(crate) fn is_heavy_task_message_type(message_type: &str, actor: &Actor) -> bool { + matches!( + (message_type, actor), + ("SolderingProofReady", Actor::Operator) | ("CutCircuits", Actor::Verifier) + ) +} + +pub(crate) async fn run_heavy_task(context: &HeavyTaskContext, task: HeavyTask) -> Result<()> { + match task { + HeavyTask::GenerateSolderingProof(message) => { + handle_cut_circuits_verifier( + context, + message.instance_id, + message.graph_id, + &message.verifier_pubkey, + message.verifier_index, + &message.selected_circuit_indexes, + ) + .await + } + HeavyTask::VerifySolderingProof(message) => { + handle_soldering_proof_ready_operator( + context, + message.instance_id, + message.graph_id, + message.verifier_index, + message.payload_hash, + message.total_len, + ) + .await + } + } +} + fn committee_instance_keys_envelope_path(instance_id: Uuid) -> std::path::PathBuf { let mut path = std::path::PathBuf::from(COMMITTEE_INSTANCE_KEYS_DIR); path.push(format!("{instance_id}.json")); @@ -183,45 +272,8 @@ pub async fn dispatch(ctx: &mut HandlerContext<'_>, content: &GOATMessageContent ) .await } - ( - GOATMessageContent::CutCircuits(CutCircuits { - instance_id, - graph_id, - verifier_pubkey, - verifier_index, - selected_circuit_indexes, - }), - Actor::Verifier, - ) => { - handle_cut_circuits_verifier( - ctx, - *instance_id, - *graph_id, - verifier_pubkey, - *verifier_index, - selected_circuit_indexes, - ) - .await - } - ( - GOATMessageContent::SolderingProofReady(SolderingProofReady { - instance_id, - graph_id, - verifier_index, - payload_hash, - total_len, - }), - Actor::Operator, - ) => { - handle_soldering_proof_ready_operator( - ctx, - *instance_id, - *graph_id, - *verifier_index, - *payload_hash, - *total_len, - ) - .await + (content, actor) if heavy_task_from_content(content, actor).is_some() => { + bail!("heavy task must be dispatched through the durable P2P inbox") } ( GOATMessageContent::CreateGraph(CreateGraph { @@ -1601,10 +1653,10 @@ async fn handle_gen_circuits_operator( Ok(()) } -// generate proofs for the chosen GC and broadcast SolderingProof. +// Generate proofs for the chosen GC and enqueue SolderingProofReady. #[tracing::instrument(level = "info", skip_all, fields(instance_id = %instance_id, graph_id = %graph_id))] async fn handle_cut_circuits_verifier( - ctx: &mut HandlerContext<'_>, + context: &HeavyTaskContext, instance_id: Uuid, graph_id: Uuid, verifier_pubkey: &PublicKey, @@ -1621,7 +1673,7 @@ async fn handle_cut_circuits_verifier( return Ok(()); } - let Some(mut verifier_state) = load_babe_setup_state(ctx.local_db, instance_id, graph_id)? + let Some(mut verifier_state) = load_babe_setup_state(&context.local_db, instance_id, graph_id)? .and_then(|state| state.verifier) else { tracing::warn!( @@ -1648,14 +1700,7 @@ async fn handle_cut_circuits_verifier( if verifier_state.finalized_indices != *selected_circuit_indexes { bail!("CutCircuits finalized indices conflict with persisted selection"); } - send_to_peer( - ctx.swarm, - GOATMessage::new( - Actor::Operator, - GOATMessageContent::SolderingProofReady(soldering_proof_ready), - ), - ) - .await?; + enqueue_soldering_proof_ready(context, soldering_proof_ready).await?; return Ok(()); } @@ -1669,7 +1714,8 @@ async fn handle_cut_circuits_verifier( let selected_indices = selected_circuit_indexes.clone(); let package_for_opening = setup_package.clone(); let soldering_builder = Arc::clone( - ctx.soldering_builder + context + .soldering_builder .as_ref() .context("BABE soldering builder is not initialized for Verifier")?, ); @@ -1698,25 +1744,48 @@ async fn handle_cut_circuits_verifier( verifier_state.finalized_indices = selected_circuit_indexes.clone(); verifier_state.soldering_proof_ready = Some(soldering_proof_ready.clone()); - update_babe_setup_state(ctx.local_db, instance_id, graph_id, |state| { + update_babe_setup_state(&context.local_db, instance_id, graph_id, |state| { state.verifier = Some(verifier_state); })?; - send_to_peer( - ctx.swarm, - GOATMessage::new( - Actor::Operator, - GOATMessageContent::SolderingProofReady(soldering_proof_ready), - ), - ) - .await?; + enqueue_soldering_proof_ready(context, soldering_proof_ready).await?; + + Ok(()) +} +async fn enqueue_soldering_proof_ready( + context: &HeavyTaskContext, + soldering_proof_ready: SolderingProofReady, +) -> Result<()> { + let outbox_id = format!( + "soldering-proof-ready:{}:{}:{}", + soldering_proof_ready.graph_id, + soldering_proof_ready.verifier_index, + hex::encode(soldering_proof_ready.payload_hash), + ); + let message = GOATMessage::new( + Actor::Operator, + GOATMessageContent::SolderingProofReady(soldering_proof_ready), + ); + let serialized = message.serialize_message().await?; + context + .local_db + .acquire() + .await? + .enqueue_p2p_outbox_message(&outbox_id, message.content.event_type(), &serialized) + .await?; + tracing::info!( + event = "verifier_soldering_proof", + outcome = "enqueued", + outbox_id, + "enqueued SolderingProofReady for swarm publication" + ); Ok(()) } #[allow(clippy::too_many_arguments)] -async fn handle_soldering_proof_ready_operator( - ctx: &mut HandlerContext<'_>, +pub(crate) async fn handle_soldering_proof_ready_operator( + context: &HeavyTaskContext, instance_id: Uuid, graph_id: Uuid, verifier_index: usize, @@ -1731,7 +1800,7 @@ async fn handle_soldering_proof_ready_operator( let operator_master_key = OperatorMasterKey::new(get_bitvm_key()?); let local_operator_pubkey = operator_master_key.master_keypair().public_key().into(); if !pending_graph_belongs_to_operator( - ctx.local_db, + &context.local_db, instance_id, graph_id, &local_operator_pubkey, @@ -1745,13 +1814,14 @@ async fn handle_soldering_proof_ready_operator( return Ok(()); } - let state = load_babe_setup_state(ctx.local_db, instance_id, graph_id)?.ok_or_else(|| { - retryable_dispatch_error( - RetryableDispatchReason::DependencyPending, - Some(30), - format!("missing BABE setup state for pending graph {graph_id}"), - ) - })?; + let state = + load_babe_setup_state(&context.local_db, instance_id, graph_id)?.ok_or_else(|| { + retryable_dispatch_error( + RetryableDispatchReason::DependencyPending, + Some(30), + format!("missing BABE setup state for pending graph {graph_id}"), + ) + })?; let operator_state = state.operator.as_ref().ok_or_else(|| { retryable_dispatch_error( RetryableDispatchReason::DependencyPending, @@ -1777,11 +1847,11 @@ async fn handle_soldering_proof_ready_operator( if candidate.verifier_index != Some(verifier_index) { bail!("selected verifier candidate index does not match SolderingProofReady slot"); } - let verifier_peer_id = ctx.from_peer_id.to_bytes(); + let verifier_peer_id = context.from_peer_id.to_bytes(); if candidate.verifier_peer_id != verifier_peer_id { tracing::warn!( "Ignore SolderingProofReady for {instance_id}:{graph_id}: sender {} does not own verifier slot {verifier_index}", - ctx.from_peer_id + context.from_peer_id ); return Ok(()); } @@ -1795,7 +1865,7 @@ async fn handle_soldering_proof_ready_operator( &payload_hash, )?; tracing::info!( - from_peer_id = %ctx.from_peer_id, + from_peer_id = %context.from_peer_id, instance_id = %instance_id, graph_id = %graph_id, verifier_index, @@ -1833,8 +1903,8 @@ async fn handle_soldering_proof_ready_operator( "read soldering proof payload from store, start processing" ); let result = - handle_soldering_proof_payload_operator(ctx, &soldering_proof_ready, &payload).await; - ctx.metrics_state.record_pegin_graph_setup(result.is_ok()); + handle_soldering_proof_payload_operator(context, &soldering_proof_ready, &payload).await; + context.metrics_state.record_pegin_graph_setup(result.is_ok()); result } @@ -1875,7 +1945,7 @@ fn decode_soldering_proof_payload( } pub(crate) async fn handle_soldering_proof_payload_operator( - ctx: &mut HandlerContext<'_>, + context: &HeavyTaskContext, soldering_proof_ready: &SolderingProofReady, payload: &[u8], ) -> Result<()> { @@ -1897,13 +1967,13 @@ pub(crate) async fn handle_soldering_proof_payload_operator( elapsed_ms = decode_started_at.elapsed().as_millis(), "decoded soldering proof payload" ); - handle_compact_soldering_proof_operator(ctx, soldering_proof_ready, payload).await + handle_compact_soldering_proof_operator(context, soldering_proof_ready, payload).await } // verify Verifier SolderingProof, build Graph and broadcast CreateGraph. #[tracing::instrument(level = "info", skip_all, fields(instance_id = %soldering_proof_ready.instance_id, graph_id = %soldering_proof_ready.graph_id))] async fn handle_compact_soldering_proof_operator( - ctx: &mut HandlerContext<'_>, + context: &HeavyTaskContext, soldering_proof_ready: &SolderingProofReady, payload: CompactSolderingProofPayload, ) -> Result<()> { @@ -1913,7 +1983,7 @@ async fn handle_compact_soldering_proof_operator( let operator_master_key = OperatorMasterKey::new(get_bitvm_key()?); let local_operator_pubkey = operator_master_key.master_keypair().public_key().into(); if !pending_graph_belongs_to_operator( - ctx.local_db, + &context.local_db, instance_id, graph_id, &local_operator_pubkey, @@ -1928,7 +1998,7 @@ async fn handle_compact_soldering_proof_operator( } let mut state = - load_babe_setup_state(ctx.local_db, instance_id, graph_id)?.ok_or_else(|| { + load_babe_setup_state(&context.local_db, instance_id, graph_id)?.ok_or_else(|| { retryable_dispatch_error( RetryableDispatchReason::DependencyPending, Some(30), @@ -1991,7 +2061,8 @@ async fn handle_compact_soldering_proof_operator( let finalized_for_validation = finalized.clone(); let soldering_for_validation = soldering.clone(); let soldering_builder = Arc::clone( - ctx.soldering_builder + context + .soldering_builder .as_ref() .context("BABE soldering builder is not initialized for Operator")?, ); @@ -2077,7 +2148,8 @@ async fn handle_compact_soldering_proof_operator( .filter(|candidate| candidate.gc_data.is_some()) .count(); let expected_slots = operator_state.candidates.len(); - if let Err(error) = save_babe_setup_state(ctx.local_db, instance_id, graph_id, &state) { + if let Err(error) = save_babe_setup_state(&context.local_db, instance_id, graph_id, &state) + { tracing::error!( event = "operator_graph_creation", outcome = "failed", @@ -2098,7 +2170,7 @@ async fn handle_compact_soldering_proof_operator( ); return Ok(()); }; - if let Err(error) = save_babe_setup_state(ctx.local_db, instance_id, graph_id, &state) { + if let Err(error) = save_babe_setup_state(&context.local_db, instance_id, graph_id, &state) { tracing::error!( event = "operator_graph_creation", outcome = "failed", @@ -2116,17 +2188,19 @@ async fn handle_compact_soldering_proof_operator( "all verifier soldering proofs are ready to build the graph" ); - let instance_params = get_instance_parameters(ctx.local_db, instance_id) + let instance_params = get_instance_parameters(&context.local_db, instance_id) .await? .ok_or_else(|| anyhow!("Instance parameters not found for {instance_id}"))?; let (graph_nonce, cur_prekickoff_txn) = - match get_current_prekickoff_tx(ctx.local_db, &local_operator_pubkey).await? { + match get_current_prekickoff_tx(&context.local_db, &local_operator_pubkey).await? { Some((graph_nonce, prekickoff_tx)) => (graph_nonce, prekickoff_tx), - None => (0, build_genesis_prekickoff_tx(ctx.btc_client, ctx.goat_client).await?), + None => { + (0, build_genesis_prekickoff_tx(&context.btc_client, &context.goat_client).await?) + } }; let prekickoff_params = - build_prekickoff_params(ctx.btc_client, graph_nonce, cur_prekickoff_txn).await?; + build_prekickoff_params(&context.btc_client, graph_nonce, cur_prekickoff_txn).await?; let graph_build_started_at = Instant::now(); tracing::info!( @@ -2138,8 +2212,8 @@ async fn handle_compact_soldering_proof_operator( "building graph parameters from verified soldering proofs" ); let mut graph_params = build_graph_params( - ctx.local_db, - ctx.goat_client, + &context.local_db, + &context.goat_client, instance_params, prekickoff_params, bitvm_gc_circuit_datas, @@ -2180,7 +2254,7 @@ async fn handle_compact_soldering_proof_operator( definition_hash = %definition_hash, "storing operator-pre-signed graph definition" ); - if let Err(error) = store_operator_presigned_graph(ctx.local_db, &graph).await { + if let Err(error) = store_operator_presigned_graph(&context.local_db, &graph).await { tracing::error!( event = "operator_graph_creation", outcome = "failed", @@ -2201,48 +2275,35 @@ async fn handle_compact_soldering_proof_operator( "stored operator-pre-signed graph definition" ); - let message_content = - GOATMessageContent::CreateGraph(CreateGraph { instance_id, graph_id, graph_nonce, graph }); - let message_id = - match send_to_peer(ctx.swarm, GOATMessage::new(Actor::All, message_content)).await { - Ok(message_id) => message_id, - Err(error) => { - tracing::error!( - event = "operator_graph_creation", - outcome = "failed", - stage = "create_graph_publish", - graph_nonce, - definition_hash = %definition_hash, - error = %error, - "failed to publish CreateGraph" - ); - return Err(retryable_dispatch_error( - RetryableDispatchReason::PublishFailed, - Some(30), - format!("publish CreateGraph: {error}"), - )); - } - }; + let message = GOATMessage::new( + Actor::All, + GOATMessageContent::CreateGraph(CreateGraph { instance_id, graph_id, graph_nonce, graph }), + ); + let serialized = message.serialize_message().await?; + let outbox_id = format!("create-graph:{graph_id}"); + let mut storage = context.local_db.acquire().await?; + storage + .insert_p2p_outbox_message(&outbox_id, message.content.event_type(), &serialized) + .await?; + drop(storage); tracing::info!( event = "operator_graph_creation", - outcome = "published", - stage = "create_graph_publish", + outcome = "enqueued", + stage = "create_graph_outbox", graph_nonce, definition_hash = %definition_hash, - message_id = ?message_id, - "published CreateGraph to the local gossipsub mesh" + outbox_id, + "enqueued CreateGraph for swarm publication" ); - // Keep the pending session until the graph notification has been accepted - // by gossipsub. If publishing fails, the inbox retry can rebuild from the - // persisted BABE state instead of losing the only recovery trigger. - let mut storage = ctx.local_db.acquire().await.context( - "acquire database connection to delete pending graph session after CreateGraph publish", - )?; + // The outbox is durable before this cleanup. A process crash before + // insertion leaves the session for inbox recovery; a crash after insertion + // leaves the outbox for swarm publication. + let mut storage = context.local_db.acquire().await?; let deleted_pending_sessions = storage .delete_pending_graph_init(&instance_id, &local_operator_pubkey.to_string()) .await - .context("delete pending graph session after CreateGraph publish")?; + .context("delete pending graph session after CreateGraph outbox enqueue")?; tracing::info!( event = "operator_graph_creation", outcome = "completed", @@ -2250,7 +2311,7 @@ async fn handle_compact_soldering_proof_operator( graph_nonce, definition_hash = %definition_hash, deleted_pending_sessions, - "deleted pending graph session after CreateGraph publish" + "deleted pending graph session after CreateGraph outbox enqueue" ); Ok(()) diff --git a/node/src/main.rs b/node/src/main.rs index baf33659..5983787d 100644 --- a/node/src/main.rs +++ b/node/src/main.rs @@ -183,8 +183,11 @@ async fn main() -> Result<(), Box> { set_node_metrics_state(metrics_state.clone()); let handler = BitvmNodeProcessor { local_db: local_db.clone(), - btc_client: BTCClient::new(get_network(), get_btc_url_from_env().as_deref()), - goat_client: GOATClient::new(env::goat_config_from_env().await, env::get_goat_network()), + btc_client: Arc::new(BTCClient::new(get_network(), get_btc_url_from_env().as_deref())), + goat_client: Arc::new(GOATClient::new( + env::goat_config_from_env().await, + env::get_goat_network(), + )), http_client: HttpAsyncClient::new(None), soldering_builder: matches!(actor, Actor::Verifier | Actor::Operator) .then(|| Arc::new(BabeBundleBuilder::new())), diff --git a/node/src/p2p_msg_handler.rs b/node/src/p2p_msg_handler.rs index b8ee8899..d329ac41 100644 --- a/node/src/p2p_msg_handler.rs +++ b/node/src/p2p_msg_handler.rs @@ -16,8 +16,8 @@ use store::localdb::LocalDB; pub struct BitvmNodeProcessor { pub local_db: LocalDB, - pub btc_client: BTCClient, - pub goat_client: GOATClient, + pub btc_client: Arc, + pub goat_client: Arc, pub http_client: HttpAsyncClient, pub soldering_builder: Option>, pub metrics_state: MetricsState, From f9b4cc4d648d112b0e2717a02aff155fad8a003d Mon Sep 17 00:00:00 2001 From: ethan Date: Thu, 13 Aug 2026 02:49:49 +0800 Subject: [PATCH 8/8] add durable heavy-task leasing --- ...260812122000_add_p2p_inbox_lease_token.sql | 2 + crates/store/src/localdb.rs | 94 +++++-- crates/store/src/schema.rs | 5 +- node/src/action.rs | 244 ++++++++++++++---- node/src/handle.rs | 113 +++++--- 5 files changed, 363 insertions(+), 95 deletions(-) create mode 100644 crates/store/migrations/20260812122000_add_p2p_inbox_lease_token.sql diff --git a/crates/store/migrations/20260812122000_add_p2p_inbox_lease_token.sql b/crates/store/migrations/20260812122000_add_p2p_inbox_lease_token.sql new file mode 100644 index 00000000..57232d41 --- /dev/null +++ b/crates/store/migrations/20260812122000_add_p2p_inbox_lease_token.sql @@ -0,0 +1,2 @@ +ALTER TABLE p2p_inbox + ADD COLUMN lease_token TEXT NOT NULL DEFAULT ''; diff --git a/crates/store/src/localdb.rs b/crates/store/src/localdb.rs index 27d54336..5bbb5145 100644 --- a/crates/store/src/localdb.rs +++ b/crates/store/src/localdb.rs @@ -52,6 +52,7 @@ fn p2p_inbox_message_from_row(row: &SqliteRow) -> Result StorageProcessor<'a> { let result = sqlx::query( "INSERT INTO p2p_inbox \ (message_id, business_id, actor, from_peer, msg_type, content, content_size, \ - state, attempt_count, next_retry_at, lease_until, created_at, updated_at) \ - VALUES (?, ?, ?, ?, ?, ?, ?, 'Pending', 0, 0, 0, ?, ?) \ + state, attempt_count, next_retry_at, lease_until, lease_token, created_at, updated_at) \ + VALUES (?, ?, ?, ?, ?, ?, ?, 'Pending', 0, 0, 0, '', ?, ?) \ ON CONFLICT(message_id) DO NOTHING", ) .bind(&message.message_id) @@ -2639,33 +2640,41 @@ impl<'a> StorageProcessor<'a> { now: i64, lease_until: i64, limit: i64, + excluded_message_ids: &[String], ) -> anyhow::Result> { - let rows = sqlx::query( + let excluded_predicate = if excluded_message_ids.is_empty() { + String::new() + } else { + 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, last_error, created_at, updated_at \ + state, attempt_count, next_retry_at, lease_until, lease_token, last_error, created_at, updated_at \ FROM p2p_inbox \ - WHERE (state = 'Pending' AND next_retry_at <= ?) \ - OR (state = 'Processing' AND lease_until <= ?) \ + WHERE ((state = 'Pending' AND next_retry_at <= ?) \ + OR (state = 'Processing' AND lease_until <= ?)){excluded_predicate} \ ORDER BY created_at ASC \ - LIMIT ?", - ) - .bind(now) - .bind(now) - .bind(limit) - .fetch_all(self.conn()) - .await?; + LIMIT ?" + ); + let mut query = sqlx::query(&query).bind(now).bind(now); + for message_id in excluded_message_ids { + query = query.bind(message_id); + } + let rows = query.bind(limit).fetch_all(self.conn()).await?; 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 = ?, updated_at = ? \ + 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) @@ -2676,6 +2685,7 @@ impl<'a> StorageProcessor<'a> { message.state = "Processing".to_owned(); message.attempt_count += 1; message.lease_until = lease_until; + message.lease_token = lease_token; message.updated_at = now; claimed.push(message); } @@ -2683,15 +2693,20 @@ impl<'a> StorageProcessor<'a> { Ok(claimed) } - pub async fn complete_p2p_inbox_message(&mut self, message_id: &str) -> anyhow::Result { + pub async fn complete_p2p_inbox_message( + &mut self, + message_id: &str, + lease_token: &str, + ) -> anyhow::Result { let result = sqlx::query( "UPDATE p2p_inbox \ SET state = 'Processed', content = X'', lease_until = 0, next_retry_at = 0, \ updated_at = ? \ - WHERE message_id = ? AND state = 'Processing'", + WHERE message_id = ? AND state = 'Processing' AND lease_token = ?", ) .bind(get_current_timestamp_secs()) .bind(message_id) + .bind(lease_token) .execute(self.conn()) .await?; Ok(result.rows_affected() > 0) @@ -2700,18 +2715,20 @@ impl<'a> StorageProcessor<'a> { pub async fn retry_p2p_inbox_message( &mut self, message_id: &str, + lease_token: &str, next_retry_at: i64, error: &str, ) -> anyhow::Result { let result = sqlx::query( "UPDATE p2p_inbox \ SET state = 'Pending', lease_until = 0, next_retry_at = ?, last_error = ?, updated_at = ? \ - WHERE message_id = ? AND state = 'Processing'", + WHERE message_id = ? AND state = 'Processing' AND lease_token = ?", ) .bind(next_retry_at) .bind(error.chars().take(1024).collect::()) .bind(get_current_timestamp_secs()) .bind(message_id) + .bind(lease_token) .execute(self.conn()) .await?; Ok(result.rows_affected() > 0) @@ -2722,6 +2739,7 @@ impl<'a> StorageProcessor<'a> { pub async fn defer_p2p_inbox_message( &mut self, message_id: &str, + lease_token: &str, next_retry_at: i64, reason: &str, ) -> anyhow::Result { @@ -2729,12 +2747,13 @@ impl<'a> StorageProcessor<'a> { "UPDATE p2p_inbox \ SET state = 'Pending', attempt_count = MAX(attempt_count - 1, 0), lease_until = 0, \ next_retry_at = ?, last_error = ?, updated_at = ? \ - WHERE message_id = ? AND state = 'Processing'", + WHERE message_id = ? AND state = 'Processing' AND lease_token = ?", ) .bind(next_retry_at) .bind(reason) .bind(get_current_timestamp_secs()) .bind(message_id) + .bind(lease_token) .execute(self.conn()) .await?; Ok(result.rows_affected() > 0) @@ -2743,17 +2762,52 @@ impl<'a> StorageProcessor<'a> { pub async fn fail_p2p_inbox_message( &mut self, message_id: &str, + lease_token: &str, error: &str, ) -> anyhow::Result { let result = sqlx::query( "UPDATE p2p_inbox \ - SET state = 'Failed', content = X'', lease_until = 0, next_retry_at = 0, \ + SET state = 'Failed', lease_until = 0, next_retry_at = 0, \ last_error = ?, updated_at = ? \ - WHERE message_id = ? AND state = 'Processing'", + WHERE message_id = ? AND state = 'Processing' AND lease_token = ?", ) .bind(error.chars().take(1024).collect::()) .bind(get_current_timestamp_secs()) .bind(message_id) + .bind(lease_token) + .execute(self.conn()) + .await?; + Ok(result.rows_affected() > 0) + } + + 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) + .bind(get_current_timestamp_secs()) + .bind(message_id) + .bind(lease_token) + .execute(self.conn()) + .await?; + Ok(result.rows_affected() > 0) + } + + 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, \ + lease_token = '', last_error = NULL, updated_at = ? \ + WHERE message_id = ? AND state = 'Failed' AND length(content) > 0", + ) + .bind(get_current_timestamp_secs()) + .bind(message_id) .execute(self.conn()) .await?; Ok(result.rows_affected() > 0) diff --git a/crates/store/src/schema.rs b/crates/store/src/schema.rs index 6fd14c1a..2dbc4fea 100644 --- a/crates/store/src/schema.rs +++ b/crates/store/src/schema.rs @@ -528,8 +528,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. `content` is cleared once the task reaches a terminal -/// state; the remaining columns are kept for operational debugging. +/// external message. Processed content is cleared, while failed content is +/// retained for manual requeue and later TTL cleanup. #[derive(Clone, FromRow, Debug, Serialize, Deserialize, Default)] pub struct P2pInboxMessage { pub message_id: String, @@ -543,6 +543,7 @@ pub struct P2pInboxMessage { pub attempt_count: i64, pub next_retry_at: i64, pub lease_until: i64, + pub lease_token: String, pub last_error: Option, pub created_at: i64, pub updated_at: i64, diff --git a/node/src/action.rs b/node/src/action.rs index f71c3302..c33bce9f 100644 --- a/node/src/action.rs +++ b/node/src/action.rs @@ -35,6 +35,7 @@ use std::sync::{Arc, LazyLock, Mutex}; use std::time::{Duration, Instant}; use store::localdb::LocalDB; use store::{MessageState, P2pInboxMessage}; +use tokio_util::sync::CancellationToken; use uuid::Uuid; #[derive(Serialize, Deserialize, Clone)] @@ -46,29 +47,53 @@ pub struct GOATMessage { const GOAT_MESSAGE_BIN_PREFIX: &[u8] = b"GOATBIN1"; const TRANSIENT_PEGIN_RETRY_DELAY_SECS: usize = 30; const P2P_INBOX_BATCH_SIZE: i64 = 8; -const P2P_INBOX_LEASE_SECS: i64 = 30 * 60; -const P2P_INBOX_MAX_ATTEMPTS: i64 = 10; +const P2P_INBOX_LEASE_SECS: i64 = 5 * 60; +const P2P_INBOX_LEASE_RENEW_INTERVAL_SECS: u64 = 60; const P2P_INBOX_ENQUEUE_ATTEMPTS: usize = 3; -static HEAVY_TASK_WORKER_ACTIVE: LazyLock> = LazyLock::new(|| Mutex::new(false)); +struct ActiveHeavyTask { + message_id: String, + lease_token: String, +} + +static ACTIVE_HEAVY_TASK: LazyLock>> = + LazyLock::new(|| Mutex::new(None)); -struct HeavyTaskPermit; +struct HeavyTaskPermit { + message_id: String, + lease_token: String, +} impl Drop for HeavyTaskPermit { fn drop(&mut self) { - if let Ok(mut active) = HEAVY_TASK_WORKER_ACTIVE.lock() { - *active = false; + if let Ok(mut active) = ACTIVE_HEAVY_TASK.lock() + && active.as_ref().is_some_and(|active| { + active.message_id == self.message_id && active.lease_token == self.lease_token + }) + { + *active = None; } } } -fn try_acquire_heavy_task_permit() -> Option { - let mut active = HEAVY_TASK_WORKER_ACTIVE.lock().ok()?; - if *active { +fn active_heavy_task_message_ids() -> Vec { + ACTIVE_HEAVY_TASK + .lock() + .ok() + .and_then(|active| active.as_ref().map(|active| vec![active.message_id.clone()])) + .unwrap_or_default() +} + +fn try_acquire_heavy_task_permit(message_id: &str, lease_token: &str) -> Option { + let mut active = ACTIVE_HEAVY_TASK.lock().ok()?; + if active.is_some() { return None; } - *active = true; - Some(HeavyTaskPermit) + *active = Some(ActiveHeavyTask { + message_id: message_id.to_owned(), + lease_token: lease_token.to_owned(), + }); + Some(HeavyTaskPermit { message_id: message_id.to_owned(), lease_token: lease_token.to_owned() }) } /// Stable retry categories shared by P2P inbox consumers and protocol @@ -772,6 +797,61 @@ fn p2p_retryable_dispatch_error( None } +fn log_stale_p2p_inbox_lease(message_id: &str, lease_token: &str, operation: &str) { + tracing::warn!( + event = "p2p_inbox", + outcome = "stale_lease", + message_id, + lease_token, + operation, + "ignored P2P inbox state update from a stale lease" + ); +} + +async fn renew_p2p_inbox_lease_until_cancelled( + local_db: LocalDB, + message_id: String, + lease_token: String, + cancellation: CancellationToken, +) -> bool { + let mut interval = + tokio::time::interval(Duration::from_secs(P2P_INBOX_LEASE_RENEW_INTERVAL_SECS)); + interval.tick().await; + loop { + tokio::select! { + _ = cancellation.cancelled() => return true, + _ = interval.tick() => { + let renewal = match local_db.acquire().await { + Ok(mut storage) => storage + .renew_p2p_inbox_lease( + &message_id, + &lease_token, + current_time_secs() + P2P_INBOX_LEASE_SECS, + ) + .await, + Err(error) => Err(error), + }; + match renewal { + Ok(true) => {} + Ok(false) => { + log_stale_p2p_inbox_lease(&message_id, &lease_token, "renew"); + return false; + } + Err(error) => { + tracing::warn!( + event = "p2p_inbox", + outcome = "lease_renew_failed", + message_id, + error = %error, + "failed to renew P2P inbox lease; will retry before expiry" + ); + } + } + } + } + } +} + #[allow(clippy::too_many_arguments)] async fn handle_p2p_inbox_messages( swarm: &mut Swarm, @@ -784,9 +864,15 @@ async fn handle_p2p_inbox_messages( metrics_state: &MetricsState, ) -> 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(now, now + P2P_INBOX_LEASE_SECS, P2P_INBOX_BATCH_SIZE) + .claim_p2p_inbox_messages( + now, + now + P2P_INBOX_LEASE_SECS, + P2P_INBOX_BATCH_SIZE, + &active_heavy_task_ids, + ) .await?; storage.commit().await?; @@ -794,14 +880,18 @@ async fn handle_p2p_inbox_messages( let from_peer_id = match PeerId::from_str(&message.from_peer) { Ok(peer_id) => peer_id, Err(error) => { - local_db + 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"); + } continue; } }; @@ -810,23 +900,38 @@ async fn handle_p2p_inbox_messages( let decoded = match GOATMessage::deserialize_message(&message.content).await { Ok(message) => message, Err(error) => { - local_db + let updated = local_db .acquire() .await? - .fail_p2p_inbox_message(&message.message_id, &error.to_string()) + .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 { - local_db + 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"); + } continue; }; Some(task) @@ -841,21 +946,26 @@ async fn handle_p2p_inbox_messages( let soldering_builder = soldering_builder.clone(); let metrics_state = metrics_state.clone(); 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_kind = heavy_task.kind(); let graph_id = heavy_task.graph_id(); - let Some(permit) = try_acquire_heavy_task_permit() else { + let Some(permit) = try_acquire_heavy_task_permit(&message_id, &lease_token) else { let retry_after_secs = 5; - local_db + 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"); + } tracing::debug!( event = "p2p_inbox", outcome = "deferred", @@ -869,6 +979,13 @@ async fn handle_p2p_inbox_messages( }; tokio::spawn(async move { let _permit = permit; + let lease_cancellation = CancellationToken::new(); + let lease_renewal = tokio::spawn(renew_p2p_inbox_lease_until_cancelled( + local_db.clone(), + message_id.clone(), + lease_token.clone(), + lease_cancellation.clone(), + )); let context = HeavyTaskContext { local_db: local_db.clone(), btc_client, @@ -878,6 +995,17 @@ async fn handle_p2p_inbox_messages( from_peer_id, }; let result = run_heavy_task(&context, heavy_task).await; + lease_cancellation.cancel(); + let lease_is_current = match lease_renewal.await { + Ok(lease_is_current) => lease_is_current, + Err(error) => { + tracing::error!(error = %error, message_id, "P2P inbox lease renewal task failed"); + false + } + }; + if !lease_is_current { + return; + } metrics_state.record_message_dispatch( task_type, if result.is_ok() { "success" } else { "failed" }, @@ -886,6 +1014,7 @@ async fn handle_p2p_inbox_messages( &local_db, &metrics_state, &message_id, + &lease_token, task_type, attempt_count, result, @@ -909,14 +1038,18 @@ async fn handle_p2p_inbox_messages( let raw_message_id = match hex::decode(&message.message_id) { Ok(message_id) => MessageId(message_id), Err(error) => { - local_db + 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"); + } continue; } }; @@ -939,13 +1072,35 @@ async fn handle_p2p_inbox_messages( let mut storage = local_db.acquire().await?; match result { Ok(()) => { - storage.complete_p2p_inbox_message(&message.message_id).await?; + 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", + ); + } } - Err(error) if message.attempt_count < P2P_INBOX_MAX_ATTEMPTS => { + Err(error) => { let Some((reason, requested_retry_after_secs)) = p2p_retryable_dispatch_error(&error) else { - storage.fail_p2p_inbox_message(&message.message_id, &error.to_string()).await?; + 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", @@ -959,13 +1114,17 @@ async fn handle_p2p_inbox_messages( }; let retry_after_secs = requested_retry_after_secs .unwrap_or_else(|| p2p_retry_delay_secs(message.attempt_count)); - storage + if !storage .retry_p2p_inbox_message( &message.message_id, + &message.lease_token, current_time_secs() + retry_after_secs, &error.to_string(), ) - .await?; + .await? + { + log_stale_p2p_inbox_lease(&message.message_id, &message.lease_token, "retry"); + } metrics_state.record_message_retry(); tracing::warn!( event = "p2p_inbox", @@ -979,18 +1138,6 @@ async fn handle_p2p_inbox_messages( "deferred cached P2P message for retry" ); } - Err(error) => { - storage.fail_p2p_inbox_message(&message.message_id, &error.to_string()).await?; - 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" - ); - } } } Ok(()) @@ -1000,6 +1147,7 @@ async fn finish_p2p_inbox_attempt( local_db: &LocalDB, metrics_state: &MetricsState, message_id: &str, + lease_token: &str, message_type: &str, attempt_count: i64, result: Result<()>, @@ -1007,23 +1155,34 @@ async fn finish_p2p_inbox_attempt( let mut storage = local_db.acquire().await?; match result { Ok(()) => { - storage.complete_p2p_inbox_message(message_id).await?; + if !storage.complete_p2p_inbox_message(message_id, lease_token).await? { + log_stale_p2p_inbox_lease(message_id, lease_token, "complete"); + } } - Err(error) if attempt_count < P2P_INBOX_MAX_ATTEMPTS => { + Err(error) => { let Some((reason, requested_retry_after_secs)) = p2p_retryable_dispatch_error(&error) else { - storage.fail_p2p_inbox_message(message_id, &error.to_string()).await?; + if !storage + .fail_p2p_inbox_message(message_id, lease_token, &error.to_string()) + .await? + { + log_stale_p2p_inbox_lease(message_id, lease_token, "fail"); + } return Ok(()); }; let retry_after_secs = requested_retry_after_secs.unwrap_or_else(|| p2p_retry_delay_secs(attempt_count)); - storage + if !storage .retry_p2p_inbox_message( message_id, + lease_token, current_time_secs() + retry_after_secs, &error.to_string(), ) - .await?; + .await? + { + log_stale_p2p_inbox_lease(message_id, lease_token, "retry"); + } metrics_state.record_message_retry(); tracing::warn!( event = "p2p_inbox", @@ -1037,9 +1196,6 @@ async fn finish_p2p_inbox_attempt( "deferred cached P2P message for retry" ); } - Err(error) => { - storage.fail_p2p_inbox_message(message_id, &error.to_string()).await?; - } } Ok(()) } diff --git a/node/src/handle.rs b/node/src/handle.rs index c3638c16..513e93f0 100644 --- a/node/src/handle.rs +++ b/node/src/handle.rs @@ -72,28 +72,36 @@ pub(crate) struct HeavyTaskContext { } pub(crate) enum HeavyTask { + GenerateVerifierSetup(InitGraph), GenerateSolderingProof(CutCircuits), + ValidateVerifierGraph(Box), VerifySolderingProof(SolderingProofReady), } impl HeavyTask { pub(crate) fn kind(&self) -> &'static str { match self { + Self::GenerateVerifierSetup(_) => "generate_verifier_setup", Self::GenerateSolderingProof(_) => "generate_soldering_proof", + Self::ValidateVerifierGraph(_) => "validate_verifier_graph", Self::VerifySolderingProof(_) => "verify_soldering_proof", } } 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, Self::GenerateSolderingProof(message) => message.graph_id, + Self::ValidateVerifierGraph(message) => message.graph_id, Self::VerifySolderingProof(message) => message.graph_id, } } @@ -104,9 +112,15 @@ pub(crate) fn heavy_task_from_content( actor: &Actor, ) -> Option { match (content, actor) { + (GOATMessageContent::InitGraph(message), Actor::Verifier) => { + Some(HeavyTask::GenerateVerifierSetup(message.clone())) + } (GOATMessageContent::CutCircuits(message), Actor::Verifier) => { Some(HeavyTask::GenerateSolderingProof(message.clone())) } + (GOATMessageContent::CreateGraph(message), Actor::Verifier) => { + Some(HeavyTask::ValidateVerifierGraph(Box::new(message.clone()))) + } (GOATMessageContent::SolderingProofReady(message), Actor::Operator) => { Some(HeavyTask::VerifySolderingProof(message.clone())) } @@ -117,12 +131,17 @@ 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) | ("CutCircuits", Actor::Verifier) + ("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) => { + handle_init_graph_verifier(context, message.instance_id, message.graph_id).await + } HeavyTask::GenerateSolderingProof(message) => { handle_cut_circuits_verifier( context, @@ -134,6 +153,16 @@ pub(crate) async fn run_heavy_task(context: &HeavyTaskContext, task: HeavyTask) ) .await } + HeavyTask::ValidateVerifierGraph(message) => { + handle_create_graph_verifier( + context, + message.instance_id, + message.graph_id, + message.graph_nonce, + &message.graph, + ) + .await + } HeavyTask::VerifySolderingProof(message) => { handle_soldering_proof_ready_operator( context, @@ -251,9 +280,6 @@ pub async fn dispatch(ctx: &mut HandlerContext<'_>, content: &GOATMessageContent (GOATMessageContent::ConfirmInstance(ConfirmInstance { instance_id }), _) => { handle_confirm_instance_default(ctx, *instance_id).await } - (GOATMessageContent::InitGraph(InitGraph { instance_id, graph_id }), Actor::Verifier) => { - handle_init_graph_verifier(ctx, *instance_id, *graph_id).await - } ( GOATMessageContent::GenCircuits(GenCircuits { instance_id, @@ -275,15 +301,6 @@ pub async fn dispatch(ctx: &mut HandlerContext<'_>, content: &GOATMessageContent (content, actor) if heavy_task_from_content(content, actor).is_some() => { bail!("heavy task must be dispatched through the durable P2P inbox") } - ( - GOATMessageContent::CreateGraph(CreateGraph { - instance_id, - graph_id, - graph_nonce, - graph, - }), - Actor::Verifier, - ) => handle_create_graph_verifier(ctx, *instance_id, *graph_id, *graph_nonce, graph).await, ( GOATMessageContent::CreateGraph(CreateGraph { instance_id, @@ -1472,17 +1489,17 @@ async fn handle_confirm_instance_operator( Ok(()) } -// generate garbled circuits and broadcast GenCircuits. +// Generate garbled circuits and enqueue GenCircuits without blocking the swarm. #[tracing::instrument(level = "info", skip_all, fields(instance_id = %instance_id, graph_id = %graph_id))] async fn handle_init_graph_verifier( - ctx: &mut HandlerContext<'_>, + context: &HeavyTaskContext, instance_id: Uuid, graph_id: Uuid, ) -> Result<()> { let verifier_master_key = VerifierMasterKey::new(get_bitvm_key()?); let verifier_pubkey = verifier_master_key.master_keypair().public_key().into(); - let saved_verifier_state = load_babe_setup_state(ctx.local_db, instance_id, graph_id)? + let saved_verifier_state = load_babe_setup_state(&context.local_db, instance_id, graph_id)? .and_then(|state| state.verifier) .filter(|state| state.verifier_pubkey == verifier_pubkey); let verifier_state = if let Some(saved) = saved_verifier_state { @@ -1507,17 +1524,29 @@ async fn handle_init_graph_verifier( }; let setup_package = verifier_state.setup_package.clone(); - update_babe_setup_state(ctx.local_db, instance_id, graph_id, |state| { + update_babe_setup_state(&context.local_db, instance_id, graph_id, |state| { state.verifier = Some(verifier_state); })?; - let message_content = GOATMessageContent::GenCircuits(GenCircuits { - instance_id, - graph_id, - verifier_pubkey, - setup_package, - }); - send_to_peer(ctx.swarm, GOATMessage::new(Actor::Operator, message_content)).await?; + let gen_circuits = GenCircuits { instance_id, graph_id, verifier_pubkey, setup_package }; + let outbox_id = format!( + "gen-circuits:{}:{}:{}", + gen_circuits.instance_id, gen_circuits.graph_id, gen_circuits.verifier_pubkey, + ); + let message = GOATMessage::new(Actor::Operator, GOATMessageContent::GenCircuits(gen_circuits)); + let serialized = message.serialize_message().await?; + context + .local_db + .acquire() + .await? + .enqueue_p2p_outbox_message(&outbox_id, message.content.event_type(), &serialized) + .await?; + tracing::info!( + event = "verifier_gc_setup", + outcome = "enqueued", + outbox_id, + "enqueued GenCircuits for swarm publication" + ); Ok(()) } @@ -2347,7 +2376,7 @@ async fn handle_confirm_instance_default( #[tracing::instrument(level = "info", skip_all, fields(instance_id = %instance_id, graph_id = %graph_id))] async fn handle_create_graph_verifier( - ctx: &mut HandlerContext<'_>, + context: &HeavyTaskContext, instance_id: Uuid, graph_id: Uuid, graph_nonce: u64, @@ -2375,7 +2404,9 @@ async fn handle_create_graph_verifier( let full_graph = BitvmGcGraph::from_simplified(graph)?; validate_verifier_slot(&full_graph, verifier_index)?; - let Some(verifier_state) = load_babe_setup_state(ctx.local_db, instance_id, graph_id)? + verify_graph_operator_pre_signatures(&full_graph) + .context("verify operator pre-signatures before endorsing graph parameters")?; + let Some(verifier_state) = load_babe_setup_state(&context.local_db, instance_id, graph_id)? .and_then(|state| state.verifier) else { tracing::warn!( @@ -2433,7 +2464,8 @@ async fn handle_create_graph_verifier( let canonical_graph_params_hash = graph.canonical_graph_params_hash()?; let signature = sign_verifier_graph_params(verifier_master_key.master_keypair(), graph)?; - let message_content = + let message = GOATMessage::new( + Actor::Committee, GOATMessageContent::VerifierGraphParamsEndorsement(VerifierGraphParamsEndorsement { instance_id, graph_id, @@ -2441,8 +2473,31 @@ async fn handle_create_graph_verifier( verifier_index, canonical_graph_params_hash, signature, - }); - send_to_peer(ctx.swarm, GOATMessage::new(Actor::Committee, message_content)).await?; + }), + ); + let serialized = message.serialize_message().await?; + let endorsement_outbox_id = + format!("verifier-graph-params-endorsement:{graph_id}:{verifier_index}"); + context + .local_db + .acquire() + .await? + .enqueue_p2p_outbox_message( + &endorsement_outbox_id, + message.content.event_type(), + &serialized, + ) + .await?; + + tracing::info!( + event = "verifier_graph_validation", + outcome = "endorsement_enqueued", + instance_id = %instance_id, + graph_id = %graph_id, + verifier_index, + endorsement_outbox_id, + "validated CreateGraph and enqueued verifier graph params endorsement" + ); Ok(()) }