From 2891d3f17c30e341db91396c29426cb582ace35d Mon Sep 17 00:00:00 2001 From: Jun Jiang Date: Sat, 20 Jul 2024 13:25:21 +0800 Subject: [PATCH] Refactor to use `console` global ANSI style control --- bridges/relays/utils/src/initialize.rs | 2 - cumulus/test/service/src/lib.rs | 1 - polkadot/node/test/service/src/lib.rs | 1 - .../bin/node/cli/benches/block_production.rs | 1 - .../bin/node/cli/benches/transaction_pool.rs | 1 - substrate/client/cli/src/config.rs | 3 +- substrate/client/cli/src/runner.rs | 1 - substrate/client/informant/src/display.rs | 20 ++- substrate/client/informant/src/lib.rs | 51 ++----- substrate/client/service/src/builder.rs | 7 +- substrate/client/service/src/config.rs | 3 - substrate/client/service/test/src/lib.rs | 1 - substrate/client/tracing/Cargo.toml | 2 +- .../tracing/src/logging/event_format.rs | 128 +++--------------- substrate/client/tracing/src/logging/mod.rs | 34 +---- 15 files changed, 43 insertions(+), 213 deletions(-) diff --git a/bridges/relays/utils/src/initialize.rs b/bridges/relays/utils/src/initialize.rs index 1bb3f8b1c63e..cd0377caa3d6 100644 --- a/bridges/relays/utils/src/initialize.rs +++ b/bridges/relays/utils/src/initialize.rs @@ -41,8 +41,6 @@ pub fn initialize_logger(with_timestamp: bool) { ) .expect("static format string is valid"); - console::set_colors_enabled(true); - let mut builder = env_logger::Builder::new(); builder.filter_level(log::LevelFilter::Warn); builder.filter_module("bridge", log::LevelFilter::Info); diff --git a/cumulus/test/service/src/lib.rs b/cumulus/test/service/src/lib.rs index 51cdebbaf54e..0458a0768925 100644 --- a/cumulus/test/service/src/lib.rs +++ b/cumulus/test/service/src/lib.rs @@ -891,7 +891,6 @@ pub fn node_config( announce_block: true, data_path: root, base_path, - informant_output_format: Default::default(), wasm_runtime_overrides: None, runtime_cache_size: 2, }) diff --git a/polkadot/node/test/service/src/lib.rs b/polkadot/node/test/service/src/lib.rs index 35156a3a9372..a4e58253bb17 100644 --- a/polkadot/node/test/service/src/lib.rs +++ b/polkadot/node/test/service/src/lib.rs @@ -232,7 +232,6 @@ pub fn node_config( announce_block: true, data_path: root, base_path, - informant_output_format: Default::default(), } } diff --git a/substrate/bin/node/cli/benches/block_production.rs b/substrate/bin/node/cli/benches/block_production.rs index c16b25187e5f..8239637b3a9f 100644 --- a/substrate/bin/node/cli/benches/block_production.rs +++ b/substrate/bin/node/cli/benches/block_production.rs @@ -104,7 +104,6 @@ fn new_node(tokio_handle: Handle) -> node_cli::service::NewFullBase { announce_block: true, data_path: base_path.path().into(), base_path, - informant_output_format: Default::default(), wasm_runtime_overrides: None, }; diff --git a/substrate/bin/node/cli/benches/transaction_pool.rs b/substrate/bin/node/cli/benches/transaction_pool.rs index 6618f4b1132e..9a71a4ec585d 100644 --- a/substrate/bin/node/cli/benches/transaction_pool.rs +++ b/substrate/bin/node/cli/benches/transaction_pool.rs @@ -99,7 +99,6 @@ fn new_node(tokio_handle: Handle) -> node_cli::service::NewFullBase { announce_block: true, data_path: base_path.path().into(), base_path, - informant_output_format: Default::default(), wasm_runtime_overrides: None, }; diff --git a/substrate/client/cli/src/config.rs b/substrate/client/cli/src/config.rs index 783c9313121f..283148a6d6ad 100644 --- a/substrate/client/cli/src/config.rs +++ b/substrate/client/cli/src/config.rs @@ -27,7 +27,7 @@ use names::{Generator, Name}; use sc_service::{ config::{ BasePath, Configuration, DatabaseSource, IpNetwork, KeystoreConfig, NetworkConfiguration, - NodeKeyConfig, OffchainWorkerConfig, OutputFormat, PrometheusConfig, PruningMode, Role, + NodeKeyConfig, OffchainWorkerConfig, PrometheusConfig, PruningMode, Role, RpcBatchRequestConfig, RpcMethods, TelemetryEndpoints, TransactionPoolOptions, WasmExecutionMethod, }, @@ -550,7 +550,6 @@ pub trait CliConfiguration: Sized { announce_block: self.announce_block()?, role, base_path, - informant_output_format: OutputFormat { enable_color: !self.disable_log_color()? }, runtime_cache_size, }) } diff --git a/substrate/client/cli/src/runner.rs b/substrate/client/cli/src/runner.rs index 6d986e38d2fb..b0dbccfa634c 100644 --- a/substrate/client/cli/src/runner.rs +++ b/substrate/client/cli/src/runner.rs @@ -291,7 +291,6 @@ mod tests { announce_block: true, base_path: sc_service::BasePath::new(root.clone()), data_path: root, - informant_output_format: Default::default(), runtime_cache_size: 2, }, runtime, diff --git a/substrate/client/informant/src/display.rs b/substrate/client/informant/src/display.rs index a234281037d5..f513e80a0381 100644 --- a/substrate/client/informant/src/display.rs +++ b/substrate/client/informant/src/display.rs @@ -16,8 +16,7 @@ // You should have received a copy of the GNU General Public License // along with this program. If not, see . -use crate::OutputFormat; -use console::{Attribute, Color}; +use console::style; use log::info; use sc_client_api::ClientInfo; use sc_network::NetworkStatus; @@ -47,19 +46,16 @@ pub struct InformantDisplay { last_total_bytes_inbound: u64, /// The last seen total of bytes sent. last_total_bytes_outbound: u64, - /// The format to print output in. - format: OutputFormat, } impl InformantDisplay { /// Builds a new informant display system. - pub fn new(format: OutputFormat) -> InformantDisplay { + pub fn new() -> InformantDisplay { InformantDisplay { last_number: None, last_update: Instant::now(), last_total_bytes_inbound: 0, last_total_bytes_outbound: 0, - format, } } @@ -146,15 +142,15 @@ impl InformantDisplay { target: "substrate", "{} {}{} ({} peers), best: #{} ({}), finalized #{} ({}), {} {}", level, - self.format.print(Color::White, Some(Attribute::Bold), &status), + style(&status).white().bold().to_string(), target, - self.format.print(Color::White, Some(Attribute::Bold), format!("{}", num_connected_peers)), - self.format.print(Color::White, Some(Attribute::Bold), format!("{}", best_number)), + style(format!("{}", num_connected_peers)).white().bold().to_string(), + style(format!("{}", best_number)).white().bold().to_string(), best_hash, - self.format.print(Color::White, Some(Attribute::Bold), format!("{}", finalized_number)), + style(format!("{}", finalized_number)).white().bold().to_string(), info.chain.finalized_hash, - self.format.print(Color::Green, None, format!("⬇ {}", TransferRateFormat(avg_bytes_per_sec_inbound))), - self.format.print(Color::Red, None, format!("⬆ {}", TransferRateFormat(avg_bytes_per_sec_outbound))), + style(format!("⬇ {}", TransferRateFormat(avg_bytes_per_sec_inbound))).green().to_string(), + style(format!("⬆ {}", TransferRateFormat(avg_bytes_per_sec_outbound))).red().to_string(), ) } } diff --git a/substrate/client/informant/src/lib.rs b/substrate/client/informant/src/lib.rs index 0cc4a2913f92..bc4636622b62 100644 --- a/substrate/client/informant/src/lib.rs +++ b/substrate/client/informant/src/lib.rs @@ -18,7 +18,7 @@ //! Console informant. Prints sync progress and block events. Runs on the calling thread. -use console::{style, Attribute, Color}; +use console::style; use futures::prelude::*; use futures_timer::Delay; use log::{debug, info, trace}; @@ -36,45 +36,15 @@ fn interval(duration: Duration) -> impl Stream + Unpin { futures::stream::unfold((), move |_| Delay::new(duration).map(|_| Some(((), ())))).map(drop) } -/// The format to print telemetry output in. -#[derive(Clone, Debug)] -pub struct OutputFormat { - /// Enable color output in logs. - /// - /// Is enabled by default. - pub enable_color: bool, -} - -impl Default for OutputFormat { - fn default() -> Self { - Self { enable_color: true } - } -} - -impl OutputFormat { - /// Print with color if `self.enable_color == true`. - fn print(&self, color: Color, attr: Option, data: impl Display) -> impl Display { - if self.enable_color { - let mut styled = style(data).fg(color); - if let Some(attr) = attr { - styled = styled.attr(attr); - } - styled.to_string() - } else { - data.to_string() - } - } -} - /// Builds the informant and returns a `Future` that drives the informant. -pub async fn build(client: Arc, network: N, syncing: S, format: OutputFormat) +pub async fn build(client: Arc, network: N, syncing: S) where N: NetworkStatusProvider, S: SyncStatusProvider, C: UsageProvider + HeaderMetadata + BlockchainEvents, >::Error: Display, { - let mut display = display::InformantDisplay::new(format.clone()); + let mut display = display::InformantDisplay::new(); let client_1 = client.clone(); @@ -104,14 +74,11 @@ where futures::select! { () = display_notifications.fuse() => (), - () = display_block_import(client, format).fuse() => (), + () = display_block_import(client).fuse() => (), }; } -fn display_block_import( - client: Arc, - format: OutputFormat, -) -> impl Future +fn display_block_import(client: Arc) -> impl Future where C: UsageProvider + HeaderMetadata + BlockchainEvents, >::Error: Display, @@ -135,11 +102,11 @@ where match maybe_ancestor { Ok(ref ancestor) if ancestor.hash != *last_hash => info!( "♻️ Reorg on #{},{} to #{},{}, common ancestor #{},{}", - format.print(Color::Red, Some(Attribute::Bold), last_num), + style(last_num).red().bold().to_string(), last_hash, - format.print(Color::Green, Some(Attribute::Bold), n.header.number()), + style(n.header.number()).green().bold().to_string(), n.hash, - format.print(Color::White, Some(Attribute::Bold), ancestor.number), + style(ancestor.number).white().bold().to_string(), ancestor.hash, ), Ok(_) => {}, @@ -165,7 +132,7 @@ where info!( target: "substrate", "{best_indicator} Imported #{} ({} → {})", - format.print(Color::White, Some(Attribute::Bold), n.header.number()), + style(n.header.number()).white().bold().to_string(), n.header.parent_hash(), n.hash, ); diff --git a/substrate/client/service/src/builder.rs b/substrate/client/service/src/builder.rs index 06fc2ea3b304..638f30fad10e 100644 --- a/substrate/client/service/src/builder.rs +++ b/substrate/client/service/src/builder.rs @@ -514,12 +514,7 @@ where spawn_handle.spawn( "informant", None, - sc_informant::build( - client.clone(), - network, - sync_service.clone(), - config.informant_output_format, - ), + sc_informant::build(client.clone(), network, sync_service.clone()), ); task_manager.keep_alive((config.base_path, rpc)); diff --git a/substrate/client/service/src/config.rs b/substrate/client/service/src/config.rs index e4788f1f3376..f8d8511f2718 100644 --- a/substrate/client/service/src/config.rs +++ b/substrate/client/service/src/config.rs @@ -23,7 +23,6 @@ use prometheus_endpoint::Registry; use sc_chain_spec::ChainSpec; pub use sc_client_db::{BlocksPruning, Database, DatabaseSource, PruningMode}; pub use sc_executor::{WasmExecutionMethod, WasmtimeInstantiationStrategy}; -pub use sc_informant::OutputFormat; pub use sc_network::{ config::{ MultiaddrWithPeerId, NetworkConfiguration, NodeKeyConfig, NonDefaultSetConfig, ProtocolId, @@ -146,8 +145,6 @@ pub struct Configuration { pub data_path: PathBuf, /// Base path of the configuration. This is shared between chains. pub base_path: BasePath, - /// Configuration of the output format that the informant uses. - pub informant_output_format: OutputFormat, /// Maximum number of different runtime versions that can be cached. pub runtime_cache_size: u8, } diff --git a/substrate/client/service/test/src/lib.rs b/substrate/client/service/test/src/lib.rs index e60bd9410c64..5b9bb537563d 100644 --- a/substrate/client/service/test/src/lib.rs +++ b/substrate/client/service/test/src/lib.rs @@ -264,7 +264,6 @@ fn node_config( announce_block: true, base_path: BasePath::new(root.clone()), data_path: root, - informant_output_format: Default::default(), runtime_cache_size: 2, } } diff --git a/substrate/client/tracing/Cargo.toml b/substrate/client/tracing/Cargo.toml index 733c7c54aa8d..f39c5ecb4e43 100644 --- a/substrate/client/tracing/Cargo.toml +++ b/substrate/client/tracing/Cargo.toml @@ -24,7 +24,6 @@ lazy_static = { workspace = true } libc = { workspace = true } log = { workspace = true, default-features = true } parking_lot = { workspace = true, default-features = true } -regex = { workspace = true } rustc-hash = { workspace = true } serde = { workspace = true, default-features = true } thiserror = { workspace = true } @@ -42,6 +41,7 @@ sp-tracing = { workspace = true, default-features = true } [dev-dependencies] criterion = { workspace = true, default-features = true } +regex = { workspace = true } tracing-subscriber = { workspace = true, features = ["chrono", "parking_lot"] } [[bench]] diff --git a/substrate/client/tracing/src/logging/event_format.rs b/substrate/client/tracing/src/logging/event_format.rs index 4d425d67c218..4abceb383dfe 100644 --- a/substrate/client/tracing/src/logging/event_format.rs +++ b/substrate/client/tracing/src/logging/event_format.rs @@ -18,8 +18,7 @@ use crate::logging::fast_local_time::FastLocalTime; use console::style; -use regex::Regex; -use std::fmt::{self, Write}; +use std::fmt; use tracing::{Event, Level, Subscriber}; use tracing_log::NormalizeEvent; use tracing_subscriber::{ @@ -37,8 +36,6 @@ pub struct EventFormat { pub display_level: bool, /// Sets whether or not the name of the current thread is displayed when formatting events. pub display_thread_name: bool, - /// Enable ANSI terminal colors for formatted output. - pub enable_color: bool, /// Duplicate INFO, WARN and ERROR messages to stdout. pub dup_to_stdout: bool, } @@ -53,20 +50,19 @@ where pub(crate) fn format_event_custom<'b, 'w, S, N>( &self, ctx: &FmtContext<'b, S, N>, - writer: format::Writer<'w>, + mut writer: format::Writer<'w>, event: &Event, ) -> fmt::Result where S: Subscriber + for<'a> LookupSpan<'a>, N: for<'a> FormatFields<'a> + 'static, { - let mut writer = &mut ControlCodeSanitizer::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, &mut format::Writer::new(&mut writer), self.enable_color)?; + time::write(&self.timer, &mut format::Writer::new(&mut writer))?; if self.display_level { - let fmt_level = FmtLevel::new(meta.level(), self.enable_color); + let fmt_level = FmtLevel::new(meta.level()); write!(writer, "{} ", fmt_level)?; } @@ -74,17 +70,17 @@ where let current_thread = std::thread::current(); match current_thread.name() { Some(name) => { - write!(writer, "{} ", FmtThreadName::new(name))?; + write!(&mut writer, "{} ", FmtThreadName::new(name))?; }, // fall-back to thread id when name is absent and ids are not enabled None => { - write!(writer, "{:0>2?} ", current_thread.id())?; + write!(&mut writer, "{:0>2?} ", current_thread.id())?; }, } } if self.display_target { - write!(writer, "{}: ", meta.target())?; + write!(&mut writer, "{}: ", meta.target())?; } // Custom code to display node name @@ -92,24 +88,16 @@ where for span in span.scope() { let exts = span.extensions(); if let Some(prefix) = exts.get::() { - write!(writer, "{}", prefix.as_str())?; + write!(&mut writer, "{}", prefix.as_str())?; break } } } - // The writer only sanitizes its output once it's flushed, so if we don't actually need - // to sanitize everything we need to flush out what was already buffered as-is and only - // force-sanitize what follows. - if !writer.sanitize { - writer.flush()?; - writer.sanitize = true; - } - - ctx.format_fields(format::Writer::new(writer), event)?; - writeln!(writer)?; + ctx.format_fields(format::Writer::new(&mut writer), event)?; + writeln!(&mut writer)?; - writer.flush() + Ok(()) } } @@ -147,12 +135,11 @@ where struct FmtLevel<'a> { level: &'a Level, - ansi: bool, } impl<'a> FmtLevel<'a> { - pub(crate) fn new(level: &'a Level, ansi: bool) -> Self { - Self { level, ansi } + pub(crate) fn new(level: &'a Level) -> Self { + Self { level } } } @@ -164,22 +151,12 @@ const ERROR_STR: &str = "ERROR"; impl<'a> fmt::Display for FmtLevel<'a> { fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { - if self.ansi { - match *self.level { - Level::TRACE => write!(f, "{}", style(TRACE_STR).magenta().to_string()), - Level::DEBUG => write!(f, "{}", style(DEBUG_STR).blue().to_string()), - Level::INFO => write!(f, "{}", style(INFO_STR).green().to_string()), - Level::WARN => write!(f, "{}", style(WARN_STR).yellow().to_string()), - Level::ERROR => write!(f, "{}", style(ERROR_STR).red().to_string()), - } - } else { - match *self.level { - Level::TRACE => f.pad(TRACE_STR), - Level::DEBUG => f.pad(DEBUG_STR), - Level::INFO => f.pad(INFO_STR), - Level::WARN => f.pad(WARN_STR), - Level::ERROR => f.pad(ERROR_STR), - } + match *self.level { + Level::TRACE => write!(f, "{}", style(TRACE_STR).magenta().to_string()), + Level::DEBUG => write!(f, "{}", style(DEBUG_STR).blue().to_string()), + Level::INFO => write!(f, "{}", style(INFO_STR).green().to_string()), + Level::WARN => write!(f, "{}", style(WARN_STR).yellow().to_string()), + Level::ERROR => write!(f, "{}", style(ERROR_STR).red().to_string()), } } } @@ -237,80 +214,19 @@ mod time { use std::fmt; use tracing_subscriber::fmt::{format, time::FormatTime}; - pub(crate) fn write( - timer: T, - writer: &mut format::Writer<'_>, - with_ansi: bool, - ) -> fmt::Result + pub(crate) fn write(timer: T, writer: &mut format::Writer<'_>) -> fmt::Result where T: FormatTime, { - if with_ansi { + if console::colors_enabled() { write!(writer, "\x1B[2m")?; timer.format_time(writer)?; write!(writer, "\x1B[0m")?; } else { timer.format_time(writer)?; } - writer.write_char(' ')?; - Ok(()) - } -} -/// A writer which (optionally) strips out terminal control codes from the logs. -/// -/// This is used by [`EventFormat`] to sanitize the log messages. -/// -/// It is required to call [`ControlCodeSanitizer::flush`] 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 ControlCodeSanitizer<'a> { - sanitize: bool, - buffer: String, - inner_writer: format::Writer<'a>, -} - -impl<'a> fmt::Write for ControlCodeSanitizer<'a> { - fn write_str(&mut self, buf: &str) -> fmt::Result { - self.buffer.push_str(buf); - Ok(()) - } -} - -// NOTE: When making any changes here make sure to also change this function in `sp-panic-handler`. -fn strip_control_codes(input: &str) -> std::borrow::Cow { - lazy_static::lazy_static! { - static ref RE: Regex = Regex::new(r#"(?x) - \x1b\[[^m]+m| # VT100 escape codes - [ - \x00-\x09\x0B-\x1F # ASCII control codes / Unicode C0 control codes, except \n - \x7F # ASCII delete - \u{80}-\u{9F} # Unicode C1 control codes - \u{202A}-\u{202E} # Unicode left-to-right / right-to-left control characters - \u{2066}-\u{2069} # Same as above - ] - "#).expect("regex parsing doesn't fail; qed"); - } - - RE.replace_all(input, "") -} - -impl<'a> ControlCodeSanitizer<'a> { - /// Creates a new instance. - fn new(sanitize: bool, inner_writer: format::Writer<'a>) -> Self { - Self { sanitize, inner_writer, buffer: String::new() } - } - - /// Write the buffered content to the `inner_writer`. - fn flush(&mut self) -> fmt::Result { - if self.sanitize { - let replaced = strip_control_codes(&self.buffer); - self.inner_writer.write_str(&replaced)? - } else { - self.inner_writer.write_str(&self.buffer)? - } - - self.buffer.clear(); + writer.write_char(' ')?; Ok(()) } } diff --git a/substrate/client/tracing/src/logging/mod.rs b/substrate/client/tracing/src/logging/mod.rs index b54b0f111589..4fc8963da96a 100644 --- a/substrate/client/tracing/src/logging/mod.rs +++ b/substrate/client/tracing/src/logging/mod.rs @@ -183,13 +183,13 @@ where let timer = fast_local_time::FastLocalTime { with_fractional: detailed_output }; console::set_colors_enabled(enable_color); + console::set_colors_enabled_stderr(enable_color); let event_format = EventFormat { timer, display_target: detailed_output, display_level: detailed_output, display_thread_name: detailed_output, - enable_color, dup_to_stdout: !io::stderr().is_terminal() && io::stdout().is_terminal(), }; let builder = FmtSubscriber::builder().with_env_filter(env_filter); @@ -654,36 +654,4 @@ mod tests { assert!(stderr.contains(&line)); } } - - #[test] - fn control_characters_are_always_stripped_out_from_the_log_messages() { - const RAW_LINE: &str = "$$START$$\x1B[1;32mIn\u{202a}\u{202e}\u{2066}\u{2069}ner\n\r\x7ftext!\u{80}\u{9f}\x1B[0m$$END$$"; - const SANITIZED_LINE: &str = "$$START$$Inner\ntext!$$END$$"; - - let output = run_test_in_another_process( - "control_characters_are_always_stripped_out_from_the_log_messages", - || { - std::env::set_var("RUST_LOG", "trace"); - let mut builder = LoggerBuilder::new(""); - builder.with_colors(true); - builder.init().unwrap(); - log::error!("{}", RAW_LINE); - }, - ); - - if let Some(output) = output { - let stderr = String::from_utf8(output.stderr).unwrap(); - // The log messages should always be sanitized. - assert!(!stderr.contains(RAW_LINE)); - assert!(stderr.contains(SANITIZED_LINE)); - - // The part where the timestamp, the logging level, etc. is printed out doesn't - // always have to be sanitized unless it's necessary, and here it shouldn't be. - assert!(stderr.contains("\x1B[31mERROR\x1B[0m")); - - // Make sure the logs aren't being duplicated. - assert_eq!(stderr.find("ERROR"), stderr.rfind("ERROR")); - assert_eq!(stderr.find(SANITIZED_LINE), stderr.rfind(SANITIZED_LINE)); - } - } }