From 90e86b53bff5cdd662a2d154cf098de82b3f2cee Mon Sep 17 00:00:00 2001 From: Jack Grigg Date: Tue, 11 Aug 2020 11:37:55 +0100 Subject: [PATCH 1/4] tracing: Parse log_path into an Option --- src/rust/src/tracing_ffi.rs | 20 ++++++++++++-------- 1 file changed, 12 insertions(+), 8 deletions(-) diff --git a/src/rust/src/tracing_ffi.rs b/src/rust/src/tracing_ffi.rs index cd2466b6d..3d7a32866 100644 --- a/src/rust/src/tracing_ffi.rs +++ b/src/rust/src/tracing_ffi.rs @@ -62,18 +62,22 @@ pub extern "C" fn tracing_init( .to_str() .expect("initial filter should be a valid string"); - if log_path.is_null() { - tracing_init_stdout(initial_filter, log_timestamps) + let log_path = if log_path.is_null() { + None } else { - let log_path = unsafe { slice::from_raw_parts(log_path, log_path_len) }; + Some(unsafe { slice::from_raw_parts(log_path, log_path_len) }) + }; - #[cfg(not(target_os = "windows"))] - let log_path = OsStr::from_bytes(log_path); + #[cfg(not(target_os = "windows"))] + let log_path = log_path.map(OsStr::from_bytes); - #[cfg(target_os = "windows")] - let log_path = OsString::from_wide(log_path); + #[cfg(target_os = "windows")] + let log_path = log_path.map(OsString::from_wide); - tracing_init_file(Path::new(&log_path), initial_filter, log_timestamps) + if let Some(log_path) = log_path.as_ref().map(Path::new) { + tracing_init_file(log_path, initial_filter, log_timestamps) + } else { + tracing_init_stdout(initial_filter, log_timestamps) } } From 25d2e6e3c39b9705386c45b3c1c6d2ebb876be33 Mon Sep 17 00:00:00 2001 From: Jack Grigg Date: Tue, 11 Aug 2020 12:55:11 +0100 Subject: [PATCH 2/4] tracing: Rework tracing_init into a single function This will make it possible to de-duplicate some components of the tracing configuration. The layers themselves cannot be fully de-duplicated due to type system constraints (a Layer wraps a Subscriber, and is itself a Subscriber typed on the one it wraps). --- src/rust/src/tracing_ffi.rs | 119 +++++++++++++++++++++--------------- 1 file changed, 70 insertions(+), 49 deletions(-) diff --git a/src/rust/src/tracing_ffi.rs b/src/rust/src/tracing_ffi.rs index 3d7a32866..ccbc83122 100644 --- a/src/rust/src/tracing_ffi.rs +++ b/src/rust/src/tracing_ffi.rs @@ -17,8 +17,9 @@ use tracing_appender::non_blocking::WorkerGuard; use tracing_core::Once; use tracing_subscriber::{ filter::EnvFilter, - layer::Layer, + layer::{Layer, SubscriberExt}, reload::{self, Handle}, + util::SubscriberInitExt, }; #[cfg(not(target_os = "windows"))] @@ -74,64 +75,84 @@ pub extern "C" fn tracing_init( #[cfg(target_os = "windows")] let log_path = log_path.map(OsString::from_wide); - if let Some(log_path) = log_path.as_ref().map(Path::new) { - tracing_init_file(log_path, initial_filter, log_timestamps) - } else { - tracing_init_stdout(initial_filter, log_timestamps) - } + tracing_init_inner( + log_path.as_ref().map(Path::new), + initial_filter, + log_timestamps, + ) } -fn tracing_init_stdout(initial_filter: &str, log_timestamps: bool) -> *mut TracingHandle { - let builder = tracing_subscriber::fmt() - .with_ansi(true) - .with_env_filter(initial_filter); - - let reload_handle = if log_timestamps { - let builder = builder.with_filter_reloading(); - let reload_handle = builder.reload_handle(); - builder.init(); - Box::new(reload_handle) as Box - } else { - let builder = builder.without_time().with_filter_reloading(); - let reload_handle = builder.reload_handle(); - builder.init(); - Box::new(reload_handle) as Box - }; - - Box::into_raw(Box::new(TracingHandle { - _file_guard: None, - reload_handle, - })) -} - -fn tracing_init_file( - log_path: &Path, +fn tracing_init_inner( + log_path: Option<&Path>, initial_filter: &str, log_timestamps: bool, ) -> *mut TracingHandle { - let file_appender = - tracing_appender::rolling::never(log_path.parent().unwrap(), log_path.file_name().unwrap()); - let (non_blocking, file_guard) = tracing_appender::non_blocking(file_appender); + let (file_logger, file_guard) = if let Some(log_path) = log_path { + let file_appender = tracing_appender::rolling::never( + log_path.parent().unwrap(), + log_path.file_name().unwrap(), + ); + let (non_blocking, file_guard) = tracing_appender::non_blocking(file_appender); - let builder = tracing_subscriber::fmt() - .with_ansi(false) - .with_env_filter(initial_filter) - .with_writer(non_blocking); - - let reload_handle = if log_timestamps { - let builder = builder.with_filter_reloading(); - let reload_handle = builder.reload_handle(); - builder.init(); - Box::new(reload_handle) as Box + ( + Some( + tracing_subscriber::fmt::layer() + .with_ansi(false) + .with_writer(non_blocking), + ), + Some(file_guard), + ) } else { - let builder = builder.without_time().with_filter_reloading(); - let reload_handle = builder.reload_handle(); - builder.init(); - Box::new(reload_handle) as Box + (None, None) + }; + let stdout_logger = tracing_subscriber::fmt::layer().with_ansi(true); + let filter = EnvFilter::from(initial_filter); + + let reload_handle = match (file_logger, log_timestamps) { + (None, true) => { + let (filter, reload_handle) = reload::Layer::new(filter); + + tracing_subscriber::registry() + .with(stdout_logger) + .with(filter) + .init(); + + Box::new(reload_handle) as Box + } + (None, false) => { + let (filter, reload_handle) = reload::Layer::new(filter); + + tracing_subscriber::registry() + .with(stdout_logger.without_time()) + .with(filter) + .init(); + + Box::new(reload_handle) as Box + } + (Some(file_logger), true) => { + let (filter, reload_handle) = reload::Layer::new(filter); + + tracing_subscriber::registry() + .with(file_logger) + .with(filter) + .init(); + + Box::new(reload_handle) as Box + } + (Some(file_logger), false) => { + let (filter, reload_handle) = reload::Layer::new(filter); + + tracing_subscriber::registry() + .with(file_logger.without_time()) + .with(filter) + .init(); + + Box::new(reload_handle) as Box + } }; Box::into_raw(Box::new(TracingHandle { - _file_guard: Some(file_guard), + _file_guard: file_guard, reload_handle, })) } From 735503b47308b46a2d0633995e5a972fb7d3b1f2 Mon Sep 17 00:00:00 2001 From: Jack Grigg Date: Tue, 11 Aug 2020 13:56:59 +0100 Subject: [PATCH 3/4] init: Rework tracing_init call --- src/init.cpp | 26 ++++++++++++++------------ 1 file changed, 14 insertions(+), 12 deletions(-) diff --git a/src/init.cpp b/src/init.cpp index 317216ae4..1c1ad0be4 100644 --- a/src/init.cpp +++ b/src/init.cpp @@ -808,20 +808,22 @@ void InitLogging() // Set up the initial filtering directive from the -debug flags. std::string initialFilter = LogConfigFilter(); - if (fPrintToConsole) { - pTracingHandle = tracing_init(nullptr, 0, initialFilter.c_str(), fLogTimestamps); - } else { - boost::filesystem::path pathDebug = GetDebugLogPath(); - const boost::filesystem::path::string_type& pathDebugStr = pathDebug.native(); - static_assert(sizeof(boost::filesystem::path::value_type) == sizeof(codeunit), - "native path has unexpected code unit size"); - pTracingHandle = tracing_init( - reinterpret_cast(pathDebugStr.c_str()), - pathDebugStr.length(), - initialFilter.c_str(), - fLogTimestamps); + boost::filesystem::path pathDebug = GetDebugLogPath(); + const boost::filesystem::path::string_type& pathDebugStr = pathDebug.native(); + static_assert(sizeof(boost::filesystem::path::value_type) == sizeof(codeunit), + "native path has unexpected code unit size"); + const codeunit* pathDebugCStr = nullptr; + size_t pathDebugLen = 0; + if (!fPrintToConsole) { + pathDebugCStr = reinterpret_cast(pathDebugStr.c_str()); + pathDebugLen = pathDebugStr.length(); } + pTracingHandle = tracing_init( + pathDebugCStr, pathDebugLen, + initialFilter.c_str(), + fLogTimestamps); + LogPrintf("\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n"); LogPrintf("Zcash version %s (%s)\n", FormatFullVersion(), CLIENT_DATE); } From 027a9925c9dea5d6ad05a7119de08810742e8e6b Mon Sep 17 00:00:00 2001 From: Jack Grigg Date: Tue, 11 Aug 2020 14:38:23 +0100 Subject: [PATCH 4/4] init: Add spans for initialization and shutdown --- src/bitcoind.cpp | 5 +++++ src/init.cpp | 6 ++++-- 2 files changed, 9 insertions(+), 2 deletions(-) diff --git a/src/bitcoind.cpp b/src/bitcoind.cpp index d7fe0ef6d..54b6359ed 100644 --- a/src/bitcoind.cpp +++ b/src/bitcoind.cpp @@ -170,6 +170,11 @@ bool AppInit(int argc, char* argv[]) // Set this early so that parameter interactions go to console InitLogging(); + + // Now that we have logging set up, start the initialization span. + auto span = TracingSpan("info", "main", "Init"); + auto spanGuard = span.Enter(); + InitParameterInteraction(); fRet = AppInit2(threadGroup, scheduler); } diff --git a/src/init.cpp b/src/init.cpp index 1c1ad0be4..b91076bcc 100644 --- a/src/init.cpp +++ b/src/init.cpp @@ -177,7 +177,9 @@ void Interrupt(boost::thread_group& threadGroup) void Shutdown() { - LogPrintf("%s: In progress...\n", __func__); + auto span = TracingSpan("info", "main", "Shutdown"); + auto spanGuard = span.Enter(); + static CCriticalSection cs_Shutdown; TRY_LOCK(cs_Shutdown, lockShutdown); if (!lockShutdown) @@ -260,7 +262,7 @@ void Shutdown() #endif globalVerifyHandle.reset(); ECC_Stop(); - LogPrintf("%s: done\n", __func__); + TracingInfo("main", "done"); if (pTracingHandle) { tracing_free(pTracingHandle); }