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 + """)