#![warn(missing_docs)]
mod directives;
mod event_format;
mod fast_local_time;
mod layers;
mod stderr_writer;
pub(crate) type DefaultLogger = stderr_writer::MakeStderrWriter;
pub use directives::*;
pub use sc_tracing_proc_macro::*;
use is_terminal::IsTerminal;
use std::io;
use tracing::Subscriber;
use tracing_subscriber::{
filter::LevelFilter,
fmt::{
format, FormatEvent, FormatFields, Formatter, Layer as FmtLayer, MakeWriter,
SubscriberBuilder,
},
layer::{self, SubscriberExt},
registry::LookupSpan,
EnvFilter, FmtSubscriber, Layer, Registry,
};
pub use event_format::*;
pub use fast_local_time::FastLocalTime;
pub use layers::*;
use stderr_writer::MakeStderrWriter;
pub type Result<T> = std::result::Result<T, Error>;
#[derive(Debug, thiserror::Error)]
#[allow(missing_docs)]
#[non_exhaustive]
#[error(transparent)]
pub enum Error {
IoError(#[from] io::Error),
SetGlobalDefaultError(#[from] tracing::subscriber::SetGlobalDefaultError),
DirectiveParseError(#[from] tracing_subscriber::filter::ParseError),
SetLoggerError(#[from] tracing_log::log_tracer::SetLoggerError),
}
macro_rules! enable_log_reloading {
($builder:expr) => {{
let builder = $builder.with_filter_reloading();
let handle = builder.reload_handle();
set_reload_handle(handle);
builder
}};
}
fn to_log_level_filter(level_filter: Option<LevelFilter>) -> log::LevelFilter {
match level_filter {
Some(LevelFilter::INFO) | None => log::LevelFilter::Info,
Some(LevelFilter::TRACE) => log::LevelFilter::Trace,
Some(LevelFilter::WARN) => log::LevelFilter::Warn,
Some(LevelFilter::ERROR) => log::LevelFilter::Error,
Some(LevelFilter::DEBUG) => log::LevelFilter::Debug,
Some(LevelFilter::OFF) => log::LevelFilter::Off,
}
}
fn prepare_subscriber<N, E, F, W>(
directives: &str,
profiling_targets: Option<&str>,
force_colors: Option<bool>,
detailed_output: bool,
builder_hook: impl Fn(
SubscriberBuilder<format::DefaultFields, EventFormat, EnvFilter, DefaultLogger>,
) -> SubscriberBuilder<N, E, F, W>,
) -> Result<impl Subscriber + for<'a> LookupSpan<'a>>
where
N: for<'writer> FormatFields<'writer> + 'static,
E: FormatEvent<Registry, N> + '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,
{
fn parse_user_directives(mut env_filter: EnvFilter, dirs: &str) -> Result<EnvFilter> {
for dir in dirs.split(',') {
env_filter = env_filter.add_directive(parse_default_directive(dir)?);
}
Ok(env_filter)
}
let mut env_filter = EnvFilter::default()
.add_directive(parse_default_directive("info").expect("provided directive is valid"))
.add_directive(parse_default_directive("ws=off").expect("provided directive is valid"))
.add_directive(parse_default_directive("yamux=off").expect("provided directive is valid"))
.add_directive(
parse_default_directive("regalloc=off").expect("provided directive is valid"),
)
.add_directive(
parse_default_directive("cranelift_codegen=off").expect("provided directive is valid"),
)
.add_directive(
parse_default_directive("cranelift_wasm=warn").expect("provided directive is valid"),
)
.add_directive(parse_default_directive("hyper=warn").expect("provided directive is valid"))
.add_directive(
parse_default_directive("trust_dns_proto=off").expect("provided directive is valid"),
)
.add_directive(
parse_default_directive("hickory_proto=off").expect("provided directive is valid"),
)
.add_directive(
parse_default_directive("libp2p_mdns::behaviour::iface=off")
.expect("provided directive is valid"),
)
.add_directive(
parse_default_directive("rustls::common_state=off")
.expect("provided directive is valid"),
)
.add_directive(
parse_default_directive("rustls::conn=off").expect("provided directive is valid"),
);
if let Ok(lvl) = std::env::var("RUST_LOG") {
if lvl != "" {
env_filter = parse_user_directives(env_filter, &lvl)?;
}
}
if directives != "" {
env_filter = parse_user_directives(env_filter, directives)?;
}
if let Some(profiling_targets) = profiling_targets {
env_filter = parse_user_directives(env_filter, profiling_targets)?;
env_filter = env_filter.add_directive(
parse_default_directive("sc_tracing=trace").expect("provided directive is valid"),
);
}
let max_level_hint = Layer::<FmtSubscriber>::max_level_hint(&env_filter);
let max_level = to_log_level_filter(max_level_hint);
tracing_log::LogTracer::builder().with_max_level(max_level).init()?;
let detailed_output = match max_level_hint {
Some(level) if level <= tracing_subscriber::filter::LevelFilter::INFO => false,
_ => true,
} || detailed_output;
let enable_color = force_colors.unwrap_or_else(|| io::stderr().is_terminal());
let timer = fast_local_time::FastLocalTime { with_fractional: detailed_output };
console::set_colors_enabled(enable_color);
console::set_colors_enabled_stderr(enable_color);
let event_format = EventFormat {
timer,
display_target: detailed_output,
display_level: detailed_output,
display_thread_name: detailed_output,
dup_to_stdout: !io::stderr().is_terminal() && io::stdout().is_terminal(),
};
let builder = FmtSubscriber::builder().with_env_filter(env_filter);
let builder = builder.with_span_events(format::FmtSpan::NONE);
let builder = builder.with_writer(MakeStderrWriter::default());
let builder = builder.event_format(event_format);
let builder = builder_hook(builder);
let subscriber = builder.finish().with(PrefixLayer);
Ok(subscriber)
}
pub struct LoggerBuilder {
directives: String,
profiling: Option<(crate::TracingReceiver, String)>,
custom_profiler: Option<Box<dyn crate::TraceHandler>>,
log_reloading: bool,
force_colors: Option<bool>,
detailed_output: bool,
}
impl LoggerBuilder {
pub fn new<S: Into<String>>(directives: S) -> Self {
Self {
directives: directives.into(),
profiling: None,
custom_profiler: None,
log_reloading: false,
force_colors: None,
detailed_output: false,
}
}
pub fn with_profiling<S: Into<String>>(
&mut self,
tracing_receiver: crate::TracingReceiver,
profiling_targets: S,
) -> &mut Self {
self.profiling = Some((tracing_receiver, profiling_targets.into()));
self
}
pub fn with_custom_profiling(
&mut self,
custom_profiler: Box<dyn crate::TraceHandler>,
) -> &mut Self {
self.custom_profiler = Some(custom_profiler);
self
}
pub fn with_log_reloading(&mut self, enabled: bool) -> &mut Self {
self.log_reloading = enabled;
self
}
pub fn with_detailed_output(&mut self, detailed: bool) -> &mut Self {
self.detailed_output = detailed;
self
}
pub fn with_colors(&mut self, enable: bool) -> &mut Self {
self.force_colors = Some(enable);
self
}
pub fn init(self) -> Result<()> {
if let Some((tracing_receiver, profiling_targets)) = self.profiling {
if self.log_reloading {
let subscriber = prepare_subscriber(
&self.directives,
Some(&profiling_targets),
self.force_colors,
self.detailed_output,
|builder| enable_log_reloading!(builder),
)?;
let mut profiling =
crate::ProfilingLayer::new(tracing_receiver, &profiling_targets);
self.custom_profiler
.into_iter()
.for_each(|profiler| profiling.add_handler(profiler));
tracing::subscriber::set_global_default(subscriber.with(profiling))?;
Ok(())
} else {
let subscriber = prepare_subscriber(
&self.directives,
Some(&profiling_targets),
self.force_colors,
self.detailed_output,
|builder| builder,
)?;
let mut profiling =
crate::ProfilingLayer::new(tracing_receiver, &profiling_targets);
self.custom_profiler
.into_iter()
.for_each(|profiler| profiling.add_handler(profiler));
tracing::subscriber::set_global_default(subscriber.with(profiling))?;
Ok(())
}
} else if self.log_reloading {
let subscriber = prepare_subscriber(
&self.directives,
None,
self.force_colors,
self.detailed_output,
|builder| enable_log_reloading!(builder),
)?;
tracing::subscriber::set_global_default(subscriber)?;
Ok(())
} else {
let subscriber = prepare_subscriber(
&self.directives,
None,
self.force_colors,
self.detailed_output,
|builder| builder,
)?;
tracing::subscriber::set_global_default(subscriber)?;
Ok(())
}
}
}
#[cfg(test)]
mod tests {
use super::*;
use crate as sc_tracing;
use log::info;
use std::{
collections::BTreeMap,
env,
process::Command,
sync::{
atomic::{AtomicBool, AtomicUsize, Ordering},
Arc,
},
};
use tracing::{metadata::Kind, subscriber::Interest, Callsite, Level, Metadata};
const EXPECTED_LOG_MESSAGE: &'static str = "yeah logging works as expected";
const EXPECTED_NODE_NAME: &'static str = "THE_NODE";
fn init_logger(directives: &str) {
let _ = LoggerBuilder::new(directives).init().unwrap();
}
fn run_test_in_another_process(
test_name: &str,
test_body: impl FnOnce(),
) -> Option<std::process::Output> {
if env::var("RUN_FORKED_TEST").is_ok() {
test_body();
None
} else {
let output = Command::new(env::current_exe().unwrap())
.arg(test_name)
.env("RUN_FORKED_TEST", "1")
.output()
.unwrap();
assert!(output.status.success());
Some(output)
}
}
#[test]
fn test_logger_filters() {
run_test_in_another_process("test_logger_filters", || {
let test_directives =
"grandpa=debug,sync=trace,client=warn,telemetry,something-with-dash=error";
init_logger(&test_directives);
tracing::dispatcher::get_default(|dispatcher| {
let test_filter = |target, level| {
struct DummyCallSite;
impl Callsite for DummyCallSite {
fn set_interest(&self, _: Interest) {}
fn metadata(&self) -> &Metadata<'_> {
unreachable!();
}
}
let metadata = tracing::metadata!(
name: "",
target: target,
level: level,
fields: &[],
callsite: &DummyCallSite,
kind: Kind::SPAN,
);
dispatcher.enabled(&metadata)
};
assert!(test_filter("grandpa", Level::INFO));
assert!(test_filter("grandpa", Level::DEBUG));
assert!(!test_filter("grandpa", Level::TRACE));
assert!(test_filter("sync", Level::TRACE));
assert!(test_filter("client", Level::WARN));
assert!(test_filter("telemetry", Level::TRACE));
assert!(test_filter("something-with-dash", Level::ERROR));
});
});
}
#[test]
fn dash_in_target_name_works() {
let executable = env::current_exe().unwrap();
let output = Command::new(executable)
.env("ENABLE_LOGGING", "1")
.args(&["--nocapture", "log_something_with_dash_target_name"])
.output()
.unwrap();
let output = String::from_utf8(output.stderr).unwrap();
assert!(output.contains(EXPECTED_LOG_MESSAGE));
}
#[test]
fn log_something_with_dash_target_name() {
if env::var("ENABLE_LOGGING").is_ok() {
let test_directives = "test-target=info";
let _guard = init_logger(&test_directives);
log::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}} \[{}\] {}$",
EXPECTED_NODE_NAME, EXPECTED_LOG_MESSAGE,
))
.unwrap();
let executable = env::current_exe().unwrap();
let output = Command::new(executable)
.env("ENABLE_LOGGING", "1")
.args(&["--nocapture", "prefix_in_log_lines_entrypoint"])
.output()
.unwrap();
let output = String::from_utf8(output.stderr).unwrap();
assert!(re.is_match(output.trim()), "Expected:\n{}\nGot:\n{}", re, output);
}
#[test]
fn prefix_in_log_lines_entrypoint() {
if env::var("ENABLE_LOGGING").is_ok() {
let _guard = init_logger("");
prefix_in_log_lines_process();
}
}
#[crate::logging::prefix_logs_with(EXPECTED_NODE_NAME)]
fn prefix_in_log_lines_process() {
log::info!("{}", EXPECTED_LOG_MESSAGE);
}
#[test]
fn do_not_write_with_colors_on_tty_entrypoint() {
if env::var("ENABLE_LOGGING").is_ok() {
let _guard = init_logger("");
log::info!("{}", console::style(EXPECTED_LOG_MESSAGE).yellow());
}
}
#[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}} {}$",
EXPECTED_LOG_MESSAGE,
))
.unwrap();
let executable = env::current_exe().unwrap();
let output = Command::new(executable)
.env("ENABLE_LOGGING", "1")
.args(&["--nocapture", "do_not_write_with_colors_on_tty_entrypoint"])
.output()
.unwrap();
let output = String::from_utf8(output.stderr).unwrap();
assert!(re.is_match(output.trim()), "Expected:\n{}\nGot:\n{}", re, output);
}
#[test]
fn log_max_level_is_set_properly() {
fn run_test(rust_log: Option<String>, tracing_targets: Option<String>) -> String {
let executable = env::current_exe().unwrap();
let mut command = Command::new(executable);
command
.env("PRINT_MAX_LOG_LEVEL", "1")
.args(&["--nocapture", "log_max_level_is_set_properly"]);
if let Some(rust_log) = rust_log {
command.env("RUST_LOG", rust_log);
}
if let Some(tracing_targets) = tracing_targets {
command.env("TRACING_TARGETS", tracing_targets);
}
let output = command.output().unwrap();
dbg!(String::from_utf8(output.stderr)).unwrap()
}
if env::var("PRINT_MAX_LOG_LEVEL").is_ok() {
let mut builder = LoggerBuilder::new("");
if let Ok(targets) = env::var("TRACING_TARGETS") {
builder.with_profiling(crate::TracingReceiver::Log, targets);
}
builder.init().unwrap();
eprint!("MAX_LOG_LEVEL={:?}", log::max_level());
} else {
assert_eq!("MAX_LOG_LEVEL=Info", run_test(None, None));
assert_eq!("MAX_LOG_LEVEL=Trace", run_test(Some("test=trace".into()), None));
assert_eq!("MAX_LOG_LEVEL=Debug", run_test(Some("test=debug".into()), None));
assert_eq!("MAX_LOG_LEVEL=Trace", run_test(None, Some("test=info".into())));
}
}
fn run_on_many_threads(thread_count: usize, callback: impl Fn(usize) + 'static + Send + Clone) {
let started_count = Arc::new(AtomicUsize::new(0));
let barrier = Arc::new(AtomicBool::new(false));
let threads: Vec<_> = (0..thread_count)
.map(|nth_thread| {
let started_count = started_count.clone();
let barrier = barrier.clone();
let callback = callback.clone();
std::thread::spawn(move || {
started_count.fetch_add(1, Ordering::SeqCst);
while !barrier.load(Ordering::SeqCst) {
std::thread::yield_now();
}
callback(nth_thread);
})
})
.collect();
while started_count.load(Ordering::SeqCst) != thread_count {
std::thread::yield_now();
}
barrier.store(true, Ordering::SeqCst);
for thread in threads {
if let Err(error) = thread.join() {
println!("error: failed to join thread: {:?}", error);
unsafe { libc::abort() }
}
}
}
#[test]
fn parallel_logs_from_multiple_threads_are_properly_gathered() {
const THREAD_COUNT: usize = 128;
const LOGS_PER_THREAD: usize = 1024;
let output = run_test_in_another_process(
"parallel_logs_from_multiple_threads_are_properly_gathered",
|| {
let builder = LoggerBuilder::new("");
builder.init().unwrap();
run_on_many_threads(THREAD_COUNT, |nth_thread| {
for _ in 0..LOGS_PER_THREAD {
info!("Thread <<{}>>", nth_thread);
}
});
},
);
if let Some(output) = output {
let stderr = String::from_utf8(output.stderr).unwrap();
let mut count_per_thread = BTreeMap::new();
for line in stderr.split("\n") {
if let Some(index_s) = line.find("Thread <<") {
let index_s = index_s + "Thread <<".len();
let index_e = line.find(">>").unwrap();
let nth_thread: usize = line[index_s..index_e].parse().unwrap();
*count_per_thread.entry(nth_thread).or_insert(0) += 1;
}
}
assert_eq!(count_per_thread.len(), THREAD_COUNT);
for (_, count) in count_per_thread {
assert_eq!(count, LOGS_PER_THREAD);
}
}
}
#[test]
fn huge_single_line_log_is_properly_printed_out() {
let mut line = String::new();
line.push_str("$$START$$");
for n in 0..16 * 1024 * 1024 {
let ch = b'a' + (n as u8 % (b'z' - b'a'));
line.push(char::from(ch));
}
line.push_str("$$END$$");
let output =
run_test_in_another_process("huge_single_line_log_is_properly_printed_out", || {
let builder = LoggerBuilder::new("");
builder.init().unwrap();
info!("{}", line);
});
if let Some(output) = output {
let stderr = String::from_utf8(output.stderr).unwrap();
assert!(stderr.contains(&line));
}
}
}