From 26ff7fa314d0f84f2557b183fb71fa873d914ee0 Mon Sep 17 00:00:00 2001 From: Chris Laplante Date: Fri, 24 Jan 2020 10:16:23 -0500 Subject: ui/teamcity: add a TeamCity service message frontend Exposes build status via TeamCity service messages, see https://www.jetbrains.com/help/teamcity/build-script-interaction-with-teamcity.html. Signed-off-by: Chris Laplante Signed-off-by: Richard Purdie --- lib/bb/ui/teamcity.py | 398 ++++++++++++++++++++++++++++++++++++++++++++++++++ 1 file changed, 398 insertions(+) create mode 100644 lib/bb/ui/teamcity.py (limited to 'lib/bb/ui') diff --git a/lib/bb/ui/teamcity.py b/lib/bb/ui/teamcity.py new file mode 100644 index 000000000..1854292fa --- /dev/null +++ b/lib/bb/ui/teamcity.py @@ -0,0 +1,398 @@ +# +# TeamCity UI Implementation +# +# Implements a TeamCity frontend for the BitBake utility, via service messages. +# See https://www.jetbrains.com/help/teamcity/build-script-interaction-with-teamcity.html +# +# Based on ncurses.py and knotty.py, variously by Michael Lauer and Richard Purdie +# +# Copyright (C) 2006 Michael 'Mickey' Lauer +# Copyright (C) 2006-2012 Richard Purdie +# Copyright (C) 2018-2020 Agilent Technologies, Inc. +# +# SPDX-License-Identifier: GPL-2.0-only +# +# Author: Chris Laplante + +from __future__ import division + +import datetime +import logging +import math +import os +import re +import sys +import xmlrpc.client +from collections import deque + +import bb +import bb.build +import bb.command +import bb.cooker +import bb.event +import bb.exceptions +import bb.runqueue +from bb.ui import uihelper + +logger = logging.getLogger("BitBake") + + +class TeamCityUI: + def __init__(self): + self._block_stack = [] + self._last_progress_state = None + + @classmethod + def escape_service_value(cls, value): + """ + Escape a value for inclusion in a service message. TeamCity uses the vertical pipe character for escaping. + See: https://confluence.jetbrains.com/display/TCD10/Build+Script+Interaction+with+TeamCity#BuildScriptInteractionwithTeamCity-Escapedvalues + """ + return re.sub(r"(['|\[\]])", r"|\1", value).replace("\n", "|n").replace("\r", "|r") + + @classmethod + def emit_service_message(cls, message_type, **kwargs): + print(cls.format_service_message(message_type, **kwargs), flush=True) + + @classmethod + def format_service_message(cls, message_type, **kwargs): + payload = " ".join(["{0}='{1}'".format(k, cls.escape_service_value(v)) for k, v in kwargs.items()]) + return "##teamcity[{0} {1}]".format(message_type, payload) + + @classmethod + def emit_simple_service_message(cls, message_type, message): + print(cls.format_simple_service_message(message_type, message), flush=True) + + @classmethod + def format_simple_service_message(cls, message_type, message): + return "##teamcity[{0} '{1}']".format(message_type, cls.escape_service_value(message)) + + @classmethod + def format_build_message(cls, text, status): + return cls.format_service_message("message", text=text, status=status) + + def block_start(self, name): + self._block_stack.append(name) + self.emit_service_message("blockOpened", name=name) + + def block_end(self): + if self._block_stack: + name = self._block_stack.pop() + self.emit_service_message("blockClosed", name=name) + + def progress(self, message, percent, extra=None): + now = datetime.datetime.now() + percent = "{0: >3.0f}".format(percent) + + report = False + if not self._last_progress_state \ + or (self._last_progress_state[0] == message + and self._last_progress_state[1] != percent + and (now - self._last_progress_state[2]).microseconds >= 5000) \ + or self._last_progress_state[0] != message: + report = True + self._last_progress_state = (message, percent, now) + + if report or percent in [0, 100]: + self.emit_simple_service_message("progressMessage", "{0}: {1}%{2}".format(message, percent, extra or "")) + + +class TeamcityLogFormatter(logging.Formatter): + def format(self, record): + details = "" + if hasattr(record, 'bb_exc_formatted'): + details = ''.join(record.bb_exc_formatted) + elif hasattr(record, 'bb_exc_info'): + etype, value, tb = record.bb_exc_info + formatted = bb.exceptions.format_exception(etype, value, tb, limit=5) + details = ''.join(formatted) + + if record.levelno in [bb.msg.BBLogFormatter.ERROR, bb.msg.BBLogFormatter.CRITICAL]: + # ERROR gets a separate errorDetails field + msg = TeamCityUI.format_service_message("message", text=record.getMessage(), status="ERROR", + errorDetails=details) + else: + payload = record.getMessage() + if details: + payload += "\n" + details + if record.levelno == bb.msg.BBLogFormatter.PLAIN: + msg = payload + elif record.levelno == bb.msg.BBLogFormatter.WARNING: + msg = TeamCityUI.format_service_message("message", text=payload, status="WARNING") + else: + msg = TeamCityUI.format_service_message("message", text=payload, status="NORMAL") + + return msg + + +_evt_list = ["bb.runqueue.runQueueExitWait", "bb.event.LogExecTTY", "logging.LogRecord", + "bb.build.TaskFailed", "bb.build.TaskBase", "bb.event.ParseStarted", + "bb.event.ParseProgress", "bb.event.ParseCompleted", "bb.event.CacheLoadStarted", + "bb.event.CacheLoadProgress", "bb.event.CacheLoadCompleted", "bb.command.CommandFailed", + "bb.command.CommandExit", "bb.command.CommandCompleted", "bb.cooker.CookerExit", + "bb.event.MultipleProviders", "bb.event.NoProvider", "bb.runqueue.sceneQueueTaskStarted", + "bb.runqueue.runQueueTaskStarted", "bb.runqueue.runQueueTaskFailed", "bb.runqueue.sceneQueueTaskFailed", + "bb.event.BuildBase", "bb.build.TaskStarted", "bb.build.TaskSucceeded", "bb.build.TaskFailedSilent", + "bb.build.TaskProgress", "bb.event.ProcessStarted", "bb.event.ProcessProgress", "bb.event.ProcessFinished"] + + +def _log_settings_from_server(server): + # Get values of variables which control our output + includelogs, error = server.runCommand(["getVariable", "BBINCLUDELOGS"]) + if error: + logger.error("Unable to get the value of BBINCLUDELOGS variable: %s" % error) + raise BaseException(error) + loglines, error = server.runCommand(["getVariable", "BBINCLUDELOGS_LINES"]) + if error: + logger.error("Unable to get the value of BBINCLUDELOGS_LINES variable: %s" % error) + raise BaseException(error) + return includelogs, loglines + + +def main(server, eventHandler, params): + params.updateToServer(server, os.environ.copy()) + + includelogs, loglines = _log_settings_from_server(server) + + ui = TeamCityUI() + + helper = uihelper.BBUIHelper() + + console = logging.StreamHandler(sys.stdout) + errconsole = logging.StreamHandler(sys.stderr) + format = TeamcityLogFormatter() + if params.options.quiet == 0: + forcelevel = None + elif params.options.quiet > 2: + forcelevel = bb.msg.BBLogFormatter.ERROR + else: + forcelevel = bb.msg.BBLogFormatter.WARNING + bb.msg.addDefaultlogFilter(console, bb.msg.BBLogFilterStdOut, forcelevel) + bb.msg.addDefaultlogFilter(errconsole, bb.msg.BBLogFilterStdErr) + console.setFormatter(format) + errconsole.setFormatter(format) + if not bb.msg.has_console_handler(logger): + logger.addHandler(console) + logger.addHandler(errconsole) + + if params.options.remote_server and params.options.kill_server: + server.terminateServer() + return + + if params.observe_only: + logger.error("Observe-only mode not supported in this UI") + return 1 + + llevel, debug_domains = bb.msg.constructLogOptions() + server.runCommand(["setEventMask", server.getEventHandle(), llevel, debug_domains, _evt_list]) + + try: + params.updateFromServer(server) + cmdline = params.parseActions() + if not cmdline: + logger.error("No task given") + return 1 + if 'msg' in cmdline and cmdline['msg']: + logger.error(cmdline['msg']) + return 1 + cmdline = cmdline['action'] + ret, error = server.runCommand(cmdline) + if error: + logger.error("{0}: {1}".format(cmdline, error)) + return 1 + elif not ret: + logger.error("Couldn't get default commandline: {0}".format(re)) + return 1 + except xmlrpc.client.Fault as x: + logger.error("XMLRPC Fault getting commandline: {0}".format(x)) + return 1 + + active_process_total = None + is_tasks_running = False + + while True: + try: + event = eventHandler.waitEvent(0.25) + if not event: + continue + + helper.eventHandler(event) + + if isinstance(event, bb.build.TaskBase): + logger.info(event._message) + if isinstance(event, logging.LogRecord): + # Don't report sstate failures as errors, since Yocto will just run the tasks for real + if event.msg == "No suitable staging package found" or (event.msg.startswith( + "Fetcher failure: Unable to find file") and "downloadfilename" in event.msg and "sstate" in event.msg): + event.levelno = bb.msg.BBLogFormatter.WARNING + if event.taskpid != 0: + # For "normal" logging conditions, don't show note logs from tasks + # but do show them if the user has changed the default log level to + # include verbose/debug messages + if event.levelno <= bb.msg.BBLogFormatter.NOTE and (event.levelno < llevel or ( + event.levelno == bb.msg.BBLogFormatter.NOTE and llevel != bb.msg.BBLogFormatter.VERBOSE)): + continue + + # Prefix task messages with recipe/task + if event.taskpid in helper.running_tasks and event.levelno != bb.msg.BBLogFormatter.PLAIN: + taskinfo = helper.running_tasks[event.taskpid] + event.msg = taskinfo['title'] + ': ' + event.msg + if hasattr(event, 'fn'): + event.msg = event.fn + ': ' + event.msg + logger.handle(event) + if isinstance(event, bb.build.TaskFailedSilent): + logger.warning("Logfile for failed setscene task is %s" % event.logfile) + continue + if isinstance(event, bb.build.TaskFailed): + rt = "{0}-{1}:{2}".format(event.pn, event.pv.replace("AUTOINC", "0"), event.task) + + logfile = event.logfile + if not logfile or not os.path.exists(logfile): + TeamCityUI.emit_service_message("buildProblem", description="{0}\nUnknown failure (no log file available)".format(rt)) + if not event.task.endswith("_setscene"): + server.runCommand(["stateForceShutdown"]) + continue + + details = deque(maxlen=loglines) + error_lines = [] + if includelogs and not event.errprinted: + with open(logfile, "r") as f: + while True: + line = f.readline() + if not line: + break + line = line.rstrip() + details.append(' | %s' % line) + # TODO: a less stupid check for errors + if (event.task == "do_compile") and ("error:" in line): + error_lines.append(line) + + if error_lines: + TeamCityUI.emit_service_message("compilationStarted", compiler=rt) + for line in error_lines: + TeamCityUI.emit_service_message("message", text=line, status="ERROR") + TeamCityUI.emit_service_message("compilationFinished", compiler=rt) + else: + TeamCityUI.emit_service_message("buildProblem", description=rt) + + err = "Logfile of failure stored in: %s" % logfile + if details: + ui.block_start("{0} task log".format(rt)) + # TeamCity seems to choke on service messages longer than about 63800 characters, so if error + # details is longer than, say, 60000, batch it up into several messages. + first_message = True + while details: + detail_len = 0 + batch = deque() + while details and detail_len < 60000: + # TODO: This code doesn't bother to handle lines that themselves are extremely long. + line = details.popleft() + batch.append(line) + detail_len += len(line) + + if first_message: + batch.appendleft("Log data follows:") + first_message = False + TeamCityUI.emit_service_message("message", text=err, status="ERROR", + errorDetails="\n".join(batch)) + else: + TeamCityUI.emit_service_message("message", text="[continued]", status="ERROR", + errorDetails="\n".join(batch)) + ui.block_end() + else: + TeamCityUI.emit_service_message("message", text=err, status="ERROR", errorDetails="") + + if not event.task.endswith("_setscene"): + server.runCommand(["stateForceShutdown"]) + + if isinstance(event, bb.event.ProcessStarted): + if event.processname in ["Initialising tasks", "Checking sstate mirror object availability"]: + active_process_total = event.total + ui.block_start(event.processname) + if isinstance(event, bb.event.ProcessFinished): + if event.processname in ["Initialising tasks", "Checking sstate mirror object availability"]: + ui.progress(event.processname, 100) + ui.block_end() + if isinstance(event, bb.event.ProcessProgress): + if event.processname in ["Initialising tasks", + "Checking sstate mirror object availability"] and active_process_total != 0: + ui.progress(event.processname, event.progress * 100 / active_process_total) + if isinstance(event, bb.event.CacheLoadStarted): + ui.block_start("Loading cache") + if isinstance(event, bb.event.CacheLoadProgress): + if event.total != 0: + ui.progress("Loading cache", math.floor(event.current * 100 / event.total)) + if isinstance(event, bb.event.CacheLoadCompleted): + ui.progress("Loading cache", 100) + ui.block_end() + if isinstance(event, bb.event.ParseStarted): + ui.block_start("Parsing recipes and checking upstream revisions") + if isinstance(event, bb.event.ParseProgress): + if event.total != 0: + ui.progress("Parsing recipes", math.floor(event.current * 100 / event.total)) + if isinstance(event, bb.event.ParseCompleted): + ui.progress("Parsing recipes", 100) + ui.block_end() + if isinstance(event, bb.command.CommandCompleted): + return + if isinstance(event, bb.command.CommandFailed): + logger.error(str(event)) + return 1 + if isinstance(event, bb.event.MultipleProviders): + logger.warning(str(event)) + continue + if isinstance(event, bb.event.NoProvider): + logger.error(str(event)) + continue + if isinstance(event, bb.command.CommandExit): + return + if isinstance(event, bb.cooker.CookerExit): + return + if isinstance(event, bb.runqueue.sceneQueueTaskStarted): + if not is_tasks_running: + is_tasks_running = True + ui.block_start("Running tasks") + if event.stats.total != 0: + ui.progress("Running setscene tasks", ( + event.stats.completed + event.stats.active + event.stats.failed + 1) * 100 / event.stats.total) + if isinstance(event, bb.runqueue.runQueueTaskStarted): + if not is_tasks_running: + is_tasks_running = True + ui.block_start("Running tasks") + if event.stats.total != 0: + pseudo_total = event.stats.total - event.stats.skipped + pseudo_complete = event.stats.completed + event.stats.active - event.stats.skipped + event.stats.failed + 1 + # TODO: sometimes this gives over 100% + ui.progress("Running runqueue tasks", (pseudo_complete) * 100 / pseudo_total, + " ({0}/{1})".format(pseudo_complete, pseudo_total)) + if isinstance(event, bb.runqueue.sceneQueueTaskFailed): + logger.warning(str(event)) + continue + if isinstance(event, bb.runqueue.runQueueTaskFailed): + logger.error(str(event)) + return 1 + if isinstance(event, bb.event.LogExecTTY): + pass + except EnvironmentError as ioerror: + # ignore interrupted io + if ioerror.args[0] == 4: + pass + except Exception as ex: + logger.error(str(ex)) + + # except KeyboardInterrupt: + # if shutdown == 2: + # mw.appendText("Third Keyboard Interrupt, exit.\n") + # exitflag = True + # if shutdown == 1: + # mw.appendText("Second Keyboard Interrupt, stopping...\n") + # _, error = server.runCommand(["stateForceShutdown"]) + # if error: + # print("Unable to cleanly stop: %s" % error) + # if shutdown == 0: + # mw.appendText("Keyboard Interrupt, closing down...\n") + # _, error = server.runCommand(["stateShutdown"]) + # if error: + # print("Unable to cleanly shutdown: %s" % error) + # shutdown = shutdown + 1 + # pass -- cgit 1.2.3-korg