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/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..a29fc3b5 100644
--- a/module_build_service/common/logger.py
+++ b/module_build_service/common/logger.py
@@ -19,11 +19,14 @@ 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 re
+import signal
+import sys
levels = {
"debug": logging.DEBUG,
@@ -203,6 +206,263 @@ 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',
+}
+
+
+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()
+ 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")
+ 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)
+
+ 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()
+
+ def console_message(msg):
+ def decorate(f):
+ f.console_message = msg
+ return f
+
+ 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:
+ 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)
+
+ @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():
+ 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 +491,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 +509,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 +566,19 @@ 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)
+
+ def handle_sigwinch(*args):
+ handler.resize()
+
+ signal.signal(signal.SIGWINCH, handle_sigwinch)
+ else:
+ logging.basicConfig(level=conf.log_level, format=log_format)
+
log = MBSLogger()
log.level = conf.log_level
else:
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/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/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/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/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/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..0ce0b2ab 100644
--- a/tests/test_common/test_logger.py
+++ b/tests/test_common/test_logger.py
@@ -1,14 +1,19 @@
# -*- coding: utf-8 -*-
# SPDX-License-Identifier: MIT
from __future__ import absolute_import
+import io
+import logging
import os
from os import path
+import re
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 +118,309 @@ 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 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('' + self.last_attr + '>')
+ if attr != 'x':
+ self.result.write('<' + attr + '>')
+ self.last_attr = attr
+
+
+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):
+ 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()
+
+ 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)
+
+ 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 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")
+ log.console("Console")
+ log.warning("Warning")
+ log.error("Error")
+
+ def test_console_basic(self):
+ self.log_messages()
+
+ 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()
+
+ 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()
+
+ 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):
+ 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")
+
+ assert self.current() == textwrap.dedent("""\
+ Frobulating ... done
+ ---
+ Frobulating ...
+ Now Hear This
+ Frobulating ... done
+ ---
+ Frobulating ...
+ 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"