[reprotest] 01/01: Improve logging to try to get to the bottom of the jenkins failures
Ximin Luo
infinity0 at debian.org
Fri Oct 27 00:06:30 UTC 2017
This is an automated email from the git hooks/post-receive script.
infinity0 pushed a commit to branch master
in repository reprotest.
commit 249103cb90f071e977234ba04113ef40f742680c
Author: Ximin Luo <infinity0 at debian.org>
Date: Fri Oct 27 02:06:03 2017 +0200
Improve logging to try to get to the bottom of the jenkins failures
---
reprotest/__init__.py | 57 +++++++++++++++++++++++++------------------------
reprotest/build.py | 14 ++++++------
tests/mock_build.py | 31 ++++++++++++++-------------
tests/test_reprotest.py | 29 ++++++++++++++++++++++++-
4 files changed, 81 insertions(+), 50 deletions(-)
diff --git a/reprotest/__init__.py b/reprotest/__init__.py
index 1c85d71..afd3383 100644
--- a/reprotest/__init__.py
+++ b/reprotest/__init__.py
@@ -24,6 +24,7 @@ from reprotest.lib import adt_testbed
from reprotest.build import Build, VariationSpec, Variations, tool_missing
from reprotest import environ, presets, shell_syn
+logger = logging.getLogger(__name__)
VIRT_PREFIX = "autopkgtest-virt-"
@@ -75,7 +76,7 @@ def start_testbed(args, temp_dir, no_clean_on_error=False, host_distro='debian')
# Find the location of reprotest using setuptools and then get the
# path for the correct virt-server script.
server_path = get_server_path(args[0])
- logging.info('STARTING VIRTUAL SERVER %r', [server_path] + args[1:])
+ logger.info('STARTING VIRTUAL SERVER %r', [server_path] + args[1:])
# TODO: make the user configurable, like autopkgtest
testbed = Testbed([server_path] + args[1:], temp_dir,
getpass.getuser(), host_distro=host_distro)
@@ -88,7 +89,7 @@ def start_testbed(args, temp_dir, no_clean_on_error=False, host_distro='debian')
pass
except BaseException as e:
if no_clean_on_error:
- logging.warn("preserving temporary files in: %s", testbed.scratch)
+ logger.warn("preserving temporary files in: %s", testbed.scratch)
should_clean = False
raise
finally:
@@ -170,7 +171,7 @@ class BuildContext(collections.namedtuple('_BuildContext',
def plan_variations(self, build):
actions = self.variations.spec.actions()
- logging.info('build "%s": %s',
+ logger.info('build "%s": %s',
self.build_name,
", ".join("%s %s" % ("FIX" if not vary else "vary", v) for v, vary, action in actions))
for v, vary, action in actions:
@@ -178,15 +179,15 @@ class BuildContext(collections.namedtuple('_BuildContext',
return build
def copydown(self, testbed):
- logging.info("copying %s over to virtual server's %s", self.local_src, self.testbed_src)
+ logger.info("copying %s over to virtual server's %s", self.local_src, self.testbed_src)
testbed.command('copydown', (os.path.join(self.local_src, ''), self.testbed_src))
def copyup(self, testbed):
- logging.info("copying %s back from virtual server's %s", self.testbed_dist, self.local_dist)
+ logger.info("copying %s back from virtual server's %s", self.testbed_dist, self.local_dist)
testbed.command('copyup', (self.testbed_dist, os.path.join(self.local_dist, '')))
def run_build(self, testbed, build, old_env, artifact_pattern, testbed_build_pre, no_clean_on_error):
- logging.info("starting build with source directory: %s, artifact pattern: %s",
+ logger.info("starting build with source directory: %s, artifact pattern: %s",
self.testbed_src, artifact_pattern)
# we remove existing artifacts in case the build doesn't overwrite it
# e.g. like how make(1) sometimes works
@@ -194,12 +195,12 @@ class BuildContext(collections.namedtuple('_BuildContext',
['sh', '-ec', 'cd "%s" && rm -rf %s && %s' %
(self.testbed_src, artifact_pattern, testbed_build_pre or "true")])
build_script = build.to_script(no_clean_on_error)
- logging.info("executing build in %s", build.tree)
- logging.debug("#### REPROTEST BUILD ENVVARS ###################################################\n" +
+ logger.info("executing build in %s", build.tree)
+ logger.debug("#### REPROTEST BUILD ENVVARS ###################################################\n" +
"\n".join(environ.env_diff(old_env, build.env)))
- logging.debug("#### BEGIN REPROTEST BUILD SCRIPT ##############################################\n" +
+ logger.debug("#### BEGIN REPROTEST BUILD SCRIPT ##############################################\n" +
build_script)
- logging.debug("#### END REPROTEST BUILD SCRIPT ################################################")
+ logger.debug("#### END REPROTEST BUILD SCRIPT ################################################")
if 'root-on-testbed' in testbed.caps:
build_argv = ['su', '-s', '/bin/sh', testbed.user, '-c', 'set -e; ' + build_script]
@@ -209,7 +210,7 @@ class BuildContext(collections.namedtuple('_BuildContext',
testbed.check_exec2(build_argv,
xenv=['-i'] + ['%s=%s' % (k, v) for k, v in build.env.items()],
kind='build')
- logging.info("build successful, copying artifacts")
+ logger.info("build successful, copying artifacts")
dist_base = os.path.join(self.testbed_dist, VSRC_DIR)
testbed.check_exec2(shell_copy_pattern(dist_base, self.testbed_src, artifact_pattern))
# FIXME: `touch` is needed because of the FIXME in build.faketime(). we can rm it after that is fixed
@@ -229,14 +230,14 @@ def run_or_tee(progargs, filename, store_dir, *args, **kwargs):
def run_diff(dist_0, dist_1, diffoscope_args, store_dir):
if diffoscope_args is None: # don't run diffoscope
diffprogram = ['diff', '-ru', dist_0, dist_1]
- logging.info("Running diff: %r", diffprogram)
+ logger.info("Running diff: %r", diffprogram)
else:
diffprogram = ['diffoscope', dist_0, dist_1] + diffoscope_args
- logging.info("Running diffoscope: %r", diffprogram)
+ logger.info("Running diffoscope: %r", diffprogram)
retcode = run_or_tee(diffprogram, 'diffoscope.out', store_dir).returncode
if retcode == 0:
- logging.info("No differences between %s, %s", dist_0, dist_1)
+ logger.info("No differences between %s, %s", dist_0, dist_1)
if store_dir:
shutil.rmtree(dist_1)
os.symlink(os.path.basename(dist_0), dist_1)
@@ -256,11 +257,11 @@ class TestArgs(collections.namedtuple('_Test',
def of(cls, build_command, source_root, artifact_pattern, result_dir=None,
source_pattern=None, no_clean_on_error=False, diffoscope_args=[]):
artifact_pattern = shell_syn.sanitize_globs(artifact_pattern)
- logging.debug("artifact_pattern sanitized to: %s", artifact_pattern)
+ logger.debug("artifact_pattern sanitized to: %s", artifact_pattern)
if source_pattern:
source_pattern = shell_syn.sanitize_globs(source_pattern)
- logging.debug("source_pattern sanitized to: %s", source_pattern)
+ logger.debug("source_pattern sanitized to: %s", source_pattern)
return cls(build_command, source_root, artifact_pattern, result_dir,
source_pattern, no_clean_on_error, diffoscope_args)
@@ -282,7 +283,7 @@ class TestArgs(collections.namedtuple('_Test',
source_root = os.path.normpath(os.path.dirname(source_root))
source_root = str(source_root)
- logging.debug("virtual_server_args: %r", virtual_server_args)
+ logger.debug("virtual_server_args: %r", virtual_server_args)
# TODO: if no_clean_on_error then this shouldn't be rm'd
with tempfile.TemporaryDirectory() as temp_dir:
@@ -292,7 +293,7 @@ class TestArgs(collections.namedtuple('_Test',
source_root = new_source_root
if testbed_pre:
subprocess.check_call(["sh", "-ec", testbed_pre], cwd=new_source_root)
- logging.debug("source_root: %s", source_root)
+ logger.debug("source_root: %s", source_root)
# TODO: an alternative strategy is to run the testbed many times, one for each build
# not sure if it's worth implementing at this stage, but perhaps in the future.
@@ -661,7 +662,7 @@ def command_line(parser, argv):
def get_main_spec(parsed_args):
variations = [parsed_args.variations] + parsed_args.vary
if parsed_args.dont_vary:
- logging.warn("--dont-vary is deprecated; use --vary=-$variation instead")
+ logger.warn("--dont-vary is deprecated; use --vary=-$variation instead")
variations += ["-%s" % a for x in parsed_args.dont_vary for a in x.split(",")]
return VariationSpec().extend(variations)
@@ -678,8 +679,8 @@ def run(argv, dry_run=None):
verbosity = parsed_args.verbosity
adtlog.verbosity = verbosity - 1
- logging.basicConfig(level=30-10*verbosity)
- logging.debug('%r', parsed_args)
+ logger.basicConfig(level=30-10*verbosity)
+ logger.debug('%r', parsed_args)
if not dry_run and parsed_args.print_sudoers:
build.print_sudoers(get_main_spec(parsed_args))
@@ -703,9 +704,9 @@ def run(argv, dry_run=None):
elif first_arg == "auto":
build_command = first_arg
if parsed_args.artifact_pattern:
- logging.warn("old CLI form `reprotest auto <source_root>` detected, "
+ logger.warn("old CLI form `reprotest auto <source_root>` detected, "
"setting source_root to the second argument: %s", parsed_args.artifact_pattern)
- logging.warn("to avoid this warning, use instead `reprotest <source_root>` "
+ logger.warn("to avoid this warning, use instead `reprotest <source_root>` "
"or (if really necessary) `reprotest -s <source_root> auto <artifact>`")
source_root = parsed_args.artifact_pattern
parsed_args.artifact_pattern = None
@@ -715,7 +716,7 @@ def run(argv, dry_run=None):
parts = shlex.split(first_arg)
if len(parts) == 1:
if shutil.which(parts[0]) is None:
- logging.warn("XXX")
+ logger.warn("XXX")
raise RuntimeError("Not found, neither as a file nor as a command: %s" % first_arg)
# if len(parts) > 1 then it could be something like '( command )'
# which is valid despite '(' not existing.
@@ -741,7 +742,7 @@ def run(argv, dry_run=None):
auto_preset_expr = parsed_args.auto_preset_expr
values = presets.get_presets(source_root, virtual_server_args[0])
values = eval(auto_preset_expr, {'_': values}, {})
- logging.info("preset auto-selected: %r", values)
+ logger.info("preset auto-selected: %r", values)
build_command = values.build_command
artifact_pattern = artifact_pattern or values.artifact_pattern
testbed_pre = testbed_pre or values.testbed_pre
@@ -773,10 +774,10 @@ def run(argv, dry_run=None):
missing = [(var, tools) for var, tools in missing if tools]
for var, tools in missing:
if tools:
- logging.warn("Varying '%s' requires these program(s): %s", var, ", ".join(tools))
+ logger.warn("Varying '%s' requires these program(s): %s", var, ", ".join(tools))
if missing:
- logging.warn("Your build will probably fail, either install them or disable the variations.")
- logging.warn("(From a system package manager, simply install the 'optional' or 'recommended' "
+ logger.warn("Your build will probably fail, either install them or disable the variations.")
+ logger.warn("(From a system package manager, simply install the 'optional' or 'recommended' "
"dependencies of reprotest.)")
# Remaining args
diff --git a/reprotest/build.py b/reprotest/build.py
index c9b796c..cd3a09c 100644
--- a/reprotest/build.py
+++ b/reprotest/build.py
@@ -18,6 +18,8 @@ from reprotest import mdiffconf
from reprotest import shell_syn
from reprotest.utils import AttributeReplacer
+logger = logging.getLogger(__name__)
+
def tool_required(*tools):
def wrap(f):
@@ -238,10 +240,10 @@ def domain_host(ctx, build, vary):
# wrap our build command
_ = _.prepend_to_build_command('sudo', '-E', 'nsenter', *ns_args, *make_sudo_command(*current_user_group()))
else:
- logging.warn("Not using sudo for domain_host; it is recommended. Your build may fail.")
- logging.warn("Be sure to `echo 1 > /proc/sys/kernel/unprivileged_userns_clone` if on a Debian system.")
+ logger.warn("Not using sudo for domain_host; it is recommended. Your build may fail.")
+ logger.warn("Be sure to `echo 1 > /proc/sys/kernel/unprivileged_userns_clone` if on a Debian system.")
if "user_group" in ctx.spec and ctx.spec.user_group.available:
- logging.error("Incompatible variations: domain_host.use_sudo False, user_group.available non-empty.")
+ logger.error("Incompatible variations: domain_host.use_sudo False, user_group.available non-empty.")
raise ValueError("Incompatible variations; check the log for details.")
_ = _.prepend_to_build_command(*"unshare -r --uts".split(),
"sh", "-ec", r"""
@@ -405,7 +407,7 @@ def user_group(ctx, build, vary):
return build
if not ctx.spec.user_group.available:
- logging.warn("IGNORING user_group variation; supply more usergroups "
+ logger.warn("IGNORING user_group variation; supply more usergroups "
"with --variations=user_group.available+=USER1:GROUP1;USER2:GROUP2 or "
"alternatively, suppress this warning with --variations=-user_group")
return build
@@ -565,8 +567,8 @@ class Variations(collections.namedtuple('_Variations', 'spec verbosity')):
def print_sudoers(spec):
- logging.warn("This feature is EXPERIMENTAL, use at your own risk.")
- logging.warn("The output may be out-of-date, please file bugs if it doesn't work...")
+ logger.warn("This feature is EXPERIMENTAL, use at your own risk.")
+ logger.warn("The output may be out-of-date, please file bugs if it doesn't work...")
user, group = current_user_group()
a = "[a-zA-Z0-9]"
diff --git a/tests/mock_build.py b/tests/mock_build.py
index 35977d6..90c0635 100755
--- a/tests/mock_build.py
+++ b/tests/mock_build.py
@@ -2,6 +2,7 @@
# For details: reprotest/debian/copyright
import argparse
+import binascii
import locale
import os
import pathlib
@@ -18,18 +19,18 @@ if __name__ == '__main__':
arg_parser.add_argument('captures', nargs='*',
help='Reproducibility properties.')
captures = set(arg_parser.parse_args().captures)
- output = [b'']
+ output = ['']
# This test can theoretically fail by producing the same
# random bits in both runs, but it is extremely unlikely.
if 'irreproducible' in captures:
- output.append(os.urandom(1024))
+ output.append(binascii.b2a_hex(base64os.urandom(1024)))
# Like the above test, this test can theoretically fail by
# producing the same file order, but this is unlikely, if not
# as unlikely as in the above test.
if 'environment' in captures:
- output.append("\n".join(os.environ.keys()).encode("ascii"))
+ output.append("\n".join(os.environ.keys()))
if 'build_path' in captures:
- output.append(os.getcwd().encode("ascii"))
+ output.append(os.getcwd())
if 'fileordering' in captures:
# Ensure this temporary directory is created in the disorders
# mount point by passing the dir argument.
@@ -37,26 +38,26 @@ if __name__ == '__main__':
test_file_order = pathlib.Path(temp)
for i in range(20):
str((test_file_order/str(i)).touch())
- output.extend(p.name.encode('ascii') for p in test_file_order.iterdir())
+ output.extend(p.name for p in test_file_order.iterdir())
if 'home' in captures:
- output.append(os.path.expanduser('~').encode('ascii'))
+ output.append(os.path.expanduser('~'))
if 'kernel' in captures:
- output.append(subprocess.check_output(['uname', '-r']))
+ output.append(subprocess.check_output(['uname', '-r']).decode("utf-8"))
if 'locales' in captures:
- output.extend(l.encode('ascii') if l else b'(None)' for l in locale.getlocale())
- output.append(subprocess.check_output(['locale']))
+ output.extend(l or '(None)' for l in locale.getlocale())
+ output.append(subprocess.check_output(['locale']).decode("utf-8"))
if 'exec_path' in captures:
- output.extend(p.encode('ascii') for p in os.get_exec_path())
+ output.extend(p for p in os.get_exec_path())
if 'time' in captures:
- output.append(str(time.time()).encode('ascii'))
+ output.append(str(time.time()))
if 'timezone' in captures:
- output.append(str(time.timezone).encode('ascii'))
+ output.append(str(time.timezone))
if 'umask' in captures:
with tempfile.TemporaryDirectory(dir=str(pathlib.Path.cwd())) as temp:
test_permissions = pathlib.Path(temp)/'test_permissions'
test_permissions.touch()
- output.append(stat.filemode(test_permissions.stat().st_mode).encode('ascii'))
+ output.append(stat.filemode(test_permissions.stat().st_mode))
else:
os.umask(0o0022) # otherwise open() will capture the surrounding one in its file metadata
- with open('artifact', 'wb') as artifact:
- artifact.write(b''.join(output))
+ with open('artifact', 'w') as artifact:
+ artifact.write(''.join(output))
diff --git a/tests/test_reprotest.py b/tests/test_reprotest.py
index b631259..c2062c8 100644
--- a/tests/test_reprotest.py
+++ b/tests/test_reprotest.py
@@ -1,6 +1,8 @@
# Licensed under the GPL: https://www.gnu.org/licenses/gpl-3.0.en.html
# For details: reprotest/debian/copyright
+import contextlib
+import logging
import os
import subprocess
import sys
@@ -56,11 +58,36 @@ def test_simple_builds(virtual_server):
check_reproducibility('python3 mock_failure.py', virtual_server)
check_reproducibility('python3 mock_build.py irreproducible', virtual_server, False)
+ at contextlib.contextmanager
+def setup_logging(debug):
+ logger = logging.getLogger()
+ oldLevel = logger.getEffectiveLevel()
+ logger.setLevel(logging.DEBUG if debug else logging.WARNING)
+
+ ch = logging.StreamHandler()
+ ch.setLevel(logging.DEBUG)
+ logger.addHandler(ch)
+
+ formatter = logging.Formatter(
+ '%(asctime)s %(levelname).1s: %(name)s: %(message)s',
+ '%Y-%m-%d %H:%M:%S',
+ )
+ ch.setFormatter(formatter)
+ try:
+ yield logger
+ finally:
+ # restore old logging settings. this helps pytest not spew out errors
+ # like "ValueError: I/O operation on closed file", see
+ # https://github.com/pytest-dev/pytest/issues/14#issuecomment-272243656
+ logger.removeHandler(ch)
+ logger.setLevel(oldLevel)
+
# TODO: test all variations that we support
@pytest.mark.parametrize('captures', list(VARIATIONS.keys()))
def test_variations(virtual_server, captures):
expected = captures not in TEST_VARIATIONS
- check_reproducibility('python3 mock_build.py ' + captures, virtual_server, expected)
+ with setup_logging(True):
+ check_reproducibility('python3 mock_build.py ' + captures, virtual_server, expected)
@pytest.mark.need_builddeps
def test_self_build(virtual_server):
--
Alioth's /usr/local/bin/git-commit-notice on /srv/git.debian.org/git/reproducible/reprotest.git
More information about the Reproducible-commits
mailing list