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.

Author: EddieHouston

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.

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"

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"

src/bin/electrs.rs

@@ -137,8 +137,7 @@ 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());
+    info!("startup complete");
 
     let main_loop_count = metrics.gauge(MetricOpts::new(
         "electrs_main_loop_count",

src/config.rs

@@ -43,10 +43,6 @@ 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)
@@ -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<dyn CookieGetter> {
         if let Some(ref value) = self.cookie {
             Arc::new(StaticCookie {

src/daemon.rs

@@ -789,7 +789,7 @@ impl Daemon {
 
             result.append(&mut headers);
 
-            info!(
+            debug!(
                 "downloaded {}/{} block headers ({:.0}%)",
                 result.len(),
                 tip_height + 1,

src/electrum/discovery.rs

@@ -588,7 +588,7 @@ mod tests {
 
         debug!("{:#?}", discovery);
 
-        info!("{}", json!(discovery.get_servers()));
+        debug!("{}", json!(discovery.get_servers()));
 
         Ok(())
     }

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());
                     });
 

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

src/new_index/mempool.rs

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