mirror of
https://github.com/bitcoin/bitcoin.git
synced 2025-02-08 10:31:50 -05:00
logging: Apply formatting to early log messages
The formatting of log messages isn't defined until StartLogging() is called; so can't be correctly applied to early log messages from prior to that call. Instead of saving the output log message, save the inputs to the logging invocation (including time, mocktime and thread name), and format those inputs into a log message when StartLogging() is called.
This commit is contained in:
Anthony Towns
parent
6cf9b34440
commit
558df5c733
2 changed files with 80 additions and 42 deletions
105
src/logging.cpp
105
src/logging.cpp
|
|
@ -76,15 +76,16 @@ bool BCLog::Logger::StartLogging()
|
|||
LogPrintStr_(strprintf("Early logging buffer overflowed, %d log lines discarded.\n", m_buffer_lines_discarded), __func__, __FILE__, __LINE__, BCLog::ALL, Level::Info);
|
||||
}
|
||||
while (!m_msgs_before_open.empty()) {
|
||||
const std::string& s = m_msgs_before_open.front();
|
||||
const auto& buflog = m_msgs_before_open.front();
|
||||
std::string s{buflog.str};
|
||||
FormatLogStrInPlace(s, buflog.category, buflog.level, buflog.source_file, buflog.source_line, buflog.logging_function, buflog.threadname, buflog.now, buflog.mocktime);
|
||||
m_msgs_before_open.pop_front();
|
||||
|
||||
if (m_print_to_file) FileWriteStr(s, m_fileout);
|
||||
if (m_print_to_console) fwrite(s.data(), 1, s.size(), stdout);
|
||||
for (const auto& cb : m_print_callbacks) {
|
||||
cb(s);
|
||||
}
|
||||
|
||||
m_msgs_before_open.pop_front();
|
||||
}
|
||||
m_cur_buffer_memusage = 0;
|
||||
if (m_print_to_console) fflush(stdout);
|
||||
|
|
@ -298,28 +299,23 @@ std::string BCLog::Logger::LogLevelsString() const
|
|||
return Join(std::vector<BCLog::Level>{levels.begin(), levels.end()}, ", ", [](BCLog::Level level) { return LogLevelToStr(level); });
|
||||
}
|
||||
|
||||
std::string BCLog::Logger::LogTimestampStr(const std::string& str)
|
||||
std::string BCLog::Logger::LogTimestampStr(SystemClock::time_point now, std::chrono::seconds mocktime) const
|
||||
{
|
||||
std::string strStamped;
|
||||
|
||||
if (!m_log_timestamps)
|
||||
return str;
|
||||
return strStamped;
|
||||
|
||||
if (m_started_new_line) {
|
||||
const auto now{SystemClock::now()};
|
||||
const auto now_seconds{std::chrono::time_point_cast<std::chrono::seconds>(now)};
|
||||
strStamped = FormatISO8601DateTime(TicksSinceEpoch<std::chrono::seconds>(now_seconds));
|
||||
if (m_log_time_micros && !strStamped.empty()) {
|
||||
strStamped.pop_back();
|
||||
strStamped += strprintf(".%06dZ", Ticks<std::chrono::microseconds>(now - now_seconds));
|
||||
}
|
||||
std::chrono::seconds mocktime = GetMockTime();
|
||||
if (mocktime > 0s) {
|
||||
strStamped += " (mocktime: " + FormatISO8601DateTime(count_seconds(mocktime)) + ")";
|
||||
}
|
||||
strStamped += ' ' + str;
|
||||
} else
|
||||
strStamped = str;
|
||||
const auto now_seconds{std::chrono::time_point_cast<std::chrono::seconds>(now)};
|
||||
strStamped = FormatISO8601DateTime(TicksSinceEpoch<std::chrono::seconds>(now_seconds));
|
||||
if (m_log_time_micros && !strStamped.empty()) {
|
||||
strStamped.pop_back();
|
||||
strStamped += strprintf(".%06dZ", Ticks<std::chrono::microseconds>(now - now_seconds));
|
||||
}
|
||||
if (mocktime > 0s) {
|
||||
strStamped += " (mocktime: " + FormatISO8601DateTime(count_seconds(mocktime)) + ")";
|
||||
}
|
||||
strStamped += ' ';
|
||||
|
||||
return strStamped;
|
||||
}
|
||||
|
|
@ -372,9 +368,24 @@ std::string BCLog::Logger::GetLogPrefix(BCLog::LogFlags category, BCLog::Level l
|
|||
return s;
|
||||
}
|
||||
|
||||
static size_t MemUsage(const std::string& str)
|
||||
static size_t MemUsage(const BCLog::Logger::BufferedLog& buflog)
|
||||
{
|
||||
return str.size() + memusage::MallocUsage(sizeof(memusage::list_node<std::string>));
|
||||
return buflog.str.size() + buflog.logging_function.size() + buflog.source_file.size() + buflog.threadname.size() + memusage::MallocUsage(sizeof(memusage::list_node<BCLog::Logger::BufferedLog>));
|
||||
}
|
||||
|
||||
void BCLog::Logger::FormatLogStrInPlace(std::string& str, BCLog::LogFlags category, BCLog::Level level, const std::string& source_file, int source_line, const std::string& logging_function, const std::string& threadname, SystemClock::time_point now, std::chrono::seconds mocktime) const
|
||||
{
|
||||
str.insert(0, GetLogPrefix(category, level));
|
||||
|
||||
if (m_log_sourcelocations) {
|
||||
str.insert(0, "[" + RemovePrefix(source_file, "./") + ":" + ToString(source_line) + "] [" + logging_function + "] ");
|
||||
}
|
||||
|
||||
if (m_log_threadnames) {
|
||||
str.insert(0, "[" + (threadname.empty() ? "unknown" : threadname) + "] ");
|
||||
}
|
||||
|
||||
str.insert(0, LogTimestampStr(now, mocktime));
|
||||
}
|
||||
|
||||
void BCLog::Logger::LogPrintStr(const std::string& str, const std::string& logging_function, const std::string& source_file, int source_line, BCLog::LogFlags category, BCLog::Level level)
|
||||
|
|
@ -387,28 +398,37 @@ void BCLog::Logger::LogPrintStr_(const std::string& str, const std::string& logg
|
|||
{
|
||||
std::string str_prefixed = LogEscapeMessage(str);
|
||||
|
||||
if (m_started_new_line) {
|
||||
str_prefixed.insert(0, GetLogPrefix(category, level));
|
||||
}
|
||||
|
||||
if (m_log_sourcelocations && m_started_new_line) {
|
||||
str_prefixed.insert(0, "[" + RemovePrefix(source_file, "./") + ":" + ToString(source_line) + "] [" + logging_function + "] ");
|
||||
}
|
||||
|
||||
if (m_log_threadnames && m_started_new_line) {
|
||||
const auto& threadname = util::ThreadGetInternalName();
|
||||
str_prefixed.insert(0, "[" + (threadname.empty() ? "unknown" : threadname) + "] ");
|
||||
}
|
||||
|
||||
str_prefixed = LogTimestampStr(str_prefixed);
|
||||
|
||||
const bool starts_new_line = m_started_new_line;
|
||||
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);
|
||||
if (!starts_new_line) {
|
||||
if (!m_msgs_before_open.empty()) {
|
||||
m_msgs_before_open.back().str += str_prefixed;
|
||||
m_cur_buffer_memusage += str_prefixed.size();
|
||||
return;
|
||||
} else {
|
||||
// unlikely edge case; add a marker that something was trimmed
|
||||
str_prefixed.insert(0, "[...] ");
|
||||
}
|
||||
}
|
||||
|
||||
{
|
||||
BufferedLog buf{
|
||||
.now=SystemClock::now(),
|
||||
.mocktime=GetMockTime(),
|
||||
.str=str_prefixed,
|
||||
.logging_function=logging_function,
|
||||
.source_file=source_file,
|
||||
.threadname=util::ThreadGetInternalName(),
|
||||
.source_line=source_line,
|
||||
.category=category,
|
||||
.level=level,
|
||||
};
|
||||
m_cur_buffer_memusage += MemUsage(buf);
|
||||
m_msgs_before_open.push_back(std::move(buf));
|
||||
}
|
||||
|
||||
m_cur_buffer_memusage += MemUsage(str_prefixed);
|
||||
while (m_cur_buffer_memusage > m_max_buffer_memusage) {
|
||||
if (m_msgs_before_open.empty()) {
|
||||
m_cur_buffer_memusage = 0;
|
||||
|
|
@ -418,9 +438,14 @@ void BCLog::Logger::LogPrintStr_(const std::string& str, const std::string& logg
|
|||
m_msgs_before_open.pop_front();
|
||||
++m_buffer_lines_discarded;
|
||||
}
|
||||
|
||||
return;
|
||||
}
|
||||
|
||||
if (starts_new_line) {
|
||||
FormatLogStrInPlace(str_prefixed, category, level, source_file, source_line, logging_function, util::ThreadGetInternalName(), SystemClock::now(), GetMockTime());
|
||||
}
|
||||
|
||||
if (m_print_to_console) {
|
||||
// print to console
|
||||
fwrite(str_prefixed.data(), 1, str_prefixed.size(), stdout);
|
||||
|
|
|
|||
|
|
@ -10,6 +10,7 @@
|
|||
#include <tinyformat.h>
|
||||
#include <util/fs.h>
|
||||
#include <util/string.h>
|
||||
#include <util/time.h>
|
||||
|
||||
#include <atomic>
|
||||
#include <cstdint>
|
||||
|
|
@ -83,11 +84,21 @@ namespace BCLog {
|
|||
|
||||
class Logger
|
||||
{
|
||||
public:
|
||||
struct BufferedLog {
|
||||
SystemClock::time_point now;
|
||||
std::chrono::seconds mocktime;
|
||||
std::string str, logging_function, source_file, threadname;
|
||||
int source_line;
|
||||
LogFlags category;
|
||||
Level level;
|
||||
};
|
||||
|
||||
private:
|
||||
mutable StdMutex m_cs; // Can not use Mutex from sync.h because in debug mode it would cause a deadlock when a potential deadlock was detected
|
||||
|
||||
FILE* m_fileout GUARDED_BY(m_cs) = nullptr;
|
||||
std::list<std::string> m_msgs_before_open GUARDED_BY(m_cs);
|
||||
std::list<BufferedLog> m_msgs_before_open GUARDED_BY(m_cs);
|
||||
bool m_buffering GUARDED_BY(m_cs) = true; //!< Buffer messages before logging can be started.
|
||||
size_t m_max_buffer_memusage GUARDED_BY(m_cs){DEFAULT_MAX_LOG_BUFFER};
|
||||
size_t m_cur_buffer_memusage GUARDED_BY(m_cs){0};
|
||||
|
|
@ -110,7 +121,9 @@ namespace BCLog {
|
|||
/** Log categories bitfield. */
|
||||
std::atomic<uint32_t> m_categories{0};
|
||||
|
||||
std::string LogTimestampStr(const std::string& str);
|
||||
void FormatLogStrInPlace(std::string& str, LogFlags category, Level level, const std::string& source_file, int source_line, const std::string& logging_function, const std::string& threadname, SystemClock::time_point now, std::chrono::seconds mocktime) const;
|
||||
|
||||
std::string LogTimestampStr(SystemClock::time_point now, std::chrono::seconds mocktime) const;
|
||||
|
||||
/** Slots that connect to the print signal */
|
||||
std::list<std::function<void(const std::string&)>> m_print_callbacks GUARDED_BY(m_cs) {};
|
||||
|
|
|
|||
Loading…
Add table
Reference in a new issue