cli: don't colorize file log output, collect internal logs for broadcast (#177420)

Fixes #177345

cli/src/bin/code/main.rs

@@ -10,7 +10,7 @@ use clap::Parser;
 use cli::{
 	commands::{args, internal_wsl, tunnels, update, version, CommandContext},
 	constants::get_default_user_agent,
-	desktop, log as own_log,
+	desktop, log,
 	state::LauncherPaths,
 	util::{
 		errors::{wrap, AnyError},
@@ -22,8 +22,6 @@ use legacy_args::try_parse_legacy;
 use opentelemetry::sdk::trace::TracerProvider as SdkTracerProvider;
 use opentelemetry::trace::TracerProvider;
 
-use log::{Level, Metadata, Record};
-
 #[tokio::main]
 async fn main() -> Result<(), std::convert::Infallible> {
 	let raw_args = std::env::args_os().collect::<Vec<_>>();
@@ -38,44 +36,56 @@ async fn main() -> Result<(), std::convert::Infallible> {
 		});
 
 	let core = parsed.core();
-	let context = CommandContext {
+	let context_paths = LauncherPaths::new(&core.global_options.cli_data_dir).unwrap();
+	let context_args = core.clone();
+
+	// gets a command context without installing the global logger
+	let context_no_logger = || CommandContext {
 		http: reqwest::ClientBuilder::new()
 			.user_agent(get_default_user_agent())
 			.build()
 			.unwrap(),
-		paths: LauncherPaths::new(&core.global_options.cli_data_dir).unwrap(),
-		log: make_logger(core),
-		args: core.clone(),
+		paths: context_paths,
+		log: make_logger(&context_args),
+		args: context_args,
 	};
 
-	log::set_logger(Box::leak(Box::new(RustyLogger(context.log.clone()))))
-		.map(|()| log::set_max_level(log::LevelFilter::Debug))
-		.expect("expected to make logger");
+	// gets a command context with the global logger installer. Usually what most commands want.
+	macro_rules! context {
+		() => {{
+			let context = context_no_logger();
+			log::install_global_logger(context.log.clone());
+			context
+		}};
+	}
 
 	let result = match parsed {
 		args::AnyCli::Standalone(args::StandaloneCli {
 			subcommand: Some(cmd),
 			..
 		}) => match cmd {
-			args::StandaloneCommands::Update(args) => update::update(context, args).await,
+			args::StandaloneCommands::Update(args) => update::update(context!(), args).await,
 			args::StandaloneCommands::Wsl(args) => match args.command {
-				args::WslCommands::Serve => internal_wsl::serve(context).await,
+				args::WslCommands::Serve => internal_wsl::serve(context!()).await,
 			},
 		},
 		args::AnyCli::Standalone(args::StandaloneCli { core: c, .. })
 		| args::AnyCli::Integrated(args::IntegratedCli { core: c, .. }) => match c.subcommand {
 			None => {
+				let context = context!();
 				let ca = context.args.get_base_code_args();
 				start_code(context, ca).await
 			}
 
 			Some(args::Commands::Extension(extension_args)) => {
+				let context = context!();
 				let mut ca = context.args.get_base_code_args();
 				extension_args.add_code_args(&mut ca);
 				start_code(context, ca).await
 			}
 
 			Some(args::Commands::Status) => {
+				let context = context!();
 				let mut ca = context.args.get_base_code_args();
 				ca.push("--status".to_string());
 				start_code(context, ca).await
@@ -83,27 +93,27 @@ async fn main() -> Result<(), std::convert::Infallible> {
 
 			Some(args::Commands::Version(version_args)) => match version_args.subcommand {
 				args::VersionSubcommand::Use(use_version_args) => {
-					version::switch_to(context, use_version_args).await
+					version::switch_to(context!(), use_version_args).await
 				}
-				args::VersionSubcommand::Show => version::show(context).await,
+				args::VersionSubcommand::Show => version::show(context!()).await,
 			},
 
 			Some(args::Commands::Tunnel(tunnel_args)) => match tunnel_args.subcommand {
-				Some(args::TunnelSubcommand::Prune) => tunnels::prune(context).await,
-				Some(args::TunnelSubcommand::Unregister) => tunnels::unregister(context).await,
-				Some(args::TunnelSubcommand::Kill) => tunnels::kill(context).await,
-				Some(args::TunnelSubcommand::Restart) => tunnels::restart(context).await,
-				Some(args::TunnelSubcommand::Status) => tunnels::status(context).await,
+				Some(args::TunnelSubcommand::Prune) => tunnels::prune(context!()).await,
+				Some(args::TunnelSubcommand::Unregister) => tunnels::unregister(context!()).await,
+				Some(args::TunnelSubcommand::Kill) => tunnels::kill(context!()).await,
+				Some(args::TunnelSubcommand::Restart) => tunnels::restart(context!()).await,
+				Some(args::TunnelSubcommand::Status) => tunnels::status(context!()).await,
 				Some(args::TunnelSubcommand::Rename(rename_args)) => {
-					tunnels::rename(context, rename_args).await
+					tunnels::rename(context!(), rename_args).await
 				}
 				Some(args::TunnelSubcommand::User(user_command)) => {
-					tunnels::user(context, user_command).await
+					tunnels::user(context!(), user_command).await
 				}
 				Some(args::TunnelSubcommand::Service(service_args)) => {
-					tunnels::service(context, service_args).await
+					tunnels::service(context_no_logger(), service_args).await
 				}
-				None => tunnels::serve(context, tunnel_args.serve_args).await,
+				None => tunnels::serve(context_no_logger(), tunnel_args.serve_args).await,
 			},
 		},
 	};
@@ -114,18 +124,17 @@ async fn main() -> Result<(), std::convert::Infallible> {
 	}
 }
 
-fn make_logger(core: &args::CliCore) -> own_log::Logger {
+fn make_logger(core: &args::CliCore) -> log::Logger {
 	let log_level = if core.global_options.verbose {
-		own_log::Level::Trace
+		log::Level::Trace
 	} else {
-		core.global_options.log.unwrap_or(own_log::Level::Info)
+		core.global_options.log.unwrap_or(log::Level::Info)
 	};
 
 	let tracer = SdkTracerProvider::builder().build().tracer("codecli");
-	let mut log = own_log::Logger::new(tracer, log_level);
+	let mut log = log::Logger::new(tracer, log_level);
 	if let Some(f) = &core.global_options.log_to_file {
-		log =
-			log.tee(own_log::FileLogSink::new(log_level, f).expect("expected to make file logger"))
+		log = log.tee(log::FileLogSink::new(log_level, f).expect("expected to make file logger"))
 	}
 
 	log
@@ -135,7 +144,7 @@ fn print_and_exit<E>(err: E) -> !
 where
 	E: std::fmt::Display,
 {
-	own_log::emit(own_log::Level::Error, "", &format!("{}", err));
+	log::emit(log::Level::Error, "", &format!("{}", err));
 	std::process::exit(1);
 }
 
@@ -167,40 +176,3 @@ async fn start_code(context: CommandContext, args: Vec<String>) -> Result<i32, A
 
 	Ok(code)
 }
-
-/// Logger that uses the common rust "log" crate and directs back to one of
-/// our managed loggers.
-struct RustyLogger(own_log::Logger);
-
-impl log::Log for RustyLogger {
-	fn enabled(&self, metadata: &Metadata) -> bool {
-		metadata.level() <= Level::Debug
-	}
-
-	fn log(&self, record: &Record) {
-		if !self.enabled(record.metadata()) {
-			return;
-		}
-
-		// exclude noisy log modules:
-		let src = match record.module_path() {
-			Some("russh::cipher") => return,
-			Some("russh::negotiation") => return,
-			Some(s) => s,
-			None => "<unknown>",
-		};
-
-		self.0.emit(
-			match record.level() {
-				log::Level::Debug => own_log::Level::Debug,
-				log::Level::Error => own_log::Level::Error,
-				log::Level::Info => own_log::Level::Info,
-				log::Level::Trace => own_log::Level::Trace,
-				log::Level::Warn => own_log::Level::Warn,
-			},
-			&format!("[{}] {}", src, record.args()),
-		);
-	}
-
-	fn flush(&self) {}
-}

cli/src/commands/tunnels.rs

@@ -22,7 +22,7 @@ use crate::{
 	auth::Auth,
 	constants::APPLICATION_NAME,
 	json_rpc::{new_json_rpc, start_json_rpc},
-	log::{self, Logger},
+	log,
 	singleton::connect_as_client,
 	state::LauncherPaths,
 	tunnels::{
@@ -330,10 +330,14 @@ fn get_connection_token(tunnel: &ActiveTunnel) -> String {
 
 async fn serve_with_csa(
 	paths: LauncherPaths,
-	mut log: Logger,
+	mut log: log::Logger,
 	gateway_args: TunnelServeArgs,
 	mut csa: CodeServerArgs,
 ) -> Result<i32, AnyError> {
+	let log_broadcast = BroadcastLogSink::new();
+	log = log.tee(log_broadcast.clone());
+	log::install_global_logger(log.clone()); // re-install so that library logs are captured
+
 	let shutdown = match gateway_args
 		.parent_process_id
 		.and_then(|p| Pid::from_str(&p).ok())
@@ -377,8 +381,6 @@ async fn serve_with_csa(
 
 	debug!(log, "starting as new singleton");
 
-	let log_broadcast = BroadcastLogSink::new();
-	log = log.tee(log_broadcast.clone());
 	let mut server =
 		make_singleton_server(log_broadcast.clone(), log.clone(), server, shutdown.clone());
 	let platform = spanf!(log, log.span("prereq"), PreReqChecker::new().verify())?;

cli/src/log.rs

@@ -178,7 +178,7 @@ impl LogSink for FileLogSink {
 			return;
 		}
 
-		let line = format(level, prefix, message);
+		let line = format(level, prefix, message, false);
 
 		// ignore any errors, not much we can do if logging fails...
 		self.file.lock().unwrap().write_all(line.as_bytes()).ok();
@@ -295,24 +295,26 @@ impl<'a> crate::util::io::ReportCopyProgress for DownloadLogger<'a> {
 	}
 }
 
-pub fn format(level: Level, prefix: &str, message: &str) -> String {
+fn format(level: Level, prefix: &str, message: &str, use_colors: bool) -> String {
 	let current = Local::now();
 	let timestamp = current.format("%Y-%m-%d %H:%M:%S").to_string();
 
 	let name = level.name().unwrap();
 
-	if let Some(c) = level.color_code() {
-		format!(
-			"\x1b[2m[{}]\x1b[0m {}{}\x1b[0m {}{}\n",
-			timestamp, c, name, prefix, message
-		)
-	} else {
-		format!("[{}] {} {}{}\n", timestamp, name, prefix, message)
+	if use_colors {
+		if let Some(c) = level.color_code() {
+			return format!(
+				"\x1b[2m[{}]\x1b[0m {}{}\x1b[0m {}{}\n",
+				timestamp, c, name, prefix, message
+			);
+		}
 	}
+
+	format!("[{}] {} {}{}\n", timestamp, name, prefix, message)
 }
 
 pub fn emit(level: Level, prefix: &str, message: &str) {
-	let line = format(level, prefix, message);
+	let line = format(level, prefix, message, true);
 	if level == Level::Trace {
 		print!("\x1b[2m{}\x1b[0m", line);
 	} else {
@@ -320,6 +322,51 @@ pub fn emit(level: Level, prefix: &str, message: &str) {
 	}
 }
 
+/// Installs the logger instance as the global logger for the 'log' service.
+/// Replaces any existing registered logger. Note that the logger will be leaked/
+pub fn install_global_logger(log: Logger) {
+	log::set_logger(Box::leak(Box::new(RustyLogger(log))))
+		.map(|()| log::set_max_level(log::LevelFilter::Debug))
+		.expect("expected to make logger");
+}
+
+/// Logger that uses the common rust "log" crate and directs back to one of
+/// our managed loggers.
+struct RustyLogger(Logger);
+
+impl log::Log for RustyLogger {
+	fn enabled(&self, metadata: &log::Metadata) -> bool {
+		metadata.level() <= log::Level::Debug
+	}
+
+	fn log(&self, record: &log::Record) {
+		if !self.enabled(record.metadata()) {
+			return;
+		}
+
+		// exclude noisy log modules:
+		let src = match record.module_path() {
+			Some("russh::cipher") => return,
+			Some("russh::negotiation") => return,
+			Some(s) => s,
+			None => "<unknown>",
+		};
+
+		self.0.emit(
+			match record.level() {
+				log::Level::Debug => Level::Debug,
+				log::Level::Error => Level::Error,
+				log::Level::Info => Level::Info,
+				log::Level::Trace => Level::Trace,
+				log::Level::Warn => Level::Warn,
+			},
+			&format!("[{}] {}", src, record.args()),
+		);
+	}
+
+	fn flush(&self) {}
+}
+
 #[macro_export]
 macro_rules! error {
     ($logger:expr, $str:expr) => {