Skip to content

Commit

Permalink
logging: Apply formatting to early log messages
Browse files Browse the repository at this point in the history 
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.
  • Loading branch information
@ajtowns
ajtowns committed Jul 3, 2024
1 parent 3d4b1f4 commit 0456828
Show file tree
Hide file tree
Showing 2 changed files with 80 additions and 50 deletions.
113 changes: 65 additions & 48 deletions src/logging.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -76,15 +76,16 @@ bool BCLog::Logger::StartLogging()
LogPrintStr_(strprintf("Early logging buffer overflowed, %d log lines skipped\n", m_buffer_lines_skipped), __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);
Expand Down Expand Up @@ -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;

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;
return strStamped;

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;
}
Expand Down Expand Up @@ -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 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, std::string source_file, int source_line, std::string logging_function, std::string threadname, SystemClock::time_point now, std::chrono::seconds mocktime) const
{
return str.size() + memusage::MallocUsage(sizeof(memusage::list_node<std::string>));
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)
Expand All @@ -387,38 +398,44 @@ 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);

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;
break;
if (!starts_new_line && !m_msgs_before_open.empty()) {
m_msgs_before_open.back().str += str;
m_cur_buffer_memusage += str.size();
} else {
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_msgs_before_open.push_back(buf);
m_cur_buffer_memusage += MemUsage(buf);
while (m_cur_buffer_memusage > m_max_buffer_memusage) {
if (m_msgs_before_open.empty()) {
m_cur_buffer_memusage = 0;
break;
}
m_cur_buffer_memusage -= MemUsage(m_msgs_before_open.front());
m_msgs_before_open.pop_front();
++m_buffer_lines_skipped;
}
m_cur_buffer_memusage -= MemUsage(m_msgs_before_open.front());
m_msgs_before_open.pop_front();
++m_buffer_lines_skipped;
}
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);
Expand Down
17 changes: 15 additions & 2 deletions src/logging.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -10,6 +10,7 @@
#include <tinyformat.h>
#include <util/fs.h>
#include <util/string.h>
#include <util/time.h>

#include <atomic>
#include <cstdint>
Expand Down Expand Up @@ -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};
Expand All @@ -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, std::string source_file, int source_line, std::string logging_function, 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) {};
Expand Down

0 comments on commit 0456828

Please sign in to comment.