From f17779453a81824872e1e0d1be4f36b7f62e212f Mon Sep 17 00:00:00 2001 From: Tiago Gomes Date: Wed, 12 Aug 2015 09:28:35 +0000 Subject: Rework debugging information for failed builds * Improve error messages and remove redundant information * Stop displaying the containerised settings, as they are not very helpful to debug a build failure * Display the error code * Change system integration commands logging to consistent with build commands logging. * Provide a log file in the staging directory for each chunk build failure or system integration failure. * Provide a chroot script in the staging directory for each chunk build failure or system integration build failure. This script allows the user to enter an environment similiar to the one where the build failed. * Fix a bug where the system integration commands stdout was being omitted when these commands failed. * Fix a bug where the error_message_for_containerised_commandline() was being called with an empty error message, as the stderr was being directed to stdout. Chunk build failure output before the this change and change I16ebe9ba4ac46fef82e37d0b3e05f42d14249de8: 2015-08-03 15:55:21 [Build 258/267] [test] Running build-commands build failed # configure # # echo "configure-commands stdout" configure-commands stdout # # echo "configure-commands stderr" >&2 configure-commands stderr # build # # echo "build commands stdout" build commands stdout # # echo "build commands stderr" >&2 build commands stderr # # echo "some more sdout" echo "some more stderr" >&2 echo $PATH foo some more sdout some more stderr /tools/bin:/usr/bin:/usr/lib/ccache:/sbin:/usr/sbin:/bin:/usr/bin sh: foo: not found ERROR: In staging area /src/tmp/failed/tmpglc5Sz: Command failed: sh -c 'echo "some more sdout" echo "some more stderr" >&2 echo $PATH foo ': Containerisation settings: {'binds': (('/src/cache/ccache/nano-tarball', '/src/tmp/staging/tmpglc5Sz/tmp/ccache'),), 'mount_proc': True, 'mounts': (('dev/shm', 'tmpfs', 'none'),), 'writable_paths': ['/src/tmp/staging/tmpglc5Sz/test.build', '/src/tmp/staging/tmpglc5Sz/test.inst', '/src/tmp/staging/tmpglc5Sz/dev', '/src/tmp/staging/tmpglc5Sz/proc', '/src/tmp/staging/tmpglc5Sz/tmp'], 'root': '/src/tmp/staging/tmpglc5Sz', 'cwd': '/test.build'} Error output: $> Chunk build failure output after this change and change I16ebe9ba4ac46fef82e37d0b3e05f42d14249de8: 2015-08-03 15:53:59 [Build 258/267] [test] Running build-commands ### CONFIGURE-COMMANDS ### + echo configure-commands stdout configure-commands stdout + echo configure-commands stderr configure-commands stderr ### BUILD-COMMANDS ### + echo build commands stdout build commands stdout + echo build commands stderr build commands stderr + echo some more sdout some more sdout + echo some more stderr some more stderr + echo /tools/bin:/usr/bin:/usr/lib/ccache:/sbin:/usr/sbin:/bin:/usr/bin /tools/bin:/usr/bin:/usr/lib/ccache:/sbin:/usr/sbin:/bin:/usr/bin + foo sh: foo: not found ERROR: In staging area /src/tmp/staging/tmpjES5_2: build failed (exi t_code=127) $> System integration build failure output before this change and change I16ebe9ba4ac46fef82e37d0b3e05f42d14249de8: 2015-08-03 15:58:25 [Build 267/267] [build-system-x86_64] Running the system integration commands 2015-08-03 15:58:25 [Build 267/267] [build-system-x86_64] Error while running system integration commands 2015-08-03 15:58:25 [Build 267/267] [build-system-x86_64] Error while building system ERROR: Command failed: baserock/system-integration/00-test-test-misc-0002: Containerisation settings: {'mounts': (('dev/shm', 'tmpfs', 'none'), ('tmp', 'tmpfs', 'none')), 'mount_proc': True, 'root': '/src/tmp/staging/tmpvpwB4l/build-system-x86_64.inst'} Error output: + foo baserock/system-integration/00-test-test-misc-0002: line 1: foo: not found $> System integration build failure output after this change and change I16ebe9ba4ac46fef82e37d0b3e05f42d14249de8: 2015-08-03 16:00:06 [Build 267/267] [build-system-x86_64] Running the system integration commands + echo stdout stdout + echo stderr stderr + foo baserock/system-integration/00-test-test-misc-0002: line 1: foo: not found ERROR: In staging area /src/tmp/staging/tmpl9VNzf: system integration commands failed (exit_code=127) $> Change-Id: Id992f707f69f3fa761b4c21e9904c4e5328e1c77 --- morphlib/builder.py | 112 ++++++++++++++--------- morphlib/stagingarea.py | 19 ++-- morphlib/util.py | 15 --- tests.build/build-chunk-failures-dump-log.stdout | 2 +- 4 files changed, 80 insertions(+), 68 deletions(-) diff --git a/morphlib/builder.py b/morphlib/builder.py index 038fd5ba..58667159 100644 --- a/morphlib/builder.py +++ b/morphlib/builder.py @@ -30,7 +30,6 @@ import cliapp import morphlib from morphlib.artifactcachereference import ArtifactCacheReference -from morphlib.util import error_message_for_containerised_commandline import morphlib.gitversion SYSTEM_INTEGRATION_PATH = os.path.join('baserock', 'system-integration') @@ -297,7 +296,7 @@ class ChunkBuilder(BuilderBase): if os.path.isfile(temppath): with open(temppath) as f: for line in f: - logging.error('OUTPUT FROM FAILED BUILD: %s' % + logging.error('BUILD OUTPUT: %s' % line.rstrip('\n')) os.rename(temppath, logpath) @@ -362,31 +361,37 @@ class ChunkBuilder(BuilderBase): else: extra_env['MAKEFLAGS'] = '-j1' - try: - # flushing is needed because writes from python and - # writes from being the output in Popen have different - # buffers, but flush handles both - if stdout: - stdout.flush() - - with open(os.devnull) as devnull: - self.runcmd(['sh', '-x', '-c', cmd], - extra_env=extra_env, - cwd=relative_builddir, - stdin=devnull, - stdout=stdout or subprocess.PIPE, - stderr=subprocess.STDOUT, - logfile=logfilepath, - ccache_dir=ccache_dir) - - if stdout: - stdout.flush() - except cliapp.AppException as e: + # flushing is needed because writes from python and + # writes from being the output in Popen have different + # buffers, but flush handles both + if stdout: + stdout.flush() + + with open(os.devnull) as devnull: + exit_code = self.runcmd(['sh', '-x', '-c', cmd], + extra_env=extra_env, + cwd=relative_builddir, + stdin=devnull, + stdout=stdout or + subprocess.PIPE, + stderr=subprocess.STDOUT, + logfile=logfilepath, + ccache_dir=ccache_dir) + + if stdout: + stdout.flush() + + if exit_code != 0: if not stdout: with open(logfilepath, 'r') as log: - self.app.output.write("%s failed\n" % step) shutil.copyfileobj(log, self.app.output) - raise e + self.app.output.write("\n") + shutil.copyfile( + logfilepath, + self.staging_area.dirname + '.log') + raise cliapp.AppException( + "In staging area %s: %s failed (exit_code=%s)" % + (self.staging_area.dirname, step, exit_code)) def write_system_integration_commands(self, destdir, integration_commands, artifact_name): # pragma: no cover @@ -565,8 +570,6 @@ class SystemBuilder(BuilderBase): # pragma: no cover tar.close() except BaseException as e: logging.error(traceback.format_exc()) - self.app.status(msg='Error while building system', - error=True) handle.abort() raise else: @@ -674,26 +677,45 @@ class SystemBuilder(BuilderBase): # pragma: no cover ('dev/shm', 'tmpfs', 'none'), ('tmp', 'tmpfs', 'none'), ) - try: - for bin in sorted(os.listdir(sys_integration_dir)): - argv = [os.path.join(SYSTEM_INTEGRATION_PATH, bin)] - container_config = dict( - root=rootdir, mounts=to_mount, mount_proc=True) - cmdline = morphlib.util.containerised_cmdline( - argv, **container_config) - exit, out, err = self.app.runcmd_unchecked( - cmdline, env=env) - if exit != 0: - logging.debug('Command returned code %i', exit) - msg = error_message_for_containerised_commandline( - argv, err, container_config) - raise cliapp.AppException(msg) - except BaseException as e: - self.app.status( - msg='Error while running system integration commands', - error=True) - raise + for bin in sorted(os.listdir(sys_integration_dir)): + argv = [os.path.join(SYSTEM_INTEGRATION_PATH, bin)] + container_config = dict( + root=rootdir, mounts=to_mount, mount_proc=True) + cmdline = morphlib.util.containerised_cmdline( + argv, **container_config) + + logfilepath = os.path.dirname(rootdir) + '.log' + teecmd = ['tee', '-a', logfilepath] + exit_code, out, err = self.app.runcmd_unchecked( + cmdline, teecmd, env=env, + stderr=subprocess.STDOUT) + + if exit_code != 0: + logging.debug('Command returned code %i', exit_code) + + chroot_script = os.path.dirname(rootdir) + '.sh' + shell_command = ['env', '-i', '--'] + for k, v in env.iteritems(): + shell_command += ["%s=%s" % (k, v)] + shell_command += [os.path.join(os.sep, 'bin', 'sh')] + with open(chroot_script, 'w') as f: + cmdline = morphlib.util.containerised_cmdline( + shell_command, **container_config) + f.write(' '.join(map(cliapp.shell_quote, cmdline))) + + with open(logfilepath, 'r') as log: + shutil.copyfileobj(log, self.app.output) + self.app.output.write("\n") + log.seek(0) + for line in log: + logging.error('INTEGRATION OUTPUT: %s' % + line.rstrip('\n')) + + raise cliapp.AppException( + "In staging area %s: system integration " + "commands failed (exit_code=%s)" + % (os.path.dirname(rootdir), exit_code)) class Builder(object): # pragma: no cover diff --git a/morphlib/stagingarea.py b/morphlib/stagingarea.py index c8c77229..e244a8d2 100644 --- a/morphlib/stagingarea.py +++ b/morphlib/stagingarea.py @@ -314,12 +314,17 @@ class StagingArea(object): else: exit, out, err = self._app.runcmd_unchecked(cmdline, **kwargs) - if exit == 0: - return out - else: + if exit != 0: logging.debug('Command returned code %i', exit) - msg = morphlib.util.error_message_for_containerised_commandline( - argv, err, container_config) - raise cliapp.AppException( - 'In staging area %s: %s' % (self.dirname, msg)) + chroot_script = self.dirname + '.sh' + shell_command = ['env', '-i', '--'] + for k, v in kwargs['env'].iteritems(): + shell_command += ["%s=%s" % (k, v)] + shell_command += [os.path.join(os.sep, 'bin', 'sh')] + cmdline = morphlib.util.containerised_cmdline( + shell_command, **container_config) + with open(chroot_script, 'w') as f: + f.write(' '.join(map(cliapp.shell_quote, cmdline))) + return exit + diff --git a/morphlib/util.py b/morphlib/util.py index 2bce6f31..a92b7f37 100644 --- a/morphlib/util.py +++ b/morphlib/util.py @@ -649,21 +649,6 @@ def containerised_cmdline(args, cwd='.', root='/', binds=(), return unshared_cmdline(cmdargs, root=root, **kwargs) -def error_message_for_containerised_commandline( - argv, err, container_kwargs): # pragma: no cover - '''Return a semi-readable error message for a containerised command.''' - - # This function should do some formatting of the container_kwargs dict, - # rather than just dumping it in the error message, but that is better than - # nothing. - - argv_string = ' '.join(map(pipes.quote, argv)) - return 'Command failed: %s:\n' \ - 'Containerisation settings: %s\n' \ - 'Error output:\n%s' \ - % (argv_string, container_kwargs, err) - - def write_from_dict(filepath, d, validate=lambda x, y: True): #pragma: no cover '''Takes a dictionary and appends the contents to a file diff --git a/tests.build/build-chunk-failures-dump-log.stdout b/tests.build/build-chunk-failures-dump-log.stdout index 83c67420..c4d4bf93 100644 --- a/tests.build/build-chunk-failures-dump-log.stdout +++ b/tests.build/build-chunk-failures-dump-log.stdout @@ -1,4 +1,3 @@ -build failed ### CONFIGURE-COMMANDS ### + echo dummy configure dummy configure @@ -6,3 +5,4 @@ dummy configure + echo The next command will fail The next command will fail + false + -- cgit v1.2.1