chore: reduce noisiness of dfx start

CHANGELOG.md

@@ -88,6 +88,11 @@ It is now possible to set the http adapter's log level in dfx.json or in network
 
 By default, a log level of "error" is used, in order to keep the output of a first-time `dfx start` minimal. Change it to "debug" for more verbose logging.
 
+### chore: reduce verbosity of dfx start
+
+`dfx start` produces a lot of log output that is at best irrelevant for most users.
+Most output is no longer visible unless either `--verbose` is used with dfx or the relevant part's (e.g. http adapter, btc adapter, or replica) log level is changed in dfx.json or networks.json.
+
 ### feat: generate secp256k1 keys by default
 
 When creating a new identity with `dfx identity new`, whereas previously it would have generated an Ed25519 key, it now generates a secp256k1 key. This is to enable users to write down a BIP39-style seed phrase, to recover their key in case of emergency, which will be printed when the key is generated and can be used with a new `--seed-phrase` flag in `dfx identity import`. `dfx identity import` is however still capable of importing an Ed25519 key.

e2e/tests-dfx/canister_http.bash

@@ -284,12 +284,12 @@ set_shared_local_network_canister_http_empty() {
     jq '.defaults.canister_http.log_level="warning"' dfx.json | sponge dfx.json
     define_project_network
 
-    assert_command dfx start --background
+    assert_command dfx start --background --verbose
     assert_match "log level: Warning"
     assert_command dfx stop
 
     jq '.defaults.canister_http.log_level="critical"' dfx.json | sponge dfx.json
-    assert_command dfx start --background
+    assert_command dfx start --background --verbose
     assert_match "log level: Critical"
 }
 
@@ -298,12 +298,12 @@ set_shared_local_network_canister_http_empty() {
     jq '.networks.local.canister_http.log_level="warning"' dfx.json | sponge dfx.json
     define_project_network
 
-    assert_command dfx start --background
+    assert_command dfx start --background --verbose
     assert_match "log level: Warning"
     assert_command dfx stop
 
     jq '.networks.local.canister_http.log_level="critical"' dfx.json | sponge dfx.json
-    assert_command dfx start --background
+    assert_command dfx start --background --verbose
     assert_match "log level: Critical"
 }
 
@@ -312,11 +312,11 @@ set_shared_local_network_canister_http_empty() {
     create_networks_json
     jq '.local.canister_http.log_level="warning"' "$E2E_NETWORKS_JSON" | sponge "$E2E_NETWORKS_JSON"
 
-    assert_command dfx start --background
+    assert_command dfx start --background --verbose
     assert_match "log level: Warning"
     assert_command dfx stop
 
     jq '.local.canister_http.log_level="critical"' "$E2E_NETWORKS_JSON" | sponge "$E2E_NETWORKS_JSON"
-    assert_command dfx start --background
+    assert_command dfx start --background --verbose
     assert_match "log level: Critical"
 }

e2e/tests-dfx/describe_local_network.bash

@@ -15,7 +15,7 @@ teardown() {
 @test "dfx start with disabled canister http" {
     create_networks_json
     echo "{}" | jq '.local.canister_http.enabled=false' >"$E2E_NETWORKS_JSON"
-    assert_command dfx start --host 127.0.0.1:0 --background
+    assert_command dfx start --host 127.0.0.1:0 --background --verbose
 
     assert_match "canister http: disabled \(default: enabled\)"
 }
@@ -24,20 +24,20 @@ teardown() {
     create_networks_json
     echo "{}" | jq '.local.replica.subnet_type="verifiedapplication"' >"$E2E_NETWORKS_JSON"
 
-    assert_command dfx start --host 127.0.0.1:0 --background
+    assert_command dfx start --host 127.0.0.1:0 --background --verbose
 
     assert_match "subnet type: VerifiedApplication \(default: Application\)"
 }
 
 @test "dfx start with nonstandard bitcoin node" {
-    assert_command dfx start --host 127.0.0.1:0 --background --bitcoin-node 192.168.0.1:18000
+    assert_command dfx start --host 127.0.0.1:0 --background --bitcoin-node 192.168.0.1:18000 --verbose
 
     assert_match "bitcoin: enabled \(default: disabled\)"
     assert_match "nodes: \[192.168.0.1:18000\] \(default: \[127.0.0.1:18444\]\)"
 }
 
 @test "dfx start enabling bitcoin" {
-    assert_command dfx start --host 127.0.0.1:0 --background --enable-bitcoin
+    assert_command dfx start --host 127.0.0.1:0 --background --enable-bitcoin --verbose
 
     assert_match "bitcoin: enabled \(default: disabled\)"
 }
@@ -48,7 +48,7 @@ teardown() {
     echo "{}" >dfx.json
 
     # we have to pass 0 for port to avoid conflicts
-    assert_command dfx start --host 127.0.0.1:0 --background
+    assert_command dfx start --host 127.0.0.1:0 --background --verbose
 
     assert_match "There is no project-specific network 'local' defined in .*/some-project/dfx.json."
     assert_match "Using the default definition for the 'local' shared network because $DFX_CONFIG_ROOT/.config/dfx/networks.json does not exist."
@@ -62,7 +62,7 @@ teardown() {
 }
 
 @test "dfx start outside of a project with default configuration" {
-    assert_command dfx start --host 127.0.0.1:0 --background
+    assert_command dfx start --host 127.0.0.1:0 --background --verbose
 
     assert_match "There is no project-specific network 'local' because there is no project \(no dfx.json\)."
     assert_match "Using the default definition for the 'local' shared network because $DFX_CONFIG_ROOT/.config/dfx/networks.json does not exist."
@@ -71,7 +71,7 @@ teardown() {
 @test "dfx start outside of a project with a shared configuration file" {
     create_networks_json
 
-    assert_command dfx start --background
+    assert_command dfx start --background --verbose
 
     assert_match "There is no project-specific network 'local' because there is no project \(no dfx.json\)."
     assert_match "Using the default definition for the 'local' shared network because $DFX_CONFIG_ROOT/.config/dfx/networks.json does not define it."
@@ -82,7 +82,7 @@ teardown() {
     create_networks_json
     echo "{}" | jq '.local.bind="127.0.0.1:0"' >"$E2E_NETWORKS_JSON"
 
-    assert_command dfx start --background
+    assert_command dfx start --background --verbose
 
     assert_match "There is no project-specific network 'local' because there is no project \(no dfx.json\)."
     assert_match "Found shared network 'local' in $DFX_CONFIG_ROOT/.config/dfx/networks.json"
@@ -92,7 +92,7 @@ teardown() {
     # almost default: use a dynamic port
     echo "{}" | jq '.networks.local.bind="127.0.0.1:0"' > dfx.json
 
-    assert_command dfx start --background
+    assert_command dfx start --background --verbose
 
     assert_match "Local server configuration:"
     assert_match "bind address: 127.0.0.1:0 \(default: 127.0.0.1:8000\)"
@@ -108,7 +108,7 @@ teardown() {
     create_networks_json
     echo "{}" | jq '.local.bind="127.0.0.1:0"' >"$E2E_NETWORKS_JSON"
 
-    assert_command dfx start --background
+    assert_command dfx start --background --verbose
 
     assert_match "Local server configuration:"
     assert_match "bind address: 127.0.0.1:0 \(default: 127.0.0.1:4943\)"

e2e/tests-dfx/nns.bash

@@ -59,7 +59,7 @@ teardown() {
 dfx_start_for_nns_install() {
     # TODO: When nns-dapp supports dynamic ports, this wait can be removed.
     assert_command timeout 300 sh -c \
-        "until dfx start --clean --background --host 127.0.0.1:8080; do echo waiting for port 8080 to become free; sleep 3; done" \
+        "until dfx start --clean --background --host 127.0.0.1:8080 --verbose; do echo waiting for port 8080 to become free; sleep 3; done" \
         || (echo "could not connect to replica on port 8080" && exit 1)
     assert_match "subnet_type: System"
     assert_match "127.0.0.1:8080"

e2e/tests-dfx/start.bash

@@ -213,12 +213,12 @@ teardown() {
     jq '.defaults.replica.log_level="warning"' dfx.json | sponge dfx.json
     define_project_network
 
-    assert_command dfx start --background
+    assert_command dfx start --background --verbose
     assert_match "log level: Warning"
     assert_command dfx stop
 
     jq '.defaults.replica.log_level="critical"' dfx.json | sponge dfx.json
-    assert_command dfx start --background
+    assert_command dfx start --background --verbose
     assert_match "log level: Critical"
 }
 
@@ -227,12 +227,12 @@ teardown() {
     jq '.networks.local.replica.log_level="warning"' dfx.json | sponge dfx.json
     define_project_network
 
-    assert_command dfx start --background
+    assert_command dfx start --background --verbose
     assert_match "log level: Warning"
     assert_command dfx stop
 
     jq '.networks.local.replica.log_level="critical"' dfx.json | sponge dfx.json
-    assert_command dfx start --background
+    assert_command dfx start --background --verbose
     assert_match "log level: Critical"
 }
 
@@ -241,12 +241,12 @@ teardown() {
     create_networks_json
     jq '.local.replica.log_level="warning"' "$E2E_NETWORKS_JSON" | sponge "$E2E_NETWORKS_JSON"
 
-    assert_command dfx start --background
+    assert_command dfx start --background --verbose
     assert_match "log level: Warning"
     assert_command dfx stop
 
     jq '.local.replica.log_level="critical"' "$E2E_NETWORKS_JSON" | sponge "$E2E_NETWORKS_JSON"
-    assert_command dfx start --background
+    assert_command dfx start --background --verbose
     assert_match "log level: Critical"
 }
 

src/dfx/src/actors/icx_proxy.rs

@@ -41,6 +41,9 @@ pub struct IcxProxyConfig {
 
     /// does the icx-proxy need to fetch the root key
     pub fetch_root_key: bool,
+
+    /// run icx-proxy in non-quiet mode
+    pub verbose: bool,
 }
 
 /// The configuration for the icx_proxy actor.
@@ -94,6 +97,7 @@ impl IcxProxy {
                 icx_proxy_pid_path.clone(),
                 receiver,
                 fetch_root_key,
+                config.verbose,
             ),
             "Failed to start ICX proxy thread.",
         )?;
@@ -186,6 +190,7 @@ fn icx_proxy_start_thread(
     icx_proxy_pid_path: PathBuf,
     receiver: Receiver<()>,
     fetch_root_key: bool,
+    verbose: bool,
 ) -> DfxResult<std::thread::JoinHandle<()>> {
     let thread_handler = move || {
         // Use a Waiter for waiting for the file to be created.
@@ -209,6 +214,9 @@ fn icx_proxy_start_thread(
             let s = format!("{}", url);
             cmd.args(&["--replica", &s]);
         }
+        if !verbose {
+            cmd.arg("-q");
+        }
         cmd.stdout(std::process::Stdio::inherit());
         cmd.stderr(std::process::Stdio::inherit());
 

src/dfx/src/actors/replica.rs

@@ -125,7 +125,6 @@ impl Replica {
 
     fn start_replica(&mut self, addr: Addr<Self>) -> DfxResult {
         let logger = self.logger.clone();
-        debug!(logger, "starting replica");
 
         // Create a replica config.
         let config = &self.config.replica_config;

src/dfx/src/commands/bootstrap.rs

@@ -54,7 +54,7 @@ pub fn exec(
     let network_descriptor =
         apply_arguments(network_descriptor, ip, port.as_deref(), timeout.as_deref())?;
     let local_server_descriptor = network_descriptor.local_server_descriptor()?;
-    local_server_descriptor.describe_bootstrap();
+    local_server_descriptor.describe_bootstrap(env.get_logger());
     let config_bootstrap = &local_server_descriptor.bootstrap;
 
     create_dir_all(&local_server_descriptor.data_directory).with_context(|| {
@@ -99,6 +99,7 @@ pub fn exec(
                 bind: socket_addr,
                 replica_urls,
                 fetch_root_key: !network_descriptor.is_ic,
+                verbose: env.get_verbose_level() > 0,
             };
 
             let port_ready_subscribe = None;

src/dfx/src/commands/replica.rs

@@ -106,7 +106,7 @@ pub fn exec(
     )?;
 
     let local_server_descriptor = network_descriptor.local_server_descriptor()?;
-    local_server_descriptor.describe(true, true);
+    local_server_descriptor.describe(env.get_logger(), true, true);
 
     let temp_dir = &local_server_descriptor.data_directory;
     create_dir_all(&temp_dir).with_context(|| {

src/dfx/src/commands/start.rs

@@ -4,6 +4,7 @@ use crate::actors::{
     start_btc_adapter_actor, start_canister_http_adapter_actor, start_emulator_actor,
     start_icx_proxy_actor, start_replica_actor, start_shutdown_controller,
 };
+use crate::config::dfx_version_str;
 use crate::error_invalid_argument;
 use crate::lib::environment::Environment;
 use crate::lib::error::{DfxError, DfxResult};
@@ -20,7 +21,7 @@ use anyhow::{anyhow, bail, Context, Error};
 use clap::Parser;
 use fn_error_context::context;
 use garcon::{Delay, Waiter};
-use slog::{warn, Logger};
+use slog::{info, warn, Logger};
 use std::fs;
 use std::fs::create_dir_all;
 use std::io::Read;
@@ -127,6 +128,13 @@ pub fn exec(
         enable_canister_http,
     }: StartOpts,
 ) -> DfxResult {
+    if !background {
+        info!(
+            env.get_logger(),
+            "Running dfx start for version {}",
+            dfx_version_str()
+        );
+    }
     let project_config = env.get_config();
 
     let network_descriptor_logger = if background {
@@ -213,7 +221,7 @@ pub fn exec(
         send_background()?;
         return fg_ping_and_wait(webserver_port_path, frontend_url);
     }
-    local_server_descriptor.describe(true, false);
+    local_server_descriptor.describe(env.get_logger(), true, false);
 
     write_pid(&pid_file_path);
     std::fs::write(&webserver_port_path, address_and_port.port().to_string()).with_context(
@@ -321,6 +329,7 @@ pub fn exec(
             bind: address_and_port,
             replica_urls: vec![], // will be determined after replica starts
             fetch_root_key: !network_descriptor.is_ic,
+            verbose: env.get_verbose_level() > 0,
         };
 
         let proxy = start_icx_proxy_actor(

src/dfx/src/lib/environment.rs

@@ -44,6 +44,7 @@ pub trait Environment {
     fn get_network_descriptor<'a>(&'a self) -> &'a NetworkDescriptor;
 
     fn get_logger(&self) -> &slog::Logger;
+    fn get_verbose_level(&self) -> i64;
     fn new_spinner(&self, message: Cow<'static, str>) -> ProgressBar;
     fn new_progress(&self, message: &str) -> ProgressBar;
 
@@ -67,7 +68,7 @@ pub struct EnvironmentImpl {
     version: Version,
 
     logger: Option<slog::Logger>,
-    progress: bool,
+    verbose_level: i64,
 
     identity_override: Option<String>,
 }
@@ -116,7 +117,7 @@ impl EnvironmentImpl {
             shared_networks_config: Arc::new(shared_networks_config),
             version: version.clone(),
             logger: None,
-            progress: true,
+            verbose_level: 0,
             identity_override: None,
         })
     }
@@ -126,13 +127,13 @@ impl EnvironmentImpl {
         self
     }
 
-    pub fn with_progress_bar(mut self, progress: bool) -> Self {
-        self.progress = progress;
+    pub fn with_identity_override(mut self, identity: Option<String>) -> Self {
+        self.identity_override = identity;
         self
     }
 
-    pub fn with_identity_override(mut self, identity: Option<String>) -> Self {
-        self.identity_override = identity;
+    pub fn with_verbose_level(mut self, verbose_level: i64) -> Self {
+        self.verbose_level = verbose_level;
         self
     }
 }
@@ -190,8 +191,12 @@ impl Environment for EnvironmentImpl {
             .expect("Log was not setup, but is being used.")
     }
 
+    fn get_verbose_level(&self) -> i64 {
+        self.verbose_level
+    }
+
     fn new_spinner(&self, message: Cow<'static, str>) -> ProgressBar {
-        if self.progress {
+        if self.verbose_level >= 0 {
             ProgressBar::new_spinner(message)
         } else {
             ProgressBar::discard()
@@ -286,6 +291,10 @@ impl<'a> Environment for AgentEnvironment<'a> {
         self.backend.get_logger()
     }
 
+    fn get_verbose_level(&self) -> i64 {
+        self.backend.get_verbose_level()
+    }
+
     fn new_spinner(&self, message: Cow<'static, str>) -> ProgressBar {
         self.backend.new_spinner(message)
     }