[PATCH v2] Bug 134: message rate limiting

[PATCH v2] Bug 134: message rate limiting

[Anshu Kumari]

Signed-off-by: Anshu Kumari <anskuma@redhat.com>
---
 log.h | 40 ++++++++++++++++++++++++++++++++++++++++
 tap.c | 19 ++++++-------------
 2 files changed, 46 insertions(+), 13 deletions(-)

diff --git a/log.h b/log.h
index 6ceb686..2e9286e 100644
--- a/log.h
+++ b/log.h
@@ -48,6 +48,46 @@ void logmsg_perror(int pri, const char *format, ...)
 		passt_exit(EXIT_FAILURE);				\
 	} while (0)
 
+#define LOG_RATELIMIT_BURST	5  /* Max messages per window per call site */
+#define LOG_RATELIMIT_INTERVAL	1  /* Default rate limit window in seconds */
+
+/**
+ * logmsg_ratelimit() - Rate-limited log message
+ * @fn:		Logging function
+ * @now:	current timestamp
+ */
+#define logmsg_ratelimit(fn, now, ...)				\
+	do {								\
+		static time_t rl_last_;					\
+		static unsigned int rl_printed_;			\
+		static unsigned int rl_suppressed_;			\
+									\
+		if ((now)->tv_sec - rl_last_ > LOG_RATELIMIT_INTERVAL) {		\
+			if (rl_suppressed_)				\
+				fn("(suppressed %u similar messages)",	\
+				   rl_suppressed_);			\
+			rl_last_ = (now)->tv_sec;			\
+			rl_printed_ = 0;				\
+			rl_suppressed_ = 0;				\
+		}							\
+									\
+		if (rl_printed_ < LOG_RATELIMIT_BURST) {		\
+			fn(__VA_ARGS__);				\
+			rl_printed_++;					\
+		} 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;
diff --git a/tap.c b/tap.c
index 1049e02..656b6e9 100644
--- a/tap.c
+++ b/tap.c
@@ -686,17 +686,8 @@ static bool tap4_is_fragment(const struct iphdr *iph,
 			     const struct timespec *now)
 {
 	if (ntohs(iph->frag_off) & ~IP_DF) {
-		/* Ratelimit messages */
-		static time_t last_message;
-		static unsigned num_dropped;
-
-		num_dropped++;
-		if (now->tv_sec - last_message > FRAGMENT_MSG_RATE) {
-			warn("Can't process IPv4 fragments (%u dropped)",
-			     num_dropped);
-			last_message = now->tv_sec;
-			num_dropped = 0;
-		}
+		warn_ratelimit(now,
+			"Can't process IPv4 fragment");
 		return true;
 	}
 	return false;
@@ -1115,8 +1106,10 @@ void tap_add_packet(struct ctx *c, struct iov_tail *data,
 		char bufmac[ETH_ADDRSTRLEN];
 
 		memcpy(c->guest_mac, eh->h_source, ETH_ALEN);
-		debug("New guest MAC address observed: %s",
-		      eth_ntop(c->guest_mac, bufmac, sizeof(bufmac)));
+		info_ratelimit(now,
+			       "New guest MAC address observed: %s",
+			       eth_ntop(c->guest_mac, bufmac,
+					sizeof(bufmac)));
 		proto_update_l2_buf(c->guest_mac);
 	}
 
-- 
2.53.0

Re: [PATCH v2] Bug 134: message rate limiting

[Stefano Brivio]

Hi Anshu,

On Tue, 24 Mar 2026 22:23:01 +0530
Anshu Kumari <anskuma@redhat.com> wrote:

Please have a look at CONTRIBUTING.md (recently added by Yumei) which
should give you an idea of what to write in the commit message.

There are also plenty of examples in the mailing list archives,
https://archives.passt.top/passt-dev/.

Other than the missing commit message and the rather uncommon title
format, this is missing a tag:

Link: https://bugs.passt.top/show_bug.cgi?id=134

...and after writing all this, I just realised that Laurent already
mentioned all these aspects, see:

  https://archives.passt.top/passt-dev/26136561-fc90-4f74-9984-aa5fd4e5ca97@redhat.com/

So, one further comment from me: it's much easier for everybody else
(and for you to get code merged) if you address comments before posting
a new version.

By the way, if you had reviewers on previous versions, it would be nice
to Cc: them (I just did), so that they don't miss the fact you posted a
new revision they might want to have a look at.

And if it's something for me to apply (I currently merge changes),
adding me in To: makes it clear to me that this is directed to me (and
you get a slightly faster reaction from me this way... usually).

> Signed-off-by: Anshu Kumari <anskuma@redhat.com>
> ---

Here you should explain (not necessarily in detail) what you changed
compared to v1.

I had just started looking at v1 but I couldn't finish, so I switched to
v2, but without any kind of change log I'm not sure if some changes are
intended and which pending comments from others you actually meant to
take care of.

Anyway, restarting from scratch, here's my review:

>  log.h | 40 ++++++++++++++++++++++++++++++++++++++++
>  tap.c | 19 ++++++-------------
>  2 files changed, 46 insertions(+), 13 deletions(-)
> 
> diff --git a/log.h b/log.h
> index 6ceb686..2e9286e 100644
> --- a/log.h
> +++ b/log.h
> @@ -48,6 +48,46 @@ void logmsg_perror(int pri, const char *format, ...)
>  		passt_exit(EXIT_FAILURE);				\
>  	} while (0)
>  
> +#define LOG_RATELIMIT_BURST	5  /* Max messages per window per call site */
> +#define LOG_RATELIMIT_INTERVAL	1  /* Default rate limit window in seconds */

If one starts reading from the top (quite common), it's not clear what
the "window" is.

If you swap these two lines, it's clearer because you're defining it
first by defining LOG_RATELIMIT_INTERVAL ("oh, it's something in
seconds").

No need for two spaces between numbers and start of the comments, one
is enough.

> +
> +/**
> + * logmsg_ratelimit() - Rate-limited log message

This is a bit of a complete sentence, but not quite, and some nouns in
a row, but not exactly fitting either.

We usually use imperative description for functions, that is, this
would be "Log a message with rate limiting".

If you prefer to describe the function for what it *is* rather than
what it *does* (less common but definitely readable) you could go with
"Rate-limited message logging".

> + * @fn:		Logging function

To explain why I'm suggesting this: I initially wrote this comment:

---
In C you can pass function pointers, so it's not obvious that this
doesn't take a function pointer, you should specify that a function
*name* is expected, I think.

And that function itself isn't really "logging" (even though I
understand what you mean, but it's not really immediate). Maybe
"Calling function name"? In any case, "Logging function name" would be
appropriate as well.
---

and realised a couple of minutes later I was wrong. This *is* a
function pointer... but it's a macro so it's not really clear from the
argument specification. Maybe: "Pointer to logging function", so
there's no ambiguity?

> + * @now:	current timestamp

For consistency: "Current".

> + */
> +#define logmsg_ratelimit(fn, now, ...)				\

This is missing a tab (backslashes are not aligned). I would recommend
you use an editor showing tabs as 8-character because that's the coding
style we use (same as the "networking" Linux kernel coding style).

My editor of choice (Geany) also shows (different) graphic signs for
tabs and spaces, but I know others use editors without this feature and
still get things right so... it must be possible.

> +	do {								\
> +		static time_t rl_last_;					\
> +		static unsigned int rl_printed_;			\
> +		static unsigned int rl_suppressed_;			\

Very minor, but I guess I'd mention it: see CONTRIBUTING.md for the
ordering of variables (so-called reverse Christmas tree) and the
rationale behind it.

> +									\
> +		if ((now)->tv_sec - rl_last_ > LOG_RATELIMIT_INTERVAL) {		\

Excess tabs -- while it's a bit heavy on eyes, "{\" without spaces is
still better than exceeding the usual 80 columns.

> +			if (rl_suppressed_)				\
> +				fn("(suppressed %u similar messages)",	\

You might have unrelated messages before this one, say, for example:

	0.0425: Flow 0 (NEW): FREE -> NEW
	0.0425: (suppressed 15 similar messages)
	0.0425: Can't process IPv4 fragments (132 dropped)

...now, what does "suppressed 15 similar messages" refer to? It naturally
looks like the one before, but it's the one after. That's confusing.

Probably the simplest solution to this issue would be to store
rl_suppressed_ in a temporary variable, before you zero it, and print
this message at the end if (rl_suppressed_), so that it comes after the
"similar" message.

Or maybe you could just swap the blocks and play a bit with the
conditions and save a variable... I haven't tried.

> +				   rl_suppressed_);			\

This comes with the problem that, if we print a bunch of messages in a
burst, and then nothing at all, it looks like just five messages were
printed. On the other hand, using a timer makes this extremely
complicated and probably coupled with substantial overhead.

But I guess you could use the trick below (note that I haven't tested
it and I didn't really think it through):

> +			rl_last_ = (now)->tv_sec;			\
> +			rl_printed_ = 0;				\
> +			rl_suppressed_ = 0;				\
> +		}							\
> +									\
> +		if (rl_printed_ < LOG_RATELIMIT_BURST) {		\
> +			fn(__VA_ARGS__);				\
> +			rl_printed_++;					\
> +		} else {						\

...just when you're about to stop printing messages, that is, when
rl_printed_ == LOG_RATELIMIT_BURST, you could print one last message
saying and then say, for example, "(suppressing further messages of this type)".

So it's clear that there are more, even if we stopped printing them.

> +			rl_suppressed_++;				\
> +		}							\
> +	} while (0)
> +
> +#define err_ratelimit(now, ...)					\

Missing a tab (similar as the occurrence above).

> +	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;
> diff --git a/tap.c b/tap.c
> index 1049e02..656b6e9 100644
> --- a/tap.c
> +++ b/tap.c
> @@ -686,17 +686,8 @@ static bool tap4_is_fragment(const struct iphdr *iph,
>  			     const struct timespec *now)
>  {
>  	if (ntohs(iph->frag_off) & ~IP_DF) {
> -		/* Ratelimit messages */
> -		static time_t last_message;
> -		static unsigned num_dropped;
> -
> -		num_dropped++;
> -		if (now->tv_sec - last_message > FRAGMENT_MSG_RATE) {
> -			warn("Can't process IPv4 fragments (%u dropped)",
> -			     num_dropped);
> -			last_message = now->tv_sec;
> -			num_dropped = 0;
> -		}
> +		warn_ratelimit(now,
> +			"Can't process IPv4 fragment");

If you just drop "(%u dropped)", it will be pretty hard to understand
the rate at which fragments are being sent: is it one per second or a
thousand? That makes a difference while debugging things.

I would suggest to keep the 'num_dropped' counter, keep printing the
number (without zeroing it, because you don't know when to do it here),
and yes, it will wrap eventually (become 0 again), but the wrapping
should be very obvious, and it's better than having no indication at
all.

Now, this is a related change but logically distinct, so it would
normally deserve its own patch, which could be in the same series.

Look at the archives for examples of series, and at CONTRIBUTING.md for
instructions. You could try sending one example series to yourself
first, to check.

On the other hand I wouldn't find it outrageous to submit this part of
change together with the implementation, given it's one example usage
(or one implementation you're half-recycling, in some sense).

However:

>  		return true;
>  	}
>  	return false;
> @@ -1115,8 +1106,10 @@ void tap_add_packet(struct ctx *c, struct iov_tail *data,
>  		char bufmac[ETH_ADDRSTRLEN];
>  
>  		memcpy(c->guest_mac, eh->h_source, ETH_ALEN);
> -		debug("New guest MAC address observed: %s",
> -		      eth_ntop(c->guest_mac, bufmac, sizeof(bufmac)));
> +		info_ratelimit(now,
> +			       "New guest MAC address observed: %s",
> +			       eth_ntop(c->guest_mac, bufmac,
> +					sizeof(bufmac)));

...it's different for this part: this is a logically distinct change and
it should really be a distinct patch for two reasons:

1. it makes things easier to review

2. it makes it easier to revert things if you introduce an issue, and
   bisect changes (see git-bisect(1)) if needed

Further, this is just one example of what needs to be changed, but you
should look for more occurrences of debug messages that can now be
promoted to info / warn and include all of them in a separate patch.
There should be a few more.

I can also have a look if needed, let me know.

>  		proto_update_l2_buf(c->guest_mac);
>  	}
>  

-- 
Stefano