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