From f5100609aabe107c9fbf8830b48259a4739f0886 Mon Sep 17 00:00:00 2001 From: "Owen W. Taylor" Date: Mon, 9 Nov 2020 12:57:54 -0500 Subject: [PATCH 1/2] Filter console output through a special handler When running in local mode, add a special handler that filters log messages to the console to produce attractive output. Implemented behaviors include: - INFO level messages are only displayed if done through MBSLogger.console() rather than MBSLogger.info(). - Timestamps and thread names are omitted unless the local build is started with the -d option - Warning/error messages have the level highlighted in red - Special handling can be added to log messages, initially: - Long running operations can be displayed to the console as "Doing foo ... done" --- module_build_service/common/config.py | 2 + module_build_service/common/logger.py | 162 +++++++++++++++++- module_build_service/manage.py | 5 +- module_build_service/resolver/MBSResolver.py | 9 +- .../scheduler/default_modules.py | 4 + module_build_service/web/mse.py | 7 +- tests/test_common/test_logger.py | 111 +++++++++++- 7 files changed, 288 insertions(+), 12 deletions(-) diff --git a/module_build_service/common/config.py b/module_build_service/common/config.py index 05bef11e..4ad3ad0c 100644 --- a/module_build_service/common/config.py +++ b/module_build_service/common/config.py @@ -76,6 +76,8 @@ class ProdConfiguration(BaseConfiguration): class LocalBuildConfiguration(BaseConfiguration): + SYSTEM = "mock" + CACHE_DIR = "~/modulebuild/cache" LOG_LEVEL = "debug" MESSAGING = "drop" diff --git a/module_build_service/common/logger.py b/module_build_service/common/logger.py index b8fea378..a4c6b1e0 100644 --- a/module_build_service/common/logger.py +++ b/module_build_service/common/logger.py @@ -19,11 +19,12 @@ logging.warning("%s failed to build", task_id) """ -from __future__ import absolute_import +from __future__ import absolute_import, print_function import os import logging import logging.handlers import inspect +import sys levels = { "debug": logging.DEBUG, @@ -203,6 +204,128 @@ class ModuleBuildLogs(object): del self.handlers[build.id] +FG_COLORS = { + 'green': '32', + 'red': '91', +} + + +class MBSConsoleHandler(logging.Handler): + """ + Special logging.Handler that is responsible for creating attractive and + informative output when running a local build. To allow certain log + messages to be handled differently for console output, methods in this + class decorated with the @console_message decorator are propagated to + the MBSLogger class. + + When MBSLogger method is called, a normal log record is generated using + the format string from the decoration. The record is logged normally + in the build log or to a non-console handler, but when the event is + received by this handler, the original decorated method is called instead. + This method can optionally return a new string to be output to the log, + or simply update internal state without logging anything. + + This handler also implements the behavior that when the handler level + is at its default INFO state, INFO level log messages are only shown if + they have an extra 'console' attribute added by calling MBSLogger.console() + rather than MBSLogger.info(). This allow further trimming down the + set of messages logged to the console without losing the distinction between + DEBUG and INFO. + """ + console_messages = {} + + def __init__(self, *args, stream=sys.stderr, **kwargs): + self.stream = stream + + self.tty = self.stream.isatty() + + self.long_running = None + + self.debug_formatter = logging.Formatter(log_format) + self.info_formatter = logging.Formatter("%(message)s") + self.error_formatter = logging.Formatter( + self.style("%(levelname)s", bold=True, fg='red') + " - %(message)s") + + logging.Handler.__init__(self, *args, level=logging.INFO, **kwargs) + + def style(self, text, bold=False, fg=None): + if self.tty: + start = "" + if bold: + start += "\033[1m" + if fg: + start += "\033[" + FG_COLORS[fg] + "m" + return start + text + "\033[0m" + else: + return text + + def emit(self, record): + if self.level == logging.INFO and record.levelno == logging.INFO: + if not getattr(record, 'console', False): + return + + self.acquire() + try: + if self.tty: + self.status_stream.erase() + + console_message_callback = self.console_messages.get(record.msg) + if console_message_callback: + formatted = console_message_callback(self, *record.args) + else: + if self.level < logging.INFO: + formatted = self.debug_formatter.format(record) + elif record.levelno == logging.INFO: + formatted = self.info_formatter.format(record) + else: + formatted = self.error_formatter.format(record) + + if formatted: + if self.long_running: + print(file=self.stream) + self.long_running = None + + print(formatted, file=self.stream) + finally: + self.release() + + def console_message(msg): + def decorate(f): + f.console_message = msg + return f + + return decorate + + @console_message("%s ...") + def long_running_start(self, msg): + if self.long_running: + print("", file=self.stream) + self.long_running = msg + print("{} ...".format(msg), + file=self.stream, end="") + self.stream.flush() + + @console_message("%s ... done") + def long_running_end(self, msg): + if self.long_running == msg: + self.long_running = None + print(" done", + file=self.stream) + else: + self.long_running = None + return "{} ... done".format(msg) + + @classmethod + def _setup_console_messages(cls): + for value in cls.__dict__.values(): + console_message = getattr(value, 'console_message', None) + if console_message: + cls.console_messages[console_message] = value + + +MBSConsoleHandler._setup_console_messages() + + class MBSLogger: def __init__(self): self._logger = logging.getLogger("MBS") @@ -231,6 +354,9 @@ class MBSLogger: def info(self, *args, **kwargs): return self._log_call("info", args, kwargs) + def console(self, *args, **kwargs): + return self._log_call("info", args, kwargs, console=True) + def warning(self, *args, **kwargs): return self._log_call("warning", args, kwargs) @@ -246,15 +372,38 @@ class MBSLogger: def log(self, *args, **kwargs): return self._log_call("log", args, kwargs) - def _log_call(self, level_name, args, kwargs): + def _log_call(self, level_name, args, kwargs, console=False): caller_filename = inspect.stack()[2][1] caller_filename = os.path.normpath(caller_filename) if not caller_filename.startswith(self._current_path): log_name = "MBS" else: log_name = "MBS" + caller_filename[len(self._current_path):-3].replace("/", ".") + + if console: + kwargs.setdefault('extra', {})['console'] = True + return getattr(logging.getLogger(log_name), level_name)(*args, **kwargs) + # @console_message decorated methods of MBSConsoleHandler are also propagated + # as additional methods of this class + + @classmethod + def _setup_console_message(cls, msg, callback): + def log_method(self, *args): + self.console(msg, *args) + + log_method.__name__ = callback.__name__ + setattr(cls, callback.__name__, log_method) + + @classmethod + def _setup_console_messages(cls): + for msg, callback in MBSConsoleHandler.console_messages.items(): + cls._setup_console_message(msg, callback) + + +MBSLogger._setup_console_messages() + def str_to_log_level(level): """ @@ -280,7 +429,14 @@ def init_logging(conf): log_backend = conf.log_backend if not log_backend or len(log_backend) == 0 or log_backend == "console": - logging.basicConfig(level=conf.log_level, format=log_format) + if conf.system == "mock": + root_logger = logging.getLogger() + root_logger.setLevel(conf.log_level) + handler = MBSConsoleHandler() + root_logger.addHandler(handler) + else: + logging.basicConfig(level=conf.log_level, format=log_format) + log = MBSLogger() log.level = conf.log_level else: diff --git a/module_build_service/manage.py b/module_build_service/manage.py index 82767753..bbb3243e 100755 --- a/module_build_service/manage.py +++ b/module_build_service/manage.py @@ -135,10 +135,9 @@ def build_module_locally( build_logs.buffer_initially() # if debug is not specified, set log level of console to INFO - if not log_debug: + if log_debug: for handler in logging.getLogger().handlers: - if isinstance(handler, logging.StreamHandler): - handler.setLevel(logging.INFO) + handler.setLevel(logging.DEBUG) if "SERVER_NAME" not in app.config or not app.config["SERVER_NAME"]: app.config["SERVER_NAME"] = "localhost" diff --git a/module_build_service/resolver/MBSResolver.py b/module_build_service/resolver/MBSResolver.py index 512f5b69..7c170caf 100644 --- a/module_build_service/resolver/MBSResolver.py +++ b/module_build_service/resolver/MBSResolver.py @@ -3,19 +3,16 @@ """MBS handler functions.""" from __future__ import absolute_import -import logging import dogpile.cache -from module_build_service.common import models +from module_build_service.common import log, models from module_build_service.common.config import conf from module_build_service.common.errors import StreamNotXyz, UnprocessableEntity from module_build_service.common.request_utils import requests_session from module_build_service.common.utils import load_mmd, import_mmd from module_build_service.resolver.KojiResolver import KojiResolver -log = logging.getLogger() - def _canonicalize_state(state): if isinstance(state, int): @@ -441,6 +438,8 @@ class MBSResolver(KojiResolver): % (", ".join([name, stream, str(version), context]), strict) ) + log.long_running_start("Loading build dependencies") + # This is the set we're going to build up and return. module_tags = {} @@ -485,6 +484,8 @@ class MBSResolver(KojiResolver): module_tags.setdefault(m["koji_tag"], []) module_tags[m["koji_tag"]].append(load_mmd(m["modulemd"])) + log.long_running_end("Loading build dependencies") + return module_tags def resolve_requires(self, requires): diff --git a/module_build_service/scheduler/default_modules.py b/module_build_service/scheduler/default_modules.py index 6846d13e..cad71f51 100644 --- a/module_build_service/scheduler/default_modules.py +++ b/module_build_service/scheduler/default_modules.py @@ -243,6 +243,8 @@ def handle_collisions_with_base_module_rpms(mmd, arches, force_for_old_dnf=False ) return + log.long_running_start("Finding RPMs to exclude from the base modules") + log.info("Finding any buildrequired modules that collide with the RPMs in the base modules") bm_tags = set() non_bm_tags = set() @@ -300,6 +302,8 @@ def handle_collisions_with_base_module_rpms(mmd, arches, force_for_old_dnf=False xmd["mbs"]["ursine_rpms"] = list(conflicts) mmd.set_xmd(xmd) + log.long_running_end("Finding RPMs to exclude from the base modules") + def _get_rpms_from_tags(koji_session, tags, arches): """ diff --git a/module_build_service/web/mse.py b/module_build_service/web/mse.py index c55ed3a7..e6704600 100644 --- a/module_build_service/web/mse.py +++ b/module_build_service/web/mse.py @@ -255,6 +255,8 @@ def generate_expanded_mmds(db_session, mmd, raise_if_stream_ambigous=False, defa if not default_streams: default_streams = {} + log.long_running_start("Expanding module streams to determine build requirements") + # Create local copy of mmd, because we will expand its dependencies, # which would change the module. current_mmd = mmd.copy() @@ -284,7 +286,7 @@ def generate_expanded_mmds(db_session, mmd, raise_if_stream_ambigous=False, defa # Resolve the dependencies between modules and get the list of all valid # combinations in which we can build this module. requires_combinations = mmd_resolver.solve(current_mmd) - log.info("Resolving done, possible requires: %r", requires_combinations) + log.long_running_end("Expanding module streams to determine build requirements") # This is where we are going to store the generated MMDs. mmds = [] @@ -383,6 +385,9 @@ def generate_expanded_mmds(db_session, mmd, raise_if_stream_ambigous=False, defa nsvc = ":".join(nsvca.split(":")[:-1]) br_list.append(nsvc) + log.console("Build requirements #%s:\n %s", + len(mmds) + 1, ", ".join(br_list)) + # Resolve the buildrequires and store the result in XMD. if "mbs" not in xmd: xmd["mbs"] = {} diff --git a/tests/test_common/test_logger.py b/tests/test_common/test_logger.py index 8ea24546..daef1090 100644 --- a/tests/test_common/test_logger.py +++ b/tests/test_common/test_logger.py @@ -1,14 +1,18 @@ # -*- coding: utf-8 -*- # SPDX-License-Identifier: MIT from __future__ import absolute_import +import io +import logging import os from os import path import pytest import shutil import tempfile +import textwrap +from unittest.mock import patch from module_build_service.common import log, models -from module_build_service.common.logger import ModuleBuildLogs +from module_build_service.common.logger import ModuleBuildLogs, MBSConsoleHandler from module_build_service.scheduler.consumer import MBSConsumer from module_build_service.scheduler.db_session import db_session @@ -113,3 +117,108 @@ class TestLogger: log2 = ModuleBuildLogs("/some/path", "build-{name}-{stream}-{version}.log") assert log2.name(db_session, build) == "build-nginx-1-2.log" assert log2.path(db_session, build) == "/some/path/build-nginx-1-2.log" + + +class TestConsoleHandler: + def terminal(test_method): + test_method.terminal = True + return test_method + + def level(level): + def decorate(test_method): + test_method.level = level + return test_method + + return decorate + + def setup_method(self, test_method): + self.stream = io.StringIO() + + if getattr(test_method, 'terminal', False): + self.get_terminal_size_patcher = patch("os.get_terminal_size") + mock_get_terminal_size = self.get_terminal_size_patcher.start() + mock_get_terminal_size.return_value = os.terminal_size((80, 24)) + + self.stream.isatty = lambda: True + self.stream.fileno = lambda: 42 + + self.handler = MBSConsoleHandler(stream=self.stream) + self.handler.level = getattr(test_method, 'level', logging.INFO) + + logging.getLogger().addHandler(self.handler) + + def teardown_method(self, test_method): + logging.getLogger().removeHandler(self.handler) + + if getattr(test_method, 'terminal', False): + self.get_terminal_size_patcher.stop() + + def log_messages(self): + log.debug("Debug") + log.info("Info") + log.console("Console") + log.warning("Warning") + log.error("Error") + + def test_console_basic(self): + self.log_messages() + + value = self.stream.getvalue() + assert "Debug" not in value + assert "Info" not in value + assert "Console" in value + assert "\nWARNING - Warning" in value + assert "\nERROR - Error" in value + + @terminal + def test_console_terminal(self): + self.log_messages() + + value = self.stream.getvalue() + assert "Debug" not in value + assert "Info" not in value + assert "Console" in value + assert "\n\x1b[1m\x1b[91mWARNING\x1b[0m - Warning" in value + assert "\n\x1b[1m\x1b[91mERROR\x1b[0m - Error" in value + + @level(logging.DEBUG) + @terminal + def test_console_debug(self): + self.log_messages() + + value = self.stream.getvalue() + assert "MainThread - MBS - DEBUG - Debug" in value + assert "MainThread - MBS - INFO - Info" in value + assert "MainThread - MBS - INFO - Console" in value + assert "MainThread - MBS - WARNING - Warning" in value + assert "MainThread - MBS - ERROR - Error" in value + + @terminal + def test_console_long_running(self): + log.long_running_start("Frobulating") + log.long_running_end("Frobulating") + log.console("---") + + log.long_running_start("Frobulating") + log.console("Now Hear This") + log.long_running_end("Frobulating") + log.console("---") + + log.long_running_start("Frobulating") + log.long_running_start("Blabbing") + log.long_running_end("Blabbing") + log.long_running_end("Frobulating") + + print(self.stream.getvalue()) + + assert self.stream.getvalue() == textwrap.dedent("""\ + Frobulating ... done + --- + Frobulating ... + Now Hear This + Frobulating ... done + --- + Frobulating ... + Blabbing ... done + Frobulating ... done + """) From 646b0590ee54daa8b422d96d4da4fd0fd31ce8d2 Mon Sep 17 00:00:00 2001 From: "Owen W. Taylor" Date: Mon, 9 Nov 2020 13:12:01 -0500 Subject: [PATCH 2/2] MBSConsoleHandler: show status of ongoing repository downloads When downloading files from Koji to make a local repository, display a temporary status of which files are being displayed to the console appended after any log messages. Updates are done by erasing the status that was written, adding a log message, then writing the status again. --- module_build_service/builder/utils.py | 30 ++- module_build_service/common/logger.py | 142 ++++++++++ module_build_service/common/models.py | 4 + module_build_service/scheduler/batches.py | 4 +- .../scheduler/handlers/modules.py | 13 +- tests/test_common/test_logger.py | 254 ++++++++++++++++-- 6 files changed, 407 insertions(+), 40 deletions(-) diff --git a/module_build_service/builder/utils.py b/module_build_service/builder/utils.py index 1e060714..5c779e09 100644 --- a/module_build_service/builder/utils.py +++ b/module_build_service/builder/utils.py @@ -83,6 +83,8 @@ def create_local_repo_from_koji_tag(config, tag, repo_dir, archs=None): # Placed here to avoid py2/py3 conflicts... import koji + log.local_repo_start(tag) + if not archs: archs = ["x86_64", "noarch"] @@ -100,6 +102,7 @@ def create_local_repo_from_koji_tag(config, tag, repo_dir, archs=None): if not builds: log.debug("No builds are associated with the tag %r", tag) + log.local_repo_done(tag, 'No builds to download') return False # Reformat builds so they are dict with build_id as a key. @@ -130,9 +133,12 @@ def create_local_repo_from_koji_tag(config, tag, repo_dir, archs=None): os.remove(local_fn) repo_changed = True url = pathinfo.build(build_info) + "/" + fname - download_args.append((url, local_fn)) + download_args.append((tag, url, local_fn)) - log.info("Downloading %d packages from Koji tag %s to %s" % (len(download_args), tag, repo_dir)) + if repo_changed: + log.local_repo_start_downloads(tag, len(download_args), repo_dir) + else: + log.local_repo_done(tag, 'All builds already downloaded') # Create the output directory try: @@ -141,22 +147,26 @@ def create_local_repo_from_koji_tag(config, tag, repo_dir, archs=None): if exception.errno != errno.EEXIST: raise - def _download_file(url_and_dest): + def _download_file(tag_url_and_dest): """ Download a file in a memory efficient manner - :param url_and_dest: a tuple containing the URL and the destination to download to + :param url_and_dest: a tuple containing the tag, the URL and the destination to download to :return: None """ - log.info("Downloading {0}...".format(url_and_dest[0])) - if len(url_and_dest) != 2: - raise ValueError("url_and_dest must have two values") + assert len(tag_url_and_dest) == 3, "tag_url_and_dest must have three values" - rv = requests.get(url_and_dest[0], stream=True, timeout=60) - with open(url_and_dest[1], "wb") as f: + tag, url, dest = tag_url_and_dest + + log.local_repo_start_download(tag, url) + + rv = requests.get(url, stream=True, timeout=60) + with open(dest, "wb") as f: for chunk in rv.iter_content(chunk_size=1024): if chunk: f.write(chunk) + log.local_repo_done_download(tag, url) + # Download the RPMs four at a time. pool = ThreadPool(4) try: @@ -173,6 +183,8 @@ def create_local_repo_from_koji_tag(config, tag, repo_dir, archs=None): log.info("Creating local repository in %s" % repo_dir) execute_cmd(["/usr/bin/createrepo_c", repo_dir]) + log.local_repo_done(tag, 'Finished downloading packages') + return True diff --git a/module_build_service/common/logger.py b/module_build_service/common/logger.py index a4c6b1e0..a29fc3b5 100644 --- a/module_build_service/common/logger.py +++ b/module_build_service/common/logger.py @@ -24,6 +24,8 @@ import os import logging import logging.handlers import inspect +import re +import signal import sys levels = { @@ -204,6 +206,95 @@ class ModuleBuildLogs(object): del self.handlers[build.id] +class LocalRepo(object): + def __init__(self, koji_tag): + self.koji_tag = koji_tag + self.current_downloads = set() + self.total_downloads = 0 + self.completed_downloads = 0 + self.status = "" + + def start_downloads(self, total): + self.status = "Downloading packages" + self.total_downloads = total + + def start_download(self, url): + self.current_downloads.add(url) + + def done_download(self, url): + self.current_downloads.remove(url) + self.completed_downloads += 1 + + def show_status(self, stream, style): + if self.total_downloads > 0: + count = " {}/{}".format(self.completed_downloads, self.total_downloads) + else: + count = "" + + print("{}: {}{}".format(style(self.koji_tag, bold=True), self.status, count), + file=stream) + for url in self.current_downloads: + print(" {}".format(os.path.basename(url)), file=stream) + + +# Used to split aaa\nbbbb\n to ('aaa', '\n', 'bbb', '\n') +NL_DELIMITER = re.compile('(\n)') +# Matches *common* ANSI control sequences +# https://en.wikipedia.org/wiki/ANSI_escape_code#CSI_sequences +CSI_SEQUENCE = re.compile('\033[0-9;]*[A-Za-z]') + + +class EraseableStream(object): + """ + Wrapper around a terminal stream for writing output that can be + erased. + """ + + def __init__(self, target): + self.target = target + self.lines_written = 0 + # We assume that the EraseableStream starts writing at column 0 + self.column = 0 + self.resize() + + def resize(self): + self.size = os.get_terminal_size(self.target.fileno()) + + def write(self, string): + # We want to track how many lines we've written so that we can + # back up and erase them. Tricky thing is handling wrapping. + + # Strip control sequences + plain = CSI_SEQUENCE.sub('', string) + + for piece in NL_DELIMITER.split(plain): + if piece == '\n': + self.column = 0 + self.lines_written += 1 + else: + self.column = self.column + len(piece) + # self.column == self.size.column doesn't wrap - + # normal modern terminals wrap when a character is written + # that would be off-screen, not immediately when the + # line is full. + while self.column > self.size.columns: + self.column -= self.size.columns + self.lines_written += 1 + + self.target.write(string) + + def erase(self): + if self.column > 0: + # move cursor to the beginning of line and delete whole line + self.target.write("\033[0G\033[2K") + for i in range(0, self.lines_written): + # move up cursor and delete whole line + self.target.write("\033[1A\033[2K") + + self.lines_written = 0 + self.column = 0 + + FG_COLORS = { 'green': '32', 'red': '91', @@ -238,8 +329,13 @@ class MBSConsoleHandler(logging.Handler): self.stream = stream self.tty = self.stream.isatty() + if self.tty: + self.status_stream = EraseableStream(self.stream) + else: + self.status_stream = None self.long_running = None + self.repos = {} self.debug_formatter = logging.Formatter(log_format) self.info_formatter = logging.Formatter("%(message)s") @@ -286,6 +382,12 @@ class MBSConsoleHandler(logging.Handler): self.long_running = None print(formatted, file=self.stream) + + if self.tty: + if self.repos: + print('------------------------------', file=self.status_stream) + for repo in self.repos.values(): + repo.show_status(self.status_stream, self.style) finally: self.release() @@ -296,6 +398,10 @@ class MBSConsoleHandler(logging.Handler): return decorate + def resize(self): + if self.status_stream: + self.status_stream.resize() + @console_message("%s ...") def long_running_start(self, msg): if self.long_running: @@ -315,6 +421,37 @@ class MBSConsoleHandler(logging.Handler): self.long_running = None return "{} ... done".format(msg) + @console_message("%s: Making local repository for Koji tag") + def local_repo_start(self, koji_tag): + repo = LocalRepo(koji_tag) + self.repos[koji_tag] = repo + + return "{}: Making local repository for Koji tag".format( + self.style(koji_tag, bold=True)) + + @console_message("%s: %s") + def local_repo_done(self, koji_tag, message): + del self.repos[koji_tag] + + return "{}: {}".format( + self.style(koji_tag, bold=True), + self.style(message, fg='green', bold=True)) + + @console_message("%s: Downloading %d packages from Koji tag to %s") + def local_repo_start_downloads(self, koji_tag, num_packages, repo_dir): + repo = self.repos[koji_tag] + repo.start_downloads(num_packages) + + @console_message("%s: Downloading %s") + def local_repo_start_download(self, koji_tag, url): + repo = self.repos[koji_tag] + repo.start_download(url) + + @console_message("%s: Done downloading %s") + def local_repo_done_download(self, koji_tag, url): + repo = self.repos[koji_tag] + repo.done_download(url) + @classmethod def _setup_console_messages(cls): for value in cls.__dict__.values(): @@ -434,6 +571,11 @@ def init_logging(conf): root_logger.setLevel(conf.log_level) handler = MBSConsoleHandler() root_logger.addHandler(handler) + + def handle_sigwinch(*args): + handler.resize() + + signal.signal(signal.SIGWINCH, handle_sigwinch) else: logging.basicConfig(level=conf.log_level, format=log_format) diff --git a/module_build_service/common/models.py b/module_build_service/common/models.py index ac0901e5..a64bf048 100644 --- a/module_build_service/common/models.py +++ b/module_build_service/common/models.py @@ -606,6 +606,10 @@ class ModuleBuild(MBSBase): def nvr_string(self): return kobo.rpmlib.make_nvr(self.nvr) + @property + def nsvc(self): + return "{}:{}:{}:{}".format(self.name, self.stream, self.version, self.context) + @classmethod def create( cls, diff --git a/module_build_service/scheduler/batches.py b/module_build_service/scheduler/batches.py index 97553974..f8b873dd 100644 --- a/module_build_service/scheduler/batches.py +++ b/module_build_service/scheduler/batches.py @@ -255,7 +255,9 @@ def start_next_batch_build(config, module, builder, components=None): log.info("Skipping build of batch %d, no component to build.", module.batch) return start_next_batch_build(config, module, builder) - log.info("Starting build of next batch %d, %s" % (module.batch, unbuilt_components)) + log.console("Starting build of next batch %d: %s", + module.batch, + ', '.join(c.package for c in unbuilt_components)) # Attempt to reuse any components possible in the batch before attempting to build any unbuilt_components_after_reuse = [] diff --git a/module_build_service/scheduler/handlers/modules.py b/module_build_service/scheduler/handlers/modules.py index 0587fbb9..149723fd 100644 --- a/module_build_service/scheduler/handlers/modules.py +++ b/module_build_service/scheduler/handlers/modules.py @@ -145,6 +145,8 @@ def done(msg_id, module_build_id, module_build_state): build.transition(db_session, conf, state=models.BUILD_STATES["ready"]) db_session.commit() + log.console("Finished building %s", build.nsvc) + build_logs.stop(build) GenericBuilder.clear_cache(build) @@ -181,7 +183,8 @@ def init(msg_id, module_build_id, module_build_state): build_logs.build_logs_dir = mock_resultsdir build_logs.start(db_session, build) - log.info("Start to handle %s which is in init state.", build.mmd().get_nsvc()) + log.console("Starting to build %s", build.nsvc) + log.console("Logging to %s", build_logs.path(db_session, build)) error_msg = "" failure_reason = "unspec" @@ -413,7 +416,8 @@ def wait(msg_id, module_build_id, module_build_state): raise if not build.component_builds: - log.info("There are no components in module %r, skipping build" % build) + log.console("There are no components in module %s, skipping build", + build.nsvc) build.transition(db_session, conf, state=models.BUILD_STATES["build"]) db_session.add(build) db_session.commit() @@ -426,13 +430,14 @@ def wait(msg_id, module_build_id, module_build_state): # If all components in module build will be reused, we don't have to build # module-build-macros, because there won't be any build done. if attempt_to_reuse_all_components(builder, build): - log.info("All components have been reused for module %r, skipping build" % build) + log.console("All components have been reused for module %s, skipping build", + build.nsvc) build.transition(db_session, conf, state=models.BUILD_STATES["build"]) db_session.add(build) db_session.commit() return [] - log.debug("Starting build batch 1") + log.console("Starting build of batch 1: module-build-macros") build.batch = 1 db_session.commit() diff --git a/tests/test_common/test_logger.py b/tests/test_common/test_logger.py index daef1090..0ce0b2ab 100644 --- a/tests/test_common/test_logger.py +++ b/tests/test_common/test_logger.py @@ -5,6 +5,7 @@ import io import logging import os from os import path +import re import pytest import shutil import tempfile @@ -119,6 +120,125 @@ class TestLogger: assert log2.path(db_session, build) == "/some/path/build-nginx-1-2.log" +class FakeTerminal(object): + """ + Just enough terminal to allow meaningfully testing the terminal fanciness + in MBSConsoleHandler + """ + + def __init__(self): + self.serializer = FakeTerminalSerializer(self) + self.reset() + self.columns = 80 + self.rows = 24 + + def get_size(self): + return os.terminal_size((self.columns, self.rows)) + + def isatty(self): + return True + + def fileno(self): + return 42 + + def flush(self): + pass + + def write(self, raw): + for m in re.finditer(r'\n|\033\[[0-9;]*[A-Za-z]|\033|[^\033\n]*', raw): + piece = m.group(0) + if piece == '\n': + self._next_row() + elif piece == '\033[0m': + self.cur_attr = "x" + elif piece == '\033[1m': + self.cur_attr = self.cur_attr.upper() + elif piece == '\033[32m': + self.cur_attr = 'G' if self.cur_attr.isupper() else 'g' + elif piece == '\033[91m': + self.cur_attr = 'R' if self.cur_attr.isupper() else 'r' + elif piece == '\033[0G': + self.cursor_column = 0 + elif piece == '\033[1A': + self.cursor_column = 0 + self.cursor_row = max(self.cursor_row - 1, 0) + elif piece == '\033[2K': + self.text[self.cursor_row] = ' ' * self.cursor_column + self.attrs[self.cursor_row] = 'x' * self.cursor_column + elif piece.startswith('\033['): + raise RuntimeError("Unhandled CSI sequence: %r", piece) + else: + pos = 0 + while len(piece) - pos > self.columns - self.cursor_column: + to_insert = self.columns - self.cursor_column + self._insert(piece[pos:pos + to_insert]) + pos += to_insert + self._next_row() + self._insert(piece[pos:]) + + def _next_row(self): + self.cursor_row += 1 + if self.cursor_row == len(self.text): + self.text.append('') + self.attrs.append('') + self.cursor_column = 0 + + def _insert(self, string): + text = self.text[self.cursor_row] + self.text[self.cursor_row] = (text[0:self.cursor_column] + + string + + text[self.cursor_column + len(string):]) + attrs = self.attrs[self.cursor_row] + self.attrs[self.cursor_row] = (attrs[0:self.cursor_column] + + self.cur_attr * len(string) + + attrs[self.cursor_column + len(string):]) + self.cursor_column += len(string) + + def reset(self): + self.text = [''] + self.attrs = [''] + self.cur_attr = 'x' + self.cursor_row = 0 + self.cursor_column = 0 + + def serialize(self): + return self.serializer.serialize() + + +class FakeTerminalSerializer(object): + """Serializes the terminal contents with tags to represent attributes""" + + def __init__(self, terminal): + self.terminal = terminal + + def serialize(self): + self.result = io.StringIO() + self.last_attr = 'x' + + for row in range(0, len(self.terminal.text)): + text = self.terminal.text[row] + attrs = self.terminal.attrs[row] + + for col in range(0, len(text)): + self.set_attr(attrs[col]) + self.result.write(text[col]) + self.set_attr('x') + self.result.write('\n') + + value = self.result.getvalue() + self.result = None + + return value + + def set_attr(self, attr): + if attr != self.last_attr: + if self.last_attr != 'x': + self.result.write('') + if attr != 'x': + self.result.write('<' + attr + '>') + self.last_attr = attr + + class TestConsoleHandler: def terminal(test_method): test_method.terminal = True @@ -132,15 +252,18 @@ class TestConsoleHandler: return decorate def setup_method(self, test_method): - self.stream = io.StringIO() - if getattr(test_method, 'terminal', False): + self.stream = FakeTerminal() + self.get_terminal_size_patcher = patch("os.get_terminal_size") mock_get_terminal_size = self.get_terminal_size_patcher.start() - mock_get_terminal_size.return_value = os.terminal_size((80, 24)) - self.stream.isatty = lambda: True - self.stream.fileno = lambda: 42 + def get_terminal_size(fileno): + return self.stream.get_size() + + mock_get_terminal_size.side_effect = get_terminal_size + else: + self.stream = io.StringIO() self.handler = MBSConsoleHandler(stream=self.stream) self.handler.level = getattr(test_method, 'level', logging.INFO) @@ -153,6 +276,14 @@ class TestConsoleHandler: if getattr(test_method, 'terminal', False): self.get_terminal_size_patcher.stop() + def current(self): + if isinstance(self.stream, FakeTerminal): + val = self.stream.serialize() + else: + val = self.stream.getvalue() + + return val.rstrip() + '\n' + def log_messages(self): log.debug("Debug") log.info("Info") @@ -163,35 +294,35 @@ class TestConsoleHandler: def test_console_basic(self): self.log_messages() - value = self.stream.getvalue() - assert "Debug" not in value - assert "Info" not in value - assert "Console" in value - assert "\nWARNING - Warning" in value - assert "\nERROR - Error" in value + current = self.current() + assert "Debug" not in current + assert "Info" not in current + assert "Console" in current + assert "\nWARNING - Warning" in current + assert "\nERROR - Error" in current @terminal def test_console_terminal(self): self.log_messages() - value = self.stream.getvalue() - assert "Debug" not in value - assert "Info" not in value - assert "Console" in value - assert "\n\x1b[1m\x1b[91mWARNING\x1b[0m - Warning" in value - assert "\n\x1b[1m\x1b[91mERROR\x1b[0m - Error" in value + current = self.current() + assert "Debug" not in current + assert "Info" not in current + assert "Console" in current + assert "WARNING - Warning" in current + assert "ERROR - Error" in current @level(logging.DEBUG) @terminal def test_console_debug(self): self.log_messages() - value = self.stream.getvalue() - assert "MainThread - MBS - DEBUG - Debug" in value - assert "MainThread - MBS - INFO - Info" in value - assert "MainThread - MBS - INFO - Console" in value - assert "MainThread - MBS - WARNING - Warning" in value - assert "MainThread - MBS - ERROR - Error" in value + current = self.current() + assert "MainThread - MBS - DEBUG - Debug" in current + assert "MainThread - MBS - INFO - Info" in current + assert "MainThread - MBS - INFO - Console" in current + assert "MainThread - MBS - WARNING - Warning" in current + assert "MainThread - MBS - ERROR - Error" in current @terminal def test_console_long_running(self): @@ -209,9 +340,7 @@ class TestConsoleHandler: log.long_running_end("Blabbing") log.long_running_end("Frobulating") - print(self.stream.getvalue()) - - assert self.stream.getvalue() == textwrap.dedent("""\ + assert self.current() == textwrap.dedent("""\ Frobulating ... done --- Frobulating ... @@ -222,3 +351,76 @@ class TestConsoleHandler: Blabbing ... done Frobulating ... done """) + + @terminal + def test_console_local_repo(self): + log.local_repo_start("module-testmodule-build") + + assert self.current() == textwrap.dedent("""\ + module-testmodule-build: Making local repository for Koji tag + ------------------------------ + module-testmodule-build: + """) + + log.local_repo_start_downloads("module-testmodule-build", 42, "/tmp/download-dir") + log.local_repo_start_download("module-testmodule-build", + "https://ftp.example.com/libsomething-1.2.3-1.x86_64.rpm") + log.local_repo_start_download("module-testmodule-build", + "https://ftp.example.com/libother-1.2.3-1.x86_64.rpm") + log.local_repo_done_download("module-testmodule-build", + "https://ftp.example.com/libother-1.2.3-1.x86_64.rpm") + assert self.current() == textwrap.dedent("""\ + module-testmodule-build: Making local repository for Koji tag + ------------------------------ + module-testmodule-build: Downloading packages 1/42 + libsomething-1.2.3-1.x86_64.rpm + """) + + log.local_repo_done_download("module-testmodule-build", + "https://ftp.example.com/libsomething-1.2.3-1.x86_64.rpm") + log.local_repo_done("module-testmodule-build", "downloaded everything") + assert self.current() == textwrap.dedent("""\ + module-testmodule-build: Making local repository for Koji tag + module-testmodule-build: downloaded everything + """) + + @terminal + def test_console_local_repo_wrap(self): + log.local_repo_start("module-testmodule-build") + long_url = "https://ftp.example.com/lib" + (80 * "z") + "-1.2.3-1.x86_64.rpm" + log.local_repo_start_downloads("module-testmodule-build", 42, "/tmp/download-dir") + log.local_repo_start_download("module-testmodule-build", long_url) + assert self.current() == textwrap.dedent("""\ + module-testmodule-build: Making local repository for Koji tag + ------------------------------ + module-testmodule-build: Downloading packages 0/42 + libzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzz + zzzzzzz-1.2.3-1.x86_64.rpm + """) + + log.local_repo_done_download("module-testmodule-build", long_url) + log.local_repo_done("module-testmodule-build", "downloaded everything") + assert self.current() == textwrap.dedent("""\ + module-testmodule-build: Making local repository for Koji tag + module-testmodule-build: downloaded everything + """) + + @terminal + def test_console_partial_line_erase(self): + self.handler.status_stream.write("Foo\nBar") + self.handler.status_stream.erase() + self.handler.status_stream.write("Baz") + + assert self.current() == "Baz\n" + + @terminal + def test_console_resize(self): + self.stream.columns = 20 + self.handler.resize() + + self.stream.write("Foo\n") + self.handler.status_stream.write(30 * "x") + self.handler.status_stream.erase() + self.handler.status_stream.write("Baz") + + assert self.current() == "Foo\nBaz\n"