xref: /openbmc/openbmc/poky/bitbake/lib/bb/ui/toasterui.py (revision 90fd73cb) 
1#
2# BitBake ToasterUI Implementation
3# based on (No)TTY UI Implementation by Richard Purdie
4#
5# Handling output to TTYs or files (no TTY)
6#
7# Copyright (C) 2006-2012 Richard Purdie
8# Copyright (C) 2013      Intel Corporation
9#
10# SPDX-License-Identifier: GPL-2.0-only
11#
12
13from __future__ import division
14import time
15import sys
16try:
17    import bb
18except RuntimeError as exc:
19    sys.exit(str(exc))
20
21from bb.ui import uihelper
22from bb.ui.buildinfohelper import BuildInfoHelper
23
24import bb.msg
25import logging
26import os
27
28# pylint: disable=invalid-name
29# module properties for UI modules are read by bitbake and the contract should not be broken
30
31
32featureSet = [bb.cooker.CookerFeatures.HOB_EXTRA_CACHES, bb.cooker.CookerFeatures.BASEDATASTORE_TRACKING, bb.cooker.CookerFeatures.SEND_SANITYEVENTS]
33
34logger = logging.getLogger("ToasterLogger")
35interactive = sys.stdout.isatty()
36
37def _log_settings_from_server(server):
38    # Get values of variables which control our output
39    includelogs, error = server.runCommand(["getVariable", "BBINCLUDELOGS"])
40    if error:
41        logger.error("Unable to get the value of BBINCLUDELOGS variable: %s", error)
42        raise BaseException(error)
43    loglines, error = server.runCommand(["getVariable", "BBINCLUDELOGS_LINES"])
44    if error:
45        logger.error("Unable to get the value of BBINCLUDELOGS_LINES variable: %s", error)
46        raise BaseException(error)
47    consolelogfile, error = server.runCommand(["getVariable", "BB_CONSOLELOG"])
48    if error:
49        logger.error("Unable to get the value of BB_CONSOLELOG variable: %s", error)
50        raise BaseException(error)
51    return consolelogfile
52
53# create a log file for a single build and direct the logger at it;
54# log file name is timestamped to the millisecond (depending
55# on system clock accuracy) to ensure it doesn't overlap with
56# other log file names
57#
58# returns (log file, path to log file) for a build
59def _open_build_log(log_dir):
60    format_str = "%(levelname)s: %(message)s"
61
62    now = time.time()
63    now_ms = int((now - int(now)) * 1000)
64    time_str = time.strftime('build_%Y%m%d_%H%M%S', time.localtime(now))
65    log_file_name = time_str + ('.%d.log' % now_ms)
66    build_log_file_path = os.path.join(log_dir, log_file_name)
67
68    build_log = logging.FileHandler(build_log_file_path)
69
70    logformat = bb.msg.BBLogFormatter(format_str)
71    build_log.setFormatter(logformat)
72
73    bb.msg.addDefaultlogFilter(build_log)
74    logger.addHandler(build_log)
75
76    return (build_log, build_log_file_path)
77
78# stop logging to the build log if it exists
79def _close_build_log(build_log):
80    if build_log:
81        build_log.flush()
82        build_log.close()
83        logger.removeHandler(build_log)
84
85_evt_list = [
86    "bb.build.TaskBase",
87    "bb.build.TaskFailed",
88    "bb.build.TaskFailedSilent",
89    "bb.build.TaskStarted",
90    "bb.build.TaskSucceeded",
91    "bb.command.CommandCompleted",
92    "bb.command.CommandExit",
93    "bb.command.CommandFailed",
94    "bb.cooker.CookerExit",
95    "bb.event.BuildInit",
96    "bb.event.BuildCompleted",
97    "bb.event.BuildStarted",
98    "bb.event.CacheLoadCompleted",
99    "bb.event.CacheLoadProgress",
100    "bb.event.CacheLoadStarted",
101    "bb.event.ConfigParsed",
102    "bb.event.DepTreeGenerated",
103    "bb.event.LogExecTTY",
104    "bb.event.MetadataEvent",
105    "bb.event.MultipleProviders",
106    "bb.event.NoProvider",
107    "bb.event.ParseCompleted",
108    "bb.event.ParseProgress",
109    "bb.event.ParseStarted",
110    "bb.event.RecipeParsed",
111    "bb.event.SanityCheck",
112    "bb.event.SanityCheckPassed",
113    "bb.event.TreeDataPreparationCompleted",
114    "bb.event.TreeDataPreparationStarted",
115    "bb.runqueue.runQueueTaskCompleted",
116    "bb.runqueue.runQueueTaskFailed",
117    "bb.runqueue.runQueueTaskSkipped",
118    "bb.runqueue.runQueueTaskStarted",
119    "bb.runqueue.sceneQueueTaskCompleted",
120    "bb.runqueue.sceneQueueTaskFailed",
121    "bb.runqueue.sceneQueueTaskStarted",
122    "logging.LogRecord"]
123
124def main(server, eventHandler, params):
125    # set to a logging.FileHandler instance when a build starts;
126    # see _open_build_log()
127    build_log = None
128
129    # set to the log path when a build starts
130    build_log_file_path = None
131
132    helper = uihelper.BBUIHelper()
133
134    if not params.observe_only:
135        params.updateToServer(server, os.environ.copy())
136        params.updateFromServer(server)
137
138    # TODO don't use log output to determine when bitbake has started
139    #
140    # WARNING: this log handler cannot be removed, as localhostbecontroller
141    # relies on output in the toaster_ui.log file to determine whether
142    # the bitbake server has started, which only happens if
143    # this logger is setup here (see the TODO in the loop below)
144    console = logging.StreamHandler(sys.stdout)
145    format_str = "%(levelname)s: %(message)s"
146    formatter = bb.msg.BBLogFormatter(format_str)
147    bb.msg.addDefaultlogFilter(console)
148    console.setFormatter(formatter)
149    logger.addHandler(console)
150    logger.setLevel(logging.INFO)
151    llevel, debug_domains = bb.msg.constructLogOptions()
152    result, error = server.runCommand(["setEventMask", server.getEventHandle(), llevel, debug_domains, _evt_list])
153    if not result or error:
154        logger.error("can't set event mask: %s", error)
155        return 1
156
157    # verify and warn
158    build_history_enabled = True
159    inheritlist, _ = server.runCommand(["getVariable", "INHERIT"])
160
161    if not "buildhistory" in inheritlist.split(" "):
162        logger.warning("buildhistory is not enabled. Please enable INHERIT += \"buildhistory\" to see image details.")
163        build_history_enabled = False
164
165    if not "buildstats" in inheritlist.split(" "):
166        logger.warning("buildstats is not enabled. Please enable INHERIT += \"buildstats\" to generate build statistics.")
167
168    if not params.observe_only:
169        cmdline = params.parseActions()
170        if not cmdline:
171            print("Nothing to do.  Use 'bitbake world' to build everything, or run 'bitbake --help' for usage information.")
172            return 1
173        if 'msg' in cmdline and cmdline['msg']:
174            logger.error(cmdline['msg'])
175            return 1
176
177        ret, error = server.runCommand(cmdline['action'])
178        if error:
179            logger.error("Command '%s' failed: %s" % (cmdline, error))
180            return 1
181        elif not ret:
182            logger.error("Command '%s' failed: returned %s" % (cmdline, ret))
183            return 1
184
185    # set to 1 when toasterui needs to shut down
186    main.shutdown = 0
187
188    interrupted = False
189    return_value = 0
190    errors = 0
191    warnings = 0
192    taskfailures = []
193    first = True
194
195    buildinfohelper = BuildInfoHelper(server, build_history_enabled,
196                                      os.getenv('TOASTER_BRBE'))
197
198    # write our own log files into bitbake's log directory;
199    # we're only interested in the path to the parent directory of
200    # this file, as we're writing our own logs into the same directory
201    consolelogfile = _log_settings_from_server(server)
202    log_dir = os.path.dirname(consolelogfile)
203    bb.utils.mkdirhier(log_dir)
204
205    while True:
206        try:
207            event = eventHandler.waitEvent(0.25)
208            if first:
209                first = False
210
211                # TODO don't use log output to determine when bitbake has started
212                #
213                # this is the line localhostbecontroller needs to
214                # see in toaster_ui.log which it uses to decide whether
215                # the bitbake server has started...
216                logger.info("ToasterUI waiting for events")
217
218            if event is None:
219                if main.shutdown > 0:
220                    # if shutting down, close any open build log first
221                    _close_build_log(build_log)
222
223                    break
224                continue
225
226            helper.eventHandler(event)
227
228            # pylint: disable=protected-access
229            # the code will look into the protected variables of the event; no easy way around this
230
231            if isinstance(event, bb.event.HeartbeatEvent):
232                continue
233
234            if isinstance(event, bb.event.ParseStarted):
235                if not (build_log and build_log_file_path):
236                    build_log, build_log_file_path = _open_build_log(log_dir)
237
238                buildinfohelper.store_started_build()
239                buildinfohelper.save_build_log_file_path(build_log_file_path)
240                buildinfohelper.set_recipes_to_parse(event.total)
241                continue
242
243            # create a build object in buildinfohelper from either BuildInit
244            # (if available) or BuildStarted (for jethro and previous versions)
245            if isinstance(event, (bb.event.BuildStarted, bb.event.BuildInit)):
246                if not (build_log and build_log_file_path):
247                    build_log, build_log_file_path = _open_build_log(log_dir)
248
249                buildinfohelper.save_build_targets(event)
250                buildinfohelper.save_build_log_file_path(build_log_file_path)
251
252                # get additional data from BuildStarted
253                if isinstance(event, bb.event.BuildStarted):
254                    buildinfohelper.save_build_layers_and_variables()
255                continue
256
257            if isinstance(event, bb.event.ParseProgress):
258                buildinfohelper.set_recipes_parsed(event.current)
259                continue
260
261            if isinstance(event, bb.event.ParseCompleted):
262                buildinfohelper.set_recipes_parsed(event.total)
263                continue
264
265            if isinstance(event, (bb.build.TaskStarted, bb.build.TaskSucceeded, bb.build.TaskFailedSilent)):
266                buildinfohelper.update_and_store_task(event)
267                logger.info("Logfile for task %s", event.logfile)
268                continue
269
270            if isinstance(event, bb.build.TaskBase):
271                logger.info(event._message)
272
273            if isinstance(event, bb.event.LogExecTTY):
274                logger.info(event.msg)
275                continue
276
277            if isinstance(event, logging.LogRecord):
278                if event.levelno == -1:
279                    event.levelno = formatter.ERROR
280
281                buildinfohelper.store_log_event(event)
282
283                if event.levelno >= formatter.ERROR:
284                    errors = errors + 1
285                elif event.levelno == formatter.WARNING:
286                    warnings = warnings + 1
287
288                # For "normal" logging conditions, don't show note logs from tasks
289                # but do show them if the user has changed the default log level to
290                # include verbose/debug messages
291                if event.taskpid != 0 and event.levelno <= formatter.NOTE:
292                    continue
293
294                logger.handle(event)
295                continue
296
297            if isinstance(event, bb.build.TaskFailed):
298                buildinfohelper.update_and_store_task(event)
299                logfile = event.logfile
300                if logfile and os.path.exists(logfile):
301                    bb.error("Logfile of failure stored in: %s" % logfile)
302                continue
303
304            # these events are unprocessed now, but may be used in the future to log
305            # timing and error informations from the parsing phase in Toaster
306            if isinstance(event, (bb.event.SanityCheckPassed, bb.event.SanityCheck)):
307                continue
308            if isinstance(event, bb.event.CacheLoadStarted):
309                continue
310            if isinstance(event, bb.event.CacheLoadProgress):
311                continue
312            if isinstance(event, bb.event.CacheLoadCompleted):
313                continue
314            if isinstance(event, bb.event.MultipleProviders):
315                logger.info(str(event))
316                continue
317
318            if isinstance(event, bb.event.NoProvider):
319                errors = errors + 1
320                text = str(event)
321                logger.error(text)
322                buildinfohelper.store_log_error(text)
323                continue
324
325            if isinstance(event, bb.event.ConfigParsed):
326                continue
327            if isinstance(event, bb.event.RecipeParsed):
328                continue
329
330            # end of saved events
331
332            if isinstance(event, (bb.runqueue.sceneQueueTaskStarted, bb.runqueue.runQueueTaskStarted, bb.runqueue.runQueueTaskSkipped)):
333                buildinfohelper.store_started_task(event)
334                continue
335
336            if isinstance(event, bb.runqueue.runQueueTaskCompleted):
337                buildinfohelper.update_and_store_task(event)
338                continue
339
340            if isinstance(event, bb.runqueue.runQueueTaskFailed):
341                buildinfohelper.update_and_store_task(event)
342                taskfailures.append(event.taskstring)
343                logger.error(str(event))
344                continue
345
346            if isinstance(event, (bb.runqueue.sceneQueueTaskCompleted, bb.runqueue.sceneQueueTaskFailed)):
347                buildinfohelper.update_and_store_task(event)
348                continue
349
350
351            if isinstance(event, (bb.event.TreeDataPreparationStarted, bb.event.TreeDataPreparationCompleted)):
352                continue
353
354            if isinstance(event, (bb.event.BuildCompleted, bb.command.CommandFailed)):
355
356                errorcode = 0
357                if isinstance(event, bb.command.CommandFailed):
358                    errors += 1
359                    errorcode = 1
360                    logger.error(str(event))
361                elif isinstance(event, bb.event.BuildCompleted):
362                    buildinfohelper.scan_image_artifacts()
363                    buildinfohelper.clone_required_sdk_artifacts()
364
365                # turn off logging to the current build log
366                _close_build_log(build_log)
367
368                # reset ready for next BuildStarted
369                build_log = None
370
371                # update the build info helper on BuildCompleted, not on CommandXXX
372                buildinfohelper.update_build_information(event, errors, warnings, taskfailures)
373
374                brbe = buildinfohelper.brbe
375                buildinfohelper.close(errorcode)
376
377                # we start a new build info
378                if params.observe_only:
379                    logger.debug("ToasterUI prepared for new build")
380                    errors = 0
381                    warnings = 0
382                    taskfailures = []
383                    buildinfohelper = BuildInfoHelper(server, build_history_enabled)
384                else:
385                    main.shutdown = 1
386
387                logger.info("ToasterUI build done, brbe: %s", brbe)
388                continue
389
390            if isinstance(event, (bb.command.CommandCompleted,
391                                  bb.command.CommandFailed,
392                                  bb.command.CommandExit)):
393                if params.observe_only:
394                    errorcode = 0
395                else:
396                    main.shutdown = 1
397
398                continue
399
400            if isinstance(event, bb.event.MetadataEvent):
401                if event.type == "SinglePackageInfo":
402                    buildinfohelper.store_build_package_information(event)
403                elif event.type == "LayerInfo":
404                    buildinfohelper.store_layer_info(event)
405                elif event.type == "BuildStatsList":
406                    buildinfohelper.store_tasks_stats(event)
407                elif event.type == "ImagePkgList":
408                    buildinfohelper.store_target_package_data(event)
409                elif event.type == "MissedSstate":
410                    buildinfohelper.store_missed_state_tasks(event)
411                elif event.type == "SDKArtifactInfo":
412                    buildinfohelper.scan_sdk_artifacts(event)
413                elif event.type == "SetBRBE":
414                    buildinfohelper.brbe = buildinfohelper._get_data_from_event(event)
415                elif event.type == "TaskArtifacts":
416                    buildinfohelper.scan_task_artifacts(event)
417                elif event.type == "OSErrorException":
418                    logger.error(event)
419                else:
420                    logger.error("Unprocessed MetadataEvent %s", event.type)
421                continue
422
423            if isinstance(event, bb.cooker.CookerExit):
424                # shutdown when bitbake server shuts down
425                main.shutdown = 1
426                continue
427
428            if isinstance(event, bb.event.DepTreeGenerated):
429                buildinfohelper.store_dependency_information(event)
430                continue
431
432            logger.warning("Unknown event: %s", event)
433            return_value += 1
434
435        except EnvironmentError as ioerror:
436            logger.warning("EnvironmentError: %s" % ioerror)
437            # ignore interrupted io system calls
438            if ioerror.args[0] == 4: # errno 4 is EINTR
439                logger.warning("Skipped EINTR: %s" % ioerror)
440            else:
441                raise
442        except KeyboardInterrupt:
443            if params.observe_only:
444                print("\nKeyboard Interrupt, exiting observer...")
445                main.shutdown = 2
446            if not params.observe_only and main.shutdown == 1:
447                print("\nSecond Keyboard Interrupt, stopping...\n")
448                _, error = server.runCommand(["stateForceShutdown"])
449                if error:
450                    logger.error("Unable to cleanly stop: %s" % error)
451            if not params.observe_only and main.shutdown == 0:
452                print("\nKeyboard Interrupt, closing down...\n")
453                interrupted = True
454                _, error = server.runCommand(["stateShutdown"])
455                if error:
456                    logger.error("Unable to cleanly shutdown: %s" % error)
457            buildinfohelper.cancel_cli_build()
458            main.shutdown = main.shutdown + 1
459        except Exception as e:
460            # print errors to log
461            import traceback
462            from pprint import pformat
463            exception_data = traceback.format_exc()
464            logger.error("%s\n%s" , e, exception_data)
465
466            # save them to database, if possible; if it fails, we already logged to console.
467            try:
468                buildinfohelper.store_log_exception("%s\n%s" % (str(e), exception_data))
469            except Exception as ce:
470                logger.error("CRITICAL - Failed to to save toaster exception to the database: %s", str(ce))
471
472            # make sure we return with an error
473            return_value += 1
474
475    if interrupted and return_value == 0:
476        return_value += 1
477
478    logger.warning("Return value is %d", return_value)
479    return return_value
480