diff --git a/bin/tests/system/checkds/tests_checkds.py b/bin/tests/system/checkds/tests_checkds.py index 7fed526907..163c4cc150 100755 --- a/bin/tests/system/checkds/tests_checkds.py +++ b/bin/tests/system/checkds/tests_checkds.py @@ -73,9 +73,9 @@ def has_signed_apex_nsec(zone, response): has_rrsig = True if not has_nsec: - print("error: missing apex NSEC record in response") + isctest.log.error("missing apex NSEC record in response") if not has_rrsig: - print("error: missing NSEC signature in response") + isctest.log.error("missing NSEC signature in response") return has_nsec and has_rrsig @@ -103,8 +103,7 @@ def verify_zone(zone, transfer): verifier = isctest.run.cmd(verify_cmd) if verifier.returncode != 0: - print(f"error: dnssec-verify {zone} failed") - sys.stderr.buffer.write(verifier.stderr) + isctest.log.error(f"dnssec-verify {zone} failed") return verifier.returncode == 0 @@ -132,7 +131,7 @@ def read_statefile(server, zone): ), f"expected a single DS in response for {zone} from {server.ip}, got {count}" filename = f"ns9/K{zone}+013+{keyid:05d}.state" - print(f"read state file {filename}") + isctest.log.debug(f"read state file {filename}") try: with open(filename, "r", encoding="utf-8") as file: @@ -212,8 +211,7 @@ def rekey(zone): controller = isctest.run.cmd(rndc_cmd) if controller.returncode != 0: - print(f"error: rndc loadkeys {zone} failed") - sys.stderr.buffer.write(controller.stderr) + isctest.log.error(f"rndc loadkeys {zone} failed") assert controller.returncode == 0 diff --git a/bin/tests/system/conftest.py b/bin/tests/system/conftest.py index a68e4f65c3..7f3c0eb0fb 100644 --- a/bin/tests/system/conftest.py +++ b/bin/tests/system/conftest.py @@ -360,12 +360,13 @@ def system_test_dir(request, system_test_name, expected_artifacts): if node.nodeid in all_test_results } assert len(test_results) - messages = [] for node, result in test_results.items(): - isctest.log.debug("%s %s", result.outcome.upper(), node) - messages.extend(result.messages.values()) - for message in messages: - isctest.log.debug("\n" + message) + message = f"{result.outcome.upper()} {node}" + nonempty_extra = [msg for msg in result.messages.values() if msg.strip()] + if nonempty_extra: + message += "\n" + message += "\n\n".join(nonempty_extra) + isctest.log.debug(message) failed = any(res.outcome == "failed" for res in test_results.values()) skipped = any(res.outcome == "skipped" for res in test_results.values()) if failed: diff --git a/bin/tests/system/dnstap/tests_dnstap.py b/bin/tests/system/dnstap/tests_dnstap.py index 258d2b5f89..e804eaa9ff 100644 --- a/bin/tests/system/dnstap/tests_dnstap.py +++ b/bin/tests/system/dnstap/tests_dnstap.py @@ -44,7 +44,7 @@ def run_rndc(server, rndc_command): cmdline = [rndc, "-c", "../_common/rndc.conf", "-p", port, "-s", server] cmdline.extend(rndc_command) - isctest.run.cmd(cmdline, log_stdout=True) + isctest.run.cmd(cmdline) def test_dnstap_dispatch_socket_addresses(): @@ -64,7 +64,6 @@ def test_dnstap_dispatch_socket_addresses(): # Read the contents of the dnstap file using dnstap-read. run = isctest.run.cmd( [isctest.vars.ALL["DNSTAPREAD"], "dnstap.out.resolver_addresses"], - log_stdout=True, ) # Check whether all frames contain the expected addresses. diff --git a/bin/tests/system/isctest/kasp.py b/bin/tests/system/isctest/kasp.py index 501bd5f4a4..5705d5063c 100644 --- a/bin/tests/system/isctest/kasp.py +++ b/bin/tests/system/isctest/kasp.py @@ -451,7 +451,7 @@ class Key: str(self.keyfile), ] - out = isctest.run.cmd(dsfromkey_command, log_stdout=True) + out = isctest.run.cmd(dsfromkey_command) dsfromkey = out.stdout.decode("utf-8").split() rdata_fromfile = " ".join(dsfromkey[:7]) diff --git a/bin/tests/system/isctest/log/basic.py b/bin/tests/system/isctest/log/basic.py index 67121d2e24..3474f1b443 100644 --- a/bin/tests/system/isctest/log/basic.py +++ b/bin/tests/system/isctest/log/basic.py @@ -11,10 +11,12 @@ import logging from pathlib import Path +import textwrap from typing import Dict, Optional LOG_FORMAT = "%(asctime)s %(levelname)7s:%(name)s %(message)s" +LOG_INDENT = 4 LOGGERS = { "conftest": None, @@ -77,6 +79,13 @@ def deinit_test_logger(): LOGGERS["test"] = None +def indent_message(msg): + lines = msg.splitlines() + first = lines[0] + "\n" + to_indent = "\n".join(lines[1:]) + return first + textwrap.indent(to_indent, " " * LOG_INDENT) + + def log(lvl: int, msg: str, *args, **kwargs): """Log message with the most-specific logger currently available.""" logger = LOGGERS["test"] @@ -85,6 +94,8 @@ def log(lvl: int, msg: str, *args, **kwargs): if logger is None: logger = LOGGERS["conftest"] assert logger is not None + if "\n" in msg: + msg = indent_message(msg) logger.log(lvl, msg, *args, **kwargs) diff --git a/bin/tests/system/isctest/query.py b/bin/tests/system/isctest/query.py index 6e84c8188d..6e7bee285e 100644 --- a/bin/tests/system/isctest/query.py +++ b/bin/tests/system/isctest/query.py @@ -32,6 +32,8 @@ def generic_query( attempts: int = 10, expected_rcode: dns_rcode = None, verify: bool = False, + log_query: bool = True, + log_response: bool = True, ) -> Any: if port is None: if query_func.__name__ == "tls": @@ -51,15 +53,25 @@ def generic_query( res = None for attempt in range(attempts): - isctest.log.debug( - f"{query_func.__name__}(): ip={ip}, port={port}, source={source}, " + log_msg = ( + f"isc.query.{query_func.__name__}(): ip={ip}, port={port}, source={source}, " f"timeout={timeout}, attempts left={attempts-attempt}" ) + if log_query: + log_msg += f"\n{message.to_text()}" + log_query = False # only log query on first attempt + isctest.log.debug(log_msg) try: res = query_func(**query_args) except (dns.exception.Timeout, ConnectionRefusedError) as e: - isctest.log.debug(f"{query_func.__name__}(): the '{e}' exception raised") + isctest.log.debug( + f"isc.query.{query_func.__name__}(): the '{e}' exception raised" + ) else: + if log_response: + isctest.log.debug( + f"isc.query.{query_func.__name__}(): response\n{res.to_text()}" + ) if res.rcode() == expected_rcode or expected_rcode is None: return res time.sleep(1) @@ -67,7 +79,7 @@ def generic_query( if expected_rcode is not None: last_rcode = dns_rcode.to_text(res.rcode()) if res else None isctest.log.debug( - f"{query_func.__name__}(): expected rcode={dns_rcode.to_text(expected_rcode)}, last rcode={last_rcode}" + f"isc.query.{query_func.__name__}(): expected rcode={dns_rcode.to_text(expected_rcode)}, last rcode={last_rcode}" ) raise dns.exception.Timeout diff --git a/bin/tests/system/isctest/run.py b/bin/tests/system/isctest/run.py index 5c994ce377..e4fbd459dd 100644 --- a/bin/tests/system/isctest/run.py +++ b/bin/tests/system/isctest/run.py @@ -24,24 +24,24 @@ def cmd( timeout=60, stdout=subprocess.PIPE, stderr=subprocess.PIPE, - log_stdout=False, + log_stdout=True, log_stderr=True, input_text: Optional[bytes] = None, raise_on_exception=True, env: Optional[dict] = None, ): """Execute a command with given args as subprocess.""" - isctest.log.debug(f"command: {' '.join(args)}") + isctest.log.debug(f"isctest.run.cmd(): {' '.join(args)}") def print_debug_logs(procdata): if procdata: if log_stdout and procdata.stdout: isctest.log.debug( - f"~~~ cmd stdout ~~~\n{procdata.stdout.decode('utf-8')}\n~~~~~~~~~~~~~~~~~~" + f"isctest.run.cmd(): (stdout)\n{procdata.stdout.decode('utf-8')}" ) if log_stderr and procdata.stderr: isctest.log.debug( - f"~~~ cmd stderr ~~~\n{procdata.stderr.decode('utf-8')}\n~~~~~~~~~~~~~~~~~~" + f"isctest.run.cmd(): (stderr)\n{procdata.stderr.decode('utf-8')}" ) if env is None: @@ -62,7 +62,7 @@ def cmd( return proc except subprocess.CalledProcessError as exc: print_debug_logs(exc) - isctest.log.debug(f" return code: {exc.returncode}") + isctest.log.debug(f"isctest.run.cmd(): (return code) {exc.returncode}") if raise_on_exception: raise exc return exc @@ -111,7 +111,6 @@ class Dig: """Run the dig command with the given parameters and return the decoded output.""" return cmd( [os.environ.get("DIG")] + f"{self.base_params} {params}".split(), - log_stdout=True, ).stdout.decode("utf-8") diff --git a/bin/tests/system/kasp/tests_kasp.py b/bin/tests/system/kasp/tests_kasp.py index 2440914995..9ffd70b87c 100644 --- a/bin/tests/system/kasp/tests_kasp.py +++ b/bin/tests/system/kasp/tests_kasp.py @@ -1258,7 +1258,7 @@ def test_kasp_dnssec_keygen(): zone, ] - return isctest.run.cmd(keygen_command, log_stdout=True).stdout.decode("utf-8") + return isctest.run.cmd(keygen_command).stdout.decode("utf-8") # check that 'dnssec-keygen -k' (configured policy) creates valid files. keyprops = [ @@ -1294,7 +1294,7 @@ def test_kasp_dnssec_keygen(): str(publish), key.path, ] - out = isctest.run.cmd(settime, log_stdout=True).stdout.decode("utf-8") + out = isctest.run.cmd(settime).stdout.decode("utf-8") isctest.check.file_contents_equal(f"{key.statefile}", f"{key.statefile}.backup") assert key.get_metadata("Publish", file=key.privatefile) == str(publish) @@ -1343,7 +1343,7 @@ def test_kasp_dnssec_keygen(): str(now), key.path, ] - out = isctest.run.cmd(settime, log_stdout=True).stdout.decode("utf-8") + out = isctest.run.cmd(settime).stdout.decode("utf-8") isctest.kasp.check_keys("kasp", keys, expected) isctest.kasp.check_keytimes(keys, expected) @@ -1378,7 +1378,7 @@ def test_kasp_dnssec_keygen(): str(now), key.path, ] - out = isctest.run.cmd(settime, log_stdout=True).stdout.decode("utf-8") + out = isctest.run.cmd(settime).stdout.decode("utf-8") isctest.kasp.check_keys("kasp", keys, expected) isctest.kasp.check_keytimes(keys, expected) @@ -1423,7 +1423,7 @@ def test_kasp_dnssec_keygen(): str(soon), key.path, ] - out = isctest.run.cmd(settime, log_stdout=True).stdout.decode("utf-8") + out = isctest.run.cmd(settime).stdout.decode("utf-8") isctest.kasp.check_keys("kasp", keys, expected) isctest.kasp.check_keytimes(keys, expected) diff --git a/bin/tests/system/keyfromlabel/tests_keyfromlabel.py b/bin/tests/system/keyfromlabel/tests_keyfromlabel.py index 428717d5a2..1f4ab8009e 100644 --- a/bin/tests/system/keyfromlabel/tests_keyfromlabel.py +++ b/bin/tests/system/keyfromlabel/tests_keyfromlabel.py @@ -70,13 +70,12 @@ def token_init_and_cleanup(): isctest.run.cmd( token_cleanup_command, env=EMPTY_OPENSSL_CONF_ENV, - log_stdout=True, raise_on_exception=False, ) try: output = isctest.run.cmd( - token_init_command, env=EMPTY_OPENSSL_CONF_ENV, log_stdout=True + token_init_command, env=EMPTY_OPENSSL_CONF_ENV ).stdout.decode("utf-8") assert "The token has been initialized and is reassigned to slot" in output yield @@ -84,7 +83,6 @@ def token_init_and_cleanup(): output = isctest.run.cmd( token_cleanup_command, env=EMPTY_OPENSSL_CONF_ENV, - log_stdout=True, raise_on_exception=False, ).stdout.decode("utf-8") assert re.search("Found token (.*) with matching token label", output) @@ -129,7 +127,7 @@ def test_keyfromlabel(alg_name, alg_type, alg_bits): ] output = isctest.run.cmd( - pkcs11_command, env=EMPTY_OPENSSL_CONF_ENV, log_stdout=True + pkcs11_command, env=EMPTY_OPENSSL_CONF_ENV ).stdout.decode("utf-8") assert "Key pair generated" in output @@ -148,7 +146,7 @@ def test_keyfromlabel(alg_name, alg_type, alg_bits): zone, ] - output = isctest.run.cmd(keyfrlab_command, log_stdout=True) + output = isctest.run.cmd(keyfrlab_command) output_decoded = output.stdout.decode("utf-8").rstrip() + ".key" assert os.path.exists(output_decoded) @@ -188,6 +186,6 @@ def test_keyfromlabel(alg_name, alg_type, alg_bits): zone, zone_file, ] - isctest.run.cmd(signer_command, log_stdout=True) + isctest.run.cmd(signer_command) assert os.path.exists(f"{zone_file}.signed") diff --git a/bin/tests/system/ksr/tests_ksr.py b/bin/tests/system/ksr/tests_ksr.py index a5aefa0b21..12b4a6e487 100644 --- a/bin/tests/system/ksr/tests_ksr.py +++ b/bin/tests/system/ksr/tests_ksr.py @@ -96,9 +96,7 @@ def ksr(zone, policy, action, options="", raise_on_exception=True): zone, ] - out = isctest.run.cmd( - ksr_command, log_stdout=True, raise_on_exception=raise_on_exception - ) + out = isctest.run.cmd(ksr_command, raise_on_exception=raise_on_exception) return out.stdout.decode("utf-8"), out.stderr.decode("utf-8") diff --git a/bin/tests/system/limits/tests_limits.py b/bin/tests/system/limits/tests_limits.py index 7d6636178c..1fe5ea0087 100644 --- a/bin/tests/system/limits/tests_limits.py +++ b/bin/tests/system/limits/tests_limits.py @@ -33,7 +33,7 @@ pytest.importorskip("dns", minversion="2.0.0") ) def test_limits(name, limit): msg_query = dns.message.make_query(f"{name}.example.", "A") - res = isctest.query.tcp(msg_query, "10.53.0.1") + res = isctest.query.tcp(msg_query, "10.53.0.1", log_response=False) iplist = [ f"10.0.{x}.{y}" @@ -47,6 +47,6 @@ def test_limits(name, limit): def test_limit_exceeded(): msg_query = dns.message.make_query("5000.example.", "A") - res = isctest.query.tcp(msg_query, "10.53.0.1") + res = isctest.query.tcp(msg_query, "10.53.0.1", log_response=False) assert res.flags & dns.flags.TC, "TC flag was not set" diff --git a/bin/tests/system/rollover/tests_rollover.py b/bin/tests/system/rollover/tests_rollover.py index f30eb2fad9..c42f3ef065 100644 --- a/bin/tests/system/rollover/tests_rollover.py +++ b/bin/tests/system/rollover/tests_rollover.py @@ -265,7 +265,7 @@ def test_rollover_multisigner(servers): zone, ] - return isctest.run.cmd(keygen_command, log_stdout=True).stdout.decode("utf-8") + return isctest.run.cmd(keygen_command).stdout.decode("utf-8") zone = "multisigner-model2.kasp" diff --git a/bin/tests/system/rsabigexponent/tests_rsabigexponent.py b/bin/tests/system/rsabigexponent/tests_rsabigexponent.py index 571fe2fe13..4588229742 100644 --- a/bin/tests/system/rsabigexponent/tests_rsabigexponent.py +++ b/bin/tests/system/rsabigexponent/tests_rsabigexponent.py @@ -43,7 +43,7 @@ def test_max_rsa_exponent_size_good(exponent_size, templates): def test_max_rsa_exponent_size_bad(exponent_size, templates): templates.render("options.conf", {"max_rsa_exponent_size": exponent_size}) with pytest.raises(subprocess.CalledProcessError): - isctest.run.cmd([CHECKCONF, "options.conf"], log_stdout=True) + isctest.run.cmd([CHECKCONF, "options.conf"]) def test_rsa_big_exponent_keys_cant_load(): diff --git a/bin/tests/system/stress/tests_stress_update.py b/bin/tests/system/stress/tests_stress_update.py index 2d5eefd3bf..cbc678f6ba 100644 --- a/bin/tests/system/stress/tests_stress_update.py +++ b/bin/tests/system/stress/tests_stress_update.py @@ -54,7 +54,9 @@ def update_zone(test_state, zone): update = dns.update.UpdateMessage(zone) update.add(f"dynamic-{i}.{zone}", 300, "TXT", f"txt-{i}") try: - response = isctest.query.udp(update, server) + response = isctest.query.udp( + update, server, log_query=False, log_response=False + ) assert response.rcode() == dns.rcode.NOERROR except dns.exception.Timeout: isctest.log.info(f"error: query timeout for {zone}") diff --git a/bin/tests/system/tsiggss/tests_isc_spnego_flaws.py b/bin/tests/system/tsiggss/tests_isc_spnego_flaws.py index 0d0ed03d7c..4c32557e89 100755 --- a/bin/tests/system/tsiggss/tests_isc_spnego_flaws.py +++ b/bin/tests/system/tsiggss/tests_isc_spnego_flaws.py @@ -17,7 +17,6 @@ A tool for reproducing ISC SPNEGO vulnerabilities """ import argparse -import datetime import struct import time @@ -177,14 +176,8 @@ def send_crafted_tkey_query(opts: argparse.Namespace) -> None: """ query = CraftedTKEYQuery(opts).msg - print("# > " + str(datetime.datetime.now())) - print(query.to_text()) - print() - response = isctest.query.tcp(query, opts.server_ip, timeout=2) - print("# < " + str(datetime.datetime.now())) - print(response.to_text()) - print() + isctest.query.tcp(query, opts.server_ip, timeout=2) def test_cve_2020_8625(): diff --git a/bin/tests/system/verify/tests_verify.py b/bin/tests/system/verify/tests_verify.py index ae82dee1c5..203c2181be 100644 --- a/bin/tests/system/verify/tests_verify.py +++ b/bin/tests/system/verify/tests_verify.py @@ -47,7 +47,7 @@ VERIFY = os.environ.get("VERIFY") ], ) def test_verify_good_zone_files(zone): - isctest.run.cmd([VERIFY, "-z", "-o", zone, f"zones/{zone}.good"], log_stdout=True) + isctest.run.cmd([VERIFY, "-z", "-o", zone, f"zones/{zone}.good"]) def test_verify_good_zone_nsec_next_name_case_mismatch(): @@ -58,7 +58,6 @@ def test_verify_good_zone_nsec_next_name_case_mismatch(): "nsec-next-name-case-mismatch", "zones/nsec-next-name-case-mismatch.good", ], - log_stdout=True, ) @@ -67,7 +66,6 @@ def get_bad_zone_output(zone): output = isctest.run.cmd( [VERIFY, *only_opt, "-o", zone, f"zones/{zone}.bad"], raise_on_exception=False, - log_stdout=True, ) stream = (output.stdout + output.stderr).decode("utf-8").replace("\n", "") return stream