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

diff --git a/daemon/defer.c b/daemon/defer.c
index aa29d2f1c8b8f1ddd78d6830175c7543e0a392bc..91c718bf398fb2e3fb706a4910258ef882b2e281 100644 (file)
--- 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
index b24ee70ecad92b00b9b18653e3094ac6d4ec2dee..06c9d56dac9a7982156ceabd48976e3915e17698 100644 (file)
--- 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
index 4312d2184d7dffe8d70856459aa7ca32d9684405..3fc16df3cd7d3ffd1b786b234c9a5150f1c85707 100644 (file)
--- 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
index 1600f59a25f3a68b1e1fa3d264d5ecc15d17d350..a7b9c92b6d9c304c462f44d297c3fd783700ec42 100644 (file)
--- 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
index 2532dc4fe21e6a771bcecbeb9ff74d9da7e7066e..0d91be0504bcab144ba8e859c1ea185d0093f36d 100644 (file)
--- 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
index 40de040130e9b81dcff32b0c8633a3d6864a1975..2e1992f84c6b8a512ce6ebd4d7bf37e68d7859a2 100644 (file)
--- 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
index 8cad0cfc198a75d783c89ace58132fc636a5713a..131b71c4760943e000e8328e75e4900659efe933 100644 (file)
--- 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 %}