Merge #16112: util: Log early messages
faa2a47cd7
logging: Add threadsafety comments (MarcoFalke)0b282f9b00
Log early messages with -printtoconsole (Anthony Towns)412987430c
Replace OpenDebugLog() with StartLogging() (Anthony Towns) Pull request description: Early log messages are dropped on the floor and they'd never make it to the console or debug log. This can be tested by running the test included in this pull request without re-compiling the `bitcoind`. Fix that by buffering early messages and flushing them as soon as all logging options have been initialized and logging has been started. This pull request is identical to "Log early messages with -printtoconsole" (#13088) by **ajtowns**, with the following changes: * Rebased * Added docstrings for `m_buffering` and `StartLogging` * Switch `CCriticalSection` (aka `RecursiveMutex`) to just `Mutex` in the last commit * Added tests Fixes #16098 Fixes #13157 Closes #13088 ACKs for commit faa2a4: ajtowns: utACKfaa2a47cd7
hebasto: ACKfaa2a47cd7
kristapsk: ACKfaa2a47cd7
(ran added functional test before / after recompiling, didn't do additional testing) Tree-SHA512: 685e2882642fe2a43ce171d42862582dadb840d03cda8236a994322c389ca2a1f3f431b179b2726c155c61793543bb340c568a5455d97f8b83bc7d307a85d387
This commit is contained in:
commit
0853d8d2fd
4 changed files with 62 additions and 40 deletions
10
src/init.cpp
10
src/init.cpp
|
@ -852,12 +852,6 @@ void InitLogging()
|
||||||
{
|
{
|
||||||
LogInstance().m_print_to_file = !gArgs.IsArgNegated("-debuglogfile");
|
LogInstance().m_print_to_file = !gArgs.IsArgNegated("-debuglogfile");
|
||||||
LogInstance().m_file_path = AbsPathForConfigVal(gArgs.GetArg("-debuglogfile", DEFAULT_DEBUGLOGFILE));
|
LogInstance().m_file_path = AbsPathForConfigVal(gArgs.GetArg("-debuglogfile", DEFAULT_DEBUGLOGFILE));
|
||||||
|
|
||||||
// Add newlines to the logfile to distinguish this execution from the last
|
|
||||||
// one; called before console logging is set up, so this is only sent to
|
|
||||||
// debug.log.
|
|
||||||
LogPrintf("\n\n\n\n\n");
|
|
||||||
|
|
||||||
LogInstance().m_print_to_console = gArgs.GetBoolArg("-printtoconsole", !gArgs.GetBoolArg("-daemon", false));
|
LogInstance().m_print_to_console = gArgs.GetBoolArg("-printtoconsole", !gArgs.GetBoolArg("-daemon", false));
|
||||||
LogInstance().m_log_timestamps = gArgs.GetBoolArg("-logtimestamps", DEFAULT_LOGTIMESTAMPS);
|
LogInstance().m_log_timestamps = gArgs.GetBoolArg("-logtimestamps", DEFAULT_LOGTIMESTAMPS);
|
||||||
LogInstance().m_log_time_micros = gArgs.GetBoolArg("-logtimemicros", DEFAULT_LOGTIMEMICROS);
|
LogInstance().m_log_time_micros = gArgs.GetBoolArg("-logtimemicros", DEFAULT_LOGTIMEMICROS);
|
||||||
|
@ -1237,11 +1231,11 @@ bool AppInitMain(InitInterfaces& interfaces)
|
||||||
// and because this needs to happen before any other debug.log printing
|
// and because this needs to happen before any other debug.log printing
|
||||||
LogInstance().ShrinkDebugFile();
|
LogInstance().ShrinkDebugFile();
|
||||||
}
|
}
|
||||||
if (!LogInstance().OpenDebugLog()) {
|
}
|
||||||
|
if (!LogInstance().StartLogging()) {
|
||||||
return InitError(strprintf("Could not open debug log file %s",
|
return InitError(strprintf("Could not open debug log file %s",
|
||||||
LogInstance().m_file_path.string()));
|
LogInstance().m_file_path.string()));
|
||||||
}
|
}
|
||||||
}
|
|
||||||
|
|
||||||
if (!LogInstance().m_log_timestamps)
|
if (!LogInstance().m_log_timestamps)
|
||||||
LogPrintf("Startup time: %s\n", FormatISO8601DateTime(GetTime()));
|
LogPrintf("Startup time: %s\n", FormatISO8601DateTime(GetTime()));
|
||||||
|
|
|
@ -39,24 +39,38 @@ static int FileWriteStr(const std::string &str, FILE *fp)
|
||||||
return fwrite(str.data(), 1, str.size(), fp);
|
return fwrite(str.data(), 1, str.size(), fp);
|
||||||
}
|
}
|
||||||
|
|
||||||
bool BCLog::Logger::OpenDebugLog()
|
bool BCLog::Logger::StartLogging()
|
||||||
{
|
{
|
||||||
std::lock_guard<std::mutex> scoped_lock(m_file_mutex);
|
std::lock_guard<std::mutex> scoped_lock(m_cs);
|
||||||
|
|
||||||
|
assert(m_buffering);
|
||||||
assert(m_fileout == nullptr);
|
assert(m_fileout == nullptr);
|
||||||
assert(!m_file_path.empty());
|
|
||||||
|
|
||||||
|
if (m_print_to_file) {
|
||||||
|
assert(!m_file_path.empty());
|
||||||
m_fileout = fsbridge::fopen(m_file_path, "a");
|
m_fileout = fsbridge::fopen(m_file_path, "a");
|
||||||
if (!m_fileout) {
|
if (!m_fileout) {
|
||||||
return false;
|
return false;
|
||||||
}
|
}
|
||||||
|
|
||||||
setbuf(m_fileout, nullptr); // unbuffered
|
setbuf(m_fileout, nullptr); // unbuffered
|
||||||
|
|
||||||
|
// Add newlines to the logfile to distinguish this execution from the
|
||||||
|
// last one.
|
||||||
|
FileWriteStr("\n\n\n\n\n", m_fileout);
|
||||||
|
}
|
||||||
|
|
||||||
// dump buffered messages from before we opened the log
|
// dump buffered messages from before we opened the log
|
||||||
|
m_buffering = false;
|
||||||
while (!m_msgs_before_open.empty()) {
|
while (!m_msgs_before_open.empty()) {
|
||||||
FileWriteStr(m_msgs_before_open.front(), m_fileout);
|
const std::string& s = m_msgs_before_open.front();
|
||||||
|
|
||||||
|
if (m_print_to_file) FileWriteStr(s, m_fileout);
|
||||||
|
if (m_print_to_console) fwrite(s.data(), 1, s.size(), stdout);
|
||||||
|
|
||||||
m_msgs_before_open.pop_front();
|
m_msgs_before_open.pop_front();
|
||||||
}
|
}
|
||||||
|
if (m_print_to_console) fflush(stdout);
|
||||||
|
|
||||||
return true;
|
return true;
|
||||||
}
|
}
|
||||||
|
@ -204,6 +218,7 @@ std::string BCLog::Logger::LogTimestampStr(const std::string& str)
|
||||||
|
|
||||||
void BCLog::Logger::LogPrintStr(const std::string& str)
|
void BCLog::Logger::LogPrintStr(const std::string& str)
|
||||||
{
|
{
|
||||||
|
std::lock_guard<std::mutex> scoped_lock(m_cs);
|
||||||
std::string str_prefixed = str;
|
std::string str_prefixed = str;
|
||||||
|
|
||||||
if (m_log_threadnames && m_started_new_line) {
|
if (m_log_threadnames && m_started_new_line) {
|
||||||
|
@ -214,20 +229,20 @@ void BCLog::Logger::LogPrintStr(const std::string &str)
|
||||||
|
|
||||||
m_started_new_line = !str.empty() && str[str.size()-1] == '\n';
|
m_started_new_line = !str.empty() && str[str.size()-1] == '\n';
|
||||||
|
|
||||||
|
if (m_buffering) {
|
||||||
|
// buffer if we haven't started logging yet
|
||||||
|
m_msgs_before_open.push_back(str_prefixed);
|
||||||
|
return;
|
||||||
|
}
|
||||||
|
|
||||||
if (m_print_to_console) {
|
if (m_print_to_console) {
|
||||||
// print to console
|
// print to console
|
||||||
fwrite(str_prefixed.data(), 1, str_prefixed.size(), stdout);
|
fwrite(str_prefixed.data(), 1, str_prefixed.size(), stdout);
|
||||||
fflush(stdout);
|
fflush(stdout);
|
||||||
}
|
}
|
||||||
if (m_print_to_file) {
|
if (m_print_to_file) {
|
||||||
std::lock_guard<std::mutex> scoped_lock(m_file_mutex);
|
assert(m_fileout != nullptr);
|
||||||
|
|
||||||
// buffer if we haven't opened the log yet
|
|
||||||
if (m_fileout == nullptr) {
|
|
||||||
m_msgs_before_open.push_back(str_prefixed);
|
|
||||||
}
|
|
||||||
else
|
|
||||||
{
|
|
||||||
// reopen the log file, if requested
|
// reopen the log file, if requested
|
||||||
if (m_reopen_file) {
|
if (m_reopen_file) {
|
||||||
m_reopen_file = false;
|
m_reopen_file = false;
|
||||||
|
@ -241,7 +256,6 @@ void BCLog::Logger::LogPrintStr(const std::string &str)
|
||||||
FileWriteStr(str_prefixed, m_fileout);
|
FileWriteStr(str_prefixed, m_fileout);
|
||||||
}
|
}
|
||||||
}
|
}
|
||||||
}
|
|
||||||
|
|
||||||
void BCLog::Logger::ShrinkDebugFile()
|
void BCLog::Logger::ShrinkDebugFile()
|
||||||
{
|
{
|
||||||
|
|
|
@ -60,9 +60,10 @@ namespace BCLog {
|
||||||
class Logger
|
class Logger
|
||||||
{
|
{
|
||||||
private:
|
private:
|
||||||
FILE* m_fileout = nullptr;
|
mutable std::mutex m_cs; // Can not use Mutex from sync.h because in debug mode it would cause a deadlock when a potential deadlock was detected
|
||||||
std::mutex m_file_mutex;
|
FILE* m_fileout = nullptr; // GUARDED_BY(m_cs)
|
||||||
std::list<std::string> m_msgs_before_open;
|
std::list<std::string> m_msgs_before_open; // GUARDED_BY(m_cs)
|
||||||
|
bool m_buffering{true}; //!< Buffer messages before logging can be started. GUARDED_BY(m_cs)
|
||||||
|
|
||||||
/**
|
/**
|
||||||
* m_started_new_line is a state variable that will suppress printing of
|
* m_started_new_line is a state variable that will suppress printing of
|
||||||
|
@ -91,9 +92,15 @@ namespace BCLog {
|
||||||
void LogPrintStr(const std::string& str);
|
void LogPrintStr(const std::string& str);
|
||||||
|
|
||||||
/** Returns whether logs will be written to any output */
|
/** Returns whether logs will be written to any output */
|
||||||
bool Enabled() const { return m_print_to_console || m_print_to_file; }
|
bool Enabled() const
|
||||||
|
{
|
||||||
|
std::lock_guard<std::mutex> scoped_lock(m_cs);
|
||||||
|
return m_buffering || m_print_to_console || m_print_to_file;
|
||||||
|
}
|
||||||
|
|
||||||
|
/** Start logging (and flush all buffered messages) */
|
||||||
|
bool StartLogging();
|
||||||
|
|
||||||
bool OpenDebugLog();
|
|
||||||
void ShrinkDebugFile();
|
void ShrinkDebugFile();
|
||||||
|
|
||||||
uint32_t GetCategoryMask() const { return m_categories.load(); }
|
uint32_t GetCategoryMask() const { return m_categories.load(); }
|
||||||
|
|
|
@ -61,9 +61,16 @@ class ConfArgsTest(BitcoinTestFramework):
|
||||||
with open(inc_conf_file2_path, 'w', encoding='utf-8') as conf:
|
with open(inc_conf_file2_path, 'w', encoding='utf-8') as conf:
|
||||||
conf.write('') # clear
|
conf.write('') # clear
|
||||||
|
|
||||||
|
def test_log_buffer(self):
|
||||||
|
with self.nodes[0].assert_debug_log(expected_msgs=['Warning: parsed potentially confusing double-negative -connect=0']):
|
||||||
|
self.start_node(0, extra_args=['-noconnect=0'])
|
||||||
|
self.stop_node(0)
|
||||||
|
|
||||||
def run_test(self):
|
def run_test(self):
|
||||||
self.stop_node(0)
|
self.stop_node(0)
|
||||||
|
|
||||||
|
self.test_log_buffer()
|
||||||
|
|
||||||
self.test_config_file_parser()
|
self.test_config_file_parser()
|
||||||
|
|
||||||
# Remove the -datadir argument so it doesn't override the config file
|
# Remove the -datadir argument so it doesn't override the config file
|
||||||
|
|
Loading…
Reference in a new issue