diff --git a/.gitlab-ci.yml b/.gitlab-ci.yml index 93185f871d..a7968b7b21 100644 --- a/.gitlab-ci.yml +++ b/.gitlab-ci.yml @@ -592,6 +592,8 @@ coccinelle: pylint: <<: *precheck_job needs: [] + variables: + PYTHONPATH: "${CI_PROJECT_DIR}/bin/tests/system" script: - pylint --rcfile $CI_PROJECT_DIR/.pylintrc $(git ls-files '*.py' | grep -vE '(ans\.py|dangerfile\.py|^bin/tests/system/)') # Ignore Pylint wrong-import-position error in system test to enable use of pytest.importorskip @@ -642,6 +644,11 @@ checkbashisms: script: - checkbashisms $(find . -path './.git' -prune -o -type f -exec sh -c 'head -n 1 "{}" | grep -qsF "#!/bin/sh"' \; -print) +mypy: + <<: *precheck_job + script: + - mypy "bin/tests/system/isctest/" + tarball-create: stage: precheck <<: *base_image diff --git a/bin/tests/system/addzone/tests_rndc_deadlock.py b/bin/tests/system/addzone/tests_rndc_deadlock.py index fefcc2dc8b..78fa11a095 100755 --- a/bin/tests/system/addzone/tests_rndc_deadlock.py +++ b/bin/tests/system/addzone/tests_rndc_deadlock.py @@ -10,25 +10,12 @@ # information regarding copyright ownership. import concurrent.futures -import os -import subprocess import time - -def run_rndc(server, rndc_command): - """ - Send the specified 'rndc_command' to 'server' with a timeout of 10 seconds - """ - rndc = os.getenv("RNDC") - port = os.getenv("CONTROLPORT") - - cmdline = [rndc, "-c", "../_common/rndc.conf", "-p", port, "-s", server] - cmdline.extend(rndc_command) - - subprocess.check_output(cmdline, stderr=subprocess.STDOUT, timeout=10) +import isctest -def rndc_loop(test_state, domain): +def rndc_loop(test_state, domain, ns3): """ Run "rndc addzone", "rndc modzone", and "rndc delzone" in a tight loop until the test is considered finished, ignoring errors @@ -45,35 +32,33 @@ def rndc_loop(test_state, domain): while not test_state["finished"]: for command in rndc_commands: - try: - run_rndc("10.53.0.3", command) - except subprocess.SubprocessError: - pass + ns3.rndc(" ".join(command), ignore_errors=True, log=False) -def check_if_server_is_responsive(): +def check_if_server_is_responsive(ns3): """ Check if server status can be successfully retrieved using "rndc status" """ try: - run_rndc("10.53.0.3", ["status"]) + ns3.rndc("status", log=False) return True - except subprocess.SubprocessError: + except isctest.rndc.RNDCException: return False -def test_rndc_deadlock(): +def test_rndc_deadlock(servers): """ Test whether running "rndc addzone", "rndc modzone", and "rndc delzone" commands concurrently does not trigger a deadlock """ test_state = {"finished": False} + ns3 = servers["ns3"] # Create 4 worker threads running "rndc" commands in a loop. with concurrent.futures.ThreadPoolExecutor() as executor: for i in range(1, 5): domain = "example%d" % i - executor.submit(rndc_loop, test_state, domain) + executor.submit(rndc_loop, test_state, domain, ns3) # Run "rndc status" 10 times, with 1-second pauses between attempts. # Each "rndc status" invocation has a timeout of 10 seconds. If any of @@ -81,7 +66,7 @@ def test_rndc_deadlock(): server_is_responsive = True attempts = 10 while server_is_responsive and attempts > 0: - server_is_responsive = check_if_server_is_responsive() + server_is_responsive = check_if_server_is_responsive(ns3) attempts -= 1 time.sleep(1) diff --git a/bin/tests/system/checkds/tests_checkds.py b/bin/tests/system/checkds/tests_checkds.py index 5f9ae7341c..01c34de132 100755 --- a/bin/tests/system/checkds/tests_checkds.py +++ b/bin/tests/system/checkds/tests_checkds.py @@ -11,7 +11,8 @@ # See the COPYRIGHT file distributed with this work for additional # information regarding copyright ownership. -import mmap +from typing import NamedTuple, Tuple + import os import subprocess import sys @@ -27,7 +28,6 @@ import dns.query import dns.rcode import dns.rdataclass import dns.rdatatype -import dns.resolver pytestmark = pytest.mark.skipif( @@ -42,8 +42,8 @@ def has_signed_apex_nsec(zone, response): ttl = 300 nextname = "a." types = "NS SOA RRSIG NSEC DNSKEY" - match = "{0} {1} IN NSEC {2}{0} {3}".format(zone, ttl, nextname, types) - sig = "{0} {1} IN RRSIG NSEC 13 2 300".format(zone, ttl) + match = f"{zone}. {ttl} IN NSEC {nextname}{zone}. {types}" + sig = f"{zone}. {ttl} IN RRSIG NSEC 13 2 300" for rr in response.answer: if match in rr.to_text(): @@ -63,19 +63,11 @@ def do_query(server, qname, qtype, tcp=False): query = dns.message.make_query(qname, qtype, use_edns=True, want_dnssec=True) try: if tcp: - response = dns.query.tcp( - query, server.nameservers[0], timeout=3, port=server.port - ) + response = dns.query.tcp(query, server.ip, timeout=3, port=server.ports.dns) else: - response = dns.query.udp( - query, server.nameservers[0], timeout=3, port=server.port - ) + response = dns.query.udp(query, server.ip, timeout=3, port=server.ports.dns) except dns.exception.Timeout: - print( - "error: query timeout for query {} {} to {}".format( - qname, qtype, server.nameservers[0] - ) - ) + print(f"error: query timeout for query {qname} {qtype} to {server.ip}") return None return response @@ -85,7 +77,7 @@ def verify_zone(zone, transfer): verify = os.getenv("VERIFY") assert verify is not None - filename = "{}out".format(zone) + filename = f"{zone}.out" with open(filename, "w", encoding="utf-8") as file: for rr in transfer.answer: file.write(rr.to_text()) @@ -97,21 +89,21 @@ def verify_zone(zone, transfer): verifier = subprocess.run(verify_cmd, capture_output=True, check=True) if verifier.returncode != 0: - print("error: dnssec-verify {} failed".format(zone)) + print(f"error: dnssec-verify {zone}. failed") sys.stderr.buffer.write(verifier.stderr) return verifier.returncode == 0 def read_statefile(server, zone): - addr = server.nameservers[0] + addr = server.ip count = 0 keyid = 0 state = {} response = do_query(server, zone, "DS", tcp=True) if not isinstance(response, dns.message.Message): - print("error: no response for {} DS from {}".format(zone, addr)) + print(f"error: no response for {zone}. DS from {addr}") return {} if response.rcode() == dns.rcode.NOERROR: @@ -129,20 +121,19 @@ def read_statefile(server, zone): if count != 1: print( - "error: expected a single DS in response for {} from {}," - "got {}".format(zone, addr, count) + f"error: expected a single DS in response for {zone}. " + "from {addr}, got {count}" ) return {} else: print( - "error: {} response for {} DNSKEY from {}".format( - dns.rcode.to_text(response.rcode()), zone, addr - ) + f"error: {dns.rcode.to_text(response.rcode())} response for {zone}. " + "DNSKEY from {addr}" ) return {} - filename = "ns9/K{}+013+{:05d}.state".format(zone, keyid) - print("read state file {}".format(filename)) + filename = f"ns9/K{zone}.+013+{keyid:05d}.state" + print(f"read state file {filename}") try: with open(filename, "r", encoding="utf-8") as file: @@ -160,21 +151,20 @@ def read_statefile(server, zone): def zone_check(server, zone): - addr = server.nameservers[0] + addr = server.ip # wait until zone is fully signed. signed = False for _ in range(10): response = do_query(server, zone, "NSEC") if not isinstance(response, dns.message.Message): - print("error: no response for {} NSEC from {}".format(zone, addr)) + print(f"error: no response for {zone}. NSEC from {addr}") elif response.rcode() == dns.rcode.NOERROR: signed = has_signed_apex_nsec(zone, response) else: print( - "error: {} response for {} NSEC from {}".format( - dns.rcode.to_text(response.rcode()), zone, addr - ) + f"error: {dns.rcode.to_text(response.rcode())} response for {zone}. " + "NSEC from {addr}" ) if signed: @@ -188,14 +178,13 @@ def zone_check(server, zone): verified = False transfer = do_query(server, zone, "AXFR", tcp=True) if not isinstance(transfer, dns.message.Message): - print("error: no response for {} AXFR from {}".format(zone, addr)) + print(f"error: no response for {zone}. AXFR from {addr}") elif transfer.rcode() == dns.rcode.NOERROR: verified = verify_zone(zone, transfer) else: print( - "error: {} response for {} AXFR from {}".format( - dns.rcode.to_text(transfer.rcode()), zone, addr - ) + f"error: {dns.rcode.to_text(transfer.rcode())} response for {zone}. " + "AXFR from {addr}" ) assert verified @@ -230,241 +219,150 @@ def keystate_check(server, zone, key): assert val != 0 -def wait_for_log(filename, log): - found = False - - for _ in range(10): - print("read log file {}".format(filename)) - - try: - with open(filename, "r", encoding="utf-8") as file: - s = mmap.mmap(file.fileno(), 0, access=mmap.ACCESS_READ) - if s.find(bytes(log, "ascii")) != -1: - found = True - except FileNotFoundError: - print("file not found {}".format(filename)) - - if found: - break - - print("sleep") - time.sleep(1) - - assert found +class CheckDSTest(NamedTuple): + zone: str + logs_to_wait_for: Tuple[str] + expected_parent_state: str -def test_checkds_dspublished(named_port): - # We create resolver instances that will be used to send queries. - server = dns.resolver.Resolver() - server.nameservers = ["10.53.0.9"] - server.port = named_port - - parent = dns.resolver.Resolver() - parent.nameservers = ["10.53.0.2"] - parent.port = named_port - +dspublished_tests = [ # DS correctly published in parent. - zone_check(server, "dspublished.checkds.") - wait_for_log( - "ns9/named.run", - "zone dspublished.checkds/IN (signed): checkds: DS response from 10.53.0.2", - ) - keystate_check(parent, "dspublished.checkds.", "DSPublish") - + CheckDSTest( + zone="dspublished.checkds", + logs_to_wait_for=("DS response from 10.53.0.2",), + expected_parent_state="DSPublish", + ), # DS correctly published in parent (reference to parental-agent). - zone_check(server, "reference.checkds.") - wait_for_log( - "ns9/named.run", - "zone reference.checkds/IN (signed): checkds: DS response from 10.53.0.2", - ) - keystate_check(parent, "reference.checkds.", "DSPublish") - + CheckDSTest( + zone="reference.checkds", + logs_to_wait_for=("DS response from 10.53.0.2",), + expected_parent_state="DSPublish", + ), # DS not published in parent. - zone_check(server, "missing-dspublished.checkds.") - wait_for_log( - "ns9/named.run", - "zone missing-dspublished.checkds/IN (signed): checkds: " - "empty DS response from 10.53.0.5", - ) - keystate_check(parent, "missing-dspublished.checkds.", "!DSPublish") - + CheckDSTest( + zone="missing-dspublished.checkds", + logs_to_wait_for=("empty DS response from 10.53.0.5",), + expected_parent_state="!DSPublish", + ), # Badly configured parent. - zone_check(server, "bad-dspublished.checkds.") - wait_for_log( - "ns9/named.run", - "zone bad-dspublished.checkds/IN (signed): checkds: " - "bad DS response from 10.53.0.6", - ) - keystate_check(parent, "bad-dspublished.checkds.", "!DSPublish") - + CheckDSTest( + zone="bad-dspublished.checkds", + logs_to_wait_for=("bad DS response from 10.53.0.6",), + expected_parent_state="!DSPublish", + ), # TBD: DS published in parent, but bogus signature. - # DS correctly published in all parents. - zone_check(server, "multiple-dspublished.checkds.") - wait_for_log( - "ns9/named.run", - "zone multiple-dspublished.checkds/IN (signed): checkds: " - "DS response from 10.53.0.2", - ) - wait_for_log( - "ns9/named.run", - "zone multiple-dspublished.checkds/IN (signed): checkds: " - "DS response from 10.53.0.4", - ) - keystate_check(parent, "multiple-dspublished.checkds.", "DSPublish") - + CheckDSTest( + zone="multiple-dspublished.checkds", + logs_to_wait_for=("DS response from 10.53.0.2", "DS response from 10.53.0.4"), + expected_parent_state="DSPublish", + ), # DS published in only one of multiple parents. - zone_check(server, "incomplete-dspublished.checkds.") - wait_for_log( - "ns9/named.run", - "zone incomplete-dspublished.checkds/IN (signed): checkds: " - "DS response from 10.53.0.2", - ) - wait_for_log( - "ns9/named.run", - "zone incomplete-dspublished.checkds/IN (signed): checkds: " - "DS response from 10.53.0.4", - ) - wait_for_log( - "ns9/named.run", - "zone incomplete-dspublished.checkds/IN (signed): checkds: " - "empty DS response from 10.53.0.5", - ) - keystate_check(parent, "incomplete-dspublished.checkds.", "!DSPublish") - + CheckDSTest( + zone="incomplete-dspublished.checkds", + logs_to_wait_for=( + "DS response from 10.53.0.2", + "DS response from 10.53.0.4", + "empty DS response from 10.53.0.5", + ), + expected_parent_state="!DSPublish", + ), # One of the parents is badly configured. - zone_check(server, "bad2-dswithdrawn.checkds.") - wait_for_log( - "ns9/named.run", - "zone bad2-dspublished.checkds/IN (signed): checkds: " - "DS response from 10.53.0.2", - ) - wait_for_log( - "ns9/named.run", - "zone bad2-dspublished.checkds/IN (signed): checkds: " - "DS response from 10.53.0.4", - ) - wait_for_log( - "ns9/named.run", - "zone bad2-dspublished.checkds/IN (signed): checkds: " - "bad DS response from 10.53.0.6", - ) - keystate_check(parent, "bad2-dspublished.checkds.", "!DSPublish") - + CheckDSTest( + zone="bad2-dspublished.checkds", + logs_to_wait_for=( + "DS response from 10.53.0.2", + "DS response from 10.53.0.4", + "bad DS response from 10.53.0.6", + ), + expected_parent_state="!DSPublish", + ), # Check with resolver parental-agent. - zone_check(server, "resolver-dspublished.checkds.") - wait_for_log( - "ns9/named.run", - "zone resolver-dspublished.checkds/IN (signed): checkds: " - "DS response from 10.53.0.3", - ) - keystate_check(parent, "resolver-dspublished.checkds.", "DSPublish") - + CheckDSTest( + zone="resolver-dspublished.checkds", + logs_to_wait_for=("DS response from 10.53.0.3",), + expected_parent_state="DSPublish", + ), # TBD: DS published in all parents, but one has bogus signature. - # TBD: Check with TSIG - # TBD: Check with TLS +] -def test_checkds_dswithdrawn(named_port): - # We create resolver instances that will be used to send queries. - server = dns.resolver.Resolver() - server.nameservers = ["10.53.0.9"] - server.port = named_port - - parent = dns.resolver.Resolver() - parent.nameservers = ["10.53.0.2"] - parent.port = named_port - +dswithdrawn_tests = [ # DS correctly published in single parent. - zone_check(server, "dswithdrawn.checkds.") - wait_for_log( - "ns9/named.run", - "zone dswithdrawn.checkds/IN (signed): checkds: " - "empty DS response from 10.53.0.5", - ) - keystate_check(parent, "dswithdrawn.checkds.", "DSRemoved") - + CheckDSTest( + zone="dswithdrawn.checkds", + logs_to_wait_for=("empty DS response from 10.53.0.5",), + expected_parent_state="DSRemoved", + ), # DS not withdrawn from parent. - zone_check(server, "missing-dswithdrawn.checkds.") - wait_for_log( - "ns9/named.run", - "zone missing-dswithdrawn.checkds/IN (signed): checkds: " - "DS response from 10.53.0.2", - ) - keystate_check(parent, "missing-dswithdrawn.checkds.", "!DSRemoved") - + CheckDSTest( + zone="missing-dswithdrawn.checkds", + logs_to_wait_for=("DS response from 10.53.0.2",), + expected_parent_state="!DSRemoved", + ), # Badly configured parent. - zone_check(server, "bad-dswithdrawn.checkds.") - wait_for_log( - "ns9/named.run", - "zone bad-dswithdrawn.checkds/IN (signed): checkds: " - "bad DS response from 10.53.0.6", - ) - keystate_check(parent, "bad-dswithdrawn.checkds.", "!DSRemoved") - + CheckDSTest( + zone="bad-dswithdrawn.checkds", + logs_to_wait_for=("bad DS response from 10.53.0.6",), + expected_parent_state="!DSRemoved", + ), # TBD: DS published in parent, but bogus signature. - # DS correctly withdrawn from all parents. - zone_check(server, "multiple-dswithdrawn.checkds.") - wait_for_log( - "ns9/named.run", - "zone multiple-dswithdrawn.checkds/IN (signed): checkds: " - "empty DS response from 10.53.0.5", - ) - wait_for_log( - "ns9/named.run", - "zone multiple-dswithdrawn.checkds/IN (signed): checkds: " - "empty DS response from 10.53.0.7", - ) - keystate_check(parent, "multiple-dswithdrawn.checkds.", "DSRemoved") - + CheckDSTest( + zone="multiple-dswithdrawn.checkds", + logs_to_wait_for=( + "empty DS response from 10.53.0.5", + "empty DS response from 10.53.0.7", + ), + expected_parent_state="DSRemoved", + ), # DS withdrawn from only one of multiple parents. - zone_check(server, "incomplete-dswithdrawn.checkds.") - wait_for_log( - "ns9/named.run", - "zone incomplete-dswithdrawn.checkds/IN (signed): checkds: " - "DS response from 10.53.0.2", - ) - wait_for_log( - "ns9/named.run", - "zone incomplete-dswithdrawn.checkds/IN (signed): checkds: " - "empty DS response from 10.53.0.5", - ) - wait_for_log( - "ns9/named.run", - "zone incomplete-dswithdrawn.checkds/IN (signed): checkds: " - "empty DS response from 10.53.0.7", - ) - keystate_check(parent, "incomplete-dswithdrawn.checkds.", "!DSRemoved") - + CheckDSTest( + zone="incomplete-dswithdrawn.checkds", + logs_to_wait_for=( + "DS response from 10.53.0.2", + "empty DS response from 10.53.0.5", + "empty DS response from 10.53.0.7", + ), + expected_parent_state="!DSRemoved", + ), # One of the parents is badly configured. - zone_check(server, "bad2-dswithdrawn.checkds.") - wait_for_log( - "ns9/named.run", - "zone bad2-dswithdrawn.checkds/IN (signed): checkds: " - "empty DS response from 10.53.0.5", - ) - wait_for_log( - "ns9/named.run", - "zone bad2-dswithdrawn.checkds/IN (signed): checkds: " - "empty DS response from 10.53.0.7", - ) - wait_for_log( - "ns9/named.run", - "zone bad2-dswithdrawn.checkds/IN (signed): checkds: " - "bad DS response from 10.53.0.6", - ) - keystate_check(parent, "bad2-dswithdrawn.checkds.", "!DSRemoved") - + CheckDSTest( + zone="bad2-dswithdrawn.checkds", + logs_to_wait_for=( + "empty DS response from 10.53.0.5", + "empty DS response from 10.53.0.7", + "bad DS response from 10.53.0.6", + ), + expected_parent_state="!DSRemoved", + ), # Check with resolver parental-agent. - zone_check(server, "resolver-dswithdrawn.checkds.") - wait_for_log( - "ns9/named.run", - "zone resolver-dswithdrawn.checkds/IN (signed): checkds: " - "empty DS response from 10.53.0.8", + CheckDSTest( + zone="resolver-dswithdrawn.checkds", + logs_to_wait_for=("empty DS response from 10.53.0.8",), + expected_parent_state="DSRemoved", ) - keystate_check(parent, "resolver-dswithdrawn.checkds.", "DSRemoved") - # TBD: DS withdrawn from all parents, but one has bogus signature. +] + + +checkds_tests = dspublished_tests + dswithdrawn_tests + + +@pytest.mark.parametrize("params", checkds_tests, ids=lambda t: t.zone) +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. + 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) + + # Check whether key states on the parent server provided match + # expectations. + keystate_check(servers["ns2"], params.zone, params.expected_parent_state) diff --git a/bin/tests/system/conftest.py b/bin/tests/system/conftest.py index 034b2c8e91..692743115c 100644 --- a/bin/tests/system/conftest.py +++ b/bin/tests/system/conftest.py @@ -22,9 +22,10 @@ from typing import Any, Dict, List, Optional import pytest - pytest.register_assert_rewrite("isctest") +import isctest + # Silence warnings caused by passing a pytest fixture to another fixture. # pylint: disable=redefined-outer-name @@ -648,3 +649,21 @@ def system_test( # pylint: disable=too-many-arguments,too-many-statements stop_servers() get_core_dumps() request.node.stash[FIXTURE_OK] = True + + +@pytest.fixture +def servers(ports, logger, system_test_dir): + instances = {} + for entry in system_test_dir.rglob("*"): + if entry.is_dir(): + try: + dir_name = entry.name + # LATER: Make ports fixture return NamedPorts directly + named_ports = isctest.instance.NamedPorts( + dns=int(ports["PORT"]), rndc=int(ports["CONTROLPORT"]) + ) + instance = isctest.instance.NamedInstance(dir_name, named_ports, logger) + instances[dir_name] = instance + except ValueError: + continue + return instances diff --git a/bin/tests/system/isctest/__init__.py b/bin/tests/system/isctest/__init__.py index 0f2eae1fb1..a55c128007 100644 --- a/bin/tests/system/isctest/__init__.py +++ b/bin/tests/system/isctest/__init__.py @@ -10,4 +10,7 @@ # information regarding copyright ownership. from . import check +from . import instance from . import query +from . import rndc +from . import watchlog diff --git a/bin/tests/system/isctest/instance.py b/bin/tests/system/isctest/instance.py new file mode 100644 index 0000000000..fdac94c7d2 --- /dev/null +++ b/bin/tests/system/isctest/instance.py @@ -0,0 +1,168 @@ +#!/usr/bin/python3 + +# 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. + +from typing import NamedTuple, Optional + +import logging +import os +import re + +from .rndc import RNDCBinaryExecutor, RNDCException, RNDCExecutor +from .watchlog import WatchLogFromStart, WatchLogFromHere + + +class NamedPorts(NamedTuple): + dns: int = 53 + rndc: int = 953 + + +class NamedInstance: + + """ + A class representing a `named` instance used in a system test. + + This class is expected to be instantiated as part of the `servers` fixture: + + ```python + def test_foo(servers): + servers["ns1"].rndc("status") + ``` + """ + + # pylint: disable=too-many-arguments + def __init__( + self, + identifier: str, + ports: NamedPorts = NamedPorts(), + rndc_logger: Optional[logging.Logger] = None, + rndc_executor: Optional[RNDCExecutor] = None, + ) -> None: + """ + `identifier` must be an `ns` string, where `` is an integer + identifier of the `named` instance this object should represent. + + `ports` is the `NamedPorts` instance listing the UDP/TCP ports on which + this `named` instance is listening for various types of traffic (both + DNS traffic and RNDC commands). + + `rndc_logger` is the `logging.Logger` to use for logging RNDC + commands sent to this `named` instance. + + `rndc_executor` is an object implementing the `RNDCExecutor` interface + that is used for executing RNDC commands on this `named` instance. + """ + self.ip = self._identifier_to_ip(identifier) + self.ports = ports + self._log_file = os.path.join(identifier, "named.run") + self._rndc_executor = rndc_executor or RNDCBinaryExecutor() + self._rndc_logger = rndc_logger or logging.getLogger() + + @staticmethod + def _identifier_to_ip(identifier: str) -> str: + regex_match = re.match(r"^ns(?P[0-9]{1,2})$", identifier) + if not regex_match: + raise ValueError("Invalid named instance identifier" + identifier) + return "10.53.0." + regex_match.group("index") + + def rndc(self, command: str, ignore_errors: bool = False, log: bool = True) -> str: + """ + Send `command` to this named instance using RNDC. Return the server's + response. + + If the RNDC command fails, an `RNDCException` is raised unless + `ignore_errors` is set to `True`. + + The RNDC command will be logged to `rndc.log` (along with the server's + response) unless `log` is set to `False`. + + >>> # Instances of the `NamedInstance` class are expected to be passed + >>> # to pytest tests as fixtures; here, some instances are created + >>> # directly (with a fake RNDC executor) so that doctest can work. + >>> import unittest.mock + >>> mock_rndc_executor = unittest.mock.Mock() + >>> ns1 = NamedInstance("ns1", rndc_executor=mock_rndc_executor) + >>> ns2 = NamedInstance("ns2", rndc_executor=mock_rndc_executor) + >>> ns3 = NamedInstance("ns3", rndc_executor=mock_rndc_executor) + >>> ns4 = NamedInstance("ns4", rndc_executor=mock_rndc_executor) + + >>> # Send the "status" command to ns1. An `RNDCException` will be + >>> # raised if the RNDC command fails. This command will be logged. + >>> response = ns1.rndc("status") + + >>> # Send the "thaw foo" command to ns2. No exception will be raised + >>> # in case the RNDC command fails. This command will be logged + >>> # (even if it fails). + >>> response = ns2.rndc("thaw foo", ignore_errors=True) + + >>> # Send the "stop" command to ns3. An `RNDCException` will be + >>> # raised if the RNDC command fails, but this command will not be + >>> # logged (the server's response will still be returned to the + >>> # caller, though). + >>> response = ns3.rndc("stop", log=False) + + >>> # Send the "halt" command to ns4 in "fire & forget mode": no + >>> # exceptions will be raised and no logging will take place (the + >>> # server's response will still be returned to the caller, though). + >>> response = ns4.rndc("stop", ignore_errors=True, log=False) + """ + try: + response = self._rndc_executor.call(self.ip, self.ports.rndc, command) + if log: + self._rndc_log(command, response) + except RNDCException as exc: + response = str(exc) + if log: + self._rndc_log(command, response) + if not ignore_errors: + raise + + return response + + def watch_log_from_start(self) -> WatchLogFromStart: + """ + Return an instance of the `WatchLogFromStart` context manager for this + `named` instance's log file. + """ + return WatchLogFromStart(self._log_file) + + 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) + + def reconfigure(self) -> None: + """ + Reconfigure this named `instance` and wait until reconfiguration is + finished. Raise an `RNDCException` if reconfiguration fails. + """ + with self.watch_log_from_here() as watcher: + self.rndc("reconfig") + watcher.wait_for_line("any newly configured zones are now loaded") + + def _rndc_log(self, command: str, response: str) -> None: + """ + Log an `rndc` invocation (and its output) to the `rndc.log` file in the + current working directory. + """ + fmt = '%(ip)s: "%(command)s"\n%(separator)s\n%(response)s%(separator)s' + self._rndc_logger.info( + fmt, + { + "ip": self.ip, + "command": command, + "separator": "-" * 80, + "response": response, + }, + ) diff --git a/bin/tests/system/isctest/rndc.py b/bin/tests/system/isctest/rndc.py new file mode 100644 index 0000000000..3accc369dc --- /dev/null +++ b/bin/tests/system/isctest/rndc.py @@ -0,0 +1,72 @@ +# 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 abc +import os +import subprocess + + +# pylint: disable=too-few-public-methods +class RNDCExecutor(abc.ABC): + + """ + An interface which RNDC executors have to implement in order for the + `NamedInstance` class to be able to use them. + """ + + @abc.abstractmethod + def call(self, ip: str, port: int, command: str) -> str: + """ + Send RNDC `command` to the `named` instance at `ip:port` and return the + server's response. + """ + + +class RNDCException(Exception): + """ + Raised by classes implementing the `RNDCExecutor` interface when sending an + RNDC command fails for any reason. + """ + + +class RNDCBinaryExecutor(RNDCExecutor): + + """ + An `RNDCExecutor` which sends RNDC commands to servers using the `rndc` + binary. + """ + + def __init__(self) -> None: + """ + This class needs the `RNDC` environment variable to be set to the path + to the `rndc` binary to use. + """ + rndc_path = os.environ.get("RNDC", "/bin/false") + rndc_conf = os.path.join("..", "_common", "rndc.conf") + self._base_cmdline = [rndc_path, "-c", rndc_conf] + + def call(self, ip: str, port: int, command: str) -> str: + """ + Send RNDC `command` to the `named` instance at `ip:port` and return the + server's response. + """ + cmdline = self._base_cmdline[:] + cmdline.extend(["-s", ip]) + cmdline.extend(["-p", str(port)]) + cmdline.extend(command.split()) + + try: + return subprocess.check_output( + cmdline, stderr=subprocess.STDOUT, timeout=10, encoding="utf-8" + ) + except subprocess.SubprocessError as exc: + msg = getattr(exc, "output", "RNDC exception occurred") + raise RNDCException(msg) from exc diff --git a/bin/tests/system/isctest/watchlog.py b/bin/tests/system/isctest/watchlog.py new file mode 100644 index 0000000000..1456c535c9 --- /dev/null +++ b/bin/tests/system/isctest/watchlog.py @@ -0,0 +1,335 @@ +# 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. + +from typing import Optional, TextIO, Dict, Any, overload, List, Union + +import abc +import os +import shlex +import subprocess +import time + + +class WatchLogException(Exception): + pass + + +class WatchLog(abc.ABC): + + """ + Wait for a log message to appear in a text file. + + This class should not be used directly; instead, its subclasses, + `WatchLogFromStart` and `WatchLogFromHere`, should be used. For `named` + instances used in system tests, it is recommended to use the + `watch_log_from_start()` and `watch_log_from_here()` helper methods exposed + by the `NamedInstance` class (see below for recommended usage patterns). + """ + + def __init__(self, path: str) -> None: + """ + `path` is the path to the log file to watch. + + Every instance of this class must call one of the `wait_for_*()` + methods exactly once or else an `Exception` is thrown. + + >>> with WatchLogFromStart("/dev/null") as watcher: + ... print("Just print something without waiting for a log line") + Traceback (most recent call last): + ... + Exception: wait_for_*() was not called + + >>> with WatchLogFromHere("/dev/null") as watcher: + ... try: + ... watcher.wait_for_line("foo", timeout=0) + ... except TimeoutError: + ... pass + ... try: + ... watcher.wait_for_lines({"bar": 42}, timeout=0) + ... except TimeoutError: + ... pass + Traceback (most recent call last): + ... + Exception: wait_for_*() was already called + """ + self._fd = None # type: Optional[TextIO] + self._path = path + self._wait_function_called = False + + def wait_for_line(self, string: str, timeout: int = 10) -> None: + """ + Block execution until a line containing the provided `string` appears + in the log file. Return `None` once the line is found or raise a + `TimeoutError` after `timeout` seconds (default: 10) if `string` does + not appear in the log file. (Catching this exception is discouraged as + it indicates that the test code did not behave as expected.) + + Recommended use: + + ```python + import isctest + + def test_foo(servers): + with servers["ns1"].watch_log_from_here() as watcher: + # ... do stuff here ... + watcher.wait_for_line("foo bar") + ``` + + One of `wait_for_line()` or `wait_for_lines()` must be called exactly + once for every `WatchLogFrom*` instance. + + >>> # For `WatchLogFromStart`, `wait_for_line()` returns without + >>> # raising an exception as soon as the line being looked for appears + >>> # anywhere in the file, no matter whether that happens before of + >>> # after the `with` statement is reached. + >>> import tempfile + >>> with tempfile.NamedTemporaryFile("w") as file: + ... print("foo", file=file, flush=True) + ... with WatchLogFromStart(file.name) as watcher: + ... retval = watcher.wait_for_line("foo", timeout=1) + >>> print(retval) + None + >>> with tempfile.NamedTemporaryFile("w") as file: + ... with WatchLogFromStart(file.name) as watcher: + ... print("foo", file=file, flush=True) + ... retval = watcher.wait_for_line("foo", timeout=1) + >>> print(retval) + None + + >>> # For `WatchLogFromHere`, `wait_for_line()` only returns without + >>> # raising an exception if the string being looked for appears in + >>> # the log file after the `with` statement is reached. + >>> import tempfile + >>> with tempfile.NamedTemporaryFile("w") as file: + ... print("foo", file=file, flush=True) + ... with WatchLogFromHere(file.name) as watcher: + ... watcher.wait_for_line("foo", timeout=1) #doctest: +ELLIPSIS + Traceback (most recent call last): + ... + TimeoutError: Timeout reached watching ... + >>> with tempfile.NamedTemporaryFile("w") as file: + ... print("foo", file=file, flush=True) + ... with WatchLogFromHere(file.name) as watcher: + ... print("foo", file=file, flush=True) + ... retval = watcher.wait_for_line("foo", timeout=1) + >>> print(retval) + None + """ + return self._wait_for({string: None}, timeout) + + def wait_for_lines(self, strings: Dict[str, Any], timeout: int = 10) -> None: + """ + Block execution until a line of interest appears in the log file. This + function is a "multi-match" variant of `wait_for_line()` which is + useful when some action may cause several different (mutually + exclusive) messages to appear in the log file. + + `strings` is a `dict` associating each string to look for with the + value this function should return when that string is found in the log + file. If none of the `strings` being looked for appear in the log file + after `timeout` seconds, a `TimeoutError` is raised. + (Catching this exception is discouraged as it indicates that the test + code did not behave as expected.) + + Since `strings` is a `dict` and preserves key order (in CPython 3.6 as + implementation detail, since 3.7 by language design), each line is + checked against each key in order until the first match. Values provided + in the `strings` dictionary (i.e. values which this function is expected + to return upon a successful match) can be of any type. + + Recommended use: + + ```python + import isctest + + def test_foo(servers): + triggers = { + "message A": "value returned when message A is found", + "message B": "value returned when message B is found", + } + with servers["ns1"].watch_log_from_here() as watcher: + # ... do stuff here ... + retval = watcher.wait_for_lines(triggers) + ``` + + One of `wait_for_line()` or `wait_for_lines()` must be called exactly + once for every `WatchLogFromHere` instance. + + >>> # Different values must be returned depending on which line is + >>> # found in the log file. + >>> import tempfile + >>> triggers = {"foo": 42, "bar": 1337} + >>> with tempfile.NamedTemporaryFile("w") as file: + ... print("foo", file=file, flush=True) + ... with WatchLogFromStart(file.name) as watcher: + ... retval1 = watcher.wait_for_lines(triggers, timeout=1) + ... with WatchLogFromHere(file.name) as watcher: + ... print("bar", file=file, flush=True) + ... retval2 = watcher.wait_for_lines(triggers, timeout=1) + >>> print(retval1) + 42 + >>> print(retval2) + 1337 + """ + return self._wait_for(strings, timeout) + + def _wait_for(self, strings: Dict[str, Any], timeout: int) -> Any: + """ + Block execution until one of the `strings` being looked for appears in + the log file. Raise a `TimeoutError` if none of the `strings` being + looked for are found in the log file for `timeout` seconds. + """ + if self._wait_function_called: + raise WatchLogException("wait_for_*() was already called") + self._wait_function_called = True + if not self._fd: + raise WatchLogException("No file to watch") + leftover = "" + deadline = time.time() + timeout + while time.time() < deadline: + for line in self._fd.readlines(): + if line[-1] != "\n": + # Line is not completely written yet, buffer and keep on waiting + leftover += line + else: + line = leftover + line + leftover = "" + for string, retval in strings.items(): + if string in line: + return retval + time.sleep(0.1) + raise TimeoutError( + "Timeout reached watching {} for {}".format( + self._path, list(strings.keys()) + ) + ) + + def __enter__(self) -> Any: + self._fd = open(self._path, encoding="utf-8") + self._seek_on_enter() + return self + + @abc.abstractmethod + def _seek_on_enter(self) -> None: + """ + This method is responsible for setting the file position indicator for + the file being watched when execution reaches the __enter__() method. + It is expected to be set differently depending on which `WatchLog` + subclass is used. Since the base `WatchLog` class should not be used + directly, raise an exception upon any attempt of such use. + """ + raise NotImplementedError + + def __exit__(self, *_: Any) -> None: + if not self._wait_function_called: + raise WatchLogException("wait_for_*() was not called") + if self._fd: + self._fd.close() + + +class WatchLogFromStart(WatchLog): + """ + A `WatchLog` subclass which looks for the provided string(s) in the entire + log file. + """ + + def _seek_on_enter(self) -> None: + pass + + +class WatchLogFromHere(WatchLog): + """ + A `WatchLog` subclass which only looks for the provided string(s) in the + portion of the log file which is appended to it after the `with` statement + is reached. + """ + + def _seek_on_enter(self) -> None: + if self._fd: + self._fd.seek(0, os.SEEK_END) + + +# pylint: disable=too-few-public-methods +class RNDCExecutor(abc.ABC): + + """ + An interface which RNDC executors have to implement in order for the + `NamedInstance` class to be able to use them. + """ + + @overload + def call(self, ip: str, port: int, command: str, timeout: int = 10) -> str: + ... + + @overload + def call(self, ip: str, port: int, command: List[str], timeout: int = 10) -> str: + ... + + @abc.abstractmethod + def call( + self, ip: str, port: int, command: Union[str, List[str]], timeout: int = 10 + ) -> str: + """ + Send RNDC `command` to the `named` instance at `ip:port` and return the + server's response. + """ + + +class RNDCException(Exception): + """ + Raised by classes implementing the `RNDCExecutor` interface when sending an + RNDC command fails for any reason. + """ + + +class RNDCBinaryExecutor(RNDCExecutor): + + """ + An `RNDCExecutor` which sends RNDC commands to servers using the `rndc` + binary. + """ + + def __init__(self) -> None: + """ + This class needs the `RNDC` environment variable to be set to the path + to the `rndc` binary to use. + """ + rndc_path = os.environ.get("RNDC", "/bin/false") + rndc_conf = os.path.join("..", "_common", "rndc.conf") + self._base_cmdline = [rndc_path, "-c", rndc_conf] + + @overload + def call(self, ip: str, port: int, command: str, timeout: int = 10) -> str: + ... + + @overload + def call(self, ip: str, port: int, command: List[str], timeout: int = 10) -> str: + ... + + def call( + self, ip: str, port: int, command: Union[str, List[str]], timeout: int = 10 + ) -> str: + """ + Send RNDC `command` to the `named` instance at `ip:port` and return the + server's response. + """ + cmdline = self._base_cmdline[:] + cmdline.extend(["-s", ip]) + cmdline.extend(["-p", str(port)]) + cmdline.extend(shlex.split(command) if isinstance(command, str) else command) + + try: + return subprocess.check_output( + cmdline, stderr=subprocess.STDOUT, timeout=timeout, encoding="utf-8" + ) + except subprocess.SubprocessError as exc: + msg = getattr(exc, "output", "RNDC exception occurred") + raise RNDCException(msg) from exc diff --git a/bin/tests/system/shutdown/tests_shutdown.py b/bin/tests/system/shutdown/tests_shutdown.py index 19f853bc32..4769c1ce9e 100755 --- a/bin/tests/system/shutdown/tests_shutdown.py +++ b/bin/tests/system/shutdown/tests_shutdown.py @@ -25,8 +25,10 @@ pytest.importorskip("dns", minversion="2.0.0") import dns.exception import dns.resolver +import isctest -def do_work(named_proc, resolver, rndc_cmd, kill_method, n_workers, n_queries): + +def do_work(named_proc, resolver, instance, kill_method, n_workers, n_queries): """Creates a number of A queries to run in parallel in order simulate a slightly more realistic test scenario. @@ -48,8 +50,8 @@ def do_work(named_proc, resolver, rndc_cmd, kill_method, n_workers, n_queries): :param resolver: target resolver :type resolver: dns.resolver.Resolver - :param rndc_cmd: rndc command with default arguments - :type rndc_cmd: list of strings, e.g. ["rndc", "-p", "23750"] + :param instance: the named instance to send RNDC commands to + :type instance: isctest.instance.NamedInstance :kill_method: "rndc" or "sigterm" :type kill_method: str @@ -63,9 +65,13 @@ def do_work(named_proc, resolver, rndc_cmd, kill_method, n_workers, n_queries): # pylint: disable-msg=too-many-arguments # pylint: disable-msg=too-many-locals - # helper function, args must be a list or tuple with arguments to rndc. - def launch_rndc(args): - return subprocess.call(rndc_cmd + args, timeout=10) + # helper function, 'command' is the rndc command to run + def launch_rndc(command): + try: + instance.rndc(command, log=False) + return 0 + except isctest.rndc.RNDCException: + return -1 # We're going to execute queries in parallel by means of a thread pool. # dnspython functions block, so we need to circunvent that. @@ -99,13 +105,13 @@ def do_work(named_proc, resolver, rndc_cmd, kill_method, n_workers, n_queries): elif shutdown: # We attempt to stop named in the middle shutdown = False if kill_method == "rndc": - futures[executor.submit(launch_rndc, ["stop"])] = "stop" + futures[executor.submit(launch_rndc, "stop")] = "stop" else: futures[executor.submit(named_proc.terminate)] = "kill" else: # We attempt to send couple rndc commands while named is # being shutdown - futures[executor.submit(launch_rndc, ["status"])] = "status" + futures[executor.submit(launch_rndc, "-t 5 status")] = "status" ret_code = -1 for future in as_completed(futures): @@ -160,8 +166,11 @@ def wait_for_proc_termination(proc, max_timeout=10): # Method 1: using rndc ctop # Method 2: killing with SIGTERM # In both methods named should exit gracefully. -@pytest.mark.parametrize("kill_method", ["rndc", "sigterm"]) -def test_named_shutdown(named_port, control_port, kill_method): +@pytest.mark.parametrize( + "kill_method", + [pytest.param("rndc", marks=pytest.mark.xfail(reason="GL#4060")), "sigterm"], +) +def test_named_shutdown(ports, kill_method): # pylint: disable-msg=too-many-locals cfg_dir = os.path.join(os.getcwd(), "resolver") assert os.path.isdir(cfg_dir) @@ -172,20 +181,20 @@ def test_named_shutdown(named_port, control_port, kill_method): named = os.getenv("NAMED") assert named is not None - rndc = os.getenv("RNDC") - assert rndc is not None - - # rndc configuration resides in ../_common/rndc.conf - rndc_cfg = os.path.join("..", "_common", "rndc.conf") - assert os.path.isfile(rndc_cfg) - - # rndc command with default arguments. - rndc_cmd = [rndc, "-c", rndc_cfg, "-p", str(control_port), "-s", "10.53.0.3"] + # This test launches and monitors a named instance itself rather than using + # bin/tests/system/start.pl, so manually defining a NamedInstance here is + # necessary for sending RNDC commands to that instance. This "custom" + # instance listens on 10.53.0.3, so use "ns3" as the identifier passed to + # the NamedInstance constructor. + named_ports = isctest.instance.NamedPorts( + dns=ports["PORT"], rndc=ports["CONTROLPORT"] + ) + instance = isctest.instance.NamedInstance("ns3", named_ports) # We create a resolver instance that will be used to send queries. resolver = dns.resolver.Resolver() resolver.nameservers = ["10.53.0.3"] - resolver.port = named_port + resolver.port = named_ports.dns named_cmdline = [named, "-c", cfg_file, "-f"] with subprocess.Popen(named_cmdline, cwd=cfg_dir) as named_proc: @@ -195,7 +204,7 @@ def test_named_shutdown(named_port, control_port, kill_method): do_work( named_proc, resolver, - rndc_cmd, + instance, kill_method, n_workers=12, n_queries=16,