WIP: logging sampled limited queries

src/knot/modules/rrl/functions.c

@@ -16,6 +16,7 @@
 
 #include <assert.h>
 #include <time.h>
+#include <stdatomic.h>
 
 #include "knot/modules/rrl/functions.h"
 #include "contrib/musl/inet_ntop.h"
@@ -41,57 +42,39 @@
 struct rrl_table {
 	kru_price_t v4_prices[RRL_V4_PREFIXES_CNT];
 	kru_price_t v6_prices[RRL_V6_PREFIXES_CNT];
+	uint32_t log_period;
+	_Atomic uint32_t log_time;
 	uint8_t kru[] ALIGNED(64);
 };
 
-/*
-static void subnet_tostr(char *dst, size_t maxlen, const struct sockaddr_storage *ss) // TODO remove or adapt
+static void addr_tostr(char *dst, size_t maxlen, const struct sockaddr_storage *ss)
 {
 	const void *addr;
-	const char *suffix;
 
 	if (ss->ss_family == AF_INET6) {
 		addr = &((struct sockaddr_in6 *)ss)->sin6_addr;
-		suffix = "/56";
 	} else {
 		addr = &((struct sockaddr_in *)ss)->sin_addr;
-		suffix = "/24";
 	}
 
-	if (knot_inet_ntop(ss->ss_family, addr, dst, maxlen) != NULL) {
-		strlcat(dst, suffix, maxlen);
-	} else {
+	if (knot_inet_ntop(ss->ss_family, addr, dst, maxlen) == NULL) {
 		dst[0] = '\0';
 	}
 }
 
-static void rrl_log_state(knotd_mod_t *mod, const struct sockaddr_storage *ss,
-                          uint16_t flags, uint8_t cls, const knot_dname_t *qname) // TODO remove or adapt, not used
+static void rrl_log_limited(knotd_mod_t *mod, const struct sockaddr_storage *ss, const uint8_t prefix)
 {
 	if (mod == NULL || ss == NULL) {
 		return;
 	}
 
 	char addr_str[SOCKADDR_STRLEN];
-	subnet_tostr(addr_str, sizeof(addr_str), ss);
+	addr_tostr(addr_str, sizeof(addr_str), ss);
 
-	const char *what = "leaves";
-	if (flags & RRL_BF_ELIMIT) {
-		what = "enters";
-	}
-
-	knot_dname_txt_storage_t buf;
-	char *qname_str = knot_dname_to_str(buf, qname, sizeof(buf));
-	if (qname_str == NULL) {
-		qname_str = "?";
-	}
-
-	knotd_mod_log(mod, LOG_NOTICE, "address/subnet %s, class %s, qname %s, %s limiting",
-	              addr_str, rrl_clsstr(cls), qname_str, what);
+	knotd_mod_log(mod, LOG_NOTICE, "address %s limited on /%d", addr_str, prefix);
 }
-*/
 
-rrl_table_t *rrl_create(size_t size, uint32_t instant_limit, uint32_t rate_limit)
+rrl_table_t *rrl_create(size_t size, uint32_t instant_limit, uint32_t rate_limit, uint32_t log_period)
 {
 	size--;
 	size_t capacity_log = 1;
@@ -119,6 +102,15 @@ rrl_table_t *rrl_create(size_t size, uint32_t instant_limit, uint32_t rate_limit
 		rrl->v6_prices[i] = base_price / RRL_V6_RATE_MULT[i];
 	}
 
+	rrl->log_period = log_period;
+
+	{
+		struct timespec now_ts = {0};
+		clock_gettime(CLOCK_MONOTONIC_COARSE, &now_ts);
+		uint32_t now = now_ts.tv_sec * 1000 + now_ts.tv_nsec / 1000000;
+		rrl->log_time = now - log_period;
+	}
+
 	return rrl;
 }
 
@@ -134,20 +126,32 @@ int rrl_query(rrl_table_t *rrl, const struct sockaddr_storage *remote,
 	uint32_t now = now_ts.tv_sec * 1000 + now_ts.tv_nsec / 1000000;
 
 	uint8_t key[16] ALIGNED(16) = {0, };
+	uint8_t limited_prefix;
 	if (remote->ss_family == AF_INET6) {
 		struct sockaddr_in6 *ipv6 = (struct sockaddr_in6 *)remote;
 		memcpy(key, &ipv6->sin6_addr, 16);
 
-		return KRU.limited_multi_prefix_or((struct kru *)rrl->kru, now, 1, key, RRL_V6_PREFIXES, rrl->v6_prices, RRL_V6_PREFIXES_CNT)
-			? KNOT_ELIMIT : KNOT_EOK;
-
+		limited_prefix = KRU.limited_multi_prefix_or((struct kru *)rrl->kru, now,
+				1, key, RRL_V6_PREFIXES, rrl->v6_prices, RRL_V6_PREFIXES_CNT);
 	} else {
 		struct sockaddr_in *ipv4 = (struct sockaddr_in *)remote;
 		memcpy(key, &ipv4->sin_addr, 4);
 
-		return KRU.limited_multi_prefix_or((struct kru *)rrl->kru, now, 0, key, RRL_V4_PREFIXES, rrl->v4_prices, RRL_V4_PREFIXES_CNT)
-			? KNOT_ELIMIT : KNOT_EOK;
+		limited_prefix = KRU.limited_multi_prefix_or((struct kru *)rrl->kru, now,
+				0, key, RRL_V4_PREFIXES, rrl->v4_prices, RRL_V4_PREFIXES_CNT);
 	}
+
+	uint32_t log_time_orig = atomic_load_explicit(&rrl->log_time, memory_order_relaxed);
+	if (rrl->log_period && limited_prefix && (now - log_time_orig + 1024 >= rrl->log_period + 1024)) {
+		do {
+			if (atomic_compare_exchange_weak_explicit(&rrl->log_time, &log_time_orig, now, memory_order_relaxed, memory_order_relaxed)) {
+				rrl_log_limited(mod, remote, limited_prefix);
+				break;
+			}
+		} while (now - log_time_orig + 1024 >= rrl->log_period + 1024);
+	}
+
+	return limited_prefix ? KNOT_ELIMIT : KNOT_EOK;
 }
 
 bool rrl_slip_roll(int n_slip)

src/knot/modules/rrl/functions.h

@@ -50,7 +50,7 @@ typedef struct {
  * \param rate Rate (in pkts/sec).
  * \return created table or NULL.
  */
-rrl_table_t *rrl_create(size_t size, uint32_t instant_limit, uint32_t rate_limit);
+rrl_table_t *rrl_create(size_t size, uint32_t instant_limit, uint32_t rate_limit, uint32_t log_period);
 
 /*!
  * \brief Query the RRL table for accept or deny, when the rate limit is reached.

src/knot/modules/rrl/kru.h

@@ -58,9 +58,11 @@ struct kru_api {
 	/// Same as previous but without short-circuit evaluation; for time measurement purposes.
 	bool (*limited_multi_or_nobreak)(struct kru *kru, uint32_t time_now, uint8_t ** keys, kru_price_t *prices, size_t queries_cnt);
 
-	/// Multiple queries based on different prefixes of a single key. Returns OR of answers. Updates KRU only if no query is blocked.
+	/// Multiple queries based on different prefixes of a single key.
+	/// Returns a prefix (value in prefixes) on which the key is blocked, or zero if all queries passed.
+	/// Updates KRU only if no query is blocked.
 	/// The key of i-th query consists of prefixes[i] bits of key, prefixes[i], and namespace.
-	bool (*limited_multi_prefix_or)(struct kru *kru, uint32_t time_now,
+	uint8_t (*limited_multi_prefix_or)(struct kru *kru, uint32_t time_now,
 			uint8_t namespace, uint8_t key[static 16], uint8_t *prefixes, kru_price_t *prices, size_t queries_cnt);
 };
 // The functions are stored this way to make it easier to switch

src/knot/modules/rrl/kru.inc.c

@@ -455,7 +455,7 @@ static bool kru_limited_multi_or_nobreak(struct kru *kru, uint32_t time_now, uin
 	return ret;
 }
 
-static bool kru_limited_multi_prefix_or(struct kru *kru, uint32_t time_now, uint8_t namespace, uint8_t key[static 16], uint8_t *prefixes, kru_price_t *prices, size_t queries_cnt)
+static uint8_t kru_limited_multi_prefix_or(struct kru *kru, uint32_t time_now, uint8_t namespace, uint8_t key[static 16], uint8_t *prefixes, kru_price_t *prices, size_t queries_cnt)
 {
 	struct query_ctx ctx[queries_cnt];
 
@@ -465,15 +465,16 @@ static bool kru_limited_multi_prefix_or(struct kru *kru, uint32_t time_now, uint
 
 	for (size_t i = 0; i < queries_cnt; i++) {
 		if (kru_limited_fetch(kru, ctx + i))
-			return true;
+			return prefixes[i];
 	}
 
-	bool ret = false;
+	bool prefix = 0;
 	for (size_t i = 0; i < queries_cnt; i++) {
-		ret |= kru_limited_update(kru, ctx + i);
+		bool ret = kru_limited_update(kru, ctx + i);
+		prefix = (ret ? prefixes[i] : prefix);
 	}
 
-	return ret;
+	return prefix;
 }
 
 /// Update limiting and return true iff it hit the limit instead.

src/knot/modules/rrl/rrl.c

@@ -23,6 +23,7 @@
 #define MOD_SLIP		"\x04""slip"
 #define MOD_TBL_SIZE		"\x0A""table-size"
 #define MOD_WHITELIST		"\x09""whitelist"
+#define MOD_LOG_PERIOD		"\x0A""log-period"
 
 const yp_item_t rrl_conf[] = {
 	{ MOD_INSTANT_LIMIT, YP_TINT, YP_VINT = { 1,  (1ll << 32) / 12288 - 1, 50 } },
@@ -30,6 +31,7 @@ const yp_item_t rrl_conf[] = {
 	{ MOD_SLIP,          YP_TINT, YP_VINT = { 0, 100, 1 } },
 	{ MOD_TBL_SIZE,      YP_TINT, YP_VINT = { 1, INT32_MAX, 524288 } },
 	{ MOD_WHITELIST,     YP_TNET, YP_VNONE, YP_FMULTI },
+	{ MOD_LOG_PERIOD,    YP_TINT, YP_VINT = { 0, INT32_MAX, 0 } },
 	{ NULL }
 };
 
@@ -174,7 +176,8 @@ int rrl_load(knotd_mod_t *mod)
 	uint32_t instant_limit = knotd_conf_mod(mod, MOD_INSTANT_LIMIT).single.integer;
 	uint32_t rate_limit = knotd_conf_mod(mod, MOD_RATE_LIMIT).single.integer;
 	size_t size = knotd_conf_mod(mod, MOD_TBL_SIZE).single.integer;
-	ctx->rrl = rrl_create(size, instant_limit, rate_limit);
+	uint32_t log_period = knotd_conf_mod(mod, MOD_LOG_PERIOD).single.integer;
+	ctx->rrl = rrl_create(size, instant_limit, rate_limit, log_period);
 	if (ctx->rrl == NULL) {
 		ctx_free(ctx);
 		return KNOT_ENOMEM;

src/knot/modules/rrl/rrl.rst

@@ -48,6 +48,8 @@ Module reference
      table-size: INT
      slip: INT
      whitelist: ADDR[/INT] | ADDR-ADDR | STR ...
+     log-period: INT
+
 
 .. _mod-rrl_id:
 
@@ -161,3 +163,16 @@ or network ranges to exempt from rate limiting.
 Empty list means that no incoming connection will be white-listed.
 
 *Default:* not set
+
+log-period
+..........
+
+Minimal time in milliseconds between two log messages,
+or zero to disable logging.
+
+If a response is limited, the address and the prefix on which it was blocked is logged
+and logging is disabled for the `log-period` msec.
+As long as limiting is needed, one source is logged each period
+and sources with more blocked queries have greater probability to be chosen.
+
+*Default:* ``0``

tests/modules/test_rrl.c

@@ -218,7 +218,7 @@ void test_rrl(void) {
 	fakeclock_init();
 
 	/* create rrl table */
-	rrl = rrl_create(RRL_TABLE_SIZE, RRL_INSTANT_LIMIT, RRL_RATE_LIMIT);
+	rrl = rrl_create(RRL_TABLE_SIZE, RRL_INSTANT_LIMIT, RRL_RATE_LIMIT, 0);
 	ok(rrl != NULL, "rrl(%s): create", impl_name);
 
 	if (KRU.initialize == KRU_GENERIC.initialize) {