daemon/defer: add log-period for dropped data logging

CZ-NIC · Dec 9, 2024 · 5acf783 · 5acf783
1 parent d093cc7
commit 5acf783
Show file tree

Hide file tree

Showing 7 changed files with 39 additions and 8 deletions.
diff --git a/daemon/defer.c b/daemon/defer.c
@@ -3,6 +3,7 @@
  */
 
 #include <math.h>
+#include <stdatomic.h>
 #include "daemon/defer.h"
 #include "daemon/session2.h"
 #include "daemon/udp_queue.h"
@@ -54,8 +55,10 @@
 struct defer {
 	size_t capacity;
 	kru_price_t max_decay;
+	uint32_t log_period;
 	int cpus;
 	bool using_avx2;
+	_Atomic uint32_t log_time;
 	_Alignas(64) uint8_t kru[];
 };
 struct defer *defer = NULL;
@@ -415,8 +418,21 @@ static inline void process_single_deferred(void)
 
 	if (age_ns >= REQ_TIMEOUT) {
 		VERBOSE_LOG("    BREAK (timeout)\n");
-		kr_log_warning(DEFER, "Data from %s too long in queue, dropping.\n",
-			kr_straddr(ctx->comm->src_addr));  // TODO make it notice as it's intended behavior of defer?
+
+		// notice logging according to log-period
+		const uint32_t time_now = kr_now();
+		uint32_t log_time_orig = atomic_load_explicit(&defer->log_time, memory_order_relaxed);
+		if (defer->log_period) {
+			while (time_now - log_time_orig + 1024 >= defer->log_period + 1024) {
+				if (atomic_compare_exchange_weak_explicit(&defer->log_time, &log_time_orig, time_now,
+						memory_order_relaxed, memory_order_relaxed)) {
+					kr_log_notice(DEFER, "Data from %s too long in queue, dropping.\n",
+							kr_straddr(ctx->comm->src_addr));
+					break;
+				}
+			}
+		}
+
 		break_query(ctx, ETIME);
 		return;
 	}
@@ -603,7 +619,7 @@ static void defer_queues_idle(uv_idle_t *handle)
 
 
 /// Initialize shared memory, queues. To be called from Lua.
-int defer_init(const char *mmap_file, int cpus)
+int defer_init(const char *mmap_file, uint32_t log_period, int cpus)
 {
 	defer_initialized = true;
 	if (mmap_file == NULL) {
@@ -620,6 +636,7 @@ int defer_init(const char *mmap_file, int cpus)
 	struct defer header = {
 		.capacity = KRU_CAPACITY,
 		.max_decay = MAX_DECAY,
+		.log_period = log_period,
 		.cpus = cpus,
 		.using_avx2 = using_avx2(),
 	};
@@ -633,6 +650,7 @@ int defer_init(const char *mmap_file, int cpus)
 		offsetof(struct defer, using_avx2) ==
 			sizeof(header.capacity) +
 			sizeof(header.max_decay) +
+			sizeof(header.log_period) +
 			sizeof(header.cpus),
 		"detected padding with undefined data inside mmapped header");
 
@@ -649,6 +667,8 @@ int defer_init(const char *mmap_file, int cpus)
 			goto fail;
 		}
 
+		defer->log_time = kr_now() - log_period;
+
 		ret = mmapped_init_continue(&defer_mmapped);
 		if (ret != 0) goto fail;
 

diff --git a/daemon/defer.h b/daemon/defer.h
@@ -9,7 +9,7 @@
 
 /// Initialize defer, incl. shared memory with KRU, excl. idle.
 KR_EXPORT
-int defer_init(const char *mmap_file, int cpus);
+int defer_init(const char *mmap_file, uint32_t log_period, int cpus);
 
 /// Initialize idle.
 int defer_init_idle(uv_loop_t *loop);

diff --git a/daemon/lua/kres-gen-33.lua b/daemon/lua/kres-gen-33.lua
@@ -617,7 +617,7 @@ struct qr_task *worker_resolve_start(knot_pkt_t *, struct kr_qflags);
 int zi_zone_import(const zi_config_t);
 _Bool ratelimiting_request_begin(struct kr_request *);
 int ratelimiting_init(const char *, size_t, uint32_t, uint32_t, uint16_t, uint32_t, _Bool);
-int defer_init(const char *, int);
+int defer_init(const char *, uint32_t, int);
 struct engine {
 	char _stub[];
 };

diff --git a/daemon/main.c b/daemon/main.c
@@ -618,7 +618,7 @@ int main(int argc, char **argv)
 
 	if (!defer_initialized) {
 		kr_log_warning(SYSTEM, "Prioritization not initialized from Lua, using hardcoded default.\n");
-		ret = defer_init("defer", 1);
+		ret = defer_init("defer", 1, 1);
 		if (ret) {
 			ret = EXIT_FAILURE;
 			goto cleanup;

diff --git a/doc/_static/config.schema.json b/doc/_static/config.schema.json
@@ -1721,10 +1721,17 @@
                     "type": "boolean",
                     "description": "Use request prioritization.",
                     "default": true
+                },
+                "log-period": {
+                    "type": "string",
+                    "pattern": "^(\\d+)(us|ms|s|m|h|d)$",
+                    "description": "Minimal time between two log messages, or '0s' to disable.",
+                    "default": "0s"
                 }
             },
             "default": {
-                "enabled": true
+                "enabled": true,
+                "log_period": "0s"
             }
         },
         "lua": {

diff --git a/python/knot_resolver/datamodel/defer_schema.py b/python/knot_resolver/datamodel/defer_schema.py
@@ -1,4 +1,5 @@
 from knot_resolver.utils.modeling import ConfigSchema
+from knot_resolver.datamodel.types import TimeUnit
 
 
 class DeferSchema(ConfigSchema):
@@ -7,6 +8,8 @@ class DeferSchema(ConfigSchema):
 
     ---
     enabled: Use request prioritization.
+    log_period: Minimal time between two log messages, or '0s' to disable.
     """
 
     enabled: bool = True
+    log_period: TimeUnit = TimeUnit("0s")
diff --git a/python/knot_resolver/datamodel/templates/defer.lua.j2 b/python/knot_resolver/datamodel/templates/defer.lua.j2
@@ -3,7 +3,8 @@
 {% if cfg.defer.enabled and not disable_defer -%}
 assert(C.defer_init(
 	'{{ cfg.rundir }}/defer',
+	{{ cfg.defer.log_period.millis() }},
 	{{ cfg.workers }}) == 0)
 {% else %}
-assert(C.defer_init(nil, 0) == 0)
+assert(C.defer_init(nil, 0, 0) == 0)
 {%- endif %}