diff options
Diffstat (limited to 'bitbake/lib/bb/build.py')
| -rw-r--r-- | bitbake/lib/bb/build.py | 409 |
1 files changed, 257 insertions, 152 deletions
diff --git a/bitbake/lib/bb/build.py b/bitbake/lib/bb/build.py index 23b6ee455f..44d08f5c55 100644 --- a/bitbake/lib/bb/build.py +++ b/bitbake/lib/bb/build.py @@ -16,17 +16,24 @@ import os import sys import logging import glob +import itertools import time +import re import stat +import datetime import bb import bb.msg import bb.process import bb.progress +from io import StringIO from bb import data, event, utils bblogger = logging.getLogger('BitBake') logger = logging.getLogger('BitBake.Build') +verboseShellLogging = False +verboseStdoutLogging = False + __mtime_cache = {} def cached_mtime_noerror(f): @@ -171,7 +178,9 @@ class StdoutNoopContextManager: @property def name(self): - return sys.stdout.name + if "name" in dir(sys.stdout): + return sys.stdout.name + return "<mem>" def exec_func(func, d, dirs = None): @@ -290,9 +299,25 @@ def exec_func_python(func, d, runfile, cwd=None): lineno = int(d.getVarFlag(func, "lineno", False)) bb.methodpool.insert_method(func, text, fn, lineno - 1) - comp = utils.better_compile(code, func, "exec_python_func() autogenerated") - utils.better_exec(comp, {"d": d}, code, "exec_python_func() autogenerated") + if verboseStdoutLogging: + sys.stdout.flush() + sys.stderr.flush() + currout = sys.stdout + currerr = sys.stderr + sys.stderr = sys.stdout = execio = StringIO() + comp = utils.better_compile(code, func, "exec_func_python() autogenerated") + utils.better_exec(comp, {"d": d}, code, "exec_func_python() autogenerated") finally: + if verboseStdoutLogging: + execio.flush() + logger.plain("%s" % execio.getvalue()) + sys.stdout = currout + sys.stderr = currerr + execio.close() + # We want any stdout/stderr to be printed before any other log messages to make debugging + # more accurate. In some cases we seem to lose stdout/stderr entirely in logging tests without this. + sys.stdout.flush() + sys.stderr.flush() bb.debug(2, "Python function %s finished" % func) if cwd and olddir: @@ -303,20 +328,60 @@ def exec_func_python(func, d, runfile, cwd=None): def shell_trap_code(): return '''#!/bin/sh\n +__BITBAKE_LAST_LINE=0 + # Emit a useful diagnostic if something fails: -bb_exit_handler() { +bb_sh_exit_handler() { + ret=$? + if [ "$ret" != 0 ]; then + echo "WARNING: exit code $ret from a shell command." + fi + exit $ret +} + +bb_bash_exit_handler() { ret=$? - case $ret in - 0) ;; - *) case $BASH_VERSION in - "") echo "WARNING: exit code $ret from a shell command.";; - *) echo "WARNING: ${BASH_SOURCE[0]}:${BASH_LINENO[0]} exit $ret from '$BASH_COMMAND'";; - esac - exit $ret - esac + { set +x; } > /dev/null + trap "" DEBUG + if [ "$ret" != 0 ]; then + echo "WARNING: ${BASH_SOURCE[0]}:${__BITBAKE_LAST_LINE} exit $ret from '$1'" + + echo "WARNING: Backtrace (BB generated script): " + for i in $(seq 1 $((${#FUNCNAME[@]} - 1))); do + if [ "$i" -eq 1 ]; then + echo -e "\t#$((i)): ${FUNCNAME[$i]}, ${BASH_SOURCE[$((i-1))]}, line ${__BITBAKE_LAST_LINE}" + else + echo -e "\t#$((i)): ${FUNCNAME[$i]}, ${BASH_SOURCE[$((i-1))]}, line ${BASH_LINENO[$((i-1))]}" + fi + done + fi + exit $ret } -trap 'bb_exit_handler' 0 -set -e + +bb_bash_debug_handler() { + local line=${BASH_LINENO[0]} + # For some reason the DEBUG trap trips with lineno=1 when scripts exit; ignore it + if [ "$line" -eq 1 ]; then + return + fi + + # Track the line number of commands as they execute. This is so we can have access to the failing line number + # in the EXIT trap. See http://gnu-bash.2382.n7.nabble.com/trap-echo-quot-trap-exit-on-LINENO-quot-EXIT-gt-wrong-linenumber-td3666.html + if [ "${FUNCNAME[1]}" != "bb_bash_exit_handler" ]; then + __BITBAKE_LAST_LINE=$line + fi +} + +case $BASH_VERSION in +"") trap 'bb_sh_exit_handler' 0 + set -e + ;; +*) trap 'bb_bash_exit_handler "$BASH_COMMAND"' 0 + trap '{ bb_bash_debug_handler; } 2>/dev/null' DEBUG + set -e + shopt -s extdebug + ;; +esac ''' def create_progress_handler(func, progress, logfile, d): @@ -346,7 +411,7 @@ def create_progress_handler(func, progress, logfile, d): cls_obj = functools.reduce(resolve, cls.split("."), bb.utils._context) if not cls_obj: # Fall-back on __builtins__ - cls_obj = functools.reduce(lambda x, y: x.get(y), cls.split("."), __builtins__) + cls_obj = functools.reduce(resolve, cls.split("."), __builtins__) if cls_obj: return cls_obj(d, outfile=logfile, otherargs=otherargs) bb.warn('%s: unknown custom progress handler in task progress varflag value "%s", ignoring' % (func, cls)) @@ -371,7 +436,7 @@ def exec_func_shell(func, d, runfile, cwd=None): bb.data.emit_func(func, script, d) - if bb.msg.loggerVerboseLogs: + if verboseShellLogging or bb.utils.to_boolean(d.getVar("BB_VERBOSE_LOGS", False)): script.write("set -x\n") if cwd: script.write("cd '%s'\n" % cwd) @@ -391,14 +456,24 @@ exit $ret if fakerootcmd: cmd = [fakerootcmd, runfile] - if bb.msg.loggerDefaultVerbose: + # We only want to output to logger via LogTee if stdout is sys.__stdout__ (which will either + # be real stdout or subprocess PIPE or similar). In other cases we are being run "recursively", + # ie. inside another function, in which case stdout is already being captured so we don't + # want to Tee here as output would be printed twice, and out of order. + if verboseStdoutLogging and sys.stdout == sys.__stdout__: logfile = LogTee(logger, StdoutNoopContextManager()) else: logfile = StdoutNoopContextManager() progress = d.getVarFlag(func, 'progress') if progress: - logfile = create_progress_handler(func, progress, logfile, d) + try: + logfile = create_progress_handler(func, progress, logfile, d) + except: + from traceback import format_exc + logger.error("Failed to create progress handler") + logger.error(format_exc()) + raise fifobuffer = bytearray() def readfifo(data): @@ -450,6 +525,62 @@ exit $ret bb.debug(2, "Executing shell function %s" % func) with open(os.devnull, 'r+') as stdin, logfile: bb.process.run(cmd, shell=False, stdin=stdin, log=logfile, extrafiles=[(fifo,readfifo)]) + except bb.process.ExecutionError as exe: + # Find the backtrace that the shell trap generated + backtrace_marker_regex = re.compile(r"WARNING: Backtrace \(BB generated script\)") + stdout_lines = (exe.stdout or "").split("\n") + backtrace_start_line = None + for i, line in enumerate(reversed(stdout_lines)): + if backtrace_marker_regex.search(line): + backtrace_start_line = len(stdout_lines) - i + break + + # Read the backtrace frames, starting at the location we just found + backtrace_entry_regex = re.compile(r"#(?P<frameno>\d+): (?P<funcname>[^\s]+), (?P<file>.+?), line (" + r"?P<lineno>\d+)") + backtrace_frames = [] + if backtrace_start_line: + for line in itertools.islice(stdout_lines, backtrace_start_line, None): + match = backtrace_entry_regex.search(line) + if match: + backtrace_frames.append(match.groupdict()) + + with open(runfile, "r") as script: + script_lines = [line.rstrip() for line in script.readlines()] + + # For each backtrace frame, search backwards in the script (from the line number called out by the frame), + # to find the comment that emit_vars injected when it wrote the script. This will give us the metadata + # filename (e.g. .bb or .bbclass) and line number where the shell function was originally defined. + script_metadata_comment_regex = re.compile(r"# line: (?P<lineno>\d+), file: (?P<file>.+)") + better_frames = [] + # Skip the very last frame since it's just the call to the shell task in the body of the script + for frame in backtrace_frames[:-1]: + # Check whether the frame corresponds to a function defined in the script vs external script. + if os.path.samefile(frame["file"], runfile): + # Search backwards from the frame lineno to locate the comment that BB injected + i = int(frame["lineno"]) - 1 + while i >= 0: + match = script_metadata_comment_regex.match(script_lines[i]) + if match: + # Calculate the relative line in the function itself + relative_line_in_function = int(frame["lineno"]) - i - 2 + # Calculate line in the function as declared in the metadata + metadata_function_line = relative_line_in_function + int(match["lineno"]) + better_frames.append("#{frameno}: {funcname}, {file}, line {lineno}".format( + frameno=frame["frameno"], + funcname=frame["funcname"], + file=match["file"], + lineno=metadata_function_line + )) + break + i -= 1 + else: + better_frames.append("#{frameno}: {funcname}, {file}, line {lineno}".format(**frame)) + + if better_frames: + better_frames = ("\t{0}".format(frame) for frame in better_frames) + exe.extra_message = "\nBacktrace (metadata-relative locations):\n{0}".format("\n".join(better_frames)) + raise finally: os.unlink(fifopath) @@ -458,10 +589,8 @@ exit $ret def _task_data(fn, task, d): localdata = bb.data.createCopy(d) localdata.setVar('BB_FILENAME', fn) - localdata.setVar('BB_CURRENTTASK', task[3:]) localdata.setVar('OVERRIDES', 'task-%s:%s' % (task[3:].replace('_', '-'), d.getVar('OVERRIDES', False))) - localdata.finalize() bb.data.expandKeys(localdata) return localdata @@ -472,11 +601,11 @@ def _exec_task(fn, task, d, quieterr): running it with its own local metadata, and with some useful variables set. """ if not d.getVarFlag(task, 'task', False): - event.fire(TaskInvalid(task, d), d) + event.fire(TaskInvalid(task, fn, d), d) logger.error("No such task: %s" % task) return 1 - logger.debug(1, "Executing task %s", task) + logger.debug("Executing task %s", task) localdata = _task_data(fn, task, d) tempdir = localdata.getVar('T') @@ -489,7 +618,7 @@ def _exec_task(fn, task, d, quieterr): curnice = os.nice(0) nice = int(nice) - curnice newnice = os.nice(nice) - logger.debug(1, "Renice to %s " % newnice) + logger.debug("Renice to %s " % newnice) ionice = localdata.getVar("BB_TASK_IONICE_LEVEL") if ionice: try: @@ -508,7 +637,8 @@ def _exec_task(fn, task, d, quieterr): logorder = os.path.join(tempdir, 'log.task_order') try: with open(logorder, 'a') as logorderfile: - logorderfile.write('{0} ({1}): {2}\n'.format(task, os.getpid(), logbase)) + timestamp = datetime.datetime.now().strftime("%Y%m%d-%H%M%S.%f") + logorderfile.write('{0} {1} ({2}): {3}\n'.format(timestamp, task, os.getpid(), logbase)) except OSError: logger.exception("Opening log file '%s'", logorder) pass @@ -575,47 +705,55 @@ def _exec_task(fn, task, d, quieterr): try: try: event.fire(TaskStarted(task, fn, logfn, flags, localdata), localdata) - except (bb.BBHandledException, SystemExit): - return 1 - try: for func in (prefuncs or '').split(): exec_func(func, localdata) exec_func(task, localdata) for func in (postfuncs or '').split(): exec_func(func, localdata) - except bb.BBHandledException: - event.fire(TaskFailed(task, fn, logfn, localdata, True), localdata) - return 1 - except Exception as exc: - if quieterr: - event.fire(TaskFailedSilent(task, fn, logfn, localdata), localdata) - else: - errprinted = errchk.triggered - logger.error(str(exc)) - event.fire(TaskFailed(task, fn, logfn, localdata, errprinted), localdata) - return 1 - finally: - sys.stdout.flush() - sys.stderr.flush() - - bblogger.removeHandler(handler) - - # Restore the backup fds - os.dup2(osi[0], osi[1]) - os.dup2(oso[0], oso[1]) - os.dup2(ose[0], ose[1]) - - # Close the backup fds - os.close(osi[0]) - os.close(oso[0]) - os.close(ose[0]) + finally: + # Need to flush and close the logs before sending events where the + # UI may try to look at the logs. + sys.stdout.flush() + sys.stderr.flush() + + bblogger.removeHandler(handler) + + # Restore the backup fds + os.dup2(osi[0], osi[1]) + os.dup2(oso[0], oso[1]) + os.dup2(ose[0], ose[1]) + + # Close the backup fds + os.close(osi[0]) + os.close(oso[0]) + os.close(ose[0]) + + logfile.close() + if os.path.exists(logfn) and os.path.getsize(logfn) == 0: + logger.debug2("Zero size logfn %s, removing", logfn) + bb.utils.remove(logfn) + bb.utils.remove(loglink) + except (Exception, SystemExit) as exc: + handled = False + if isinstance(exc, bb.BBHandledException): + handled = True + + if quieterr: + if not handled: + logger.warning(repr(exc)) + event.fire(TaskFailedSilent(task, fn, logfn, localdata), localdata) + else: + errprinted = errchk.triggered + # If the output is already on stdout, we've printed the information in the + # logs once already so don't duplicate + if verboseStdoutLogging or handled: + errprinted = True + if not handled: + logger.error(repr(exc)) + event.fire(TaskFailed(task, fn, logfn, localdata, errprinted), localdata) + return 1 - logfile.close() - if os.path.exists(logfn) and os.path.getsize(logfn) == 0: - logger.debug(2, "Zero size logfn %s, removing", logfn) - bb.utils.remove(logfn) - bb.utils.remove(loglink) event.fire(TaskSucceeded(task, fn, logfn, localdata), localdata) if not localdata.getVarFlag(task, 'nostamp', False) and not localdata.getVarFlag(task, 'selfstamp', False): @@ -653,132 +791,92 @@ def exec_task(fn, task, d, profile = False): event.fire(failedevent, d) return 1 -def stamp_internal(taskname, d, file_name, baseonly=False, noextra=False): +def _get_cleanmask(taskname, mcfn): """ - Internal stamp helper function - Makes sure the stamp directory exists + Internal stamp helper function to generate stamp cleaning mask Returns the stamp path+filename In the bitbake core, d can be a CacheData and file_name will be set. When called in task context, d will be a data store, file_name will not be set """ - taskflagname = taskname - if taskname.endswith("_setscene") and taskname != "do_setscene": - taskflagname = taskname.replace("_setscene", "") - - if file_name: - stamp = d.stamp[file_name] - extrainfo = d.stamp_extrainfo[file_name].get(taskflagname) or "" - else: - stamp = d.getVar('STAMP') - file_name = d.getVar('BB_FILENAME') - extrainfo = d.getVarFlag(taskflagname, 'stamp-extra-info') or "" + cleanmask = bb.parse.siggen.stampcleanmask_mcfn(taskname, mcfn) + taskflagname = taskname.replace("_setscene", "") + if cleanmask: + return [cleanmask, cleanmask.replace(taskflagname, taskflagname + "_setscene")] + return [] + +def clean_stamp_mcfn(task, mcfn): + cleanmask = _get_cleanmask(task, mcfn) + for mask in cleanmask: + for name in glob.glob(mask): + # Preserve sigdata files in the stamps directory + if "sigdata" in name or "sigbasedata" in name: + continue + # Preserve taint files in the stamps directory + if name.endswith('.taint'): + continue + os.unlink(name) - if baseonly: - return stamp - if noextra: - extrainfo = "" +def clean_stamp(task, d): + mcfn = d.getVar('BB_FILENAME') + clean_stamp_mcfn(task, mcfn) - if not stamp: - return +def make_stamp_mcfn(task, mcfn): - stamp = bb.parse.siggen.stampfile(stamp, file_name, taskname, extrainfo) + basestamp = bb.parse.siggen.stampfile_mcfn(task, mcfn) - stampdir = os.path.dirname(stamp) + stampdir = os.path.dirname(basestamp) if cached_mtime_noerror(stampdir) == 0: bb.utils.mkdirhier(stampdir) - return stamp + clean_stamp_mcfn(task, mcfn) -def stamp_cleanmask_internal(taskname, d, file_name): - """ - Internal stamp helper function to generate stamp cleaning mask - Returns the stamp path+filename + # Remove the file and recreate to force timestamp + # change on broken NFS filesystems + if basestamp: + bb.utils.remove(basestamp) + open(basestamp, "w").close() - In the bitbake core, d can be a CacheData and file_name will be set. - When called in task context, d will be a data store, file_name will not be set +def make_stamp(task, d): """ - taskflagname = taskname - if taskname.endswith("_setscene") and taskname != "do_setscene": - taskflagname = taskname.replace("_setscene", "") - - if file_name: - stamp = d.stampclean[file_name] - extrainfo = d.stamp_extrainfo[file_name].get(taskflagname) or "" - else: - stamp = d.getVar('STAMPCLEAN') - file_name = d.getVar('BB_FILENAME') - extrainfo = d.getVarFlag(taskflagname, 'stamp-extra-info') or "" + Creates/updates a stamp for a given task + """ + mcfn = d.getVar('BB_FILENAME') - if not stamp: - return [] + make_stamp_mcfn(task, mcfn) - cleanmask = bb.parse.siggen.stampcleanmask(stamp, file_name, taskname, extrainfo) + # If we're in task context, write out a signature file for each task + # as it completes + if not task.endswith("_setscene"): + stampbase = bb.parse.siggen.stampfile_base(mcfn) + bb.parse.siggen.dump_sigtask(mcfn, task, stampbase, True) - return [cleanmask, cleanmask.replace(taskflagname, taskflagname + "_setscene")] -def make_stamp(task, d, file_name = None): - """ - Creates/updates a stamp for a given task - (d can be a data dict or dataCache) - """ - cleanmask = stamp_cleanmask_internal(task, d, file_name) +def find_stale_stamps(task, mcfn): + current = bb.parse.siggen.stampfile_mcfn(task, mcfn) + current2 = bb.parse.siggen.stampfile_mcfn(task + "_setscene", mcfn) + cleanmask = _get_cleanmask(task, mcfn) + found = [] for mask in cleanmask: for name in glob.glob(mask): - # Preserve sigdata files in the stamps directory if "sigdata" in name or "sigbasedata" in name: continue - # Preserve taint files in the stamps directory if name.endswith('.taint'): continue - os.unlink(name) - - stamp = stamp_internal(task, d, file_name) - # Remove the file and recreate to force timestamp - # change on broken NFS filesystems - if stamp: - bb.utils.remove(stamp) - open(stamp, "w").close() - - # If we're in task context, write out a signature file for each task - # as it completes - if not task.endswith("_setscene") and task != "do_setscene" and not file_name: - stampbase = stamp_internal(task, d, None, True) - file_name = d.getVar('BB_FILENAME') - bb.parse.siggen.dump_sigtask(file_name, task, stampbase, True) - -def del_stamp(task, d, file_name = None): - """ - Removes a stamp for a given task - (d can be a data dict or dataCache) - """ - stamp = stamp_internal(task, d, file_name) - bb.utils.remove(stamp) + if name == current or name == current2: + continue + logger.debug2("Stampfile %s does not match %s or %s" % (name, current, current2)) + found.append(name) + return found -def write_taint(task, d, file_name = None): +def write_taint(task, d): """ Creates a "taint" file which will force the specified task and its dependents to be re-run the next time by influencing the value of its taskhash. - (d can be a data dict or dataCache) """ - import uuid - if file_name: - taintfn = d.stamp[file_name] + '.' + task + '.taint' - else: - taintfn = d.getVar('STAMP') + '.' + task + '.taint' - bb.utils.mkdirhier(os.path.dirname(taintfn)) - # The specific content of the taint file is not really important, - # we just need it to be random, so a random UUID is used - with open(taintfn, 'w') as taintf: - taintf.write(str(uuid.uuid4())) - -def stampfile(taskname, d, file_name = None, noextra=False): - """ - Return the stamp for a given task - (d can be a data dict or dataCache) - """ - return stamp_internal(taskname, d, file_name, noextra=noextra) + mcfn = d.getVar('BB_FILENAME') + bb.parse.siggen.invalidate_task(task, mcfn) def add_tasks(tasklist, d): task_deps = d.getVar('_task_deps', False) @@ -803,6 +901,11 @@ def add_tasks(tasklist, d): task_deps[name] = {} if name in flags: deptask = d.expand(flags[name]) + if name in ['noexec', 'fakeroot', 'nostamp']: + if deptask != '1': + bb.warn("In a future version of BitBake, setting the '{}' flag to something other than '1' " + "will result in the flag not being set. See YP bug #13808.".format(name)) + task_deps[name][task] = deptask getTask('mcdepends') getTask('depends') @@ -901,6 +1004,8 @@ def tasksbetween(task_start, task_end, d): def follow_chain(task, endtask, chain=None): if not chain: chain = [] + if task in chain: + bb.fatal("Circular task dependencies as %s depends on itself via the chain %s" % (task, " -> ".join(chain))) chain.append(task) for othertask in tasks: if othertask == task: |