From 6a41f92e60b0019e7b720d963eea1bc992212614 Mon Sep 17 00:00:00 2001 From: Edward Houston Date: Tue, 14 Apr 2026 11:37:26 +0200 Subject: [PATCH 1/2] 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. --- src/bin/electrs.rs | 10 ++++++++++ src/config.rs | 22 +++++++++++++++++++++- src/new_index/mempool.rs | 2 +- src/new_index/schema.rs | 6 +++--- tests/common.rs | 1 + 5 files changed, 36 insertions(+), 5 deletions(-) diff --git a/src/bin/electrs.rs b/src/bin/electrs.rs index 640e2d67d..14a698b24 100644 --- a/src/bin/electrs.rs +++ b/src/bin/electrs.rs @@ -57,10 +57,13 @@ fn run_server(config: Arc, salt_rwlock: Arc>) -> 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,6 +74,7 @@ fn run_server(config: Arc, salt_rwlock: Arc>) -> 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), @@ -78,7 +82,9 @@ fn run_server(config: Arc, salt_rwlock: Arc>) -> Result<( &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, salt_rwlock: Arc>) -> 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, salt_rwlock: Arc>) -> 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", diff --git a/src/config.rs b/src/config.rs index 9eeb9ac02..9e4264bc8 100644 --- a/src/config.rs +++ b/src/config.rs @@ -43,6 +43,10 @@ pub struct Config { pub rpc_logging: RpcLogging, pub zmq_addr: Option, + /// 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 { if let Some(ref value) = self.cookie { Arc::new(StaticCookie { diff --git a/src/new_index/mempool.rs b/src/new_index/mempool.rs index b82fbe2aa..81de38fac 100644 --- a/src/new_index/mempool.rs +++ b/src/new_index/mempool.rs @@ -559,7 +559,7 @@ impl Mempool { .difference(&indexed_txids) .collect::>(); - debug!( + info!( "mempool with total {} txs, {} indexed locally, {} to fetch", bitcoind_txids.len(), indexed_txids.len(), diff --git a/src/new_index/schema.rs b/src/new_index/schema.rs index cdb3dea22..83a99000c 100644 --- a/src/new_index/schema.rs +++ b/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 diff --git a/tests/common.rs b/tests/common.rs index 849608877..0b76a8bff 100644 --- a/tests/common.rs +++ b/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 From 064b1133a6b69c28bf395c9aa163902289900533 Mon Sep 17 00:00:00 2001 From: Edward Houston Date: Wed, 15 Apr 2026 16:45:48 +0200 Subject: [PATCH 2/2] refactor(logging): make info the default log level, demote noisy messages to debug Base verbosity is now info (error+warn+info) without any flags. Each -v flag adds one level: -v=debug, -vv=trace. This replaces the previous approach of temporarily overriding the log level during startup and reverting after. Info-level messages are now always visible by default, eliminating the set/revert mechanism. Noisy messages demoted to debug: per-request HTTP logging, peer connect/disconnect, mempool stats, header download progress, and discovery server list dumps. Promoted 'opening DB' to info for startup visibility. --- README.md | 4 ++-- contrib/electrs.service | 2 +- doc/usage.md | 2 +- src/bin/electrs.rs | 3 +-- src/config.rs | 26 ++++---------------------- src/daemon.rs | 2 +- src/electrum/discovery.rs | 2 +- src/electrum/server.rs | 4 ++-- src/new_index/db.rs | 2 +- src/new_index/mempool.rs | 2 +- src/rest.rs | 2 +- tests/common.rs | 1 - 12 files changed, 16 insertions(+), 36 deletions(-) diff --git a/README.md b/README.md index 409e7ced4..8fc410b97 100644 --- a/README.md +++ b/README.md @@ -15,10 +15,10 @@ Install Rust, Bitcoin Core (no `txindex` needed) and the `clang` and `cmake` pac ```bash $ git clone https://github.com/blockstream/electrs && cd electrs $ git checkout new-index -$ cargo run --release --bin electrs -- -vvvv --daemon-dir ~/.bitcoin +$ cargo run --release --bin electrs -- --daemon-dir ~/.bitcoin # Or for liquid: -$ cargo run --features liquid --release --bin electrs -- -vvvv --network liquid --daemon-dir ~/.liquid +$ cargo run --features liquid --release --bin electrs -- --network liquid --daemon-dir ~/.liquid ``` See [electrs's original documentation](https://github.com/romanz/electrs/blob/master/doc/usage.md) for more detailed instructions. diff --git a/contrib/electrs.service b/contrib/electrs.service index a1d003c85..34d4e0080 100644 --- a/contrib/electrs.service +++ b/contrib/electrs.service @@ -3,7 +3,7 @@ Description=Electrum Rust Server [Service] Type=simple -ExecStart=/path/to/electrs/target/release/electrs -vvvv --db-dir /path/to/electrs/db/ +ExecStart=/path/to/electrs/target/release/electrs --db-dir /path/to/electrs/db/ Restart=on-failure RestartSec=60 Environment="RUST_BACKTRACE=1" diff --git a/doc/usage.md b/doc/usage.md index 5d4dba54c..98a555071 100644 --- a/doc/usage.md +++ b/doc/usage.md @@ -32,7 +32,7 @@ Otherwise, [`~/.bitcoin/.cookie`](https://github.com/bitcoin/bitcoin/blob/021218 First index sync should take ~1.5 hours: ```bash -$ cargo run --release -- -vvv --timestamp --db-dir ./db [--cookie="USER:PASSWORD"] +$ cargo run --release -- --timestamp --db-dir ./db [--cookie="USER:PASSWORD"] 2018-08-17T18:27:42 - INFO - NetworkInfo { version: 179900, subversion: "/Satoshi:0.17.99/" } 2018-08-17T18:27:42 - INFO - BlockchainInfo { chain: "main", blocks: 537204, headers: 537204, bestblockhash: "0000000000000000002956768ca9421a8ddf4e53b1d81e429bd0125a383e3636", pruned: false, initialblockdownload: false } 2018-08-17T18:27:42 - DEBUG - opening DB at "./db/mainnet" diff --git a/src/bin/electrs.rs b/src/bin/electrs.rs index 14a698b24..6a417d824 100644 --- a/src/bin/electrs.rs +++ b/src/bin/electrs.rs @@ -137,8 +137,7 @@ fn run_server(config: Arc, salt_rwlock: Arc>) -> Result<( Arc::clone(&salt_rwlock), ); - info!("startup complete, switching to configured log verbosity"); - log::set_max_level(config.log_level_filter()); + info!("startup complete"); let main_loop_count = metrics.gauge(MetricOpts::new( "electrs_main_loop_count", diff --git a/src/config.rs b/src/config.rs index 9e4264bc8..81884620b 100644 --- a/src/config.rs +++ b/src/config.rs @@ -43,10 +43,6 @@ pub struct Config { pub rpc_logging: RpcLogging, pub zmq_addr: Option, - /// 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) @@ -113,7 +109,7 @@ impl Config { Arg::with_name("verbosity") .short("v") .multiple(true) - .help("Increase logging verbosity"), + .help("Increase logging verbosity (default: info, -v: debug, -vv: trace)"), ) .arg( Arg::with_name("timestamp") @@ -467,13 +463,10 @@ 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(startup_verbosity); + // Base verbosity is 2 (Info), each -v flag adds one level: + // no flags = Info, -v = Debug, -vv = Trace + log.verbosity(2 + m.occurrences_of("verbosity") as usize); log.timestamp(if m.is_present("timestamp") { stderrlog::Timestamp::Millisecond } else { @@ -518,7 +511,6 @@ 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, @@ -536,16 +528,6 @@ 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 { if let Some(ref value) = self.cookie { Arc::new(StaticCookie { diff --git a/src/daemon.rs b/src/daemon.rs index de96deb3e..4cb38306f 100644 --- a/src/daemon.rs +++ b/src/daemon.rs @@ -789,7 +789,7 @@ impl Daemon { result.append(&mut headers); - info!( + debug!( "downloaded {}/{} block headers ({:.0}%)", result.len(), tip_height + 1, diff --git a/src/electrum/discovery.rs b/src/electrum/discovery.rs index 0e28b2aec..28471c52b 100644 --- a/src/electrum/discovery.rs +++ b/src/electrum/discovery.rs @@ -588,7 +588,7 @@ mod tests { debug!("{:#?}", discovery); - info!("{}", json!(discovery.get_servers())); + debug!("{}", json!(discovery.get_servers())); Ok(()) } diff --git a/src/electrum/server.rs b/src/electrum/server.rs index ea5579699..9394c500e 100644 --- a/src/electrum/server.rs +++ b/src/electrum/server.rs @@ -870,7 +870,7 @@ impl RPC { let salt = salt_rwlock.read().unwrap().clone(); let spawned = spawn_thread("peer", move || { - info!("[{}] connected peer", addr); + debug!("[{}] connected peer", addr); let conn = Connection::new( query, stream, @@ -884,7 +884,7 @@ impl RPC { salt, ); conn.run(receiver); - info!("[{}] disconnected peer", addr); + debug!("[{}] disconnected peer", addr); let _ = garbage_sender.send(std::thread::current().id()); }); diff --git a/src/new_index/db.rs b/src/new_index/db.rs index 43fad6786..50b198465 100644 --- a/src/new_index/db.rs +++ b/src/new_index/db.rs @@ -91,7 +91,7 @@ pub enum DBFlush { impl DB { pub fn open(path: &Path, config: &Config, verify_compat: bool) -> DB { - debug!("opening DB at {:?}", path); + info!("opening DB at {:?}", path); let mut db_opts = rocksdb::Options::default(); db_opts.create_if_missing(true); db_opts.set_max_open_files(100_000); // TODO: make sure to `ulimit -n` this process correctly diff --git a/src/new_index/mempool.rs b/src/new_index/mempool.rs index 81de38fac..b82fbe2aa 100644 --- a/src/new_index/mempool.rs +++ b/src/new_index/mempool.rs @@ -559,7 +559,7 @@ impl Mempool { .difference(&indexed_txids) .collect::>(); - info!( + debug!( "mempool with total {} txs, {} indexed locally, {} to fetch", bitcoind_txids.len(), indexed_txids.len(), diff --git a/src/rest.rs b/src/rest.rs index bb909d151..6f6c98950 100644 --- a/src/rest.rs +++ b/src/rest.rs @@ -685,7 +685,7 @@ fn handle_request( None => HashMap::new(), }; - info!("handle {:?} {:?}", method, uri); + debug!("handle {:?} {:?}", method, uri); match ( &method, path.get(0), diff --git a/tests/common.rs b/tests/common.rs index 0b76a8bff..849608877 100644 --- a/tests/common.rs +++ b/tests/common.rs @@ -112,7 +112,6 @@ impl TestRunner { electrum_banner: "".into(), rpc_logging: RpcLogging::default(), zmq_addr: None, - log_verbosity: 0, #[cfg(feature = "liquid")] asset_db_path: None, // XXX