ratelimiting for PerSourcePenalties logging

Damien Miller djm at mindrot.org
Thu Aug 1 14:58:44 AEST 2024


Hi,

A few people have requested rate-limiting for PerSourcePenalties logging.
These patches add it. Please give them a try if you're interested in this
feature.

-d
-------------- next part --------------
From c4080ad35331985ec5b864ee638cb33f54dbcfda Mon Sep 17 00:00:00 2001
From: Damien Miller <djm at mindrot.org>
Date: Thu, 1 Aug 2024 13:50:08 +1000
Subject: [PATCH 1/2] log ratelimiting infrastructure

---
 log.c | 158 +++++++++++++++++++++++++++++++++++++++++++++++++++++++++-
 log.h |  23 +++++++++
 2 files changed, 180 insertions(+), 1 deletion(-)

diff --git a/log.c b/log.c
index 5e12fcb..e9c3d83 100644
--- a/log.c
+++ b/log.c
@@ -36,14 +36,16 @@
 
 #include <sys/types.h>
 
+#include <errno.h>
 #include <fcntl.h>
+#include <limits.h>
 #include <stdarg.h>
 #include <stdio.h>
 #include <stdlib.h>
 #include <string.h>
 #include <syslog.h>
+#include <time.h>
 #include <unistd.h>
-#include <errno.h>
 #include <vis.h>
 
 #include "log.h"
@@ -447,3 +449,157 @@ sshlogdirect(LogLevel level, int forced, const char *fmt, ...)
 	do_log(level, forced, NULL, fmt, args);
 	va_end(args);
 }
+
+
+/*
+ * A simple system for ratelimiting aperiodic events such as logs, without
+ * needing to be hooked into a mainloop/timer. A running total of events is
+ * maintained and when it exceeds a threshold further events are dropped
+ * until the rate falls back below that threshold.
+ *
+ * To prevent flipping in and out of rate-limiting, there is a hysteresis
+ * timer that delays leaving the rate-limited state.
+ *
+ * While in the rate-limited state, events can be periodically allowed though
+ * and the number of dropped events since the last log obtained.
+ */
+
+/* #define RATELIMIT_DEBUG */
+
+#ifdef RATELIMIT_DEBUG
+# define RLDBG(x) do { \
+		printf("%s:%d %s: ", __FILE__, __LINE__, __func__); \
+		printf x; \
+		printf("\n"); \
+		fflush(stdout); \
+	} while (0)
+#else
+# define RLDBG(x)
+#endif
+
+/* set up a ratelimit */
+void
+log_ratelimit_init(struct log_ratelimit_ctx *rl, u_int threshold,
+    u_int hysteresis, u_int log_every)
+{
+	memset(rl, 0, sizeof(*rl));
+	rl->threshold = threshold;
+	rl->hysteresis = hysteresis;
+	rl->log_every = log_every;
+	RLDBG(("called: rl=%p thresh=%u hys=%u log_every=%u",
+	    rl, rl->threshold, rl->hysteresis, rl->log_every));
+}
+
+/*
+ * check whether a log event should be dropped because of rate-limiting.
+ * returns non-zero if the event should be dropped. If events_since_last
+ * is supplied then, for periodic logs, it will be set to the number of
+ * dropped events since the last message.
+ */
+int
+log_ratelimit(struct log_ratelimit_ctx *rl, time_t now, int *active,
+    u_int *events_dropped)
+{
+	time_t olast_event;
+
+	RLDBG(("called: rl=%p thresh=%u hys=%u log_every=%u "
+	    "accum=%u since=%ld since_last=%u", rl, rl->threshold,
+	    rl->hysteresis, rl->log_every, rl->accumulated_events,
+	    rl->last_event == 0 ? -1 : (long)(now - rl->last_event),
+	    rl->ratelimited_events));
+
+	if (events_dropped != NULL)
+		*events_dropped = 0;
+	if (active != NULL)
+		*active = rl->ratelimit_active;
+
+	/* First, decay accumulated events */
+	if (rl->last_event == 0)
+		rl->last_event = now;
+	if (now > rl->last_event) {
+		u_long n = now - rl->last_event;
+
+		if (n > UINT_MAX)
+			n = UINT_MAX;
+		if (rl->accumulated_events < (u_int)n)
+			rl->accumulated_events = 0;
+		else
+			rl->accumulated_events -= (u_int)n;
+		RLDBG(("decay: accum=%u", rl->accumulated_events));
+	}
+	rl->accumulated_events++; /* add this event */
+	olast_event = rl->last_event;
+	rl->last_event = now;
+	RLDBG(("check threshold: accum=%u vs thresh=%u",
+	    rl->accumulated_events, rl->threshold));
+
+	/* Are we under threshold? */
+	if (rl->accumulated_events < rl->threshold) {
+		if (!rl->ratelimit_active)
+			return 0;
+		RLDBG(("under threshold: hys=%u since_hys=%ld since_last=%ld",
+		    rl->hysteresis, rl->hysteresis_start == 0 ? -1 :
+		    (long)(now - rl->hysteresis_start),
+		    olast_event == 0 ? -1 : (long)(now - olast_event)));
+		if (rl->hysteresis_start == 0) {
+			/* active, but under threshold; hysteresis */
+			if (olast_event + rl->hysteresis < now) {
+				/* hysteresis expired before this event */
+				RLDBG(("hysteresis preexpired"));
+				goto inactive;
+			}
+			RLDBG(("start hysteresis"));
+			rl->hysteresis_start = now;
+		} else if (rl->hysteresis_start + rl->hysteresis < now) {
+			/* Hysteresis period expired, transition to inactive */
+			RLDBG(("complete hysteresis"));
+ inactive:
+			if (events_dropped != NULL)
+				*events_dropped = rl->ratelimited_events;
+			if (active != NULL)
+				*active = 0;
+			rl->ratelimit_active = 0;
+			rl->ratelimit_start = 0;
+			rl->last_log = 0;
+			rl->hysteresis_start = 0;
+			rl->ratelimited_events = 0;
+			return 0;
+		}
+		/* ratelimiting active, but in hysteresis period */
+	} else if (!rl->ratelimit_active) {
+		/* Transition to rate-limiting */
+		RLDBG(("start ratelimit"));
+		rl->ratelimit_active = 1;
+		rl->ratelimit_start = now;
+		rl->last_log = now;
+		rl->hysteresis_start = 0;
+		rl->ratelimited_events = 1;
+		if (active != NULL)
+			*active = 1;
+		return 1;
+	} else if (rl->hysteresis_start != 0) {
+		/* active and over threshold; reset hysteresis timer */
+		RLDBG(("clear hysteresis"));
+		rl->hysteresis_start = 0;
+	}
+
+	/* over threshold or in hysteresis period; log periodically */
+	if (active != NULL)
+		*active = 1;
+	RLDBG(("log_every=%u since_log=%ld", rl->log_every,
+	    (long)(now - rl->last_log)));
+	if (rl->log_every > 0 && now >= rl->last_log + rl->log_every) {
+		RLDBG(("periodic: since_last=%u", rl->ratelimited_events));
+		rl->last_log = now;
+		if (events_dropped != NULL) {
+			*events_dropped = rl->ratelimited_events;
+			rl->ratelimited_events = 0;
+		}
+		return 0;
+	}
+
+	/* drop event */
+	rl->ratelimited_events++;
+	RLDBG(("drop: ratelimited_events=%u", rl->ratelimited_events));
+	return 1;
+}
diff --git a/log.h b/log.h
index cced76c..14fbde7 100644
--- a/log.h
+++ b/log.h
@@ -78,6 +78,29 @@ void	 sshfatal(const char *, const char *, int, int,
 void	 sshlogdirect(LogLevel, int, const char *, ...)
     __attribute__((format(printf, 3, 4)));
 
+struct log_ratelimit_ctx {
+	/* configuration */
+	u_int threshold;	/* events per second */
+	u_int hysteresis;	/* seconds */
+	u_int log_every;	/* seconds */
+
+	/* state */
+	time_t last_event;
+	u_int accumulated_events; /* used for threshold comparisons */
+
+	/* state while actively rate-limiting */
+	int ratelimit_active;
+	time_t ratelimit_start;
+	time_t last_log;
+	time_t hysteresis_start;
+	u_int ratelimited_events;
+};
+
+void log_ratelimit_init(struct log_ratelimit_ctx *rl, u_int threshold,
+    u_int hysteresis, u_int log_every);
+int log_ratelimit(struct log_ratelimit_ctx *rl, time_t now, int *active,
+    u_int *events_dropped);
+
 #define do_log2(level, ...)	sshlog(__FILE__, __func__, __LINE__, 0, level, NULL, __VA_ARGS__)
 #define debug3(...)		sshlog(__FILE__, __func__, __LINE__, 0, SYSLOG_LEVEL_DEBUG3, NULL, __VA_ARGS__)
 #define debug2(...)		sshlog(__FILE__, __func__, __LINE__, 0, SYSLOG_LEVEL_DEBUG2, NULL, __VA_ARGS__)
-- 
2.45.2

-------------- next part --------------
From a555af180174dfd1c7934a4a45e8456bab78cdf3 Mon Sep 17 00:00:00 2001
From: Damien Miller <djm at mindrot.org>
Date: Thu, 1 Aug 2024 14:48:59 +1000
Subject: [PATCH 2/2] ratelimit MaxStartups and PerSourcePenalties logs

---
 sshd.c | 72 ++++++++++++++++++++++++++--------------------------------
 1 file changed, 32 insertions(+), 40 deletions(-)

diff --git a/sshd.c b/sshd.c
index 64d0d0d..e5da7ed 100644
--- a/sshd.c
+++ b/sshd.c
@@ -533,59 +533,51 @@ should_drop_connection(int startups)
 static int
 drop_connection(int sock, int startups, int notify_pipe)
 {
+	static struct log_ratelimit_ctx ratelimit_maxstartups;
+	static struct log_ratelimit_ctx ratelimit_penalty;
+	static int init_done;
 	char *laddr, *raddr;
-	const char *reason = NULL, msg[] = "Not allowed at this time\r\n";
-	static time_t last_drop, first_drop;
-	static u_int ndropped;
-	LogLevel drop_level = SYSLOG_LEVEL_VERBOSE;
-	time_t now;
+	const char *reason = NULL, *subreason = NULL;
+	const char msg[] = "Not allowed at this time\r\n";
+	struct log_ratelimit_ctx *rl = NULL;
+	int ratelimited;
+	u_int ndropped;
 
-	if (!srclimit_penalty_check_allow(sock, &reason)) {
-		drop_level = SYSLOG_LEVEL_INFO;
-		goto handle;
+	if (!init_done) {
+		init_done = 1;
+		log_ratelimit_init(&ratelimit_maxstartups, 4, 10, 60);
+		log_ratelimit_init(&ratelimit_penalty, 8, 20, 60);
 	}
 
-	now = monotime();
-	if (!should_drop_connection(startups) &&
-	    srclimit_check_allow(sock, notify_pipe) == 1) {
-		if (last_drop != 0 &&
-		    startups < options.max_startups_begin - 1) {
-			/* XXX maybe need better hysteresis here */
-			logit("exited MaxStartups throttling after %s, "
-			    "%u connections dropped",
-			    fmt_timeframe(now - first_drop), ndropped);
-			last_drop = 0;
-		}
-		return 0;
+	/* PerSourcePenalties */
+	if (!srclimit_penalty_check_allow(sock, &subreason)) {
+		reason = "PerSourcePenalties";
+		rl = &ratelimit_penalty;
+	} else {
+		/* MaxStartups */
+		if (!should_drop_connection(startups) &&
+		    srclimit_check_allow(sock, notify_pipe) == 1)
+			return 0;
+		reason = "Maxstartups";
+		rl = &ratelimit_maxstartups;
 	}
 
-#define SSHD_MAXSTARTUPS_LOG_INTERVAL	(5 * 60)
-	if (last_drop == 0) {
-		error("beginning MaxStartups throttling");
-		drop_level = SYSLOG_LEVEL_INFO;
-		first_drop = now;
-		ndropped = 0;
-	} else if (last_drop + SSHD_MAXSTARTUPS_LOG_INTERVAL < now) {
-		/* Periodic logs */
-		error("in MaxStartups throttling for %s, "
-		    "%u connections dropped",
-		    fmt_timeframe(now - first_drop), ndropped + 1);
-		drop_level = SYSLOG_LEVEL_INFO;
-	}
-	last_drop = now;
-	ndropped++;
-	reason = "past Maxstartups";
-
- handle:
 	laddr = get_local_ipaddr(sock);
 	raddr = get_peer_ipaddr(sock);
-	do_log2(drop_level, "drop connection #%d from [%s]:%d on [%s]:%d %s",
+	ratelimited = log_ratelimit(rl, time(NULL), NULL, &ndropped);
+	do_log2(ratelimited ? SYSLOG_LEVEL_DEBUG3 : SYSLOG_LEVEL_INFO,
+	    "drop connection #%d from [%s]:%d on [%s]:%d %s",
 	    startups,
 	    raddr, get_peer_port(sock),
 	    laddr, get_local_port(sock),
-	    reason);
+	    subreason != NULL ? subreason : reason);
 	free(laddr);
 	free(raddr);
+	if (ndropped != 0) {
+		logit("%s logging rate-limited: additional %u connections "
+		    "dropped", reason, ndropped);
+	}
+
 	/* best-effort notification to client */
 	(void)write(sock, msg, sizeof(msg) - 1);
 	return 1;
-- 
2.45.2



More information about the openssh-unix-dev mailing list