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 all commits
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
159 changes: 132 additions & 27 deletions collector/lib/Logging.h
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -3,6 +3,7 @@

#include <chrono>
#include <cstdint>
#include <filesystem>
#include <iomanip>
#include <iostream>
#include <sstream>
Expand Down Expand Up @@ -54,15 +55,35 @@ void WriteTerminationLog(std::string message);

const size_t LevelPaddingWidth = 7;

class LogMessage {
/**
* Interface for log headers.
*
* This class defines how log headers should behave and provides some
* basic, reusable methods.
*/
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);
ILogHeader(const char* file, int line, LogLevel level)
: line_(line), level_(level) {
std::filesystem::path p(file);
if (p.has_filename()) {
file_ = p.filename().string();
} else {
file_ = p.string();
}
}

~LogMessage() {
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 +92,106 @@ class LogMessage {
<< std::left << std::setw(LevelPaddingWidth) << GetLogLevelName(level_)
<< " " << std::put_time(nowTm, "%Y/%m/%d %H:%M:%S")
<< "] ";
}

if (throttled_) {
std::cerr << "[Throttled] ";
void PrintFile() {
if (CheckLogLevel(LogLevel::DEBUG)) {
std::cerr << "(" << file_ << ":" << line_ << ") ";
}
}

private:
std::string file_;
int line_;
LogLevel level_;
};

/**
* Basic log header.
*
* Most log lines will use this header.
*
* The format when running in debug level will be:
* [LEVEL YYYY/MM/DD HH:mm:SS] (file:line)
*
* Other log levels exclude the (file:line) part of the header.
*/
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();
}
};

/**
* Throttled log header.
*
* When the same log message is triggered multiple times, this header
* helps prevent flooding the logs and instead counts the occurrences
* of the message, which will be output after a given time window
* expires.
*
* The format when running in debug level will be:
* [LEVEL YYYY/MM/DD HH:mm:SS] [Throttled COUNT message] (file:line)
*
* Other log levels exclude the (file:line) part of the header.
*/
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] ";
ovalenti marked this conversation as resolved.
Show resolved Hide resolved
count_ = 0;

PrintFile();
}

if (include_file_) {
const char* basename = strrchr(file_, '/');
if (!basename) {
basename = file_;
} else {
++basename;
}
std::cerr << "(" << basename << ":" << line_ << ") ";
/**
* Check if the log message should be suppressed.
*
* Throttled logs only output a message every interval_ time windows.
* Every time this method is called, we increment count_ so the next
* time the log is printed we can add the amount of times the log has
* happened.
*
* @returns true if the log has to be suppressed.
*/
bool Suppress() {
std::chrono::duration elapsed = std::chrono::steady_clock::now() - last_log_;
count_++;
Copy link
Contributor

Choose a reason for hiding this comment

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

It might cause some surprise in the future (imagine someone else reshuffling this code), that ShouldPrint function actually increments the counter. Maybe it would be more obvious to introduce another method Suppress, that will increment the count? In that case the macro would look like:

if (log_level & cond & CLOG_VAR(stmt).ShouldPrint) {
    LogMessage;
} else {
    CLOG_VAR(stmt).Suppress();
}

Copy link
Collaborator Author

Choose a reason for hiding this comment

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

Yeah, I didn't really like this approach but I couldn't think of a better solution. I like your suggestion though, I'll add that.

Copy link
Collaborator Author

Choose a reason for hiding this comment

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

Ok, now I remember why this is a pain, the macro needs to end with LogMessage(...) so we can directly << into it. I could do something similar to what you proposed by not using braces around the if/else statements, but that causes a bunch of warnings about a dangling else condition and it's overall ugly.

Best I can think of is renaming ShouldPrint to Suppress, turn the logic of the returned value around and use that, so at least it's a bit more obvious that Suppress is telling the macro to not output the log message and increment the count.

Copy link
Contributor

Choose a reason for hiding this comment

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

Interesting. IIUC currently it does

if (log_level && cond && CLOG_VAR(stmt).ShouldPrint())
    LogMessage()

How does it return LogMessage(...) if the if condition is false?

Copy link
Collaborator Author

Choose a reason for hiding this comment

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

It doesn't, it's a macro, so LogMessage() and everything to the ; is skipped when the condition is false.

image

Copy link
Contributor

@erthalion erthalion Oct 8, 2024 •
edited
Loading

Choose a reason for hiding this comment

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

Wouldn't then reversing the if condition solve this conundrum? Like

if (!log_level ||!cond || CLOG_VAR(stmt).ShouldPrint()) {
    Suppress()
} else
    LogMessage(...)

Copy link
Collaborator Author

Choose a reason for hiding this comment

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

Problem with that is that missing the log level or having the condition be false would also add to the count of message, I think we need something like:

if (log_level && cond) 
  if (!CLOG_VAR(stmt).ShouldPrint()) {
    Suppress()
  } else
    LogMessage(...)

But then you have a dangling else and the logic becomes difficult to follow.

You also get this really nice warning a bunch of times when compiling:

In file included from /home/mmoltras/go/src/github.com/stackrox/collector/collector/lib/system-inspector/EventExtractor.h:10,
                 from /home/mmoltras/go/src/github.com/stackrox/collector/collector/lib/ContainerMetadata.cpp:5:
/home/mmoltras/go/src/github.com/stackrox/collector/collector/lib/system-inspector/EventExtractor.h: In member function ‘const int64_t* collector::system_inspector::EventExtractor::get_event_rawres(sinsp_evt*)’:
/home/mmoltras/go/src/github.com/stackrox/collector/collector/lib/Logging.h:224:6: warning: suggest explicit braces to avoid ambiguous ‘else’ [-Wdangling-else]
  224 |   if (collector::logging::CheckLogLevel(collector::logging::LogLevel::lvl) && (cond)) \
      |      ^
/home/mmoltras/go/src/github.com/stackrox/collector/collector/lib/Logging.h:230:39: note: in expansion of macro ‘CLOG_THROTTLED_IF’
  230 | #define CLOG_THROTTLED(lvl, interval) CLOG_THROTTLED_IF(true, lvl, interval)
      |                                       ^~~~~~~~~~~~~~~~~

Copy link
Contributor

Choose a reason for hiding this comment

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

Well, ok, then just go with whatever is easier + loud commentaries around to explain what this function does :)

if (elapsed < interval_) {
return true;
}

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

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 +204,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_).Suppress()) \
collector::logging::LogMessage(CLOG_VAR(_clog_stmt_))

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

Expand Down
Loading