Don't log with colors when we are writing to a tty (#7525)

* Don't log with colors when we are writing to a tty

This fixes a regression that was introduced by the switch to tracing.
Before we killed all colors before writing to a tty, this pr brings the
behaviour back.

* Remove accidentally added crate

* Review feedback

* More feedback

* Update client/cli/src/logging.rs

Co-authored-by: André Silva <123550+andresilva@users.noreply.github.com>

* Update client/cli/src/logging.rs

Co-authored-by: André Silva <123550+andresilva@users.noreply.github.com>

Co-authored-by: André Silva <123550+andresilva@users.noreply.github.com>

Author: bkchr

Cargo.lock

@@ -15,7 +15,8 @@ targets = ["x86_64-unknown-linux-gnu"]
 [dependencies]
 log = "0.4.11"
 atty = "0.2.13"
-regex = "1.3.4"
+regex = "1.4.2"
+lazy_static = "1.4.0"
 ansi_term = "0.12.1"
 tokio = { version = "0.2.21", features = [ "signal", "rt-core", "rt-threaded", "blocking" ] }
 futures = "0.3.4"

client/cli/Cargo.toml

@@ -47,13 +47,13 @@ use structopt::{
 	clap::{self, AppSettings},
 	StructOpt,
 };
-#[doc(hidden)]
-pub use tracing;
 use tracing_subscriber::{
 	filter::Directive, fmt::time::ChronoLocal, layer::SubscriberExt, FmtSubscriber, Layer,
 };
 
 pub use logging::PREFIX_LOG_SPAN;
+#[doc(hidden)]
+pub use tracing;
 
 /// Substrate client CLI
 ///
@@ -308,8 +308,7 @@ pub fn init_logger(
 		}
 	}
 
-	let isatty = atty::is(atty::Stream::Stderr);
-	let enable_color = isatty;
+	let enable_color = atty::is(atty::Stream::Stderr);
 	let timer = ChronoLocal::with_format(if simple {
 		"%Y-%m-%d %H:%M:%S".to_string()
 	} else {
@@ -321,12 +320,13 @@ pub fn init_logger(
 		.with_writer(std::io::stderr)
 		.event_format(logging::EventFormat {
 			timer,
-			ansi: enable_color,
 			display_target: !simple,
 			display_level: !simple,
 			display_thread_name: !simple,
+			enable_color,
 		})
-		.finish().with(logging::NodeNameLayer);
+		.finish()
+		.with(logging::NodeNameLayer);
 
 	if let Some(profiling_targets) = profiling_targets {
 		let profiling = sc_tracing::ProfilingLayer::new(tracing_receiver, &profiling_targets);
@@ -450,8 +450,7 @@ mod tests {
 	#[test]
 	fn prefix_in_log_lines_entrypoint() {
 		if env::var("ENABLE_LOGGING").is_ok() {
-			let test_pattern = "test-target=info";
-			init_logger(&test_pattern, Default::default(), Default::default()).unwrap();
+			init_logger("", Default::default(), Default::default()).unwrap();
 			prefix_in_log_lines_process();
 		}
 	}
@@ -460,4 +459,35 @@ mod tests {
 	fn prefix_in_log_lines_process() {
 		log::info!("{}", EXPECTED_LOG_MESSAGE);
 	}
+
+	/// This is no actual test, it will be used by the `do_not_write_with_colors_on_tty` test.
+	/// The given test will call the test executable to only execute this test that
+	/// will only print a log line with some colors in it.
+	#[test]
+	fn do_not_write_with_colors_on_tty_entrypoint() {
+		if env::var("ENABLE_LOGGING").is_ok() {
+			init_logger("", Default::default(), Default::default()).unwrap();
+			log::info!("{}", ansi_term::Colour::Yellow.paint(EXPECTED_LOG_MESSAGE));
+		}
+	}
+
+	#[test]
+	fn do_not_write_with_colors_on_tty() {
+		let re = regex::Regex::new(&format!(
+			r"^\d{{4}}-\d{{2}}-\d{{2}} \d{{2}}:\d{{2}}:\d{{2}}  {}$",
+			EXPECTED_LOG_MESSAGE,
+		)).unwrap();
+		let executable = env::current_exe().unwrap();
+		let output = Command::new(executable)
+			.env("ENABLE_LOGGING", "1")
+			.args(&["--nocapture", "do_not_write_with_colors_on_tty_entrypoint"])
+			.output()
+			.unwrap();
+
+		let output = String::from_utf8(output.stderr).unwrap();
+		assert!(
+			re.is_match(output.trim()),
+			format!("Expected:\n{}\nGot:\n{}", re, output),
+		);
+	}
 }

client/cli/src/lib.rs

@@ -16,8 +16,8 @@
 // You should have received a copy of the GNU General Public License
 // along with this program. If not, see <https://www.gnu.org/licenses/>.
 
+use std::fmt::{self, Write};
 use ansi_term::Colour;
-use std::fmt;
 use tracing::{span::Attributes, Event, Id, Level, Subscriber};
 use tracing_log::NormalizeEvent;
 use tracing_subscriber::{
@@ -29,16 +29,62 @@ use tracing_subscriber::{
 	registry::LookupSpan,
 	Layer,
 };
+use regex::Regex;
 
 /// Span name used for the logging prefix. See macro `sc_cli::prefix_logs_with!`
 pub const PREFIX_LOG_SPAN: &str = "substrate-log-prefix";
 
+/// A writer that may write to `inner_writer` with colors.
+///
+/// This is used by [`EventFormat`] to kill colors when `enable_color` is `false`.
+///
+/// It is required to call [`MaybeColorWriter::write`] after all writes are done,
+/// because the content of these writes is buffered and will only be written to the
+/// `inner_writer` at that point.
+struct MaybeColorWriter<'a> {
+	enable_color: bool,
+	buffer: String,
+	inner_writer: &'a mut dyn fmt::Write,
+}
+
+impl<'a> fmt::Write for MaybeColorWriter<'a> {
+	fn write_str(&mut self, buf: &str) -> fmt::Result {
+		self.buffer.push_str(buf);
+		Ok(())
+	}
+}
+
+impl<'a> MaybeColorWriter<'a> {
+	/// Creates a new instance.
+	fn new(enable_color: bool, inner_writer: &'a mut dyn fmt::Write) -> Self {
+		Self {
+			enable_color,
+			inner_writer,
+			buffer: String::new(),
+		}
+	}
+
+	/// Write the buffered content to the `inner_writer`.
+	fn write(&mut self) -> fmt::Result {
+		lazy_static::lazy_static! {
+			static ref RE: Regex = Regex::new("\x1b\\[[^m]+m").expect("Error initializing color regex");
+		}
+
+		if !self.enable_color {
+			let replaced = RE.replace_all(&self.buffer, "");
+			self.inner_writer.write_str(&replaced)
+		} else {
+			self.inner_writer.write_str(&self.buffer)
+		}
+	}
+}
+
 pub(crate) struct EventFormat<T = SystemTime> {
 	pub(crate) timer: T,
-	pub(crate) ansi: bool,
 	pub(crate) display_target: bool,
 	pub(crate) display_level: bool,
 	pub(crate) display_thread_name: bool,
+	pub(crate) enable_color: bool,
 }
 
 // NOTE: the following code took inspiration from tracing-subscriber
@@ -56,12 +102,13 @@ where
 		writer: &mut dyn fmt::Write,
 		event: &Event,
 	) -> fmt::Result {
+		let writer = &mut MaybeColorWriter::new(self.enable_color, writer);
 		let normalized_meta = event.normalized_metadata();
 		let meta = normalized_meta.as_ref().unwrap_or_else(|| event.metadata());
-		time::write(&self.timer, writer, self.ansi)?;
+		time::write(&self.timer, writer, self.enable_color)?;
 
 		if self.display_level {
-			let fmt_level = { FmtLevel::new(meta.level(), self.ansi) };
+			let fmt_level = { FmtLevel::new(meta.level(), self.enable_color) };
 			write!(writer, "{} ", fmt_level)?;
 		}
 
@@ -94,7 +141,9 @@ where
 			write!(writer, "{}:", meta.target())?;
 		}
 		ctx.format_fields(writer, event)?;
-		writeln!(writer)
+		writeln!(writer)?;
+
+		writer.write()
 	}
 }
 

client/cli/src/logging.rs

@@ -35,7 +35,9 @@ mod display;
 /// The format to print telemetry output in.
 #[derive(Clone, Debug)]
 pub struct OutputFormat {
-	/// Enable color output in logs. True by default.
+	/// Enable color output in logs.
+	///
+	/// Is enabled by default.
 	pub enable_color: bool,
 }