From f85ac9e56718264c48a4af33e7d2514319022a2d Mon Sep 17 00:00:00 2001 From: Micaiah Reid Date: Fri, 12 Apr 2024 07:35:07 -0600 Subject: [PATCH] fix: correctly track bitcoin block append metrics; add additional metrics (#563) Addresses #562 --- .../src/indexer/fork_scratch_pad.rs | 17 +- components/chainhook-sdk/src/indexer/mod.rs | 15 +- .../src/indexer/stacks/blocks_pool.rs | 17 +- components/chainhook-sdk/src/monitoring.rs | 220 +++++++++++++++--- components/chainhook-sdk/src/observer/http.rs | 44 ++-- components/chainhook-sdk/src/observer/mod.rs | 70 +++--- .../chainhook-sdk/src/observer/tests/mod.rs | 2 - 7 files changed, 305 insertions(+), 80 deletions(-) diff --git a/components/chainhook-sdk/src/indexer/fork_scratch_pad.rs b/components/chainhook-sdk/src/indexer/fork_scratch_pad.rs index ddf467aa..6e56b281 100644 --- a/components/chainhook-sdk/src/indexer/fork_scratch_pad.rs +++ b/components/chainhook-sdk/src/indexer/fork_scratch_pad.rs @@ -105,7 +105,7 @@ impl ForkScratchPad { } None => { ctx.try_log(|logger| { - slog::debug!( + slog::error!( logger, "Unable to process Bitcoin {} - inboxed for later", header.block_identifier @@ -253,6 +253,13 @@ impl ForkScratchPad { } } + ctx.try_log(|logger| { + slog::debug!( + logger, + "Removing {} confirmed blocks from block store.", + canonical_segment[6..].len() + ) + }); for confirmed_block in canonical_segment[6..].into_iter() { let block = match self.headers_store.remove(confirmed_block) { None => { @@ -267,6 +274,14 @@ impl ForkScratchPad { } // Prune data + ctx.try_log(|logger| { + slog::debug!( + logger, + "Pruning {} blocks and {} forks.", + blocks_to_prune.len(), + forks_to_prune.len() + ) + }); for block_to_prune in blocks_to_prune { self.headers_store.remove(&block_to_prune); } diff --git a/components/chainhook-sdk/src/indexer/mod.rs b/components/chainhook-sdk/src/indexer/mod.rs index e7591f23..b9b1aa54 100644 --- a/components/chainhook-sdk/src/indexer/mod.rs +++ b/components/chainhook-sdk/src/indexer/mod.rs @@ -143,17 +143,24 @@ impl Indexer { event } - pub fn handle_stacks_marshalled_block( + pub fn standardize_stacks_marshalled_block( &mut self, marshalled_block: JsonValue, ctx: &Context, - ) -> Result, String> { - let block = stacks::standardize_stacks_marshalled_block( + ) -> Result { + stacks::standardize_stacks_marshalled_block( &self.config, marshalled_block, &mut self.stacks_context, ctx, - )?; + ) + } + + pub fn process_stacks_block( + &mut self, + block: StacksBlockData, + ctx: &Context, + ) -> Result, String> { self.stacks_blocks_pool.process_block(block, ctx) } diff --git a/components/chainhook-sdk/src/indexer/stacks/blocks_pool.rs b/components/chainhook-sdk/src/indexer/stacks/blocks_pool.rs index 7ab026b6..025e5079 100644 --- a/components/chainhook-sdk/src/indexer/stacks/blocks_pool.rs +++ b/components/chainhook-sdk/src/indexer/stacks/blocks_pool.rs @@ -357,6 +357,13 @@ impl StacksBlockPool { // that must be merged in Block 7. let mut blocks_to_confirm = canonical_segment[6..].to_vec(); blocks_to_confirm.reverse(); + ctx.try_log(|logger| { + slog::debug!( + logger, + "Removing {} confirmed blocks from block store.", + blocks_to_confirm.len() + ) + }); for confirmed_block in blocks_to_confirm.iter() { let block = match self.block_store.remove(confirmed_block) { None => { @@ -371,6 +378,14 @@ impl StacksBlockPool { } // Prune data + ctx.try_log(|logger| { + slog::debug!( + logger, + "Pruning {} blocks and {} forks.", + blocks_to_prune.len(), + forks_to_prune.len() + ) + }); for block_to_prune in blocks_to_prune { self.block_store.remove(&block_to_prune); self.micro_forks.remove(&block_to_prune); @@ -381,8 +396,6 @@ impl StacksBlockPool { self.forks.remove(&fork_id); } // confirmed_blocks.reverse(); - - ctx.try_log(|logger| slog::debug!(logger, "AFTER: {:?}", confirmed_blocks.len())); } pub fn process_microblocks( diff --git a/components/chainhook-sdk/src/monitoring.rs b/components/chainhook-sdk/src/monitoring.rs index ff9ab2b9..f3872ac1 100644 --- a/components/chainhook-sdk/src/monitoring.rs +++ b/components/chainhook-sdk/src/monitoring.rs @@ -18,14 +18,23 @@ type UInt64Gauge = GenericGauge; #[derive(Debug, Clone)] pub struct PrometheusMonitoring { - pub stx_highest_block_ingested: UInt64Gauge, + pub stx_highest_block_appended: UInt64Gauge, + pub stx_highest_block_received: UInt64Gauge, + pub stx_highest_block_evaluated: UInt64Gauge, + pub stx_canonical_fork_lag: UInt64Gauge, + pub stx_block_evaluation_lag: UInt64Gauge, pub stx_last_reorg_timestamp: IntGauge, pub stx_last_reorg_applied_blocks: UInt64Gauge, pub stx_last_reorg_rolled_back_blocks: UInt64Gauge, pub stx_last_block_ingestion_time: UInt64Gauge, pub stx_registered_predicates: UInt64Gauge, pub stx_deregistered_predicates: UInt64Gauge, - pub btc_highest_block_ingested: UInt64Gauge, + // + pub btc_highest_block_appended: UInt64Gauge, + pub btc_highest_block_received: UInt64Gauge, + pub btc_highest_block_evaluated: UInt64Gauge, + pub btc_canonical_fork_lag: UInt64Gauge, + pub btc_block_evaluation_lag: UInt64Gauge, pub btc_last_reorg_timestamp: IntGauge, pub btc_last_reorg_applied_blocks: UInt64Gauge, pub btc_last_reorg_rolled_back_blocks: UInt64Gauge, @@ -38,10 +47,31 @@ pub struct PrometheusMonitoring { impl PrometheusMonitoring { pub fn new() -> PrometheusMonitoring { let registry = Registry::new(); - let stx_highest_block_ingested = PrometheusMonitoring::create_and_register_uint64_gauge( + // stacks metrics + let stx_highest_block_appended = PrometheusMonitoring::create_and_register_uint64_gauge( ®istry, - "chainhook_stx_highest_block_ingested", - "The highest Stacks block ingested by the Chainhook node.", + "chainhook_stx_highest_block_appended", + "The highest Stacks block successfully appended to a Chainhook node fork.", + ); + let stx_highest_block_received = PrometheusMonitoring::create_and_register_uint64_gauge( + ®istry, + "chainhook_stx_highest_block_received", + "The highest Stacks block received by the Chainhook node from the Stacks node.", + ); + let stx_highest_block_evaluated = PrometheusMonitoring::create_and_register_uint64_gauge( + ®istry, + "chainhook_stx_highest_block_evaluated", + "The highest Stacks block successfully evaluated against predicates.", + ); + let stx_canonical_fork_lag = PrometheusMonitoring::create_and_register_uint64_gauge( + ®istry, + "chainhook_stx_canonical_fork_lag", + "The difference between the highest Stacks block received and the highest Stacks block appended.", + ); + let stx_block_evaluation_lag = PrometheusMonitoring::create_and_register_uint64_gauge( + ®istry, + "chainhook_stx_block_evaluation_lag", + "The difference between the highest Stacks block appended and the highest Stacks block evaluated.", ); let stx_last_reorg_timestamp = PrometheusMonitoring::create_and_register_int_gauge( ®istry, @@ -74,10 +104,32 @@ impl PrometheusMonitoring { "chainhook_stx_deregistered_predicates", "The number of Stacks predicates that have been deregistered by the Chainhook node.", ); - let btc_highest_block_ingested = PrometheusMonitoring::create_and_register_uint64_gauge( + + // bitcoin metrics + let btc_highest_block_appended = PrometheusMonitoring::create_and_register_uint64_gauge( + ®istry, + "chainhook_btc_highest_block_appended", + "The highest Bitcoin block successfully appended to a Chainhook node fork.", + ); + let btc_highest_block_received = PrometheusMonitoring::create_and_register_uint64_gauge( + ®istry, + "chainhook_btc_highest_block_received", + "The highest Bitcoin block received by the Chainhook node from the Bitcoin node.", + ); + let btc_highest_block_evaluated = PrometheusMonitoring::create_and_register_uint64_gauge( + ®istry, + "chainhook_btc_highest_block_evaluated", + "The highest Bitcoin block successfully evaluated against predicates.", + ); + let btc_canonical_fork_lag = PrometheusMonitoring::create_and_register_uint64_gauge( ®istry, - "chainhook_btc_highest_block_ingested", - "The highest Bitcoin block ingested by the Chainhook node.", + "chainhook_btc_canonical_fork_lag", + "The difference between the highest Bitcoin block received and the highest Bitcoin block appended.", + ); + let btc_block_evaluation_lag = PrometheusMonitoring::create_and_register_uint64_gauge( + ®istry, + "chainhook_btc_block_evaluation_lag", + "The difference between the highest Bitcoin block appended and the highest Bitcoin block evaluated.", ); let btc_last_reorg_timestamp = PrometheusMonitoring::create_and_register_int_gauge( ®istry, @@ -113,14 +165,23 @@ impl PrometheusMonitoring { ); PrometheusMonitoring { - stx_highest_block_ingested, + stx_highest_block_appended, + stx_highest_block_received, + stx_highest_block_evaluated, + stx_canonical_fork_lag, + stx_block_evaluation_lag, stx_last_reorg_timestamp, stx_last_reorg_applied_blocks, stx_last_reorg_rolled_back_blocks, stx_last_block_ingestion_time, stx_registered_predicates, stx_deregistered_predicates, - btc_highest_block_ingested, + // + btc_highest_block_appended, + btc_highest_block_received, + btc_highest_block_evaluated, + btc_canonical_fork_lag, + btc_block_evaluation_lag, btc_last_reorg_timestamp, btc_last_reorg_applied_blocks, btc_last_reorg_rolled_back_blocks, @@ -130,7 +191,7 @@ impl PrometheusMonitoring { registry, } } - + // setup helpers pub fn create_and_register_uint64_gauge( registry: &Registry, name: &str, @@ -147,6 +208,7 @@ impl PrometheusMonitoring { g } + // stx helpers pub fn stx_metrics_deregister_predicate(&self) { self.stx_registered_predicates.dec(); self.stx_deregistered_predicates.inc(); @@ -171,10 +233,18 @@ impl PrometheusMonitoring { .set(rolled_back_blocks); } - pub fn stx_metrics_ingest_block(&self, new_block_height: u64) { - let highest_ingested = self.stx_highest_block_ingested.get(); - if new_block_height > highest_ingested { - self.stx_highest_block_ingested.set(new_block_height); + pub fn stx_metrics_block_appeneded(&self, new_block_height: u64) { + let highest_appended = self.stx_highest_block_appended.get(); + if new_block_height > highest_appended { + self.stx_highest_block_appended.set(new_block_height); + + let highest_received = self.stx_highest_block_received.get(); + self.stx_canonical_fork_lag + .set(highest_received.saturating_sub(new_block_height)); + + let highest_evaluated = self.stx_highest_block_evaluated.get(); + self.stx_block_evaluation_lag + .set(new_block_height.saturating_sub(highest_evaluated)); } let time = SystemTime::now() .duration_since(UNIX_EPOCH) @@ -183,6 +253,29 @@ impl PrometheusMonitoring { self.stx_last_block_ingestion_time.set(time); } + pub fn stx_metrics_block_received(&self, new_block_height: u64) { + let highest_received = self.stx_highest_block_received.get(); + if new_block_height > highest_received { + self.stx_highest_block_received.set(new_block_height); + + let highest_appended = self.stx_highest_block_appended.get(); + self.stx_canonical_fork_lag + .set(new_block_height.saturating_sub(highest_appended)); + } + } + + pub fn stx_metrics_block_evaluated(&self, new_block_height: u64) { + let highest_evaluated = self.stx_highest_block_evaluated.get(); + if new_block_height > highest_evaluated { + self.stx_highest_block_evaluated.set(new_block_height); + + let highest_appended = self.stx_highest_block_appended.get(); + self.stx_block_evaluation_lag + .set(highest_appended.saturating_sub(new_block_height)); + } + } + + // btc helpers pub fn btc_metrics_deregister_predicate(&self) { self.btc_registered_predicates.dec(); self.btc_deregistered_predicates.inc(); @@ -208,10 +301,18 @@ impl PrometheusMonitoring { .set(rolled_back_blocks); } - pub fn btc_metrics_ingest_block(&self, new_block_height: u64) { - let highest_ingested = self.btc_highest_block_ingested.get(); - if new_block_height > highest_ingested { - self.btc_highest_block_ingested.set(new_block_height); + pub fn btc_metrics_block_appended(&self, new_block_height: u64) { + let highest_appended = self.btc_highest_block_appended.get(); + if new_block_height > highest_appended { + self.btc_highest_block_appended.set(new_block_height); + + let highest_received = self.btc_highest_block_received.get(); + self.btc_canonical_fork_lag + .set(highest_received.saturating_sub(new_block_height)); + + let highest_evaluated = self.btc_highest_block_evaluated.get(); + self.btc_block_evaluation_lag + .set(new_block_height.saturating_sub(highest_evaluated)); } let time = SystemTime::now() .duration_since(UNIX_EPOCH) @@ -220,10 +321,37 @@ impl PrometheusMonitoring { self.btc_last_block_ingestion_time.set(time); } + pub fn btc_metrics_block_received(&self, new_block_height: u64) { + let highest_received = self.btc_highest_block_received.get(); + if new_block_height > highest_received { + self.btc_highest_block_received.set(new_block_height); + + let highest_appended = self.btc_highest_block_appended.get(); + + self.btc_canonical_fork_lag + .set(new_block_height.saturating_sub(highest_appended)); + } + } + + pub fn btc_metrics_block_evaluated(&self, new_block_height: u64) { + let highest_evaluated = self.btc_highest_block_evaluated.get(); + if new_block_height > highest_evaluated { + self.btc_highest_block_evaluated.set(new_block_height); + + let highest_appended = self.btc_highest_block_appended.get(); + self.btc_block_evaluation_lag + .set(highest_appended.saturating_sub(new_block_height)); + } + } + pub fn get_metrics(&self) -> JsonValue { json!({ "bitcoin": { - "tip_height": self.btc_highest_block_ingested.get(), + "last_received_block_height": self.btc_highest_block_received.get(), + "last_appended_block_height": self.btc_highest_block_appended.get(), + "last_evaluated_block_height": self.btc_highest_block_evaluated.get(), + "canonical_fork_lag": self.btc_canonical_fork_lag.get(), + "block_evaluation_lag": self.btc_block_evaluation_lag.get(), "last_block_ingestion_at": self.btc_last_block_ingestion_time.get(), "last_reorg": { "timestamp": self.btc_last_reorg_timestamp.get(), @@ -234,7 +362,11 @@ impl PrometheusMonitoring { "deregistered_predicates": self.btc_deregistered_predicates.get(), }, "stacks": { - "tip_height": self.stx_highest_block_ingested.get(), + "last_received_block_height": self.stx_highest_block_received.get(), + "last_appended_block_height": self.stx_highest_block_appended.get(), + "last_evaluated_block_height": self.stx_highest_block_evaluated.get(), + "canonical_fork_lag": self.stx_canonical_fork_lag.get(), + "block_evaluation_lag": self.btc_block_evaluation_lag.get(), "last_block_ingestion_at": self.stx_last_block_ingestion_time.get(), "last_reorg": { "timestamp": self.stx_last_reorg_timestamp.get(), @@ -358,17 +490,30 @@ mod test { #[test] fn it_tracks_stx_block_ingestion() { let prometheus = PrometheusMonitoring::new(); - assert_eq!(prometheus.stx_highest_block_ingested.get(), 0); + assert_eq!(prometheus.stx_highest_block_appended.get(), 0); assert_eq!(prometheus.stx_last_block_ingestion_time.get(), 0); - prometheus.stx_metrics_ingest_block(100); - assert_eq!(prometheus.stx_highest_block_ingested.get(), 100); + // receive a block + prometheus.stx_metrics_block_received(100); + // verify our lag in block appendation + assert_eq!(prometheus.stx_canonical_fork_lag.get(), 100); + // now append the block + prometheus.stx_metrics_block_appeneded(100); + assert_eq!(prometheus.stx_highest_block_appended.get(), 100); let time = prometheus.stx_last_block_ingestion_time.get(); assert!(time > 0); + // verify our lag is resolved after appending + assert_eq!(prometheus.stx_canonical_fork_lag.get(), 0); + // verify our lag in block evaluation + assert_eq!(prometheus.stx_block_evaluation_lag.get(), 100); + // now evaluate a block + prometheus.stx_metrics_block_evaluated(100); + // verify our lag is resolved after evaluating + assert_eq!(prometheus.stx_block_evaluation_lag.get(), 0); // ingesting a block lower than previous tip will // update ingestion time but not highest block ingested sleep(Duration::new(1, 0)); - prometheus.stx_metrics_ingest_block(99); - assert_eq!(prometheus.stx_highest_block_ingested.get(), 100); + prometheus.stx_metrics_block_appeneded(99); + assert_eq!(prometheus.stx_highest_block_appended.get(), 100); assert!(prometheus.stx_last_block_ingestion_time.get() > time); } @@ -403,17 +548,30 @@ mod test { #[test] fn it_tracks_btc_block_ingestion() { let prometheus = PrometheusMonitoring::new(); - assert_eq!(prometheus.btc_highest_block_ingested.get(), 0); + assert_eq!(prometheus.btc_highest_block_appended.get(), 0); assert_eq!(prometheus.btc_last_block_ingestion_time.get(), 0); - prometheus.btc_metrics_ingest_block(100); - assert_eq!(prometheus.btc_highest_block_ingested.get(), 100); + // receive a block + prometheus.btc_metrics_block_received(100); + // verify our lag in block appendation + assert_eq!(prometheus.btc_canonical_fork_lag.get(), 100); + // now append the block + prometheus.btc_metrics_block_appended(100); + assert_eq!(prometheus.btc_highest_block_appended.get(), 100); let time = prometheus.btc_last_block_ingestion_time.get(); assert!(time > 0); + // verify our lag is resolved after appending + assert_eq!(prometheus.btc_canonical_fork_lag.get(), 0); + // verify our lag in block evaluation + assert_eq!(prometheus.btc_block_evaluation_lag.get(), 100); + // now evaluate a block + prometheus.btc_metrics_block_evaluated(100); + // verify our lag is resolved after evaluating + assert_eq!(prometheus.btc_block_evaluation_lag.get(), 0); // ingesting a block lower than previous tip will // update ingestion time but not highest block ingested sleep(Duration::new(1, 0)); - prometheus.btc_metrics_ingest_block(99); - assert_eq!(prometheus.btc_highest_block_ingested.get(), 100); + prometheus.btc_metrics_block_appended(99); + assert_eq!(prometheus.btc_highest_block_appended.get(), 100); assert!(prometheus.btc_last_block_ingestion_time.get() > time); } } diff --git a/components/chainhook-sdk/src/observer/http.rs b/components/chainhook-sdk/src/observer/http.rs index a446968c..4687ddd0 100644 --- a/components/chainhook-sdk/src/observer/http.rs +++ b/components/chainhook-sdk/src/observer/http.rs @@ -20,7 +20,7 @@ pub fn handle_ping( ctx: &State, prometheus_monitoring: &State, ) -> Json { - ctx.try_log(|logger| slog::info!(logger, "GET /ping")); + ctx.try_log(|logger| slog::debug!(logger, "GET /ping")); Json(json!({ "status": 200, @@ -34,6 +34,7 @@ pub async fn handle_new_bitcoin_block( bitcoin_config: &State, bitcoin_block: Json, background_job_tx: &State>>>, + prometheus_monitoring: &State, ctx: &State, ) -> Json { if bitcoin_config @@ -74,6 +75,8 @@ pub async fn handle_new_bitcoin_block( }; let header = block.get_block_header(); + let block_height = header.block_identifier.index; + prometheus_monitoring.btc_metrics_block_received(block_height); match background_job_tx.lock() { Ok(tx) => { let _ = tx.send(ObserverCommand::ProcessBitcoinBlock(block)); @@ -112,6 +115,7 @@ pub async fn handle_new_bitcoin_block( match chain_update { Ok(Some(chain_event)) => { + prometheus_monitoring.btc_metrics_block_appended(block_height); match background_job_tx.lock() { Ok(tx) => { let _ = tx.send(ObserverCommand::PropagateBitcoinChainEvent(chain_event)); @@ -150,6 +154,7 @@ pub fn handle_new_stacks_block( indexer_rw_lock: &State>>, marshalled_block: Json, background_job_tx: &State>>>, + prometheus_monitoring: &State, ctx: &State, ) -> Json { ctx.try_log(|logger| slog::info!(logger, "POST /new_block")); @@ -157,12 +162,24 @@ pub fn handle_new_stacks_block( // kind of update that this new block would imply, taking // into account the last 7 blocks. // TODO(lgalabru): use _pox_config - let (_pox_config, chain_event) = match indexer_rw_lock.inner().write() { + let (_pox_config, chain_event, new_tip) = match indexer_rw_lock.inner().write() { Ok(mut indexer) => { let pox_config = indexer.get_pox_config(); - let chain_event = - indexer.handle_stacks_marshalled_block(marshalled_block.into_inner(), &ctx); - (pox_config, chain_event) + let block = match indexer + .standardize_stacks_marshalled_block(marshalled_block.into_inner(), ctx) + { + Ok(block) => block, + Err(e) => { + return Json(json!({ + "status": 500, + "result": format!("Unable to standardize stacks block {}", e), + })); + } + }; + let new_tip = block.block_identifier.index; + prometheus_monitoring.stx_metrics_block_received(new_tip); + let chain_event = indexer.process_stacks_block(block, &ctx); + (pox_config, chain_event, new_tip) } Err(e) => { ctx.try_log(|logger| { @@ -181,6 +198,7 @@ pub fn handle_new_stacks_block( match chain_event { Ok(Some(chain_event)) => { + prometheus_monitoring.stx_metrics_block_appeneded(new_tip); let background_job_tx = background_job_tx.inner(); match background_job_tx.lock() { Ok(tx) => { @@ -224,7 +242,7 @@ pub fn handle_new_microblocks( background_job_tx: &State>>>, ctx: &State, ) -> Json { - ctx.try_log(|logger| slog::info!(logger, "POST /new_microblocks")); + ctx.try_log(|logger| slog::debug!(logger, "POST /new_microblocks")); // Standardize the structure of the microblock, and identify the // kind of update that this new microblock would imply let chain_event = match indexer_rw_lock.inner().write() { @@ -292,7 +310,7 @@ pub fn handle_new_mempool_tx( background_job_tx: &State>>>, ctx: &State, ) -> Json { - ctx.try_log(|logger| slog::info!(logger, "POST /new_mempool_tx")); + ctx.try_log(|logger| slog::debug!(logger, "POST /new_mempool_tx")); let transactions = raw_txs .iter() .map(|tx_data| { @@ -323,7 +341,7 @@ pub fn handle_new_mempool_tx( #[post("/drop_mempool_tx", format = "application/json")] pub fn handle_drop_mempool_tx(ctx: &State) -> Json { - ctx.try_log(|logger| slog::info!(logger, "POST /drop_mempool_tx")); + ctx.try_log(|logger| slog::debug!(logger, "POST /drop_mempool_tx")); // TODO(lgalabru): use propagate mempool events Json(json!({ "status": 200, @@ -333,7 +351,7 @@ pub fn handle_drop_mempool_tx(ctx: &State) -> Json { #[post("/attachments/new", format = "application/json")] pub fn handle_new_attachement(ctx: &State) -> Json { - ctx.try_log(|logger| slog::info!(logger, "POST /attachments/new")); + ctx.try_log(|logger| slog::debug!(logger, "POST /attachments/new")); Json(json!({ "status": 200, "result": "Ok", @@ -342,7 +360,7 @@ pub fn handle_new_attachement(ctx: &State) -> Json { #[post("/mined_block", format = "application/json", data = "")] pub fn handle_mined_block(payload: Json, ctx: &State) -> Json { - ctx.try_log(|logger| slog::info!(logger, "POST /mined_block {:?}", payload)); + ctx.try_log(|logger| slog::debug!(logger, "POST /mined_block {:?}", payload)); Json(json!({ "status": 200, "result": "Ok", @@ -351,7 +369,7 @@ pub fn handle_mined_block(payload: Json, ctx: &State) -> Jso #[post("/mined_microblock", format = "application/json", data = "")] pub fn handle_mined_microblock(payload: Json, ctx: &State) -> Json { - ctx.try_log(|logger| slog::info!(logger, "POST /mined_microblock {:?}", payload)); + ctx.try_log(|logger| slog::debug!(logger, "POST /mined_microblock {:?}", payload)); Json(json!({ "status": 200, "result": "Ok", @@ -364,7 +382,7 @@ pub async fn handle_bitcoin_wallet_rpc_call( bitcoin_rpc_call: Json, ctx: &State, ) -> Json { - ctx.try_log(|logger| slog::info!(logger, "POST /wallet")); + ctx.try_log(|logger| slog::debug!(logger, "POST /wallet")); use base64::engine::general_purpose::STANDARD as BASE64; use base64::engine::Engine as _; @@ -402,7 +420,7 @@ pub async fn handle_bitcoin_rpc_call( background_job_tx: &State>>>, ctx: &State, ) -> Json { - ctx.try_log(|logger| slog::info!(logger, "POST /")); + ctx.try_log(|logger| slog::debug!(logger, "POST /")); use base64::engine::general_purpose::STANDARD as BASE64; use base64::engine::Engine as _; diff --git a/components/chainhook-sdk/src/observer/mod.rs b/components/chainhook-sdk/src/observer/mod.rs index 64ff4879..19ec0029 100644 --- a/components/chainhook-sdk/src/observer/mod.rs +++ b/components/chainhook-sdk/src/observer/mod.rs @@ -853,7 +853,6 @@ pub async fn start_observer_commands_handler( }); break; }; - prometheus_monitoring.btc_metrics_ingest_block(block.block_identifier.index); bitcoin_block_store.insert( block.block_identifier.clone(), @@ -879,12 +878,17 @@ pub async fn start_observer_commands_handler( let mut confirmed_blocks = vec![]; // Update Chain event before propagation - let chain_event = match blockchain_event { + let (chain_event, new_tip) = match blockchain_event { BlockchainEvent::BlockchainUpdatedWithHeaders(data) => { let mut blocks_to_mutate = vec![]; let mut new_blocks = vec![]; + let mut new_tip = 0; for header in data.new_headers.iter() { + if header.block_identifier.index > new_tip { + new_tip = header.block_identifier.index; + } + if store_update_required { let Some(block) = bitcoin_block_store.remove(&header.block_identifier) @@ -931,11 +935,14 @@ pub async fn start_observer_commands_handler( } } - BitcoinChainEvent::ChainUpdatedWithBlocks( - BitcoinChainUpdatedWithBlocksData { - new_blocks, - confirmed_blocks: confirmed_blocks.clone(), - }, + ( + BitcoinChainEvent::ChainUpdatedWithBlocks( + BitcoinChainUpdatedWithBlocksData { + new_blocks, + confirmed_blocks: confirmed_blocks.clone(), + }, + ), + new_tip, ) } BlockchainEvent::BlockchainUpdatedWithReorg(data) => { @@ -943,8 +950,13 @@ pub async fn start_observer_commands_handler( let mut blocks_to_mutate = vec![]; let mut blocks_to_apply = vec![]; + let mut new_tip = 0; for header in data.headers_to_apply.iter() { + if header.block_identifier.index > new_tip { + new_tip = header.block_identifier.index; + } + if store_update_required { let Some(block) = bitcoin_block_store.remove(&header.block_identifier) @@ -1021,18 +1033,20 @@ pub async fn start_observer_commands_handler( blocks_to_apply.len() as u64, blocks_to_rollback.len() as u64, ); - prometheus_monitoring.btc_metrics_ingest_block( - highest_tip_block.block_identifier.index, - ); } None => {} } - BitcoinChainEvent::ChainUpdatedWithReorg(BitcoinChainUpdatedWithReorgData { - blocks_to_apply, - blocks_to_rollback, - confirmed_blocks: confirmed_blocks.clone(), - }) + ( + BitcoinChainEvent::ChainUpdatedWithReorg( + BitcoinChainUpdatedWithReorgData { + blocks_to_apply, + blocks_to_rollback, + confirmed_blocks: confirmed_blocks.clone(), + }, + ), + new_tip, + ) } }; @@ -1190,6 +1204,8 @@ pub async fn start_observer_commands_handler( } } + prometheus_monitoring.btc_metrics_block_evaluated(new_tip); + if let Some(ref tx) = observer_events_tx { let _ = tx.send(ObserverEvent::BitcoinChainEvent((chain_event, report))); } @@ -1216,19 +1232,19 @@ pub async fn start_observer_commands_handler( stacks_chainhooks.len() ) }); + // track stacks chain metrics - match &chain_event { + let new_tip = match &chain_event { StacksChainEvent::ChainUpdatedWithBlocks(update) => { match update .new_blocks .iter() .max_by_key(|b| b.block.block_identifier.index) { - Some(highest_tip_update) => prometheus_monitoring - .stx_metrics_ingest_block( - highest_tip_update.block.block_identifier.index, - ), - None => {} + Some(highest_tip_update) => { + highest_tip_update.block.block_identifier.index + } + None => 0, } } StacksChainEvent::ChainUpdatedWithReorg(update) => { @@ -1243,15 +1259,13 @@ pub async fn start_observer_commands_handler( update.blocks_to_apply.len() as u64, update.blocks_to_rollback.len() as u64, ); - prometheus_monitoring.stx_metrics_ingest_block( - highest_tip_update.block.block_identifier.index, - ) + highest_tip_update.block.block_identifier.index } - None => {} + None => 0, } } - _ => {} - } + _ => 0, + }; // process hooks let (predicates_triggered, predicates_evaluated, predicates_expired) = @@ -1360,6 +1374,8 @@ pub async fn start_observer_commands_handler( let _ = send_request(request, 3, 1, &ctx).await; } + prometheus_monitoring.stx_metrics_block_evaluated(new_tip); + if let Some(ref tx) = observer_events_tx { let _ = tx.send(ObserverEvent::StacksChainEvent((chain_event, report))); } diff --git a/components/chainhook-sdk/src/observer/tests/mod.rs b/components/chainhook-sdk/src/observer/tests/mod.rs index d182fccc..55785472 100644 --- a/components/chainhook-sdk/src/observer/tests/mod.rs +++ b/components/chainhook-sdk/src/observer/tests/mod.rs @@ -553,8 +553,6 @@ fn test_stacks_chainhook_register_deregister() { // Should propagate block assert_stacks_chain_event(&observer_events_rx); - let thing = &prometheus_monitoring.registry.gather(); - println!("gathered, {:?}", thing); let _ = observer_commands_tx.send(ObserverCommand::Terminate); handle.join().expect("unable to terminate thread"); }