modules/fm-orchestrator
1
0
Fork 0
mirror of https://pagure.io/fm-orchestrator.git synced 2026-02-02 20:59:06 +08:00
Code Issues Actions Packages Projects Releases Wiki Activity

Filter console output through a special handler

Browse Source 
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 ... <pause>done"
This commit is contained in:
Owen W. Taylor
2020-11-09 12:57:54 -05:00
committed by breilly
parent ae004e86a0
commit f5100609aa
7 changed files with 288 additions and 12 deletions
Download Patch File Download Diff File Expand all files Collapse all files

2
module_build_service/common/config.py
View File

@@ -76,6 +76,8 @@ class ProdConfiguration(BaseConfiguration):
class LocalBuildConfiguration(BaseConfiguration):
SYSTEM = "mock"
CACHE_DIR = "~/modulebuild/cache"
LOG_LEVEL = "debug"
MESSAGING = "drop"

162
module_build_service/common/logger.py
View File

@@ -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:

5
module_build_service/manage.py
View File

@@ -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"

9
module_build_service/resolver/MBSResolver.py
View File

@@ -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):

4
module_build_service/scheduler/default_modules.py
View File

@@ -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):
"""

7
module_build_service/web/mse.py
View File

@@ -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"] = {}

111
tests/test_common/test_logger.py
View File

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