From f45e777b9f544fe4b6958129ded563eba4585307 Mon Sep 17 00:00:00 2001 From: Tom Krizek Date: Fri, 22 Dec 2023 10:55:17 +0100 Subject: [PATCH 1/5] Add LogFile helper LogFile class contains a log path and has means to find a string in the log file. (cherry picked from commit 05b0ebac0fae3cfc88a216b60a748d56f6eaed42) --- bin/tests/system/isctest/__init__.py | 2 +- bin/tests/system/isctest/instance.py | 8 ++--- .../system/isctest/{watchlog.py => log.py} | 36 ++++++++++++++++++- 3 files changed, 40 insertions(+), 6 deletions(-) rename bin/tests/system/isctest/{watchlog.py => log.py} (91%) diff --git a/bin/tests/system/isctest/__init__.py b/bin/tests/system/isctest/__init__.py index a55c128007..3ea82a3f45 100644 --- a/bin/tests/system/isctest/__init__.py +++ b/bin/tests/system/isctest/__init__.py @@ -13,4 +13,4 @@ from . import check from . import instance from . import query from . import rndc -from . import watchlog +from . import log diff --git a/bin/tests/system/isctest/instance.py b/bin/tests/system/isctest/instance.py index fdac94c7d2..ede48c095c 100644 --- a/bin/tests/system/isctest/instance.py +++ b/bin/tests/system/isctest/instance.py @@ -18,7 +18,7 @@ import os import re from .rndc import RNDCBinaryExecutor, RNDCException, RNDCExecutor -from .watchlog import WatchLogFromStart, WatchLogFromHere +from .log import LogFile, WatchLogFromStart, WatchLogFromHere class NamedPorts(NamedTuple): @@ -63,7 +63,7 @@ class NamedInstance: """ self.ip = self._identifier_to_ip(identifier) self.ports = ports - self._log_file = os.path.join(identifier, "named.run") + self.log = LogFile(os.path.join(identifier, "named.run")) self._rndc_executor = rndc_executor or RNDCBinaryExecutor() self._rndc_logger = rndc_logger or logging.getLogger() @@ -133,14 +133,14 @@ class NamedInstance: Return an instance of the `WatchLogFromStart` context manager for this `named` instance's log file. """ - return WatchLogFromStart(self._log_file) + return WatchLogFromStart(self.log.path) def watch_log_from_here(self) -> WatchLogFromHere: """ Return an instance of the `WatchLogFromHere` context manager for this `named` instance's log file. """ - return WatchLogFromHere(self._log_file) + return WatchLogFromHere(self.log.path) def reconfigure(self) -> None: """ diff --git a/bin/tests/system/isctest/watchlog.py b/bin/tests/system/isctest/log.py similarity index 91% rename from bin/tests/system/isctest/watchlog.py rename to bin/tests/system/isctest/log.py index 1456c535c9..38c1143821 100644 --- a/bin/tests/system/isctest/watchlog.py +++ b/bin/tests/system/isctest/log.py @@ -9,7 +9,7 @@ # See the COPYRIGHT file distributed with this work for additional # information regarding copyright ownership. -from typing import Optional, TextIO, Dict, Any, overload, List, Union +from typing import Iterator, Optional, TextIO, Dict, Any, overload, List, Union import abc import os @@ -22,6 +22,40 @@ class WatchLogException(Exception): pass +class LogFile: + """ + Log file wrapper with a path and means to find a string in its contents. + """ + + def __init__(self, path: str): + self.path = path + + @property + def _lines(self) -> Iterator[str]: + with open(self.path, encoding="utf-8") as f: + yield from f + + def __contains__(self, substring: str) -> bool: + """ + Return whether any of the lines in the log contains a given string. + """ + for line in self._lines: + if substring in line: + return True + return False + + def expect(self, msg: str): + """Check the string is present anywhere in the log file.""" + if msg in self: + return + assert False, f"log message not found in log {self.path}: {msg}" + + def prohibit(self, msg: str): + """Check the string is not present in the entire log file.""" + if msg in self: + assert False, f"forbidden message appeared in log {self.path}: {msg}" + + class WatchLog(abc.ABC): """ From 93b4b110a756e44d22bee7e19658811607a34c82 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Micha=C5=82=20K=C4=99pie=C5=84?= Date: Thu, 21 Dec 2023 12:22:18 +0100 Subject: [PATCH 2/5] Refactor string matching loop for readability (cherry picked from commit 831c5d34f96441fa9aa258feab26e452333cc3ff) --- bin/tests/system/checkds/tests_checkds.py | 13 ++++++++----- 1 file changed, 8 insertions(+), 5 deletions(-) diff --git a/bin/tests/system/checkds/tests_checkds.py b/bin/tests/system/checkds/tests_checkds.py index 01c34de132..b6fcaa15d8 100755 --- a/bin/tests/system/checkds/tests_checkds.py +++ b/bin/tests/system/checkds/tests_checkds.py @@ -356,12 +356,15 @@ def test_checkds(servers, params): # Wait until the provided zone is signed and then verify its DNSSEC data. zone_check(servers["ns9"], params.zone) - # Wait until all the expected log lines are found in the log file for the - # provided server. + # Wait up to 10 seconds until all the expected log lines are found in the + # log file for the provided server. + time_remaining = 10 for log_string in params.logs_to_wait_for: - with servers["ns9"].watch_log_from_start() as watcher: - line = f"zone {params.zone}/IN (signed): checkds: {log_string}" - watcher.wait_for_line(line) + line = f"zone {params.zone}/IN (signed): checkds: {log_string}" + while line not in servers["ns9"].log: + time_remaining -= 1 + assert time_remaining, f'Timed out waiting for "{log_string}" to be logged' + time.sleep(1) # Check whether key states on the parent server provided match # expectations. From b09835a5d11f0296b417d5ad98ed5568d043d687 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Micha=C5=82=20K=C4=99pie=C5=84?= Date: Tue, 19 Dec 2023 11:10:04 +0100 Subject: [PATCH 3/5] Ensure wait_for_line() is not called with timeout=0 (cherry picked from commit 1770b370959874d0ea51f00249fda8c92a26d765) --- bin/tests/system/isctest/log.py | 1 + 1 file changed, 1 insertion(+) diff --git a/bin/tests/system/isctest/log.py b/bin/tests/system/isctest/log.py index 38c1143821..8a382626c0 100644 --- a/bin/tests/system/isctest/log.py +++ b/bin/tests/system/isctest/log.py @@ -227,6 +227,7 @@ class WatchLog(abc.ABC): if not self._fd: raise WatchLogException("No file to watch") leftover = "" + assert timeout, "Do not use this class unless you want to WAIT for something." deadline = time.time() + timeout while time.time() < deadline: for line in self._fd.readlines(): From 24fd30f7eba4b7560ae1e6da1be7ec96acdca7da Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Micha=C5=82=20K=C4=99pie=C5=84?= Date: Tue, 19 Dec 2023 15:58:36 +0100 Subject: [PATCH 4/5] Add wait_for_zones_loaded fixture The wait_for_zones_loaded fixture waits for the "all zones loaded" message in the named log file before the test function can proceed. (cherry picked from commit 662a88055c59d0abc00d3db06c573bab2eca5463) --- bin/tests/system/conftest.py | 21 +++++++++++++++++++++ bin/tests/system/pytest.ini | 2 ++ 2 files changed, 23 insertions(+) diff --git a/bin/tests/system/conftest.py b/bin/tests/system/conftest.py index 692743115c..a1a42770cf 100644 --- a/bin/tests/system/conftest.py +++ b/bin/tests/system/conftest.py @@ -357,6 +357,27 @@ def mlogger(system_test_name): return logging.getLogger(system_test_name) +def _get_marker(node, marker): + try: + # pytest >= 4.x + return node.get_closest_marker(marker) + except AttributeError: + # pytest < 4.x + return node.get_marker(marker) + + +@pytest.fixture(autouse=True) +def wait_for_zones_loaded(request, servers): + """Wait for all zones to be loaded by specified named instances.""" + instances = _get_marker(request.node, "requires_zones_loaded") + if not instances: + return + + for instance in instances.args: + with servers[instance].watch_log_from_start() as watcher: + watcher.wait_for_line("all zones loaded") + + @pytest.fixture def logger(request, system_test_name): """Logging facility specific to a particular test.""" diff --git a/bin/tests/system/pytest.ini b/bin/tests/system/pytest.ini index 1559595852..a8733cefb6 100644 --- a/bin/tests/system/pytest.ini +++ b/bin/tests/system/pytest.ini @@ -18,3 +18,5 @@ log_level = INFO python_files = tests_*.py junit_logging = log junit_log_passing_tests = 0 +markers = + requires_zones_loaded: ensures the test does not start until the specified named instances load all configured zones From dfe31f7395c7b80d8a7fc4891f2d9dcaa2a6fb65 Mon Sep 17 00:00:00 2001 From: Michal Nowak Date: Fri, 22 Dec 2023 10:57:12 +0100 Subject: [PATCH 5/5] Rewrite spf system test to pytest (cherry picked from commit e67d770432794f00855446ebc4353596360b4a3f) --- bin/tests/system/spf/tests.sh | 46 ------------------------- bin/tests/system/spf/tests_sh_spf.py | 14 -------- bin/tests/system/spf/tests_spf_zones.py | 32 +++++++++++++++++ 3 files changed, 32 insertions(+), 60 deletions(-) delete mode 100644 bin/tests/system/spf/tests.sh delete mode 100644 bin/tests/system/spf/tests_sh_spf.py create mode 100644 bin/tests/system/spf/tests_spf_zones.py diff --git a/bin/tests/system/spf/tests.sh b/bin/tests/system/spf/tests.sh deleted file mode 100644 index a74f55904e..0000000000 --- a/bin/tests/system/spf/tests.sh +++ /dev/null @@ -1,46 +0,0 @@ -#!/bin/sh - -# Copyright (C) Internet Systems Consortium, Inc. ("ISC") -# -# SPDX-License-Identifier: MPL-2.0 -# -# This Source Code Form is subject to the terms of the Mozilla Public -# License, v. 2.0. If a copy of the MPL was not distributed with this -# file, you can obtain one at https://mozilla.org/MPL/2.0/. -# -# See the COPYRIGHT file distributed with this work for additional -# information regarding copyright ownership. - -set -e - -. ../conf.sh - -n=1 -status=0 - -# Wait until all zones are loaded before checking SPF related logs -for i in 1 2 3 4 5 6 7 8 9 10; do - grep "all zones loaded" ns1/named.run >/dev/null && break - sleep 1 -done - -echo_i "checking that SPF warnings have been correctly generated ($n)" -ret=0 - -grep "zone spf/IN: loaded serial 0" ns1/named.run >/dev/null || ret=1 -grep "'y.spf' found type SPF" ns1/named.run >/dev/null || ret=1 -grep "'spf' found type SPF" ns1/named.run >/dev/null && ret=1 - -grep "zone warn/IN: loaded serial 0" ns1/named.run >/dev/null || ret=1 -grep "'y.warn' found type SPF" ns1/named.run >/dev/null || ret=1 -grep "'warn' found type SPF" ns1/named.run >/dev/null && ret=1 - -grep "zone nowarn/IN: loaded serial 0" ns1/named.run >/dev/null || ret=1 -grep "'y.nowarn' found type SPF" ns1/named.run >/dev/null && ret=1 -grep "'nowarn' found type SPF" ns1/named.run >/dev/null && ret=1 -n=$((n + 1)) -if [ $ret != 0 ]; then echo_i "failed"; fi -status=$((status + ret)) - -echo_i "exit status: $status" -[ $status -eq 0 ] || exit 1 diff --git a/bin/tests/system/spf/tests_sh_spf.py b/bin/tests/system/spf/tests_sh_spf.py deleted file mode 100644 index 53c623d594..0000000000 --- a/bin/tests/system/spf/tests_sh_spf.py +++ /dev/null @@ -1,14 +0,0 @@ -# Copyright (C) Internet Systems Consortium, Inc. ("ISC") -# -# SPDX-License-Identifier: MPL-2.0 -# -# This Source Code Form is subject to the terms of the Mozilla Public -# License, v. 2.0. If a copy of the MPL was not distributed with this -# file, you can obtain one at https://mozilla.org/MPL/2.0/. -# -# See the COPYRIGHT file distributed with this work for additional -# information regarding copyright ownership. - - -def test_spf(run_tests_sh): - run_tests_sh() diff --git a/bin/tests/system/spf/tests_spf_zones.py b/bin/tests/system/spf/tests_spf_zones.py new file mode 100644 index 0000000000..550704ba51 --- /dev/null +++ b/bin/tests/system/spf/tests_spf_zones.py @@ -0,0 +1,32 @@ +# Copyright (C) Internet Systems Consortium, Inc. ("ISC") +# +# SPDX-License-Identifier: MPL-2.0 +# +# This Source Code Form is subject to the terms of the Mozilla Public +# License, v. 2.0. If a copy of the MPL was not distributed with this +# file, you can obtain one at https://mozilla.org/MPL/2.0/. +# +# See the COPYRIGHT file distributed with this work for additional +# information regarding copyright ownership. + +import pytest + + +@pytest.mark.requires_zones_loaded("ns1") +def test_spf_log(servers): + for msg in ( + "zone spf/IN: 'y.spf' found type SPF record but no SPF TXT record found", + "zone warn/IN: 'y.warn' found type SPF record but no SPF TXT record found", + "zone spf/IN: loaded serial 0", + "zone warn/IN: loaded serial 0", + "zone nowarn/IN: loaded serial 0", + ): + servers["ns1"].log.expect(msg) + + for msg in ( + "zone nowarn/IN: 'y.nowarn' found type SPF record but no SPF TXT record found", + "zone spf/IN: 'spf' found type SPF record but no SPF TXT record found", + "zone warn/IN: 'warn' found type SPF record but no SPF TXT record found", + "zone nowarn/IN: 'nowarn' found type SPF record but no SPF TXT record found", + ): + servers["ns1"].log.prohibit(msg)