Skip to content
This repository has been archived by the owner on Nov 15, 2023. It is now read-only.

Logging improvements #14760

Open
wants to merge 3 commits into
base: master
Choose a base branch
from
Open

Logging improvements #14760

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
3 commits
Select commit Hold shift + click to select a range
fb2b3e1
Minor cleanup of unnecessarily full/partially qualified types
nazar-pc Aug 14, 2023
8888706
Allow disabling colors with `NO_COLOR` environment variable
nazar-pc Aug 14, 2023
ea40383
Add support for `--use-utc-log-time` CLI argument
nazar-pc Aug 14, 2023
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Jump to
Jump to file
Failed to load files.
Diff view
Diff view
9 changes: 9 additions & 0 deletions client/cli/src/config.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -554,6 +554,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:
Expand Down Expand Up @@ -608,6 +613,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);

Expand Down
11 changes: 10 additions & 1 deletion client/cli/src/params/shared_params.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -56,6 +56,10 @@ pub struct SharedParams {
#[arg(long)]
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.
Expand Down Expand Up @@ -114,7 +118,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
Expand Down
23 changes: 9 additions & 14 deletions client/tracing/src/logging/event_format.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -16,7 +16,6 @@
// You should have received a copy of the GNU General Public License
// along with this program. If not, see <https://www.gnu.org/licenses/>.

use crate::logging::fast_local_time::FastLocalTime;
use ansi_term::Colour;
use regex::Regex;
use std::fmt::{self, Write};
Expand All @@ -30,9 +29,9 @@ use tracing_subscriber::{
};

/// A pre-configured event formatter.
pub struct EventFormat<T = FastLocalTime> {
pub struct EventFormat {
/// Use the given timer for log message timestamps.
pub timer: T,
pub timer: Box<dyn FormatTime + Send + Sync + 'static>,
/// Sets whether or not an event's target is displayed.
pub display_target: bool,
/// Sets whether or not an event's level is displayed.
Expand All @@ -45,17 +44,14 @@ pub struct EventFormat<T = FastLocalTime> {
pub dup_to_stdout: bool,
}

impl<T> EventFormat<T>
where
T: FormatTime,
{
impl EventFormat {
// 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>(
&self,
ctx: CustomFmtContext<'b, S, N>,
writer: &mut dyn fmt::Write,
writer: &mut dyn Write,
event: &Event,
) -> fmt::Result
where
Expand All @@ -65,7 +61,7 @@ where
let 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, writer, self.enable_color)?;

if self.display_level {
let fmt_level = { FmtLevel::new(meta.level(), self.enable_color) };
Expand Down Expand Up @@ -118,16 +114,15 @@ 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
impl<S, N, T> FormatEvent<S, N> for EventFormat<T>
impl<S, N> FormatEvent<S, N> for EventFormat
where
S: Subscriber + for<'a> LookupSpan<'a>,
N: for<'a> FormatFields<'a> + 'static,
T: FormatTime,
{
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 &&
Expand Down Expand Up @@ -239,9 +234,9 @@ mod time {
use std::fmt;
use tracing_subscriber::fmt::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 dyn fmt::Write, with_ansi: bool) -> fmt::Result
where
T: FormatTime,
T: FormatTime + ?Sized,
{
if with_ansi {
let style = Style::new().dimmed();
Expand Down
38 changes: 28 additions & 10 deletions client/tracing/src/logging/mod.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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::*;
Expand All @@ -38,10 +38,11 @@ use tracing::Subscriber;
use tracing_subscriber::{
filter::LevelFilter,
fmt::{
format, FormatEvent, FormatFields, Formatter, Layer as FmtLayer, MakeWriter,
SubscriberBuilder,
format,
time::{ChronoUtc, FormatTime},
FormatEvent, FormatFields, Formatter, Layer as FmtLayer, MakeWriter, SubscriberBuilder,
},
layer::{self, SubscriberExt},
layer::SubscriberExt,
registry::LookupSpan,
EnvFilter, FmtSubscriber, Layer, Registry,
};
Expand Down Expand Up @@ -95,6 +96,7 @@ fn prepare_subscriber<N, E, F, W>(
directives: &str,
profiling_targets: Option<&str>,
force_colors: Option<bool>,
use_utc: bool,
detailed_output: bool,
builder_hook: impl Fn(
SubscriberBuilder<format::DefaultFields, EventFormat, EnvFilter, DefaultLogger>,
Expand All @@ -104,8 +106,8 @@ where
N: for<'writer> FormatFields<'writer> + 'static,
E: FormatEvent<Registry, N> + 'static,
W: MakeWriter + 'static,
F: layer::Layer<Formatter<N, E, W>> + Send + Sync + 'static,
FmtLayer<Registry, N, E, W>: layer::Layer<Registry> + Send + Sync + 'static,
F: Layer<Formatter<N, E, W>> + Send + Sync + 'static,
FmtLayer<Registry, N, E, W>: Layer<Registry> + Send + Sync + 'static,
{
// Accept all valid directives and print invalid ones
fn parse_user_directives(mut env_filter: EnvFilter, dirs: &str) -> Result<EnvFilter> {
Expand Down Expand Up @@ -166,12 +168,16 @@ 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: Box<dyn FormatTime + Send + Sync + 'static> = if use_utc {
Box::new(ChronoUtc::with_format("%Y-%m-%dT%H:%M:%S%.6fZ".to_string()))
} else {
Box::new(FastLocalTime { with_fractional: detailed_output })
};

let event_format = EventFormat {
timer,
Expand Down Expand Up @@ -203,6 +209,7 @@ pub struct LoggerBuilder {
custom_profiler: Option<Box<dyn crate::TraceHandler>>,
log_reloading: bool,
force_colors: Option<bool>,
use_utc: bool,
detailed_output: bool,
}

Expand All @@ -215,6 +222,7 @@ impl LoggerBuilder {
custom_profiler: None,
log_reloading: false,
force_colors: None,
use_utc: false,
detailed_output: false,
}
}
Expand Down Expand Up @@ -261,6 +269,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.
Expand All @@ -271,6 +285,7 @@ impl LoggerBuilder {
&self.directives,
Some(&profiling_targets),
self.force_colors,
self.use_utc,
self.detailed_output,
|builder| enable_log_reloading!(builder),
)?;
Expand All @@ -289,6 +304,7 @@ impl LoggerBuilder {
&self.directives,
Some(&profiling_targets),
self.force_colors,
self.use_utc,
self.detailed_output,
|builder| builder,
)?;
Expand All @@ -308,6 +324,7 @@ impl LoggerBuilder {
&self.directives,
None,
self.force_colors,
self.use_utc,
self.detailed_output,
|builder| enable_log_reloading!(builder),
)?;
Expand All @@ -320,6 +337,7 @@ impl LoggerBuilder {
&self.directives,
None,
self.force_colors,
self.use_utc,
self.detailed_output,
|builder| builder,
)?;
Expand Down Expand Up @@ -440,7 +458,7 @@ 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);
}
}

Expand Down Expand Up @@ -475,7 +493,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.
Expand Down