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

Jump to bottom

Count the number of throttled log message and print it. #1520

Closed
wants to merge 5 commits into from
Closed

Count the number of throttled log message and print it. #1520

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
1ef58b3
Count the number of throttled log message and print it.
ovalenti Jan 25, 2024
fba49a4
Use implicit if-else precedence.
ovalenti Jul 4, 2024
29cf48f
Reset the throttling counter as a side-effect of LogMessage constructor
ovalenti Jul 5, 2024
5d81b21
Break the if-else into two distinct if statements
ovalenti Jul 5, 2024
dd35730
Initialize throttled_times properly
ovalenti Jul 5, 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
2 changes: 1 addition & 1 deletion collector/lib/Logging.cpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -113,7 +113,7 @@ void InspectorLogCallback(std::string&& msg, sinsp_logger::severity severity) {
return;
}

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

const char* GetGlobalLogPrefix() {
Expand Down
33 changes: 21 additions & 12 deletions collector/lib/Logging.h
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -56,10 +56,15 @@ const size_t LevelPaddingWidth = 7;

class LogMessage {
public:
LogMessage(const char* file, int line, bool throttled, LogLevel level)
: file_(file), line_(line), level_(level), throttled_(throttled) {
LogMessage(const char* file, int line, LogLevel level, unsigned long* throttled_times = 0)
Copy link
Collaborator

Choose a reason for hiding this comment

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

[nit] using nullptr rather than 0 would make this a little clearer

Suggested change
LogMessage(const char* file, int line, LogLevel level, unsigned long* throttled_times = 0)
LogMessage(const char* file, int line, LogLevel level, unsigned long* throttled_times = nullptr)

Copy link
Collaborator

Choose a reason for hiding this comment

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

+1 on this one, we are terrible at using nullptr, we should try to do better.

: file_(file), line_(line), level_(level), throttled_times_(0) {
// if in debug mode, output file names associated with log messages
include_file_ = CheckLogLevel(LogLevel::DEBUG);
if (throttled_times) {
// this is a throttled message, take the occurrences number and reset it
throttled_times_ = *throttled_times;
*throttled_times = 0;
}
}

~LogMessage() {
Expand All @@ -72,8 +77,8 @@ class LogMessage {
<< " " << std::put_time(nowTm, "%Y/%m/%d %H:%M:%S")
<< "] ";

if (throttled_) {
std::cerr << "[Throttled] ";
if (throttled_times_ != 0) {
std::cerr << "[Throttled " << throttled_times_ << " messages] ";
}

if (include_file_) {
Expand Down Expand Up @@ -107,7 +112,7 @@ class LogMessage {
LogLevel level_;
std::stringstream buf_;
bool include_file_;
bool throttled_;
unsigned long throttled_times_;
};

} // namespace logging
Expand All @@ -118,16 +123,20 @@ class LogMessage {

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

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

#define CLOG_THROTTLED_IF(cond, lvl, interval) \
static std::chrono::steady_clock::time_point _clog_lastlog_##__LINE__; \
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)
#define CLOG_THROTTLED_IF(cond, lvl, interval) \
Copy link
Collaborator

Choose a reason for hiding this comment

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

I'm gonna be honest, I don't like macros. I think most of them are directly written by the devil himself, waiting for us to make a silly mistake in an expansion, triggering undefined behavior and bringing down entire programs in an instant.

This particular case was already pretty bad, but with the added changes it becomes borderline unreadable, I had to put a TON of effort into just trying to understand what was going on in it and, I have to assume, if we ever need to do any further changes or (God forbid) do a bug fix, it will take way too much effort to do so.

That said, I am also in favor of the added feature, I think counting the amount of times a log has been throttled adds value (throttling twice is not as bad as throttling 2000 times). Maybe we can come up with a better solution, there might be a way we can rewrite at least part of the macro to be a concrete method and pass things like __LINE__ as an argument to it. Or maybe we have to rethink how our entire logging implementation works, the implementation itself is really clever, using the destructor of the class to do the actual print out, but that also means every time we log we are creating and destroying an object, maybe we want to change it to have a single instance of a logger object and this sort of throttling can be done with a map of sorts, grouping line number to the amount of triggers that have occurred.

I digress, I will not block the change from being merged because I like the idea behind it, but I cannot in good faith approve the PR because of the reasons stated before.

static std::chrono::steady_clock::time_point _clog_lastlog_##__LINE__; \
static unsigned long _clog_throttle_times_##__LINE__ = 0; \
std::chrono::duration _clog_elapsed_##__LINE__ = std::chrono::steady_clock::now() - _clog_lastlog_##__LINE__; \
if (collector::logging::CheckLogLevel(collector::logging::LogLevel::lvl) && (cond) && _clog_elapsed_##__LINE__ < interval) { \
Copy link
Contributor

Choose a reason for hiding this comment

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

I have not been able to refactor this to use nested ifs. I think this is okay.

_clog_throttle_times_##__LINE__++; \
} \
if (collector::logging::CheckLogLevel(collector::logging::LogLevel::lvl) && (cond) && _clog_elapsed_##__LINE__ >= interval) \
Stringy marked this conversation as resolved.
Show resolved Hide resolved
_clog_lastlog_##__LINE__ = std::chrono::steady_clock::now(), \
collector::logging::LogMessage(__FILE__, __LINE__, collector::logging::LogLevel::lvl, &_clog_throttle_times_##__LINE__)

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

Expand Down
Loading