Fix logging initialisation (#348)

- Fixes #345 (first crash, related to `RUST_LOG` being set)
- Adds multiple warnings when non-standard logging or build options are set
- Fixes the (internal) crate name of the cli so that the log target `watchexec_cli` works
- Fixes the verbosity config to target the actual crate names (snake vs kebab case)
- Fixes a usage error related to tracing's `log` compatibility

Cargo.lock

@@ -2661,7 +2661,6 @@ dependencies = [
  "project-origins",
  "tokio",
  "tracing",
- "tracing-log",
  "tracing-subscriber",
  "watchexec",
  "watchexec-filterer-globset",

crates/cli/Cargo.toml

@@ -28,7 +28,6 @@ futures = "0.3.17"
 miette = { version = "4.7.1", features = ["fancy"] }
 notify-rust = "4.5.2"
 tracing = "0.1.26"
-tracing-log = "0.1.3"
 
 [dependencies.clap]
 version = "3.1.18"
@@ -72,6 +71,7 @@ features = [
 	"env-filter",
 	"fmt",
 	"json",
+	"tracing-log",
 ]
 
 [target.'cfg(target_env = "musl")'.dependencies]

crates/cli/src/args.rs

@@ -17,7 +17,7 @@ const OPTSET_OUTPUT: &str = "Output options";
 const OPTSET_BEHAVIOUR: &str = "Behaviour options";
 
 pub fn get_args(tagged_filterer: bool) -> Result<ArgMatches> {
-	let app = Command::new("watchexec")
+	let mut app = Command::new("watchexec")
 		.version(crate_version!())
 		.about("Execute commands when watched files change")
 		.after_help("Use @argfile as first argument to load arguments from the file `argfile` (one argument per line) which will be inserted in place of the @argfile (further arguments on the CLI will override or add onto those in the file).")
@@ -178,6 +178,16 @@ pub fn get_args(tagged_filterer: bool) -> Result<ArgMatches> {
 			.number_of_values(1)
 			.multiple_occurrences(true));
 
+	// none of these are mutually exclusive, but it should be rare to unintentionally have two on
+	if cfg!(debug_assertions) {
+		app = app.before_help("⚠ DEBUG BUILD ⚠");
+	} else if cfg!(feature = "dev-console") {
+		app = app.before_help("⚠ DEV CONSOLE ENABLED ⚠");
+	} else if std::env::var("RUST_LOG").is_ok() {
+		app =
+			app.before_help("⚠ RUST_LOG environment variable set, logging options have no effect");
+	}
+
 	let app = if tagged_filterer {
 		app.arg(
 			Arg::new("filter")

crates/cli/src/lib.rs

@@ -0,0 +1,105 @@
+#![deny(rust_2018_idioms)]
+
+use std::{env::var, fs::File, sync::Mutex};
+
+use miette::{IntoDiagnostic, Result};
+use tracing::{debug, info, warn};
+use watchexec::{
+	event::{Event, Priority},
+	Watchexec,
+};
+
+mod args;
+mod config;
+mod filterer;
+
+#[cfg(target_env = "musl")]
+#[global_allocator]
+static GLOBAL: mimalloc::MiMalloc = mimalloc::MiMalloc;
+
+pub async fn run() -> Result<()> {
+	let mut log_on = false;
+
+	#[cfg(feature = "dev-console")]
+	match console_subscriber::try_init() {
+		Ok(_) => {
+			warn!("dev-console enabled");
+			log_on = true;
+		}
+		Err(e) => {
+			eprintln!("Failed to initialise tokio console, falling back to normal logging\n{e}")
+		}
+	}
+
+	if !log_on && var("RUST_LOG").is_ok() {
+		match tracing_subscriber::fmt::try_init() {
+			Ok(_) => {
+				warn!(RUST_LOG=%var("RUST_LOG").unwrap(), "logging configured from RUST_LOG");
+				log_on = true;
+			}
+			Err(e) => eprintln!("Failed to initialise logging with RUST_LOG, falling back\n{e}"),
+		}
+	}
+
+	let tagged_filterer = var("WATCHEXEC_FILTERER")
+		.map(|v| v == "tagged")
+		.unwrap_or(false);
+
+	let args = args::get_args(tagged_filterer)?;
+
+	if log_on {
+		warn!("ignoring logging options from args");
+	} else {
+		let verbosity = args.occurrences_of("verbose");
+		let log_file = if let Some(file) = args.value_of_os("log-file") {
+			// TODO: use tracing-appender instead
+			Some(File::create(file).into_diagnostic()?)
+		} else {
+			None
+		};
+
+		let mut builder = tracing_subscriber::fmt().with_env_filter(match verbosity {
+			0 => "watchexec_cli=warn",
+			1 => "watchexec=debug,watchexec_filterer_globset=debug,watchexec_filterer_ignore=debug,watchexec_filterer_tagged=debug,watchexec_cli=debug",
+			2 => "ignore_files=trace,project_origins=trace,watchexec=trace,watchexec_filterer_globset=trace,watchexec_filterer_ignore=trace,watchexec_filterer_tagged=trace,watchexec_cli=trace",
+			_ => "trace",
+		});
+
+		if verbosity > 2 {
+			use tracing_subscriber::fmt::format::FmtSpan;
+			builder = builder.with_span_events(FmtSpan::NEW | FmtSpan::CLOSE);
+		}
+
+		match if let Some(writer) = log_file {
+			builder.json().with_writer(Mutex::new(writer)).try_init()
+		} else if verbosity > 3 {
+			builder.pretty().try_init()
+		} else {
+			builder.try_init()
+		} {
+			Ok(_) => info!("logging initialised"),
+			Err(e) => eprintln!("Failed to initialise logging, continuing with none\n{e}"),
+		}
+	}
+
+	debug!(version=%env!("CARGO_PKG_VERSION"), ?args, "constructing Watchexec from CLI");
+
+	let init = config::init(&args)?;
+	let mut runtime = config::runtime(&args)?;
+	runtime.filterer(if tagged_filterer {
+		eprintln!("!!! EXPERIMENTAL: using tagged filterer !!!");
+		filterer::tagged(&args).await?
+	} else {
+		filterer::globset(&args).await?
+	});
+
+	let wx = Watchexec::new(init, runtime)?;
+
+	if !args.is_present("postpone") {
+		wx.send_event(Event::default(), Priority::Urgent).await?;
+	}
+
+	wx.main().await.into_diagnostic()??;
+
+	Ok(())
+}

crates/cli/src/main.rs

@@ -1,91 +1,4 @@
-#![deny(rust_2018_idioms)]
-
-use std::{env::var, fs::File, sync::Mutex};
-
-use miette::{IntoDiagnostic, Result};
-use tracing::debug;
-use tracing_log::LogTracer;
-use watchexec::{
-	event::{Event, Priority},
-	Watchexec,
-};
-
-mod args;
-mod config;
-mod filterer;
-
-#[cfg(target_env = "musl")]
-#[global_allocator]
-static GLOBAL: mimalloc::MiMalloc = mimalloc::MiMalloc;
-
 #[tokio::main]
-async fn main() -> Result<()> {
-	LogTracer::init().into_diagnostic()?;
-
-	#[cfg(feature = "dev-console")]
-	console_subscriber::init();
-
-	if var("RUST_LOG").is_ok() && cfg!(not(feature = "dev-console")) {
-		tracing_subscriber::fmt::init();
-	}
-
-	let tagged_filterer = var("WATCHEXEC_FILTERER")
-		.map(|v| v == "tagged")
-		.unwrap_or(false);
-
-	let args = args::get_args(tagged_filterer)?;
-
-	{
-		let verbosity = args.occurrences_of("verbose");
-		let log_file = if let Some(file) = args.value_of_os("log-file") {
-			Some(File::create(file).into_diagnostic()?)
-		} else {
-			None
-		};
-
-		let mut builder = tracing_subscriber::fmt().with_env_filter(match verbosity {
-			0 => "watchexec-cli=warn",
-			1 => "watchexec=debug,watchexec-filterer-globset=debug,watchexec-filterer-ignore=debug,watchexec-filterer-tagged=debug,watchexec-cli=debug",
-			2 => "ignore-files=trace,project-origins=trace,watchexec=trace,watchexec-filterer-globset=trace,watchexec-filterer-ignore=trace,watchexec-filterer-tagged=trace,watchexec-cli=trace",
-			_ => "trace",
-		});
-
-		if verbosity > 2 {
-			use tracing_subscriber::fmt::format::FmtSpan;
-			builder = builder.with_span_events(FmtSpan::NEW | FmtSpan::CLOSE);
-		}
-
-		if let Some(writer) = log_file {
-			builder
-				.json()
-				.with_writer(Mutex::new(writer))
-				.try_init()
-				.ok();
-		} else if verbosity > 3 {
-			builder.pretty().try_init().ok();
-		} else {
-			builder.try_init().ok();
-		}
-	}
-
-	debug!(version=%env!("CARGO_PKG_VERSION"), ?args, "constructing Watchexec from CLI");
-
-	let init = config::init(&args)?;
-	let mut runtime = config::runtime(&args)?;
-	runtime.filterer(if tagged_filterer {
-		eprintln!("!!! EXPERIMENTAL: using tagged filterer !!!");
-		filterer::tagged(&args).await?
-	} else {
-		filterer::globset(&args).await?
-	});
-
-	let wx = Watchexec::new(init, runtime)?;
-
-	if !args.is_present("postpone") {
-		wx.send_event(Event::default(), Priority::Urgent).await?;
-	}
-
-	wx.main().await.into_diagnostic()??;
-
-	Ok(())
+async fn main() -> miette::Result<()> {
+	watchexec_cli::run().await
 }

crates/cli/tests/snapshots/help__help_unix.snap

@@ -2,6 +2,8 @@
 source: crates/cli/tests/help.rs
 expression: "String::from_utf8(output.stdout).unwrap()"
 ---
+⚠ DEBUG BUILD ⚠
+
 watchexec 1.20.0
 Execute commands when watched files change
 

crates/cli/tests/snapshots/help__help_windows.snap

@@ -3,6 +3,8 @@ source: crates/cli/tests/help.rs
 assertion_line: 16
 expression: "String::from_utf8(output.stdout).unwrap()"
 ---
+⚠ DEBUG BUILD ⚠
+
 watchexec 1.20.0
 Execute commands when watched files change