Skip to content
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

Output the number of times a log has been throttled #1876

Merged
merged 5 commits into from
Oct 8, 2024
Merged

Output the number of times a log has been throttled #1876

Show file tree
Hide file tree
Changes from 1 commit
Commits
Show all changes
5 commits
Select commit Hold shift + click to select a range
bb13883
Output the number of times a log has been throttled
Molter73 Oct 4, 2024
24093a0
Always count when checking if a log should be print
Molter73 Oct 4, 2024
0b7a6c7
PR comments
Molter73 Oct 8, 2024
314a7f8
Add documentation to ThrottledLogHeader::Suppress
Molter73 Oct 8, 2024
0d5be43
Minor comment adjustments
Molter73 Oct 8, 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
7 changes: 5 additions & 2 deletions collector/lib/Logging.cpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -101,6 +101,8 @@ bool ParseLogLevelName(std::string name, LogLevel* level) {
}

void InspectorLogCallback(std::string&& msg, sinsp_logger::severity severity) {
using namespace collector::logging;

auto collector_severity = (LogLevel)severity;

if (collector_severity == LogLevel::DEBUG && msg.rfind("libbpf:", 0) == 0) {
Expand All @@ -109,11 +111,12 @@ void InspectorLogCallback(std::string&& msg, sinsp_logger::severity severity) {
collector_severity = LogLevel::TRACE;
}

if (!collector::logging::CheckLogLevel(collector_severity)) {
if (!CheckLogLevel(collector_severity)) {
return;
}

collector::logging::LogMessage(__FILE__, __LINE__, false, collector_severity) << msg;
static LogHeader header(__FILE__, __LINE__, collector_severity);
LogMessage(header) << msg;
}

const char* GetGlobalLogPrefix() {
Expand Down
113 changes: 88 additions & 25 deletions collector/lib/Logging.h
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -54,15 +54,21 @@ void WriteTerminationLog(std::string message);

const size_t LevelPaddingWidth = 7;

class LogMessage {
class ILogHeader {
public:
LogMessage(const char* file, int line, bool throttled, LogLevel level)
: file_(file), line_(line), level_(level), throttled_(throttled) {
// if in debug mode, output file names associated with log messages
include_file_ = CheckLogLevel(LogLevel::DEBUG);
}

~LogMessage() {
ILogHeader(const char* file, int line, LogLevel level)
: file_(file), line_(line), level_(level) {}
ILogHeader(const ILogHeader&) = delete;
ILogHeader(ILogHeader&&) = delete;
ILogHeader& operator=(const ILogHeader&) = delete;
ILogHeader& operator=(ILogHeader&&) = delete;
virtual ~ILogHeader() = default;

virtual void PrintHeader() = 0;
inline LogLevel GetLogLevel() const { return level_; }

protected:
void PrintPrefix() {
auto now = std::chrono::system_clock::to_time_t(std::chrono::system_clock::now());
auto nowTm = gmtime(&now);

Expand All @@ -71,25 +77,79 @@ class LogMessage {
<< std::left << std::setw(LevelPaddingWidth) << GetLogLevelName(level_)
<< " " << std::put_time(nowTm, "%Y/%m/%d %H:%M:%S")
<< "] ";
}

if (throttled_) {
std::cerr << "[Throttled] ";
}

if (include_file_) {
void PrintFile() {
if (CheckLogLevel(LogLevel::DEBUG)) {
const char* basename = strrchr(file_, '/');
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

It's strictly speaking beyond this PR, but since we have c++17, why don't we use something fancy here, like std::filesystem::path instead of a plain string?

Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I didn't want to do too many changes here outside of counting logs, but I agree that using std::filesystem::path makes more sense here, I'll take a look into it.

if (!basename) {
if (basename == nullptr) {
basename = file_;
} else {
++basename;
}
std::cerr << "(" << basename << ":" << line_ << ") ";
}
}

private:
const char* file_;
int line_;
LogLevel level_;
};

class LogHeader : public ILogHeader {
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Future us would appreciate a few lines of comments, explaining what's the difference between this and the following classes.

Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Makes sense, I'll document them.

public:
LogHeader(const char* file, int line, LogLevel level)
: ILogHeader(file, line, level) {}

void PrintHeader() override {
PrintPrefix();
PrintFile();
}
};

class ThrottledLogHeader : public ILogHeader {
public:
ThrottledLogHeader(const char* file, int line, LogLevel level, std::chrono::duration<unsigned int> interval)
: ILogHeader(file, line, level), interval_(interval) {}

void PrintHeader() override {
PrintPrefix();

std::cerr << "[Throttled " << count_ << " messages] ";
count_ = 0;

PrintFile();
}

bool ShouldPrint() {
std::chrono::duration elapsed = std::chrono::steady_clock::now() - last_log_;
if (elapsed < interval_) {
count_++;
return false;
}

last_log_ = std::chrono::steady_clock::now();
return true;
}

private:
std::chrono::steady_clock::time_point last_log_;
std::chrono::duration<unsigned int> interval_;
unsigned long count_{};
};

class LogMessage {
public:
LogMessage(ILogHeader& ls) : ls_(ls) {}

~LogMessage() {
ls_.PrintHeader();

std::cerr << buf_.str()
<< std::endl;

if (level_ == LogLevel::FATAL) {
if (ls_.GetLogLevel() == LogLevel::FATAL) {
WriteTerminationLog(buf_.str());
exit(1);
}
Expand All @@ -102,32 +162,35 @@ class LogMessage {
}

private:
const char* file_;
int line_;
LogLevel level_;
ILogHeader& ls_;
std::stringstream buf_;
bool include_file_;
bool throttled_;
};

} // namespace logging

} // namespace collector

// Helpers for creating unique variables within a compilation unit.
#define CLOG_CAT_(a, b) a##b
#define CLOG_CAT(a, b) CLOG_CAT_(a, b)
#define CLOG_VAR(a) CLOG_CAT(a, __LINE__)

#define CLOG_ENABLED(lvl) (collector::logging::CheckLogLevel(collector::logging::LogLevel::lvl))

#define CLOG_IF(cond, lvl) \
static collector::logging::LogHeader CLOG_VAR(_clog_stmt_)( \
__FILE__, __LINE__, collector::logging::LogLevel::lvl); \
if (collector::logging::CheckLogLevel(collector::logging::LogLevel::lvl) && (cond)) \
collector::logging::LogMessage(__FILE__, __LINE__, false, collector::logging::LogLevel::lvl)
collector::logging::LogMessage(CLOG_VAR(_clog_stmt_))

#define CLOG(lvl) CLOG_IF(true, lvl)

#define CLOG_THROTTLED_IF(cond, lvl, interval) \
static std::chrono::steady_clock::time_point _clog_lastlog_##__LINE__; \
static collector::logging::ThrottledLogHeader CLOG_VAR(_clog_stmt_)( \
__FILE__, __LINE__, collector::logging::LogLevel::lvl, interval); \
if (collector::logging::CheckLogLevel(collector::logging::LogLevel::lvl) && (cond) && \
(std::chrono::steady_clock::now() - _clog_lastlog_##__LINE__ >= interval)) \
_clog_lastlog_##__LINE__ = std::chrono::steady_clock::now(), \
collector::logging::LogMessage(__FILE__, __LINE__, true, collector::logging::LogLevel::lvl)
CLOG_VAR(_clog_stmt_).ShouldPrint()) \
collector::logging::LogMessage(CLOG_VAR(_clog_stmt_))

#define CLOG_THROTTLED(lvl, interval) CLOG_THROTTLED_IF(true, lvl, interval)

Expand Down
Loading