| # |
| # 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 <chris.laplante@agilent.com> |
| |
| 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 |