From debfd8a5c5cc961bb2b008f700e08058707aefcc Mon Sep 17 00:00:00 2001 From: "Owen W. Taylor" Date: Thu, 29 Oct 2020 10:20:54 -0400 Subject: [PATCH 1/4] Combine mock stderr and stdout logs Mock doesn't normally log anything to stdout - so it's confusing to mention separate logs in the messages. Combine the two output streams together. (This is what koji does as well.) --- .../builder/KojiModuleBuilder.py | 4 ++-- .../builder/MockModuleBuilder.py | 20 ++++++++----------- module_build_service/builder/utils.py | 17 +++++++--------- 3 files changed, 17 insertions(+), 24 deletions(-) diff --git a/module_build_service/builder/KojiModuleBuilder.py b/module_build_service/builder/KojiModuleBuilder.py index b8044519..5b56f29a 100644 --- a/module_build_service/builder/KojiModuleBuilder.py +++ b/module_build_service/builder/KojiModuleBuilder.py @@ -356,7 +356,7 @@ class KojiModuleBuilder(GenericBuilder): fd.close() log.debug("Building %s.spec" % name) - # We are not interested in the rpmbuild stdout... + # We are not interested in the rpmbuild output... null_fd = open(os.devnull, "w") execute_cmd( [ @@ -369,7 +369,7 @@ class KojiModuleBuilder(GenericBuilder): "_sourcedir %s" % sources_dir, ], cwd=td, - stdout=null_fd, + output=null_fd, ) null_fd.close() sdir = os.path.join(td, "SRPMS") diff --git a/module_build_service/builder/MockModuleBuilder.py b/module_build_service/builder/MockModuleBuilder.py index ccfc5f29..370339c4 100644 --- a/module_build_service/builder/MockModuleBuilder.py +++ b/module_build_service/builder/MockModuleBuilder.py @@ -646,11 +646,9 @@ class MockModuleBuilder(GenericBuilder): mock_config = os.path.join( self.configdir, "mock-%s.cfg" % str(threading.current_thread().name)) - # Open the logs to which we will forward mock stdout/stderr. - mock_stdout_log = open( - os.path.join(self.resultsdir, artifact_name + "-mock-stdout.log"), "w") - mock_stderr_log = open( - os.path.join(self.resultsdir, artifact_name + "-mock-stderr.log"), "w") + # Open the log to which we will forward mock stdout/stderr. + mock_output_log = open( + os.path.join(self.resultsdir, artifact_name + "-mock-output.log"), "w") srpm = artifact_name resultsdir = builder.resultsdir @@ -658,12 +656,11 @@ class MockModuleBuilder(GenericBuilder): # Initialize mock. execute_cmd( ["mock", "-v", "-r", mock_config, "--init"], - stdout=mock_stdout_log, - stderr=mock_stderr_log, + output=mock_output_log, ) # Start the build and store results to resultsdir - builder.build(mock_stdout_log, mock_stderr_log) + builder.build(mock_output_log) srpm = find_srpm(resultsdir) # Emit messages simulating complete build. These messages @@ -687,8 +684,7 @@ class MockModuleBuilder(GenericBuilder): with open(os.path.join(resultsdir, "status.log"), "w") as f: f.write("failed\n") - mock_stdout_log.close() - mock_stderr_log.close() + mock_output_log.close() self._save_log(resultsdir, "state.log", artifact_name) self._save_log(resultsdir, "root.log", artifact_name) @@ -810,8 +806,8 @@ class BaseBuilder(object): self.resultsdir = resultsdir self.cmd = ["mock", "-v", "-r", config, "--no-clean", "--resultdir=%s" % resultsdir] - def build(self, stdout, stderr): - execute_cmd(self.cmd, stdout=stdout, stderr=stderr) + def build(self, output): + execute_cmd(self.cmd, output=output) class SRPMBuilder(BaseBuilder): diff --git a/module_build_service/builder/utils.py b/module_build_service/builder/utils.py index 5c779e09..cdffac60 100644 --- a/module_build_service/builder/utils.py +++ b/module_build_service/builder/utils.py @@ -26,27 +26,24 @@ def find_srpm(cod): return os.path.join(cod, f) -def execute_cmd(args, stdout=None, stderr=None, cwd=None): +def execute_cmd(args, output=None, cwd=None): """ - Executes command defined by `args`. If `stdout` or `stderr` is set to - Python file object, the stderr/stdout output is redirecter to that file. + Executes command defined by `args`. If `output` is set to + Python file object, the stderr and stdout output is redirected to that file. If `cwd` is set, current working directory is set accordingly for the executed command. :param args: list defining the command to execute. - :param stdout: Python file object to redirect the stdout to. - :param stderr: Python file object to redirect the stderr to. + :param output: Python file object to redirect the stderr and stdout to. :param cwd: string defining the current working directory for command. :raises RuntimeError: Raised when command exits with non-zero exit code. """ out_log_msg = "" - if stdout and hasattr(stdout, "name"): - out_log_msg += ", stdout log: %s" % stdout.name - if stderr and hasattr(stderr, "name"): - out_log_msg += ", stderr log: %s" % stderr.name + if output and hasattr(output, "name"): + out_log_msg += ", output log: %s" % output.name log.info("Executing the command \"%s\"%s" % (" ".join(args), out_log_msg)) - proc = subprocess.Popen(args, stdout=stdout, stderr=stderr, cwd=cwd) + proc = subprocess.Popen(args, stdout=output, stderr=output, cwd=cwd) out, err = proc.communicate() if proc.returncode != 0: From 728b96133dc52900a56ebacdb297622a8c3b5ad0 Mon Sep 17 00:00:00 2001 From: "Owen W. Taylor" Date: Thu, 29 Oct 2020 11:04:59 -0400 Subject: [PATCH 2/4] local builds: Don't call mock with -v Verbose output from mock is not useful for someone trying to figure out why their module build failed, and in fact makes it harder by adding quite a bit of extraneous noise. --- module_build_service/builder/MockModuleBuilder.py | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/module_build_service/builder/MockModuleBuilder.py b/module_build_service/builder/MockModuleBuilder.py index 370339c4..5ca4eb5e 100644 --- a/module_build_service/builder/MockModuleBuilder.py +++ b/module_build_service/builder/MockModuleBuilder.py @@ -655,7 +655,7 @@ class MockModuleBuilder(GenericBuilder): try: # Initialize mock. execute_cmd( - ["mock", "-v", "-r", mock_config, "--init"], + ["mock", "-r", mock_config, "--init"], output=mock_output_log, ) @@ -804,7 +804,7 @@ class BaseBuilder(object): def __init__(self, config, resultsdir): self.config = config self.resultsdir = resultsdir - self.cmd = ["mock", "-v", "-r", config, "--no-clean", "--resultdir=%s" % resultsdir] + self.cmd = ["mock", "-r", config, "--no-clean", "--resultdir=%s" % resultsdir] def build(self, output): execute_cmd(self.cmd, output=output) From cff90e587ac68d1a4094c4e41bc71e8eb0eec48b Mon Sep 17 00:00:00 2001 From: "Owen W. Taylor" Date: Wed, 27 Jan 2021 16:21:24 -0500 Subject: [PATCH 3/4] builder/utils/execute_cmd: remove useless return value and add a test Since we never pass in subprocess.PIPE for stdin/stdout/stderr, subprocess.communicate() does nothing, and the return out/err tuple was always empty. --- module_build_service/builder/utils.py | 3 +-- tests/test_builder/test_builder_utils.py | 16 ++++++++++++++++ 2 files changed, 17 insertions(+), 2 deletions(-) diff --git a/module_build_service/builder/utils.py b/module_build_service/builder/utils.py index cdffac60..35afac14 100644 --- a/module_build_service/builder/utils.py +++ b/module_build_service/builder/utils.py @@ -44,12 +44,11 @@ def execute_cmd(args, output=None, cwd=None): log.info("Executing the command \"%s\"%s" % (" ".join(args), out_log_msg)) proc = subprocess.Popen(args, stdout=output, stderr=output, cwd=cwd) - out, err = proc.communicate() + proc.wait() if proc.returncode != 0: err_msg = "Command '%s' returned non-zero value %d%s" % (args, proc.returncode, out_log_msg) raise RuntimeError(err_msg) - return out, err def get_koji_config(mbs_config): diff --git a/tests/test_builder/test_builder_utils.py b/tests/test_builder/test_builder_utils.py index 2af324d3..5ea337ea 100644 --- a/tests/test_builder/test_builder_utils.py +++ b/tests/test_builder/test_builder_utils.py @@ -17,6 +17,22 @@ from module_build_service.scheduler.db_session import db_session from tests import read_staged_data, scheduler_init_data +def test_execute_cmd(tmpdir, caplog): + logfile = str(tmpdir / "out.log") + with open(logfile, "w") as f: + utils.execute_cmd(["echo", "hello"], output=f) + + with open(logfile) as f: + assert f.read() == "hello\n" + + assert 'Executing the command "echo hello", output log: %s' % logfile in caplog.text + + +def test_execute_cmd_fail(): + with pytest.raises(RuntimeError): + utils.execute_cmd(["false"]) + + @pytest.mark.parametrize("variation", ("none", "empty", "already_downloaded")) @patch("requests.get") @patch("koji.ClientSession") From e776a77048f9c36946beadcc7a7210803f9958f3 Mon Sep 17 00:00:00 2001 From: "Owen W. Taylor" Date: Mon, 9 Nov 2020 12:09:57 -0500 Subject: [PATCH 4/4] Redirect createrepo_c output to the build logs It's more useful to have the createrepo_c output in the build logs than cluttering the build stdout. --- module_build_service/builder/MockModuleBuilder.py | 8 +++++--- module_build_service/builder/utils.py | 5 +++-- module_build_service/common/logger.py | 15 +++++++++++++++ tests/test_common/test_logger.py | 8 +++++++- 4 files changed, 30 insertions(+), 6 deletions(-) diff --git a/module_build_service/builder/MockModuleBuilder.py b/module_build_service/builder/MockModuleBuilder.py index 5ca4eb5e..5d7d8879 100644 --- a/module_build_service/builder/MockModuleBuilder.py +++ b/module_build_service/builder/MockModuleBuilder.py @@ -23,7 +23,7 @@ from module_build_service.builder.utils import ( get_koji_config, validate_koji_tag, ) -from module_build_service.common import conf, log, models +from module_build_service.common import build_logs, conf, log, models from module_build_service.common.koji import get_session from module_build_service.common.modulemd import Modulemd from module_build_service.common.utils import import_mmd, load_mmd_file, mmd_to_str @@ -409,14 +409,16 @@ class MockModuleBuilder(GenericBuilder): m1_mmd.add_rpm_artifact(artifact_to_add) # Generate repo. - execute_cmd(["/usr/bin/createrepo_c", "--pkglist", pkglist, path]) + execute_cmd(["/usr/bin/createrepo_c", "--pkglist", pkglist, path], + output=build_logs.current_log_stream) # ...and inject modules.yaml there if asked. if include_module_yaml: mmd_path = os.path.join(path, "modules.yaml") with open(mmd_path, "wb") as f: f.write(mmd_to_str(m1_mmd).encode("utf-8")) - execute_cmd(["/usr/bin/modifyrepo_c", "--mdtype=modules", mmd_path, repodata_path]) + execute_cmd(["/usr/bin/modifyrepo_c", "--mdtype=modules", mmd_path, repodata_path], + output=build_logs.current_log_stream) def _add_repo(self, name, baseurl, extra=""): """ diff --git a/module_build_service/builder/utils.py b/module_build_service/builder/utils.py index 35afac14..bb78b87b 100644 --- a/module_build_service/builder/utils.py +++ b/module_build_service/builder/utils.py @@ -13,7 +13,7 @@ import subprocess import munch import requests -from module_build_service.common import conf, log, models +from module_build_service.common import build_logs, conf, log, models from module_build_service.common.errors import ValidationError, ProgrammingError @@ -177,7 +177,8 @@ def create_local_repo_from_koji_tag(config, tag, repo_dir, archs=None): shutil.rmtree(repodata_path) log.info("Creating local repository in %s" % repo_dir) - execute_cmd(["/usr/bin/createrepo_c", repo_dir]) + execute_cmd(["/usr/bin/createrepo_c", repo_dir], + output=build_logs.current_log_stream) log.local_repo_done(tag, 'Finished downloading packages') diff --git a/module_build_service/common/logger.py b/module_build_service/common/logger.py index a29fc3b5..78d300b9 100644 --- a/module_build_service/common/logger.py +++ b/module_build_service/common/logger.py @@ -205,6 +205,21 @@ class ModuleBuildLogs(object): log.removeHandler(handler) del self.handlers[build.id] + @property + def current_log_stream(self): + # Imported here because of importing cycle between __init__.py, + # scheduler and models. + from module_build_service.scheduler.consumer import MBSConsumer + + if MBSConsumer.current_module_build_id: + handler = self.handlers.get(MBSConsumer.current_module_build_id) + if handler: + return handler.stream + else: + return sys.stderr + else: + return sys.stderr + class LocalRepo(object): def __init__(self, koji_tag): diff --git a/tests/test_common/test_logger.py b/tests/test_common/test_logger.py index 0ce0b2ab..0a049aad 100644 --- a/tests/test_common/test_logger.py +++ b/tests/test_common/test_logger.py @@ -8,6 +8,7 @@ from os import path import re import pytest import shutil +import sys import tempfile import textwrap from unittest.mock import patch @@ -69,10 +70,11 @@ class TestLogger: log.info("ignore this test msg") log.warning("ignore this test msg") log.error("ignore this test msg") + assert self.build_log.current_log_stream is sys.stderr self.build_log.stop(build) assert not os.path.exists(path) - # Try logging with current_module_build_id set to 2 and then to 2. + # Try logging with current_module_build_id set to 1 and then to 2. # Only messages with current_module_build_id set to 2 should appear in # the log. self.build_log.start(db_session, build) @@ -81,12 +83,14 @@ class TestLogger: log.info("ignore this test msg1") log.warning("ignore this test msg1") log.error("ignore this test msg1") + assert self.build_log.current_log_stream is sys.stderr MBSConsumer.current_module_build_id = 2 log.debug("ignore this test msg2") log.info("ignore this test msg2") log.warning("ignore this test msg2") log.error("ignore this test msg2") + self.build_log.current_log_stream.write("ignore this test output2") self.build_log.stop(build) assert os.path.exists(path) @@ -95,6 +99,7 @@ class TestLogger: # Note that DEBUG is not present unless configured server-wide. for level in ["INFO", "WARNING", "ERROR"]: assert data.find("MBS - {0} - ignore this test msg2".format(level)) != -1 + assert data.find("ignore this test output2") # Try to log more messages when build_log for module 1 is stopped. # New messages should not appear in a log. @@ -103,6 +108,7 @@ class TestLogger: log.info("ignore this test msg3") log.warning("ignore this test msg3") log.error("ignore this test msg3") + assert self.build_log.current_log_stream is sys.stderr self.build_log.stop(build) with open(path, "r") as f: data = f.read()