add additional trace logging and remove some unused logging

Blockstream · Apr 18, 2024 · 3d0d7fc · 3d0d7fc
1 parent a64561a
commit 3d0d7fc
Show file tree

Hide file tree

Showing 9 changed files with 52 additions and 47 deletions.
diff --git a/src/bin/electrs.rs b/src/bin/electrs.rs
@@ -2,6 +2,7 @@ extern crate error_chain;
 #[macro_use]
 extern crate log;
 
+
 extern crate electrs;
 
 use error_chain::ChainedError;
@@ -116,26 +117,24 @@ fn run_server(config: Arc<Config>) -> Result<()> {
     let electrum_server = ElectrumRPC::start(Arc::clone(&config), Arc::clone(&query), &metrics);
 
     loop {
+        trace!("signal.wait");
         if let Err(err) = signal.wait(Duration::from_secs(5), true) {
             info!("stopping server: {}", err);
             rest_server.stop();
             // the electrum server is stopped when dropped
             break;
         }
 
-        debug!("checking for new blocks, current_tip={}", tip);
-
+        trace!("calling getbestblockhash my tip={}", tip);
         // Index new blocks
         let current_tip = daemon.getbestblockhash()?;
 
-        debug!("new blockhash from bitcoind={}", current_tip);
-
         if current_tip != tip {
-            debug!("updating index to {}", current_tip);
+            trace!("retrieved NEW blockhash bitcoind new={}", current_tip);
             indexer.update(&daemon)?;
             tip = current_tip;
         } else {
-            debug!("tip unchanged, no update");
+            trace!("tip UNCHANGED")
         }
 
         // Update mempool
@@ -152,9 +151,11 @@ fn run_server(config: Arc<Config>) -> Result<()> {
 }
 
 fn main() {
+
     let config = Arc::new(Config::from_args());
     if let Err(e) = run_server(config) {
         error!("server failed: {}", e.display_chain());
         process::exit(1);
     }
+
 }
diff --git a/src/config.rs b/src/config.rs
@@ -388,6 +388,7 @@ impl Config {
             .map(|s| serde_json::from_str(s).expect("invalid --electrum-public-hosts"));
 
         let mut log = stderrlog::new();
+
         log.verbosity(m.occurrences_of("verbosity") as usize);
         log.timestamp(if m.is_present("timestamp") {
             stderrlog::Timestamp::Millisecond

diff --git a/src/electrum/mod.rs b/src/electrum/mod.rs
@@ -13,20 +13,20 @@ use std::collections::HashMap;
 use std::str::FromStr;
 
 use serde::{de, Deserialize, Deserializer, Serialize};
-use std::time::Instant;
+//use std::time::Instant;
 
 use crate::chain::BlockHash;
 use crate::errors::ResultExt;
-use crate::util::{BlockId, log_fn_duration};
+use crate::util::{BlockId};//, log_fn_duration};
 
 pub fn get_electrum_height(blockid: Option<BlockId>, has_unconfirmed_parents: bool) -> isize {
-    let t = Instant::now();
+  //  let t = Instant::now();
     let res = match (blockid, has_unconfirmed_parents) {
         (Some(blockid), _) => blockid.height as isize,
         (None, false) => 0,
         (None, true) => -1,
     };
-    log_fn_duration("electrum::mod::get_electrum_height", t.elapsed().as_micros());
+//    log_fn_duration("electrum::mod::get_electrum_height", t.elapsed().as_micros());
     res
 }
 

diff --git a/src/electrum/server.rs b/src/electrum/server.rs
@@ -25,7 +25,7 @@ use crate::errors::*;
 use crate::metrics::{Gauge, HistogramOpts, HistogramVec, MetricOpts, Metrics};
 use crate::new_index::{Query, Utxo};
 use crate::util::electrum_merkle::{get_header_merkle_proof, get_id_from_pos, get_tx_merkle_proof};
-use crate::util::{create_socket, spawn_thread, BlockId, BoolThen, Channel, FullHash, HeaderEntry, SyncChannel, log_fn_duration};
+use crate::util::{create_socket, spawn_thread, BlockId, BoolThen, Channel, FullHash, HeaderEntry, SyncChannel};//, log_fn_duration};
 
 const ELECTRS_VERSION: &str = env!("CARGO_PKG_VERSION");
 const PROTOCOL_VERSION: ProtocolVersion = ProtocolVersion::new(1, 4);
@@ -36,12 +36,12 @@ use crate::electrum::{DiscoveryManager, ServerFeatures};
 
 // TODO: Sha256dHash should be a generic hash-container (since script hash is single SHA256)
 fn hash_from_value(val: Option<&Value>) -> Result<Sha256dHash> {
-    let t = Instant::now();
+  //  let t = Instant::now();
     let script_hash = val.chain_err(|| "missing hash")?;
     let script_hash = script_hash.as_str().chain_err(|| "non-string hash")?;
     let script_hash = script_hash.parse().chain_err(|| "non-hex hash")?;
     let res = Ok(script_hash);
-    log_fn_duration("server::hash_from_value", t.elapsed().as_micros());
+ //   log_fn_duration("server::hash_from_value", t.elapsed().as_micros());
     res
 }
 
@@ -304,7 +304,7 @@ impl Connection {
     }
 
     fn blockchain_scripthash_get_history(&self, params: &[Value]) -> Result<Value> {
-        let t = Instant::now();
+      //  let t = Instant::now();
         let script_hash = hash_from_value(params.get(0)).chain_err(|| "bad script_hash")?;
         let history_txids = get_history(&self.query, &script_hash[..], self.txs_limit)?;
 
@@ -320,7 +320,7 @@ impl Connection {
                 GetHistoryResult { txid, height, fee }
             })
             .collect::<Vec<_>>()));
-        log_fn_duration("server::blockchain_scripthash_get_history", t.elapsed().as_micros());
+     //   log_fn_duration("server::blockchain_scripthash_get_history", t.elapsed().as_micros());
         res
     }
 
@@ -669,10 +669,10 @@ fn get_history(
     scripthash: &[u8],
     txs_limit: usize,
 ) -> Result<Vec<(Txid, Option<BlockId>)>> {
-    let t = Instant::now();
+ //   let t = Instant::now();
     // to avoid silently trunacting history entries, ask for one extra more than the limit and fail if it exists
     let history_txids = query.history_txids(scripthash, txs_limit + 1);
-    log_fn_duration("server::get_history", t.elapsed().as_micros());
+ //   log_fn_duration("server::get_history", t.elapsed().as_micros());
 
     ensure!(history_txids.len() <= txs_limit, ErrorKind::TooPopular);
     Ok(history_txids)

diff --git a/src/new_index/db.rs b/src/new_index/db.rs
@@ -1,10 +1,10 @@
 use rocksdb;
 
 use std::path::Path;
-use std::time::Instant;
+//use std::time::Instant;
 
 use crate::config::Config;
-use crate::util::{bincode, Bytes, log_fn_duration};
+use crate::util::{bincode, Bytes};//, log_fn_duration};
 
 static DB_VERSION: u32 = 1;
 
@@ -132,12 +132,12 @@ impl DB {
     }
 
     pub fn iter_scan_from(&self, prefix: &[u8], start_at: &[u8]) -> ScanIterator {
-        let t = Instant::now();
+        //let t = Instant::now();
         let iter = self.db.iterator(rocksdb::IteratorMode::From(
             start_at,
             rocksdb::Direction::Forward,
         ));
-        log_fn_duration("db::iter_scan_from", t.elapsed().as_micros());
+        //log_fn_duration("db::iter_scan_from", t.elapsed().as_micros());
         ScanIterator {
             prefix: prefix.to_vec(),
             iter,

diff --git a/src/new_index/mempool.rs b/src/new_index/mempool.rs
@@ -21,7 +21,7 @@ use crate::new_index::{
     SpendingInfo, SpendingInput, TxHistoryInfo, Utxo,
 };
 use crate::util::fees::{make_fee_histogram, TxFeeInfo};
-use crate::util::{extract_tx_prevouts, full_hash, has_prevout, is_spendable, Bytes, log_fn_duration};
+use crate::util::{extract_tx_prevouts, full_hash, has_prevout, is_spendable, Bytes};//, log_fn_duration};
 
 #[cfg(feature = "liquid")]
 use crate::elements::asset;
@@ -120,22 +120,22 @@ impl Mempool {
     }
 
     pub fn get_tx_fee(&self, txid: &Txid) -> Option<u64> {
-        let t = Instant::now();
+      //  let t = Instant::now();
         let res = Some(self.feeinfo.get(txid)?.fee);
-        log_fn_duration("mempool::get_tx_fee", t.elapsed().as_micros());
+     //   log_fn_duration("mempool::get_tx_fee", t.elapsed().as_micros());
         res
     }
 
     pub fn has_unconfirmed_parents(&self, txid: &Txid) -> bool {
-        let t = Instant::now();
+    //    let t = Instant::now();
         let tx = match self.txstore.get(txid) {
             Some(tx) => tx,
             None => return false,
         };
         let res = tx.input
             .iter()
             .any(|txin| self.txstore.contains_key(&txin.previous_output.txid));
-        log_fn_duration("mempool::has_unconfirmed_parents", t.elapsed().as_micros());
+    //    log_fn_duration("mempool::has_unconfirmed_parents", t.elapsed().as_micros());
         res
     }
 
@@ -158,7 +158,7 @@ impl Mempool {
     }
 
     pub fn history_txids(&self, scripthash: &[u8], limit: usize) -> Vec<Txid> {
-        let t  = Instant::now();
+  //      let t  = Instant::now();
         let _timer = self
             .latency
             .with_label_values(&["history_txids"])
@@ -172,7 +172,7 @@ impl Mempool {
                 .take(limit)
                 .collect()
         };
-        log_fn_duration("mempool::history_txids", t.elapsed().as_micros());
+    //    log_fn_duration("mempool::history_txids", t.elapsed().as_micros());
         res
     }
 
@@ -306,7 +306,7 @@ impl Mempool {
     }
 
     fn add(&mut self, txs: Vec<Transaction>) {
-        let t = Instant::now();
+        //let t = Instant::now();
         self.delta
             .with_label_values(&["add"])
             .observe(txs.len() as f64);
@@ -415,7 +415,7 @@ impl Mempool {
     }
 
     pub fn lookup_txos(&self, outpoints: &BTreeSet<OutPoint>) -> Result<HashMap<OutPoint, TxOut>> {
-        let t = Instant::now();
+        //let t = Instant::now();
         let _timer = self
             .latency
             .with_label_values(&["lookup_txos"])
@@ -505,7 +505,7 @@ impl Mempool {
     }
 
     pub fn update(mempool: &Arc<RwLock<Mempool>>, daemon: &Daemon) -> Result<()> {
-        let t = Instant::now();
+        //let t = Instant::now();
         let _timer = mempool.read().unwrap().latency.with_label_values(&["update"]).start_timer();
 
         // 1. Determine which transactions are no longer in the daemon's mempool and which ones have newly entered it

diff --git a/src/new_index/query.rs b/src/new_index/query.rs
@@ -90,7 +90,7 @@ impl Query {
     }
 
     pub fn history_txids(&self, scripthash: &[u8], limit: usize) -> Vec<(Txid, Option<BlockId>)> {
-        let t = Instant::now();
+        //let t = Instant::now();
         let confirmed_txids = self.chain.history_txids(scripthash, limit);
         let confirmed_len = confirmed_txids.len();
         let confirmed_txids = confirmed_txids.into_iter().map(|(tx, b)| (tx, Some(b)));
@@ -102,7 +102,7 @@ impl Query {
             .map(|tx| (tx, None));
 
         let res = confirmed_txids.chain(mempool_txids).collect();
-        log_fn_duration("query::history_txids", t.elapsed().as_micros());
+        //log_fn_duration("query::history_txids", t.elapsed().as_micros());
         res
     }
 

diff --git a/src/new_index/schema.rs b/src/new_index/schema.rs
@@ -20,7 +20,7 @@ use elements::{
 use std::collections::{BTreeSet, HashMap, HashSet};
 use std::path::Path;
 use std::sync::{Arc, RwLock};
-use std::time::Instant;
+//use std::time::Instant;
 
 use crate::chain::{
     BlockHash, BlockHeader, Network, OutPoint, Script, Transaction, TxOut, Txid, Value,
@@ -29,7 +29,7 @@ use crate::config::Config;
 use crate::daemon::Daemon;
 use crate::errors::*;
 use crate::metrics::{Gauge, HistogramOpts, HistogramTimer, HistogramVec, MetricOpts, Metrics};
-use crate::util::{bincode, full_hash, has_prevout, is_spendable, BlockHeaderMeta, BlockId, BlockMeta, BlockStatus, Bytes, HeaderEntry, HeaderList, ScriptToAddr, log_fn_duration};
+use crate::util::{bincode, full_hash, has_prevout, is_spendable, BlockHeaderMeta, BlockId, BlockMeta, BlockStatus, Bytes, HeaderEntry, HeaderList, ScriptToAddr};//, log_fn_duration};
 
 use crate::new_index::db::{DBFlush, DBRow, ReverseScanIterator, ScanIterator, DB};
 use crate::new_index::fetch::{start_fetcher, BlockEntry, FetchFrom};
@@ -455,12 +455,12 @@ impl ChainQuery {
     }
 
     pub fn history_iter_scan(&self, code: u8, hash: &[u8], start_height: usize) -> ScanIterator {
-        let t = Instant::now();
+   //     let t = Instant::now();
         let res = self.store.history_db.iter_scan_from(
             &TxHistoryRow::filter(code, &hash[..]),
             &TxHistoryRow::prefix_height(code, &hash[..], start_height as u32),
         );
-        log_fn_duration("chainquery::history_iter_scan", t.elapsed().as_micros());
+   //     log_fn_duration("chainquery::history_iter_scan", t.elapsed().as_micros());
         res
     }
     fn history_iter_scan_reverse(&self, code: u8, hash: &[u8]) -> ReverseScanIterator {
@@ -515,29 +515,29 @@ impl ChainQuery {
     }
 
     pub fn history_txids(&self, scripthash: &[u8], limit: usize) -> Vec<(Txid, BlockId)> {
-        let t = Instant::now();
+    //    let t = Instant::now();
         // scripthash lookup
         let res = self._history_txids(b'H', scripthash, limit);
-        log_fn_duration("chainquery::history_txids", t.elapsed().as_micros());
+  //      log_fn_duration("chainquery::history_txids", t.elapsed().as_micros());
         res
     }
 
     fn _history_txids(&self, code: u8, hash: &[u8], limit: usize) -> Vec<(Txid, BlockId)> {
-        let t = Instant::now();
-        let _timer = self.start_timer("history_txids");
+      //  let t = Instant::now();
+      //  let _timer = self.start_timer("history_txids");
         let res = self.history_iter_scan(code, hash, 0)
             .map(|row| TxHistoryRow::from_row(row).get_txid())
             .unique()
             .filter_map(|txid| self.tx_confirming_block(&txid).map(|b| (txid, b)))
             .take(limit)
             .collect();
-        log_fn_duration("chainquery::_history_txids", t.elapsed().as_micros());
+      //  log_fn_duration("chainquery::_history_txids", t.elapsed().as_micros());
         res
     }
 
     // TODO: avoid duplication with stats/stats_delta?
     pub fn utxo(&self, scripthash: &[u8], limit: usize) -> Result<Vec<Utxo>> {
-        let _timer = self.start_timer("utxo");
+  //      let _timer = self.start_timer("utxo");
 
         // get the last known utxo set and the blockhash it was updated for.
         // invalidates the cache if the block was orphaned.
@@ -1053,14 +1053,14 @@ fn lookup_txos(
     allow_missing: bool,
     num_threads: usize,
 ) -> HashMap<OutPoint, TxOut> {
-    let t = Instant::now();
+    //let t = Instant::now();
     let pool = rayon::ThreadPoolBuilder::new()
         .num_threads(num_threads) // we need to saturate SSD IOPS
         .thread_name(|i| format!("lookup-txo-{}", i))
         .build()
         .unwrap();
     //log_fn_duration("schema::ThreadPoolBuilder", t.elapsed().as_micros());
-    let t2 = Instant::now();
+    //let t2 = Instant::now();
     let res = pool.install(|| {
         outpoints
             .par_iter()
@@ -1082,7 +1082,7 @@ fn lookup_txos(
 }
 
 fn lookup_txo(txstore_db: &DB, outpoint: &OutPoint) -> Option<TxOut> {
-    let t = Instant::now();
+    //let t = Instant::now();
     let res = txstore_db
         .get(&TxOutRow::key(&outpoint))
         .map(|val| deserialize(&val).expect("failed to parse TxOut"));

diff --git a/src/signal.rs b/src/signal.rs
@@ -52,7 +52,10 @@ impl Waiter {
                 }
             }
             Ok(sig) => bail!(ErrorKind::Interrupt(sig)),
-            Err(RecvTimeoutError::Timeout) => Ok(()),
+            Err(RecvTimeoutError::Timeout) => {
+                trace!("timeout");
+                Ok(())
+            }
             Err(RecvTimeoutError::Disconnected) => bail!("signal hook channel disconnected"),
         }
     }