mirror of
https://github.com/isc-projects/bind9.git
synced 2026-06-11 10:59:59 -04:00
Merge branch 'tkrizek/pytest-log' into 'main'
Simplify pytest logging See merge request isc-projects/bind9!8742
This commit is contained in:
Tom Krizek
commit
366b93f835
8 changed files with 213 additions and 200 deletions
|
|
@ -208,8 +208,8 @@ assigned port numbers. They're also set as environment variables. These include:
|
|||
|
||||
Each module has a separate log which will be saved as pytest.log.txt in the
|
||||
temporary directory in which the test is executed. This log includes messages
|
||||
for this module setup/teardown as well as any logging from the tests using the
|
||||
`logger` fixture. Logging level DEBUG and above will be present in this log.
|
||||
for this module setup/teardown as well as any logging from the tests. Logging
|
||||
level DEBUG and above will be present in this log.
|
||||
|
||||
In general, any log messages using INFO or above will also be printed out
|
||||
during pytest execution. In CI, the pytest output is also saved to
|
||||
|
|
@ -276,7 +276,6 @@ is possible to pass fixtures to the test function by specifying their name as
|
|||
function arguments. Fixtures are used to provide context to the tests, e.g.:
|
||||
|
||||
- `ports` is a dictionary with assigned port numbers
|
||||
- `logger` is a test-specific logging object
|
||||
|
||||
### tests_sh_*.py
|
||||
|
||||
|
|
|
|||
|
|
@ -69,19 +69,19 @@ then
|
|||
}
|
||||
echo_i() {
|
||||
printf '%s\n' "$*" | while IFS= read -r __LINE ; do
|
||||
echoinfo "I:$SYSTESTDIR:$__LINE"
|
||||
echoinfo "I:$__LINE"
|
||||
done
|
||||
}
|
||||
|
||||
echo_ic() {
|
||||
printf '%s\n' "$*" | while IFS= read -r __LINE ; do
|
||||
echoinfo "I:$SYSTESTDIR: $__LINE"
|
||||
echoinfo "I: $__LINE"
|
||||
done
|
||||
}
|
||||
|
||||
echo_d() {
|
||||
printf '%s\n' "$*" | while IFS= read -r __LINE ; do
|
||||
echoinfo "D:$SYSTESTDIR:$__LINE"
|
||||
echoinfo "D:$__LINE"
|
||||
done
|
||||
}
|
||||
else
|
||||
|
|
@ -106,32 +106,32 @@ else
|
|||
|
||||
echo_i() {
|
||||
echo "$@" | while IFS= read -r __LINE ; do
|
||||
echoinfo "I:$SYSTESTDIR:$__LINE"
|
||||
echoinfo "I:$__LINE"
|
||||
done
|
||||
}
|
||||
|
||||
echo_ic() {
|
||||
echo "$@" | while IFS= read -r __LINE ; do
|
||||
echoinfo "I:$SYSTESTDIR: $__LINE"
|
||||
echoinfo "I: $__LINE"
|
||||
done
|
||||
}
|
||||
|
||||
echo_d() {
|
||||
echo "$@" | while IFS= read -r __LINE ; do
|
||||
echoinfo "D:$SYSTESTDIR:$__LINE"
|
||||
echoinfo "D:$__LINE"
|
||||
done
|
||||
}
|
||||
fi
|
||||
|
||||
cat_i() {
|
||||
while IFS= read -r __LINE ; do
|
||||
echoinfo "I:$SYSTESTDIR:$__LINE"
|
||||
echoinfo "I:$__LINE"
|
||||
done
|
||||
}
|
||||
|
||||
cat_d() {
|
||||
while IFS= read -r __LINE ; do
|
||||
echoinfo "D:$SYSTESTDIR:$__LINE"
|
||||
echoinfo "D:$__LINE"
|
||||
done
|
||||
}
|
||||
|
||||
|
|
@ -499,7 +499,7 @@ _times() {
|
|||
}
|
||||
|
||||
rndc_reload() {
|
||||
$RNDC -c ../_common/rndc.conf -s $2 -p ${CONTROLPORT} reload $3 2>&1 | sed 's/^/'"I:$SYSTESTDIR:$1"' /'
|
||||
$RNDC -c ../_common/rndc.conf -s $2 -p ${CONTROLPORT} reload $3 2>&1 | sed 's/^/'"I:$1"' /'
|
||||
# reloading single zone is synchronous, if we're reloading whole server
|
||||
# we need to wait for reload to finish
|
||||
if [ -z "$3" ]; then
|
||||
|
|
@ -512,7 +512,7 @@ rndc_reload() {
|
|||
|
||||
rndc_reconfig() {
|
||||
seconds=${3:-10}
|
||||
$RNDC -c ../_common/rndc.conf -s "$2" -p "${CONTROLPORT}" reconfig 2>&1 | sed 's/^/'"I:$SYSTESTDIR:$1"' /'
|
||||
$RNDC -c ../_common/rndc.conf -s "$2" -p "${CONTROLPORT}" reconfig 2>&1 | sed 's/^/'"I:$1"' /'
|
||||
for _ in $(_times "$seconds"); do
|
||||
"$RNDC" -c ../_common/rndc.conf -s "$2" -p "${CONTROLPORT}" status | grep "reload/reconfig in progress" > /dev/null || break
|
||||
sleep 1
|
||||
|
|
|
|||
|
|
@ -10,7 +10,6 @@
|
|||
# information regarding copyright ownership.
|
||||
|
||||
from functools import partial
|
||||
import logging
|
||||
import os
|
||||
from pathlib import Path
|
||||
import re
|
||||
|
|
@ -47,7 +46,6 @@ else:
|
|||
|
||||
# ----------------------- Globals definition -----------------------------
|
||||
|
||||
LOG_FORMAT = "%(asctime)s %(levelname)7s:%(name)s %(message)s"
|
||||
XDIST_WORKER = os.environ.get("PYTEST_XDIST_WORKER", "")
|
||||
FILE_DIR = os.path.abspath(Path(__file__).parent)
|
||||
ENV_RE = re.compile(b"([^=]+)=(.*)")
|
||||
|
|
@ -63,7 +61,6 @@ PRIORITY_TESTS = [
|
|||
"upforwd/",
|
||||
]
|
||||
PRIORITY_TESTS_RE = re.compile("|".join(PRIORITY_TESTS))
|
||||
CONFTEST_LOGGER = logging.getLogger("conftest")
|
||||
SYSTEM_TEST_DIR_GIT_PATH = "bin/tests/system"
|
||||
SYSTEM_TEST_NAME_RE = re.compile(f"{SYSTEM_TEST_DIR_GIT_PATH}" + r"/([^/]+)")
|
||||
SYMLINK_REPLACEMENT_RE = re.compile(r"/tests(_.*)\.py")
|
||||
|
|
@ -71,38 +68,6 @@ SYMLINK_REPLACEMENT_RE = re.compile(r"/tests(_.*)\.py")
|
|||
# ---------------------- Module initialization ---------------------------
|
||||
|
||||
|
||||
def init_pytest_conftest_logger(conftest_logger):
|
||||
"""
|
||||
This initializes the conftest logger which is used for pytest setup
|
||||
and configuration before tests are executed -- aka any logging in this
|
||||
file that is _not_ module-specific.
|
||||
"""
|
||||
conftest_logger.setLevel(logging.DEBUG)
|
||||
file_handler = logging.FileHandler("pytest.conftest.log.txt")
|
||||
file_handler.setLevel(logging.DEBUG)
|
||||
file_handler.setFormatter(logging.Formatter(LOG_FORMAT))
|
||||
conftest_logger.addHandler(file_handler)
|
||||
|
||||
|
||||
init_pytest_conftest_logger(CONFTEST_LOGGER)
|
||||
|
||||
|
||||
def avoid_duplicated_logs():
|
||||
"""
|
||||
Remove direct root logger output to file descriptors.
|
||||
This default is causing duplicates because all our messages go through
|
||||
regular logging as well and are thus displayed twice.
|
||||
"""
|
||||
todel = []
|
||||
for handler in logging.root.handlers:
|
||||
if handler.__class__ == logging.StreamHandler:
|
||||
# Beware: As for pytest 7.2.2, LiveLogging and LogCapture
|
||||
# handlers inherit from logging.StreamHandler
|
||||
todel.append(handler)
|
||||
for handler in todel:
|
||||
logging.root.handlers.remove(handler)
|
||||
|
||||
|
||||
def parse_env(env_bytes):
|
||||
"""Parse the POSIX env format into Python dictionary."""
|
||||
out = {}
|
||||
|
|
@ -127,7 +92,7 @@ def get_env_bytes(cmd):
|
|||
stdout=subprocess.PIPE,
|
||||
)
|
||||
except subprocess.CalledProcessError as exc:
|
||||
CONFTEST_LOGGER.error("failed to get shell env: %s", exc)
|
||||
isctest.log.error("failed to get shell env: %s", exc)
|
||||
raise exc
|
||||
env_bytes = proc.stdout
|
||||
return parse_env(env_bytes)
|
||||
|
|
@ -137,7 +102,7 @@ def get_env_bytes(cmd):
|
|||
# FUTURE: Remove conf.sh entirely and define all variables in pytest only.
|
||||
CONF_ENV = get_env_bytes(". ./conf.sh && env")
|
||||
os.environb.update(CONF_ENV)
|
||||
CONFTEST_LOGGER.debug("variables in env: %s", ", ".join([str(key) for key in CONF_ENV]))
|
||||
isctest.log.debug("variables in env: %s", ", ".join([str(key) for key in CONF_ENV]))
|
||||
|
||||
# --------------------------- pytest hooks -------------------------------
|
||||
|
||||
|
|
@ -161,7 +126,7 @@ def pytest_configure(config):
|
|||
try:
|
||||
import xdist.scheduler.loadscope # pylint: disable=unused-import
|
||||
except ImportError:
|
||||
CONFTEST_LOGGER.debug(
|
||||
isctest.log.debug(
|
||||
"xdist is too old and does not have "
|
||||
"scheduler.loadscope, disabling parallelism"
|
||||
)
|
||||
|
|
@ -181,7 +146,7 @@ def pytest_ignore_collect(path):
|
|||
# is otherwise and invalid character for a system test name.
|
||||
match = SYSTEM_TEST_NAME_RE.search(str(path))
|
||||
if match is None:
|
||||
CONFTEST_LOGGER.warning("unexpected test path: %s (ignored)", path)
|
||||
isctest.log.warning("unexpected test path: %s (ignored)", path)
|
||||
return True
|
||||
system_test_name = match.groups()[0]
|
||||
return "_" in system_test_name
|
||||
|
|
@ -349,13 +314,6 @@ def system_test_name(request):
|
|||
return path.parent.name
|
||||
|
||||
|
||||
@pytest.fixture(scope="module")
|
||||
def mlogger(system_test_name):
|
||||
"""Logging facility specific to this test module."""
|
||||
avoid_duplicated_logs()
|
||||
return logging.getLogger(system_test_name)
|
||||
|
||||
|
||||
def _get_marker(node, marker):
|
||||
try:
|
||||
# pytest >= 4.x
|
||||
|
|
@ -377,15 +335,17 @@ def wait_for_zones_loaded(request, servers):
|
|||
watcher.wait_for_line("all zones loaded")
|
||||
|
||||
|
||||
@pytest.fixture
|
||||
@pytest.fixture(autouse=True)
|
||||
def logger(request, system_test_name):
|
||||
"""Logging facility specific to a particular test."""
|
||||
return logging.getLogger(f"{system_test_name}.{request.node.name}")
|
||||
"""Sets up logging facility specific to a particular test."""
|
||||
isctest.log.init_test_logger(system_test_name, request.node.name)
|
||||
yield
|
||||
isctest.log.deinit_test_logger()
|
||||
|
||||
|
||||
@pytest.fixture(scope="module")
|
||||
def system_test_dir(
|
||||
request, env, system_test_name, mlogger
|
||||
request, env, system_test_name
|
||||
): # pylint: disable=too-many-statements,too-many-locals
|
||||
"""
|
||||
Temporary directory for executing the test.
|
||||
|
|
@ -405,7 +365,7 @@ def system_test_dir(
|
|||
except AttributeError:
|
||||
# This may happen if pytest execution is interrupted and
|
||||
# pytest_runtest_makereport() is never called.
|
||||
mlogger.debug("can't obtain test results, test run was interrupted")
|
||||
isctest.log.debug("can't obtain test results, test run was interrupted")
|
||||
return "error"
|
||||
test_results = {
|
||||
node.nodeid: all_test_results[node.nodeid]
|
||||
|
|
@ -415,10 +375,10 @@ def system_test_dir(
|
|||
assert len(test_results)
|
||||
messages = []
|
||||
for node, result in test_results.items():
|
||||
mlogger.debug("%s %s", result.outcome.upper(), node)
|
||||
isctest.log.debug("%s %s", result.outcome.upper(), node)
|
||||
messages.extend(result.messages)
|
||||
for message in messages:
|
||||
mlogger.debug("\n" + 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:
|
||||
|
|
@ -448,60 +408,54 @@ def system_test_dir(
|
|||
unlink(symlink_dst)
|
||||
symlink_dst.symlink_to(os.path.relpath(testdir, start=system_test_root))
|
||||
|
||||
# Configure logger to write to a file inside the temporary test directory
|
||||
mlogger.handlers.clear()
|
||||
mlogger.setLevel(logging.DEBUG)
|
||||
handler = logging.FileHandler(testdir / "pytest.log.txt", mode="w")
|
||||
formatter = logging.Formatter(LOG_FORMAT)
|
||||
handler.setFormatter(formatter)
|
||||
mlogger.addHandler(handler)
|
||||
isctest.log.init_module_logger(system_test_name, testdir)
|
||||
|
||||
# System tests are meant to be executed from their directory - switch to it.
|
||||
old_cwd = os.getcwd()
|
||||
os.chdir(testdir)
|
||||
mlogger.debug("switching to tmpdir: %s", testdir)
|
||||
isctest.log.info("switching to tmpdir: %s", testdir)
|
||||
try:
|
||||
yield testdir # other fixtures / tests will execute here
|
||||
finally:
|
||||
os.chdir(old_cwd)
|
||||
mlogger.debug("changed workdir to: %s", old_cwd)
|
||||
isctest.log.debug("changed workdir to: %s", old_cwd)
|
||||
|
||||
result = get_test_result()
|
||||
|
||||
# Clean temporary dir unless it should be kept
|
||||
keep = False
|
||||
if request.config.getoption("--noclean"):
|
||||
mlogger.debug(
|
||||
isctest.log.debug(
|
||||
"--noclean requested, keeping temporary directory %s", testdir
|
||||
)
|
||||
keep = True
|
||||
elif result == "failed":
|
||||
mlogger.debug(
|
||||
isctest.log.debug(
|
||||
"test failure detected, keeping temporary directory %s", testdir
|
||||
)
|
||||
keep = True
|
||||
elif not request.node.stash[FIXTURE_OK]:
|
||||
mlogger.debug(
|
||||
isctest.log.debug(
|
||||
"test setup/teardown issue detected, keeping temporary directory %s",
|
||||
testdir,
|
||||
)
|
||||
keep = True
|
||||
|
||||
if keep:
|
||||
mlogger.info(
|
||||
isctest.log.info(
|
||||
"test artifacts in: %s", symlink_dst.relative_to(system_test_root)
|
||||
)
|
||||
else:
|
||||
mlogger.debug("deleting temporary directory")
|
||||
handler.flush()
|
||||
handler.close()
|
||||
isctest.log.debug("deleting temporary directory")
|
||||
|
||||
isctest.log.deinit_module_logger()
|
||||
if not keep:
|
||||
shutil.rmtree(testdir)
|
||||
unlink(symlink_dst)
|
||||
|
||||
|
||||
def _run_script( # pylint: disable=too-many-arguments
|
||||
env,
|
||||
mlogger,
|
||||
system_test_dir: Path,
|
||||
interpreter: str,
|
||||
script: str,
|
||||
|
|
@ -518,8 +472,8 @@ def _run_script( # pylint: disable=too-many-arguments
|
|||
cwd = os.getcwd()
|
||||
if not path.exists():
|
||||
raise FileNotFoundError(f"script {script} not found in {cwd}")
|
||||
mlogger.debug("running script: %s %s %s", interpreter, script, " ".join(args))
|
||||
mlogger.debug(" workdir: %s", cwd)
|
||||
isctest.log.debug("running script: %s %s %s", interpreter, script, " ".join(args))
|
||||
isctest.log.debug(" workdir: %s", cwd)
|
||||
returncode = 1
|
||||
|
||||
cmd = [interpreter, script] + args
|
||||
|
|
@ -534,24 +488,24 @@ def _run_script( # pylint: disable=too-many-arguments
|
|||
) as proc:
|
||||
if proc.stdout:
|
||||
for line in proc.stdout:
|
||||
mlogger.info(" %s", line.rstrip("\n"))
|
||||
isctest.log.info(" %s", line.rstrip("\n"))
|
||||
proc.communicate()
|
||||
returncode = proc.returncode
|
||||
if returncode:
|
||||
raise subprocess.CalledProcessError(returncode, cmd)
|
||||
mlogger.debug(" exited with %d", returncode)
|
||||
isctest.log.debug(" exited with %d", returncode)
|
||||
|
||||
|
||||
@pytest.fixture(scope="module")
|
||||
def shell(env, system_test_dir, mlogger):
|
||||
def shell(env, system_test_dir):
|
||||
"""Function to call a shell script with arguments."""
|
||||
return partial(_run_script, env, mlogger, system_test_dir, env["SHELL"])
|
||||
return partial(_run_script, env, system_test_dir, env["SHELL"])
|
||||
|
||||
|
||||
@pytest.fixture(scope="module")
|
||||
def perl(env, system_test_dir, mlogger):
|
||||
def perl(env, system_test_dir):
|
||||
"""Function to call a perl script with arguments."""
|
||||
return partial(_run_script, env, mlogger, system_test_dir, env["PERL"])
|
||||
return partial(_run_script, env, system_test_dir, env["PERL"])
|
||||
|
||||
|
||||
@pytest.fixture(scope="module")
|
||||
|
|
@ -568,7 +522,6 @@ def run_tests_sh(system_test_dir, shell):
|
|||
def system_test( # pylint: disable=too-many-arguments,too-many-statements
|
||||
request,
|
||||
env: Dict[str, str],
|
||||
mlogger,
|
||||
system_test_dir,
|
||||
shell,
|
||||
perl,
|
||||
|
|
@ -599,7 +552,7 @@ def system_test( # pylint: disable=too-many-arguments,too-many-statements
|
|||
try:
|
||||
perl("testsock.pl", ["-p", env["PORT"]])
|
||||
except subprocess.CalledProcessError as exc:
|
||||
mlogger.error("testsock.pl: exited with code %d", exc.returncode)
|
||||
isctest.log.error("testsock.pl: exited with code %d", exc.returncode)
|
||||
pytest.skip("Network interface aliases not set up.")
|
||||
|
||||
def check_prerequisites():
|
||||
|
|
@ -616,21 +569,21 @@ def system_test( # pylint: disable=too-many-arguments,too-many-statements
|
|||
except FileNotFoundError:
|
||||
pass # setup.sh is optional
|
||||
except subprocess.CalledProcessError as exc:
|
||||
mlogger.error("Failed to run test setup")
|
||||
isctest.log.error("Failed to run test setup")
|
||||
pytest.fail(f"setup.sh exited with {exc.returncode}")
|
||||
|
||||
def start_servers():
|
||||
try:
|
||||
perl("start.pl", ["--port", env["PORT"], system_test_dir.name])
|
||||
except subprocess.CalledProcessError as exc:
|
||||
mlogger.error("Failed to start servers")
|
||||
isctest.log.error("Failed to start servers")
|
||||
pytest.fail(f"start.pl exited with {exc.returncode}")
|
||||
|
||||
def stop_servers():
|
||||
try:
|
||||
perl("stop.pl", [system_test_dir.name])
|
||||
except subprocess.CalledProcessError as exc:
|
||||
mlogger.error("Failed to stop servers")
|
||||
isctest.log.error("Failed to stop servers")
|
||||
get_core_dumps()
|
||||
pytest.fail(f"stop.pl exited with {exc.returncode}")
|
||||
|
||||
|
|
@ -638,13 +591,13 @@ def system_test( # pylint: disable=too-many-arguments,too-many-statements
|
|||
try:
|
||||
shell("get_core_dumps.sh", [system_test_dir.name])
|
||||
except subprocess.CalledProcessError as exc:
|
||||
mlogger.error("Found core dumps or sanitizer reports")
|
||||
isctest.log.error("Found core dumps or sanitizer reports")
|
||||
pytest.fail(f"get_core_dumps.sh exited with {exc.returncode}")
|
||||
|
||||
os.environ.update(env) # Ensure pytests have the same env vars as shell tests.
|
||||
mlogger.info(f"test started: {request.node.name}")
|
||||
isctest.log.info(f"test started: {request.node.name}")
|
||||
port = int(env["PORT"])
|
||||
mlogger.info("using port range: <%d, %d>", port, port + PORTS_PER_TEST - 1)
|
||||
isctest.log.info("using port range: <%d, %d>", port, port + PORTS_PER_TEST - 1)
|
||||
|
||||
if not hasattr(request.node, "stash"): # compatibility with pytest<7.0.0
|
||||
request.node.stash = {} # use regular dict instead of pytest.Stash
|
||||
|
|
@ -662,17 +615,17 @@ def system_test( # pylint: disable=too-many-arguments,too-many-statements
|
|||
setup_test()
|
||||
try:
|
||||
start_servers()
|
||||
mlogger.debug("executing test(s)")
|
||||
isctest.log.debug("executing test(s)")
|
||||
yield
|
||||
finally:
|
||||
mlogger.debug("test(s) finished")
|
||||
isctest.log.debug("test(s) finished")
|
||||
stop_servers()
|
||||
get_core_dumps()
|
||||
request.node.stash[FIXTURE_OK] = True
|
||||
|
||||
|
||||
@pytest.fixture
|
||||
def servers(ports, logger, system_test_dir):
|
||||
def servers(ports, system_test_dir):
|
||||
instances = {}
|
||||
for entry in system_test_dir.rglob("*"):
|
||||
if entry.is_dir():
|
||||
|
|
@ -682,7 +635,7 @@ def servers(ports, logger, system_test_dir):
|
|||
named_ports = isctest.instance.NamedPorts(
|
||||
dns=int(ports["PORT"]), rndc=int(ports["CONTROLPORT"])
|
||||
)
|
||||
instance = isctest.instance.NamedInstance(dir_name, named_ports, logger)
|
||||
instance = isctest.instance.NamedInstance(dir_name, named_ports)
|
||||
instances[dir_name] = instance
|
||||
except ValueError:
|
||||
continue
|
||||
|
|
|
|||
|
|
@ -18,7 +18,7 @@ import os
|
|||
import re
|
||||
|
||||
from .rndc import RNDCBinaryExecutor, RNDCException, RNDCExecutor
|
||||
from .log import LogFile, WatchLogFromStart, WatchLogFromHere
|
||||
from .log import info, LogFile, WatchLogFromStart, WatchLogFromHere
|
||||
|
||||
|
||||
class NamedPorts(NamedTuple):
|
||||
|
|
@ -64,7 +64,7 @@ class NamedInstance:
|
|||
self.ports = ports
|
||||
self.log = LogFile(os.path.join(identifier, "named.run"))
|
||||
self._rndc_executor = rndc_executor or RNDCBinaryExecutor()
|
||||
self._rndc_logger = rndc_logger or logging.getLogger()
|
||||
self._rndc_logger = rndc_logger
|
||||
|
||||
@staticmethod
|
||||
def _identifier_to_ip(identifier: str) -> str:
|
||||
|
|
@ -156,12 +156,13 @@ class NamedInstance:
|
|||
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,
|
||||
},
|
||||
)
|
||||
args = {
|
||||
"ip": self.ip,
|
||||
"command": command,
|
||||
"separator": "-" * 80,
|
||||
"response": response,
|
||||
}
|
||||
if self._rndc_logger is None:
|
||||
info(fmt, args)
|
||||
else:
|
||||
self._rndc_logger.info(fmt, args)
|
||||
|
|
|
|||
24
bin/tests/system/isctest/log/__init__.py
Normal file
24
bin/tests/system/isctest/log/__init__.py
Normal file
|
|
@ -0,0 +1,24 @@
|
|||
# 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 .basic import (
|
||||
deinit_module_logger,
|
||||
deinit_test_logger,
|
||||
init_module_logger,
|
||||
init_test_logger,
|
||||
debug,
|
||||
info,
|
||||
warning,
|
||||
error,
|
||||
critical,
|
||||
)
|
||||
|
||||
from .watchlog import LogFile, WatchLogFromStart, WatchLogFromHere
|
||||
113
bin/tests/system/isctest/log/basic.py
Normal file
113
bin/tests/system/isctest/log/basic.py
Normal file
|
|
@ -0,0 +1,113 @@
|
|||
# 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 logging
|
||||
from pathlib import Path
|
||||
from typing import Dict, Optional
|
||||
|
||||
|
||||
CONFTEST_LOGGER = logging.getLogger("conftest")
|
||||
LOG_FORMAT = "%(asctime)s %(levelname)7s:%(name)s %(message)s"
|
||||
|
||||
LOGGERS = {
|
||||
"conftest": None,
|
||||
"module": None,
|
||||
"test": None,
|
||||
} # type: Dict[str, Optional[logging.Logger]]
|
||||
|
||||
|
||||
def init_conftest_logger():
|
||||
"""
|
||||
This initializes the conftest logger which is used for pytest setup
|
||||
and configuration before tests are executed -- aka any logging in this
|
||||
file that is _not_ module-specific.
|
||||
"""
|
||||
LOGGERS["conftest"] = logging.getLogger("conftest")
|
||||
LOGGERS["conftest"].setLevel(logging.DEBUG)
|
||||
file_handler = logging.FileHandler("pytest.conftest.log.txt")
|
||||
file_handler.setFormatter(logging.Formatter(LOG_FORMAT))
|
||||
LOGGERS["conftest"].addHandler(file_handler)
|
||||
|
||||
|
||||
def avoid_duplicated_logs():
|
||||
"""
|
||||
Remove direct root logger output to file descriptors.
|
||||
This default is causing duplicates because all our messages go through
|
||||
regular logging as well and are thus displayed twice.
|
||||
"""
|
||||
todel = []
|
||||
for handler in logging.root.handlers:
|
||||
if handler.__class__ == logging.StreamHandler:
|
||||
# Beware: As for pytest 7.2.2, LiveLogging and LogCapture
|
||||
# handlers inherit from logging.StreamHandler
|
||||
todel.append(handler)
|
||||
for handler in todel:
|
||||
logging.root.handlers.remove(handler)
|
||||
|
||||
|
||||
init_conftest_logger()
|
||||
avoid_duplicated_logs()
|
||||
|
||||
|
||||
def init_module_logger(system_test_name: str, testdir: Path):
|
||||
logger = logging.getLogger(system_test_name)
|
||||
logger.handlers.clear()
|
||||
logger.setLevel(logging.DEBUG)
|
||||
handler = logging.FileHandler(testdir / "pytest.log.txt", mode="w")
|
||||
handler.setFormatter(logging.Formatter(LOG_FORMAT))
|
||||
logger.addHandler(handler)
|
||||
LOGGERS["module"] = logger
|
||||
|
||||
|
||||
def deinit_module_logger():
|
||||
for handler in LOGGERS["module"].handlers:
|
||||
handler.flush()
|
||||
handler.close()
|
||||
LOGGERS["module"] = None
|
||||
|
||||
|
||||
def init_test_logger(system_test_name: str, test_name: str):
|
||||
LOGGERS["test"] = logging.getLogger(f"{system_test_name}.{test_name}")
|
||||
|
||||
|
||||
def deinit_test_logger():
|
||||
LOGGERS["test"] = None
|
||||
|
||||
|
||||
def log(lvl: int, msg: str, *args, **kwargs):
|
||||
"""Log message with the most-specific logger currently available."""
|
||||
logger = LOGGERS["test"]
|
||||
if logger is None:
|
||||
logger = LOGGERS["module"]
|
||||
if logger is None:
|
||||
logger = LOGGERS["conftest"]
|
||||
assert logger is not None
|
||||
logger.log(lvl, msg, *args, **kwargs)
|
||||
|
||||
|
||||
def debug(msg: str, *args, **kwargs):
|
||||
log(logging.DEBUG, msg, *args, **kwargs)
|
||||
|
||||
|
||||
def info(msg: str, *args, **kwargs):
|
||||
log(logging.INFO, msg, *args, **kwargs)
|
||||
|
||||
|
||||
def warning(msg: str, *args, **kwargs):
|
||||
log(logging.WARNING, msg, *args, **kwargs)
|
||||
|
||||
|
||||
def error(msg: str, *args, **kwargs):
|
||||
log(logging.ERROR, msg, *args, **kwargs)
|
||||
|
||||
|
||||
def critical(msg: str, *args, **kwargs):
|
||||
log(logging.CRITICAL, msg, *args, **kwargs)
|
||||
|
|
@ -9,12 +9,10 @@
|
|||
# See the COPYRIGHT file distributed with this work for additional
|
||||
# information regarding copyright ownership.
|
||||
|
||||
from typing import Iterator, Optional, TextIO, Dict, Any, overload, List, Union
|
||||
from typing import Iterator, Optional, TextIO, Dict, Any
|
||||
|
||||
import abc
|
||||
import os
|
||||
import shlex
|
||||
import subprocess
|
||||
import time
|
||||
|
||||
|
||||
|
|
@ -289,79 +287,3 @@ class WatchLogFromHere(WatchLog):
|
|||
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
|
||||
|
|
@ -13,9 +13,12 @@ import concurrent.futures
|
|||
import os
|
||||
import subprocess
|
||||
import time
|
||||
|
||||
import dns.query
|
||||
import dns.update
|
||||
|
||||
import isctest
|
||||
|
||||
|
||||
def rndc_loop(test_state, server):
|
||||
rndc = os.getenv("RNDC")
|
||||
|
|
@ -37,7 +40,7 @@ def rndc_loop(test_state, server):
|
|||
time.sleep(1)
|
||||
|
||||
|
||||
def update_zone(test_state, zone, named_port, logger):
|
||||
def update_zone(test_state, zone, named_port):
|
||||
server = "10.53.0.2"
|
||||
for i in range(1000):
|
||||
if test_state["finished"]:
|
||||
|
|
@ -48,13 +51,13 @@ def update_zone(test_state, zone, named_port, logger):
|
|||
response = dns.query.udp(update, server, 10, named_port)
|
||||
assert response.rcode() == dns.rcode.NOERROR
|
||||
except dns.exception.Timeout:
|
||||
logger.info(f"error: query timeout for {zone}")
|
||||
isctest.log.info(f"error: query timeout for {zone}")
|
||||
|
||||
logger.info(f"Update of {server} zone {zone} successful")
|
||||
isctest.log.info(f"Update of {server} zone {zone} successful")
|
||||
|
||||
|
||||
# If the test has run to completion without named crashing, it has succeeded.
|
||||
def test_update_stress(named_port, logger):
|
||||
def test_update_stress(named_port):
|
||||
test_state = {"finished": False}
|
||||
|
||||
with concurrent.futures.ThreadPoolExecutor() as executor:
|
||||
|
|
@ -63,9 +66,7 @@ def test_update_stress(named_port, logger):
|
|||
updaters = []
|
||||
for i in range(5):
|
||||
zone = f"zone00000{i}.example."
|
||||
updaters.append(
|
||||
executor.submit(update_zone, test_state, zone, named_port, logger)
|
||||
)
|
||||
updaters.append(executor.submit(update_zone, test_state, zone, named_port))
|
||||
|
||||
# All the update_zone() tasks are expected to complete within 5
|
||||
# minutes. If they do not, we cannot assert immediately as that will
|
||||
|
|
|
|||
Loading…
Reference in a new issue