Merge pull request #6008 from fdefelici/feat/signer-mon-conflicts

feat: add monitoring for signer agreement state conflict

Author: jferrant

stacks-signer/src/monitoring/mod.rs

@@ -33,6 +33,21 @@ SignerAgreementStateChangeReason {
     InactiveMiner("inactive_miner"),
     /// Signer agreement protocol version has been upgraded
     ProtocolUpgrade("protocol_upgrade"),
+    /// An update related to the Miner view
+    MinerViewUpdate("miner_view_update"),
+    /// A specific Miner View update related to the parent tenure
+    MinerParentTenureUpdate("miner_parent_tenure_update"),
+});
+
+define_named_enum!(
+/// Represent different conflict types on signer agreement protocol
+SignerAgreementStateConflict {
+    /// Waiting for burn block propagation to be aligned with the signer set
+    BurnBlockDelay("burn_block_delay"),
+    /// Waiting for stacks block propagation to be aligned with the signer set
+    StacksBlockDelay("stacks_block_delay"),
+    /// No agreement on miner view with the signer set
+    MinerView("miner_view"),
 });
 
 /// Actions for updating metrics
@@ -44,7 +59,7 @@ pub mod actions {
 
     use crate::config::GlobalConfig;
     use crate::monitoring::prometheus::*;
-    use crate::monitoring::SignerAgreementStateChangeReason;
+    use crate::monitoring::{SignerAgreementStateChangeReason, SignerAgreementStateConflict};
     use crate::v0::signer_state::LocalStateMachine;
 
     /// Update stacks tip height gauge
@@ -134,6 +149,21 @@ pub mod actions {
             .inc();
     }
 
+    /// Increment signer agreement state conflict counter
+    pub fn increment_signer_agreement_state_conflict(conflict: SignerAgreementStateConflict) {
+        let label_value = conflict.get_name();
+        SIGNER_AGREEMENT_STATE_CONFLICTS
+            .with_label_values(&[&label_value])
+            .inc();
+    }
+
+    /// Record the time (seconds) taken for a signer to agree with the signer set
+    pub fn record_signer_agreement_capitulation_latency(latency_s: u64) {
+        SIGNER_AGREEMENT_CAPITULATION_LATENCIES_HISTOGRAM
+            .with_label_values(&[])
+            .observe(latency_s as f64);
+    }
+
     /// Start serving monitoring metrics.
     /// This will only serve the metrics if the `monitoring_prom` feature is enabled.
     pub fn start_serving_monitoring_metrics(config: GlobalConfig) -> Result<(), String> {
@@ -157,7 +187,7 @@ pub mod actions {
     use blockstack_lib::chainstate::nakamoto::NakamotoBlock;
     use stacks_common::info;
 
-    use crate::monitoring::SignerAgreementStateChangeReason;
+    use crate::monitoring::{SignerAgreementStateChangeReason, SignerAgreementStateConflict};
     use crate::v0::signer_state::LocalStateMachine;
     use crate::GlobalConfig;
 
@@ -212,6 +242,12 @@ pub mod actions {
     ) {
     }
 
+    /// Increment signer agreement state conflict counter
+    pub fn increment_signer_agreement_state_conflict(_conflict: SignerAgreementStateConflict) {}
+
+    /// Record the time (seconds) taken for a signer to agree with the signer set
+    pub fn record_signer_agreement_capitulation_latency(_latency_s: u64) {}
+
     /// Start serving monitoring metrics.
     /// This will only serve the metrics if the `monitoring_prom` feature is enabled.
     pub fn start_serving_monitoring_metrics(config: GlobalConfig) -> Result<(), String> {

stacks-signer/src/monitoring/prometheus.rs

@@ -81,10 +81,22 @@ lazy_static! {
 
     pub static ref SIGNER_AGREEMENT_STATE_CHANGE_REASONS: IntCounterVec = register_int_counter_vec!(
         "stacks_signer_agreement_state_change_reasons",
-        "The number of state machine changes in signer agreement protocol. `reason` can be one of: 'burn_block_arrival', 'stacks_block_arrival', 'inactive_miner', 'protocol_upgrade'",
+        "The number of state machine changes in signer agreement protocol. `reason` can be one of: 'burn_block_arrival', 'stacks_block_arrival', 'inactive_miner', 'protocol_upgrade', 'miner_view_update', 'miner_parent_tenure_update'",
         &["reason"]
     ).unwrap();
 
+    pub static ref SIGNER_AGREEMENT_STATE_CONFLICTS: IntCounterVec = register_int_counter_vec!(
+        "stacks_signer_agreement_state_conflicts",
+        "The number of state machine conflicts in signer agreement protocol. `conflict` can be one of: 'burn_block_delay', 'stacks_block_delay', 'miner_view'",
+        &["conflict"]
+    ).unwrap();
+
+    pub static ref SIGNER_AGREEMENT_CAPITULATION_LATENCIES_HISTOGRAM: HistogramVec = register_histogram_vec!(histogram_opts!(
+        "stacks_signer_agreement_capitulation_latencies_histogram",
+        "Measuring the time (in seconds) for the signer to agree (capitulate) with the signer set",
+        vec![0.0, 1.0, 3.0, 5.0, 10.0, 20.0, 30.0, 60.0, 120.0]
+    ), &[]).unwrap();
+
     pub static ref SIGNER_LOCAL_STATE_MACHINE: Mutex<Option<LocalStateMachine>> = Mutex::new(None);
 }
 

stacks-signer/src/signerdb.rs

@@ -528,7 +528,7 @@ CREATE TABLE IF NOT EXISTS signer_state_machine_updates (
     signer_addr TEXT NOT NULL,
     reward_cycle INTEGER NOT NULL,
     state_update TEXT NOT NULL,
-    received_time TEXT NOT NULL,
+    received_time INTEGER NOT NULL,
     PRIMARY KEY (signer_addr, reward_cycle)
 ) STRICT;"#;
 
@@ -1412,6 +1412,22 @@ impl SignerDb {
         }
         Ok(result)
     }
+
+    /// Retrieve the elapsed time (in seconds) between
+    /// the oldest and the newest state machine update messages
+    /// produced by the signer set
+    pub fn get_signer_state_machine_updates_latency(
+        &self,
+        reward_cycle: u64,
+    ) -> Result<u64, DBError> {
+        let query = "SELECT COALESCE( (MAX(received_time) - MIN(received_time)), 0 ) AS elapsed_time FROM signer_state_machine_updates WHERE reward_cycle = ?1";
+        let args = params![u64_to_sql(reward_cycle)?];
+        let elapsed_time_opt: Option<u64> = query_row(&self.db, query, args)?;
+        match elapsed_time_opt {
+            Some(seconds) => Ok(seconds),
+            None => Ok(0),
+        }
+    }
 }
 
 fn try_deserialize<T>(s: Option<String>) -> Result<Option<T>, DBError>
@@ -2515,4 +2531,92 @@ pub mod tests {
         assert_eq!(updates.get(&address_2), None);
         assert_eq!(updates.get(&address_3), Some(&update_3));
     }
+
+    #[test]
+    fn retrieve_latency_for_signer_state_machine_updates() {
+        let db_path = tmp_db_path();
+        let mut db = SignerDb::new(db_path).expect("Failed to create signer db");
+        let reward_cycle_1 = 1;
+        let address_1 = StacksAddress::p2pkh(false, &StacksPublicKey::new());
+        let update_1 = StateMachineUpdate::new(
+            0,
+            3,
+            StateMachineUpdateContent::V0 {
+                burn_block: ConsensusHash([0x55; 20]),
+                burn_block_height: 100,
+                current_miner: StateMachineUpdateMinerState::ActiveMiner {
+                    current_miner_pkh: Hash160([0xab; 20]),
+                    tenure_id: ConsensusHash([0x44; 20]),
+                    parent_tenure_id: ConsensusHash([0x22; 20]),
+                    parent_tenure_last_block: StacksBlockId([0x33; 32]),
+                    parent_tenure_last_block_height: 1,
+                },
+            },
+        )
+        .unwrap();
+        let time_1 = SystemTime::UNIX_EPOCH;
+
+        let address_2 = StacksAddress::p2pkh(false, &StacksPublicKey::new());
+        let update_2 = StateMachineUpdate::new(
+            0,
+            4,
+            StateMachineUpdateContent::V0 {
+                burn_block: ConsensusHash([0x55; 20]),
+                burn_block_height: 100,
+                current_miner: StateMachineUpdateMinerState::NoValidMiner,
+            },
+        )
+        .unwrap();
+        let time_2 = SystemTime::UNIX_EPOCH + Duration::from_secs(1);
+
+        let address_3 = StacksAddress::p2pkh(false, &StacksPublicKey::new());
+        let update_3 = StateMachineUpdate::new(
+            0,
+            2,
+            StateMachineUpdateContent::V0 {
+                burn_block: ConsensusHash([0x66; 20]),
+                burn_block_height: 101,
+                current_miner: StateMachineUpdateMinerState::NoValidMiner,
+            },
+        )
+        .unwrap();
+        let time_3 = SystemTime::UNIX_EPOCH + Duration::from_secs(10);
+
+        assert_eq!(
+            0,
+            db.get_signer_state_machine_updates_latency(reward_cycle_1)
+                .unwrap(),
+            "latency on empty database should be 0 seconds for reward_cycle {reward_cycle_1}"
+        );
+
+        db.insert_state_machine_update(reward_cycle_1, &address_1, &update_1, &time_1)
+            .expect("Unable to insert block into db");
+
+        assert_eq!(
+            0,
+            db.get_signer_state_machine_updates_latency(reward_cycle_1)
+                .unwrap(),
+            "latency between same update should be 0 seconds"
+        );
+
+        db.insert_state_machine_update(reward_cycle_1, &address_2, &update_2, &time_2)
+            .expect("Unable to insert block into db");
+
+        assert_eq!(
+            1,
+            db.get_signer_state_machine_updates_latency(reward_cycle_1)
+                .unwrap(),
+            "latency between updates should be 1 second"
+        );
+
+        db.insert_state_machine_update(reward_cycle_1, &address_3, &update_3, &time_3)
+            .expect("Unable to insert block into db");
+
+        assert_eq!(
+            10,
+            db.get_signer_state_machine_updates_latency(reward_cycle_1)
+                .unwrap(),
+            "latency between updates should be 10 second"
+        );
+    }
 }

stacks-signer/src/v0/signer.rs

@@ -734,6 +734,7 @@ impl Signer {
             &mut self.global_state_evaluator,
             self.stacks_address,
             version,
+            self.reward_cycle,
         );
     }
 

stacks-signer/src/v0/signer_state.rs

@@ -200,6 +200,9 @@ impl GlobalStateEvaluator {
         };
         let (global_burn_view, _) = self.determine_global_burn_view(local_address, local_update)?;
         if current_burn_block != global_burn_view {
+            crate::monitoring::actions::increment_signer_agreement_state_conflict(
+                crate::monitoring::SignerAgreementStateConflict::BurnBlockDelay,
+            );
             return None;
         }
         let mut current_miners = HashMap::new();
@@ -240,6 +243,9 @@ impl GlobalStateEvaluator {
                 }
             }
         }
+        crate::monitoring::actions::increment_signer_agreement_state_conflict(
+            crate::monitoring::SignerAgreementStateConflict::MinerView,
+        );
         None
     }
 
@@ -822,6 +828,7 @@ impl LocalStateMachine {
         eval: &mut GlobalStateEvaluator,
         local_address: StacksAddress,
         local_supported_signer_protocol_version: u64,
+        reward_cycle: u64,
     ) {
         // Before we ever access eval...we should make sure to include our own local state machine update message in the evaluation
         let Ok(mut local_update) =
@@ -859,6 +866,9 @@ impl LocalStateMachine {
 
         if active_signer_protocol_version != old_protocol_version {
             info!("Updating active signer protocol version from {old_protocol_version} to {active_signer_protocol_version}");
+            crate::monitoring::actions::increment_signer_agreement_state_change_reason(
+                crate::monitoring::SignerAgreementStateChangeReason::ProtocolUpgrade,
+            );
             *self = Self::Initialized(SignerStateMachine {
                 burn_block: *burn_block,
                 burn_block_height: *burn_block_height,
@@ -907,6 +917,12 @@ impl LocalStateMachine {
                 "current_miner" => ?current_miner,
                 "new_miner" => ?new_miner,
             );
+            crate::monitoring::actions::increment_signer_agreement_state_change_reason(
+                crate::monitoring::SignerAgreementStateChangeReason::MinerViewUpdate,
+            );
+            Self::monitor_miner_parent_tenure_update(&current_miner, &new_miner);
+            Self::monitor_capitulation_latency(signerdb, reward_cycle);
+
             *self = Self::Initialized(SignerStateMachine {
                 burn_block,
                 burn_block_height,
@@ -917,6 +933,47 @@ impl LocalStateMachine {
         }
     }
 
+    #[allow(unused_variables)]
+    fn monitor_miner_parent_tenure_update(
+        current_miner: &StateMachineUpdateMinerState,
+        new_miner: &StateMachineUpdateMinerState,
+    ) {
+        #[cfg(feature = "monitoring_prom")]
+        if let (
+            StateMachineUpdateMinerState::ActiveMiner {
+                parent_tenure_id: current_parent_tenure,
+                ..
+            },
+            StateMachineUpdateMinerState::ActiveMiner {
+                parent_tenure_id: new_parent_tenure,
+                ..
+            },
+        ) = (&current_miner, &new_miner)
+        {
+            if current_parent_tenure != new_parent_tenure {
+                crate::monitoring::actions::increment_signer_agreement_state_change_reason(
+                    crate::monitoring::SignerAgreementStateChangeReason::MinerParentTenureUpdate,
+                );
+            }
+        }
+    }
+
+    #[allow(unused_variables)]
+    fn monitor_capitulation_latency(signer_db: &SignerDb, reward_cycle: u64) {
+        #[cfg(feature = "monitoring_prom")]
+        {
+            let latency_result = signer_db.get_signer_state_machine_updates_latency(reward_cycle);
+            match latency_result {
+                Ok(seconds) => {
+                    crate::monitoring::actions::record_signer_agreement_capitulation_latency(
+                        seconds,
+                    )
+                }
+                Err(e) => warn!("Failed to retrieve state updates latency in signerdb: {e}"),
+            }
+        }
+    }
+
     /// Extract out the tx replay set if it exists
     pub fn get_tx_replay_set(&self) -> Option<Vec<StacksTransaction>> {
         let Self::Initialized(state) = self else {