From: Lukáš Ježek Date: Fri, 2 Jul 2021 07:32:51 +0000 (+0200) Subject: log: fix CI tests X-Git-Url: http://git.ipfire.org/?a=commitdiff_plain;h=d3421eaf39ea6a9f995e892a628689407c9fe75a;p=thirdparty%2Fknot-resolver.git log: fix CI tests --- diff --git a/daemon/lua/kres-gen.lua b/daemon/lua/kres-gen.lua index 319cef030..39a305367 100644 --- a/daemon/lua/kres-gen.lua +++ b/daemon/lua/kres-gen.lua @@ -301,7 +301,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 baa92b35b..086dab9f7 100644 --- 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 57db6e1bf..57c8542ed 100644 --- 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 d1537b70a..702dfd34e 100644 --- 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 4c2c5d213..82b7a1fc1 100644 --- 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 3bf1203ea..27c082bfc 100644 --- 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 6c83e54bc..f16993fa3 100644 --- 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 f190003db..703b11fe8 100644 --- a/tests/pytests/kresd.py +++ b/tests/pytests/kresd.py @@ -295,7 +295,7 @@ 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_STARTUP_MSGID = re.compile(r'^\[[^]]+\]\[{}.*'.format(KRESD_STARTUP_MSGID)) KRESD_LOG_IO_CLOSE = re.compile(r'^\[io\].*closed by peer.*')