diff --git a/substrate/client/cli/src/config.rs b/substrate/client/cli/src/config.rs index 4d218da6aa898..a408321034de5 100644 --- a/substrate/client/cli/src/config.rs +++ b/substrate/client/cli/src/config.rs @@ -546,6 +546,11 @@ pub trait CliConfiguration: Sized { Ok(self.shared_params().disable_log_color()) } + /// Should use UTC time in log output? + fn use_utc_log_time(&self) -> Result { + Ok(self.shared_params().use_utc_log_time()) + } + /// Initialize substrate. This must be done only once per process. /// /// This method: @@ -600,6 +605,10 @@ pub trait CliConfiguration: Sized { logger.with_colors(false); } + if self.use_utc_log_time()? { + logger.with_utc(true); + } + // Call hook for custom profiling setup. logger_hook(&mut logger, config); diff --git a/substrate/client/cli/src/params/shared_params.rs b/substrate/client/cli/src/params/shared_params.rs index 3d20ca504a691..5de2560fd4f2d 100644 --- a/substrate/client/cli/src/params/shared_params.rs +++ b/substrate/client/cli/src/params/shared_params.rs @@ -53,9 +53,14 @@ pub struct SharedParams { pub detailed_log_output: bool, /// Disable log color output. - #[arg(long)] + #[cfg_attr(not(windows), arg(long))] + #[cfg_attr(windows, arg(long, default_value_t = true, action = clap::ArgAction::Set))] pub disable_log_color: bool, + /// Use UTC time in log output. + #[arg(long)] + pub use_utc_log_time: bool, + /// Enable feature to dynamically update and reload the log filter. /// Be aware that enabling this feature can lead to a performance decrease up to factor six or /// more. Depending on the global logging level the performance decrease changes. @@ -114,7 +119,12 @@ impl SharedParams { /// Should the log color output be disabled? pub fn disable_log_color(&self) -> bool { - self.disable_log_color + std::env::var("NO_COLOR").map_or(self.disable_log_color, |no_color| no_color == "1") + } + + /// Should use UTC time in log output? + pub fn use_utc_log_time(&self) -> bool { + self.use_utc_log_time } /// Is log reloading enabled diff --git a/substrate/client/tracing/benches/bench.rs b/substrate/client/tracing/benches/bench.rs index 1379023ddfa6c..79260ff8c386d 100644 --- a/substrate/client/tracing/benches/bench.rs +++ b/substrate/client/tracing/benches/bench.rs @@ -19,9 +19,17 @@ use criterion::{criterion_group, criterion_main, Criterion}; use tracing_subscriber::fmt::time::{ChronoLocal, FormatTime}; fn bench_fast_local_time(c: &mut Criterion) { - c.bench_function("fast_local_time", |b| { + c.bench_function("fast_local_time/local", |b| { let mut buffer = String::new(); - let t = sc_tracing::logging::FastLocalTime { with_fractional: true }; + let t = sc_tracing::logging::FastLocalTime { utc: false, with_fractional: true }; + b.iter(|| { + buffer.clear(); + t.format_time(&mut buffer).unwrap(); + }) + }); + c.bench_function("fast_local_time/utc", |b| { + let mut buffer = String::new(); + let t = sc_tracing::logging::FastLocalTime { utc: true, with_fractional: true }; b.iter(|| { buffer.clear(); t.format_time(&mut buffer).unwrap(); diff --git a/substrate/client/tracing/src/logging/event_format.rs b/substrate/client/tracing/src/logging/event_format.rs index f4579f006c25d..667062a9a9af8 100644 --- a/substrate/client/tracing/src/logging/event_format.rs +++ b/substrate/client/tracing/src/logging/event_format.rs @@ -55,7 +55,7 @@ where pub(crate) fn format_event_custom<'b, S, N>( &self, ctx: CustomFmtContext<'b, S, N>, - writer: &mut dyn fmt::Write, + writer: &mut dyn Write, event: &Event, ) -> fmt::Result where @@ -127,7 +127,7 @@ where fn format_event( &self, ctx: &FmtContext, - writer: &mut dyn fmt::Write, + writer: &mut dyn Write, event: &Event, ) -> fmt::Result { if self.dup_to_stdout && diff --git a/substrate/client/tracing/src/logging/fast_local_time.rs b/substrate/client/tracing/src/logging/fast_local_time.rs index 7be7bec8364aa..9e79e9664eca0 100644 --- a/substrate/client/tracing/src/logging/fast_local_time.rs +++ b/substrate/client/tracing/src/logging/fast_local_time.rs @@ -17,19 +17,28 @@ // along with this program. If not, see . use chrono::{Datelike, Timelike}; -use std::{cell::RefCell, fmt::Write, time::SystemTime}; +use std::{cell::RefCell, fmt, fmt::Write, time::SystemTime}; use tracing_subscriber::fmt::time::FormatTime; -/// A structure which, when `Display`d, will print out the current local time. +/// A structure which, when `Display`d, will print out the current time either in local timezone or +/// in UTC. #[derive(Debug, Clone, Copy, Eq, PartialEq, Default)] pub struct FastLocalTime { + /// Decides whenever to use UTC timezone instead. + /// + /// If `true` the output will match the following `chrono` format string: + /// `%Y-%m-%dT%H:%M:%S%.6fZ` + /// + /// This is the same format used by [`tracing_subscriber`] by default, `with_fractional` has no + /// effect when this option is set to `true`. + pub utc: bool, /// Decides whenever the fractional timestamp with be included in the output. /// /// If `false` the output will match the following `chrono` format string: - /// `%Y-%m-%d %H:%M:%S` + /// `%Y-%m-%d %H:%M:%S%:z` /// /// If `true` the output will match the following `chrono` format string: - /// `%Y-%m-%d %H:%M:%S%.3f` + /// `%Y-%m-%d %H:%M:%S%.3f%:z` pub with_fractional: bool, } @@ -43,7 +52,7 @@ struct InlineString { } impl Write for InlineString { - fn write_str(&mut self, s: &str) -> std::fmt::Result { + fn write_str(&mut self, s: &str) -> fmt::Result { let new_length = self.length + s.len(); assert!( new_length <= TIMESTAMP_MAXIMUM_LENGTH, @@ -66,8 +75,10 @@ impl InlineString { #[derive(Default)] struct CachedTimestamp { + timezone_offset: InlineString, buffer: InlineString, last_regenerated_at: u64, + last_utc: bool, last_fractional: u32, } @@ -76,7 +87,8 @@ thread_local! { } impl FormatTime for FastLocalTime { - fn format_time(&self, w: &mut dyn Write) -> std::fmt::Result { + fn format_time(&self, w: &mut dyn Write) -> fmt::Result { + const TIMESTAMP_PARTIAL_UTC_LENGTH: usize = "0000-00-00T00:00:00".len(); const TIMESTAMP_PARTIAL_LENGTH: usize = "0000-00-00 00:00:00".len(); let elapsed = SystemTime::now() @@ -88,24 +100,59 @@ impl FormatTime for FastLocalTime { let mut cache = cache.borrow_mut(); // Regenerate the timestamp only at most once each second. - if cache.last_regenerated_at != unix_time { - let ts = chrono::Local::now(); - let fractional = (ts.nanosecond() % 1_000_000_000) / 1_000_000; - cache.last_regenerated_at = unix_time; - cache.last_fractional = fractional; - cache.buffer.length = 0; - - write!( - &mut cache.buffer, - "{:04}-{:02}-{:02} {:02}:{:02}:{:02}.{:03}", - ts.year(), - ts.month(), - ts.day(), - ts.hour(), - ts.minute(), - ts.second(), - fractional - )?; + if cache.last_regenerated_at != unix_time || cache.last_utc != self.utc { + cache.last_utc = self.utc; + + if self.utc { + let ts = chrono::Utc::now(); + let fractional = (ts.nanosecond() % 1_000_000_000) / 1_000; + cache.last_regenerated_at = unix_time; + cache.last_fractional = fractional; + cache.buffer.length = 0; + + write!( + &mut cache.buffer, + "{:04}-{:02}-{:02}T{:02}:{:02}:{:02}.{:06}Z", + ts.year(), + ts.month(), + ts.day(), + ts.hour(), + ts.minute(), + ts.second(), + fractional + )?; + } else { + let ts = chrono::Local::now(); + let fractional = (ts.nanosecond() % 1_000_000_000) / 1_000_000; + cache.last_regenerated_at = unix_time; + cache.last_fractional = fractional; + cache.buffer.length = 0; + + write!( + &mut cache.buffer, + "{:04}-{:02}-{:02} {:02}:{:02}:{:02}.{:03}", + ts.year(), + ts.month(), + ts.day(), + ts.hour(), + ts.minute(), + ts.second(), + fractional + )?; + + if cache.timezone_offset.length == 0 { + write!(&mut cache.timezone_offset, "{}", ts.offset())?; + } + } + } else if self.utc { + let fractional = elapsed.subsec_micros(); + + // Regenerate the fractional part at most once each millisecond. + if cache.last_fractional != fractional { + cache.last_fractional = fractional; + cache.buffer.length = TIMESTAMP_PARTIAL_UTC_LENGTH + 1; + write!(&mut cache.buffer, "{:06}Z", fractional)?; + } } else if self.with_fractional { let fractional = elapsed.subsec_millis(); @@ -118,17 +165,25 @@ impl FormatTime for FastLocalTime { } let mut slice = cache.buffer.as_str(); - if !self.with_fractional { - slice = &slice[..TIMESTAMP_PARTIAL_LENGTH]; + + if self.utc { + w.write_str(slice)?; + } else { + if !self.with_fractional { + slice = &slice[..TIMESTAMP_PARTIAL_LENGTH]; + } + + w.write_str(slice)?; + w.write_str(cache.timezone_offset.as_str())?; } - w.write_str(slice) + Ok(()) }) } } -impl std::fmt::Display for FastLocalTime { - fn fmt(&self, w: &mut std::fmt::Formatter) -> std::fmt::Result { +impl fmt::Display for FastLocalTime { + fn fmt(&self, w: &mut fmt::Formatter) -> fmt::Result { self.format_time(w) } } @@ -136,19 +191,27 @@ impl std::fmt::Display for FastLocalTime { #[test] fn test_format_fast_local_time() { assert_eq!( - chrono::Local::now().format("%Y-%m-%d %H:%M:%S").to_string().len(), - FastLocalTime { with_fractional: false }.to_string().len() + chrono::Local::now().format("%Y-%m-%d %H:%M:%S%:z").to_string().len(), + FastLocalTime { utc: false, with_fractional: false }.to_string().len() + ); + assert_eq!( + chrono::Local::now().format("%Y-%m-%d %H:%M:%S%.3f%:z").to_string().len(), + FastLocalTime { utc: false, with_fractional: true }.to_string().len() + ); + assert_eq!( + chrono::Utc::now().format("%Y-%m-%dT%H:%M:%S%.6fZ").to_string().len(), + FastLocalTime { utc: true, with_fractional: false }.to_string().len() ); assert_eq!( - chrono::Local::now().format("%Y-%m-%d %H:%M:%S%.3f").to_string().len(), - FastLocalTime { with_fractional: true }.to_string().len() + chrono::Utc::now().format("%Y-%m-%dT%H:%M:%S%.6fZ").to_string().len(), + FastLocalTime { utc: true, with_fractional: true }.to_string().len() ); // A simple trick to make sure this test won't randomly fail if we so happen // to land on the exact moment when we tick over to the next second. - let now_1 = FastLocalTime { with_fractional: false }.to_string(); - let expected = chrono::Local::now().format("%Y-%m-%d %H:%M:%S").to_string(); - let now_2 = FastLocalTime { with_fractional: false }.to_string(); + let now_1 = FastLocalTime { utc: false, with_fractional: false }.to_string(); + let expected = chrono::Local::now().format("%Y-%m-%d %H:%M:%S%:z").to_string(); + let now_2 = FastLocalTime { utc: false, with_fractional: false }.to_string(); assert!( now_1 == expected || now_2 == expected, diff --git a/substrate/client/tracing/src/logging/mod.rs b/substrate/client/tracing/src/logging/mod.rs index a3cf277fbd501..435d801052446 100644 --- a/substrate/client/tracing/src/logging/mod.rs +++ b/substrate/client/tracing/src/logging/mod.rs @@ -28,7 +28,7 @@ mod fast_local_time; mod layers; mod stderr_writer; -pub(crate) type DefaultLogger = stderr_writer::MakeStderrWriter; +pub(crate) type DefaultLogger = MakeStderrWriter; pub use directives::*; pub use sc_tracing_proc_macro::*; @@ -41,7 +41,7 @@ use tracing_subscriber::{ format, FormatEvent, FormatFields, Formatter, Layer as FmtLayer, MakeWriter, SubscriberBuilder, }, - layer::{self, SubscriberExt}, + layer::SubscriberExt, registry::LookupSpan, EnvFilter, FmtSubscriber, Layer, Registry, }; @@ -95,6 +95,7 @@ fn prepare_subscriber( directives: &str, profiling_targets: Option<&str>, force_colors: Option, + use_utc: bool, detailed_output: bool, builder_hook: impl Fn( SubscriberBuilder, @@ -104,8 +105,8 @@ where N: for<'writer> FormatFields<'writer> + 'static, E: FormatEvent + 'static, W: MakeWriter + 'static, - F: layer::Layer> + Send + Sync + 'static, - FmtLayer: layer::Layer + Send + Sync + 'static, + F: Layer> + Send + Sync + 'static, + FmtLayer: Layer + Send + Sync + 'static, { // Accept all valid directives and print invalid ones fn parse_user_directives(mut env_filter: EnvFilter, dirs: &str) -> Result { @@ -166,12 +167,12 @@ where // If we're only logging `INFO` entries then we'll use a simplified logging format. let detailed_output = match max_level_hint { - Some(level) if level <= tracing_subscriber::filter::LevelFilter::INFO => false, + Some(level) if level <= LevelFilter::INFO => false, _ => true, } || detailed_output; let enable_color = force_colors.unwrap_or_else(|| atty::is(atty::Stream::Stderr)); - let timer = fast_local_time::FastLocalTime { with_fractional: detailed_output }; + let timer = FastLocalTime { utc: use_utc, with_fractional: detailed_output }; let event_format = EventFormat { timer, @@ -203,6 +204,7 @@ pub struct LoggerBuilder { custom_profiler: Option>, log_reloading: bool, force_colors: Option, + use_utc: bool, detailed_output: bool, } @@ -215,6 +217,7 @@ impl LoggerBuilder { custom_profiler: None, log_reloading: false, force_colors: None, + use_utc: false, detailed_output: false, } } @@ -261,6 +264,12 @@ impl LoggerBuilder { self } + /// Use UTC in log output. + pub fn with_utc(&mut self, utc: bool) -> &mut Self { + self.use_utc = utc; + self + } + /// Initialize the global logger /// /// This sets various global logging and tracing instances and thus may only be called once. @@ -271,6 +280,7 @@ impl LoggerBuilder { &self.directives, Some(&profiling_targets), self.force_colors, + self.use_utc, self.detailed_output, |builder| enable_log_reloading!(builder), )?; @@ -289,6 +299,7 @@ impl LoggerBuilder { &self.directives, Some(&profiling_targets), self.force_colors, + self.use_utc, self.detailed_output, |builder| builder, )?; @@ -308,6 +319,7 @@ impl LoggerBuilder { &self.directives, None, self.force_colors, + self.use_utc, self.detailed_output, |builder| enable_log_reloading!(builder), )?; @@ -320,6 +332,7 @@ impl LoggerBuilder { &self.directives, None, self.force_colors, + self.use_utc, self.detailed_output, |builder| builder, )?; @@ -440,14 +453,14 @@ mod tests { let test_directives = "test-target=info"; let _guard = init_logger(&test_directives); - log::info!(target: "test-target", "{}", EXPECTED_LOG_MESSAGE); + info!(target: "test-target", "{}", EXPECTED_LOG_MESSAGE); } } #[test] fn prefix_in_log_lines() { let re = regex::Regex::new(&format!( - r"^\d{{4}}-\d{{2}}-\d{{2}} \d{{2}}:\d{{2}}:\d{{2}} \[{}\] {}$", + r"^\d{{4}}-\d{{2}}-\d{{2}} \d{{2}}:\d{{2}}:\d{{2}}[\-\+]\d{{2}}:\d{{2}} \[{}\] {}$", EXPECTED_NODE_NAME, EXPECTED_LOG_MESSAGE, )) .unwrap(); @@ -475,7 +488,7 @@ mod tests { #[crate::logging::prefix_logs_with(EXPECTED_NODE_NAME)] fn prefix_in_log_lines_process() { - log::info!("{}", EXPECTED_LOG_MESSAGE); + info!("{}", EXPECTED_LOG_MESSAGE); } /// This is not an actual test, it is used by the `do_not_write_with_colors_on_tty` test. @@ -492,7 +505,7 @@ mod tests { #[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}} {}$", + r"^\d{{4}}-\d{{2}}-\d{{2}} \d{{2}}:\d{{2}}:\d{{2}}[\-\+]\d{{2}}:\d{{2}} {}$", EXPECTED_LOG_MESSAGE, )) .unwrap();