[PATCH v3] log: Add rate-limiting macros for log messages

[PATCH v3] log: Add rate-limiting macros for log messages

[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 <anskuma@redhat.com>
---
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

Re: [PATCH v3] log: Add rate-limiting macros for log messages

[David Gibson]

On Wed, 25 Mar 2026 18:41:21 +0530
Anshu Kumari <anskuma@redhat.com> wrote:

> 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 <anskuma@redhat.com>

Reviewed-by: David Gibson <david@gibson.dropbear.id.au>

For future reference, I prefer to handle upstream reviews at my
upstream email address <david@gibson.dropbear.id.au> rather than my Red
Hat address.

> ---
> 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 <dgibson@redhat.com>  (He or They)
Principal Software Engineer, Virtualization, Red Hat

Re: [PATCH v3] log: Add rate-limiting macros for log messages

[Stefano Brivio]

Thanks, this looks almost correct to me. Still two comments from my
side:

On Wed, 25 Mar 2026 18:41:21 +0530
Anshu Kumari <anskuma@redhat.com> wrote:

> 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 <anskuma@redhat.com>
> ---
> 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