Review logging levels: make info more useful (#354)

Fixes #260

crates/cli/src/filterer/common.rs

@@ -9,7 +9,7 @@ use dunce::canonicalize;
 use ignore_files::IgnoreFile;
 use miette::{miette, IntoDiagnostic, Result};
 use project_origins::ProjectType;
-use tracing::{debug, warn};
+use tracing::{debug, warn, info};
 use watchexec::paths::common_prefix;
 
 pub async fn dirs(args: &ArgMatches) -> Result<(PathBuf, PathBuf)> {
@@ -73,10 +73,10 @@ pub async fn dirs(args: &ArgMatches) -> Result<(PathBuf, PathBuf)> {
 		)
 		.into_diagnostic()?
 	};
-	debug!(?project_origin, "resolved common/project origin");
+	info!(?project_origin, "resolved common/project origin");
 
 	let workdir = curdir;
-	debug!(?workdir, "resolved working directory");
+	info!(?workdir, "resolved working directory");
 
 	Ok((project_origin, workdir))
 }
@@ -87,7 +87,7 @@ pub async fn vcs_types(origin: &Path) -> Vec<ProjectType> {
 		.into_iter()
 		.filter(|pt| pt.is_vcs())
 		.collect::<Vec<_>>();
-	debug!(?vcs_types, "resolved vcs types");
+	info!(?vcs_types, "resolved vcs types");
 	vcs_types
 }
 
@@ -194,5 +194,6 @@ pub async fn ignores(
 		debug!(?ignores, "filtered ignores to exclude VCS-specific ignores");
 	}
 
+	info!(files=?ignores.iter().map(|ig| ig.path.as_path()).collect::<Vec<_>>(), "found some ignores");
 	ignores
 }

crates/cli/src/filterer/globset.rs

@@ -6,6 +6,7 @@ use std::{
 
 use clap::ArgMatches;
 use miette::{IntoDiagnostic, Result};
+use tracing::info;
 use watchexec::{
 	error::RuntimeError,
 	event::{
@@ -62,6 +63,7 @@ pub async fn globset(args: &ArgMatches) -> Result<Arc<WatchexecFilterer>> {
 		.flat_map(|s| s.split(b','))
 		.map(|e| os_strip_prefix(e, b'.'));
 
+	info!("initialising Globset filterer");
 	Ok(Arc::new(WatchexecFilterer {
 		inner: GlobsetFilterer::new(project_origin, filters, ignores, ignore_files, exts)
 			.await

crates/cli/src/filterer/tagged.rs

@@ -4,7 +4,7 @@ use clap::ArgMatches;
 use futures::future::try_join_all;
 use ignore_files::IgnoreFile;
 use miette::{IntoDiagnostic, Result};
-use tracing::{debug, trace, warn};
+use tracing::{info, trace, warn};
 use watchexec_filterer_tagged::{
 	discover_files_from_environment, Filter, FilterFile, Matcher, Op, Pattern, TaggedFilterer,
 };
@@ -29,14 +29,14 @@ pub async fn tagged(args: &ArgMatches) -> Result<Arc<TaggedFilterer>> {
 		});
 		filter_files.push(file);
 	}
-	debug!(?filter_files, "resolved command filter files");
+	info!(?filter_files, "resolved command filter files");
 
 	if !args.is_present("no-global-filters") {
 		let (global_filter_files, errors) = discover_files_from_environment().await;
 		for err in errors {
 			warn!("while discovering project-local filter files: {}", err);
 		}
-		debug!(?global_filter_files, "discovered global filter files");
+		info!(?global_filter_files, "discovered global filter files");
 		filter_files.extend(global_filter_files);
 	}
 
@@ -85,9 +85,9 @@ pub async fn tagged(args: &ArgMatches) -> Result<Arc<TaggedFilterer>> {
 		});
 	}
 
-	debug!(filters=%filters.len(), "parsed filters");
 	trace!(?filters, "all filters");
 	filterer.add_filters(&filters).await?;
 
+	info!(filters=%filters.len(), "initialising Tagged filterer");
 	Ok(filterer)
 }

crates/cli/src/lib.rs

@@ -3,7 +3,7 @@
 use std::{env::var, fs::File, sync::Mutex};
 
 use miette::{IntoDiagnostic, Result};
-use tracing::{debug, info, warn};
+use tracing::{info, warn, debug};
 use watchexec::{
 	event::{Event, Priority},
 	Watchexec,
@@ -46,11 +46,11 @@ pub async fn run() -> Result<()> {
 		.unwrap_or(false);
 
 	let args = args::get_args(tagged_filterer)?;
+	let verbosity = args.occurrences_of("verbose");
 
 	if log_on {
 		warn!("ignoring logging options from args");
-	} else {
+	} else if verbosity > 0 {
-		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()?)
@@ -59,9 +59,10 @@ pub async fn run() -> Result<()> {
 		};
 
 		let mut builder = tracing_subscriber::fmt().with_env_filter(match verbosity {
-			0 => "watchexec_cli=warn",
+			0 => unreachable!("checked by if earlier"),
-			1 => "watchexec=debug,watchexec_filterer_globset=debug,watchexec_filterer_ignore=debug,watchexec_filterer_tagged=debug,watchexec_cli=debug",
+			1 => "warn",
-			2 => "ignore_files=trace,project_origins=trace,watchexec=trace,watchexec_filterer_globset=trace,watchexec_filterer_ignore=trace,watchexec_filterer_tagged=trace,watchexec_cli=trace",
+			2 => "info",
+			3 => "debug",
 			_ => "trace",
 		});
 
@@ -82,7 +83,8 @@ pub async fn run() -> Result<()> {
 		}
 	}
 
-	debug!(version=%env!("CARGO_PKG_VERSION"), ?args, "constructing Watchexec from CLI");
+	info!(version=%env!("CARGO_PKG_VERSION"), "constructing Watchexec from CLI");
+	debug!(?args, "arguments");
 
 	let init = config::init(&args)?;
 	let mut runtime = config::runtime(&args)?;
@@ -93,13 +95,17 @@ pub async fn run() -> Result<()> {
 		filterer::globset(&args).await?
 	});
 
+	info!("initialising Watchexec runtime");
 	let wx = Watchexec::new(init, runtime)?;
 
 	if !args.is_present("postpone") {
+		debug!("kicking off with empty event");
 		wx.send_event(Event::default(), Priority::Urgent).await?;
 	}
 
+	info!("running main loop");
 	wx.main().await.into_diagnostic()??;
+	info!("done with main loop");
 
 	Ok(())
 }