bb/ui/toasterui.py

#
# BitBake ToasterUI Implementation
# based on (No)TTY UI Implementation by Richard Purdie
#
# Handling output to TTYs or files (no TTY)
#
# Copyright (C) 2006-2012 Richard Purdie
# Copyright (C) 2013      Intel Corporation
#
# SPDX-License-Identifier: GPL-2.0-only
#

from __future__ import division
import time
import sys
try:
    import bb
except RuntimeError as exc:
    sys.exit(str(exc))

from bb.ui import uihelper
from bb.ui.buildinfohelper import BuildInfoHelper

import bb.msg
import logging
import os

# pylint: disable=invalid-name
# module properties for UI modules are read by bitbake and the contract should not be broken


featureSet = [bb.cooker.CookerFeatures.HOB_EXTRA_CACHES, bb.cooker.CookerFeatures.BASEDATASTORE_TRACKING, bb.cooker.CookerFeatures.SEND_SANITYEVENTS]

logger = logging.getLogger("ToasterLogger")
interactive = sys.stdout.isatty()

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)
    consolelogfile, error = server.runCommand(["getVariable", "BB_CONSOLELOG"])
    if error:
        logger.error("Unable to get the value of BB_CONSOLELOG variable: %s", error)
        raise BaseException(error)
    return consolelogfile

# create a log file for a single build and direct the logger at it;
# log file name is timestamped to the millisecond (depending
# on system clock accuracy) to ensure it doesn't overlap with
# other log file names
#
# returns (log file, path to log file) for a build
def _open_build_log(log_dir):
    format_str = "%(levelname)s: %(message)s"

    now = time.time()
    now_ms = int((now - int(now)) * 1000)
    time_str = time.strftime('build_%Y%m%d_%H%M%S', time.localtime(now))
    log_file_name = time_str + ('.%d.log' % now_ms)
    build_log_file_path = os.path.join(log_dir, log_file_name)

    build_log = logging.FileHandler(build_log_file_path)

    logformat = bb.msg.BBLogFormatter(format_str)
    build_log.setFormatter(logformat)

    bb.msg.addDefaultlogFilter(build_log)
    logger.addHandler(build_log)

    return (build_log, build_log_file_path)

# stop logging to the build log if it exists
def _close_build_log(build_log):
    if build_log:
        build_log.flush()
        build_log.close()
        logger.removeHandler(build_log)

_evt_list = [
    "bb.build.TaskBase",
    "bb.build.TaskFailed",
    "bb.build.TaskFailedSilent",
    "bb.build.TaskStarted",
    "bb.build.TaskSucceeded",
    "bb.command.CommandCompleted",
    "bb.command.CommandExit",
    "bb.command.CommandFailed",
    "bb.cooker.CookerExit",
    "bb.event.BuildInit",
    "bb.event.BuildCompleted",
    "bb.event.BuildStarted",
    "bb.event.CacheLoadCompleted",
    "bb.event.CacheLoadProgress",
    "bb.event.CacheLoadStarted",
    "bb.event.ConfigParsed",
    "bb.event.DepTreeGenerated",
    "bb.event.LogExecTTY",
    "bb.event.MetadataEvent",
    "bb.event.MultipleProviders",
    "bb.event.NoProvider",
    "bb.event.ParseCompleted",
    "bb.event.ParseProgress",
    "bb.event.ParseStarted",
    "bb.event.RecipeParsed",
    "bb.event.SanityCheck",
    "bb.event.SanityCheckPassed",
    "bb.event.TreeDataPreparationCompleted",
    "bb.event.TreeDataPreparationStarted",
    "bb.runqueue.runQueueTaskCompleted",
    "bb.runqueue.runQueueTaskFailed",
    "bb.runqueue.runQueueTaskSkipped",
    "bb.runqueue.runQueueTaskStarted",
    "bb.runqueue.sceneQueueTaskCompleted",
    "bb.runqueue.sceneQueueTaskFailed",
    "bb.runqueue.sceneQueueTaskStarted",
    "logging.LogRecord"]

def main(server, eventHandler, params):
    # set to a logging.FileHandler instance when a build starts;
    # see _open_build_log()
    build_log = None

    # set to the log path when a build starts
    build_log_file_path = None

    helper = uihelper.BBUIHelper()

    # TODO don't use log output to determine when bitbake has started
    #
    # WARNING: this log handler cannot be removed, as localhostbecontroller
    # relies on output in the toaster_ui.log file to determine whether
    # the bitbake server has started, which only happens if
    # this logger is setup here (see the TODO in the loop below)
    console = logging.StreamHandler(sys.stdout)
    format_str = "%(levelname)s: %(message)s"
    formatter = bb.msg.BBLogFormatter(format_str)
    bb.msg.addDefaultlogFilter(console)
    console.setFormatter(formatter)
    logger.addHandler(console)
    logger.setLevel(logging.INFO)
    llevel, debug_domains = bb.msg.constructLogOptions()
    result, error = server.runCommand(["setEventMask", server.getEventHandle(), llevel, debug_domains, _evt_list])
    if not result or error:
        logger.error("can't set event mask: %s", error)
        return 1

    # verify and warn
    build_history_enabled = True
    inheritlist, _ = server.runCommand(["getVariable", "INHERIT"])

    if not "buildhistory" in inheritlist.split(" "):
        logger.warning("buildhistory is not enabled. Please enable INHERIT += \"buildhistory\" to see image details.")
        build_history_enabled = False

    if not "buildstats" in inheritlist.split(" "):
        logger.warning("buildstats is not enabled. Please enable INHERIT += \"buildstats\" to generate build statistics.")

    if not params.observe_only:
        params.updateFromServer(server)
        params.updateToServer(server, os.environ.copy())
        cmdline = params.parseActions()
        if not cmdline:
            print("Nothing to do.  Use 'bitbake world' to build everything, or run 'bitbake --help' for usage information.")
            return 1
        if 'msg' in cmdline and cmdline['msg']:
            logger.error(cmdline['msg'])
            return 1

        ret, error = server.runCommand(cmdline['action'])
        if error:
            logger.error("Command '%s' failed: %s" % (cmdline, error))
            return 1
        elif not ret:
            logger.error("Command '%s' failed: returned %s" % (cmdline, ret))
            return 1

    # set to 1 when toasterui needs to shut down
    main.shutdown = 0

    interrupted = False
    return_value = 0
    errors = 0
    warnings = 0
    taskfailures = []
    first = True

    buildinfohelper = BuildInfoHelper(server, build_history_enabled,
                                      os.getenv('TOASTER_BRBE'))

    # write our own log files into bitbake's log directory;
    # we're only interested in the path to the parent directory of
    # this file, as we're writing our own logs into the same directory
    consolelogfile = _log_settings_from_server(server)
    log_dir = os.path.dirname(consolelogfile)
    bb.utils.mkdirhier(log_dir)

    while True:
        try:
            event = eventHandler.waitEvent(0.25)
            if first:
                first = False

                # TODO don't use log output to determine when bitbake has started
                #
                # this is the line localhostbecontroller needs to
                # see in toaster_ui.log which it uses to decide whether
                # the bitbake server has started...
                logger.info("ToasterUI waiting for events")

            if event is None:
                if main.shutdown > 0:
                    # if shutting down, close any open build log first
                    _close_build_log(build_log)

                    break
                continue

            helper.eventHandler(event)

            # pylint: disable=protected-access
            # the code will look into the protected variables of the event; no easy way around this

            if isinstance(event, bb.event.HeartbeatEvent):
                continue

            if isinstance(event, bb.event.ParseStarted):
                if not (build_log and build_log_file_path):
                    build_log, build_log_file_path = _open_build_log(log_dir)

                buildinfohelper.store_started_build()
                buildinfohelper.save_build_log_file_path(build_log_file_path)
                buildinfohelper.set_recipes_to_parse(event.total)
                continue

            # create a build object in buildinfohelper from either BuildInit
            # (if available) or BuildStarted (for jethro and previous versions)
            if isinstance(event, (bb.event.BuildStarted, bb.event.BuildInit)):
                if not (build_log and build_log_file_path):
                    build_log, build_log_file_path = _open_build_log(log_dir)

                buildinfohelper.save_build_targets(event)
                buildinfohelper.save_build_log_file_path(build_log_file_path)

                # get additional data from BuildStarted
                if isinstance(event, bb.event.BuildStarted):
                    buildinfohelper.save_build_layers_and_variables()
                continue

            if isinstance(event, bb.event.ParseProgress):
                buildinfohelper.set_recipes_parsed(event.current)
                continue

            if isinstance(event, bb.event.ParseCompleted):
                buildinfohelper.set_recipes_parsed(event.total)
                continue

            if isinstance(event, (bb.build.TaskStarted, bb.build.TaskSucceeded, bb.build.TaskFailedSilent)):
                buildinfohelper.update_and_store_task(event)
                logger.info("Logfile for task %s", event.logfile)
                continue

            if isinstance(event, bb.build.TaskBase):
                logger.info(event._message)

            if isinstance(event, bb.event.LogExecTTY):
                logger.info(event.msg)
                continue

            if isinstance(event, logging.LogRecord):
                if event.levelno == -1:
                    event.levelno = formatter.ERROR

                buildinfohelper.store_log_event(event)

                if event.levelno >= formatter.ERROR:
                    errors = errors + 1
                elif event.levelno == formatter.WARNING:
                    warnings = warnings + 1

                # 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.taskpid != 0 and event.levelno <= formatter.NOTE:
                    continue

                logger.handle(event)
                continue

            if isinstance(event, bb.build.TaskFailed):
                buildinfohelper.update_and_store_task(event)
                logfile = event.logfile
                if logfile and os.path.exists(logfile):
                    bb.error("Logfile of failure stored in: %s" % logfile)
                continue

            # these events are unprocessed now, but may be used in the future to log
            # timing and error informations from the parsing phase in Toaster
            if isinstance(event, (bb.event.SanityCheckPassed, bb.event.SanityCheck)):
                continue
            if isinstance(event, bb.event.CacheLoadStarted):
                continue
            if isinstance(event, bb.event.CacheLoadProgress):
                continue
            if isinstance(event, bb.event.CacheLoadCompleted):
                continue
            if isinstance(event, bb.event.MultipleProviders):
                logger.info(str(event))
                continue

            if isinstance(event, bb.event.NoProvider):
                errors = errors + 1
                text = str(event)
                logger.error(text)
                buildinfohelper.store_log_error(text)
                continue

            if isinstance(event, bb.event.ConfigParsed):
                continue
            if isinstance(event, bb.event.RecipeParsed):
                continue

            # end of saved events

            if isinstance(event, (bb.runqueue.sceneQueueTaskStarted, bb.runqueue.runQueueTaskStarted, bb.runqueue.runQueueTaskSkipped)):
                buildinfohelper.store_started_task(event)
                continue

            if isinstance(event, bb.runqueue.runQueueTaskCompleted):
                buildinfohelper.update_and_store_task(event)
                continue

            if isinstance(event, bb.runqueue.runQueueTaskFailed):
                buildinfohelper.update_and_store_task(event)
                taskfailures.append(event.taskstring)
                logger.error(str(event))
                continue

            if isinstance(event, (bb.runqueue.sceneQueueTaskCompleted, bb.runqueue.sceneQueueTaskFailed)):
                buildinfohelper.update_and_store_task(event)
                continue


            if isinstance(event, (bb.event.TreeDataPreparationStarted, bb.event.TreeDataPreparationCompleted)):
                continue

            if isinstance(event, (bb.event.BuildCompleted, bb.command.CommandFailed)):

                errorcode = 0
                if isinstance(event, bb.command.CommandFailed):
                    errors += 1
                    errorcode = 1
                    logger.error(str(event))
                elif isinstance(event, bb.event.BuildCompleted):
                    buildinfohelper.scan_image_artifacts()
                    buildinfohelper.clone_required_sdk_artifacts()

                # turn off logging to the current build log
                _close_build_log(build_log)

                # reset ready for next BuildStarted
                build_log = None

                # update the build info helper on BuildCompleted, not on CommandXXX
                buildinfohelper.update_build_information(event, errors, warnings, taskfailures)

                brbe = buildinfohelper.brbe
                buildinfohelper.close(errorcode)

                # we start a new build info
                if params.observe_only:
                    logger.debug("ToasterUI prepared for new build")
                    errors = 0
                    warnings = 0
                    taskfailures = []
                    buildinfohelper = BuildInfoHelper(server, build_history_enabled)
                else:
                    main.shutdown = 1

                logger.info("ToasterUI build done, brbe: %s", brbe)
                continue

            if isinstance(event, (bb.command.CommandCompleted,
                                  bb.command.CommandFailed,
                                  bb.command.CommandExit)):
                if params.observe_only:
                    errorcode = 0
                else:
                    main.shutdown = 1

                continue

            if isinstance(event, bb.event.MetadataEvent):
                if event.type == "SinglePackageInfo":
                    buildinfohelper.store_build_package_information(event)
                elif event.type == "LayerInfo":
                    buildinfohelper.store_layer_info(event)
                elif event.type == "BuildStatsList":
                    buildinfohelper.store_tasks_stats(event)
                elif event.type == "ImagePkgList":
                    buildinfohelper.store_target_package_data(event)
                elif event.type == "MissedSstate":
                    buildinfohelper.store_missed_state_tasks(event)
                elif event.type == "SDKArtifactInfo":
                    buildinfohelper.scan_sdk_artifacts(event)
                elif event.type == "SetBRBE":
                    buildinfohelper.brbe = buildinfohelper._get_data_from_event(event)
                elif event.type == "TaskArtifacts":
                    buildinfohelper.scan_task_artifacts(event)
                elif event.type == "OSErrorException":
                    logger.error(event)
                else:
                    logger.error("Unprocessed MetadataEvent %s", event.type)
                continue

            if isinstance(event, bb.cooker.CookerExit):
                # shutdown when bitbake server shuts down
                main.shutdown = 1
                continue

            if isinstance(event, bb.event.DepTreeGenerated):
                buildinfohelper.store_dependency_information(event)
                continue

            logger.warning("Unknown event: %s", event)
            return_value += 1

        except EnvironmentError as ioerror:
            logger.warning("EnvironmentError: %s" % ioerror)
            # ignore interrupted io system calls
            if ioerror.args[0] == 4: # errno 4 is EINTR
                logger.warning("Skipped EINTR: %s" % ioerror)
            else:
                raise
        except KeyboardInterrupt:
            if params.observe_only:
                print("\nKeyboard Interrupt, exiting observer...")
                main.shutdown = 2
            if not params.observe_only and main.shutdown == 1:
                print("\nSecond Keyboard Interrupt, stopping...\n")
                _, error = server.runCommand(["stateForceShutdown"])
                if error:
                    logger.error("Unable to cleanly stop: %s" % error)
            if not params.observe_only and main.shutdown == 0:
                print("\nKeyboard Interrupt, closing down...\n")
                interrupted = True
                _, error = server.runCommand(["stateShutdown"])
                if error:
                    logger.error("Unable to cleanly shutdown: %s" % error)
            buildinfohelper.cancel_cli_build()
            main.shutdown = main.shutdown + 1
        except Exception as e:
            # print errors to log
            import traceback
            from pprint import pformat
            exception_data = traceback.format_exc()
            logger.error("%s\n%s" , e, exception_data)

            # save them to database, if possible; if it fails, we already logged to console.
            try:
                buildinfohelper.store_log_exception("%s\n%s" % (str(e), exception_data))
            except Exception as ce:
                logger.error("CRITICAL - Failed to to save toaster exception to the database: %s", str(ce))

            # make sure we return with an error
            return_value += 1

    if interrupted and return_value == 0:
        return_value += 1

    logger.warning("Return value is %d", return_value)
    return return_value