feat(logging): enable info-level logging during startup, drop to configured verbosity after

  Electrs has been observed starting, running for a few minutes, then
  dying silently in environments with no verbosity flags set. With the default
  verbosity (error-only), there is zero diagnostic output during startup.

  Initialize stderrlog at info level minimum during startup so key lifecycle
  milestones are always visible (daemon connection, DB open, sync progress,
  mempool load, server ready). After startup completes, log level drops to the
  user's configured verbosity via log::set_max_level().

  Also promotes a handful of debug!() calls in schema.rs and mempool.rs to
  info!() so they fire during the startup window.

Author: EddieHouston

src/bin/electrs.rs

@@ -57,10 +57,13 @@ fn run_server(config: Arc<Config>, salt_rwlock: Arc<RwLock<String>>) -> Result<(
     let metrics = Metrics::new(config.monitoring_addr);
     metrics.start();
 
+    info!("starting electrs");
+
     if let Some(zmq_addr) = config.zmq_addr.as_ref() {
         zmq::start(&format!("tcp://{zmq_addr}"), block_hash_notify);
     }
 
+    info!("connecting to daemon at {}", config.daemon_rpc_addr);
     let daemon = Arc::new(Daemon::new(
         &config.daemon_dir,
         &config.blocks_dir,
@@ -71,14 +74,17 @@ fn run_server(config: Arc<Config>, salt_rwlock: Arc<RwLock<String>>) -> Result<(
         signal.clone(),
         &metrics,
     )?);
+    info!("opening database at {}", config.db_path.display());
     let store = Arc::new(Store::open(&config, &metrics, true));
     let mut indexer = Indexer::open(
         Arc::clone(&store),
         fetch_from(&config, &store),
         &config,
         &metrics,
     );
+    info!("starting initial sync");
     let mut tip = indexer.update(&daemon)?;
+    info!("initial sync complete, tip at {}", tip);
 
     let chain = Arc::new(ChainQuery::new(
         Arc::clone(&store),
@@ -93,6 +99,7 @@ fn run_server(config: Arc<Config>, salt_rwlock: Arc<RwLock<String>>) -> Result<(
         precache::precache(&chain, precache_scripthashes);
     }
 
+    info!("loading mempool");
     let mempool = Arc::new(RwLock::new(Mempool::new(
         Arc::clone(&chain),
         &metrics,
@@ -130,6 +137,9 @@ fn run_server(config: Arc<Config>, salt_rwlock: Arc<RwLock<String>>) -> Result<(
         Arc::clone(&salt_rwlock),
     );
 
+    info!("startup complete, switching to configured log verbosity");
+    log::set_max_level(config.log_level_filter());
+
     let main_loop_count = metrics.gauge(MetricOpts::new(
         "electrs_main_loop_count",
         "count of iterations of electrs main loop each 5 seconds or after interrupts",

src/config.rs

@@ -43,6 +43,10 @@ pub struct Config {
     pub rpc_logging: RpcLogging,
     pub zmq_addr: Option<SocketAddr>,
 
+    /// The user's requested log verbosity level (number of -v flags).
+    /// Used to restore log level after startup logging completes.
+    pub log_verbosity: usize,
+
     /// RocksDB block cache size in MB (per database)
     /// Caches decompressed data blocks, plus index and filter blocks (via cache_index_and_filter_blocks).
     /// Total memory usage = cache_size * 3_databases (txstore, history, cache)
@@ -463,8 +467,13 @@ impl Config {
             .value_of("electrum_public_hosts")
             .map(|s| serde_json::from_str(s).expect("invalid --electrum-public-hosts"));
 
+        let user_verbosity = m.occurrences_of("verbosity") as usize;
+        // Initialize logging at info level (verbosity 2) minimum so that
+        // startup milestone logs are always visible. After startup completes,
+        // the log level is dropped to the user's configured verbosity.
+        let startup_verbosity = std::cmp::max(user_verbosity, 2);
         let mut log = stderrlog::new();
-        log.verbosity(m.occurrences_of("verbosity") as usize);
+        log.verbosity(startup_verbosity);
         log.timestamp(if m.is_present("timestamp") {
             stderrlog::Timestamp::Millisecond
         } else {
@@ -509,6 +518,7 @@ impl Config {
             initial_sync_batch_size: value_t_or_exit!(m, "initial_sync_batch_size", usize),
             db_cache_index_filter_blocks: m.is_present("cache_index_filter_blocks"),
             zmq_addr,
+            log_verbosity: user_verbosity,
 
             #[cfg(feature = "liquid")]
             parent_network,
@@ -526,6 +536,16 @@ impl Config {
         config
     }
 
+    pub fn log_level_filter(&self) -> log::LevelFilter {
+        match self.log_verbosity {
+            0 => log::LevelFilter::Error,
+            1 => log::LevelFilter::Warn,
+            2 => log::LevelFilter::Info,
+            3 => log::LevelFilter::Debug,
+            _ => log::LevelFilter::Trace,
+        }
+    }
+
     pub fn cookie_getter(&self) -> Arc<dyn CookieGetter> {
         if let Some(ref value) = self.cookie {
             Arc::new(StaticCookie {

src/new_index/mempool.rs

@@ -559,7 +559,7 @@ impl Mempool {
             .difference(&indexed_txids)
             .collect::<Vec<_>>();
 
-        debug!(
+        info!(
             "mempool with total {} txs, {} indexed locally, {} to fetch",
             bitcoind_txids.len(),
             indexed_txids.len(),

src/new_index/schema.rs

@@ -63,11 +63,11 @@ impl Store {
 
         let txstore_db = DB::open(&path.join("txstore"), config, verify_compat);
         let added_blockhashes = load_blockhashes(&txstore_db, &BlockRow::done_filter());
-        debug!("{} blocks were added", added_blockhashes.len());
+        info!("{} blocks were added", added_blockhashes.len());
 
         let history_db = DB::open(&path.join("history"), config, verify_compat);
         let indexed_blockhashes = load_blockhashes(&history_db, &BlockRow::done_filter());
-        debug!("{} blocks were indexed", indexed_blockhashes.len());
+        info!("{} blocks were indexed", indexed_blockhashes.len());
 
         let cache_db = DB::open(&path.join("cache"), config, verify_compat);
 
@@ -92,7 +92,7 @@ impl Store {
                     .expect("invalid header chain")
                     .prev_blockhash;
             }
-            debug!(
+            info!(
                 "{} headers were loaded, tip at {:?}",
                 headers_map.len(),
                 tip_hash

tests/common.rs

@@ -112,6 +112,7 @@ impl TestRunner {
             electrum_banner: "".into(),
             rpc_logging: RpcLogging::default(),
             zmq_addr: None,
+            log_verbosity: 0,
 
             #[cfg(feature = "liquid")]
             asset_db_path: None, // XXX