[PATCH v3] log: Add rate-limiting macros for log messages
Currently, some log messages that would be useful at info or warn level
are kept at debug level because there is no way to throttle them, and a
guest could otherwise flood the host logs.
Add a logmsg_ratelimit() macro that uses per-call-site static variables
to independently track each call site's rate. It allows up to
LOG_RATELIMIT_BURST (5) messages per LOG_RATELIMIT_INTERVAL (1 second)
window, then prints a suppression notice. When a new window opens and
messages were suppressed, the count is reported after the next allowed
message.
Signed-off-by: Anshu Kumari
Thanks, this looks almost correct to me. Still two comments from my
side:
On Wed, 25 Mar 2026 18:41:21 +0530
Anshu Kumari
Currently, some log messages that would be useful at info or warn level are kept at debug level because there is no way to throttle them, and a guest could otherwise flood the host logs.
Add a logmsg_ratelimit() macro that uses per-call-site static variables to independently track each call site's rate. It allows up to LOG_RATELIMIT_BURST (5) messages per LOG_RATELIMIT_INTERVAL (1 second) window, then prints a suppression notice. When a new window opens and messages were suppressed, the count is reported after the next allowed message.
...there should be the Link: tag here, before Signed-off-by:, that Laurent and myself suggested.
Signed-off-by: Anshu Kumari
--- v3: - Print suppressed count after the message, not before - Add suppression notice when burst limit is hit - Reverse Christmas tree variable ordering - Fix tab/space alignment in macro - swapped LOG_RATELIMIT_INTERVAL and LOG_RATELIMIT_BURST location v2: - Use _ suffix for macro variables instead of prefix - Remove intv parameter from convenience wrappers --- log.h | 45 +++++++++++++++++++++++++++++++++++++++++++++ 1 file changed, 45 insertions(+)
diff --git a/log.h b/log.h index 6ceb686..8e6d65e 100644 --- a/log.h +++ b/log.h @@ -48,6 +48,51 @@ void logmsg_perror(int pri, const char *format, ...) passt_exit(EXIT_FAILURE); \ } while (0)
+#define LOG_RATELIMIT_INTERVAL 1 /* Default rate limit window in seconds */ +#define LOG_RATELIMIT_BURST 5 /* Max messages per window per call site */ + +/** + * logmsg_ratelimit() - Log a message with rate limiting + * @fn: Logging function name (e.g. warn, info, debug) + * @now: Current timestamp + */ +#define logmsg_ratelimit(fn, now, ...) \ + do { \ + static unsigned int rl_suppressed_; \ + static unsigned int rl_printed_; \ + static time_t rl_last_; \ + \ + if ((now)->tv_sec - rl_last_ > LOG_RATELIMIT_INTERVAL) {\ + rl_last_ = (now)->tv_sec; \ + rl_printed_ = 0; \ + } \ + \ + if (rl_printed_ < LOG_RATELIMIT_BURST) { \ + fn(__VA_ARGS__); \ + if (rl_suppressed_) { \ + fn("(suppressed %u similar messages)", \ + rl_suppressed_); \ + rl_suppressed_ = 0; \ + } \ + rl_printed_++; \ + } else if (rl_printed_ == LOG_RATELIMIT_BURST) { \ + fn("(suppressing further similar messages)"); \
There's one remaining problem with this implementation: this message is printed only the first time the original logging message is *not* printed. There should be an overlap of the two cases instead, so that this message is printed *just after* the last logged message. Otherwise you could have the following situation: message A (#1) message A (#2) ... message A (#5) message B (#1) (suppressing further similar messages) ...as message A was being printed for the sixth time. But that seems to refer to message B that was printed in between. You should make sure it's either: message A (#1) message A (#2) ... message A (#5) (suppressing further similar messages) message B (#1) or: message A (#1) message A (#2) ... message A (#5) message B (#1) message A (#6) (suppressing further similar messages) I think the first version is slightly preferable as the limit is 5, as defined, and not 6.
+ rl_printed_++; \ + rl_suppressed_++; \ + } else { \ + rl_suppressed_++; \ + } \ + } while (0) + +#define err_ratelimit(now, ...) \ + logmsg_ratelimit(err, now, __VA_ARGS__) +#define warn_ratelimit(now, ...) \ + logmsg_ratelimit(warn, now, __VA_ARGS__) +#define info_ratelimit(now, ...) \ + logmsg_ratelimit(info, now, __VA_ARGS__) +#define debug_ratelimit(now, ...) \ + logmsg_ratelimit(debug, now, __VA_ARGS__) + extern int log_file; extern int log_trace; extern bool log_conf_parsed;
The rest looks good to me. -- Stefano
On Wed, 25 Mar 2026 18:41:21 +0530
Anshu Kumari
Currently, some log messages that would be useful at info or warn level are kept at debug level because there is no way to throttle them, and a guest could otherwise flood the host logs.
Add a logmsg_ratelimit() macro that uses per-call-site static variables to independently track each call site's rate. It allows up to LOG_RATELIMIT_BURST (5) messages per LOG_RATELIMIT_INTERVAL (1 second) window, then prints a suppression notice. When a new window opens and messages were suppressed, the count is reported after the next allowed message.
Signed-off-by: Anshu Kumari
Reviewed-by: David Gibson
--- v3: - Print suppressed count after the message, not before - Add suppression notice when burst limit is hit - Reverse Christmas tree variable ordering - Fix tab/space alignment in macro - swapped LOG_RATELIMIT_INTERVAL and LOG_RATELIMIT_BURST location
v2: - Use _ suffix for macro variables instead of prefix - Remove intv parameter from convenience wrappers --- log.h | 45 +++++++++++++++++++++++++++++++++++++++++++++ 1 file changed, 45 insertions(+)
diff --git a/log.h b/log.h index 6ceb686..8e6d65e 100644 --- a/log.h +++ b/log.h @@ -48,6 +48,51 @@ void logmsg_perror(int pri, const char *format, ...) passt_exit(EXIT_FAILURE); \ } while (0)
+#define LOG_RATELIMIT_INTERVAL 1 /* Default rate limit window in seconds */ +#define LOG_RATELIMIT_BURST 5 /* Max messages per window per call site */ + +/** + * logmsg_ratelimit() - Log a message with rate limiting + * @fn: Logging function name (e.g. warn, info, debug) + * @now: Current timestamp + */ +#define logmsg_ratelimit(fn, now, ...) \ + do { \ + static unsigned int rl_suppressed_; \ + static unsigned int rl_printed_; \ + static time_t rl_last_; \ + \ + if ((now)->tv_sec - rl_last_ > LOG_RATELIMIT_INTERVAL) {\ + rl_last_ = (now)->tv_sec; \ + rl_printed_ = 0; \ + } \ + \ + if (rl_printed_ < LOG_RATELIMIT_BURST) { \ + fn(__VA_ARGS__); \ + if (rl_suppressed_) { \ + fn("(suppressed %u similar messages)", \ + rl_suppressed_); \ + rl_suppressed_ = 0; \ + } \ + rl_printed_++; \ + } else if (rl_printed_ == LOG_RATELIMIT_BURST) { \ + fn("(suppressing further similar messages)"); \ + rl_printed_++; \ + rl_suppressed_++; \ + } else { \ + rl_suppressed_++; \ + } \ + } while (0) + +#define err_ratelimit(now, ...) \ + logmsg_ratelimit(err, now, __VA_ARGS__) +#define warn_ratelimit(now, ...) \ + logmsg_ratelimit(warn, now, __VA_ARGS__) +#define info_ratelimit(now, ...) \ + logmsg_ratelimit(info, now, __VA_ARGS__) +#define debug_ratelimit(now, ...) \ + logmsg_ratelimit(debug, now, __VA_ARGS__) + extern int log_file; extern int log_trace; extern bool log_conf_parsed; -- 2.53.0
--
David Gibson
participants (3)
-
Anshu Kumari
-
David Gibson
-
Stefano Brivio