Output the number of times a log has been throttled

[Molter73]

Description

Adding the number of times a log message has been throttled can add value in the sense that having the message show up once or twice may not be as worrisome as it showing up thousands of times.

In order to achieve this, the log message can be split between its header and the actual message. The header will now be handled by classes separate to LogMessage that will hold the information necessary to print them and use a common ILogHeader interface. This is done in order to reduce the amount of code necessary in macros, there shouldn't be a huge performance difference, but the current approach might take a bit more memory in order to store this data, some testing is needed. Calling virtual methods for printing the header could also have a performance impact, but given we don't print that many logs in info severity, would not consider this a problem.

Supersedes #1520.

Checklist

• Investigated and inspected CI test results
• Updated documentation accordingly

Automated testing

• Added unit tests
• Added integration tests
• Added regression tests

If any of these don't apply, please comment below.

Testing Performed

Manually checked logging still works as expected.

Added a throttle message in system-inspector::Service::GetNext and checked the output happened every 10 seconds:

[ovalenti]

This is much cleaner than the macro version, I like it !

Not too worried by the extra cost of the method calls for the same reasons you expose.

[Molter73]

Checked memory used on a deployed collector with kubectl top and this version has a similar usage to the one that is currently on the master branch of the main repo, so I think we are ok on that front as well.

[erthalion]

Looks good, thanks. Couple commentaries below, but feel free to decide which of them sound important enough for you to include.

[erthalion]

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?

[Molter73]

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.

[erthalion]

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();
}

[Molter73]

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.

[Molter73]

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.

[erthalion]

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?

[Molter73]

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

[erthalion]

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

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

[Molter73]

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)
      |                                       ^~~~~~~~~~~~~~~~~

[erthalion]

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

[erthalion]

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

[Molter73]

Makes sense, I'll document them.