From 2b77921470c4d73862cbad0191e7ffee90842cfd Mon Sep 17 00:00:00 2001
From: =?UTF-8?q?Nicki=20K=C5=99=C3=AD=C5=BEek?= <nicki@isc.org>
Date: Tue, 17 Jun 2025 15:47:48 +0200
Subject: [PATCH 1/8] Replace print statements in checkds test

Use isctest.log logging facility for consistent and predictable logging
output rather than using print(). Remove writes of stderr, as that
output will be logged in the debug log in case the commands called with
isctest.run.cmd() fails.

(cherry picked from commit 4b8998e4ad1eda6e4fca23c362dd8034d6cce3fa)
---
 bin/tests/system/checkds/tests_checkds.py | 12 +++++-------
 1 file changed, 5 insertions(+), 7 deletions(-)

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
 

From 129dd186fc4ddde2cf4a66e2c4465b8e92069d18 Mon Sep 17 00:00:00 2001
From: =?UTF-8?q?Nicki=20K=C5=99=C3=AD=C5=BEek?= <nicki@isc.org>
Date: Tue, 17 Jun 2025 17:21:33 +0200
Subject: [PATCH 2/8] Don't log empty test result messages

The messages obtained from test results may contain stuff like detailed
failure/error information, tracebacks etc. In many cases, the message
will be empty, in which case it doesn't need to be logged.

For an example, run test with many test cases, e.g.
verify/test_verify.py, and inspect the tail of the pytest.log.txt before
and after this commit.

(cherry picked from commit 0a6b0cf68c6553f7eeef06fb507c1b28b9c61f38)
---
 bin/tests/system/conftest.py | 3 ++-
 1 file changed, 2 insertions(+), 1 deletion(-)

diff --git a/bin/tests/system/conftest.py b/bin/tests/system/conftest.py
index a68e4f65c3..1393b0266a 100644
--- a/bin/tests/system/conftest.py
+++ b/bin/tests/system/conftest.py
@@ -365,7 +365,8 @@ def system_test_dir(request, system_test_name, expected_artifacts):
             isctest.log.debug("%s %s", result.outcome.upper(), node)
             messages.extend(result.messages.values())
         for message in messages:
-            isctest.log.debug("\n" + message)
+            if message:
+                isctest.log.debug("\n" + 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:

From a6599a082234c0206af75b73d7f4e43cc4b71f92 Mon Sep 17 00:00:00 2001
From: =?UTF-8?q?Nicki=20K=C5=99=C3=AD=C5=BEek?= <nicki@isc.org>
Date: Tue, 17 Jun 2025 17:33:22 +0200
Subject: [PATCH 3/8] Indent multiline output in pytest logging

When multiline message is logged, indent all but the first line (which
will be preceeded by the LOG_FORMAT). This improves the clarity of logs,
as it's immediately clear which lines are regular log output, and which
ones are multiline debug output.

Adjust the isctest.run.cmd() stdout/stderr logging to this new format.

(cherry picked from commit 23e6b49cc57cb41a0260686366e7ba86cac0ec4a)
---
 bin/tests/system/isctest/log/basic.py | 11 +++++++++++
 bin/tests/system/isctest/run.py       |  8 ++++----
 2 files changed, 15 insertions(+), 4 deletions(-)

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/run.py b/bin/tests/system/isctest/run.py
index 5c994ce377..4c3acc5d2b 100644
--- a/bin/tests/system/isctest/run.py
+++ b/bin/tests/system/isctest/run.py
@@ -31,17 +31,17 @@ def cmd(
     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

From 03af371948c2d008d1c56a3a2e387e03263ade0e Mon Sep 17 00:00:00 2001
From: =?UTF-8?q?Nicki=20K=C5=99=C3=AD=C5=BEek?= <nicki@isc.org>
Date: Tue, 17 Jun 2025 17:40:07 +0200
Subject: [PATCH 4/8] Add options for query&response logging to pytest

In some cases, it's useful to log the sent and received DNS messages.
Add options to enable this on demand. Query is only logged the first
time it's sent, since it doesn't change. If response logging is turned
on, then each response is logged, since it might be different every
time.

(cherry picked from commit 1e87b5ffc6c689942d37274659c78c382c1c6988)
---
 bin/tests/system/isctest/query.py | 20 ++++++++++++++++----
 1 file changed, 16 insertions(+), 4 deletions(-)

diff --git a/bin/tests/system/isctest/query.py b/bin/tests/system/isctest/query.py
index 6e84c8188d..4b8590fb2f 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 = False,
+    log_response: bool = False,
 ) -> 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
 

From 7aa00bcddcfb2827762c43ce8876d7487c849e7c Mon Sep 17 00:00:00 2001
From: =?UTF-8?q?Nicki=20K=C5=99=C3=AD=C5=BEek?= <nicki@isc.org>
Date: Tue, 17 Jun 2025 17:43:06 +0200
Subject: [PATCH 5/8] Use proper logging in SPNEGO tests

Avoid using print() and use proper logging facility instead.

(cherry picked from commit 51ac5bdd14030cec2c04db648c6991136e8f4d40)
---
 bin/tests/system/tsiggss/tests_isc_spnego_flaws.py | 11 +++--------
 1 file changed, 3 insertions(+), 8 deletions(-)

diff --git a/bin/tests/system/tsiggss/tests_isc_spnego_flaws.py b/bin/tests/system/tsiggss/tests_isc_spnego_flaws.py
index 0d0ed03d7c..955d9901e8 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,10 @@ 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, log_query=True, log_response=True
+    )
 
 
 def test_cve_2020_8625():

From 9549c8885aba6d959b9104c6c25bd5484801096d Mon Sep 17 00:00:00 2001
From: =?UTF-8?q?Nicki=20K=C5=99=C3=AD=C5=BEek?= <nicki@isc.org>
Date: Thu, 26 Jun 2025 16:14:50 +0200
Subject: [PATCH 6/8] Log query and response when using isctest.query.*

Make sure the queries and responses are logged at the DEBUG level, which
may provide useful information in case of failing tests.

This doesn't seem to significantly increase the overall artifacts size.
Previously, pytest.log.txt files from all system tests would take around
3 MB, with this change, it's around 8 MB).

(cherry picked from commit 56fec9ba04b3ddb82591d2c9edf4f073d650209c)
---
 bin/tests/system/isctest/query.py                  | 4 ++--
 bin/tests/system/limits/tests_limits.py            | 4 ++--
 bin/tests/system/stress/tests_stress_update.py     | 4 +++-
 bin/tests/system/tsiggss/tests_isc_spnego_flaws.py | 4 +---
 4 files changed, 8 insertions(+), 8 deletions(-)

diff --git a/bin/tests/system/isctest/query.py b/bin/tests/system/isctest/query.py
index 4b8590fb2f..6e7bee285e 100644
--- a/bin/tests/system/isctest/query.py
+++ b/bin/tests/system/isctest/query.py
@@ -32,8 +32,8 @@ def generic_query(
     attempts: int = 10,
     expected_rcode: dns_rcode = None,
     verify: bool = False,
-    log_query: bool = False,
-    log_response: bool = False,
+    log_query: bool = True,
+    log_response: bool = True,
 ) -> Any:
     if port is None:
         if query_func.__name__ == "tls":
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/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 955d9901e8..4c32557e89 100755
--- a/bin/tests/system/tsiggss/tests_isc_spnego_flaws.py
+++ b/bin/tests/system/tsiggss/tests_isc_spnego_flaws.py
@@ -177,9 +177,7 @@ def send_crafted_tkey_query(opts: argparse.Namespace) -> None:
 
     query = CraftedTKEYQuery(opts).msg
 
-    isctest.query.tcp(
-        query, opts.server_ip, timeout=2, log_query=True, log_response=True
-    )
+    isctest.query.tcp(query, opts.server_ip, timeout=2)
 
 
 def test_cve_2020_8625():

From 88549e884962a4c17365ee24a4675090a1753852 Mon Sep 17 00:00:00 2001
From: =?UTF-8?q?Nicki=20K=C5=99=C3=AD=C5=BEek?= <nicki@isc.org>
Date: Thu, 26 Jun 2025 16:18:01 +0200
Subject: [PATCH 7/8] Log command stdout when using isctest.run.cmd()

The command's stdout may provide useful debug info, so make sure we log
it by default. It doesn't seem to have a significant impact on the log
size.

(cherry picked from commit 9f3f6ec38e2ebb5314b1df72d0b28eb951a61038)
---
 bin/tests/system/dnstap/tests_dnstap.py                |  3 +--
 bin/tests/system/isctest/kasp.py                       |  2 +-
 bin/tests/system/isctest/run.py                        |  3 +--
 bin/tests/system/kasp/tests_kasp.py                    | 10 +++++-----
 bin/tests/system/keyfromlabel/tests_keyfromlabel.py    | 10 ++++------
 bin/tests/system/ksr/tests_ksr.py                      |  4 +---
 bin/tests/system/rollover/tests_rollover.py            |  2 +-
 .../system/rsabigexponent/tests_rsabigexponent.py      |  2 +-
 bin/tests/system/verify/tests_verify.py                |  4 +---
 9 files changed, 16 insertions(+), 24 deletions(-)

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/run.py b/bin/tests/system/isctest/run.py
index 4c3acc5d2b..e4fbd459dd 100644
--- a/bin/tests/system/isctest/run.py
+++ b/bin/tests/system/isctest/run.py
@@ -24,7 +24,7 @@ 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,
@@ -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/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/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

From c0ca8854c5f50e7cf13ee3b44ac84ff73cce48e9 Mon Sep 17 00:00:00 2001
From: =?UTF-8?q?Nicki=20K=C5=99=C3=AD=C5=BEek?= <nicki@isc.org>
Date: Thu, 26 Jun 2025 18:20:06 +0200
Subject: [PATCH 8/8] Log assertion failures right after test result

The extra messages are typically traceback from assertion failures.
Previously, they'd be printed only after all individual test case
results have been printed. That made it difficult to pair the traceback
to the failing test in some cases, as the node information (aka test
name) might not always be present.

Instead, log any extra messages related to a particular test failure
directly after reporting its result, making the failure details more
readily available and easy to connect with a particular test case.

(cherry picked from commit fcf31417ddee33be028f69a1ea4326ccede46d78)
---
 bin/tests/system/conftest.py | 12 ++++++------
 1 file changed, 6 insertions(+), 6 deletions(-)

diff --git a/bin/tests/system/conftest.py b/bin/tests/system/conftest.py
index 1393b0266a..7f3c0eb0fb 100644
--- a/bin/tests/system/conftest.py
+++ b/bin/tests/system/conftest.py
@@ -360,13 +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:
-            if message:
-                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: