log: fix CI tests

diff --git a/daemon/lua/kres-gen-29.lua b/daemon/lua/kres-gen-29.lua
index 7630c79ac3c0b1998b584b09ce44db23f1b9cbe3..668c773c5d9a127801cd160a64aa49e523930ed8 100644 (file)
--- a/daemon/lua/kres-gen-29.lua
+++ b/daemon/lua/kres-gen-29.lua
@@ -308,7 +308,7 @@ struct kr_server_selection {
 };
 typedef unsigned long log_groups_t;
 typedef int log_level_t;
-enum kr_log_groups_type {LOG_GRP_SYSTEM = 1, LOG_GRP_CACHE, LOG_GRP_IO, LOG_GRP_NETWORK, LOG_GRP_TA, LOG_GRP_TLS, LOG_GRP_GNUTLS, LOG_GRP_TLSCLIENT, LOG_GRP_XDP, LOG_GRP_ZIMPORT, LOG_GRP_ZSCANNER, LOG_GRP_DOH, LOG_GRP_DNSSEC, LOG_GRP_HINT, LOG_GRP_PLAN, LOG_GRP_ITERATOR, LOG_GRP_VALIDATOR, LOG_GRP_RESOLVER, LOG_GRP_SELECTION, LOG_GRP_ZCUT, LOG_GRP_COOKIES, LOG_GRP_STATISTICS, LOG_GRP_REBIND, LOG_GRP_WORKER, LOG_GRP_POLICY, LOG_GRP_TASENTINEL, LOG_GRP_TASIGNALING, LOG_GRP_TAUPDATE, LOG_GRP_DAF, LOG_GRP_DETECTTIMEJUMP, LOG_GRP_DETECTTIMESKEW, LOG_GRP_GRAPHITE, LOG_GRP_PREFILL, LOG_GRP_PRIMING, LOG_GRP_SRVSTALE, LOG_GRP_WATCHDOG};
+enum kr_log_groups_type {LOG_GRP_SYSTEM = 1, LOG_GRP_CACHE, LOG_GRP_IO, LOG_GRP_NETWORK, LOG_GRP_TA, LOG_GRP_TLS, LOG_GRP_GNUTLS, LOG_GRP_TLSCLIENT, LOG_GRP_XDP, LOG_GRP_ZIMPORT, LOG_GRP_ZSCANNER, LOG_GRP_DOH, LOG_GRP_DNSSEC, LOG_GRP_HINT, LOG_GRP_PLAN, LOG_GRP_ITERATOR, LOG_GRP_VALIDATOR, LOG_GRP_RESOLVER, LOG_GRP_SELECTION, LOG_GRP_ZCUT, LOG_GRP_COOKIES, LOG_GRP_STATISTICS, LOG_GRP_REBIND, LOG_GRP_WORKER, LOG_GRP_POLICY, LOG_GRP_TASENTINEL, LOG_GRP_TASIGNALING, LOG_GRP_TAUPDATE, LOG_GRP_DAF, LOG_GRP_DETECTTIMEJUMP, LOG_GRP_DETECTTIMESKEW, LOG_GRP_GRAPHITE, LOG_GRP_PREFILL, LOG_GRP_PRIMING, LOG_GRP_SRVSTALE, LOG_GRP_WATCHDOG, LOG_GRP_TESTS};
 
 kr_layer_t kr_layer_t_static;
 _Bool kr_dbg_assertion_abort;

diff --git a/daemon/lua/map.test.integr/kresd_config.j2 b/daemon/lua/map.test.integr/kresd_config.j2
index baa92b35ba2e9f9fc9fa250ba7df67d577316557..086dab9f795f2ed1d4ed9f66fa477586b31eaaf6 100644 (file)
--- a/daemon/lua/map.test.integr/kresd_config.j2
+++ b/daemon/lua/map.test.integr/kresd_config.j2
@@ -1,5 +1,6 @@
 -- SPDX-License-Identifier: GPL-3.0-or-later
-log('my PID = %d', worker.pid)
+local ffi = require('ffi')
+log_info(ffi.C.LOG_GRP_TESTS, 'my PID = %d', worker.pid)
 
 trust_anchors.remove('.')
 
@@ -38,32 +39,32 @@ net.listen(worker.control_path .. worker.pid, nil, {kind = 'control'})
 assert(#net.list() >= 3)  -- UDP, TCP, control
 
 -- debug, kept for future use
---log('%s', worker.control_path)
---log('%s', table_print(net.list()))
+--set_log_level("debug")
+log_debug(ffi.C.LOG_GRP_TESTS, '%s', worker.control_path)
+log_debug(ffi.C.LOG_GRP_TESTS, '%s', table_print(net.list()))
 
 function wait_for_sockets()
-       log('waiting for control sockets')
-       local ffi = require('ffi')
+       log_info(ffi.C.LOG_GRP_TESTS, 'waiting for control sockets')
        local timeout = 5000 -- ms
        local start_time = tonumber(ffi.C.kr_now())
        local now
        while true do
                now = tonumber(ffi.C.kr_now())
                if now > start_time + timeout then
-                       log('timeout while waiting for control sockets to appear')
+                       log_info(ffi.C.LOG_GRP_TESTS, 'timeout while waiting for control sockets to appear')
                        os.exit(3)
                end
                local pids = kluautil.list_dir(worker.control_path)
                if #pids == n_instances then
                        -- debug, kept for future use
-                       --log('got control sockets:')
-                       --log(table_print(pids))
+                       log_debug(ffi.C.LOG_GRP_TESTS, 'got control sockets:')
+                       log_debug(ffi.C.LOG_GRP_TESTS, table_print(pids))
                        break
                else
                        worker.sleep(0.1)
                end
        end
-       log('PIDs are visible now (waiting took %d ms)', now - start_time)
+       log_info(ffi.C.LOG_GRP_TESTS, 'PIDs are visible now (waiting took %d ms)', now - start_time)
 end
 
 -- expression should throw Lua error:
@@ -90,7 +91,7 @@ end
 function tests()
        -- add delay to each test to force scheduler to interleave tests and DNS queries
        local test_delay = 20 / 1000 -- seconds
-       log('starting map() tests now')
+       log_info(ffi.C.LOG_GRP_TESTS, 'starting map() tests now')
 
        tap.boom(map, {'1 ++ 1'}, 'syntax error in command is detected')
        worker.sleep(test_delay)
@@ -143,11 +144,11 @@ local started = false
 function tests_start()
        -- just in case, duplicates should not happen
        if started then
-               log('huh? duplicate test invocation ignored, a retrasmit?')
+               log_info(ffi.C.LOG_GRP_TESTS, 'huh? duplicate test invocation ignored, a retrasmit?')
                return
        end
        started = true
-       log('start query triggered, scheduling tests')
+       log_info(ffi.C.LOG_GRP_TESTS, 'start query triggered, scheduling tests')
 
        -- DNS queries and map() commands must be serviced while sleep is running
        worker.coroutine(function() worker.sleep(3600) end)
@@ -171,7 +172,7 @@ policy.add(policy.suffix(tests_done, {'\4done\0'}), true)
 policy.add(policy.all(
        function()
                local delay = 10  -- ms
-               log('packet delayed by %d ms', delay)
+               log_info(ffi.C.LOG_GRP_TESTS, 'packet delayed by %d ms', delay)
                worker.sleep(delay / 1000)
        end))
 

diff --git a/lib/layer/test.integr/kresd_config.j2 b/lib/layer/test.integr/kresd_config.j2
index 57db6e1bfdaf6caaaf398ab70ed5799e19831ecd..57c8542ed9080d4f586c6a68926939cb64d005b2 100644 (file)
--- a/lib/layer/test.integr/kresd_config.j2
+++ b/lib/layer/test.integr/kresd_config.j2
@@ -1,11 +1,13 @@
 -- SPDX-License-Identifier: GPL-3.0-or-later
 
+local ffi = require('ffi')
+
 -- hook for iter_refuse_toomany.rpl
 local function check_max_number_of_upstream_queries(maxcnt)
        return function (state, req)
                local vals = worker.stats()
                local upstream_packets = vals.ipv4 + vals.ipv6
-               log('%d packets sent to upstream', upstream_packets)
+               log_info(ffi.C.LOG_GRP_TESTS, '%d packets sent to upstream', upstream_packets)
                local answ_f
                if upstream_packets > maxcnt then  -- . + com. + ????
                        answ_f = policy.ANSWER(

diff --git a/lib/log.c b/lib/log.c
index d1537b70a973dce970178afcb36fd61c769a8d43..702dfd34e119e1012b64f3bdd7fcd9ba0c664690 100644 (file)
--- a/lib/log.c
+++ b/lib/log.c
@@ -60,6 +60,7 @@ log_group_names_t log_group_names[] = {
        GRP_NAME_ITEM(LOG_GRP_PRIMING),
        GRP_NAME_ITEM(LOG_GRP_SRVSTALE),
        GRP_NAME_ITEM(LOG_GRP_WATCHDOG),
+       GRP_NAME_ITEM(LOG_GRP_TESTS),
        { NULL,         -1 },
 };
 

diff --git a/lib/log.h b/lib/log.h
index e1d8b911822bf3b2cf94b34a8df37d152b1779fc..c43f53f304199cc5e92e6dfc1a6e7f0894e9778c 100644 (file)
--- a/lib/log.h
+++ b/lib/log.h
@@ -66,6 +66,7 @@ enum kr_log_groups_type {
        LOG_GRP_PRIMING,
        LOG_GRP_SRVSTALE,
        LOG_GRP_WATCHDOG,
+       LOG_GRP_TESTS,
 };
 
 
@@ -105,6 +106,7 @@ enum kr_log_groups_type {
 #define LOG_GRP_PRIMING_TAG            "primin"
 #define LOG_GRP_SRVSTALE_TAG           "srvstl"
 #define LOG_GRP_WATCHDOG_TAG           "wtchdg"
+#define LOG_GRP_TESTS_TAG              "tests "
 
 KR_EXPORT
 extern log_groups_t kr_log_groups;

diff --git a/modules/bogus_log/test.integr/kresd_config.j2 b/modules/bogus_log/test.integr/kresd_config.j2
index 3bf1203eaffc7d13acfc8781cfef32839eb48003..27c082bfc1ec43b2ff2ad75a24c85bd7576eae4f 100644 (file)
--- a/modules/bogus_log/test.integr/kresd_config.j2
+++ b/modules/bogus_log/test.integr/kresd_config.j2
@@ -1,4 +1,6 @@
 -- SPDX-License-Identifier: GPL-3.0-or-later
+local ffi = require('ffi')
+
 {% for TAF in TRUST_ANCHOR_FILES %}
 trust_anchors.add_file('{{TAF}}')
 {% endfor %}
@@ -7,7 +9,7 @@ trust_anchors.add_file('{{TAF}}')
 modules.load('bogus_log')
 
 function check_stats(got)
-       log('checking if bogus_log.frequent values match expected values:')
+       log_info(ffi.C.LOG_GRP_TESTS, 'checking if bogus_log.frequent values match expected values:')
        local expected = {
                [1] = {
                        ['type'] = 'DNSKEY',
@@ -18,17 +20,17 @@ function check_stats(got)
        print(table_print(expected))
 
        if table_print(expected) == table_print(got) then
-               log('no problem found')
+               log_info(ffi.C.LOG_GRP_TESTS, 'no problem found')
                return policy.DENY_MSG('Ok')
        else
-               log('mismatch!')
+               log_info(ffi.C.LOG_GRP_TESTS, 'mismatch!')
                return policy.DENY_MSG('bogus_log.frequent mismatch, see logs')
        end
 end
 
 function reply_result(state, req)
        local got = bogus_log.frequent()
-       log('current bogus_log.frequent() values:')
+       print('current bogus_log.frequent() values:')
        print(table_print(got))
        local result = check_stats(got)
        return result(state, req)

diff --git a/modules/stats/test.integr/kresd_config.j2 b/modules/stats/test.integr/kresd_config.j2
index 6c83e54bc914c209fb67adb9ebf0e5dca29b67e0..f16993fa3234c92865a1beb54990280e612eb0d3 100644 (file)
--- a/modules/stats/test.integr/kresd_config.j2
+++ b/modules/stats/test.integr/kresd_config.j2
@@ -1,11 +1,13 @@
 -- SPDX-License-Identifier: GPL-3.0-or-later
+local ffi = require('ffi')
+
 {% raw %}
 modules.load('stats')
 
 FWD_TARGET = policy.FORWARD('192.0.2.1')
 
 function check_stats(got)
-       log('checking if stat values match expected values:')
+       log_info(ffi.C.LOG_GRP_TESTS, 'checking if stat values match expected values:')
        local expected = {
                ['answer.cd'] = 2,
                ['answer.cached'] = 1,
@@ -27,7 +29,8 @@ function check_stats(got)
        local ok = true
        for key, expval in pairs(expected) do
                if got[key] ~= expval then
-                       log('ERROR: stats key ' .. key
+                       log_info(ffi.C.LOG_GRP_TESTS,
+                           'ERROR: stats key ' .. key
                            .. ' has unexpected value'
                            .. ' (expected ' .. tostring(expval)
                            .. ' got ' .. tostring(got[key] .. ')'))
@@ -35,7 +38,7 @@ function check_stats(got)
                end
        end
        if ok then
-               log('no problem found')
+               log_info(ffi.C.LOG_GRP_TESTS, 'no problem found')
                return FWD_TARGET
        else
                return policy.DENY_MSG('Stats test failure')
@@ -44,7 +47,7 @@ end
 
 function reply_result(state, req)
        local got = stats.list()
-       log('current stats.list() values:')
+       log_info(ffi.C.LOG_GRP_TESTS, 'current stats.list() values:')
        print(table_print(got))
        local result = check_stats(got)
        return result(state, req)

diff --git a/tests/pytests/kresd.py b/tests/pytests/kresd.py
index f190003db66f3878aee8740d54df6d5e1b406168..62835f3662e4393baf8818733203cd5ebb07267c 100644 (file)
--- a/tests/pytests/kresd.py
+++ b/tests/pytests/kresd.py
@@ -295,8 +295,8 @@ def make_port(ip=None, ip6=None):
     raise RuntimeError("No available port found!")
 
 
-KRESD_LOG_STARTUP_MSGID = re.compile(r'^\[{}.*'.format(KRESD_STARTUP_MSGID))
-KRESD_LOG_IO_CLOSE = re.compile(r'^\[io\].*closed by peer.*')
+KRESD_LOG_STARTUP_MSGID = re.compile(r'^\[[^]]+\]\[{}.*'.format(KRESD_STARTUP_MSGID))
+KRESD_LOG_IO_CLOSE = re.compile(r'^\[io    \].*closed by peer.*')
 
 
 @contextmanager