Merge branch 'logging-improvements' into subspace-v1

substrate/client/cli/src/config.rs

@@ -546,6 +546,11 @@ pub trait CliConfiguration<DCV: DefaultConfigurationValues = ()>: Sized {
 		Ok(self.shared_params().disable_log_color())
 	}
 
+	/// Should use UTC time in log output?
+	fn use_utc_log_time(&self) -> Result<bool> {
+		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<DCV: DefaultConfigurationValues = ()>: 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);
 

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

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();

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<S, N>,
-		writer: &mut dyn fmt::Write,
+		writer: &mut dyn Write,
 		event: &Event,
 	) -> fmt::Result {
 		if self.dup_to_stdout &&

substrate/client/tracing/src/logging/fast_local_time.rs

@@ -17,19 +17,28 @@
 // along with this program. If not, see <https://www.gnu.org/licenses/>.
 
 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,37 +165,53 @@ 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)
 	}
 }
 
 #[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,