Skip to content

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

Open
EddieHouston wants to merge 1 commit intoBlockstream:new-indexfrom
EddieHouston:startup-logging
Open

feat(logging): always-on startup logging #207
EddieHouston wants to merge 1 commit 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
@EddieHouston EddieHouston self-assigned this Apr 14, 2026
…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.
let metrics = Metrics::new(config.monitoring_addr);
metrics.start();

info!("starting electrs");
Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

log that we are starting with info log level set something like. "starting electrs with INFO log level during startup"

Arc::clone(&salt_rwlock),
);

info!("startup complete, switching to configured log verbosity");
Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

print the configured log verbosity here

@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.

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