From a8e3140c069cc0b527b1adb790a3d67bfdd49301 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Bastian=20K=C3=B6cher?= Date: Thu, 12 Nov 2020 11:24:13 +0100 Subject: [PATCH 1/6] 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. --- Cargo.lock | 10 +++-- client/cli/Cargo.toml | 3 +- client/cli/src/lib.rs | 79 ++++++++++++++++++++++++++++++++++--- client/informant/Cargo.toml | 1 + client/informant/src/lib.rs | 4 +- 5 files changed, 85 insertions(+), 12 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 62cb03dedafa3..5fc9910c505c1 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -6204,9 +6204,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", @@ -6226,9 +6226,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" @@ -6549,6 +6549,7 @@ dependencies = [ "fdlimit", "futures 0.3.5", "hex", + "lazy_static", "libp2p", "log", "names", @@ -7075,6 +7076,7 @@ name = "sc-informant" version = "0.8.0" dependencies = [ "ansi_term 0.12.1", + "atty", "futures 0.3.5", "log", "parity-util-mem", 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..b75e45b63c6ec 100644 --- a/client/cli/src/lib.rs +++ b/client/cli/src/lib.rs @@ -47,13 +47,14 @@ use structopt::{ clap::{self, AppSettings}, StructOpt, }; -#[doc(hidden)] -pub use tracing; use tracing_subscriber::{ - filter::Directive, fmt::time::ChronoLocal, layer::SubscriberExt, FmtSubscriber, Layer, + filter::Directive, fmt::{MakeWriter, time::ChronoLocal}, layer::SubscriberExt, FmtSubscriber, Layer, }; +use regex::bytes::Regex; pub use logging::PREFIX_LOG_SPAN; +#[doc(hidden)] +pub use tracing; /// Substrate client CLI /// @@ -318,7 +319,7 @@ pub fn init_logger( let subscriber = FmtSubscriber::builder() .with_env_filter(env_filter) - .with_writer(std::io::stderr) + .with_writer(MaybeColorWriter(enable_color)) .event_format(logging::EventFormat { timer, ansi: enable_color, @@ -346,6 +347,42 @@ pub fn init_logger( Ok(()) } +/// A writer that may writes to `stderr` with colors. +/// +/// This is used by the logging to kill colors when they are disabled. +/// +/// If the inner is `false`, the colors will be removed before writing to stderr. +#[derive(Clone)] +struct MaybeColorWriter(bool); + +impl std::io::Write for MaybeColorWriter { + fn write(&mut self, buf: &[u8]) -> std::io::Result { + lazy_static::lazy_static! { + static ref RE: Regex = Regex::new("\x1b\\[[^m]+m").expect("Error initializing color regex"); + } + + if !self.0 { + let replaced = RE.replace_all(buf, &b""[..]); + std::io::stderr().write(&replaced)?; + Ok(buf.len()) + } else { + std::io::stderr().write(buf) + } + } + + fn flush(&mut self) -> std::io::Result<()> { + std::io::stderr().flush() + } +} + +impl MakeWriter for MaybeColorWriter { + type Writer = Self; + + fn make_writer(&self) -> Self { + self.clone() + } +} + #[cfg(test)] mod tests { use super::*; @@ -450,8 +487,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 +496,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/informant/Cargo.toml b/client/informant/Cargo.toml index 871cc3ef426ec..528fc02bb5211 100644 --- a/client/informant/Cargo.toml +++ b/client/informant/Cargo.toml @@ -14,6 +14,7 @@ targets = ["x86_64-unknown-linux-gnu"] [dependencies] ansi_term = "0.12.1" +atty = "0.2.13" futures = "0.3.4" log = "0.4.8" parity-util-mem = { version = "0.7.0", default-features = false, features = ["primitive-types"] } 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, } From 8f6e19565e96cf627e23ce5ef64a1611e17ed060 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Bastian=20K=C3=B6cher?= Date: Thu, 12 Nov 2020 11:58:23 +0100 Subject: [PATCH 2/6] Remove accidentally added crate --- client/informant/Cargo.toml | 1 - 1 file changed, 1 deletion(-) diff --git a/client/informant/Cargo.toml b/client/informant/Cargo.toml index 528fc02bb5211..871cc3ef426ec 100644 --- a/client/informant/Cargo.toml +++ b/client/informant/Cargo.toml @@ -14,7 +14,6 @@ targets = ["x86_64-unknown-linux-gnu"] [dependencies] ansi_term = "0.12.1" -atty = "0.2.13" futures = "0.3.4" log = "0.4.8" parity-util-mem = { version = "0.7.0", default-features = false, features = ["primitive-types"] } From a628e4a966f2fdb561a2311d56cac21dc6859fea Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Bastian=20K=C3=B6cher?= Date: Thu, 12 Nov 2020 12:02:00 +0100 Subject: [PATCH 3/6] Review feedback --- Cargo.lock | 2 -- client/cli/Cargo.toml | 1 - client/cli/src/lib.rs | 27 ++++++++++++++++++--------- 3 files changed, 18 insertions(+), 12 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 5fc9910c505c1..6537111a37829 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -6549,7 +6549,6 @@ dependencies = [ "fdlimit", "futures 0.3.5", "hex", - "lazy_static", "libp2p", "log", "names", @@ -7076,7 +7075,6 @@ name = "sc-informant" version = "0.8.0" dependencies = [ "ansi_term 0.12.1", - "atty", "futures 0.3.5", "log", "parity-util-mem", diff --git a/client/cli/Cargo.toml b/client/cli/Cargo.toml index 51c499828ac2a..cdf0ae5b4e77e 100644 --- a/client/cli/Cargo.toml +++ b/client/cli/Cargo.toml @@ -16,7 +16,6 @@ targets = ["x86_64-unknown-linux-gnu"] log = "0.4.11" atty = "0.2.13" 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 b75e45b63c6ec..35789ae0c23a2 100644 --- a/client/cli/src/lib.rs +++ b/client/cli/src/lib.rs @@ -319,7 +319,7 @@ pub fn init_logger( let subscriber = FmtSubscriber::builder() .with_env_filter(env_filter) - .with_writer(MaybeColorWriter(enable_color)) + .with_writer(MaybeColorWriter::new(enable_color)) .event_format(logging::EventFormat { timer, ansi: enable_color, @@ -351,18 +351,27 @@ pub fn init_logger( /// /// This is used by the logging to kill colors when they are disabled. /// -/// If the inner is `false`, the colors will be removed before writing to stderr. +/// If the `enable_colors` is `false`, the colors will be removed before writing to stderr. #[derive(Clone)] -struct MaybeColorWriter(bool); +struct MaybeColorWriter{ + enable_colors: bool, + remove_color_regex: Regex, +} -impl std::io::Write for MaybeColorWriter { - fn write(&mut self, buf: &[u8]) -> std::io::Result { - lazy_static::lazy_static! { - static ref RE: Regex = Regex::new("\x1b\\[[^m]+m").expect("Error initializing color regex"); +impl MaybeColorWriter { + fn new(enable_colors: bool) -> Self { + Self { + enable_colors, + remove_color_regex: Regex::new("\x1b\\[[^m]+m") + .expect("Error initializing color regex"), } + } +} - if !self.0 { - let replaced = RE.replace_all(buf, &b""[..]); +impl std::io::Write for MaybeColorWriter { + fn write(&mut self, buf: &[u8]) -> std::io::Result { + if !self.enable_colors { + let replaced = self.remove_color_regex.replace_all(buf, &b""[..]); std::io::stderr().write(&replaced)?; Ok(buf.len()) } else { From 7ffa84d1f695a4fdd207e51a2b632c04b76419fd Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Bastian=20K=C3=B6cher?= Date: Thu, 12 Nov 2020 13:32:19 +0100 Subject: [PATCH 4/6] More feedback --- Cargo.lock | 1 + client/cli/Cargo.toml | 1 + client/cli/src/lib.rs | 58 ++++---------------------------------- client/cli/src/logging.rs | 59 +++++++++++++++++++++++++++++++++++---- 4 files changed, 62 insertions(+), 57 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 6537111a37829..7c9bdc4305d1a 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -6549,6 +6549,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 cdf0ae5b4e77e..51c499828ac2a 100644 --- a/client/cli/Cargo.toml +++ b/client/cli/Cargo.toml @@ -16,6 +16,7 @@ targets = ["x86_64-unknown-linux-gnu"] log = "0.4.11" atty = "0.2.13" 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 35789ae0c23a2..b543f80a9d3b3 100644 --- a/client/cli/src/lib.rs +++ b/client/cli/src/lib.rs @@ -48,9 +48,8 @@ use structopt::{ StructOpt, }; use tracing_subscriber::{ - filter::Directive, fmt::{MakeWriter, time::ChronoLocal}, layer::SubscriberExt, FmtSubscriber, Layer, + filter::Directive, fmt::time::ChronoLocal, layer::SubscriberExt, FmtSubscriber, Layer, }; -use regex::bytes::Regex; pub use logging::PREFIX_LOG_SPAN; #[doc(hidden)] @@ -309,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 { @@ -319,15 +317,16 @@ pub fn init_logger( let subscriber = FmtSubscriber::builder() .with_env_filter(env_filter) - .with_writer(MaybeColorWriter::new(enable_color)) + .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); @@ -347,51 +346,6 @@ pub fn init_logger( Ok(()) } -/// A writer that may writes to `stderr` with colors. -/// -/// This is used by the logging to kill colors when they are disabled. -/// -/// If the `enable_colors` is `false`, the colors will be removed before writing to stderr. -#[derive(Clone)] -struct MaybeColorWriter{ - enable_colors: bool, - remove_color_regex: Regex, -} - -impl MaybeColorWriter { - fn new(enable_colors: bool) -> Self { - Self { - enable_colors, - remove_color_regex: Regex::new("\x1b\\[[^m]+m") - .expect("Error initializing color regex"), - } - } -} - -impl std::io::Write for MaybeColorWriter { - fn write(&mut self, buf: &[u8]) -> std::io::Result { - if !self.enable_colors { - let replaced = self.remove_color_regex.replace_all(buf, &b""[..]); - std::io::stderr().write(&replaced)?; - Ok(buf.len()) - } else { - std::io::stderr().write(buf) - } - } - - fn flush(&mut self) -> std::io::Result<()> { - std::io::stderr().flush() - } -} - -impl MakeWriter for MaybeColorWriter { - type Writer = Self; - - fn make_writer(&self) -> Self { - self.clone() - } -} - #[cfg(test)] mod tests { use super::*; diff --git a/client/cli/src/logging.rs b/client/cli/src/logging.rs index e1fc90505b45f..f73da1c821e0c 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 writes 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 this 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() } } From dadea48bcaa11b8aa88fc22b21d6bc2fa75ca1f4 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Bastian=20K=C3=B6cher?= Date: Thu, 12 Nov 2020 19:09:59 +0100 Subject: [PATCH 5/6] Update client/cli/src/logging.rs MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Co-authored-by: André Silva <123550+andresilva@users.noreply.github.com> --- client/cli/src/logging.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/client/cli/src/logging.rs b/client/cli/src/logging.rs index f73da1c821e0c..8ac1ab31aaa01 100644 --- a/client/cli/src/logging.rs +++ b/client/cli/src/logging.rs @@ -40,7 +40,7 @@ pub const PREFIX_LOG_SPAN: &str = "substrate-log-prefix"; /// /// 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 this point. +/// `inner_writer` at that point. struct MaybeColorWriter<'a> { enable_color: bool, buffer: String, From 26969b923ee97aa8291b21a93fd05a7ee7162448 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Bastian=20K=C3=B6cher?= Date: Thu, 12 Nov 2020 19:10:11 +0100 Subject: [PATCH 6/6] Update client/cli/src/logging.rs MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Co-authored-by: André Silva <123550+andresilva@users.noreply.github.com> --- client/cli/src/logging.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/client/cli/src/logging.rs b/client/cli/src/logging.rs index 8ac1ab31aaa01..ffb4c3dfaafa1 100644 --- a/client/cli/src/logging.rs +++ b/client/cli/src/logging.rs @@ -34,7 +34,7 @@ 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 writes to `inner_writer` with colors. +/// A writer that may write to `inner_writer` with colors. /// /// This is used by [`EventFormat`] to kill colors when `enable_color` is `false`. ///