Major bump of tracing-subscriber version (paritytech#3891)

I don't think there are any more releases to the 0.2.x versions, so best
we're on the 0.3.x release.

No change on the benchmarks, fast local time is still just as fast as
before:

new version bench:
```
fast_local_time         time:   [30.551 ns 30.595 ns 30.668 ns]
```

old version bench:
```
fast_local_time         time:   [30.598 ns 30.646 ns 30.723 ns]
```

---------

Co-authored-by: Bastian Köcher <git@kchr.de>

Cargo.toml

@@ -558,6 +558,7 @@ serde_json = { version = "1.0.114", default-features = false }
 serde_yaml = { version = "0.9" }
 syn = { version = "2.0.53" }
 thiserror = { version = "1.0.48" }
+tracing-subscriber = { version = "0.3.18" }
 
 [profile.release]
 # Polkadot runtime requires unwinding.

substrate/client/executor/Cargo.toml

@@ -47,7 +47,7 @@ sp-runtime = { path = "../../primitives/runtime" }
 sp-maybe-compressed-blob = { path = "../../primitives/maybe-compressed-blob" }
 sc-tracing = { path = "../tracing" }
 sp-tracing = { path = "../../primitives/tracing" }
-tracing-subscriber = "0.2.19"
+tracing-subscriber = { workspace = true }
 paste = "1.0"
 regex = "1.6.0"
 criterion = "0.4.0"

substrate/client/tracing/Cargo.toml

@@ -30,7 +30,7 @@ serde = { workspace = true, default-features = true }
 thiserror = { workspace = true }
 tracing = "0.1.29"
 tracing-log = "0.1.3"
-tracing-subscriber = { version = "0.2.25", features = ["parking_lot"] }
+tracing-subscriber = { workspace = true, features = ["parking_lot"] }
 sc-client-api = { path = "../api" }
 sc-tracing-proc-macro = { path = "proc-macro" }
 sp-api = { path = "../../primitives/api" }
@@ -42,6 +42,7 @@ sp-tracing = { path = "../../primitives/tracing" }
 
 [dev-dependencies]
 criterion = "0.4.0"
+tracing-subscriber = { workspace = true, features = ["chrono", "parking_lot"] }
 
 [[bench]]
 name = "bench"

substrate/client/tracing/benches/bench.rs

@@ -16,15 +16,19 @@
 // limitations under the License.
 
 use criterion::{criterion_group, criterion_main, Criterion};
-use tracing_subscriber::fmt::time::{ChronoLocal, FormatTime};
+use tracing_subscriber::fmt::{
+	format,
+	time::{ChronoLocal, FormatTime},
+};
 
 fn bench_fast_local_time(c: &mut Criterion) {
 	c.bench_function("fast_local_time", |b| {
 		let mut buffer = String::new();
 		let t = sc_tracing::logging::FastLocalTime { with_fractional: true };
 		b.iter(|| {
 			buffer.clear();
-			t.format_time(&mut buffer).unwrap();
+			let mut writer = format::Writer::new(&mut buffer);
+			t.format_time(&mut writer).unwrap();
 		})
 	});
 }
@@ -33,10 +37,11 @@ fn bench_fast_local_time(c: &mut Criterion) {
 fn bench_chrono_local(c: &mut Criterion) {
 	c.bench_function("chrono_local", |b| {
 		let mut buffer = String::new();
-		let t = ChronoLocal::with_format("%Y-%m-%d %H:%M:%S%.3f".to_string());
+		let t = ChronoLocal::new("%Y-%m-%d %H:%M:%S%.3f".to_string());
 		b.iter(|| {
 			buffer.clear();
-			t.format_time(&mut buffer).unwrap();
+			let mut writer: format::Writer<'_> = format::Writer::new(&mut buffer);
+			t.format_time(&mut writer).unwrap();
 		})
 	});
 }

substrate/client/tracing/src/lib.rs

@@ -290,7 +290,7 @@ impl<S> Layer<S> for ProfilingLayer
 where
 	S: Subscriber + for<'span> LookupSpan<'span>,
 {
-	fn new_span(&self, attrs: &Attributes<'_>, id: &Id, ctx: Context<S>) {
+	fn on_new_span(&self, attrs: &Attributes<'_>, id: &Id, ctx: Context<S>) {
 		if let Some(span) = ctx.span(id) {
 			let mut extension = span.extensions_mut();
 			let parent_id = attrs.parent().cloned().or_else(|| {

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

@@ -24,7 +24,7 @@ use tracing::{Event, Level, Subscriber};
 use tracing_log::NormalizeEvent;
 use tracing_subscriber::{
 	field::RecordFields,
-	fmt::{time::FormatTime, FmtContext, FormatEvent, FormatFields},
+	fmt::{format, time::FormatTime, FmtContext, FormatEvent, FormatFields},
 	layer::Context,
 	registry::{LookupSpan, SpanRef},
 };
@@ -52,20 +52,20 @@ where
 	// NOTE: the following code took inspiration from tracing-subscriber
 	//
 	//       https://github.com/tokio-rs/tracing/blob/2f59b32/tracing-subscriber/src/fmt/format/mod.rs#L449
-	pub(crate) fn format_event_custom<'b, S, N>(
+	pub(crate) fn format_event_custom<'b, 'w, S, N>(
 		&self,
 		ctx: CustomFmtContext<'b, S, N>,
-		writer: &mut dyn fmt::Write,
+		writer: format::Writer<'w>,
 		event: &Event,
 	) -> fmt::Result
 	where
 		S: Subscriber + for<'a> LookupSpan<'a>,
 		N: for<'a> FormatFields<'a> + 'static,
 	{
-		let writer = &mut ControlCodeSanitizer::new(!self.enable_color, writer);
+		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, writer, self.enable_color)?;
+		time::write(&self.timer, &mut format::Writer::new(&mut writer), self.enable_color)?;
 
 		if self.display_level {
 			let fmt_level = { FmtLevel::new(meta.level(), self.enable_color) };
@@ -108,7 +108,7 @@ where
 			writer.sanitize = true;
 		}
 
-		ctx.format_fields(writer, event)?;
+		ctx.format_fields(format::Writer::new(writer), event)?;
 		writeln!(writer)?;
 
 		writer.flush()
@@ -127,7 +127,7 @@ where
 	fn format_event(
 		&self,
 		ctx: &FmtContext<S, N>,
-		writer: &mut dyn fmt::Write,
+		mut writer: format::Writer<'_>,
 		event: &Event,
 	) -> fmt::Result {
 		if self.dup_to_stdout &&
@@ -136,7 +136,8 @@ where
 				event.metadata().level() == &Level::ERROR)
 		{
 			let mut out = String::new();
-			self.format_event_custom(CustomFmtContext::FmtContext(ctx), &mut out, event)?;
+			let buf_writer = format::Writer::new(&mut out);
+			self.format_event_custom(CustomFmtContext::FmtContext(ctx), buf_writer, event)?;
 			writer.write_str(&out)?;
 			print!("{}", out);
 			Ok(())
@@ -237,9 +238,13 @@ impl<'a> fmt::Display for FmtThreadName<'a> {
 mod time {
 	use ansi_term::Style;
 	use std::fmt;
-	use tracing_subscriber::fmt::time::FormatTime;
+	use tracing_subscriber::fmt::{format, time::FormatTime};
 
-	pub(crate) fn write<T>(timer: T, writer: &mut dyn fmt::Write, with_ansi: bool) -> fmt::Result
+	pub(crate) fn write<T>(
+		timer: T,
+		writer: &mut format::Writer<'_>,
+		with_ansi: bool,
+	) -> fmt::Result
 	where
 		T: FormatTime,
 	{
@@ -269,11 +274,7 @@ where
 	S: Subscriber + for<'lookup> LookupSpan<'lookup>,
 	N: for<'writer> FormatFields<'writer> + 'static,
 {
-	fn format_fields<R: RecordFields>(
-		&self,
-		writer: &'a mut dyn fmt::Write,
-		fields: R,
-	) -> fmt::Result {
+	fn format_fields<R: RecordFields>(&self, writer: format::Writer<'_>, fields: R) -> fmt::Result {
 		match self {
 			CustomFmtContext::FmtContext(fmt_ctx) => fmt_ctx.format_fields(writer, fields),
 			CustomFmtContext::ContextWithFormatFields(_ctx, fmt_fields) =>
@@ -312,7 +313,7 @@ where
 struct ControlCodeSanitizer<'a> {
 	sanitize: bool,
 	buffer: String,
-	inner_writer: &'a mut dyn fmt::Write,
+	inner_writer: format::Writer<'a>,
 }
 
 impl<'a> fmt::Write for ControlCodeSanitizer<'a> {
@@ -342,7 +343,7 @@ fn strip_control_codes(input: &str) -> std::borrow::Cow<str> {
 
 impl<'a> ControlCodeSanitizer<'a> {
 	/// Creates a new instance.
-	fn new(sanitize: bool, inner_writer: &'a mut dyn fmt::Write) -> Self {
+	fn new(sanitize: bool, inner_writer: format::Writer<'a>) -> Self {
 		Self { sanitize, inner_writer, buffer: String::new() }
 	}
 

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

@@ -18,7 +18,7 @@
 
 use chrono::{Datelike, Timelike};
 use std::{cell::RefCell, fmt::Write, time::SystemTime};
-use tracing_subscriber::fmt::time::FormatTime;
+use tracing_subscriber::fmt::{format, time::FormatTime};
 
 /// A structure which, when `Display`d, will print out the current local time.
 #[derive(Debug, Clone, Copy, Eq, PartialEq, Default)]
@@ -76,7 +76,7 @@ thread_local! {
 }
 
 impl FormatTime for FastLocalTime {
-	fn format_time(&self, w: &mut dyn Write) -> std::fmt::Result {
+	fn format_time(&self, w: &mut format::Writer<'_>) -> std::fmt::Result {
 		const TIMESTAMP_PARTIAL_LENGTH: usize = "0000-00-00 00:00:00".len();
 
 		let elapsed = SystemTime::now()
@@ -128,8 +128,8 @@ impl FormatTime for FastLocalTime {
 }
 
 impl std::fmt::Display for FastLocalTime {
-	fn fmt(&self, w: &mut std::fmt::Formatter) -> std::fmt::Result {
-		self.format_time(w)
+	fn fmt(&self, mut w: &mut std::fmt::Formatter) -> std::fmt::Result {
+		self.format_time(&mut format::Writer::new(&mut w))
 	}
 }
 

substrate/client/tracing/src/logging/layers/prefix_layer.rs

@@ -32,7 +32,7 @@ impl<S> Layer<S> for PrefixLayer
 where
 	S: Subscriber + for<'a> LookupSpan<'a>,
 {
-	fn new_span(&self, attrs: &Attributes<'_>, id: &Id, ctx: Context<'_, S>) {
+	fn on_new_span(&self, attrs: &Attributes<'_>, id: &Id, ctx: Context<'_, S>) {
 		let span = match ctx.span(id) {
 			Some(span) => span,
 			None => {

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

@@ -104,7 +104,7 @@ fn prepare_subscriber<N, E, F, W>(
 where
 	N: for<'writer> FormatFields<'writer> + 'static,
 	E: FormatEvent<Registry, N> + 'static,
-	W: MakeWriter + 'static,
+	W: for<'writer> MakeWriter<'writer> + 'static,
 	F: layer::Layer<Formatter<N, E, W>> + Send + Sync + 'static,
 	FmtLayer<Registry, N, E, W>: layer::Layer<Registry> + Send + Sync + 'static,
 {

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

@@ -148,7 +148,7 @@ impl Default for MakeStderrWriter {
 	}
 }
 
-impl tracing_subscriber::fmt::MakeWriter for MakeStderrWriter {
+impl tracing_subscriber::fmt::MakeWriter<'_> for MakeStderrWriter {
 	type Writer = StderrWriter;
 
 	fn make_writer(&self) -> Self::Writer {

substrate/primitives/tracing/Cargo.toml

@@ -26,7 +26,8 @@ codec = { version = "3.6.1", package = "parity-scale-codec", default-features =
 ] }
 tracing = { version = "0.1.29", default-features = false }
 tracing-core = { version = "0.1.32", default-features = false }
-tracing-subscriber = { version = "0.2.25", optional = true, features = [
+tracing-subscriber = { workspace = true, optional = true, features = [
+	"env-filter",
 	"tracing-log",
 ] }