From 9c2f0e71d5403d9c40c9ec852f822d8f90e7fac5 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Bastian=20K=C3=B6cher?= Date: Thu, 12 Nov 2020 20:01:58 +0100 Subject: [PATCH] Don't log with colors when we are writing to a tty (#7525) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit * 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> --- Cargo.lock | 9 +++--- client/cli/Cargo.toml | 3 +- client/cli/src/lib.rs | 46 ++++++++++++++++++++++++----- client/cli/src/logging.rs | 59 +++++++++++++++++++++++++++++++++---- client/informant/src/lib.rs | 4 ++- 5 files changed, 102 insertions(+), 19 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 69657bb8e37d9..a664ecc629243 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -6243,9 +6243,9 @@ dependencies = [ [[package]] name = "regex" -version = "1.3.9" +version = "1.4.2" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "9c3780fcf44b193bc4d09f36d2a3c87b251da4a046c87795a0d35f4f927ad8e6" +checksum = "38cf2c13ed4745de91a5eb834e11c00bcc3709e773173b2ce4c56c9fbde04b9c" dependencies = [ "aho-corasick", "memchr", @@ -6265,9 +6265,9 @@ dependencies = [ [[package]] name = "regex-syntax" -version = "0.6.18" +version = "0.6.21" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "26412eb97c6b088a6997e05f69403a802a92d520de2f8e63c2b65f9e0f47c4e8" +checksum = "3b181ba2dcf07aaccad5448e8ead58db5b742cf85dfe035e2227f137a539a189" [[package]] name = "region" @@ -6588,6 +6588,7 @@ dependencies = [ "fdlimit", "futures 0.3.5", "hex", + "lazy_static", "libp2p", "log", "names", diff --git a/client/cli/Cargo.toml b/client/cli/Cargo.toml index b7e798a3ba1c1..51c499828ac2a 100644 --- a/client/cli/Cargo.toml +++ b/client/cli/Cargo.toml @@ -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" diff --git a/client/cli/src/lib.rs b/client/cli/src/lib.rs index c25693dc418b1..b543f80a9d3b3 100644 --- a/client/cli/src/lib.rs +++ b/client/cli/src/lib.rs @@ -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), + ); + } } diff --git a/client/cli/src/logging.rs b/client/cli/src/logging.rs index e1fc90505b45f..ffb4c3dfaafa1 100644 --- a/client/cli/src/logging.rs +++ b/client/cli/src/logging.rs @@ -16,8 +16,8 @@ // You should have received a copy of the GNU General Public License // along with this program. If not, see . +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 { 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() } } diff --git a/client/informant/src/lib.rs b/client/informant/src/lib.rs index c60eda76f63f6..d4f34cb488a97 100644 --- a/client/informant/src/lib.rs +++ b/client/informant/src/lib.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, }