Skip to content

feat(logging): always-on startup logging #207

Open
EddieHouston wants to merge 2 commits intoBlockstream:new-indexfrom
EddieHouston:startup-logging
Open

feat(logging): always-on startup logging #207
EddieHouston wants to merge 2 commits intoBlockstream:new-indexfrom
EddieHouston:startup-logging

Conversation

@EddieHouston
Copy link
Copy Markdown
Collaborator

@EddieHouston EddieHouston commented Apr 14, 2026

Summary

  • Electrs has been seen dying silently during startup in environments
    running with no -v flag (error-only logging), making it impossible to
    diagnose where they got stuck
  • Logging is now initialized at info level minimum during startup, then
    drops to the user's configured verbosity after servers are listening
  • Adds info! milestone logs at each startup phase: daemon connection,
    DB open, initial sync start/complete, mempool load, startup complete
  • Promotes key debug! logs in schema.rs and mempool.rs to info!
    so block/header/mempool counts are visible during the startup window

Test plan

  • Run electrs with no -v flag — verify startup milestones are
    logged and logging goes silent after "startup complete"
  • Run electrs with -vvv — verify behavior is unchanged (already
    above the info threshold)
  • Kill electrs mid-startup — verify the last log line indicates
    which phase it was in

DeviaVir
DeviaVir previously approved these changes Apr 14, 2026
Comment thread src/.DS_Store Outdated
DeviaVir
DeviaVir previously approved these changes Apr 14, 2026
@EddieHouston EddieHouston self-assigned this Apr 14, 2026
Comment thread src/bin/electrs.rs
Comment thread src/bin/electrs.rs Outdated
@philippem
Copy link
Copy Markdown
Collaborator

philippem commented Apr 14, 2026

let's wait until we see

2026-04-14T11:28:46.020-07:00 - INFO Electrum RPC server running on 0.0.0.0:50001
2026-04-14T11:28:46.021-07:00 - INFO REST server running on 0.0.0.0:3001

before we revert verbosity. it's only at this point that electrs is ready

  • print the previous and after levels
  • the "Config" print message at startup should show the actual requested log level, not the overridden one:
$ ./run-release.sh
Config { log: StdErrLog { verbosity: Info, quiet: false, show_level: true, timestamp: Millisecond, modules: [], writer: "stderr", color_choice: Never, show_module_names: false }, network_type: Bitcoin, db_path: "/mnt/quattro/electrs/bitcoin-mainnet/mainnet", daemon_dir: "/home/phil/.bitcoin", blocks_dir: "/home/phil/.bitcoin/blocks", daemon_rpc_addr: 0.0.0.0:8332, daemon_parallelism: 8, cookie: Some("rpcuser:rpcpassword"), electrum_rpc_addr: 0.0.0.0:50001, http_addr: 0.0.0.0:3001, http_socket_file: None, monitoring_addr: 0.0.0.0:4224, jsonrpc_import: true, light_mode: false, address_search: false, index_unspendables: false, cors: Some("*"), precache_scripts: None, utxos_limit: 500, electrum_txs_limit: 500, electrum_banner: "Welcome to electrs-esplora 0.4.1", rpc_logging: RpcLogging { enabled: false, hide_params: false, anonymize_ip: false }, zmq_addr: None, log_verbosity: 1, db_block_cache_mb: 8192, db_parallelism: 20, db_write_buffer_size_mb: 256, initial_sync_batch_size: 100, db_cache_index_filter_blocks: false }

this is what it should show:

$ ./run-release.sh
Config { log: StdErrLog { verbosity: Error, quiet: false, show_level: true, timestamp: Millisecond, modules: [], writer: "stderr", color_choice: Auto, show_module_names: false }, network_type: Bitcoin, db_path: "/mnt/quattro/electrs/bitcoin-mainnet/mainnet", daemon_dir: "/home/phil/.bitcoin", blocks_dir: "/home/phil/.bitcoin/blocks", daemon_rpc_addr: 0.0.0.0:8332, daemon_parallelism: 8, cookie: Some("rpcuser:rpcpassword"), electrum_rpc_addr: 0.0.0.0:50001, http_addr: 0.0.0.0:3001, http_socket_file: None, monitoring_addr: 0.0.0.0:4224, jsonrpc_import: true, light_mode: false, address_search: false, index_unspendables: false, cors: Some("*"), precache_scripts: None, utxos_limit: 500, electrum_txs_limit: 500, electrum_banner: "Welcome to electrs-esplora 0.4.1", rpc_logging: RpcLogging { enabled: false, hide_params: false, anonymize_ip: false }, zmq_addr: None, db_block_cache_mb: 8192, db_parallelism: 20, db_write_buffer_size_mb: 256, initial_sync_batch_size: 100, db_cache_index_filter_blocks: false }
  • another way to implement this would be to add a second option for startup logging. that would simplify the set/revert mechanics

@shesek
Copy link
Copy Markdown
Collaborator

shesek commented Apr 14, 2026

I would consider a different approach: make level 2 logging (error+warn+info) the default and the minimum, such that a single -v enables debug-level logging and -vv enables trace (i.e. log.verbosity(2 + m.occurrences_of("verbosity"))). Then promote important log messages to be info-level (this PR already promotes some messages, but possibly too many. I think some should remain debug).

I don't think it's really ever desirable to hide error/warn/info messages, and it's typical for CLI programs to output these by default without requiring -v, so that behavior makes more sense to me. And it's also simpler than the revert mechanism introduced here.

Changing the meaning of -v does break backwards compatibility, but I think it's something we could live with. The (probably?) most typical setting, -vvvv, will still work the same. If we want to continue supporting logging level < 2, we could introduce a separate -q/--quiet parameter which is the more typical way to handle this, but I don't think that's really necessary.

@EddieHouston
Copy link
Copy Markdown
Collaborator Author

I would consider a different approach: make level 2 logging (error+warn+info) the default and the minimum, such that a single -v enables debug-level logging and -vv enables trace (i.e. log.verbosity(2 + m.occurrences_of("verbosity"))). Then promote important log messages to be info-level (this PR already promotes some messages, but possibly too many. I think some should remain debug).

I don't think it's really ever desirable to hide error/warn/info messages, and it's typical for CLI programs to output these by default without requiring -v, so that behavior makes more sense to me. And it's also simpler than the revert mechanism introduced here.

Changing the meaning of -v does break backwards compatibility, but I think it's something we could live with. The (probably?) most typical setting, -vvvv, will still work the same. If we want to continue supporting logging level < 2, we could introduce a separate -q/--quiet parameter which is the more typical way to handle this, but I don't think that's really necessary.

Good simplification. This does remove the need to override log levels. I can see demoting the mempool message changed in this PR back to debug. I could also see some other info logs we can demote to debug as well:

File Line Message Why
src/rest.rs 688 handle {:?} {:?} Every HTTP request — biggest noise source
src/electrum/server.rs 873 connected peer Every peer connection
src/electrum/server.rs 887 disconnected peer Every peer disconnection
src/daemon.rs 792 downloaded N/M block headers Chatty during initial sync (bracket messages stay info)
src/electrum/discovery.rs 591 Full server list JSON dump Large payload, periodic

If we later find that there is a need to implement the -q/--quiet option (depending on memory growth with 2 as the default)... we can then look at if an override on startup is necessary when that is set.

…igured 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.
@EddieHouston EddieHouston force-pushed the startup-logging branch 2 times, most recently from cf56222 to be6a6d8 Compare April 16, 2026 07:16
…ages 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.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

4 participants