Logging: Reduce amount of log-messages

[dmth]

Whilst running our Test-System with approx 19 collectors + parsers and ~5 experts, we've noticed that the log-file directory will get very huge in a rather short amount of time. Since beginning of July we've collected approx. 11 GB Logfiles. Logrotation and zipping of logfiles is active.

The Loglevel in our setup is quite verbose (info), and should be set to warning. We suspect that this will create much less log-messages. In addition it will filter out the "Processed i+500 messages" messages. (IMHO This message should also be a debug one)

Nevertheless, we've noticed that the logfiles can be flooded with messages like "empty message received" For instance when redis has not been started. This message is added as a warning to all bots in this case an will be added to the log every X milliseconds.

Possible ToDos:

• The implications of a verbose log-level could be added to the user-documentation.
• Decide if the "Processed i+500 messages" should be info or debug. There might also a chance for optimization in ll. 269 of lib/bot.py for instance by checking the configured log-level prior to the modulo operation. (For each message the modulo is calculated even if the code after the operation does not do anything)
• Find other cases where logging is too verbose / or not sufficient
• We should agree on a "sane" default for logging. This might be warning in case of a productive environment.

[sebix]

Also see #614

In addition it will filter out the "Processed i+500 messages" messages. (IMHO This message should also be a debug one)

Or make it configurable? But it's obsolete as soon as we have #361

[sebix]

The implications of a verbose log-level could be added to the user-documentation.

9c0c55a

Find other cases where logging is too verbose / or not sufficient

#641

We should agree on a "sane" default for logging. This might be warning in case of a productive environment.

Should warning be default for packaged releases? I think INFO is still a good default, but for production environments this should be warning tough.

[dmth]

We should agree on a "sane" default for logging. This might be warning in case of a productive environment.

Should warning be default for packaged releases? I think INFO is still a good default, but for production environments this should be warning tough.

I agree on "Warning" as a reasonable default for productive settings.

[ghost]

Decide if the "Processed i+500 messages" should be info or debug. There might also a chance for optimization in ll. 269 of lib/bot.py for instance by checking the configured log-level prior to the modulo operation. (For each message the modulo is calculated even if the code after the operation does not do anything)

To fix this on a short term: Could be solved by replacing the number-of-messages approach by a time-based approach. After every process() call we check when the last run did happen and if that time is bigger than a time interval of e.g. 5min (configurable), print "Processed ... messages.". This does make the process more verbose for low-volume bots and less verbose for high-volume bots.

[ghost]

@certtools/intelmq-contributors Any comments on my suggested solution in #743 (comment) ?

[dmth]

print "Processed ... messages."

Could this be a "Processed N Messages since last logging", an not be a total count?

[ghost]

Could this be a "Processed N Messages since last logging", an not be a total count?

Good idea. And also send this message at shutdown if the number is non-zero.