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.
Loading
Jump to
Jump to file
Failed to load files.
Loading
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
Loading