upstream: add infrastructure for ratelimited logging; feedback/ok

dtucker

OpenBSD-Commit-ID: 18a83e5ac09d59aaf1e834fd6b796db89dd842e7

log.c

@@ -1,4 +1,4 @@
-/* $OpenBSD: log.c,v 1.62 2024/06/27 22:36:44 djm Exp $ */
+/* $OpenBSD: log.c,v 1.64 2024/12/07 10:05:36 djm Exp $ */
 /*
  * Author: Tatu Ylonen <[email protected]>
  * Copyright (c) 1995 Tatu Ylonen <[email protected]>, Espoo, Finland
@@ -38,14 +38,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>
 #if defined(HAVE_STRNVIS) && defined(HAVE_VIS_H) && !defined(BROKEN_STRNVIS)
 # include <vis.h>
 #endif
@@ -489,3 +491,167 @@ 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.
+ *
+ * XXX a moving average rate of events might be a better approach here rather
+ *     than linear decay, which can suppress events for a while after large
+ *     bursts.
+ */
+
+/* #define RATELIMIT_DEBUG 1 */
+
+#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 max_accum, u_int hysteresis, u_int log_every)
+{
+	memset(rl, 0, sizeof(*rl));
+	rl->threshold = threshold;
+	rl->max_accum = max_accum;
+	rl->hysteresis = hysteresis;
+	rl->log_every = log_every;
+	RLDBG(("called: rl=%p thresh=%u max=%u hys=%u log_every=%u",
+	    rl, rl->threshold, rl->max_accum, 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 max=%u hys=%u log_every=%u "
+	    "accum=%u since=%ld since_last=%u", rl, rl->threshold,
+	    rl->max_accum, rl->hysteresis,
+	    rl->log_every, rl->accumulated_events,
+	    rl->last_event == 0 ? -1 : (long)(now - rl->last_event),
+	    rl->ratelimited_events));
+
+	if (now < 0)
+		return 0;
+	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) {
+		uint64_t 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 */
+	if (rl->accumulated_events > rl->max_accum)
+		rl->accumulated_events = rl->max_accum;
+	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;
+}

log.h

@@ -1,4 +1,4 @@
-/* $OpenBSD: log.h,v 1.34 2024/06/27 22:36:44 djm Exp $ */
+/* $OpenBSD: log.h,v 1.35 2024/12/07 10:05:37 djm Exp $ */
 
 /*
  * Author: Tatu Ylonen <[email protected]>
@@ -81,6 +81,30 @@ 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 max_accum;	/* max events to accumulate */
+	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 max_accum, 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__)