Skip to content

202406 early logs #9

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Closed
wants to merge 4 commits into from
Closed

202406 early logs #9

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
4 commits
Select commit Hold shift + click to select a range
4d7f8ea
test
ajtowns Jun 28, 2024
09a7fe1
apply-logging-opts-to-buffered-logs
ajtowns Jun 28, 2024
06970b7
limit-buffer
ajtowns Jun 28, 2024
ab3485b
Revert "test"
ajtowns Jun 28, 2024
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
98 changes: 63 additions & 35 deletions src/logging.cpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -4,6 +4,7 @@
// file COPYING or http://www.opensource.org/licenses/mit-license.php.

#include <logging.h>
#include <memusage.h>
#include <util/fs.h>
#include <util/string.h>
#include <util/threadnames.h>
Expand Down Expand Up @@ -72,16 +73,18 @@ bool BCLog::Logger::StartLogging()
// dump buffered messages from before we opened the log
m_buffering = false;
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);

return true;
Expand Down Expand Up @@ -276,28 +279,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 @@ -350,34 +348,64 @@ std::string BCLog::Logger::GetLogPrefix(BCLog::LogFlags category, BCLog::Level l
return s;
}

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)
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
{
StdLockGuard scoped_lock(m_cs);
std::string str_prefixed = LogEscapeMessage(str);
str.insert(0, GetLogPrefix(category, level));

if (m_started_new_line) {
str_prefixed.insert(0, GetLogPrefix(category, level));
if (m_log_sourcelocations) {
str.insert(0, "[" + RemovePrefix(source_file, "./") + ":" + ToString(source_line) + "] [" + logging_function + "] ");
}

if (m_log_sourcelocations && m_started_new_line) {
str_prefixed.insert(0, "[" + RemovePrefix(source_file, "./") + ":" + ToString(source_line) + "] [" + logging_function + "] ");
if (m_log_threadnames) {
str.insert(0, "[" + (threadname.empty() ? "unknown" : threadname) + "] ");
}

if (m_log_threadnames && m_started_new_line) {
const auto& threadname = util::ThreadGetInternalName();
str_prefixed.insert(0, "[" + (threadname.empty() ? "unknown" : threadname) + "] ");
}
str.insert(0, LogTimestampStr(now, mocktime));
}

str_prefixed = LogTimestampStr(str_prefixed);
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::LogPrintStr(const std::string& str, const std::string& logging_function, const std::string& source_file, int source_line, BCLog::LogFlags category, BCLog::Level level)
{
StdLockGuard scoped_lock(m_cs);
std::string str_prefixed = LogEscapeMessage(str);

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 && !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();
}
}
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
19 changes: 17 additions & 2 deletions src/logging.h
View file
Open in desktop
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 @@ -82,12 +83,24 @@ 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){1000000}; // buffer up to 1MB of log data prior to StartLogging
size_t m_cur_buffer_memusage GUARDED_BY(m_cs){0};

/**
* m_started_new_line is a state variable that will suppress printing of
Expand All @@ -106,7 +119,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